[ 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 388396882 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.001010] APIC: Switch to symmetric I/O mode setup [ 0.003134] x2apic enabled [ 0.004004] Switched APIC routing to physical x2apic. [ 0.005007] kvm-guest: setup PV IPIs [ 0.007620] ..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.008013] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.009005] pid_max: default: 32768 minimum: 301 [ 0.010095] LSM: Security Framework initializing [ 0.011033] Yama: becoming mindful. [ 0.012023] SELinux: Initializing. [ 0.013048] *** VALIDATE selinux *** [ 0.020253] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.024758] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.025196] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.026100] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.027125] *** VALIDATE tmpfs *** [ 0.029212] *** VALIDATE proc *** [ 0.030264] *** VALIDATE cgroup *** [ 0.031008] *** VALIDATE cgroup2 *** [ 0.033265] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.034143] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.035011] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.036032] Spectre V2 : User space: Vulnerable [ 0.037004] Speculative Store Bypass: Vulnerable [ 0.040504] debug: unmapping init [mem 0xffffffff9ba59000-0xffffffff9ba60fff] [ 0.042165] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.043566] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.044021] ... version: 2 [ 0.044964] ... bit width: 48 [ 0.045014] ... generic registers: 4 [ 0.045847] ... value mask: 0000ffffffffffff [ 0.046017] ... max period: 00007fffffffffff [ 0.047010] ... fixed-purpose events: 3 [ 0.048008] ... event mask: 000000070000000f [ 0.049308] rcu: Hierarchical SRCU implementation. [ 0.051298] smp: Bringing up secondary CPUs ... [ 0.052526] x86: Booting SMP configuration: [ 0.053019] .... node #0, CPUs: #1 #2 #3 [ 0.056267] smp: Brought up 1 node, 4 CPUs [ 0.057946] smpboot: Max logical packages: 1 [ 0.058013] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.248358] node 0 deferred pages initialised in 189ms [ 0.251546] devtmpfs: initialized [ 0.252237] x86/mm: Memory block size: 128MB [ 0.254842] gcov: version magic: 0x41383552 [ 0.256209] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.257076] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.258300] pinctrl core: initialized pinctrl subsystem [ 0.259160] [ 0.259472] ************************************************************* [ 0.260008] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.261008] ** ** [ 0.262007] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.263009] ** ** [ 0.264011] ** This means that this kernel is built to expose internal ** [ 0.265010] ** IOMMU data structures, which may compromise security on ** [ 0.266009] ** your system. ** [ 0.267006] ** ** [ 0.268014] ** If you see this message and you are not debugging the ** [ 0.269017] ** kernel, report this immediately to your vendor! ** [ 0.270016] ** ** [ 0.271016] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.272016] ************************************************************* [ 0.273823] NET: Registered protocol family 16 [ 0.274530] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.275078] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.276068] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.277570] cpuidle: using governor menu [ 0.279827] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.282484] PCI: Using configuration type 1 for base access [ 0.284157] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.294083] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.295023] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.297038] cryptd: max_cpu_qlen set to 1000 [ 0.300652] ACPI: Added _OSI(Module Device) [ 0.302029] ACPI: Added _OSI(Processor Device) [ 0.304017] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.305009] ACPI: Added _OSI(Processor Aggregator Device) [ 0.308594] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.312370] ACPI: Interpreter enabled [ 0.313051] ACPI: PM: (supports S0 S3 S4 S5) [ 0.313941] ACPI: Using IOAPIC for interrupt routing [ 0.315149] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.318330] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.328482] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.330035] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.332024] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.336101] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.340370] acpiphp: Slot [2] registered [ 0.341080] acpiphp: Slot [5] registered [ 0.343170] acpiphp: Slot [6] registered [ 0.345168] acpiphp: Slot [3] registered [ 0.346097] acpiphp: Slot [4] registered [ 0.348087] acpiphp: Slot [7] registered [ 0.350096] acpiphp: Slot [8] registered [ 0.351074] acpiphp: Slot [9] registered [ 0.352080] acpiphp: Slot [10] registered [ 0.353126] acpiphp: Slot [11] registered [ 0.355107] acpiphp: Slot [12] registered [ 0.356118] acpiphp: Slot [13] registered [ 0.358097] acpiphp: Slot [14] registered [ 0.359094] acpiphp: Slot [15] registered [ 0.361151] acpiphp: Slot [16] registered [ 0.362086] acpiphp: Slot [17] registered [ 0.363185] acpiphp: Slot [18] registered [ 0.365093] acpiphp: Slot [19] registered [ 0.366155] acpiphp: Slot [20] registered [ 0.368094] acpiphp: Slot [21] registered [ 0.369140] acpiphp: Slot [22] registered [ 0.370098] acpiphp: Slot [23] registered [ 0.372134] acpiphp: Slot [24] registered [ 0.373096] acpiphp: Slot [25] registered [ 0.374121] acpiphp: Slot [26] registered [ 0.376061] acpiphp: Slot [27] registered [ 0.377103] acpiphp: Slot [28] registered [ 0.379059] acpiphp: Slot [29] registered [ 0.380062] acpiphp: Slot [30] registered [ 0.382120] acpiphp: Slot [31] registered [ 0.383077] PCI host bridge to bus 0000:00 [ 0.385025] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.390032] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.394027] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.397105] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.399023] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.401026] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.403255] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.405999] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.409000] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.415019] pci 0000:00:01.1: reg 0x20: [io 0xc120-0xc12f] [ 0.418589] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.421017] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.423012] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.427023] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.429582] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.431723] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.434044] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.439374] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.443017] pci 0000:00:02.0: reg 0x10: [io 0xc100-0xc11f] [ 0.453015] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.458779] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.463917] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.469016] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.472917] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.486016] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.496180] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.502011] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.507017] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.520023] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.529033] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.532401] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.534320] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.536252] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.538155] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.541144] iommu: Default domain type: Passthrough [ 0.543388] SCSI subsystem initialized [ 0.545086] ACPI: bus type USB registered [ 0.546076] usbcore: registered new interface driver usbfs [ 0.547067] usbcore: registered new interface driver hub [ 0.549092] usbcore: registered new device driver usb [ 0.551151] pps_core: LinuxPPS API ver. 1 registered [ 0.553013] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.556073] PTP clock support registered [ 0.558142] EDAC MC: Ver: 3.0.0 [ 0.560199] PCI: Using ACPI for IRQ routing [ 0.561505] NetLabel: Initializing [ 0.563013] NetLabel: domain hash size = 128 [ 0.564007] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.565066] NetLabel: unlabeled traffic allowed by default [ 0.567130] vgaarb: loaded [ 0.569242] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.570010] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.574018] clocksource: Switched to clocksource kvm-clock [ 0.671094] VFS: Disk quotas dquot_6.6.0 [ 0.672653] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.675070] *** VALIDATE ramfs *** [ 0.676232] *** VALIDATE hugetlbfs *** [ 0.677701] pnp: PnP ACPI init [ 0.681031] pnp: PnP ACPI: found 6 devices [ 0.697960] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.700639] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.702254] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.703995] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.705847] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.707838] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.710269] NET: Registered protocol family 2 [ 0.712442] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.717219] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.720558] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.725022] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.727363] TCP: Hash tables configured (established 65536 bind 65536) [ 0.729613] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.732237] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.734256] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.737284] NET: Registered protocol family 1 [ 0.739607] RPC: Registered named UNIX socket transport module. [ 0.741923] RPC: Registered udp transport module. [ 0.743526] RPC: Registered tcp transport module. [ 0.745287] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.747415] NET: Registered protocol family 44 [ 0.748751] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.751117] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.753981] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.756366] PCI: CLS 0 bytes, default 64 [ 0.758293] Unpacking initramfs... [ 2.086193] debug: unmapping init [mem 0xffff9cbdbcc64000-0xffff9cbdbffcffff] [ 2.092799] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.095421] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.100156] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 2.595847] Initialise system trusted keyrings [ 2.597734] Key type blacklist registered [ 2.599578] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.609043] zbud: loaded [ 2.611596] *** VALIDATE nfs *** [ 2.612910] *** VALIDATE nfs4 *** [ 2.614419] pstore: using deflate compression [ 2.618652] Platform Keyring initialized [ 2.727270] NET: Registered protocol family 38 [ 2.729684] Key type asymmetric registered [ 2.731915] Asymmetric key parser 'x509' registered [ 2.734369] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 2.737885] io scheduler mq-deadline registered [ 2.740221] io scheduler kyber registered [ 2.742350] io scheduler bfq registered [ 2.744465] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 2.747882] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 2.751758] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 2.754888] ACPI: Power Button [PWRF] [ 2.762752] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 2.771645] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 2.790849] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 2.819261] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 2.849066] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 2.853440] Non-volatile memory driver v1.3 [ 2.854791] Linux agpgart interface v0.103 [ 2.883503] virtio_blk virtio1: [vda] 145800 512-byte logical blocks (74.6 MB/71.2 MiB) [ 2.886379] vda: detected capacity change from 0 to 74649600 [ 2.903073] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 2.905901] vdb: detected capacity change from 0 to 1073741824 [ 2.912609] libphy: Fixed MDIO Bus: probed [ 2.919169] usbcore: registered new interface driver usbserial_generic [ 2.921906] usbserial: USB Serial support registered for generic [ 2.923957] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 2.927770] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 2.929855] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 2.933471] mousedev: PS/2 mouse device common for all mice [ 2.936700] rtc_cmos 00:05: RTC can wake from S4 [ 2.939396] rtc_cmos 00:05: registered as rtc0 [ 2.941284] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 2.944484] intel_pstate: CPU model not supported [ 2.948029] hid: raw HID events driver (C) Jiri Kosina [ 2.949900] usbcore: registered new interface driver usbhid [ 2.950782] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 2.955309] usbhid: USB HID core driver [ 2.955493] drop_monitor: Initializing network drop monitor service [ 2.955679] Initializing XFRM netlink socket [ 2.956021] NET: Registered protocol family 10 [ 2.957881] Segment Routing with IPv6 [ 2.969762] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 2.972251] NET: Registered protocol family 17 [ 2.979658] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 2.983297] mpls_gso: MPLS GSO support [ 3.008715] RAS: Correctable Errors collector initialized. [ 3.012712] AVX version of gcm_enc/dec engaged. [ 3.014280] AES CTR mode by8 optimization enabled [ 3.122833] sched_clock: Marking stable (3122776152, 0)->(3893104420, -770328268) [ 3.128446] registered taskstats version 1 [ 3.131320] Loading compiled-in X.509 certificates [ 3.133151] zswap: loaded using pool lzo/zbud [ 3.164670] Key type big_key registered [ 3.177246] Key type encrypted registered [ 3.179112] ima: No TPM chip found, activating TPM-bypass! [ 3.184153] ima: Allocated hash algorithm: sha1 [ 3.187783] ima: No architecture policies found [ 3.190655] evm: Initialising EVM extended attributes: [ 3.194506] evm: security.selinux [ 3.196911] evm: security.ima [ 3.198392] evm: security.capability [ 3.201992] evm: HMAC attrs: 0x1 [ 3.204845] rtc_cmos 00:05: setting system clock to 2026-07-17 11:37:40 UTC (1784288260) [ 3.215199] debug: unmapping init [mem 0xffffffff9ca03000-0xffffffff9cbfffff] [ 3.221451] debug: unmapping init [mem 0xffffffff9b782000-0xffffffff9ba58fff] [ 3.224752] Write protecting the kernel read-only data: 28672k [ 3.228460] debug: unmapping init [mem 0xffffffff99e03000-0xffffffff99ffffff] [ 3.231754] debug: unmapping init [mem 0xffffffff9a714000-0xffffffff9a7fffff] [ 3.291209] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 3.303809] systemd[1]: Detected virtualization kvm. [ 3.305974] systemd[1]: Detected architecture x86-64. [ 3.309945] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.335903] systemd[1]: No hostname configured. [ 3.337344] systemd[1]: Set hostname to . [ 3.339892] random: systemd: uninitialized urandom read (16 bytes read) [ 3.345041] systemd[1]: Initializing machine ID from random generator. [ 3.516732] random: systemd: uninitialized urandom read (16 bytes read) [ 3.520763] systemd[1]: Listening on udev Control Socket. [ OK ] Listening on udev Control Socket. [ 3.525642] random: systemd: uninitialized urandom read (16 bytes read) [ 3.527879] systemd[1]: Listening on Journal Socket. [ OK ] Listening on Journal Socket. [ 3.535621] systemd[1]: Started Memstrack Anylazing Service. [ OK ] Started Memstrack Anylazing Service. Starting Apply Kernel Variables... [ OK ] Reached target Initrd Root Device. [ OK ] Reached target Timers. [ OK ] Listening on udev Kernel Socket. [ OK ] Reached target Slices. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. [ OK ] Listening on Journal Socket (/dev/log). [ OK ] Reached target Sockets. Starting Journal Service... [ OK ] Reached target Local File Systems. Starting Create Volatile Files and Directories... Starting Setup Virtual Console... [ OK ] Reached target Swap. [ OK ] Started Apply Kernel Variables. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Setup Virtual Console. 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... [ 4.355812] device-mapper: uevent: version 1.0.3 [ 4.357745] 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... [ OK ] Started udev Coldplug all Devices. [ 5.315343] virtio_net virtio0 ens2: renamed from eth0 Starting dracut initqueue hook... Mounting Kernel Configuration File System... [ 5.375793] scsi host0: ata_piix [ 5.426383] scsi host1: ata_piix [ 5.428230] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc120 irq 14 [ 5.435330] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc128 irq 15 [ OK ] Mounted Kernel Configuration File System. [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System.[ 5.773962] random: fast init done [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ 10.715157] random: crng init done [ 10.716418] random: 7 urandom warning(s) missed due to ratelimiting [ 10.770081] dracut-initqueue[570]: RTNETLINK answers: File exists Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Mounting /sysroot... [ 12.109916] 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 Initrd Default Target. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped target Timers. [ OK ] Stopped dracut initqueue hook. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target System Initialization. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped target Swap. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. [ OK ] Stopped Apply Kernel Variables. Stopping udev Kernel Device Manager... [ OK ] Stopped target Sockets. [ OK ] Stopped target Paths. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped target Slices. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Closed udev Control Socket. [ OK ] Closed udev Kernel Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 13.799338] printk: systemd: 26 output lines suppressed due to ratelimiting [ 14.187690] SELinux: Disabled at runtime. [ 14.270045] 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) [ 14.283271] systemd[1]: Detected virtualization kvm. [ 14.285282] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 15.173112] systemd[1]: initrd-switch-root.service: Succeeded. [ 15.179284] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 15.185901] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 15.192184] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 15.197376] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 15.208813] systemd[1]: Starting Journal Service... Starting Journal Service... [ 15.218099] systemd[1]: Created slice system-sshd\x2dkeygen.slice. [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Stopped target Switch Root. [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 RPCbind Server Activation Socket. [ OK ] Reached target RPC Port Mapper. [ OK ] Stopped target Initrd File Systems. Activating swap /dev/disk/by-label/SWAP... [ OK ] Started Forward Password Requests to Wall Directory Watch. Mounting POSIX Message Queue File System... [ OK ] Listening on udev Control Socket. [ 15.302987] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS [ OK ] Created slice system-getty.slice. [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Created slice User and Session Slice. [ OK ] Reached target Slices. [ OK ] Started Dispatch Password Requests to Console Directory Watch. Starting Remount Root and Kernel File Systems... Starting Apply Kernel Variables... [ OK ] Listening on Process Core Dump Socket. [ OK ] Reached target rpc_pipefs.target. Starting Create list of required st…ce nodes for the current kernel... Mounting Kernel Debug File System... Mounting Huge Pages File System... [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Reached target Paths. [ OK ] Listening on udev Kernel Socket. Starting udev Coldplug all Devices... [ OK ] Stopped target Initrd Root File System. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Mounted POSIX Message Queue File System. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Started Journal Service. [ OK ] Started Apply Kernel Variables. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Mounted Kernel Debug File System. [ OK ] Mounted Huge Pages File System. Starting Configure read-only root support... Starting Flush Journal to Persistent Storage... Starting Create Static Device Nodes in /dev... [ OK ] Reached target Swap. [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Reached target Local File Systems (Pre). Mounting /home/green/git/lustre-release... Mounting /mnt... Starting udev Kernel Device Manager... [ OK ] Started udev Coldplug all Devices. [ OK ] Mounted /mnt. [ 16.490975] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 17.163630] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 17.252386] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 17.619732] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 17.825579] EDAC sbridge: Ver: 1.1.2 [ 19.947884] Key type dns_resolver registered [ 20.464708] NFS: Registering the id_resolver key type [ 20.467073] Key type id_resolver registered [ 20.468678] Key type id_legacy registered [ OK ] Started Configure read-only root support. Starting Load/Save Random Seed... [ OK ] Reached target Local File Systems. Starting Rebuild Dynamic Linker Cache... Starting Mark the need to relabel after reboot... Starting Create Volatile Files and Directories... [ OK ] Started Load/Save Random Seed. [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Create Volatile Files and Directories. Starting Update UTMP about System Boot/Shutdown... Starting RPC Bind... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Started dnf makecache --timer. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. Starting Login Service... [ OK ] Started D-Bus System Message Bus. Starting Network Manager... Starting Restore /run/initramfs on shutdown... [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Started irqbalance daemon. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Reached target Timers. [ OK ] Reached target sshd-keygen.target. [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Login Service. [ OK ] Started Network Manager. [ OK ] Reached target Network. Starting OpenSSH server daemon... Starting Dynamic System Tuning Daemon... Starting GSSAPI Proxy Daemon... Starting Network Manager Wait Online... [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Started OpenSSH server daemon. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... Starting Hostname Service... [ OK ] Started Permit User Sessions. [ OK ] Started Getty on tty1. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Serial Getty on ttyS1. [ OK ] Reached target Login Prompts. [ OK ] Started Command Scheduler. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting System Logging Service... Starting Notify NFS peers of a restart... Starting Crash recovery kernel arming... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg309-client login: [ 51.579311] libcfs: loading out-of-tree module taints kernel. [ 51.603605] Key type ._llcrypt registered [ 51.604905] Key type .llcrypt registered [ 51.907304] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [ 51.913295] alg: No test for adler32 (adler32-zlib) [ 52.898762] Lustre: Lustre: Build Version: 2.17.54_173_g0a24909 [ 53.166647] LNet: Added LNI 192.168.203.9@tcp [8/256/0/180] [ 54.767223] Key type lgssc registered [ 55.324873] Lustre: Echo OBD driver; http://www.lustre.org/ [ 113.587814] Lustre: Mounted lustre-client [ 115.958792] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 122.318374] Lustre: DEBUG MARKER: oleg309-client.virtnet: executing check_logdir /tmp/testlogs/ [ 123.684287] Lustre: DEBUG MARKER: oleg309-client.virtnet: executing yml_node [ 125.072942] Lustre: DEBUG MARKER: Client: 2.17.54.173 [ 125.890917] Lustre: DEBUG MARKER: MDS: 2.17.54.173 [ 126.729249] Lustre: DEBUG MARKER: OSS: 2.17.54.173 [ 127.255635] Lustre: DEBUG MARKER: -----============= acceptance-small: recovery-small ============----- Fri Jul 17 07:39:44 EDT 2026 [ 132.700163] Lustre: DEBUG MARKER: excepting tests: 136 [ 133.343516] Lustre: DEBUG MARKER: === recovery-small: start setup 07:39:50 (1784288390) === [ 135.088547] Lustre: DEBUG MARKER: oleg309-client.virtnet: executing check_config_client /mnt/lustre [ 139.231236] Lustre: lustre-OST0000-osc-ffff9cbe2019d800: disconnect after 24s idle [ 141.107261] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 145.184543] Lustre: DEBUG MARKER: === recovery-small: finish setup 07:40:01 (1784288401) === [ 145.740918] Lustre: DEBUG MARKER: == recovery-small test 1: create, chmod, stat: drop req, drop rep ========================================================== 07:40:02 (1784288402) [ 162.271189] Lustre: 10796:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1784288403/real 1784288403] req@ffff9cbe114d8a80 x1870961898957056/t0(0) o700->lustre-MDT0000-mdc-ffff9cbe2019d800@192.168.203.109@tcp:30/10 lens 264/248 e 0 to 1 dl 1784288419 ref 2 fl Rpc:XQr/200/ffffffff rc 0/-1 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 162.283677] Lustre: lustre-MDT0000-mdc-ffff9cbe2019d800: Connection to lustre-MDT0000 (at 192.168.203.109@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 162.297693] Lustre: lustre-MDT0000-mdc-ffff9cbe2019d800: Connection restored to 192.168.203.109@tcp (at 192.168.203.109@tcp) [ 179.679194] Lustre: 10817:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1784288420/real 1784288420] req@ffff9cbe114d9180 x1870961898959360/t0(0) o36->lustre-MDT0000-mdc-ffff9cbe2019d800@192.168.203.109@tcp:12/10 lens 520/576 e 0 to 1 dl 1784288436 ref 2 fl Rpc:XQr/200/ffffffff rc 0/-1 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 179.693506] Lustre: lustre-MDT0000-mdc-ffff9cbe2019d800: Connection to lustre-MDT0000 (at 192.168.203.109@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 179.707738] Lustre: lustre-MDT0000-mdc-ffff9cbe2019d800: Connection restored to 192.168.203.109@tcp (at 192.168.203.109@tcp) [ 196.063139] Lustre: 10843:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1784288437/real 1784288437] req@ffff9cbe193f5500 x1870961898961152/t0(0) o101->lustre-MDT0000-mdc-ffff9cbe2019d800@192.168.203.109@tcp:12/10 lens 576/1152 e 0 to 1 dl 1784288453 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'tchmod.0' uid:0 gid:0 projid:0 [ 196.075181] Lustre: lustre-MDT0000-mdc-ffff9cbe2019d800: Connection to lustre-MDT0000 (at 192.168.203.109@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 196.087159] Lustre: lustre-MDT0000-mdc-ffff9cbe2019d800: Connection restored to 192.168.203.109@tcp (at 192.168.203.109@tcp) [ 213.471161] Lustre: 10863:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1784288454/real 1784288454] req@ffff9cbe19358380 x1870961898963968/t0(0) o36->lustre-MDT0000-mdc-ffff9cbe2019d800@192.168.203.109@tcp:12/10 lens 488/512 e 0 to 1 dl 1784288470 ref 2 fl Rpc:XQr/200/ffffffff rc 0/-1 job:'tchmod.0' uid:0 gid:0 projid:4294967295 [ 213.482636] Lustre: lustre-MDT0000-mdc-ffff9cbe2019d800: Connection to lustre-MDT0000 (at 192.168.203.109@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 213.497114] Lustre: lustre-MDT0000-mdc-ffff9cbe2019d800: Connection restored to 192.168.203.109@tcp (at 192.168.203.109@tcp) [ 229.855133] Lustre: 10889:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1784288471/real 1784288471] req@ffff9cbe19358380 x1870961898965760/t0(0) o34->lustre-MDT0000-mdc-ffff9cbe2019d800@192.168.203.109@tcp:12/10 lens 472/728 e 0 to 1 dl 1784288487 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'statone.0' uid:0 gid:0 projid:0 [ 229.865058] Lustre: lustre-MDT0000-mdc-ffff9cbe2019d800: Connection to lustre-MDT0000 (at 192.168.203.109@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 229.875159] Lustre: lustre-MDT0000-mdc-ffff9cbe2019d800: Connection restored to 192.168.203.109@tcp (at 192.168.203.109@tcp) [ 245.727150] Lustre: 10909:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1784288487/real 1784288487] req@ffff9cbe114d8000 x1870961898967552/t0(0) o34->lustre-MDT0000-mdc-ffff9cbe2019d800@192.168.203.109@tcp:12/10 lens 472/728 e 0 to 1 dl 1784288503 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'statone.0' uid:0 gid:0 projid:0 [ 245.736727] Lustre: lustre-MDT0000-mdc-ffff9cbe2019d800: Connection to lustre-MDT0000 (at 192.168.203.109@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 245.747411] Lustre: lustre-MDT0000-mdc-ffff9cbe2019d800: Connection restored to 192.168.203.109@tcp (at 192.168.203.109@tcp) [ 248.169232] Lustre: DEBUG MARKER: == recovery-small test 4: open: drop req, drop rep ======= 07:41:44 (1784288504) [ 264.671149] Lustre: 11518:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1784288505/real 1784288505] req@ffff9cbe1935bb80 x1870961898969856/t0(0) o101->lustre-MDT0000-mdc-ffff9cbe2019d800@192.168.203.109@tcp:12/10 lens 576/1152 e 0 to 1 dl 1784288521 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'cat.0' uid:0 gid:0 projid:0 [ 264.681735] Lustre: lustre-MDT0000-mdc-ffff9cbe2019d800: Connection to lustre-MDT0000 (at 192.168.203.109@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 264.704036] Lustre: lustre-MDT0000-mdc-ffff9cbe2019d800: Connection restored to 192.168.203.109@tcp (at 192.168.203.109@tcp) [ 283.727883] Lustre: DEBUG MARKER: == recovery-small test 5: rename: drop req, drop rep ===== 07:42:20 (1784288540) [ 300.511227] Lustre: 12146:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1784288541/real 1784288541] req@ffff9cbe193f6d80 x1870961898976640/t0(0) o101->lustre-MDT0000-mdc-ffff9cbe2019d800@192.168.203.109@tcp:12/10 lens 576/1152 e 0 to 1 dl 1784288557 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'mv.0' uid:0 gid:0 projid:0 [ 300.522381] Lustre: 12146:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 300.525519] Lustre: lustre-MDT0000-mdc-ffff9cbe2019d800: Connection to lustre-MDT0000 (at 192.168.203.109@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 300.529941] Lustre: Skipped 1 previous similar message [ 300.539062] Lustre: lustre-MDT0000-mdc-ffff9cbe2019d800: Connection restored to 192.168.203.109@tcp (at 192.168.203.109@tcp) [ 300.541744] Lustre: Skipped 1 previous similar message [ 319.510127] Lustre: DEBUG MARKER: == recovery-small test 6: link, unlink: drop req, drop rep ========================================================== 07:42:56 (1784288576) [ 346.591450] Lustre: lustre-OST0000-osc-ffff9cbe2019d800: disconnect after 23s idle [ 346.593764] Lustre: Skipped 1 previous similar message [ 369.631192] Lustre: 12831:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1784288610/real 1784288610] req@ffff9cbe19358380 x1870961898991104/t0(0) o101->lustre-MDT0000-mdc-ffff9cbe2019d800@192.168.203.109@tcp:12/10 lens 576/1152 e 0 to 1 dl 1784288626 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'unlink.0' uid:0 gid:0 projid:0 [ 369.638994] Lustre: 12831:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 369.641186] Lustre: lustre-MDT0000-mdc-ffff9cbe2019d800: Connection to lustre-MDT0000 (at 192.168.203.109@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 369.646360] Lustre: Skipped 3 previous similar messages [ 369.657795] Lustre: lustre-MDT0000-mdc-ffff9cbe2019d800: Connection restored to 192.168.203.109@tcp (at 192.168.203.109@tcp) [ 369.661862] Lustre: Skipped 3 previous similar messages [ 388.588076] Lustre: DEBUG MARKER: == recovery-small test 8: touch: drop rep (bug 1423) ===== 07:44:05 (1784288645) [ 408.144535] Lustre: DEBUG MARKER: == recovery-small test 9: pause bulk on OST (bug 1420) === 07:44:24 (1784288664) [ 416.565342] Lustre: DEBUG MARKER: == recovery-small test 10a: finish request on server after client eviction (bug 1521) ========================================================== 07:44:33 (1784288673) [ 416.715722] Lustre: *** cfs_fail_loc=305, val=0*** [ 419.847984] Lustre: *** cfs_fail_loc=305, val=0*** [ 419.849597] Lustre: *** cfs_fail_loc=305, val=0*** [ 425.486489] Lustre: *** cfs_fail_loc=305, val=0*** [ 433.163101] Lustre: *** cfs_fail_loc=305, val=0*** [ 436.228690] Lustre: *** cfs_fail_loc=305, val=0*** [ 436.244150] Lustre: *** cfs_fail_loc=305, val=0*** [ 440.847598] Lustre: *** cfs_fail_loc=305, val=0*** [ 449.548427] Lustre: *** cfs_fail_loc=305, val=0*** [ 451.589599] Lustre: *** cfs_fail_loc=305, val=0*** [ 451.590458] Lustre: *** cfs_fail_loc=305, val=0*** [ 457.231423] Lustre: *** cfs_fail_loc=305, val=0*** [ 464.900449] Lustre: *** cfs_fail_loc=305, val=0*** [ 467.990614] Lustre: *** cfs_fail_loc=305, val=0*** [ 467.996327] Lustre: *** cfs_fail_loc=305, val=0*** [ 472.580478] Lustre: *** cfs_fail_loc=305, val=0*** [ 481.284562] Lustre: *** cfs_fail_loc=305, val=0*** [ 484.357065] Lustre: *** cfs_fail_loc=305, val=0*** [ 484.357081] Lustre: *** cfs_fail_loc=305, val=0*** [ 488.964752] Lustre: *** cfs_fail_loc=305, val=0*** [ 496.644798] Lustre: *** cfs_fail_loc=305, val=0*** [ 499.716745] Lustre: *** cfs_fail_loc=305, val=0*** [ 499.717501] Lustre: *** cfs_fail_loc=305, val=0*** [ 505.361919] Lustre: *** cfs_fail_loc=305, val=0*** [ 513.028865] Lustre: *** cfs_fail_loc=305, val=0*** [ 516.101309] Lustre: *** cfs_fail_loc=305, val=0*** [ 516.101340] Lustre: *** cfs_fail_loc=305, val=0*** [ 520.708555] Lustre: *** cfs_fail_loc=305, val=0*** [ 529.533358] LustreError: lustre-MDT0000-mdc-ffff9cbe2019d800: operation ldlm_enqueue to node 192.168.203.109@tcp failed: rc = -107 [ 529.538165] Lustre: lustre-MDT0000-mdc-ffff9cbe2019d800: Connection to lustre-MDT0000 (at 192.168.203.109@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 529.545856] Lustre: Skipped 2 previous similar messages [ 529.551258] LustreError: lustre-MDT0000-mdc-ffff9cbe2019d800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 529.561182] Lustre: lustre-MDT0000-mdc-ffff9cbe2019d800: Connection restored to 192.168.203.109@tcp (at 192.168.203.109@tcp) [ 529.565368] Lustre: Skipped 2 previous similar messages [ 532.792385] Lustre: DEBUG MARKER: == recovery-small test 10b: re-send BL AST =============== 07:46:29 (1784288789) [ 533.478817] LustreError: lustre-OST0001-osc-ffff9cbe2019d800: This client was evicted by lustre-OST0001; in progress operations using this service will fail. [ 533.483025] LustreError: lustre-OST0000-osc-ffff9cbe2019d800: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 552.021296] Lustre: DEBUG MARKER: == recovery-small test 10c: re-send BL AST vs reconnect race (LU-5569) ========================================================== 07:46:48 (1784288808) [ 555.541477] Lustre: DEBUG MARKER: == recovery-small test 10d: test failed blocking ast ===== 07:46:52 (1784288812) [ 556.924735] Lustre: Unmounted lustre-client [ 557.064995] Lustre: Mounted lustre-client [ 557.572191] LustreError: lustre-OST0000-osc-ffff9cbe05637800: operation ost_statfs to node 192.168.203.109@tcp failed: rc = -107 [ 557.579464] LustreError: lustre-OST0000-osc-ffff9cbe05637800: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 557.584891] Lustre: 2380:0:(llite_lib.c:4327:ll_dirty_page_discard_warn()) lustre: dirty page discard: 192.168.203.109@tcp:/lustre/fid: [0x200000404:0x1:0x0]/ may get corrupted (rc -108) [ 558.069428] Lustre: Unmounted lustre-client [ 560.221737] Lustre: DEBUG MARKER: == recovery-small test 10e: re-send BL AST vs reconnect race 2 ========================================================== 07:46:57 (1784288817) [ 560.755716] Lustre: DEBUG MARKER: SKIP: recovery-small test_10e need two clients [ 561.306441] Lustre: DEBUG MARKER: == recovery-small test 11: wake up a thread waiting for completion after eviction (b=2460) ========================================================== 07:46:58 (1784288818) [ 580.756438] Lustre: DEBUG MARKER: == recovery-small test 12: recover from timed out resend in ptlrpcd (b=2494) ========================================================== 07:47:17 (1784288837) [ 580.778464] Lustre: DEBUG MARKER: multiop /mnt/lustre/f12.recovery-small OS_c [ 597.471118] Lustre: 18504:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1784288838/real 1784288838] req@ffff9cbe114d9880 x1870961899065600/t0(0) o35->lustre-MDT0000-mdc-ffff9cbe05637800@192.168.203.109@tcp:23/10 lens 392/624 e 0 to 1 dl 1784288854 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'multiop.0' uid:0 gid:0 projid:0 [ 597.480582] Lustre: 18504:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 655.950363] Lustre: DEBUG MARKER: == recovery-small test 13: mdc_readpage restart test (bug 1138) ========================================================== 07:48:32 (1784288912) [ 674.144811] Lustre: DEBUG MARKER: == recovery-small test 14: mdc_readpage resend test (bug 1138) ========================================================== 07:48:50 (1784288930) [ 676.620468] Lustre: DEBUG MARKER: == recovery-small test 15: failed open (-ENOMEM) ========= 07:48:53 (1784288933) [ 678.825905] Lustre: DEBUG MARKER: == recovery-small test 16: timeout bulk put, don't evict client (2732) ========================================================== 07:48:55 (1784288935) [ 717.885599] Lustre: DEBUG MARKER: == recovery-small test 17a: timeout bulk get, don't evict client (2732) ========================================================== 07:49:34 (1784288974) [ 762.210191] Lustre: DEBUG MARKER: == recovery-small test 17b: timeout bulk get, dont evict client (3582) ========================================================== 07:50:19 (1784289019) [ 762.645031] Lustre: DEBUG MARKER: SKIP: recovery-small test_17b Needs multiple clients [ 763.122876] Lustre: DEBUG MARKER: == recovery-small test 18a: manual ost invalidate clears page cache immediately ========================================================== 07:50:20 (1784289020) [ 763.333342] Lustre: setting import lustre-OST0001_UUID INACTIVE by administrator request [ 763.356430] LustreError: lustre-OST0001-osc-ffff9cbe05637800: This client was evicted by lustre-OST0001; in progress operations using this service will fail. [ 765.406568] Lustre: DEBUG MARKER: == recovery-small test 18b: eviction and reconnect clears page cache (2766) ========================================================== 07:50:22 (1784289022) [ 766.948799] LustreError: lustre-OST0000-osc-ffff9cbe05637800: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 790.261521] Lustre: DEBUG MARKER: == recovery-small test 18c: Dropped connect reply after eviction handing (14755) ========================================================== 07:50:47 (1784289047) [ 792.142264] LustreError: lustre-OST0000-osc-ffff9cbe05637800: operation ost_statfs to node 192.168.203.109@tcp failed: rc = -107 [ 792.146664] Lustre: lustre-OST0000-osc-ffff9cbe05637800: Connection to lustre-OST0000 (at 192.168.203.109@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 792.151687] Lustre: Skipped 9 previous similar messages [ 801.762587] Lustre: Evicted from lustre-OST0000_UUID (at 192.168.203.109@tcp) after server handle changed from 0x1b0d482b226812c2 to 0x1b0d482b22681404 [ 801.765896] LustreError: lustre-OST0000-osc-ffff9cbe05637800: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 805.959599] Lustre: DEBUG MARKER: == recovery-small test 19a: test expired_lock_main on mds (2867) ========================================================== 07:51:02 (1784289062) [ 806.106084] Lustre: Mounted lustre-client [ 806.107261] Lustre: Skipped 1 previous similar message [ 821.736659] Lustre: lustre-MDT0000-mdc-ffff9cbe05637800: Connection restored to 192.168.203.109@tcp (at 192.168.203.109@tcp) [ 821.739437] Lustre: Skipped 7 previous similar messages [ 854.495198] Lustre: 2382:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1784289095/real 1784289095] req@ffff9cbe114daa00 x1870961899128832/t0(0) o103->lustre-MDT0000-mdc-ffff9cbe05637800@192.168.203.109@tcp:17/18 lens 328/224 e 0 to 1 dl 1784289111 ref 1 fl Rpc:XQr/202/ffffffff rc 0/-1 job:'ldlm_bl.0' uid:0 gid:0 projid:4294967295 [ 854.508395] Lustre: 2382:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 4 previous similar messages [ 908.918472] LustreError: lustre-MDT0000-mdc-ffff9cbe05637800: operation ldlm_enqueue to node 192.168.203.109@tcp failed: rc = -107 [ 908.924426] LustreError: lustre-MDT0000-mdc-ffff9cbe05637800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 908.928805] LustreError: 24821:0:(file.c:6088:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -5 [ 908.928982] LustreError: 24822:0:(file.c:251:ll_close_inode_openhandle()) lustre-clilmv-ffff9cbe05637800: inode [0x200000404:0x1:0x0] mdc close failed: rc = -108 [ 909.182108] Lustre: Unmounted lustre-client [ 911.355735] Lustre: DEBUG MARKER: == recovery-small test 19b: test expired_lock_main on ost (2867) ========================================================== 07:52:48 (1784289168) [ 911.480893] Lustre: Mounted lustre-client [ 1015.613194] Lustre: Unmounted lustre-client [ 1015.663272] LustreError: lustre-OST0000-osc-ffff9cbe05637800: operation ldlm_enqueue to node 192.168.203.109@tcp failed: rc = -107 [ 1015.670757] LustreError: lustre-OST0000-osc-ffff9cbe05637800: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 1015.707819] LustreError: lustre-OST0001-osc-ffff9cbe05637800: This client was evicted by lustre-OST0001; in progress operations using this service will fail. [ 1017.783665] Lustre: DEBUG MARKER: == recovery-small test 19c: check reconnect and lock resend do not trigger expired_lock_main ========================================================== 07:54:34 (1784289274) [ 1017.912827] Lustre: Mounted lustre-client [ 1020.571515] Lustre: Unmounted lustre-client [ 1027.399978] Lustre: DEBUG MARKER: == recovery-small test 20a: ldlm_handle_enqueue error (should return error) ========================================================== 07:54:44 (1784289284) [ 1027.822288] LustreError: lustre-OST0000-osc-ffff9cbe05637800: operation ldlm_enqueue to node 192.168.203.109@tcp failed: rc = -12 [ 1027.824826] LustreError: Skipped 1 previous similar message [ 1029.725825] Lustre: DEBUG MARKER: == recovery-small test 20b: ldlm_handle_enqueue error (should return error) ========================================================== 07:54:46 (1784289286) [ 1032.114781] Lustre: DEBUG MARKER: == recovery-small test 21a: drop close request while close and open are both in flight ========================================================== 07:54:48 (1784289288) [ 1053.182202] Lustre: DEBUG MARKER: == recovery-small test 21b: drop open request while close and open are both in flight ========================================================== 07:55:10 (1784289310) [ 1191.119323] Lustre: DEBUG MARKER: == recovery-small test 21c: drop both request while close and open are both in flight ========================================================== 07:57:27 (1784289447) [ 1213.698117] Lustre: DEBUG MARKER: == recovery-small test 21d: drop close reply while close and open are both in flight ========================================================== 07:57:50 (1784289470) [ 1233.401674] Lustre: DEBUG MARKER: == recovery-small test 21e: drop open reply while close and open are both in flight ========================================================== 07:58:10 (1784289490) [ 1370.079153] Lustre: 30644:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1784289491/real 1784289491] req@ffff9cbe0722b800 x1870961899256576/t0(0) o36->lustre-MDT0000-mdc-ffff9cbe05637800@192.168.203.109@tcp:12/10 lens 488/512 e 0 to 1 dl 1784289627 ref 2 fl Rpc:XQr/200/ffffffff rc 0/-1 job:'touch.0' uid:0 gid:0 projid:4294967295 [ 1370.086171] Lustre: 30644:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 19 previous similar messages [ 1370.088175] Lustre: lustre-MDT0000-mdc-ffff9cbe05637800: Connection to lustre-MDT0000 (at 192.168.203.109@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1370.092280] Lustre: Skipped 25 previous similar messages [ 1370.100784] Lustre: lustre-MDT0000-mdc-ffff9cbe05637800: Connection restored to 192.168.203.109@tcp (at 192.168.203.109@tcp) [ 1370.105053] Lustre: Skipped 22 previous similar messages [ 1370.641271] Lustre: DEBUG MARKER: == recovery-small test 21f: drop both reply while close and open are both in flight ========================================================== 08:00:27 (1784289627) [ 1392.218617] Lustre: DEBUG MARKER: == recovery-small test 21g: drop open reply and close request while close and open are both in flight ========================================================== 08:00:49 (1784289649) [ 1413.032960] Lustre: DEBUG MARKER: == recovery-small test 21h: drop open request and close reply while close and open are both in flight ========================================================== 08:01:09 (1784289669) [ 1434.210160] Lustre: DEBUG MARKER: == recovery-small test 22: drop close request and do mknod ========================================================== 08:01:31 (1784289691) [ 1452.232967] Lustre: DEBUG MARKER: == recovery-small test 23: client hang when close a file after mds crash ========================================================== 08:01:48 (1784289708) [ 1475.555187] LustreError: MGC192.168.203.109@tcp: Connection to MGS (at 192.168.203.109@tcp) was lost; in progress operations using this service will fail [ 1475.568496] Lustre: Evicted from MGS (at 192.168.203.109@tcp) after server handle changed from 0x1b0d482b226808c7 to 0x1b0d482b22683154 [ 1478.907309] Lustre: DEBUG MARKER: oleg309-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1479.466394] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1482.943891] Lustre: DEBUG MARKER: == recovery-small test 24a: fsync error (should return error) ========================================================== 08:02:19 (1784289739) [ 1483.416346] LustreError: lustre-OST0000-osc-ffff9cbe05637800: operation ost_write to node 192.168.203.109@tcp failed: rc = -107 [ 1483.418840] LustreError: Skipped 1 previous similar message [ 1483.421916] LustreError: lustre-OST0000-osc-ffff9cbe05637800: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 1483.426026] Lustre: 2382:0:(llite_lib.c:4327:ll_dirty_page_discard_warn()) lustre: dirty page discard: 192.168.203.109@tcp:/lustre/fid: [0x240000403:0x8:0x0]// may get corrupted (rc -5) [ 1485.452237] Lustre: DEBUG MARKER: == recovery-small test 24b: test dirty page discard due to client eviction ========================================================== 08:02:22 (1784289742) [ 1485.988286] LustreError: lustre-OST0000-osc-ffff9cbe05637800: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 1485.994111] Lustre: 2380:0:(llite_lib.c:4327:ll_dirty_page_discard_warn()) lustre: dirty page discard: 192.168.203.109@tcp:/lustre/fid: [0x240000403:0xb:0x0]// may get corrupted (rc -108) [ 1488.076095] Lustre: DEBUG MARKER: == recovery-small test 26a: evict dead exports =========== 08:02:24 (1784289744) [ 1488.815810] Lustre: DEBUG MARKER: SKIP: recovery-small test_26a msg and ost1 are at the same node [ 1489.412960] Lustre: DEBUG MARKER: == recovery-small test 26b: evict dead exports =========== 08:02:26 (1784289746) [ 1490.038723] Lustre: DEBUG MARKER: SKIP: recovery-small test_26b msg and ost1 are at the same node [ 1490.579640] Lustre: DEBUG MARKER: == recovery-small test 27: fail LOV while using OSC's ==== 08:02:27 (1784289747) [ 1506.273550] LustreError: MGC192.168.203.109@tcp: Connection to MGS (at 192.168.203.109@tcp) was lost; in progress operations using this service will fail [ 1506.290378] Lustre: Evicted from MGS (at 192.168.203.109@tcp) after server handle changed from 0x1b0d482b22683154 to 0x1b0d482b226858bb [ 1600.478231] LustreError: lustre-MDT0000-mdc-ffff9cbe05637800: operation mds_close to node 192.168.203.109@tcp failed: rc = -19 [ 1600.482244] LustreError: Skipped 3 previous similar messages [ 1613.798521] LustreError: MGC192.168.203.109@tcp: Connection to MGS (at 192.168.203.109@tcp) was lost; in progress operations using this service will fail [ 1613.805792] Lustre: Evicted from MGS (at 192.168.203.109@tcp) after server handle changed from 0x1b0d482b226858bb to 0x1b0d482b226df54a [ 1621.214194] Lustre: DEBUG MARKER: == recovery-small test 28: handle error adding new clients (bug 6086) ========================================================== 08:04:38 (1784289878) [ 1621.344294] Lustre: *** cfs_fail_loc=305, val=0*** [ 1621.346355] Lustre: Skipped 4 previous similar messages [ 1656.799290] LustreError: MGC192.168.203.109@tcp: Connection to MGS (at 192.168.203.109@tcp) was lost; in progress operations using this service will fail [ 1656.807432] Lustre: Evicted from MGS (at 192.168.203.109@tcp) after server handle changed from 0x1b0d482b226df54a to 0x1b0d482b226dffca [ 1659.088167] Lustre: DEBUG MARKER: oleg309-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1659.559267] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1662.787672] Lustre: DEBUG MARKER: == recovery-small test 29a: error adding new clients doesn't cause LBUG (bug 22273) ========================================================== 08:05:19 (1784289919) [ 1667.041651] LustreError: MGC192.168.203.109@tcp: Connection to MGS (at 192.168.203.109@tcp) was lost; in progress operations using this service will fail [ 1667.048230] Lustre: Evicted from MGS (at 192.168.203.109@tcp) after server handle changed from 0x1b0d482b226dffca to 0x1b0d482b226e0319 [ 1672.255393] LustreError: lustre-MDT0000-mdc-ffff9cbe05637800: operation ldlm_enqueue to node 192.168.203.109@tcp failed: rc = -107 [ 1677.287493] LustreError: lustre-MDT0000-mdc-ffff9cbe05637800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 1690.036415] Lustre: DEBUG MARKER: == recovery-small test 29b: error adding new clients doesn't cause LBUG (bug 22273) ========================================================== 08:05:46 (1784289946) [ 1697.765693] LustreError: lustre-OST0000-osc-ffff9cbe05637800: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 1709.741182] Lustre: DEBUG MARKER: == recovery-small test 50: failover MDS under load ======= 08:06:06 (1784289966) [ 1738.719411] LustreError: MGC192.168.203.109@tcp: Connection to MGS (at 192.168.203.109@tcp) was lost; in progress operations using this service will fail [ 1738.735160] Lustre: Evicted from MGS (at 192.168.203.109@tcp) after server handle changed from 0x1b0d482b226e0319 to 0x1b0d482b226ed57b [ 1742.018894] Lustre: DEBUG MARKER: oleg309-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1742.845276] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1805.425243] LustreError: lustre-MDT0000-mdc-ffff9cbe05637800: operation ldlm_enqueue to node 192.168.203.109@tcp failed: rc = -107 [ 1805.427717] LustreError: Skipped 1 previous similar message [ 1821.155742] LustreError: MGC192.168.203.109@tcp: Connection to MGS (at 192.168.203.109@tcp) was lost; in progress operations using this service will fail [ 1821.171557] Lustre: Evicted from MGS (at 192.168.203.109@tcp) after server handle changed from 0x1b0d482b226ed57b to 0x1b0d482b2272c192 [ 1825.789502] Lustre: DEBUG MARKER: oleg309-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1826.459213] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1903.075321] LustreError: MGC192.168.203.109@tcp: Connection to MGS (at 192.168.203.109@tcp) was lost; in progress operations using this service will fail [ 1903.175122] Lustre: Evicted from MGS (at 192.168.203.109@tcp) after server handle changed from 0x1b0d482b2272c192 to 0x1b0d482b2276afc4 [ 1910.294612] Lustre: DEBUG MARKER: oleg309-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1910.950370] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1934.844434] Lustre: DEBUG MARKER: == recovery-small test 51: failover MDS during recovery == 08:09:51 (1784290191) [ 1952.635780] Lustre: DEBUG MARKER: test_51: failover in 1 sec [ 1969.635282] LustreError: MGC192.168.203.109@tcp: Connection to MGS (at 192.168.203.109@tcp) was lost; in progress operations using this service will fail [ 1969.639567] LustreError: Skipped 1 previous similar message [ 1969.642463] Lustre: 16765:0:(mgc_request.c:1899:mgc_process_log()) MGC192.168.203.109@tcp: IR log lustre-cliir failed, not fatal: rc = -5 [ 1969.657222] Lustre: Evicted from MGS (at 192.168.203.109@tcp) after server handle changed from 0x1b0d482b22789716 to 0x1b0d482b2278991c [ 1969.660360] Lustre: Skipped 1 previous similar message [ 1969.856298] Lustre: DEBUG MARKER: test_51: failover in 5 sec [ 1972.755307] Lustre: lustre-MDT0000-mdc-ffff9cbe05637800: Connection restored to 192.168.203.109@tcp (at 192.168.203.109@tcp) [ 1972.758167] Lustre: Skipped 24 previous similar messages [ 1975.547901] Lustre: lustre-MDT0000-mdc-ffff9cbe05637800: Connection to lustre-MDT0000 (at 192.168.203.109@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1975.552885] Lustre: Skipped 16 previous similar messages [ 1991.328360] Lustre: DEBUG MARKER: test_51: failover in 10 sec [ 2018.098460] Lustre: DEBUG MARKER: test_51: failover in 20 sec [ 2055.323211] Lustre: DEBUG MARKER: test_51: failover in 25 sec [ 2081.184032] LustreError: lustre-MDT0000-mdc-ffff9cbe05637800: operation mds_reint to node 192.168.203.109@tcp failed: rc = -19 [ 2081.186530] LustreError: Skipped 6 previous similar messages [ 2097.668433] Lustre: DEBUG MARKER: test_51: failover in 30 sec [ 2097.681338] Lustre: Evicted from MGS (at 192.168.203.109@tcp) after server handle changed from 0x1b0d482b227a99b2 to 0x1b0d482b227c2a9c [ 2097.685973] Lustre: Skipped 3 previous similar messages [ 2143.720963] LustreError: MGC192.168.203.109@tcp: Connection to MGS (at 192.168.203.109@tcp) was lost; in progress operations using this service will fail [ 2143.728282] LustreError: Skipped 4 previous similar messages [ 2168.164919] Lustre: DEBUG MARKER: == recovery-small test 52: failover OST under load ======= 08:13:44 (1784290424) [ 2199.702567] Lustre: DEBUG MARKER: oleg309-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 2200.514679] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 2532.187844] Lustre: DEBUG MARKER: oleg309-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 2532.995683] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 2841.548300] LustreError: lustre-OST0000-osc-ffff9cbe05637800: operation ldlm_enqueue to node 192.168.203.109@tcp failed: rc = -107 [ 2841.554944] LustreError: Skipped 5 previous similar messages [ 2841.557397] Lustre: lustre-OST0000-osc-ffff9cbe05637800: Connection to lustre-OST0000 (at 192.168.203.109@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 2841.565034] Lustre: Skipped 6 previous similar messages [ 2862.337614] Lustre: DEBUG MARKER: oleg309-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 2863.054848] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 3133.972915] Lustre: DEBUG MARKER: == recovery-small test 53a: touch: drop rep ============== 08:29:50 (1784291390) [ 3149.791118] Lustre: 51997:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1784291391/real 1784291391] req@ffff9cbe100ba300 x1870961961746048/t0(0) o101->lustre-MDT0000-mdc-ffff9cbe05637800@192.168.203.109@tcp:12/10 lens 576/1152 e 0 to 1 dl 1784291407 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'openfile.0' uid:0 gid:0 projid:0 [ 3149.798949] Lustre: 51997:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 7 previous similar messages [ 3149.810046] Lustre: lustre-MDT0000-mdc-ffff9cbe05637800: Connection restored to 192.168.203.109@tcp (at 192.168.203.109@tcp) [ 3149.812447] Lustre: Skipped 11 previous similar messages [ 3152.366724] Lustre: DEBUG MARKER: == recovery-small test 53b: touch: drop rep ============== 08:30:09 (1784291409) [ 3171.996432] Lustre: DEBUG MARKER: == recovery-small test 53c: touch: drop rep ============== 08:30:28 (1784291428) [ 3191.264582] Lustre: DEBUG MARKER: == recovery-small test 54: back in time ================== 08:30:48 (1784291448) [ 3191.405696] Lustre: Mounted lustre-client [ 3217.378401] LustreError: MGC192.168.203.109@tcp: Connection to MGS (at 192.168.203.109@tcp) was lost; in progress operations using this service will fail [ 3217.385449] Lustre: Evicted from MGS (at 192.168.203.109@tcp) after server handle changed from 0x1b0d482b227e39cc to 0x1b0d482b22b53281 [ 3217.388278] Lustre: Skipped 1 previous similar message [ 3222.722984] Lustre: DEBUG MARKER: oleg309-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3223.233277] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3224.564367] Lustre: Unmounted lustre-client [ 3226.523379] Lustre: DEBUG MARKER: == recovery-small test 55: ost_brw_read/write drops timed-out read/write request ========================================================== 08:31:23 (1784291483) [ 3245.023155] Lustre: 2382:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1784291486/real 1784291486] req@ffff9cbe18399500 x1870961961784960/t0(0) o4->lustre-OST0000-osc-ffff9cbe05637800@192.168.203.109@tcp:6/4 lens 488/448 e 0 to 1 dl 1784291502 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'dd.0' uid:0 gid:0 projid:0 [ 3245.034212] Lustre: 2382:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 5 previous similar messages [ 3313.898072] Lustre: DEBUG MARKER: == recovery-small test 56: do not fail on getattr resend ========================================================== 08:32:50 (1784291570) [ 3356.554224] Lustre: DEBUG MARKER: == recovery-small test 57: read procfs entries causes kernel crash ========================================================== 08:33:33 (1784291613) [ 3357.871106] Lustre: Unmounted lustre-client [ 3372.076070] Lustre: Mounted lustre-client [ 3374.121357] Lustre: DEBUG MARKER: == recovery-small test 58: Eviction in the middle of open RPC reply processing ========================================================== 08:33:50 (1784291630) [ 3374.186594] LustreError: 57844:0:(mdc_locks.c:1335:mdc_finish_intent_lock()) cfs_fail_timeout id 801 sleeping for 20000ms [ 3375.241579] Lustre: *** cfs_fail_loc=305, val=0*** [ 3394.263100] LustreError: 57844:0:(mdc_locks.c:1335:mdc_finish_intent_lock()) cfs_fail_timeout id 801 awake [ 3396.517576] Lustre: DEBUG MARKER: == recovery-small test 59: Read cancel race on client eviction ========================================================== 08:34:13 (1784291653) [ 3396.657169] Lustre: Mounted lustre-client [ 3397.030353] Lustre: setting import lustre-MDT0000_UUID INACTIVE by administrator request [ 3407.288772] Lustre: Unmounted lustre-client [ 3409.399524] Lustre: DEBUG MARKER: == recovery-small test 60: Add Changelog entries during MDS failover ========================================================== 08:34:26 (1784291666) [ 3447.775106] Lustre: 2382:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1784291689/real 1784291689] req@ffff9cbe0842ca80 x1870961964619392/t0(0) o400->MGC192.168.203.109@tcp@192.168.203.109@tcp:26/25 lens 224/224 e 0 to 1 dl 1784291705 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3447.785684] Lustre: 2382:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 35 previous similar messages [ 3447.785882] LustreError: MGC192.168.203.109@tcp: Connection to MGS (at 192.168.203.109@tcp) was lost; in progress operations using this service will fail [ 3447.794065] Lustre: Evicted from MGS (at 192.168.203.109@tcp) after server handle changed from 0x1b0d482b22b53e66 to 0x1b0d482b22b863ba [ 3476.705574] Lustre: DEBUG MARKER: == recovery-small test 61: Verify to not reuse orphan objects - bug 17025 ========================================================== 08:35:33 (1784291733) [ 3479.702076] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3483.619137] Lustre: lustre-MDT0000-mdc-ffff9cbe10035000: Connection to lustre-MDT0000 (at 192.168.203.109@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 3483.624828] Lustre: Skipped 13 previous similar messages [ 3488.741000] LustreError: lustre-MDT0000-mdc-ffff9cbe10035000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 3498.982117] Lustre: DEBUG MARKER: == recovery-small test 65: lock enqueue for destroyed export ========================================================== 08:35:55 (1784291755) [ 3499.110424] Lustre: Mounted lustre-client [ 3504.613726] LustreError: lustre-OST0000-osc-ffff9cbe10035000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 3515.186875] Lustre: Unmounted lustre-client [ 3517.250496] Lustre: DEBUG MARKER: == recovery-small test 66: lock enqueue re-send vs client eviction ========================================================== 08:36:14 (1784291774) [ 3522.036536] LustreError: lustre-MDT0000-mdc-ffff9cbe10035000: operation ldlm_enqueue to node 192.168.203.109@tcp failed: rc = -107 [ 3522.041518] LustreError: Skipped 1 previous similar message [ 3522.046666] LustreError: lustre-MDT0000-mdc-ffff9cbe10035000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 3522.054261] LustreError: 62502:0:(file.c:6088:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -5 [ 3524.406445] Lustre: DEBUG MARKER: == recovery-small test 67: connect vs import invalidate race ========================================================== 08:36:21 (1784291781) [ 3524.465143] LustreError: 63211:0:(recover.c:329:ptlrpc_recover_import()) cfs_race id 531 sleeping [ 3527.799103] LustreError: lustre-MDT0000-mdc-ffff9cbe10035000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 3527.803761] LustreError: 63229:0:(import.c:293:ptlrpc_invalidate_import()) cfs_fail_race id 531 waking [ 3527.808208] LustreError: 63211:0:(recover.c:329:ptlrpc_recover_import()) cfs_fail_race id 531 awake: rc=1661 [ 3527.810783] LustreError: 63211:0:(import.c:717:ptlrpc_connect_import_locked()) already connecting [ 3527.821940] LustreError: 63234:0:(file.c:6088:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 3528.850781] LustreError: 63240:0:(file.c:6088:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 3528.853886] LustreError: 63240:0:(file.c:6088:ll_inode_revalidate_fini()) Skipped 5 previous similar messages [ 3530.937711] LustreError: 63263:0:(file.c:6088:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 3530.941020] LustreError: 63263:0:(file.c:6088:ll_inode_revalidate_fini()) Skipped 13 previous similar messages [ 3535.101532] LustreError: 63307:0:(file.c:6088:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 3535.105492] LustreError: 63307:0:(file.c:6088:ll_inode_revalidate_fini()) Skipped 27 previous similar messages [ 3540.518028] Lustre: DEBUG MARKER: == recovery-small test 100: IR: Make sure normal recovery still works w/o IR ========================================================== 08:36:37 (1784291797) [ 3561.648652] Lustre: DEBUG MARKER: oleg309-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 3562.196166] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 3566.052541] Lustre: DEBUG MARKER: == recovery-small test 101a: IR: Make sure IR works w/o normal recovery ========================================================== 08:37:02 (1784291822) [ 3585.668328] Lustre: DEBUG MARKER: oleg309-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 3586.192814] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 3590.283973] Lustre: DEBUG MARKER: == recovery-small test 101b: IR: Make sure IR works w/o normal recovery and proceed EAGAIN ========================================================== 08:37:27 (1784291847) [ 3636.507898] Lustre: DEBUG MARKER: oleg309-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 3637.005759] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 3640.429518] Lustre: DEBUG MARKER: == recovery-small test 102: IR: New client gets updated nidtbl after MGS restart ========================================================== 08:38:17 (1784291897) [ 3660.301328] Lustre: DEBUG MARKER: oleg309-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 3660.806343] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 3663.091142] Lustre: Unmounted lustre-client [ 3687.554972] Lustre: DEBUG MARKER: oleg309-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 3689.026172] Lustre: Mounted lustre-client [ 3691.227306] Lustre: DEBUG MARKER: == recovery-small test 103: IR: MDS can start w/o MGS and get updated nidtbl later ========================================================== 08:39:08 (1784291948) [ 3692.041127] Lustre: DEBUG MARKER: SKIP: recovery-small test_103 needs separate mgs and mds [ 3692.569607] Lustre: DEBUG MARKER: == recovery-small test 104: IR: ost can disable IR voluntarily ========================================================== 08:39:09 (1784291949) [ 3703.262112] Lustre: DEBUG MARKER: == recovery-small test 105: IR: NON IR clients support === 08:39:20 (1784291960) [ 3703.756982] Lustre: DEBUG MARKER: SKIP: recovery-small test_105 Needs multiple clients [ 3704.282302] Lustre: DEBUG MARKER: == recovery-small test 106: lightweight connection support ========================================================== 08:39:21 (1784291961) [ 3704.689391] Lustre: *** cfs_fail_loc=805, val=0*** [ 3707.479658] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 3725.283159] LustreError: MGC192.168.203.109@tcp: Connection to MGS (at 192.168.203.109@tcp) was lost; in progress operations using this service will fail [ 3725.291385] LustreError: Skipped 1 previous similar message [ 3725.292936] LustreError: 2378:0:(ldlm_resource.c:1207:ldlm_resource_complain()) lustre-MDT0000-mdc-ffff9cbe08469800: namespace resource [0x200000007:0x1:0x0].0x0 (ffff9cbe066f7900) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 3725.307233] Lustre: Evicted from MGS (at 192.168.203.109@tcp) after server handle changed from 0x1b0d482b22bb8fe4 to 0x1b0d482b22bb941a [ 3725.312733] Lustre: Skipped 1 previous similar message [ 3728.208346] Lustre: Unmounted lustre-client [ 3730.631427] Lustre: DEBUG MARKER: == recovery-small test 107: drop reint reply, then restart MDT ========================================================== 08:39:47 (1784291987) [ 3745.771605] LustreError: 2378:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9cbe07702d80 x1870961966096768/t90194313219(90194313219) o101->lustre-MDT0000-mdc-ffff9cbe20bb5000@192.168.203.109@tcp:12/10 lens 520/664 e 0 to 0 dl 1784292063 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'multiop.0' uid:0 gid:0 projid:0 [ 3750.418668] Lustre: lustre-MDT0000-mdc-ffff9cbe20bb5000: Connection restored to 192.168.203.109@tcp (at 192.168.203.109@tcp) [ 3750.421244] Lustre: Skipped 29 previous similar messages [ 3752.231187] Lustre: DEBUG MARKER: oleg309-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3752.763461] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3756.157170] Lustre: DEBUG MARKER: == recovery-small test 108: client eviction don't crash == 08:40:12 (1784292012) [ 3761.124303] LustreError: 2378:0:(osc_request.c:1024:osc_init_grant()) lustre-OST0000-osc-ffff9cbe20bb5000: granted 8437760 but already consumed 12582912 [ 3761.127610] LustreError: lustre-OST0000-osc-ffff9cbe20bb5000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 3761.131811] Lustre: 2381:0:(llite_lib.c:4327:ll_dirty_page_discard_warn()) lustre: dirty page discard: 192.168.203.109@tcp:/lustre/fid: [0x20000a042:0x6:0x0]// may get corrupted (rc -5) [ 3761.230446] LustreError: 74501:0:(ldlm_resource.c:1207:ldlm_resource_complain()) lustre-OST0000-osc-ffff9cbe20bb5000: namespace resource [0x280000401:0x2f22:0x0].0x0 (ffff9cbe06dbad00) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 3761.234759] LustreError: 74501:0:(ldlm_resource.c:1207:ldlm_resource_complain()) Skipped 1 previous similar message [ 3764.629606] Lustre: DEBUG MARKER: == recovery-small test 110a: create remote directory: drop client req ========================================================== 08:40:21 (1784292021) [ 3825.631147] Lustre: 75161:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1784292022/real 1784292022] req@ffff9cbe06d0a300 x1870961966108160/t0(0) o101->lustre-MDT0000-mdc-ffff9cbe20bb5000@192.168.203.109@tcp:12/10 lens 576/1152 e 0 to 1 dl 1784292082 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'lfs.0' uid:0 gid:0 projid:0 [ 3825.637474] Lustre: 75161:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 3828.189703] Lustre: DEBUG MARKER: == recovery-small test 110b: create remote directory: drop Master rep ========================================================== 08:41:25 (1784292085) [ 3890.816475] Lustre: DEBUG MARKER: == recovery-small test 110c: create remote directory: drop update rep on slave MDT ========================================================== 08:42:27 (1784292147) [ 3909.169173] Lustre: DEBUG MARKER: == recovery-small test 110d: remove remote directory: drop client req ========================================================== 08:42:46 (1784292166) [ 3971.662114] Lustre: DEBUG MARKER: == recovery-small test 110e: remove remote directory: drop master rep ========================================================== 08:43:48 (1784292228) [ 4035.125624] Lustre: DEBUG MARKER: == recovery-small test 110f: remove remote directory: drop slave rep ========================================================== 08:44:51 (1784292291) [ 4054.530319] Lustre: DEBUG MARKER: == recovery-small test 110g: drop reply during migration ========================================================== 08:45:11 (1784292311) [ 4115.423236] Lustre: lustre-MDT0001-mdc-ffff9cbe20bb5000: Connection to lustre-MDT0001 (at 192.168.203.109@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 4115.429887] Lustre: Skipped 19 previous similar messages [ 4117.923759] Lustre: DEBUG MARKER: == recovery-small test 110h: drop update reply during cross-MDT file rename ========================================================== 08:46:14 (1784292374) [ 4136.570898] Lustre: DEBUG MARKER: == recovery-small test 110i: drop update reply during cross-MDT dir rename ========================================================== 08:46:33 (1784292393) [ 4155.965068] Lustre: DEBUG MARKER: == recovery-small test 110j: drop update reply during cross-MDT ln ========================================================== 08:46:52 (1784292412) [ 4174.369315] Lustre: DEBUG MARKER: == recovery-small test 110k: FID_QUERY failed during recovery ========================================================== 08:47:11 (1784292431) [ 4174.465421] Lustre: Unmounted lustre-client [ 4188.908496] Lustre: Mounted lustre-client [ 4188.909761] Lustre: Skipped 1 previous similar message [ 4198.202345] Lustre: DEBUG MARKER: == recovery-small test 110m: update resent vs original RPC race ========================================================== 08:47:35 (1784292455) [ 4209.664102] Lustre: DEBUG MARKER: == recovery-small test 111: mdd setup fail should not cause umount oops ========================================================== 08:47:46 (1784292466) [ 4219.875404] LustreError: MGC192.168.203.109@tcp: Connection to MGS (at 192.168.203.109@tcp) was lost; in progress operations using this service will fail [ 4219.879477] LustreError: Skipped 1 previous similar message [ 4219.884439] Lustre: Evicted from MGS (at 192.168.203.109@tcp) after server handle changed from 0x1b0d482b22bbbe1a to 0x1b0d482b22bbc37d [ 4219.887410] Lustre: Skipped 1 previous similar message [ 4220.765353] Lustre: DEBUG MARKER: == recovery-small test 112a: bulk resend while orignal request is in progress ========================================================== 08:47:57 (1784292477) [ 4244.796971] Lustre: DEBUG MARKER: == recovery-small test 115a: read: late REQ MDunlink and no bulk ========================================================== 08:48:21 (1784292501) [ 4244.890251] Lustre: *** cfs_fail_loc=51b, val=3*** [ 4250.854889] Lustre: DEBUG MARKER: == recovery-small test 115b: write: late REQ MDunlink and no bulk ========================================================== 08:48:27 (1784292507) [ 4250.936930] Lustre: *** cfs_fail_loc=51b, val=4*** [ 4257.026543] Lustre: DEBUG MARKER: == recovery-small test 115c: read: late Reply MDunlink and no bulk ========================================================== 08:48:33 (1784292513) [ 4257.113855] Lustre: *** cfs_fail_loc=50f, val=3*** [ 4260.741751] Lustre: DEBUG MARKER: == recovery-small test 115d: write: late Reply MDunlink and no bulk ========================================================== 08:48:37 (1784292517) [ 4260.811413] Lustre: *** cfs_fail_loc=50f, val=4*** [ 4264.309701] Lustre: DEBUG MARKER: == recovery-small test 115e: read: late Bulk MDunlink and no reply ========================================================== 08:48:41 (1784292521) [ 4264.394077] Lustre: *** cfs_fail_loc=510, val=3*** [ 4267.826715] Lustre: DEBUG MARKER: == recovery-small test 115f: read: late REQ MDunlink and no reply ========================================================== 08:48:44 (1784292524) [ 4267.977531] Lustre: *** cfs_fail_loc=51b, val=3*** [ 4274.300522] Lustre: DEBUG MARKER: == recovery-small test 115g: read: late REQ MDunlink and Reply MDunlink ========================================================== 08:48:51 (1784292531) [ 4339.812362] Lustre: DEBUG MARKER: == recovery-small test 120: flock race: completion vs. evict ========================================================== 08:49:56 (1784292596) [ 4340.135109] LustreError: 89279:0:(ldlm_flock.c:803:ldlm_flock_completion_ast()) cfs_fail_timeout id 320 sleeping for 4000ms [ 4343.142546] LustreError: lustre-MDT0000-mdc-ffff9cbe03542000: operation ldlm_enqueue to node 192.168.203.109@tcp failed: rc = -107 [ 4343.150726] LustreError: Skipped 1 previous similar message [ 4343.167898] LustreError: lustre-MDT0000-mdc-ffff9cbe03542000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 4343.181169] LustreError: 89293:0:(file.c:251:ll_close_inode_openhandle()) lustre-clilmv-ffff9cbe03542000: inode [0x20000afe2:0x3:0x0] mdc close failed: rc = -108 [ 4343.220095] LustreError: 89293:0:(ldlm_resource.c:1207:ldlm_resource_complain()) lustre-MDT0000-mdc-ffff9cbe03542000: namespace resource [0x20000afe2:0xc:0x0].0xc (ffff9cbe036d7600) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 4344.215162] LustreError: 89279:0:(ldlm_flock.c:803:ldlm_flock_completion_ast()) cfs_fail_timeout id 320 awake [ 4346.334036] LustreError: 89309:0:(ldlm_flock.c:803:ldlm_flock_completion_ast()) cfs_fail_timeout id 320 sleeping for 4000ms [ 4349.330214] LustreError: lustre-MDT0000-mdc-ffff9cbe03542000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 4349.350447] LustreError: 89323:0:(ldlm_resource.c:1207:ldlm_resource_complain()) lustre-MDT0000-mdc-ffff9cbe03542000: namespace resource [0x20000afe2:0xc:0x0].0xc (ffff9cbe05949000) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 4349.370687] LustreError: 89323:0:(ldlm_resource.c:1207:ldlm_resource_complain()) Skipped 1 previous similar message [ 4350.431154] LustreError: 89309:0:(ldlm_flock.c:803:ldlm_flock_completion_ast()) cfs_fail_timeout id 320 awake [ 4356.756437] LustreError: lustre-MDT0000-mdc-ffff9cbe03542000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 4356.767313] Lustre: lustre-MDT0000-mdc-ffff9cbe03542000: Connection restored to 192.168.203.109@tcp (at 192.168.203.109@tcp) [ 4356.771643] Lustre: Skipped 9 previous similar messages [ 4356.937415] LustreError: 89365:0:(ldlm_flock.c:808:ldlm_flock_completion_ast()) cfs_fail_timeout id 321 sleeping for 4000ms [ 4359.235303] LustreError: lustre-MDT0000-mdc-ffff9cbe03542000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 4359.256098] LustreError: 89385:0:(file.c:6088:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 4359.258695] LustreError: 89385:0:(file.c:6088:ll_inode_revalidate_fini()) Skipped 20 previous similar messages [ 4360.285476] LustreError: 89391:0:(file.c:6088:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 4360.290105] LustreError: 89391:0:(file.c:6088:ll_inode_revalidate_fini()) Skipped 5 previous similar messages [ 4360.999113] LustreError: 89365:0:(ldlm_flock.c:808:ldlm_flock_completion_ast()) cfs_fail_timeout id 321 awake [ 4361.003548] LustreError: 89365:0:(file.c:251:ll_close_inode_openhandle()) lustre-clilmv-ffff9cbe03542000: inode [0x20000afe2:0xc:0x0] mdc close failed: rc = -108 [ 4361.008945] LustreError: 89365:0:(file.c:251:ll_close_inode_openhandle()) Skipped 4 previous similar messages [ 4362.396594] LustreError: 89413:0:(file.c:6088:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 4362.400331] LustreError: 89413:0:(file.c:6088:ll_inode_revalidate_fini()) Skipped 13 previous similar messages [ 4365.609872] LustreError: 89440:0:(ldlm_flock.c:808:ldlm_flock_completion_ast()) cfs_fail_timeout id 321 sleeping for 4000ms [ 4367.922733] LustreError: lustre-MDT0000-mdc-ffff9cbe03542000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 4367.928836] LustreError: 89454:0:(ldlm_resource.c:1207:ldlm_resource_complain()) lustre-MDT0000-mdc-ffff9cbe03542000: namespace resource [0x20000afe2:0xc:0x0].0xc (ffff9cbe05949d00) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 4367.934078] LustreError: 89454:0:(ldlm_resource.c:1207:ldlm_resource_complain()) Skipped 1 previous similar message [ 4369.671182] LustreError: 89440:0:(ldlm_flock.c:808:ldlm_flock_completion_ast()) cfs_fail_timeout id 321 awake [ 4376.029888] LustreError: lustre-MDT0000-mdc-ffff9cbe03542000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 4376.182631] LustreError: 89495:0:(ldlm_flock.c:857:ldlm_flock_completion_ast()) cfs_fail_timeout id 322 sleeping for 4000ms [ 4378.564290] LustreError: lustre-MDT0000-mdc-ffff9cbe03542000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 4378.572685] LustreError: 89510:0:(ldlm_resource.c:1207:ldlm_resource_complain()) lustre-MDT0000-mdc-ffff9cbe03542000: namespace resource [0x20000afe2:0xc:0x0].0xc (ffff9cbe10465600) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 4378.579460] LustreError: 89510:0:(ldlm_resource.c:1207:ldlm_resource_complain()) Skipped 1 previous similar message [ 4380.247131] LustreError: 89495:0:(ldlm_flock.c:857:ldlm_flock_completion_ast()) cfs_fail_timeout id 322 awake [ 4382.640454] LustreError: lustre-MDT0000-mdc-ffff9cbe03542000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 4382.663419] LustreError: 89542:0:(file.c:6088:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 4382.667561] LustreError: 89542:0:(file.c:6088:ll_inode_revalidate_fini()) Skipped 6 previous similar messages [ 4384.343534] LustreError: 89523:0:(file.c:251:ll_close_inode_openhandle()) lustre-clilmv-ffff9cbe03542000: inode [0x20000afe2:0xc:0x0] mdc close failed: rc = -108 [ 4390.989086] LustreError: 89594:0:(ldlm_flock.c:803:ldlm_flock_completion_ast()) cfs_fail_timeout id 320 sleeping for 4000ms [ 4390.993230] LustreError: 89594:0:(ldlm_flock.c:803:ldlm_flock_completion_ast()) Skipped 1 previous similar message [ 4393.538729] LustreError: lustre-MDT0000-mdc-ffff9cbe03542000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 4393.562297] LustreError: 89616:0:(file.c:6088:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 4393.565400] LustreError: 89616:0:(file.c:6088:ll_inode_revalidate_fini()) Skipped 26 previous similar messages [ 4395.055109] LustreError: 89594:0:(ldlm_flock.c:803:ldlm_flock_completion_ast()) cfs_fail_timeout id 320 awake [ 4395.058617] LustreError: 89594:0:(ldlm_flock.c:803:ldlm_flock_completion_ast()) Skipped 1 previous similar message [ 4395.061914] LustreError: 89594:0:(file.c:251:ll_close_inode_openhandle()) lustre-clilmv-ffff9cbe03542000: inode [0x20000afe2:0xc:0x0] mdc close failed: rc = -108 [ 4400.054048] Lustre: DEBUG MARKER: == recovery-small test 113: ldlm enqueue dropped reply should not cause deadlocks ========================================================== 08:50:56 (1784292656) [ 4460.511345] Lustre: 90313:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1784292657/real 1784292657] req@ffff9cbe065b2680 x1870961966316928/t0(0) o101->lustre-MDT0000-mdc-ffff9cbe03542000@192.168.203.109@tcp:12/10 lens 576/1152 e 0 to 1 dl 1784292717 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'stat.0' uid:0 gid:0 projid:0 [ 4460.522804] Lustre: 90313:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 7 previous similar messages [ 4461.303507] LustreError: 84689:0:(ldlm_lockd.c:2890:ldlm_bl_thread_blwi()) cfs_fail_timeout id 31f sleeping for 4000ms [ 4461.308459] LustreError: 84689:0:(ldlm_lockd.c:2890:ldlm_bl_thread_blwi()) Skipped 1 previous similar message [ 4465.367134] LustreError: 84689:0:(ldlm_lockd.c:2890:ldlm_bl_thread_blwi()) cfs_fail_timeout id 31f awake [ 4465.371254] LustreError: 84689:0:(ldlm_lockd.c:2890:ldlm_bl_thread_blwi()) Skipped 1 previous similar message [ 4468.103582] Lustre: DEBUG MARKER: == recovery-small test 130a: enqueue resend on not existing file ========================================================== 08:52:04 (1784292724) [ 4531.136791] Lustre: DEBUG MARKER: == recovery-small test 130b: enqueue resend on a stale inode ========================================================== 08:53:08 (1784292788) [ 4593.841678] Lustre: DEBUG MARKER: == recovery-small test 130c: layout intent resend on a stale inode ========================================================== 08:54:10 (1784292850) [ 4619.746620] Lustre: DEBUG MARKER: == recovery-small test 132: long punch =================== 08:54:36 (1784292876) [ 4619.868829] Lustre: Mounted lustre-client [ 4740.634679] Lustre: Unmounted lustre-client [ 4742.909166] Lustre: DEBUG MARKER: == recovery-small test 131: IO vs evict results to IO under staled lock ========================================================== 08:56:39 (1784292999) [ 4743.089667] LustreError: 93998:0:(osc_request.c:2989:osc_build_rpc()) cfs_fail_timeout id 414 sleeping for 10000ms [ 4744.015324] Lustre: lustre-OST0000-osc-ffff9cbe03542000: Connection to lustre-OST0000 (at 192.168.203.109@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 4744.019039] Lustre: Skipped 14 previous similar messages [ 4744.022507] LustreError: lustre-OST0000-osc-ffff9cbe03542000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 4744.027705] LustreError: 94080:0:(ldlm_resource.c:1207:ldlm_resource_complain()) lustre-OST0000-osc-ffff9cbe03542000: namespace resource [0x280000401:0x2f4d:0x0].0x0 (ffff9cbe10465300) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 4744.035090] LustreError: 94080:0:(ldlm_resource.c:1207:ldlm_resource_complain()) Skipped 1 previous similar message [ 4744.135040] LustreError: 93998:0:(osc_request.c:2989:osc_build_rpc()) cfs_fail_timeout interrupted [ 4744.139262] Lustre: 2381:0:(llite_lib.c:4327:ll_dirty_page_discard_warn()) lustre: dirty page discard: 192.168.203.109@tcp:/lustre/fid: [0x20000bf89:0x9:0x0]// may get corrupted (rc -108) [ 4746.295219] Lustre: DEBUG MARKER: == recovery-small test 133: don't fail on flock resend === 08:56:43 (1784293003) [ 4788.757862] Lustre: DEBUG MARKER: == recovery-small test 134: race between failover and search for reply data free slot ========================================================== 08:57:25 (1784293045) [ 4789.259693] Lustre: DEBUG MARKER: SKIP: recovery-small test_134 Need 2+ clients, have 1 [ 4789.809779] Lustre: DEBUG MARKER: == recovery-small test 135: DOM: open/create resend to return size ========================================================== 08:57:26 (1784293046) [ 4813.913219] Lustre: DEBUG MARKER: SKIP: recovery-small test_136 skipping excluded test 136 [ 4814.482281] Lustre: DEBUG MARKER: == recovery-small test 137: late resend must be skipped if already applied ========================================================== 08:57:51 (1784293071) [ 4838.030970] Lustre: DEBUG MARKER: == recovery-small test 138: Umount MDT during recovery === 08:58:14 (1784293094) [ 4941.302537] Lustre: Mounted lustre-client [ 4943.278973] Lustre: DEBUG MARKER: == recovery-small test 139: corrupted catid won't cause crash ========================================================== 09:00:00 (1784293200) [ 4950.800195] Lustre: DEBUG MARKER: == recovery-small test 140a: local mount is flagged properly ========================================================== 09:00:07 (1784293207) [ 4951.521566] LustreError: MGC192.168.203.109@tcp: Connection to MGS (at 192.168.203.109@tcp) was lost; in progress operations using this service will fail [ 4951.527378] Lustre: Evicted from MGS (at 192.168.203.109@tcp) after server handle changed from 0x1b0d482b22bbde96 to 0x1b0d482b22bbe201 [ 4965.543372] Lustre: DEBUG MARKER: == recovery-small test 140b: local mount is excluded from recovery ========================================================== 09:00:22 (1784293222) [ 4970.335393] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 4987.364710] Lustre: MGC192.168.203.109@tcp: Connection restored to 192.168.203.109@tcp (at 192.168.203.109@tcp) [ 4987.369040] Lustre: Skipped 14 previous similar messages [ 4993.817994] Lustre: DEBUG MARKER: oleg309-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4994.355875] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4998.360245] Lustre: DEBUG MARKER: == recovery-small test 141: do not lose locks on MGS restart ========================================================== 09:00:55 (1784293255) [ 4999.117166] Lustre: DEBUG MARKER: SKIP: recovery-small test_141 cannot run in local mode or from build tree [ 4999.624135] Lustre: DEBUG MARKER: == recovery-small test 142: orphan name stub can be cleaned up in startup ========================================================== 09:00:56 (1784293256) [ 5007.801974] Lustre: DEBUG MARKER: == recovery-small test 143: orphan cleanup thread shouldn't be blocked even delete failed ========================================================== 09:01:04 (1784293264) [ 5018.083233] Lustre: 97573:0:(mgc_request.c:1899:mgc_process_log()) MGC192.168.203.109@tcp: IR log lustre-cliir failed, not fatal: rc = -5 [ 5033.520723] Lustre: DEBUG MARKER: == recovery-small test 144a: MDT failover should stop precreation threads ========================================================== 09:01:30 (1784293290) [ 5035.716253] LustreError: lustre-OST0000-osc-ffff9cbe061fc800: operation ost_setattr to node 192.168.203.109@tcp failed: rc = -107 [ 5035.719051] LustreError: Skipped 10 previous similar messages [ 5062.528197] Lustre: DEBUG MARKER: oleg309-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 5063.311029] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 5147.444622] Lustre: DEBUG MARKER: oleg309-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5148.000176] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5170.503285] Lustre: DEBUG MARKER: oleg309-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5171.026163] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5225.196513] Lustre: DEBUG MARKER: == recovery-small test 144b: orphan cleanup shouldn't be blocked for no objects+failover situation ========================================================== 09:04:42 (1784293482) [ 5256.171864] Lustre: DEBUG MARKER: oleg309-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 5257.227894] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 5375.648753] Lustre: DEBUG MARKER: == recovery-small test 144c: reconnection during orphan cleanup shouldn't lose LAST_ID synchronization ========================================================== 09:07:12 (1784293632) [ 5427.685644] Lustre: lustre-MDT0000-mdc-ffff9cbe061fc800: Connection to lustre-MDT0000 (at 192.168.203.109@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 5427.691963] Lustre: Skipped 10 previous similar messages [ 5455.974188] Lustre: DEBUG MARKER: == recovery-small test 145: connect mdtlovs and process update logs after recovery expire ========================================================== 09:08:32 (1784293712) [ 5456.452781] Lustre: DEBUG MARKER: SKIP: recovery-small test_145 needs >= 3 MDTs [ 5457.005723] Lustre: DEBUG MARKER: == recovery-small test 146: test eviction is counted properly ========================================================== 09:08:33 (1784293713) [ 5457.675789] LustreError: lustre-MDT0000-mdc-ffff9cbe061fc800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5460.325376] Lustre: DEBUG MARKER: == recovery-small test 147: Check client reconnect ======= 09:08:37 (1784293717) [ 5625.827611] Lustre: Evicted from lustre-OST0000_UUID (at 192.168.203.109@tcp) after server handle changed from 0x1b0d482b22cba733 to 0x1b0d482b22cba836 [ 5625.832225] Lustre: Skipped 6 previous similar messages [ 5625.834369] LustreError: lustre-OST0000-osc-ffff9cbe061fc800: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 5626.499430] Lustre: DEBUG MARKER: == recovery-small test 148: data corruption through resend ========================================================== 09:11:23 (1784293883) [ 5649.311109] Lustre: 2381:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1784293886/real 1784293886] req@ffff9cbe08adb480 x1870961984112512/t0(0) o4->lustre-OST0000-osc-ffff9cbe061fc800@192.168.203.109@tcp:6/4 lens 4584/448 e 0 to 1 dl 1784293906 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'dd.0' uid:0 gid:0 projid:0 [ 5649.319125] Lustre: 2381:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 6 previous similar messages [ 5649.324141] Lustre: lustre-OST0000-osc-ffff9cbe061fc800: Connection restored to 192.168.203.109@tcp (at 192.168.203.109@tcp) [ 5649.327562] Lustre: Skipped 11 previous similar messages [ 5661.467667] Lustre: DEBUG MARKER: == recovery-small test 149: skip orphan removal at umount ========================================================== 09:11:58 (1784293918) [ 5682.145598] LustreError: MGC192.168.203.109@tcp: Connection to MGS (at 192.168.203.109@tcp) was lost; in progress operations using this service will fail [ 5682.150954] LustreError: Skipped 6 previous similar messages [ 5692.386326] LustreError: lustre-MDT0000-mdc-ffff9cbe061fc800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5692.391483] LustreError: 111825:0:(file.c:251:ll_close_inode_openhandle()) lustre-clilmv-ffff9cbe061fc800: inode [0x2000105d1:0x6:0x0] mdc close failed: rc = -5 [ 5697.507547] LustreError: lustre-MDT0001-mdc-ffff9cbe061fc800: This client was evicted by lustre-MDT0001; in progress operations using this service will fail. [ 5700.071138] Lustre: DEBUG MARKER: == recovery-small test 150: statfs when MDT0 offline with lazystatfs option ========================================================== 09:12:36 (1784293956) [ 5701.794520] LustreError: lustre-MDT0000-mdc-ffff9cbe061fc800: operation mds_statfs to node 192.168.203.109@tcp failed: rc = -107 [ 5701.798664] LustreError: Skipped 267 previous similar messages [ 5701.802111] LustreError: 112948:0:(lmv_obd.c:1468:lmv_statfs()) lustre-MDT0000-mdc-ffff9cbe061fc800: can't stat MDS #0: rc = -107 [ 5716.111420] Lustre: DEBUG MARKER: == recovery-small test 152: QoS object allocation could be awakened in case of OST failover ========================================================== 09:12:52 (1784293972) [ 5741.787797] Lustre: DEBUG MARKER: == recovery-small test 153: evict vs reconnect race ====== 09:13:18 (1784293998) [ 5779.145275] Lustre: DEBUG MARKER: == recovery-small test 154a: corruption update llog can be skipped ========================================================== 09:13:55 (1784294035) [ 5801.265852] Lustre: DEBUG MARKER: == recovery-small test 154b: restore update llog after failed recovery ========================================================== 09:14:18 (1784294058) [ 5812.195288] LustreError: lustre-MDT0000-mdc-ffff9cbe061fc800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5813.953088] Lustre: Mounted lustre-client [ 5814.328232] Lustre: Unmounted lustre-client [ 5814.329800] Lustre: Skipped 1 previous similar message [ 5820.791734] Lustre: DEBUG MARKER: == recovery-small test 155: failover after client remount ========================================================== 09:14:37 (1784294077) [ 5824.018926] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5846.927780] Lustre: DEBUG MARKER: == recovery-small test 156: tot_granted miscount after client eviction ========================================================== 09:15:03 (1784294103) [ 5850.199351] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-OST0000 [ 5865.955263] LustreError: 2378:0:(client.c:3533:ptlrpc_replay_req()) cfs_fail_timeout id 536 sleeping for 45000ms [ 5910.991203] LustreError: 2378:0:(client.c:3533:ptlrpc_replay_req()) cfs_fail_timeout id 536 awake [ 5910.998501] LustreError: lustre-OST0000-osc-ffff9cbe2054c000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 5913.120466] Lustre: DEBUG MARKER: oleg309-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 5913.668941] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 5918.137663] Lustre: DEBUG MARKER: == recovery-small test 157: eviction during mmaped i/o === 09:16:14 (1784294174) [ 5918.293273] LustreError: 120080:0:(vvp_io.c:1490:vvp_io_fault_start()) cfs_fail_timeout id 1432 sleeping for 3000ms [ 5920.231023] LustreError: lustre-OST0000-osc-ffff9cbe2054c000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 5920.236220] LustreError: 120094:0:(ldlm_resource.c:1207:ldlm_resource_complain()) lustre-OST0000-osc-ffff9cbe2054c000: namespace resource [0x280000402:0x18c3:0x0].0x0 (ffff9cbe4053ea00) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 5920.243018] LustreError: 120094:0:(ldlm_resource.c:1207:ldlm_resource_complain()) Skipped 1 previous similar message [ 5921.311129] LustreError: 120080:0:(vvp_io.c:1490:vvp_io_fault_start()) cfs_fail_timeout id 1432 awake [ 5923.391191] Lustre: DEBUG MARKER: == recovery-small test 158a: connect without access right ========================================================== 09:16:20 (1784294180) [ 5923.738162] Lustre: Unmounted lustre-client [ 5923.740197] Lustre: Skipped 2 previous similar messages [ 5923.851325] Lustre: Mounted lustre-client [ 5923.852326] Lustre: Skipped 2 previous similar messages [ 5938.981249] Lustre: lustre-MDT0001-mdc-ffff9cbe10036000: connection denied by lustre-MDT0001_UUID: rc = -13 [ 5938.985278] LustreError: lustre-MDT0001-mdc-ffff9cbe10036000: This client was evicted by lustre-MDT0001; in progress operations using this service will fail. [ 5956.115987] LustreError: lustre-MDT0001-mdc-ffff9cbe10036000: This client was evicted by lustre-MDT0001; in progress operations using this service will fail. [ 5958.384555] Lustre: Unmounted lustre-client [ 5958.510372] Lustre: Mounted lustre-client [ 5960.442161] Lustre: DEBUG MARKER: == recovery-small test 160: MDT destroys are blocked by grouplocks ========================================================== 09:16:57 (1784294217) [ 5962.892661] LustreError: lustre-MDT0000-mdc-ffff9cbe20548800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 6003.425453] Lustre: DEBUG MARKER: == recovery-small test 161: evict osp by ping evictor ==== 09:17:40 (1784294260) [ 6016.150180] Lustre: DEBUG MARKER: == recovery-small test 162: File attributes should be persisted after MDS failover ========================================================== 09:17:52 (1784294272) [ 6021.811708] LustreError: 2378:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9cbe0845d500 x1870961984451840/t154618822723(154618822723) o101->lustre-MDT0000-mdc-ffff9cbe20548800@192.168.203.109@tcp:12/10 lens 576/608 e 0 to 0 dl 1784294335 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'chattr.0' uid:0 gid:0 projid:0 [ 6030.460747] Lustre: DEBUG MARKER: == recovery-small test 163: changelog check for fail write and processing records ========================================================== 09:18:07 (1784294287) [ 6038.856522] Lustre: DEBUG MARKER: == recovery-small test 170: Reconnect after REPLAY_LOCKS hangs (LU-18154) ========================================================== 09:18:15 (1784294295) [ 6041.632518] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-OST0000 [ 6044.130465] Lustre: lustre-OST0000-osc-ffff9cbe20548800: Connection to lustre-OST0000 (at 192.168.203.109@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 6044.136658] Lustre: Skipped 16 previous similar messages [ 6061.623898] Lustre: DEBUG MARKER: oleg309-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 60 0 [ 6068.959629] Lustre: *** cfs_fail_loc=537, val=0*** [ 6068.962351] LustreError: 2378:0:(import.c:717:ptlrpc_connect_import_locked()) already connecting [ 6070.302528] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 8 sec [ 6072.600492] Lustre: DEBUG MARKER: == recovery-small test complete, duration 5945 sec ======= 09:18:49 (1784294329) [ 6073.225035] Lustre: DEBUG MARKER: === recovery-small: start cleanup 09:18:49 (1784294329) === [ 6164.394938] Lustre: DEBUG MARKER: === recovery-small: finish cleanup 09:20:21 (1784294421) === [ 6164.846923] Lustre: Unmounted lustre-client [ 6202.464545] Key type lgssc unregistered [ 6202.579562] LNet: 127549:0:(lib-ptl.c:967:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 6202.583786] LNetError: 127549:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 6202.592910] LNet: Removed LNI 192.168.203.9@tcp [ 6202.897113] Key type .llcrypt unregistered [ 6202.898420] Key type ._llcrypt unregistered