[ 0.000000] Linux version 4.18.0rh8.10-debug (green@maintenance) (gcc version 8.5.0 20210514 (Red Hat 8.5.0-26) (GCC)) #2 SMP Mon Jul 14 01:24:22 EDT 2025 [ 0.000000] Command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers' [ 0.000000] x86/fpu: xstate_offset[2]: 576, xstate_sizes[2]: 256 [ 0.000000] x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'standard' format. [ 0.000000] signal: max sigframe size: 1776 [ 0.000000] BIOS-provided physical RAM map: [ 0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable [ 0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000000100000-0x00000000bffd9fff] usable [ 0.000000] BIOS-e820: [mem 0x00000000bffda000-0x00000000bfffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000100000000-0x0000000146dfffff] usable [ 0.000000] NX (Execute Disable) protection: active [ 0.000000] SMBIOS 2.8 present. [ 0.000000] DMI: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.17.0-10.fc44 06/10/2025 [ 0.000000] Hypervisor detected: KVM [ 0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00 [ 0.000000] kvm-clock: using sched offset of 430443419 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2399.998 MHz processor [ 0.000000] last_pfn = 0x146e00 max_arch_pfn = 0x400000000 [ 0.000000] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT [ 0.000000] last_pfn = 0xbffda max_arch_pfn = 0x400000000 [ 0.000000] found SMP MP-table at [mem 0x000f54d0-0x000f54df] [ 0.000000] RAMDISK: [mem 0xbcc64000-0xbffcffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F52F0 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE2464 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE2300 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 0022C0 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE2374 000090 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE2404 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE243C 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe2300-0xbffe2373] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe22ff] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe2374-0xbffe2403] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe2404-0xbffe243b] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe243c-0xbffe2463] [ 0.000000] No NUMA configuration found [ 0.000000] Faking a node at [mem 0x0000000000000000-0x0000000146dfffff] [ 0.000000] NODE_DATA(0) allocated [mem 0x1465a3000-0x1465cdfff] [ 0.000000] Reserving 256MB of memory at 2752MB for crashkernel (System RAM: 4205MB) [ 0.000000] Zone ranges: [ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.000000] DMA32 [mem 0x0000000001000000-0x00000000ffffffff] [ 0.000000] Normal [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Device empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff] [ 0.000000] node 0: [mem 0x0000000000100000-0x00000000bffd9fff] [ 0.000000] node 0: [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Zeroed struct page in unavailable ranges: 4744 pages [ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x0000000146dfffff] [ 0.000000] ACPI: PM-Timer IO Port: 0x608 [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) [ 0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) [ 0.000000] Using ACPI (MADT) for SMP configuration information [ 0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000] TSC deadline timer available [ 0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs [ 0.000000] kvm-guest: KVM setup pv remote TLB flush [ 0.000000] kvm-guest: setup PV sched yield [ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff] [ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff] [ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff] [ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff] [ 0.000000] PM: Registered nosave memory: [mem 0xbffda000-0xbfffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xc0000000-0xfeffbfff] [ 0.000000] PM: Registered nosave memory: [mem 0xfeffc000-0xfeffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xff000000-0xfffbffff] [ 0.000000] PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff] [ 0.000000] [mem 0xc0000000-0xfeffbfff] available for PCI devices [ 0.000000] Booting paravirtualized kernel on KVM [ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns [ 0.000000] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1 [ 0.000000] percpu: Embedded 63 pages/cpu s221184 r8192 d28672 u524288 [ 0.000000] kvm-guest: PV spinlocks enabled [ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1059618 [ 0.000000] Policy zone: Normal [ 0.000000] Kernel command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] Specific versions of hardware are certified with Red Hat Enterprise Linux 8. Please see the list of hardware certified with Red Hat Enterprise Linux 8 at https://catalog.redhat.com. [ 0.000000] audit: disabled (until reboot) [ 0.000000] software IO TLB: area num 4. [ 0.000000] Memory: 2829700K/4306400K available (18435K kernel code, 11221K rwdata, 7248K rodata, 2908K init, 18040K bss, 524580K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] ftrace: allocating 41240 entries in 162 pages [ 0.000000] ftrace: allocated 162 pages with 3 groups [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] rcu: RCU event tracing is enabled. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ 0.000000] rcu: RCU callback double-/use-after-free debug enabled. [ 0.000000] Rude variant of Tasks RCU enabled. [ 0.000000] Tracing variant of Tasks RCU enabled. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 0.000000] NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16 [ 0.000000] random: get_random_bytes called from start_kernel+0x622/0x9a8 with crng_init=0 [ 0.001000] Console: colour *CGA 80x25 [ 0.001000] printk: console [ttyS1] enabled [ 0.001000] ACPI: Core revision 20220331 [ 0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.001014] APIC: Switch to symmetric I/O mode setup [ 0.002269] x2apic enabled [ 0.003010] Switched APIC routing to physical x2apic. [ 0.004018] kvm-guest: setup PV IPIs [ 0.007602] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.008000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.008031] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.009027] pid_max: default: 32768 minimum: 301 [ 0.011071] LSM: Security Framework initializing [ 0.012088] Yama: becoming mindful. [ 0.013061] SELinux: Initializing. [ 0.014097] *** VALIDATE selinux *** [ 0.023454] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.028443] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.029192] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.031065] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.032150] *** VALIDATE tmpfs *** [ 0.034520] *** VALIDATE proc *** [ 0.036186] *** VALIDATE cgroup *** [ 0.037015] *** VALIDATE cgroup2 *** [ 0.039315] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.041066] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.042010] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.043041] Spectre V2 : User space: Vulnerable [ 0.044014] Speculative Store Bypass: Vulnerable [ 0.047395] debug: unmapping init [mem 0xffffffffa0e59000-0xffffffffa0e60fff] [ 0.049198] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.050782] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.051028] ... version: 2 [ 0.052011] ... bit width: 48 [ 0.053010] ... generic registers: 4 [ 0.054016] ... value mask: 0000ffffffffffff [ 0.055016] ... max period: 00007fffffffffff [ 0.056018] ... fixed-purpose events: 3 [ 0.057018] ... event mask: 000000070000000f [ 0.058392] rcu: Hierarchical SRCU implementation. [ 0.060698] smp: Bringing up secondary CPUs ... [ 0.061674] x86: Booting SMP configuration: [ 0.062034] .... node #0, CPUs: #1 #2 #3 [ 0.065460] smp: Brought up 1 node, 4 CPUs [ 0.067010] smpboot: Max logical packages: 1 [ 0.067957] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.267000] node 0 deferred pages initialised in 198ms [ 0.272017] devtmpfs: initialized [ 0.273933] x86/mm: Memory block size: 128MB [ 0.278073] gcov: version magic: 0x41383552 [ 0.283022] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.284100] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.285416] pinctrl core: initialized pinctrl subsystem [ 0.286257] [ 0.286997] ************************************************************* [ 0.287020] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.288021] ** ** [ 0.289017] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.290016] ** ** [ 0.291021] ** This means that this kernel is built to expose internal ** [ 0.292016] ** IOMMU data structures, which may compromise security on ** [ 0.293019] ** your system. ** [ 0.294016] ** ** [ 0.295020] ** If you see this message and you are not debugging the ** [ 0.296022] ** kernel, report this immediately to your vendor! ** [ 0.297018] ** ** [ 0.298015] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.299019] ************************************************************* [ 0.300876] NET: Registered protocol family 16 [ 0.303516] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.307087] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.311090] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.316049] cpuidle: using governor menu [ 0.318842] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.321617] PCI: Using configuration type 1 for base access [ 0.324125] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.334057] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.337042] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.340130] cryptd: max_cpu_qlen set to 1000 [ 0.344231] ACPI: Added _OSI(Module Device) [ 0.346022] ACPI: Added _OSI(Processor Device) [ 0.348015] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.349015] ACPI: Added _OSI(Processor Aggregator Device) [ 0.354137] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.361665] ACPI: Interpreter enabled [ 0.363106] ACPI: PM: (supports S0 S3 S4 S5) [ 0.365020] ACPI: Using IOAPIC for interrupt routing [ 0.367166] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.372467] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.383838] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.386056] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.389026] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.392111] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.398602] acpiphp: Slot [2] registered [ 0.399108] acpiphp: Slot [5] registered [ 0.401220] acpiphp: Slot [6] registered [ 0.402130] acpiphp: Slot [3] registered [ 0.404136] acpiphp: Slot [4] registered [ 0.405085] acpiphp: Slot [7] registered [ 0.406172] acpiphp: Slot [8] registered [ 0.408153] acpiphp: Slot [9] registered [ 0.410150] acpiphp: Slot [10] registered [ 0.411208] acpiphp: Slot [11] registered [ 0.413142] acpiphp: Slot [12] registered [ 0.415149] acpiphp: Slot [13] registered [ 0.417141] acpiphp: Slot [14] registered [ 0.418177] acpiphp: Slot [15] registered [ 0.419137] acpiphp: Slot [16] registered [ 0.421129] acpiphp: Slot [17] registered [ 0.423191] acpiphp: Slot [18] registered [ 0.424136] acpiphp: Slot [19] registered [ 0.426126] acpiphp: Slot [20] registered [ 0.428176] acpiphp: Slot [21] registered [ 0.429161] acpiphp: Slot [22] registered [ 0.431145] acpiphp: Slot [23] registered [ 0.433148] acpiphp: Slot [24] registered [ 0.435151] acpiphp: Slot [25] registered [ 0.437152] acpiphp: Slot [26] registered [ 0.438000] acpiphp: Slot [27] registered [ 0.438000] acpiphp: Slot [28] registered [ 0.441199] acpiphp: Slot [29] registered [ 0.442133] acpiphp: Slot [30] registered [ 0.444133] acpiphp: Slot [31] registered [ 0.446085] PCI host bridge to bus 0000:00 [ 0.447026] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.449029] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.451030] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.453025] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.456029] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.458031] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.460227] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.463228] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.466780] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.475019] pci 0000:00:01.1: reg 0x20: [io 0xc120-0xc12f] [ 0.480065] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.483026] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.485021] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.488026] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.490627] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.493774] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.496056] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.500717] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.506023] pci 0000:00:02.0: reg 0x10: [io 0xc100-0xc11f] [ 0.517022] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.521018] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.527523] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.533926] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.539941] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.554852] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.563578] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.571020] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.580016] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.592035] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.603368] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.605348] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.606801] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.609434] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.612278] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.619055] iommu: Default domain type: Passthrough [ 0.626009] SCSI subsystem initialized [ 0.631240] ACPI: bus type USB registered [ 0.635859] usbcore: registered new interface driver usbfs [ 0.638222] usbcore: registered new interface driver hub [ 0.641258] usbcore: registered new device driver usb [ 0.644387] pps_core: LinuxPPS API ver. 1 registered [ 0.646020] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.651123] PTP clock support registered [ 0.655180] EDAC MC: Ver: 3.0.0 [ 0.656000] PCI: Using ACPI for IRQ routing [ 0.658953] NetLabel: Initializing [ 0.661017] NetLabel: domain hash size = 128 [ 0.664019] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.668119] NetLabel: unlabeled traffic allowed by default [ 0.672141] vgaarb: loaded [ 0.680478] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.685019] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.695089] clocksource: Switched to clocksource kvm-clock [ 0.989461] VFS: Disk quotas dquot_6.6.0 [ 0.995331] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 1.000752] *** VALIDATE ramfs *** [ 1.003324] *** VALIDATE hugetlbfs *** [ 1.009978] pnp: PnP ACPI init [ 1.018114] pnp: PnP ACPI: found 6 devices [ 1.068751] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 1.077747] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 1.082432] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 1.086753] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 1.091018] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 1.095939] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 1.101613] NET: Registered protocol family 2 [ 1.106137] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 1.115797] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 1.121992] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 1.135924] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 1.147808] TCP: Hash tables configured (established 65536 bind 65536) [ 1.153902] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 1.160191] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 1.165472] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 1.171278] NET: Registered protocol family 1 [ 1.175787] RPC: Registered named UNIX socket transport module. [ 1.180034] RPC: Registered udp transport module. [ 1.183768] RPC: Registered tcp transport module. [ 1.186919] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 1.190928] NET: Registered protocol family 44 [ 1.194385] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 1.198055] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 1.203099] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 1.211668] PCI: CLS 0 bytes, default 64 [ 1.214503] Unpacking initramfs... [ 1.596012] hrtimer: interrupt took 3993392 ns [ 4.178505] debug: unmapping init [mem 0xffff9f71fcc64000-0xffff9f71fffcffff] [ 4.185910] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 4.198533] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 4.205660] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 5.608568] Initialise system trusted keyrings [ 5.620297] Key type blacklist registered [ 5.623235] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 5.664045] zbud: loaded [ 5.687115] *** VALIDATE nfs *** [ 5.693082] *** VALIDATE nfs4 *** [ 5.700875] pstore: using deflate compression [ 5.728853] Platform Keyring initialized [ 6.024489] NET: Registered protocol family 38 [ 6.026777] Key type asymmetric registered [ 6.028811] Asymmetric key parser 'x509' registered [ 6.031831] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 6.035827] io scheduler mq-deadline registered [ 6.037982] io scheduler kyber registered [ 6.040369] io scheduler bfq registered [ 6.046264] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 6.050557] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 6.054720] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 6.059383] ACPI: Power Button [PWRF] [ 6.066518] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 6.074753] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 6.090977] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 6.130869] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 6.181781] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 6.187943] Non-volatile memory driver v1.3 [ 6.190100] Linux agpgart interface v0.103 [ 6.223639] virtio_blk virtio1: [vda] 68008 512-byte logical blocks (34.8 MB/33.2 MiB) [ 6.228833] vda: detected capacity change from 0 to 34820096 [ 6.250190] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 6.253804] vdb: detected capacity change from 0 to 1073741824 [ 6.260389] libphy: Fixed MDIO Bus: probed [ 6.269592] usbcore: registered new interface driver usbserial_generic [ 6.272777] usbserial: USB Serial support registered for generic [ 6.276550] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 6.283384] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 6.286678] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 6.289741] mousedev: PS/2 mouse device common for all mice [ 6.292837] rtc_cmos 00:05: RTC can wake from S4 [ 6.300373] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 6.301551] rtc_cmos 00:05: registered as rtc0 [ 6.314400] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 6.318589] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 6.320203] intel_pstate: CPU model not supported [ 6.330954] hid: raw HID events driver (C) Jiri Kosina [ 6.343081] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 6.346862] usbcore: registered new interface driver usbhid [ 6.357475] usbhid: USB HID core driver [ 6.359448] drop_monitor: Initializing network drop monitor service [ 6.363846] Initializing XFRM netlink socket [ 6.369697] NET: Registered protocol family 10 [ 6.379352] Segment Routing with IPv6 [ 6.381689] NET: Registered protocol family 17 [ 6.385719] mpls_gso: MPLS GSO support [ 6.393678] RAS: Correctable Errors collector initialized. [ 6.401264] AVX version of gcm_enc/dec engaged. [ 6.405398] AES CTR mode by8 optimization enabled [ 6.570706] sched_clock: Marking stable (6570615142, 0)->(7510504036, -939888894) [ 6.579229] registered taskstats version 1 [ 6.582425] Loading compiled-in X.509 certificates [ 6.584707] zswap: loaded using pool lzo/zbud [ 6.651822] Key type big_key registered [ 6.678639] Key type encrypted registered [ 6.685512] ima: No TPM chip found, activating TPM-bypass! [ 6.692632] ima: Allocated hash algorithm: sha1 [ 6.696281] ima: No architecture policies found [ 6.701394] evm: Initialising EVM extended attributes: [ 6.712865] evm: security.selinux [ 6.719836] evm: security.ima [ 6.721017] evm: security.capability [ 6.728360] evm: HMAC attrs: 0x1 [ 6.734115] rtc_cmos 00:05: setting system clock to 2026-06-12 16:07:33 UTC (1781280453) [ 6.760821] debug: unmapping init [mem 0xffffffffa1e03000-0xffffffffa1ffffff] [ 6.765889] debug: unmapping init [mem 0xffffffffa0b82000-0xffffffffa0e58fff] [ 6.779934] Write protecting the kernel read-only data: 28672k [ 6.789490] debug: unmapping init [mem 0xffffffff9f203000-0xffffffff9f3fffff] [ 6.802033] debug: unmapping init [mem 0xffffffff9fb14000-0xffffffff9fbfffff] [ 6.914659] 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) [ 6.939783] systemd[1]: Detected virtualization kvm. [ 6.948031] systemd[1]: Detected architecture x86-64. [ 6.950656] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 7.008811] systemd[1]: No hostname configured. [ 7.011765] systemd[1]: Set hostname to . [ 7.014810] random: systemd: uninitialized urandom read (16 bytes read) [ 7.020440] systemd[1]: Initializing machine ID from random generator. [ 7.094798] random: ln: uninitialized urandom read (6 bytes read) [ 7.287157] random: systemd: uninitialized urandom read (16 bytes read) [ 7.290587] systemd[1]: Reached target Slices. [ OK ] Reached target Slices. [ 7.310878] systemd[1]: Started Dispatch Password Requests to Console Directory Watch. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ 7.354146] systemd[1]: Reached target Timers. [ OK ] Reached target Timers. [ OK ] Reached target Local File Systems. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Listening on Journal Socket. Starting Create Volatile Files and Directories... Starting Create list of required st…ce nodes for the current kernel... [ OK ] Reached target Initrd Root Device. [ OK ] Listening on Journal Socket (/dev/log). Starting Journal Service... [ OK ] Listening on udev Kernel Socket. Starting Setup Virtual Console... [ OK ] Started Memstrack Anylazing Service. [ OK ] Reached target Paths. [ OK ] Listening on udev Control Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Swap. Starting Apply Kernel Variables... [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Setup Virtual Console. [ OK ] Started Apply Kernel Variables. Starting dracut cmdline hook... Starting Create Static Device Nodes in /dev... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started Journal Service. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 8.600696] device-mapper: uevent: version 1.0.3 [ 8.610249] device-mapper: ioctl: 4.46.0-ioctl (2022-02-22) initialised: dm-devel@redhat.com [ OK ] Started dracut pre-udev hook. Starting udev Kernel Device Manager... [ OK ] Started udev Kernel Device Manager. Starting dracut pre-trigger hook... [ OK ] Started dracut pre-trigger hook. Starting udev Coldplug all Devices... Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. Starting dracut initqueue hook... [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ 10.090255] virtio_net virtio0 ens2: renamed from eth0 [ 10.564819] scsi host0: ata_piix [ 10.608155] scsi host1: ata_piix [ 10.622889] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc120 irq 14 [ 10.628178] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc128 irq 15 [ 15.240456] random: crng init done [ 15.241991] random: 7 urandom warning(s) missed due to ratelimiting [ 15.901588] dracut-initqueue[589]: RTNETLINK answers: File exists Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. Mounting /sysroot... [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. [ 17.726520] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped target Timers. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Slices. [ OK ] Stopped target System Initialization. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. Stopping udev Kernel Device Manager... [ OK ] Stopped target Swap. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped target Paths. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped target Sockets. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Closed udev Control Socket. [ OK ] Closed udev Kernel Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 20.095139] printk: systemd: 26 output lines suppressed due to ratelimiting [ 21.016443] SELinux: Disabled at runtime. [ 21.176502] 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) [ 21.196283] systemd[1]: Detected virtualization kvm. [ 21.207613] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 23.253433] systemd[1]: initrd-switch-root.service: Succeeded. [ 23.265513] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 23.284350] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 23.296473] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 23.306768] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 23.336560] systemd[1]: Starting Journal Service... Starting Journal Service... [ 23.395499] systemd[1]: Mounting POSIX Message Queue File System... Mounting POSIX Message Queue File System... [ OK ] Created slice User and Session Slice. Mounting Huge Pages File System... [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Listening on Process Core Dump Socket. [ OK ] Reached target RPC Port Mapper. Activating swap /dev/disk/by-label/SWAP... [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Listening on udev Kernel Socket. [ 23.761250] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS Starting Create list of required st…ce nodes for the current kernel... [ OK ] Reached target rpc_pipefs.target. [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Stopped target Switch Root. [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Reached target Local Encrypted Volumes. Starting Remount Root and Kernel File Systems... [ OK ] Reached target Slices. [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Stopped target Initrd File Systems. [ OK ] Reached target Paths. [ OK ] Stopped target Initrd Root File System. [ OK ] Created slice system-getty.slice. Starting Apply Kernel Variables... [ OK ] Listening on udev Control Socket. Starting udev Coldplug all Devices... Mounting Kernel Debug File System... [ OK ] Started Journal Service. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Mounted Huge Pages File System. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Started Apply Kernel Variables. [ OK ] Mounted Kernel Debug File System. Starting Configure read-only root support... Starting Create Static Device Nodes in /dev... [ OK ] Reached target Swap. Starting Flush Journal to Persistent Storage... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started udev Coldplug all Devices. [ 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 ] Mounted /mnt. [ 25.038326] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 26.075411] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 26.099693] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 26.861920] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 26.969279] EDAC sbridge: Ver: 1.1.2 [ 30.655794] Key type dns_resolver registered [* ] A start job is running for Configur…-only root support (8s / no limit)[ 31.305213] NFS: Registering the id_resolver key type [ 31.310739] Key type id_resolver registered [ 31.316723] Key type id_legacy registered [** ] A start job is running for Configur…-only root support (8s / no limit) [ OK ] Started Configure read-only root support. Starting Load/Save Random Seed... [ OK ] Reached target Local File Systems. Starting Mark the need to relabel after reboot... Starting Rebuild Dynamic Linker Cache... Starting Create Volatile Files and Directories... [ OK ] Started Load/Save Random Seed. [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Create Volatile Files and Directories. Starting RPC Bind... Starting Update UTMP about System Boot/Shutdown... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Started dnf makecache --timer. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Reached target Timers. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. [ OK ] Started D-Bus System Message Bus. Starting Network Manager... [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting Restore /run/initramfs on shutdown... Starting Login Service... [ OK ] Started irqbalance daemon. [ OK ] Reached target sshd-keygen.target. [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Network Manager. [ OK ] Reached target Network. Starting GSSAPI Proxy Daemon... Starting OpenSSH server daemon... Starting Dynamic System Tuning Daemon... Starting Network Manager Wait Online... [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Started OpenSSH server daemon. [ OK ] Started Login Service. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... Starting Hostname Service... [ OK ] Started Permit User Sessions. [ OK ] Started Serial Getty on ttyS1. [ OK ] Started Command Scheduler. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Getty on tty1. [ OK ] Reached target Login Prompts. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting System Logging Service... Starting Crash recovery kernel arming... Starting Notify NFS peers of a restart... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Starting Authorization Manager... Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg312-client login: [ 87.249305] libcfs: loading out-of-tree module taints kernel. [ 87.600116] alg: No test for adler32 (adler32-zlib) [ 88.362139] Key type ._llcrypt registered [ 88.364312] Key type .llcrypt registered [ 88.838936] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [ 89.562345] Lustre: Lustre: Build Version: 2.15.8_2_g7406dad [ 90.401140] LNet: Added LNI 192.168.203.12@tcp [8/256/0/180] [ 90.412575] LNet: Accept secure, port 988 [ 92.159190] Key type lgssc registered [ 94.524031] Lustre: Echo OBD driver; http://www.lustre.org/ [ 233.871190] Lustre: Mounted lustre-client [ 239.862816] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 259.556177] Lustre: lustre-OST0000-osc-ffff9f72471fb800: disconnect after 23s idle [ 261.049973] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing check_logdir /tmp/testlogs/ [ 266.930356] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing yml_node [ 273.138931] Lustre: DEBUG MARKER: Client: 2.15.8.2 [ 276.908084] Lustre: DEBUG MARKER: MDS: 2.15.8.2 [ 280.730155] Lustre: DEBUG MARKER: OSS: 2.15.8.2 [ 283.051405] Lustre: DEBUG MARKER: -----============= acceptance-small: recovery-small ============----- Fri Jun 12 12:12:07 EDT 2026 [ 295.751404] Lustre: DEBUG MARKER: excepting tests: 136 [ 303.660956] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing check_config_client /mnt/lustre [ 327.724437] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 339.896183] Lustre: DEBUG MARKER: == recovery-small test 1: create, chmod, stat: drop req, drop rep ========================================================== 12:13:05 (1781280785) [ 353.759669] Lustre: 8979:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1781280788/real 1781280788] req@0000000063c4786c x1867808020371712/t0(0) o700->lustre-MDT0000-mdc-ffff9f72471fb800@192.168.203.112@tcp:30/10 lens 264/248 e 0 to 1 dl 1781280800 ref 2 fl Rpc:XQr/0/ffffffff rc 0/-1 job:'mcreate.0' [ 353.774841] Lustre: lustre-MDT0000-mdc-ffff9f72471fb800: Connection to lustre-MDT0000 (at 192.168.203.112@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 353.824054] Lustre: lustre-MDT0000-mdc-ffff9f72471fb800: Connection restored to (at 192.168.203.112@tcp) [ 362.463407] Lustre: 8999:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1781280802/real 1781280802] req@00000000d8b4d757 x1867808020372544/t0(0) o36->lustre-MDT0000-mdc-ffff9f72471fb800@192.168.203.112@tcp:12/10 lens 520/448 e 0 to 1 dl 1781280809 ref 2 fl Rpc:XQr/0/ffffffff rc 0/-1 job:'mcreate.0' [ 362.488222] Lustre: lustre-MDT0000-mdc-ffff9f72471fb800: Connection to lustre-MDT0000 (at 192.168.203.112@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 362.531983] Lustre: lustre-MDT0000-mdc-ffff9f72471fb800: Connection restored to (at 192.168.203.112@tcp) [ 371.679410] Lustre: 9022:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1781280811/real 1781280811] req@000000003cdf1831 x1867808020372928/t0(0) o101->lustre-MDT0000-mdc-ffff9f72471fb800@192.168.203.112@tcp:12/10 lens 576/1152 e 0 to 1 dl 1781280818 ref 2 fl Rpc:XQr/0/ffffffff rc 0/-1 job:'tchmod.0' [ 371.733860] Lustre: lustre-MDT0000-mdc-ffff9f72471fb800: Connection to lustre-MDT0000 (at 192.168.203.112@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 371.794113] Lustre: lustre-MDT0000-mdc-ffff9f72471fb800: Connection restored to (at 192.168.203.112@tcp) [ 380.895547] Lustre: 9040:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1781280820/real 1781280820] req@0000000092c54802 x1867808020373760/t0(0) o36->lustre-MDT0000-mdc-ffff9f72471fb800@192.168.203.112@tcp:12/10 lens 488/512 e 0 to 1 dl 1781280827 ref 2 fl Rpc:XQr/0/ffffffff rc 0/-1 job:'tchmod.0' [ 380.943538] Lustre: lustre-MDT0000-mdc-ffff9f72471fb800: Connection to lustre-MDT0000 (at 192.168.203.112@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 380.998378] Lustre: lustre-MDT0000-mdc-ffff9f72471fb800: Connection restored to (at 192.168.203.112@tcp) [ 389.599499] Lustre: 9064:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1781280829/real 1781280830] req@00000000776d1563 x1867808020374144/t0(0) o34->lustre-MDT0000-mdc-ffff9f72471fb800@192.168.203.112@tcp:12/10 lens 472/728 e 0 to 1 dl 1781280836 ref 2 fl Rpc:XQr/0/ffffffff rc 0/-1 job:'statone.0' [ 389.644631] Lustre: lustre-MDT0000-mdc-ffff9f72471fb800: Connection to lustre-MDT0000 (at 192.168.203.112@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 389.695159] Lustre: lustre-MDT0000-mdc-ffff9f72471fb800: Connection restored to (at 192.168.203.112@tcp) [ 398.304000] Lustre: 9082:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1781280838/real 1781280838] req@00000000e2cc0de1 x1867808020374528/t0(0) o34->lustre-MDT0000-mdc-ffff9f72471fb800@192.168.203.112@tcp:12/10 lens 472/728 e 0 to 1 dl 1781280845 ref 2 fl Rpc:XQr/0/ffffffff rc 0/-1 job:'statone.0' [ 398.379427] Lustre: lustre-MDT0000-mdc-ffff9f72471fb800: Connection to lustre-MDT0000 (at 192.168.203.112@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 398.412349] Lustre: lustre-MDT0000-mdc-ffff9f72471fb800: Connection restored to (at 192.168.203.112@tcp) [ 411.774629] Lustre: DEBUG MARKER: == recovery-small test 4: open: drop req, drop rep ======= 12:14:16 (1781280856) [ 420.831616] Lustre: 9680:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1781280860/real 1781280860] req@00000000b784b308 x1867808020375552/t0(0) o101->lustre-MDT0000-mdc-ffff9f72471fb800@192.168.203.112@tcp:12/10 lens 576/1152 e 0 to 1 dl 1781280867 ref 2 fl Rpc:XQr/0/ffffffff rc 0/-1 job:'cat.0' [ 420.864035] Lustre: lustre-MDT0000-mdc-ffff9f72471fb800: Connection to lustre-MDT0000 (at 192.168.203.112@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 420.932636] Lustre: lustre-MDT0000-mdc-ffff9f72471fb800: Connection restored to (at 192.168.203.112@tcp) [ 437.502544] Lustre: DEBUG MARKER: == recovery-small test 5: rename: drop req, drop rep ===== 12:14:42 (1781280882) [ 455.647803] Lustre: 10314:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1781280895/real 1781280895] req@00000000de263095 x1867808020379328/t0(0) o36->lustre-MDT0000-mdc-ffff9f72471fb800@192.168.203.112@tcp:12/10 lens 552/624 e 0 to 1 dl 1781280902 ref 2 fl Rpc:XQr/0/ffffffff rc 0/-1 job:'mv.0' [ 455.685455] Lustre: 10314:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 455.702597] Lustre: lustre-MDT0000-mdc-ffff9f72471fb800: Connection to lustre-MDT0000 (at 192.168.203.112@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 455.722040] Lustre: Skipped 2 previous similar messages [ 455.771349] Lustre: lustre-MDT0000-mdc-ffff9f72471fb800: Connection restored to (at 192.168.203.112@tcp) [ 455.784422] Lustre: Skipped 2 previous similar messages [ 464.120946] Lustre: DEBUG MARKER: == recovery-small test 6: link, unlink: drop req, drop rep ========================================================== 12:15:09 (1781280909) [ 478.175744] Lustre: lustre-OST0000-osc-ffff9f72471fb800: disconnect after 20s idle [ 478.187907] Lustre: Skipped 1 previous similar message [ 498.393817] Lustre: DEBUG MARKER: == recovery-small test 8: touch: drop rep (bug 1423) ===== 12:15:43 (1781280943) [ 514.416929] Lustre: DEBUG MARKER: == recovery-small test 9: pause bulk on OST (bug 1420) === 12:15:59 (1781280959) [ 530.643425] Lustre: DEBUG MARKER: == recovery-small test 10a: finish request on server after client eviction (bug 1521) ========================================================== 12:16:15 (1781280975) [ 531.173040] Lustre: *** cfs_fail_loc=305, val=0*** [ 542.649587] Lustre: *** cfs_fail_loc=305, val=0*** [ 542.671567] Lustre: Skipped 1 previous similar message [ 547.808350] Lustre: lustre-OST0000-osc-ffff9f72471fb800: disconnect after 23s idle [ 553.868926] Lustre: *** cfs_fail_loc=305, val=0*** [ 553.870753] Lustre: Skipped 1 previous similar message [ 565.150369] Lustre: *** cfs_fail_loc=305, val=0*** [ 565.152436] Lustre: Skipped 1 previous similar message [ 576.425623] Lustre: *** cfs_fail_loc=305, val=0*** [ 587.674513] Lustre: *** cfs_fail_loc=305, val=0*** [ 587.680309] Lustre: Skipped 2 previous similar messages [ 610.144541] Lustre: *** cfs_fail_loc=305, val=0*** [ 610.146423] Lustre: Skipped 2 previous similar messages [ 633.117722] LustreError: 11-0: lustre-MDT0000-mdc-ffff9f72471fb800: operation ldlm_enqueue to node 192.168.203.112@tcp failed: rc = -107 [ 633.125082] Lustre: lustre-MDT0000-mdc-ffff9f72471fb800: Connection to lustre-MDT0000 (at 192.168.203.112@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 633.133377] Lustre: Skipped 4 previous similar messages [ 633.141559] LustreError: lustre-MDT0000-mdc-ffff9f72471fb800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 633.160980] Lustre: lustre-MDT0000-mdc-ffff9f72471fb800: Connection restored to (at 192.168.203.112@tcp) [ 633.173346] Lustre: Skipped 4 previous similar messages [ 641.187273] Lustre: DEBUG MARKER: == recovery-small test 10b: re-send BL AST =============== 12:18:06 (1781281086) [ 662.095674] Lustre: DEBUG MARKER: == recovery-small test 10c: re-send BL AST vs reconnect race (LU-5569) ========================================================== 12:18:27 (1781281107) [ 662.773805] Lustre: *** cfs_fail_loc=305, val=0*** [ 662.775830] Lustre: Skipped 4 previous similar messages [ 670.280595] Lustre: DEBUG MARKER: == recovery-small test 10d: test failed blocking ast ===== 12:18:35 (1781281115) [ 673.543776] Lustre: Unmounted lustre-client [ 674.206845] Lustre: Mounted lustre-client [ 676.567219] LustreError: 11-0: lustre-OST0000-osc-ffff9f724370f800: operation ost_statfs to node 192.168.203.112@tcp failed: rc = -107 [ 676.593547] LustreError: lustre-OST0000-osc-ffff9f724370f800: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 676.614541] Lustre: 2225:0:(llite_lib.c:3595:ll_dirty_page_discard_warn()) lustre: dirty page discard: 192.168.203.112@tcp:/lustre/fid: [0x200000403:0x1:0x0]// may get corrupted (rc -108) [ 679.239448] Lustre: Unmounted lustre-client [ 685.323504] Lustre: DEBUG MARKER: == recovery-small test 10e: re-send BL AST vs reconnect race 2 ========================================================== 12:18:50 (1781281130) [ 687.048943] Lustre: DEBUG MARKER: SKIP: recovery-small test_10e need two clients [ 688.888965] Lustre: DEBUG MARKER: == recovery-small test 11: wake up a thread waiting for completion after eviction (b=2460) ========================================================== 12:18:54 (1781281134) [ 710.535376] Lustre: DEBUG MARKER: == recovery-small test 12: recover from timed out resend in ptlrpcd (b=2494) ========================================================== 12:19:16 (1781281156) [ 710.764884] Lustre: DEBUG MARKER: multiop /mnt/lustre/f12.recovery-small OS_c [ 718.815287] Lustre: 16494:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1781281158/real 1781281158] req@000000008d8da9c1 x1867808020415040/t0(0) o35->lustre-MDT0000-mdc-ffff9f724370f800@192.168.203.112@tcp:23/10 lens 392/624 e 0 to 1 dl 1781281165 ref 2 fl Rpc:XQr/0/ffffffff rc 0/-1 job:'multiop.0' [ 718.840694] Lustre: 16494:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 4 previous similar messages [ 754.745618] Lustre: DEBUG MARKER: == recovery-small test 13: mdc_readpage restart test (bug 1138) ========================================================== 12:20:00 (1781281200) [ 762.335303] Lustre: lustre-MDT0000-mdc-ffff9f724370f800: Connection to lustre-MDT0000 (at 192.168.203.112@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 762.365500] Lustre: Skipped 3 previous similar messages [ 762.388834] Lustre: lustre-MDT0000-mdc-ffff9f724370f800: Connection restored to (at 192.168.203.112@tcp) [ 762.397182] Lustre: Skipped 3 previous similar messages [ 769.911840] Lustre: DEBUG MARKER: == recovery-small test 14: mdc_readpage resend test (bug 1138) ========================================================== 12:20:15 (1781281215) [ 778.419836] Lustre: DEBUG MARKER: == recovery-small test 15: failed open (-ENOMEM) ========= 12:20:23 (1781281223) [ 786.035662] Lustre: DEBUG MARKER: == recovery-small test 16: timeout bulk put, don't evict client (2732) ========================================================== 12:20:31 (1781281231) [ 860.995216] Lustre: DEBUG MARKER: == recovery-small test 17a: timeout bulk get, don't evict client (2732) ========================================================== 12:21:46 (1781281306) [ 915.484595] Lustre: DEBUG MARKER: == recovery-small test 17b: timeout bulk get, dont evict client (3582) ========================================================== 12:22:40 (1781281360) [ 916.948553] Lustre: DEBUG MARKER: SKIP: recovery-small test_17b Needs multiple clients [ 918.730941] Lustre: DEBUG MARKER: == recovery-small test 18a: manual ost invalidate clears page cache immediately ========================================================== 12:22:44 (1781281364) [ 919.765300] Lustre: setting import lustre-OST0001_UUID INACTIVE by administrator request [ 919.874383] LustreError: lustre-OST0001-osc-ffff9f724370f800: This client was evicted by lustre-OST0001; in progress operations using this service will fail. [ 926.023220] Lustre: DEBUG MARKER: == recovery-small test 18b: eviction and reconnect clears page cache (2766) ========================================================== 12:22:51 (1781281371) [ 929.291860] LustreError: lustre-OST0000-osc-ffff9f724370f800: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 959.608745] Lustre: DEBUG MARKER: == recovery-small test 18c: Dropped connect reply after eviction handing (14755) ========================================================== 12:23:24 (1781281404) [ 964.839888] LustreError: 11-0: lustre-OST0000-osc-ffff9f724370f800: operation ost_statfs to node 192.168.203.112@tcp failed: rc = -107 [ 971.254940] Lustre: Evicted from lustre-OST0000_UUID (at 192.168.203.112@tcp) after server handle changed from 0x65ce9a1e9e3e4f14 to 0x65ce9a1e9e3e5048 [ 971.279544] LustreError: lustre-OST0000-osc-ffff9f724370f800: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 981.625404] Lustre: DEBUG MARKER: == recovery-small test 19a: test expired_lock_main on mds (2867) ========================================================== 12:23:46 (1781281426) [ 982.265325] Lustre: Mounted lustre-client [ 982.269809] Lustre: Skipped 1 previous similar message [ 991.711152] Lustre: 2225:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1781281431/real 1781281431] req@000000009c82bb9d x1867808020443456/t0(0) o103->lustre-MDT0000-mdc-ffff9f724370f800@192.168.203.112@tcp:17/18 lens 328/224 e 0 to 1 dl 1781281438 ref 1 fl Rpc:XQr/0/ffffffff rc 0/-1 job:'ldlm_bl_01.0' [ 991.727376] Lustre: 2225:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 1019.361863] Lustre: lustre-MDT0000-mdc-ffff9f724370f800: Connection to lustre-MDT0000 (at 192.168.203.112@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1019.377917] Lustre: Skipped 8 previous similar messages [ 1019.401904] Lustre: lustre-MDT0000-mdc-ffff9f724370f800: Connection restored to (at 192.168.203.112@tcp) [ 1019.416665] Lustre: Skipped 5 previous similar messages [ 1087.269329] LustreError: 11-0: lustre-MDT0000-mdc-ffff9f724370f800: operation ldlm_enqueue to node 192.168.203.112@tcp failed: rc = -107 [ 1087.287275] LustreError: lustre-MDT0000-mdc-ffff9f724370f800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 1087.308837] LustreError: 22703:0:(file.c:5205:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -5 [ 1087.314267] LustreError: 22705:0:(file.c:246:ll_close_inode_openhandle()) lustre-clilmv-ffff9f724370f800: inode [0x200000403:0x1:0x0] mdc close failed: rc = -108 [ 1089.102260] Lustre: Unmounted lustre-client [ 1096.768553] Lustre: DEBUG MARKER: == recovery-small test 19b: test expired_lock_main on ost (2867) ========================================================== 12:25:42 (1781281542) [ 1097.584300] Lustre: Mounted lustre-client [ 1205.086579] Lustre: Unmounted lustre-client [ 1205.241265] LustreError: lustre-OST0001-osc-ffff9f724370f800: This client was evicted by lustre-OST0001; in progress operations using this service will fail. [ 1211.438573] Lustre: DEBUG MARKER: == recovery-small test 19c: check reconnect and lock resend do not trigger expired_lock_main ========================================================== 12:27:36 (1781281656) [ 1211.963568] Lustre: Mounted lustre-client [ 1217.121993] Lustre: Unmounted lustre-client [ 1229.267518] Lustre: DEBUG MARKER: == recovery-small test 20a: ldlm_handle_enqueue error (should return error) ========================================================== 12:27:54 (1781281674) [ 1230.893475] LustreError: 11-0: lustre-OST0000-osc-ffff9f724370f800: operation ldlm_enqueue to node 192.168.203.112@tcp failed: rc = -12 [ 1237.179565] Lustre: DEBUG MARKER: == recovery-small test 20b: ldlm_handle_enqueue error (should return error) ========================================================== 12:28:02 (1781281682) [ 1245.073820] Lustre: DEBUG MARKER: == recovery-small test 21a: drop close request while close and open are both in flight ========================================================== 12:28:10 (1781281690) [ 1255.393270] Lustre: 25965:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1781281695/real 1781281695] req@00000000117c9099 x1867808020479680/t0(0) o35->lustre-MDT0000-mdc-ffff9f724370f800@192.168.203.112@tcp:23/10 lens 392/624 e 0 to 1 dl 1781281702 ref 2 fl Rpc:XQr/0/ffffffff rc 0/-1 job:'multiop.0' [ 1255.423731] Lustre: 25965:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 41 previous similar messages [ 1262.383526] Lustre: DEBUG MARKER: == recovery-small test 21b: drop open request while close and open are both in flight ========================================================== 12:28:28 (1781281708) [ 1405.561530] Lustre: DEBUG MARKER: == recovery-small test 21c: drop both request while close and open are both in flight ========================================================== 12:30:50 (1781281850) [ 1425.660250] Lustre: DEBUG MARKER: == recovery-small test 21d: drop close reply while close and open are both in flight ========================================================== 12:31:11 (1781281871) [ 1445.384378] Lustre: DEBUG MARKER: == recovery-small test 21e: drop open reply while close and open are both in flight ========================================================== 12:31:30 (1781281890) [ 1578.975329] Lustre: lustre-MDT0000-mdc-ffff9f724370f800: Connection to lustre-MDT0000 (at 192.168.203.112@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1578.995104] Lustre: Skipped 29 previous similar messages [ 1579.012793] Lustre: lustre-MDT0000-mdc-ffff9f724370f800: Connection restored to (at 192.168.203.112@tcp) [ 1579.024647] Lustre: Skipped 28 previous similar messages [ 1580.524396] Lustre: DEBUG MARKER: == recovery-small test 21f: drop both reply while close and open are both in flight ========================================================== 12:33:46 (1781282026) [ 1597.751711] Lustre: DEBUG MARKER: == recovery-small test 21g: drop open reply and close request while close and open are both in flight ========================================================== 12:34:03 (1781282043) [ 1614.875243] Lustre: DEBUG MARKER: == recovery-small test 21h: drop open request and close reply while close and open are both in flight ========================================================== 12:34:20 (1781282060) [ 1631.099120] Lustre: DEBUG MARKER: == recovery-small test 22: drop close request and do mknod ========================================================== 12:34:36 (1781282076) [ 1644.064708] Lustre: DEBUG MARKER: == recovery-small test 23: client hang when close a file after mds crash ========================================================== 12:34:49 (1781282089) [ 1660.319306] LustreError: 166-1: MGC192.168.203.112@tcp: Connection to MGS (at 192.168.203.112@tcp) was lost; in progress operations using this service will fail [ 1677.673654] Lustre: Evicted from MGS (at 192.168.203.112@tcp) after server handle changed from 0x65ce9a1e9e3e46bd to 0x65ce9a1e9e3e66e5 [ 1695.926951] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1697.201773] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1704.934557] Lustre: DEBUG MARKER: == recovery-small test 24a: fsync error (should return error) ========================================================== 12:35:50 (1781282150) [ 1706.429346] LustreError: 11-0: lustre-OST0000-osc-ffff9f724370f800: operation ost_write to node 192.168.203.112@tcp failed: rc = -107 [ 1706.443254] LustreError: Skipped 1 previous similar message [ 1706.459669] LustreError: lustre-OST0000-osc-ffff9f724370f800: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 1706.470049] Lustre: 2227:0:(llite_lib.c:3595:ll_dirty_page_discard_warn()) lustre: dirty page discard: 192.168.203.112@tcp:/lustre/fid: [0x200000404:0x30:0x0]// may get corrupted (rc -5) [ 1713.741641] Lustre: DEBUG MARKER: == recovery-small test 24b: test dirty page discard due to client eviction ========================================================== 12:35:59 (1781282159) [ 1715.177588] LustreError: lustre-OST0000-osc-ffff9f724370f800: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 1715.211431] Lustre: 2226:0:(llite_lib.c:3595:ll_dirty_page_discard_warn()) lustre: dirty page discard: 192.168.203.112@tcp:/lustre/fid: [0x200000404:0x35:0x0]// may get corrupted (rc -108) [ 1716.909965] Lustre: DEBUG MARKER: recovery-small test_24b: @@@@@@ IGNORE (bz5494): multiop didn't fail fsync: 5 or close: 0 [ 1723.593873] Lustre: DEBUG MARKER: == recovery-small test 26a: evict dead exports =========== 12:36:09 (1781282169) [ 1725.424609] Lustre: DEBUG MARKER: SKIP: recovery-small test_26a msg and ost1 are at the same node [ 1727.353265] Lustre: DEBUG MARKER: == recovery-small test 26b: evict dead exports =========== 12:36:12 (1781282172) [ 1728.662221] Lustre: DEBUG MARKER: SKIP: recovery-small test_26b msg and ost1 are at the same node [ 1730.173975] Lustre: DEBUG MARKER: == recovery-small test 27: fail LOV while using OSC's ==== 12:36:15 (1781282175) [ 1733.605156] LustreError: 11-0: lustre-MDT0000-mdc-ffff9f724370f800: operation mds_reint to node 192.168.203.112@tcp failed: rc = -19 [ 1733.618119] LustreError: Skipped 1 previous similar message [ 1756.644694] LustreError: 166-1: MGC192.168.203.112@tcp: Connection to MGS (at 192.168.203.112@tcp) was lost; in progress operations using this service will fail [ 1756.667105] Lustre: Evicted from MGS (at 192.168.203.112@tcp) after server handle changed from 0x65ce9a1e9e3e66e5 to 0x65ce9a1e9e3e861f [ 1853.765347] LustreError: 11-0: lustre-MDT0000-mdc-ffff9f724370f800: operation ldlm_enqueue to node 192.168.203.112@tcp failed: rc = -19 [ 1853.777751] LustreError: Skipped 1 previous similar message [ 1862.111403] Lustre: 2226:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1781282301/real 1781282301] req@000000003d9aec49 x1867808021693696/t0(0) o400->MGC192.168.203.112@tcp@192.168.203.112@tcp:26/25 lens 224/224 e 0 to 1 dl 1781282308 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:3.0' [ 1862.161481] Lustre: 2226:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 11 previous similar messages [ 1862.168366] LustreError: 166-1: MGC192.168.203.112@tcp: Connection to MGS (at 192.168.203.112@tcp) was lost; in progress operations using this service will fail [ 1878.518961] Lustre: Evicted from MGS (at 192.168.203.112@tcp) after server handle changed from 0x65ce9a1e9e3e861f to 0x65ce9a1e9e41045a [ 1910.009895] Lustre: DEBUG MARKER: == recovery-small test 28: handle error adding new clients (bug 6086) ========================================================== 12:39:15 (1781282355) [ 1910.501889] Lustre: *** cfs_fail_loc=305, val=0*** [ 1910.503713] Lustre: Skipped 2 previous similar messages [ 1925.081324] LustreError: 11-0: lustre-OST0000-osc-ffff9f724370f800: operation ost_connect to node 192.168.203.112@tcp failed: rc = -75 [ 1942.431221] LustreError: 166-1: MGC192.168.203.112@tcp: Connection to MGS (at 192.168.203.112@tcp) was lost; in progress operations using this service will fail [ 1959.996793] Lustre: Evicted from MGS (at 192.168.203.112@tcp) after server handle changed from 0x65ce9a1e9e41045a to 0x65ce9a1e9e410cf7 [ 1971.201834] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1972.995903] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1980.342346] Lustre: DEBUG MARKER: == recovery-small test 29a: error adding new clients doesn't cause LBUG (bug 22273) ========================================================== 12:40:25 (1781282425) [ 1990.646201] LustreError: 166-1: MGC192.168.203.112@tcp: Connection to MGS (at 192.168.203.112@tcp) was lost; in progress operations using this service will fail [ 1990.685970] Lustre: Evicted from MGS (at 192.168.203.112@tcp) after server handle changed from 0x65ce9a1e9e410cf7 to 0x65ce9a1e9e410e55 [ 1992.648996] LustreError: lustre-MDT0000-mdc-ffff9f724370f800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 2014.179121] Lustre: DEBUG MARKER: == recovery-small test 29b: error adding new clients doesn't cause LBUG (bug 22273) ========================================================== 12:40:59 (1781282459) [ 2031.601092] LustreError: lustre-OST0000-osc-ffff9f724370f800: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 2042.277427] Lustre: DEBUG MARKER: == recovery-small test 50: failover MDS under load ======= 12:41:27 (1781282487) [ 2055.364497] LustreError: 11-0: lustre-MDT0000-mdc-ffff9f724370f800: operation mds_reint to node 192.168.203.112@tcp failed: rc = -19 [ 2063.333533] LustreError: 166-1: MGC192.168.203.112@tcp: Connection to MGS (at 192.168.203.112@tcp) was lost; in progress operations using this service will fail [ 2080.748346] Lustre: Evicted from MGS (at 192.168.203.112@tcp) after server handle changed from 0x65ce9a1e9e410e55 to 0x65ce9a1e9e4172fc [ 2114.088675] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2116.509726] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2181.270227] Lustre: lustre-MDT0000-mdc-ffff9f724370f800: Connection to lustre-MDT0000 (at 192.168.203.112@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 2181.282985] Lustre: Skipped 13 previous similar messages [ 2192.351453] LustreError: 166-1: MGC192.168.203.112@tcp: Connection to MGS (at 192.168.203.112@tcp) was lost; in progress operations using this service will fail [ 2209.704888] Lustre: Evicted from MGS (at 192.168.203.112@tcp) after server handle changed from 0x65ce9a1e9e4172fc to 0x65ce9a1e9e438199 [ 2209.710869] Lustre: MGC192.168.203.112@tcp: Connection restored to 192.168.203.112@tcp (at 192.168.203.112@tcp) [ 2209.715390] Lustre: Skipped 17 previous similar messages [ 2222.785714] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2224.664820] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2301.856026] LustreError: 166-1: MGC192.168.203.112@tcp: Connection to MGS (at 192.168.203.112@tcp) was lost; in progress operations using this service will fail [ 2318.265359] Lustre: Evicted from MGS (at 192.168.203.112@tcp) after server handle changed from 0x65ce9a1e9e438199 to 0x65ce9a1e9e45c25c [ 2338.216126] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2340.652346] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2369.472600] Lustre: DEBUG MARKER: == recovery-small test 51: failover MDS during recovery == 12:46:54 (1781282814) [ 2373.315352] LustreError: 11-0: lustre-MDT0000-mdc-ffff9f724370f800: operation mds_reint to node 192.168.203.112@tcp failed: rc = -19 [ 2373.329351] LustreError: Skipped 5 previous similar messages [ 2384.799218] LustreError: 166-1: MGC192.168.203.112@tcp: Connection to MGS (at 192.168.203.112@tcp) was lost; in progress operations using this service will fail [ 2402.160039] Lustre: Evicted from MGS (at 192.168.203.112@tcp) after server handle changed from 0x65ce9a1e9e45c25c to 0x65ce9a1e9e46f694 [ 2408.732899] Lustre: DEBUG MARKER: test_51: failover in 1 sec [ 2448.416282] Lustre: DEBUG MARKER: test_51: failover in 5 sec [ 2465.760664] Lustre: 2227:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1781282905/real 1781282905] req@00000000abbad17a x1867808024585984/t0(0) o400->MGC192.168.203.112@tcp@192.168.203.112@tcp:26/25 lens 224/224 e 0 to 1 dl 1781282912 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:1.0' [ 2465.795706] Lustre: 2227:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 11 previous similar messages [ 2490.727181] Lustre: DEBUG MARKER: test_51: failover in 10 sec [ 2513.888000] LustreError: 166-1: MGC192.168.203.112@tcp: Connection to MGS (at 192.168.203.112@tcp) was lost; in progress operations using this service will fail [ 2513.896785] LustreError: Skipped 2 previous similar messages [ 2530.277600] Lustre: Evicted from MGS (at 192.168.203.112@tcp) after server handle changed from 0x65ce9a1e9e4787aa to 0x65ce9a1e9e4807e8 [ 2530.295842] Lustre: Skipped 2 previous similar messages [ 2540.213601] Lustre: DEBUG MARKER: test_51: failover in 20 sec [ 2600.473733] Lustre: DEBUG MARKER: test_51: failover in 25 sec [ 2666.599304] Lustre: DEBUG MARKER: test_51: failover in 30 sec [ 2761.683981] Lustre: DEBUG MARKER: == recovery-small test 52: failover OST under load ======= 12:53:26 (1781283206) [ 2812.208059] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 2814.601814] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 3107.357832] LustreError: 11-0: lustre-OST0000-osc-ffff9f724370f800: operation ldlm_enqueue to node 192.168.203.112@tcp failed: rc = -19 [ 3107.377242] LustreError: Skipped 8 previous similar messages [ 3107.382742] Lustre: lustre-OST0000-osc-ffff9f724370f800: Connection to lustre-OST0000 (at 192.168.203.112@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 3107.410396] Lustre: Skipped 9 previous similar messages [ 3157.025403] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 3159.988742] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 3485.310033] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 3487.981355] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 3734.952269] Lustre: DEBUG MARKER: == recovery-small test 53a: touch: drop rep ============== 13:09:40 (1781284180) [ 3781.599161] Lustre: 49912:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1781284183/real 1781284183] req@0000000080c20894 x1867808035554944/t0(0) o101->lustre-MDT0000-mdc-ffff9f724370f800@192.168.203.112@tcp:12/10 lens 648/66264 e 0 to 1 dl 1781284227 ref 2 fl Rpc:XPQr/0/ffffffff rc 0/-1 job:'openfile.0' [ 3781.630221] Lustre: 49912:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 4 previous similar messages [ 3781.638384] Lustre: lustre-MDT0000-mdc-ffff9f724370f800: Connection to lustre-MDT0000 (at 192.168.203.112@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 3781.655963] Lustre: Skipped 1 previous similar message [ 3781.715602] Lustre: lustre-MDT0000-mdc-ffff9f724370f800: Connection restored to 192.168.203.112@tcp (at 192.168.203.112@tcp) [ 3781.737039] Lustre: Skipped 18 previous similar messages [ 3792.032382] Lustre: DEBUG MARKER: == recovery-small test 53b: touch: drop rep ============== 13:10:37 (1781284237) [ 3850.046712] Lustre: DEBUG MARKER: == recovery-small test 53c: touch: drop rep ============== 13:11:35 (1781284295) [ 3896.290460] Lustre: 51268:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1781284298/real 1781284298] req@000000005ef40315 x1867808035560960/t0(0) o101->lustre-MDT0000-mdc-ffff9f724370f800@192.168.203.112@tcp:12/10 lens 664/66264 e 0 to 1 dl 1781284342 ref 2 fl Rpc:XPQr/0/ffffffff rc 0/-1 job:'openfile.0' [ 3896.329523] Lustre: 51268:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 3896.384231] Lustre: lustre-MDT0000-mdc-ffff9f724370f800: Connection restored to 192.168.203.112@tcp (at 192.168.203.112@tcp) [ 3896.388453] Lustre: Skipped 1 previous similar message [ 3904.455014] Lustre: DEBUG MARKER: == recovery-small test 54: back in time ================== 13:12:29 (1781284349) [ 3904.859146] Lustre: Mounted lustre-client [ 3927.519332] LustreError: 166-1: MGC192.168.203.112@tcp: Connection to MGS (at 192.168.203.112@tcp) was lost; in progress operations using this service will fail [ 3927.527898] LustreError: Skipped 3 previous similar messages [ 3944.953755] Lustre: Evicted from MGS (at 192.168.203.112@tcp) after server handle changed from 0x65ce9a1e9e4a856d to 0x65ce9a1e9e6059ea [ 3944.978078] Lustre: Skipped 3 previous similar messages [ 3964.518779] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3966.396668] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3968.667932] Lustre: Unmounted lustre-client [ 3976.710077] Lustre: DEBUG MARKER: == recovery-small test 55: ost_brw_read/write drops timed-out read/write request ========================================================== 13:13:41 (1781284421) [ 4050.399157] Lustre: 2227:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1781284490/real 1781284490] req@0000000091386379 x1867808035591808/t0(0) o4->lustre-OST0000-osc-ffff9f724370f800@192.168.203.112@tcp:6/4 lens 488/448 e 0 to 1 dl 1781284497 ref 2 fl Rpc:XQr/2/ffffffff rc -11/-1 job:'dd.0' [ 4050.442903] Lustre: 2227:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 47 previous similar messages [ 4050.496710] Lustre: lustre-OST0000-osc-ffff9f724370f800: Connection restored to 192.168.203.112@tcp (at 192.168.203.112@tcp) [ 4050.517927] Lustre: Skipped 9 previous similar messages [ 4285.818010] Lustre: DEBUG MARKER: == recovery-small test 56: do not fail on getattr resend ========================================================== 13:18:50 (1781284730) [ 4336.060643] Lustre: DEBUG MARKER: == recovery-small test 57: read procfs entries causes kernel crash ========================================================== 13:19:41 (1781284781) [ 4340.030626] Lustre: Unmounted lustre-client [ 4364.358604] Lustre: Mounted lustre-client [ 4371.911235] Lustre: DEBUG MARKER: == recovery-small test 58: Eviction in the middle of open RPC reply processing ========================================================== 13:20:17 (1781284817) [ 4372.599498] LustreError: 55883:0:(fail.c:138:__cfs_fail_timeout_set()) cfs_fail_timeout id 801 sleeping for 20000ms [ 4373.647144] LustreError: 55883:0:(fail.c:144:__cfs_fail_timeout_set()) cfs_fail_timeout interrupted [ 4373.866875] Lustre: *** cfs_fail_loc=305, val=0*** [ 4393.319115] Lustre: DEBUG MARKER: == recovery-small test 59: Read cancel race on client eviction ========================================================== 13:20:38 (1781284838) [ 4393.792952] Lustre: Mounted lustre-client [ 4398.588232] Lustre: setting import lustre-MDT0000_UUID INACTIVE by administrator request [ 4408.974837] Lustre: Unmounted lustre-client [ 4417.245814] Lustre: DEBUG MARKER: == recovery-small test 60: Add Changelog entries during MDS failover ========================================================== 13:21:02 (1781284862) [ 4509.913298] LustreError: 11-0: lustre-MDT0000-mdc-ffff9f7245257800: operation mds_reint to node 192.168.203.112@tcp failed: rc = -19 [ 4509.930244] LustreError: Skipped 1 previous similar message [ 4509.937732] Lustre: lustre-MDT0000-mdc-ffff9f7245257800: Connection to lustre-MDT0000 (at 192.168.203.112@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 4509.954300] Lustre: Skipped 42 previous similar messages [ 4519.903157] Lustre: 2226:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1781284959/real 1781284959] req@00000000a0c95eb5 x1867808036977216/t0(0) o400->MGC192.168.203.112@tcp@192.168.203.112@tcp:26/25 lens 224/224 e 0 to 1 dl 1781284966 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:2.0' [ 4519.928695] Lustre: 2226:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 250 previous similar messages [ 4519.950918] LustreError: 166-1: MGC192.168.203.112@tcp: Connection to MGS (at 192.168.203.112@tcp) was lost; in progress operations using this service will fail [ 4536.290561] Lustre: Evicted from MGS (at 192.168.203.112@tcp) after server handle changed from 0x65ce9a1e9e606295 to 0x65ce9a1e9e631805 [ 4536.315146] Lustre: MGC192.168.203.112@tcp: Connection restored to (at 192.168.203.112@tcp) [ 4536.323418] Lustre: Skipped 30 previous similar messages [ 4686.477305] Lustre: DEBUG MARKER: == recovery-small test 61: Verify to not reuse orphan objects - bug 17025 ========================================================== 13:25:31 (1781285131) [ 4692.038556] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4705.247297] LustreError: 166-1: MGC192.168.203.112@tcp: Connection to MGS (at 192.168.203.112@tcp) was lost; in progress operations using this service will fail [ 4705.287605] Lustre: Evicted from MGS (at 192.168.203.112@tcp) after server handle changed from 0x65ce9a1e9e631805 to 0x65ce9a1e9e67dc3c [ 4710.475276] LustreError: lustre-MDT0000-mdc-ffff9f7245257800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 4728.950773] Lustre: DEBUG MARKER: == recovery-small test 65: lock enqueue for destroyed export ========================================================== 13:26:14 (1781285174) [ 4729.514873] Lustre: Mounted lustre-client [ 4736.830242] LustreError: 11-0: lustre-OST0000-osc-ffff9f7245257800: operation ldlm_enqueue to node 192.168.203.112@tcp failed: rc = -107 [ 4736.859229] LustreError: lustre-OST0000-osc-ffff9f7245257800: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 4745.964068] Lustre: Unmounted lustre-client [ 4753.108840] Lustre: DEBUG MARKER: == recovery-small test 66: lock enqueue re-send vs client eviction ========================================================== 13:26:38 (1781285198) [ 4763.637456] LustreError: lustre-MDT0000-mdc-ffff9f7245257800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 4763.652094] LustreError: 60307:0:(file.c:5205:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 4771.395874] Lustre: DEBUG MARKER: == recovery-small test 67: connect vs import invalidate race ========================================================== 13:26:56 (1781285216) [ 4771.610438] LustreError: 60925:0:(libcfs_fail.h:169:cfs_race()) cfs_race id 531 sleeping [ 4775.592855] LustreError: lustre-MDT0000-mdc-ffff9f7245257800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 4775.600685] LustreError: 60943:0:(libcfs_fail.h:180:cfs_race()) cfs_fail_race id 531 waking [ 4775.605916] LustreError: 60925:0:(libcfs_fail.h:178:cfs_race()) cfs_fail_race id 531 awake: rc=1010 [ 4775.616753] LustreError: 60925:0:(import.c:702:ptlrpc_connect_import_locked()) already connecting [ 4775.664675] LustreError: 60948:0:(file.c:5205:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 4776.779465] LustreError: 60959:0:(file.c:5205:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 4779.042536] LustreError: 60982:0:(file.c:5205:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 4779.054571] LustreError: 60982:0:(file.c:5205:ll_inode_revalidate_fini()) Skipped 1 previous similar message [ 4783.663828] LustreError: 61026:0:(file.c:5205:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 4783.678617] LustreError: 61026:0:(file.c:5205:ll_inode_revalidate_fini()) Skipped 3 previous similar messages [ 4793.429494] Lustre: DEBUG MARKER: == recovery-small test 100: IR: Make sure normal recovery still works w/o IR ========================================================== 13:27:18 (1781285238) [ 4830.956274] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 4832.844600] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4844.491858] Lustre: DEBUG MARKER: == recovery-small test 101a: IR: Make sure IR works w/o normal recovery ========================================================== 13:28:09 (1781285289) [ 4881.292563] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 4882.679608] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4893.041072] Lustre: DEBUG MARKER: == recovery-small test 101b: IR: Make sure IR works w/o normal recovery and proceed EAGAIN ========================================================== 13:28:58 (1781285338) [ 4957.223299] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 4959.091760] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4968.084568] Lustre: DEBUG MARKER: == recovery-small test 102: IR: New client gets updated nidtbl after MGS restart ========================================================== 13:30:13 (1781285413) [ 5006.336538] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 5008.434228] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 5015.186572] Lustre: Unmounted lustre-client [ 5068.316137] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 5071.141227] Lustre: Mounted lustre-client [ 5078.462795] Lustre: DEBUG MARKER: == recovery-small test 103: IR: MDS can start w/o MGS and get updated nidtbl later ========================================================== 13:32:03 (1781285523) [ 5081.392573] Lustre: DEBUG MARKER: SKIP: recovery-small test_103 needs separate mgs and mds [ 5083.335220] Lustre: DEBUG MARKER: == recovery-small test 104: IR: ost can disable IR voluntarily ========================================================== 13:32:08 (1781285528) [ 5091.826837] LustreError: 11-0: lustre-OST0000-osc-ffff9f7245e31800: operation ost_disconnect to node 192.168.203.112@tcp failed: rc = -107 [ 5091.843384] LustreError: Skipped 1 previous similar message [ 5111.391413] Lustre: DEBUG MARKER: == recovery-small test 105: IR: NON IR clients support === 13:32:36 (1781285556) [ 5113.506983] Lustre: DEBUG MARKER: SKIP: recovery-small test_105 Needs multiple clients [ 5116.132354] Lustre: DEBUG MARKER: == recovery-small test 106: lightweight connection support ========================================================== 13:32:40 (1781285560) [ 5117.658309] Lustre: *** cfs_fail_loc=805, val=0*** [ 5117.694835] Lustre: Mounted lustre-client [ 5122.981699] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5134.303871] Lustre: 2227:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1781285574/real 1781285574] req@00000000859dca6f x1867808037998336/t0(0) o400->MGC192.168.203.112@tcp@192.168.203.112@tcp:26/25 lens 224/224 e 0 to 1 dl 1781285581 ref 1 fl Rpc:XNQr/0/ffffffff rc 0/-1 job:'kworker/u8:3.0' [ 5134.347195] Lustre: 2227:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 5134.355193] LustreError: 166-1: MGC192.168.203.112@tcp: Connection to MGS (at 192.168.203.112@tcp) was lost; in progress operations using this service will fail [ 5134.381266] Lustre: lustre-MDT0000-mdc-ffff9f7244c0f800: Connection to lustre-MDT0000 (at 192.168.203.112@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 5134.403699] Lustre: Skipped 12 previous similar messages [ 5151.730937] Lustre: Evicted from MGS (at 192.168.203.112@tcp) after server handle changed from 0x65ce9a1e9e67ed76 to 0x65ce9a1e9e67f158 [ 5151.740599] Lustre: MGC192.168.203.112@tcp: Connection restored to (at 192.168.203.112@tcp) [ 5151.748088] Lustre: Skipped 12 previous similar messages [ 5160.125327] Lustre: Unmounted lustre-client [ 5167.847554] Lustre: DEBUG MARKER: == recovery-small test 107: drop reint reply, then restart MDT ========================================================== 13:33:33 (1781285613) [ 5204.970791] LustreError: 2224:0:(client.c:3161:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@000000002bf59fcb x1867808038004032/t94489280516(94489280516) o101->lustre-MDT0000-mdc-ffff9f7245e31800@192.168.203.112@tcp:12/10 lens 664/600 e 0 to 0 dl 1781285658 ref 2 fl Interpret:RPQU/4/0 rc 301/301 job:'multiop.0' [ 5216.441633] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 5218.307605] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5227.883855] Lustre: DEBUG MARKER: == recovery-small test 108: client eviction don't crash == 13:34:33 (1781285673) [ 5229.381481] LustreError: lustre-OST0000-osc-ffff9f7245e31800: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 5229.396314] Lustre: 2227:0:(llite_lib.c:3595:ll_dirty_page_discard_warn()) lustre: dirty page discard: 192.168.203.112@tcp:/lustre/fid: [0x20000a042:0x6:0x0]// may get corrupted (rc -5) [ 5229.439772] LustreError: 72284:0:(ldlm_resource.c:1127:ldlm_resource_complain()) lustre-OST0000-osc-ffff9f7245e31800: namespace resource [0x4522:0x0:0x0].0x0 (00000000a23bc15b) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 5238.005319] Lustre: DEBUG MARKER: == recovery-small test 110a: create remote directory: drop client req ========================================================== 13:34:43 (1781285683) [ 5239.677103] Lustre: DEBUG MARKER: SKIP: recovery-small test_110a needs >= 2 MDTs [ 5241.638783] Lustre: DEBUG MARKER: == recovery-small test 110b: create remote directory: drop Master rep ========================================================== 13:34:46 (1781285686) [ 5243.510837] Lustre: DEBUG MARKER: SKIP: recovery-small test_110b needs >= 2 MDTs [ 5245.616707] Lustre: DEBUG MARKER: == recovery-small test 110c: create remote directory: drop update rep on slave MDT ========================================================== 13:34:50 (1781285690) [ 5247.350284] Lustre: DEBUG MARKER: SKIP: recovery-small test_110c needs >= 2 MDTs [ 5249.108520] Lustre: DEBUG MARKER: == recovery-small test 110d: remove remote directory: drop client req ========================================================== 13:34:54 (1781285694) [ 5250.837702] Lustre: DEBUG MARKER: SKIP: recovery-small test_110d needs >= 2 MDTs [ 5252.576288] Lustre: DEBUG MARKER: == recovery-small test 110e: remove remote directory: drop master rep ========================================================== 13:34:57 (1781285697) [ 5254.373251] Lustre: DEBUG MARKER: SKIP: recovery-small test_110e needs >= 2 MDTs [ 5256.588614] Lustre: DEBUG MARKER: == recovery-small test 110f: remove remote directory: drop slave rep ========================================================== 13:35:01 (1781285701) [ 5258.177496] Lustre: DEBUG MARKER: SKIP: recovery-small test_110f needs >= 2 MDTs [ 5260.259684] Lustre: DEBUG MARKER: == recovery-small test 110g: drop reply during migration ========================================================== 13:35:05 (1781285705) [ 5261.756981] Lustre: DEBUG MARKER: SKIP: recovery-small test_110g needs >= 2 MDTs [ 5263.657722] Lustre: DEBUG MARKER: == recovery-small test 110h: drop update reply during cross-MDT file rename ========================================================== 13:35:08 (1781285708) [ 5265.410601] Lustre: DEBUG MARKER: SKIP: recovery-small test_110h needs >= 2 MDTs [ 5267.811628] Lustre: DEBUG MARKER: == recovery-small test 110i: drop update reply during cross-MDT dir rename ========================================================== 13:35:12 (1781285712) [ 5269.866050] Lustre: DEBUG MARKER: SKIP: recovery-small test_110i needs >= 2 MDTs [ 5271.919121] Lustre: DEBUG MARKER: == recovery-small test 110j: drop update reply during cross-MDT ln ========================================================== 13:35:16 (1781285716) [ 5273.711549] Lustre: DEBUG MARKER: SKIP: recovery-small test_110j needs >= 2 MDTs [ 5275.335847] Lustre: DEBUG MARKER: == recovery-small test 110k: FID_QUERY failed during recovery ========================================================== 13:35:20 (1781285720) [ 5276.925175] Lustre: DEBUG MARKER: SKIP: recovery-small test_110k needs >= 2 MDTS [ 5278.750384] Lustre: DEBUG MARKER: == recovery-small test 110m: update resent vs original RPC race ========================================================== 13:35:24 (1781285724) [ 5281.467651] Lustre: DEBUG MARKER: SKIP: recovery-small test_110m needs at least 2 MDTs [ 5282.962768] Lustre: DEBUG MARKER: == recovery-small test 111: mdd setup fail should not cause umount oops ========================================================== 13:35:28 (1781285728) [ 5314.453562] Lustre: DEBUG MARKER: == recovery-small test 112a: bulk resend while orignal request is in progress ========================================================== 13:35:59 (1781285759) [ 5344.398310] Lustre: DEBUG MARKER: == recovery-small test 115a: read: late REQ MDunlink and no bulk ========================================================== 13:36:29 (1781285789) [ 5345.059785] Lustre: *** cfs_fail_loc=51b, val=0*** [ 5355.178501] Lustre: DEBUG MARKER: == recovery-small test 115b: write: late REQ MDunlink and no bulk ========================================================== 13:36:40 (1781285800) [ 5355.424464] Lustre: *** cfs_fail_loc=51b, val=0*** [ 5365.848306] Lustre: DEBUG MARKER: == recovery-small test 115c: read: late Reply MDunlink and no bulk ========================================================== 13:36:51 (1781285811) [ 5366.222117] Lustre: *** cfs_fail_loc=50f, val=0*** [ 5374.752742] Lustre: DEBUG MARKER: == recovery-small test 115d: write: late Reply MDunlink and no bulk ========================================================== 13:37:00 (1781285820) [ 5375.061555] Lustre: *** cfs_fail_loc=50f, val=0*** [ 5384.928345] Lustre: DEBUG MARKER: == recovery-small test 115e: read: late Bulk MDunlink and no reply ========================================================== 13:37:10 (1781285830) [ 5385.422485] Lustre: *** cfs_fail_loc=510, val=0*** [ 5394.767509] Lustre: DEBUG MARKER: == recovery-small test 115f: read: late REQ MDunlink and no reply ========================================================== 13:37:19 (1781285839) [ 5395.233118] Lustre: *** cfs_fail_loc=51b, val=0*** [ 5450.711850] Lustre: DEBUG MARKER: == recovery-small test 115g: read: late REQ MDunlink and Reply MDunlink ========================================================== 13:38:16 (1781285896) [ 5451.105949] Lustre: *** cfs_fail_loc=51c, val=0*** [ 5506.816810] Lustre: DEBUG MARKER: == recovery-small test 120: flock race: completion vs. evict ========================================================== 13:39:12 (1781285952) [ 5507.334184] LustreError: 82389:0:(fail.c:138:__cfs_fail_timeout_set()) cfs_fail_timeout id 320 sleeping for 4000ms [ 5510.218978] LustreError: 11-0: lustre-MDT0000-mdc-ffff9f7245e31800: operation ldlm_enqueue to node 192.168.203.112@tcp failed: rc = -107 [ 5510.228457] LustreError: Skipped 1 previous similar message [ 5510.254056] LustreError: lustre-MDT0000-mdc-ffff9f7245e31800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5510.277364] LustreError: 82406:0:(file.c:246:ll_close_inode_openhandle()) lustre-clilmv-ffff9f7245e31800: inode [0x20000a042:0x9:0x0] mdc close failed: rc = -108 [ 5510.304363] LustreError: 82406:0:(ldlm_resource.c:1127:ldlm_resource_complain()) lustre-MDT0000-mdc-ffff9f7245e31800: namespace resource [0x20000a042:0xf:0x0].0xc (00000000af42153f) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 5511.415679] LustreError: 82389:0:(fail.c:149:__cfs_fail_timeout_set()) cfs_fail_timeout id 320 awake [ 5513.546850] LustreError: 82421:0:(fail.c:138:__cfs_fail_timeout_set()) cfs_fail_timeout id 320 sleeping for 4000ms [ 5516.615129] LustreError: lustre-MDT0000-mdc-ffff9f7245e31800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5516.631446] LustreError: 82439:0:(ldlm_resource.c:1127:ldlm_resource_complain()) lustre-MDT0000-mdc-ffff9f7245e31800: namespace resource [0x20000a042:0xf:0x0].0xc (00000000e8d9355f) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 5516.649306] LustreError: 82439:0:(ldlm_resource.c:1127:ldlm_resource_complain()) Skipped 1 previous similar message [ 5517.624830] LustreError: 82421:0:(fail.c:149:__cfs_fail_timeout_set()) cfs_fail_timeout id 320 awake [ 5521.632869] LustreError: 82452:0:(fail.c:138:__cfs_fail_timeout_set()) cfs_fail_timeout id 320 sleeping for 4000ms [ 5524.817649] LustreError: lustre-MDT0000-mdc-ffff9f7245e31800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5524.847613] LustreError: 82469:0:(ldlm_resource.c:1127:ldlm_resource_complain()) lustre-MDT0000-mdc-ffff9f7245e31800: namespace resource [0x20000a042:0xf:0x0].0xc (0000000053411a5b) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 5524.888518] LustreError: 82469:0:(ldlm_resource.c:1127:ldlm_resource_complain()) Skipped 1 previous similar message [ 5525.719240] LustreError: 82452:0:(fail.c:149:__cfs_fail_timeout_set()) cfs_fail_timeout id 320 awake [ 5525.822204] LustreError: 82481:0:(fail.c:138:__cfs_fail_timeout_set()) cfs_fail_timeout id 321 sleeping for 4000ms [ 5528.921055] LustreError: lustre-MDT0000-mdc-ffff9f7245e31800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5528.998567] LustreError: 82504:0:(file.c:5205:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 5529.013749] LustreError: 82504:0:(file.c:5205:ll_inode_revalidate_fini()) Skipped 1 previous similar message [ 5529.823334] LustreError: 82481:0:(fail.c:149:__cfs_fail_timeout_set()) cfs_fail_timeout id 321 awake [ 5529.828530] LustreError: 82481:0:(file.c:246:ll_close_inode_openhandle()) lustre-clilmv-ffff9f7245e31800: inode [0x20000a042:0xf:0x0] mdc close failed: rc = -108 [ 5529.838589] LustreError: 82481:0:(file.c:246:ll_close_inode_openhandle()) Skipped 1 previous similar message [ 5530.115828] LustreError: 82510:0:(file.c:5205:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 5530.132743] LustreError: 82510:0:(file.c:5205:ll_inode_revalidate_fini()) Skipped 5 previous similar messages [ 5532.411477] LustreError: 82533:0:(file.c:5205:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 5532.429567] LustreError: 82533:0:(file.c:5205:ll_inode_revalidate_fini()) Skipped 13 previous similar messages [ 5536.091812] LustreError: 82558:0:(fail.c:138:__cfs_fail_timeout_set()) cfs_fail_timeout id 321 sleeping for 4000ms [ 5539.375339] LustreError: lustre-MDT0000-mdc-ffff9f7245e31800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5539.397622] LustreError: 82576:0:(ldlm_resource.c:1127:ldlm_resource_complain()) lustre-MDT0000-mdc-ffff9f7245e31800: namespace resource [0x20000a042:0xf:0x0].0xc (000000009d099ecf) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 5539.432143] LustreError: 82576:0:(ldlm_resource.c:1127:ldlm_resource_complain()) Skipped 1 previous similar message [ 5540.167536] LustreError: 82558:0:(fail.c:149:__cfs_fail_timeout_set()) cfs_fail_timeout id 321 awake [ 5544.183870] LustreError: 82589:0:(fail.c:138:__cfs_fail_timeout_set()) cfs_fail_timeout id 321 sleeping for 4000ms [ 5547.123269] LustreError: lustre-MDT0000-mdc-ffff9f7245e31800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5548.271170] LustreError: 82589:0:(fail.c:149:__cfs_fail_timeout_set()) cfs_fail_timeout id 321 awake [ 5551.346954] LustreError: lustre-MDT0000-mdc-ffff9f7245e31800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5551.387672] LustreError: 82636:0:(ldlm_resource.c:1127:ldlm_resource_complain()) lustre-MDT0000-mdc-ffff9f7245e31800: namespace resource [0x20000a042:0xf:0x0].0xc (00000000faef1296) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 5551.433227] LustreError: 82636:0:(ldlm_resource.c:1127:ldlm_resource_complain()) Skipped 3 previous similar messages [ 5551.434965] LustreError: 82641:0:(file.c:5205:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 5551.460505] LustreError: 82641:0:(file.c:5205:ll_inode_revalidate_fini()) Skipped 6 previous similar messages [ 5555.634579] LustreError: lustre-MDT0000-mdc-ffff9f7245e31800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5556.623979] LustreError: 82649:0:(file.c:246:ll_close_inode_openhandle()) lustre-clilmv-ffff9f7245e31800: inode [0x20000a042:0xf:0x0] mdc close failed: rc = -108 [ 5564.578697] LustreError: 82722:0:(fail.c:138:__cfs_fail_timeout_set()) cfs_fail_timeout id 320 sleeping for 4000ms [ 5564.592393] LustreError: 82722:0:(fail.c:138:__cfs_fail_timeout_set()) Skipped 2 previous similar messages [ 5568.135200] LustreError: lustre-MDT0000-mdc-ffff9f7245e31800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5568.207631] LustreError: 82748:0:(file.c:5205:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 5568.216220] LustreError: 82748:0:(file.c:5205:ll_inode_revalidate_fini()) Skipped 27 previous similar messages [ 5568.671412] LustreError: 82722:0:(fail.c:149:__cfs_fail_timeout_set()) cfs_fail_timeout id 320 awake [ 5568.677719] LustreError: 82722:0:(fail.c:149:__cfs_fail_timeout_set()) Skipped 2 previous similar messages [ 5568.685598] LustreError: 82722:0:(file.c:246:ll_close_inode_openhandle()) lustre-clilmv-ffff9f7245e31800: inode [0x20000a042:0xf:0x0] mdc close failed: rc = -108 [ 5578.526461] Lustre: DEBUG MARKER: == recovery-small test 113: ldlm enqueue dropped reply should not cause deadlocks ========================================================== 13:40:24 (1781286024) [ 5598.405442] Lustre: DEBUG MARKER: == recovery-small test 130a: enqueue resend on not existing file ========================================================== 13:40:43 (1781286043) [ 5652.397779] Lustre: DEBUG MARKER: == recovery-small test 130b: enqueue resend on a stale inode ========================================================== 13:41:37 (1781286097) [ 5704.919690] Lustre: DEBUG MARKER: == recovery-small test 130c: layout intent resend on a stale inode ========================================================== 13:42:30 (1781286150) [ 5738.219217] Lustre: DEBUG MARKER: == recovery-small test 132: long punch =================== 13:43:03 (1781286183) [ 5738.797583] Lustre: Mounted lustre-client [ 5863.008378] Lustre: Unmounted lustre-client [ 5869.718262] Lustre: DEBUG MARKER: == recovery-small test 131: IO vs evict results to IO under staled lock ========================================================== 13:45:15 (1781286315) [ 5870.299148] LustreError: 87066:0:(fail.c:138:__cfs_fail_timeout_set()) cfs_fail_timeout id 414 sleeping for 4000ms [ 5870.305547] LustreError: 87066:0:(fail.c:138:__cfs_fail_timeout_set()) Skipped 2 previous similar messages [ 5873.394590] Lustre: lustre-OST0000-osc-ffff9f7245e31800: Connection to lustre-OST0000 (at 192.168.203.112@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 5873.413952] Lustre: Skipped 18 previous similar messages [ 5873.431277] LustreError: lustre-OST0000-osc-ffff9f7245e31800: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 5873.458323] LustreError: 87146:0:(ldlm_resource.c:1127:ldlm_resource_complain()) lustre-OST0000-osc-ffff9f7245e31800: namespace resource [0x454d:0x0:0x0].0x0 (000000009880b142) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 5873.476441] LustreError: 87146:0:(ldlm_resource.c:1127:ldlm_resource_complain()) Skipped 1 previous similar message [ 5874.327147] LustreError: 87066:0:(fail.c:149:__cfs_fail_timeout_set()) cfs_fail_timeout id 414 awake [ 5874.345634] LustreError: 87066:0:(fail.c:149:__cfs_fail_timeout_set()) Skipped 2 previous similar messages [ 5874.349527] Lustre: 2226:0:(llite_lib.c:3595:ll_dirty_page_discard_warn()) lustre: dirty page discard: 192.168.203.112@tcp:/lustre/fid: [0x20000bf89:0x9:0x0]// may get corrupted (rc -108) [ 5880.625370] Lustre: DEBUG MARKER: == recovery-small test 133: don't fail on flock resend === 13:45:26 (1781286326) [ 5927.904497] Lustre: 87752:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1781286330/real 1781286330] req@0000000035e106a9 x1867808038092864/t0(0) o101->lustre-MDT0000-mdc-ffff9f7245e31800@192.168.203.112@tcp:12/10 lens 328/344 e 0 to 1 dl 1781286374 ref 2 fl Rpc:XQr/0/ffffffff rc 0/-1 job:'multiop.0' [ 5927.937131] Lustre: 87752:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 15 previous similar messages [ 5927.963251] Lustre: lustre-MDT0000-mdc-ffff9f7245e31800: Connection restored to (at 192.168.203.112@tcp) [ 5927.975980] Lustre: Skipped 18 previous similar messages [ 5934.997320] Lustre: DEBUG MARKER: == recovery-small test 134: race between failover and search for reply data free slot ========================================================== 13:46:19 (1781286379) [ 5936.991681] Lustre: DEBUG MARKER: SKIP: recovery-small test_134 Need 2+ clients, have 1 [ 5938.933777] Lustre: DEBUG MARKER: == recovery-small test 135: DOM: open/create resend to return size ========================================================== 13:46:24 (1781286384) [ 5992.763646] Lustre: DEBUG MARKER: SKIP: recovery-small test_136 skipping excluded test 136 [ 5994.483744] Lustre: DEBUG MARKER: == recovery-small test 137: late resend must be skipped if already applied ========================================================== 13:47:19 (1781286439) [ 6044.160747] Lustre: DEBUG MARKER: == recovery-small test 138: Umount MDT during recovery === 13:48:09 (1781286489) [ 6046.064389] Lustre: DEBUG MARKER: SKIP: recovery-small test_138 needs >= 2 MDTs [ 6047.561966] Lustre: DEBUG MARKER: == recovery-small test 139: corrupted catid won't cause crash ========================================================== 13:48:13 (1781286493) [ 6049.267468] Lustre: DEBUG MARKER: SKIP: recovery-small test_139 needs >= 2 MDTs [ 6051.246027] Lustre: DEBUG MARKER: == recovery-small test 140a: local mount is flagged properly ========================================================== 13:48:16 (1781286496) [ 6084.171362] Lustre: DEBUG MARKER: == recovery-small test 140b: local mount is excluded from recovery ========================================================== 13:48:49 (1781286529) [ 6096.582668] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 6124.532360] LustreError: 166-1: MGC192.168.203.112@tcp: Connection to MGS (at 192.168.203.112@tcp) was lost; in progress operations using this service will fail [ 6124.557206] LustreError: Skipped 2 previous similar messages [ 6124.575622] Lustre: Evicted from MGS (at 192.168.203.112@tcp) after server handle changed from 0x65ce9a1e9e67fc5d to 0x65ce9a1e9e6814dd [ 6124.589447] Lustre: Skipped 2 previous similar messages [ 6124.622579] LustreError: 2224:0:(client.c:3161:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@00000000cce8afaa x1867808038089344/t103079215241(103079215241) o101->lustre-MDT0000-mdc-ffff9f7245e31800@192.168.203.112@tcp:12/10 lens 576/600 e 0 to 0 dl 1781286588 ref 2 fl Interpret:RPQU/4/0 rc 301/301 job:'dd.0' [ 6138.057090] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 6140.311402] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6153.113023] Lustre: DEBUG MARKER: == recovery-small test 141: do not lose locks on MGS restart ========================================================== 13:49:58 (1781286598) [ 6155.544202] Lustre: DEBUG MARKER: SKIP: recovery-small test_141 cannot run in local mode or from build tree [ 6157.757155] Lustre: DEBUG MARKER: == recovery-small test 142: orphan name stub can be cleaned up in startup ========================================================== 13:50:02 (1781286602) [ 6170.611243] LustreError: 166-1: MGC192.168.203.112@tcp: Connection to MGS (at 192.168.203.112@tcp) was lost; in progress operations using this service will fail [ 6170.659276] Lustre: Evicted from MGS (at 192.168.203.112@tcp) after server handle changed from 0x65ce9a1e9e6814dd to 0x65ce9a1e9e681825 [ 6170.681947] LustreError: 2224:0:(client.c:3161:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@00000000cce8afaa x1867808038089344/t103079215241(103079215241) o101->lustre-MDT0000-mdc-ffff9f7245e31800@192.168.203.112@tcp:12/10 lens 576/600 e 0 to 0 dl 1781286633 ref 2 fl Interpret:RPQU/4/0 rc 301/301 job:'dd.0' [ 6183.348945] Lustre: DEBUG MARKER: == recovery-small test 143: orphan cleanup thread shouldn't be blocked even delete failed ========================================================== 13:50:28 (1781286628) [ 6218.724259] LustreError: 2224:0:(client.c:3161:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@00000000cce8afaa x1867808038089344/t103079215241(103079215241) o101->lustre-MDT0000-mdc-ffff9f7245e31800@192.168.203.112@tcp:12/10 lens 576/600 e 0 to 0 dl 1781286681 ref 2 fl Interpret:RPQU/4/0 rc 301/301 job:'dd.0' [ 6233.584327] Lustre: DEBUG MARKER: == recovery-small test 144a: MDT failover should stop precreation threads ========================================================== 13:51:18 (1781286678) [ 6239.724079] LustreError: 11-0: lustre-OST0000-osc-ffff9f7245e31800: operation ost_setattr to node 192.168.203.112@tcp failed: rc = -19 [ 6239.743694] LustreError: Skipped 9 previous similar messages [ 6273.388852] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 6274.868753] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 6359.028781] LustreError: 166-1: MGC192.168.203.112@tcp: Connection to MGS (at 192.168.203.112@tcp) was lost; in progress operations using this service will fail [ 6359.044140] LustreError: Skipped 1 previous similar message [ 6359.052953] Lustre: Evicted from MGS (at 192.168.203.112@tcp) after server handle changed from 0x65ce9a1e9e681a40 to 0x65ce9a1e9e6820ad [ 6359.059399] Lustre: Skipped 1 previous similar message [ 6370.419197] LustreError: 2224:0:(client.c:3161:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@00000000cce8afaa x1867808038089344/t103079215241(103079215241) o101->lustre-MDT0000-mdc-ffff9f7245e31800@192.168.203.112@tcp:12/10 lens 576/600 e 0 to 0 dl 1781286965 ref 2 fl Interpret:RPQU/4/0 rc 301/301 job:'dd.0' [ 6377.217088] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 6379.306328] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6390.751193] INFO: task touch:95296 blocked for more than 120 seconds. [ 6390.761598] Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 6390.772707] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 6390.784319] task:touch state:D stack:0 pid:95296 ppid:95019 flags:0x80000004 [ 6390.793362] Call Trace: [ 6390.796781] __schedule+0x351/0xcb0 [ 6390.800327] schedule+0xc0/0x180 [ 6390.802162] schedule_preempt_disabled+0x21/0x40 [ 6390.804778] rwsem_down_write_slowpath+0x5d7/0xa40 [ 6390.810161] down_write+0x80/0xd0 [ 6390.815764] do_last+0x2eb/0xfc0 [ 6390.820435] ? nd_jump_root+0xe5/0x160 [ 6390.827174] ? path_init+0x437/0x520 [ 6390.831389] path_openat+0xf7/0x500 [ 6390.833775] ? __mod_lruvec_state+0x5a/0x80 [ 6390.836478] do_filp_open+0x99/0x140 [ 6390.840366] ? getname_flags+0x6e/0x330 [ 6390.850025] ? __check_object_size+0xff/0x256 [ 6390.851848] ? do_raw_spin_unlock+0x75/0x190 [ 6390.856100] ? _raw_spin_unlock+0x12/0x30 [ 6390.865366] do_sys_openat2+0x2b4/0x410 [ 6390.871390] do_sys_open+0x73/0xa0 [ 6390.876382] __x64_sys_openat+0x24/0x30 [ 6390.878670] do_syscall_64+0xc1/0x440 [ 6390.881293] entry_SYSCALL_64_after_hwframe+0x49/0xae [ 6390.887480] RIP: 0033:0x7f3dd016c332 [ 6390.891292] Code: Unable to access opcode bytes at RIP 0x7f3dd016c308. [ 6390.899249] RSP: 002b:00007ffd346878b0 EFLAGS: 00000246 ORIG_RAX: 0000000000000101 [ 6390.910222] RAX: ffffffffffffffda RBX: 00000000ffffffff RCX: 00007f3dd016c332 [ 6390.914808] RDX: 0000000000000941 RSI: 00007ffd3468a075 RDI: 00000000ffffff9c [ 6390.930762] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000001 [ 6390.938744] R10: 00000000000001b6 R11: 0000000000000246 R12: 0000000000000001 [ 6390.953127] R13: 0000000000000001 R14: 00007ffd3468a075 R15: 00007f3dd040f374 [ 6390.968269] INFO: task touch:95298 blocked for more than 120 seconds. [ 6390.977174] Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 6390.987078] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 6390.997190] task:touch state:D stack:0 pid:95298 ppid:95019 flags:0x80000004 [ 6391.014604] Call Trace: [ 6391.019069] __schedule+0x351/0xcb0 [ 6391.025441] schedule+0xc0/0x180 [ 6391.027033] schedule_preempt_disabled+0x21/0x40 [ 6391.033857] rwsem_down_write_slowpath+0x5d7/0xa40 [ 6391.041586] down_write+0x80/0xd0 [ 6391.050928] do_last+0x2eb/0xfc0 [ 6391.052916] ? nd_jump_root+0xe5/0x160 [ 6391.061784] ? path_init+0x437/0x520 [ 6391.066275] path_openat+0xf7/0x500 [ 6391.070393] ? __mod_lruvec_state+0x5a/0x80 [ 6391.073933] do_filp_open+0x99/0x140 [ 6391.079520] ? getname_flags+0x6e/0x330 [ 6391.083142] ? __check_object_size+0xff/0x256 [ 6391.089238] ? do_raw_spin_unlock+0x75/0x190 [ 6391.094814] ? _raw_spin_unlock+0x12/0x30 [ 6391.102423] do_sys_openat2+0x2b4/0x410 [ 6391.103987] do_sys_open+0x73/0xa0 [ 6391.105431] __x64_sys_openat+0x24/0x30 [ 6391.122673] do_syscall_64+0xc1/0x440 [ 6391.127502] entry_SYSCALL_64_after_hwframe+0x49/0xae [ 6391.132095] RIP: 0033:0x7f9029f8c332 [ 6391.138031] Code: Unable to access opcode bytes at RIP 0x7f9029f8c308. [ 6391.143152] RSP: 002b:00007ffc804f2c80 EFLAGS: 00000246 ORIG_RAX: 0000000000000101 [ 6391.148548] RAX: ffffffffffffffda RBX: 00000000ffffffff RCX: 00007f9029f8c332 [ 6391.153077] RDX: 0000000000000941 RSI: 00007ffc804f4075 RDI: 00000000ffffff9c [ 6391.157521] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000001 [ 6391.160925] R10: 00000000000001b6 R11: 0000000000000246 R12: 0000000000000001 [ 6391.168671] R13: 0000000000000001 R14: 00007ffc804f4075 R15: 00007f902a22f374 [ 6391.173778] INFO: task touch:95299 blocked for more than 120 seconds. [ 6391.183438] Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 6391.193417] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 6391.197556] task:touch state:D stack:0 pid:95299 ppid:95019 flags:0x80000004 [ 6391.199910] Call Trace: [ 6391.200850] __schedule+0x351/0xcb0 [ 6391.202174] schedule+0xc0/0x180 [ 6391.203684] schedule_preempt_disabled+0x21/0x40 [ 6391.205249] rwsem_down_write_slowpath+0x5d7/0xa40 [ 6391.206846] down_write+0x80/0xd0 [ 6391.208389] do_last+0x2eb/0xfc0 [ 6391.209342] ? nd_jump_root+0xe5/0x160 [ 6391.210869] ? path_init+0x437/0x520 [ 6391.212985] path_openat+0xf7/0x500 [ 6391.216217] do_filp_open+0x99/0x140 [ 6391.218463] ? getname_flags+0x6e/0x330 [ 6391.222185] ? __check_object_size+0xff/0x256 [ 6391.223889] ? do_raw_spin_unlock+0x75/0x190 [ 6391.235711] ? _raw_spin_unlock+0x12/0x30 [ 6391.238197] do_sys_openat2+0x2b4/0x410 [ 6391.244465] do_sys_open+0x73/0xa0 [ 6391.250344] __x64_sys_openat+0x24/0x30 [ 6391.251675] do_syscall_64+0xc1/0x440 [ 6391.253606] entry_SYSCALL_64_after_hwframe+0x49/0xae [ 6391.256921] RIP: 0033:0x7f764d035332 [ 6391.259695] Code: Unable to access opcode bytes at RIP 0x7f764d035308. [ 6391.264888] RSP: 002b:00007ffc8b22edf0 EFLAGS: 00000246 ORIG_RAX: 0000000000000101 [ 6391.274156] RAX: ffffffffffffffda RBX: 00000000ffffffff RCX: 00007f764d035332 [ 6391.283036] RDX: 0000000000000941 RSI: 00007ffc8b230075 RDI: 00000000ffffff9c [ 6391.287105] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000001 [ 6391.291829] R10: 00000000000001b6 R11: 0000000000000246 R12: 0000000000000001 [ 6391.297253] R13: 0000000000000001 R14: 00007ffc8b230075 R15: 00007f764d2d8374 [ 6391.302437] INFO: task touch:95300 blocked for more than 120 seconds. [ 6391.307480] Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 6391.318749] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 6391.325097] task:touch state:D stack:0 pid:95300 ppid:95019 flags:0x80000004 [ 6391.330602] Call Trace: [ 6391.332245] __schedule+0x351/0xcb0 [ 6391.334733] schedule+0xc0/0x180 [ 6391.336910] schedule_preempt_disabled+0x21/0x40 [ 6391.339834] rwsem_down_write_slowpath+0x5d7/0xa40 [ 6391.342120] down_write+0x80/0xd0 [ 6391.343901] do_last+0x2eb/0xfc0 [ 6391.345708] ? nd_jump_root+0xe5/0x160 [ 6391.348138] ? path_init+0x437/0x520 [ 6391.349856] path_openat+0xf7/0x500 [ 6391.352735] do_filp_open+0x99/0x140 [ 6391.355533] ? getname_flags+0x6e/0x330 [ 6391.358130] ? __check_object_size+0xff/0x256 [ 6391.361120] ? do_raw_spin_unlock+0x75/0x190 [ 6391.362927] ? _raw_spin_unlock+0x12/0x30 [ 6391.364437] do_sys_openat2+0x2b4/0x410 [ 6391.366263] do_sys_open+0x73/0xa0 [ 6391.368925] __x64_sys_openat+0x24/0x30 [ 6391.371291] do_syscall_64+0xc1/0x440 [ 6391.373355] entry_SYSCALL_64_after_hwframe+0x49/0xae [ 6391.375317] RIP: 0033:0x7fed93009332 [ 6391.376483] Code: Unable to access opcode bytes at RIP 0x7fed93009308. [ 6391.378746] RSP: 002b:00007ffc4dcd0a80 EFLAGS: 00000246 ORIG_RAX: 0000000000000101 [ 6391.380961] RAX: ffffffffffffffda RBX: 00000000ffffffff RCX: 00007fed93009332 [ 6391.383112] RDX: 0000000000000941 RSI: 00007ffc4dcd2075 RDI: 00000000ffffff9c [ 6391.385824] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000001 [ 6391.387794] R10: 00000000000001b6 R11: 0000000000000246 R12: 0000000000000001 [ 6391.389941] R13: 0000000000000001 R14: 00007ffc4dcd2075 R15: 00007fed932ac374 [ 6391.393059] INFO: task touch:95301 blocked for more than 120 seconds. [ 6391.396866] Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 6391.399562] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 6391.401646] task:touch state:D stack:0 pid:95301 ppid:95019 flags:0x80000004 [ 6391.405042] Call Trace: [ 6391.405537] __schedule+0x351/0xcb0 [ 6391.407456] schedule+0xc0/0x180 [ 6391.409259] schedule_preempt_disabled+0x21/0x40 [ 6391.411285] rwsem_down_write_slowpath+0x5d7/0xa40 [ 6391.413482] down_write+0x80/0xd0 [ 6391.414540] do_last+0x2eb/0xfc0 [ 6391.415700] ? nd_jump_root+0xe5/0x160 [ 6391.416915] ? path_init+0x437/0x520 [ 6391.419182] path_openat+0xf7/0x500 [ 6391.421730] ? __mod_lruvec_state+0x5a/0x80 [ 6391.425610] do_filp_open+0x99/0x140 [ 6391.427600] ? getname_flags+0x6e/0x330 [ 6391.429374] ? __check_object_size+0xff/0x256 [ 6391.432176] ? do_raw_spin_unlock+0x75/0x190 [ 6391.434019] ? _raw_spin_unlock+0x12/0x30 [ 6391.436168] do_sys_openat2+0x2b4/0x410 [ 6391.439655] do_sys_open+0x73/0xa0 [ 6391.442801] __x64_sys_openat+0x24/0x30 [ 6391.447106] do_syscall_64+0xc1/0x440 [ 6391.452849] entry_SYSCALL_64_after_hwframe+0x49/0xae [ 6391.455310] RIP: 0033:0x7fe09f37d332 [ 6391.457093] Code: Unable to access opcode bytes at RIP 0x7fe09f37d308. [ 6391.459593] RSP: 002b:00007ffc5e90ffa0 EFLAGS: 00000246 ORIG_RAX: 0000000000000101 [ 6391.462981] RAX: ffffffffffffffda RBX: 00000000ffffffff RCX: 00007fe09f37d332 [ 6391.465088] RDX: 0000000000000941 RSI: 00007ffc5e911075 RDI: 00000000ffffff9c [ 6391.466821] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000001 [ 6391.472572] R10: 00000000000001b6 R11: 0000000000000246 R12: 0000000000000001 [ 6391.477762] R13: 0000000000000001 R14: 00007ffc5e911075 R15: 00007fe09f620374 [ 6391.486226] INFO: task touch:95302 blocked for more than 120 seconds. [ 6391.493352] Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 6391.498352] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 6391.501241] task:touch state:D stack:0 pid:95302 ppid:95019 flags:0x80000004 [ 6391.505891] Call Trace: [ 6391.507212] __schedule+0x351/0xcb0 [ 6391.512416] schedule+0xc0/0x180 [ 6391.513843] schedule_preempt_disabled+0x21/0x40 [ 6391.516429] rwsem_down_write_slowpath+0x5d7/0xa40 [ 6391.519247] down_write+0x80/0xd0 [ 6391.521479] do_last+0x2eb/0xfc0 [ 6391.522789] ? nd_jump_root+0xe5/0x160 [ 6391.524553] ? path_init+0x437/0x520 [ 6391.532304] path_openat+0xf7/0x500 [ 6391.538769] do_filp_open+0x99/0x140 [ 6391.541802] ? getname_flags+0x6e/0x330 [ 6391.549160] ? __check_object_size+0xff/0x256 [ 6391.554060] ? do_raw_spin_unlock+0x75/0x190 [ 6391.558886] ? _raw_spin_unlock+0x12/0x30 [ 6391.562040] do_sys_openat2+0x2b4/0x410 [ 6391.564067] do_sys_open+0x73/0xa0 [ 6391.565478] __x64_sys_openat+0x24/0x30 [ 6391.572041] do_syscall_64+0xc1/0x440 [ 6391.576911] entry_SYSCALL_64_after_hwframe+0x49/0xae [ 6391.579503] RIP: 0033:0x7fc64c401332 [ 6391.581619] Code: Unable to access opcode bytes at RIP 0x7fc64c401308. [ 6391.584020] RSP: 002b:00007fff373a1a50 EFLAGS: 00000246 ORIG_RAX: 0000000000000101 [ 6391.588445] RAX: ffffffffffffffda RBX: 00000000ffffffff RCX: 00007fc64c401332 [ 6391.592207] RDX: 0000000000000941 RSI: 00007fff373a4075 RDI: 00000000ffffff9c [ 6391.596373] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000001 [ 6391.600819] R10: 00000000000001b6 R11: 0000000000000246 R12: 0000000000000001 [ 6391.607423] R13: 0000000000000001 R14: 00007fff373a4075 R15: 00007fc64c6a4374 [ 6391.611511] INFO: task touch:95303 blocked for more than 120 seconds. [ 6391.614822] Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 6391.620023] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 6391.628784] task:touch state:D stack:0 pid:95303 ppid:95019 flags:0x80000004 [ 6391.633927] Call Trace: [ 6391.634915] __schedule+0x351/0xcb0 [ 6391.636271] schedule+0xc0/0x180 [ 6391.638632] schedule_preempt_disabled+0x21/0x40 [ 6391.641593] rwsem_down_write_slowpath+0x5d7/0xa40 [ 6391.643759] down_write+0x80/0xd0 [ 6391.645328] do_last+0x2eb/0xfc0 [ 6391.647616] ? nd_jump_root+0xe5/0x160 [ 6391.649618] ? path_init+0x437/0x520 [ 6391.652363] path_openat+0xf7/0x500 [ 6391.654461] do_filp_open+0x99/0x140 [ 6391.656637] ? getname_flags+0x6e/0x330 [ 6391.659490] ? __check_object_size+0xff/0x256 [ 6391.662791] ? do_raw_spin_unlock+0x75/0x190 [ 6391.666946] ? _raw_spin_unlock+0x12/0x30 [ 6391.670088] do_sys_openat2+0x2b4/0x410 [ 6391.677607] do_sys_open+0x73/0xa0 [ 6391.680424] __x64_sys_openat+0x24/0x30 [ 6391.683621] do_syscall_64+0xc1/0x440 [ 6391.689419] entry_SYSCALL_64_after_hwframe+0x49/0xae [ 6391.693166] RIP: 0033:0x7f86b0253332 [ 6391.695358] Code: Unable to access opcode bytes at RIP 0x7f86b0253308. [ 6391.704140] RSP: 002b:00007ffca5e56b50 EFLAGS: 00000246 ORIG_RAX: 0000000000000101 [ 6391.710159] RAX: ffffffffffffffda RBX: 00000000ffffffff RCX: 00007f86b0253332 [ 6391.717416] RDX: 0000000000000941 RSI: 00007ffca5e59075 RDI: 00000000ffffff9c [ 6391.726233] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000001 [ 6391.731098] R10: 00000000000001b6 R11: 0000000000000246 R12: 0000000000000001 [ 6391.734752] R13: 0000000000000001 R14: 00007ffca5e59075 R15: 00007f86b04f6374 [ 6391.742819] INFO: task touch:95304 blocked for more than 120 seconds. [ 6391.745997] Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 6391.754887] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 6391.760574] task:touch state:D stack:0 pid:95304 ppid:95019 flags:0x80000004 [ 6391.765347] Call Trace: [ 6391.767245] __schedule+0x351/0xcb0 [ 6391.772703] schedule+0xc0/0x180 [ 6391.781133] schedule_preempt_disabled+0x21/0x40 [ 6391.783848] rwsem_down_write_slowpath+0x5d7/0xa40 [ 6391.787706] down_write+0x80/0xd0 [ 6391.794120] do_last+0x2eb/0xfc0 [ 6391.801479] ? nd_jump_root+0xe5/0x160 [ 6391.806692] ? path_init+0x437/0x520 [ 6391.808920] path_openat+0xf7/0x500 [ 6391.811410] do_filp_open+0x99/0x140 [ 6391.816554] ? getname_flags+0x6e/0x330 [ 6391.823227] ? __check_object_size+0xff/0x256 [ 6391.827811] ? do_raw_spin_unlock+0x75/0x190 [ 6391.830587] ? _raw_spin_unlock+0x12/0x30 [ 6391.833669] do_sys_openat2+0x2b4/0x410 [ 6391.836611] do_sys_open+0x73/0xa0 [ 6391.839238] __x64_sys_openat+0x24/0x30 [ 6391.842384] do_syscall_64+0xc1/0x440 [ 6391.845427] entry_SYSCALL_64_after_hwframe+0x49/0xae [ 6391.848623] RIP: 0033:0x7f1e75989332 [ 6391.851615] Code: Unable to access opcode bytes at RIP 0x7f1e75989308. [ 6391.859051] RSP: 002b:00007ffe38f61e90 EFLAGS: 00000246 ORIG_RAX: 0000000000000101 [ 6391.864018] RAX: ffffffffffffffda RBX: 00000000ffffffff RCX: 00007f1e75989332 [ 6391.867540] RDX: 0000000000000941 RSI: 00007ffe38f64075 RDI: 00000000ffffff9c [ 6391.871851] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000001 [ 6391.876125] R10: 00000000000001b6 R11: 0000000000000246 R12: 0000000000000001 [ 6391.881018] R13: 0000000000000001 R14: 00007ffe38f64075 R15: 00007f1e75c2c374 [ 6391.892685] INFO: task touch:95305 blocked for more than 120 seconds. [ 6391.902862] Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 6391.906952] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 6391.912442] task:touch state:D stack:0 pid:95305 ppid:95019 flags:0x80000004 [ 6391.917785] Call Trace: [ 6391.920535] __schedule+0x351/0xcb0 [ 6391.924433] schedule+0xc0/0x180 [ 6391.929477] schedule_preempt_disabled+0x21/0x40 [ 6391.933675] rwsem_down_write_slowpath+0x5d7/0xa40 [ 6391.940108] down_write+0x80/0xd0 [ 6391.942899] do_last+0x2eb/0xfc0 [ 6391.945145] ? nd_jump_root+0xe5/0x160 [ 6391.947834] ? path_init+0x437/0x520 [ 6391.951128] path_openat+0xf7/0x500 [ 6391.954806] ? __mod_lruvec_state+0x5a/0x80 [ 6391.958197] do_filp_open+0x99/0x140 [ 6391.963580] ? getname_flags+0x6e/0x330 [ 6391.966839] ? __check_object_size+0xff/0x256 [ 6391.973915] ? do_raw_spin_unlock+0x75/0x190 [ 6391.979671] ? _raw_spin_unlock+0x12/0x30 [ 6391.981758] do_sys_openat2+0x2b4/0x410 [ 6391.983879] do_sys_open+0x73/0xa0 [ 6391.985864] __x64_sys_openat+0x24/0x30 [ 6391.987855] do_syscall_64+0xc1/0x440 [ 6391.990549] entry_SYSCALL_64_after_hwframe+0x49/0xae [ 6391.993439] RIP: 0033:0x7fa0cbb8c332 [ 6391.995613] Code: Unable to access opcode bytes at RIP 0x7fa0cbb8c308. [ 6391.999212] RSP: 002b:00007fffe51f9640 EFLAGS: 00000246 ORIG_RAX: 0000000000000101 [ 6392.002993] RAX: ffffffffffffffda RBX: 00000000ffffffff RCX: 00007fa0cbb8c332 [ 6392.007734] RDX: 0000000000000941 RSI: 00007fffe51fb075 RDI: 00000000ffffff9c [ 6392.011718] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000001 [ 6392.015485] R10: 00000000000001b6 R11: 0000000000000246 R12: 0000000000000001 [ 6392.024580] R13: 0000000000000001 R14: 00007fffe51fb075 R15: 00007fa0cbe2f374 [ 6392.033394] INFO: task touch:95306 blocked for more than 120 seconds. [ 6392.037071] Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 6392.044547] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 6392.049893] task:touch state:D stack:0 pid:95306 ppid:95019 flags:0x80000004 [ 6392.058012] Call Trace: [ 6392.060602] __schedule+0x351/0xcb0 [ 6392.063669] schedule+0xc0/0x180 [ 6392.066889] schedule_preempt_disabled+0x21/0x40 [ 6392.070459] rwsem_down_write_slowpath+0x5d7/0xa40 [ 6392.075654] down_write+0x80/0xd0 [ 6392.077015] do_last+0x2eb/0xfc0 [ 6392.078890] ? nd_jump_root+0xe5/0x160 [ 6392.081379] ? path_init+0x437/0x520 [ 6392.090798] path_openat+0xf7/0x500 [ 6392.091833] do_filp_open+0x99/0x140 [ 6392.092787] ? getname_flags+0x6e/0x330 [ 6392.097705] ? __check_object_size+0xff/0x256 [ 6392.102629] ? do_raw_spin_unlock+0x75/0x190 [ 6392.104493] ? _raw_spin_unlock+0x12/0x30 [ 6392.110844] do_sys_openat2+0x2b4/0x410 [ 6392.112832] do_sys_open+0x73/0xa0 [ 6392.117157] __x64_sys_openat+0x24/0x30 [ 6392.120118] do_syscall_64+0xc1/0x440 [ 6392.122564] entry_SYSCALL_64_after_hwframe+0x49/0xae [ 6392.124939] RIP: 0033:0x7fae03f56332 [ 6392.127639] Code: Unable to access opcode bytes at RIP 0x7fae03f56308. [ 6392.137946] RSP: 002b:00007ffc44cb9cf0 EFLAGS: 00000246 ORIG_RAX: 0000000000000101 [ 6392.143442] RAX: ffffffffffffffda RBX: 00000000ffffffff RCX: 00007fae03f56332 [ 6392.148410] RDX: 0000000000000941 RSI: 00007ffc44cbb075 RDI: 00000000ffffff9c [ 6392.153927] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000001 [ 6392.158116] R10: 00000000000001b6 R11: 0000000000000246 R12: 0000000000000001 [ 6392.163089] R13: 0000000000000001 R14: 00007ffc44cbb075 R15: 00007fae041f9374 [ 6413.301910] LustreError: 2224:0:(client.c:3161:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@00000000cce8afaa x1867808038089344/t103079215241(103079215241) o101->lustre-MDT0000-mdc-ffff9f7245e31800@192.168.203.112@tcp:12/10 lens 576/600 e 0 to 0 dl 1781287007 ref 2 fl Interpret:RPQU/4/0 rc 301/301 job:'dd.0' [ 6423.733973] Lustre: DEBUG MARKER: oleg312-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 6425.425880] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6503.121238] Lustre: DEBUG MARKER: == recovery-small test 145: connect mdtlovs and process update logs after recovery expire ========================================================== 13:55:48 (1781286948) [ 6506.865980] Lustre: DEBUG MARKER: SKIP: recovery-small test_145 needs >= 3 MDTs [ 6510.370635] Lustre: DEBUG MARKER: == recovery-small test 147: Check client reconnect ======= 13:55:55 (1781286955) [ 6699.425227] Lustre: DEBUG MARKER: == recovery-small test 148: data corruption through resend ========================================================== 13:59:04 (1781287144) [ 6727.136613] Lustre: 2228:0:(client.c:2295:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1781287153/real 1781287153] req@000000008d98af12 x1867808038443840/t0(0) o4->lustre-OST0000-osc-ffff9f7245e31800@192.168.203.112@tcp:6/4 lens 4584/448 e 0 to 1 dl 1781287173 ref 2 fl Rpc:XQr/0/ffffffff rc 0/-1 job:'dd.0' [ 6727.170533] Lustre: 2228:0:(client.c:2295:ptlrpc_expire_one_request()) Skipped 12 previous similar messages [ 6727.177283] Lustre: lustre-OST0000-osc-ffff9f7245e31800: Connection to lustre-OST0000 (at 192.168.203.112@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 6727.186336] Lustre: Skipped 9 previous similar messages [ 6739.990631] Lustre: DEBUG MARKER: == recovery-small test 149: skip orphan removal at umount ========================================================== 13:59:45 (1781287185) [ 6741.380873] Lustre: DEBUG MARKER: SKIP: recovery-small test_149 needs >= 2 MDTs [ 6743.234219] Lustre: DEBUG MARKER: == recovery-small test 152: QoS object allocation could be awakened in case of OST failover ========================================================== 13:59:48 (1781287188) [ 6778.446969] Lustre: DEBUG MARKER: == recovery-small test complete, duration 6494 sec ======= 14:00:23 (1781287223) [ 6784.446321] Lustre: Unmounted lustre-client [ 6804.959571] Key type lgssc unregistered [ 6805.337268] LNet: 101593:0:(lib-ptl.c:992:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 6806.370506] LNet: Removed LNI 192.168.203.12@tcp [ 6807.038145] Key type .llcrypt unregistered [ 6807.041604] Key type ._llcrypt unregistered