[ 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 436725791 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, 524584K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] ftrace: allocating 41240 entries in 162 pages [ 0.000000] ftrace: allocated 162 pages with 3 groups [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] rcu: RCU event tracing is enabled. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ 0.000000] rcu: RCU callback double-/use-after-free debug enabled. [ 0.000000] Rude variant of Tasks RCU enabled. [ 0.000000] Tracing variant of Tasks RCU enabled. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 0.000000] NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16 [ 0.000000] random: get_random_bytes called from start_kernel+0x622/0x9a8 with crng_init=0 [ 0.001000] Console: colour *CGA 80x25 [ 0.001000] printk: console [ttyS1] enabled [ 0.001000] ACPI: Core revision 20220331 [ 0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.001011] APIC: Switch to symmetric I/O mode setup [ 0.003355] x2apic enabled [ 0.004010] Switched APIC routing to physical x2apic. [ 0.005013] kvm-guest: setup PV IPIs [ 0.008000] ..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.008019] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.009011] pid_max: default: 32768 minimum: 301 [ 0.010134] LSM: Security Framework initializing [ 0.012040] Yama: becoming mindful. [ 0.013047] SELinux: Initializing. [ 0.014069] *** VALIDATE selinux *** [ 0.022197] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.027125] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.028153] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.029098] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.030112] *** VALIDATE tmpfs *** [ 0.032441] *** VALIDATE proc *** [ 0.033246] *** VALIDATE cgroup *** [ 0.034011] *** VALIDATE cgroup2 *** [ 0.035271] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.036149] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.037010] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.038027] Spectre V2 : User space: Vulnerable [ 0.040006] Speculative Store Bypass: Vulnerable [ 0.043013] debug: unmapping init [mem 0xffffffff8bc59000-0xffffffff8bc60fff] [ 0.045163] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.046706] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.047023] ... version: 2 [ 0.048013] ... bit width: 48 [ 0.049014] ... generic registers: 4 [ 0.050011] ... value mask: 0000ffffffffffff [ 0.051012] ... max period: 00007fffffffffff [ 0.052012] ... fixed-purpose events: 3 [ 0.053012] ... event mask: 000000070000000f [ 0.054326] rcu: Hierarchical SRCU implementation. [ 0.056366] smp: Bringing up secondary CPUs ... [ 0.057595] x86: Booting SMP configuration: [ 0.058027] .... node #0, CPUs: #1 #2 #3 [ 0.061294] smp: Brought up 1 node, 4 CPUs [ 0.063013] smpboot: Max logical packages: 1 [ 0.064013] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.141000] node 0 deferred pages initialised in 75ms [ 0.144100] devtmpfs: initialized [ 0.146208] x86/mm: Memory block size: 128MB [ 0.148899] gcov: version magic: 0x41383552 [ 0.150146] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.151079] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.152253] pinctrl core: initialized pinctrl subsystem [ 0.153188] [ 0.153828] ************************************************************* [ 0.154019] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.155012] ** ** [ 0.156015] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.157013] ** ** [ 0.158014] ** This means that this kernel is built to expose internal ** [ 0.159015] ** IOMMU data structures, which may compromise security on ** [ 0.160014] ** your system. ** [ 0.161017] ** ** [ 0.162012] ** If you see this message and you are not debugging the ** [ 0.163016] ** kernel, report this immediately to your vendor! ** [ 0.164013] ** ** [ 0.165016] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.166014] ************************************************************* [ 0.167606] NET: Registered protocol family 16 [ 0.168426] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.169059] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.170063] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.171534] cpuidle: using governor menu [ 0.174291] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.175431] PCI: Using configuration type 1 for base access [ 0.176132] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.183124] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.185021] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.189177] cryptd: max_cpu_qlen set to 1000 [ 0.192009] ACPI: Added _OSI(Module Device) [ 0.193061] ACPI: Added _OSI(Processor Device) [ 0.195014] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.197014] ACPI: Added _OSI(Processor Aggregator Device) [ 0.203000] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.209282] ACPI: Interpreter enabled [ 0.210046] ACPI: PM: (supports S0 S3 S4 S5) [ 0.211012] ACPI: Using IOAPIC for interrupt routing [ 0.212092] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.213475] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.222568] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.223040] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.224019] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.225075] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.227274] acpiphp: Slot [2] registered [ 0.228112] acpiphp: Slot [5] registered [ 0.229116] acpiphp: Slot [6] registered [ 0.230131] acpiphp: Slot [3] registered [ 0.231112] acpiphp: Slot [4] registered [ 0.232101] acpiphp: Slot [7] registered [ 0.233101] acpiphp: Slot [8] registered [ 0.234105] acpiphp: Slot [9] registered [ 0.235098] acpiphp: Slot [10] registered [ 0.236099] acpiphp: Slot [11] registered [ 0.237153] acpiphp: Slot [12] registered [ 0.238099] acpiphp: Slot [13] registered [ 0.239103] acpiphp: Slot [14] registered [ 0.240098] acpiphp: Slot [15] registered [ 0.241097] acpiphp: Slot [16] registered [ 0.242077] acpiphp: Slot [17] registered [ 0.243086] acpiphp: Slot [18] registered [ 0.244059] acpiphp: Slot [19] registered [ 0.245083] acpiphp: Slot [20] registered [ 0.246096] acpiphp: Slot [21] registered [ 0.247104] acpiphp: Slot [22] registered [ 0.248094] acpiphp: Slot [23] registered [ 0.249139] acpiphp: Slot [24] registered [ 0.250120] acpiphp: Slot [25] registered [ 0.251101] acpiphp: Slot [26] registered [ 0.252088] acpiphp: Slot [27] registered [ 0.253098] acpiphp: Slot [28] registered [ 0.254103] acpiphp: Slot [29] registered [ 0.255084] acpiphp: Slot [30] registered [ 0.256116] acpiphp: Slot [31] registered [ 0.257100] PCI host bridge to bus 0000:00 [ 0.258030] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.259015] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.260026] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.261021] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.262021] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.263026] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.264164] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.265756] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.267291] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.271811] pci 0000:00:01.1: reg 0x20: [io 0xc120-0xc12f] [ 0.274013] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.275020] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.276017] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.277015] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.278528] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.279717] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.280045] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.281677] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.288016] pci 0000:00:02.0: reg 0x10: [io 0xc100-0xc11f] [ 0.298016] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.302014] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.308634] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.314014] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.321016] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.333015] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.344152] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.350023] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.376027] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.414018] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.426402] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.429477] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.433395] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.435427] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.437261] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.443140] iommu: Default domain type: Passthrough [ 0.444438] SCSI subsystem initialized [ 0.446200] ACPI: bus type USB registered [ 0.448101] usbcore: registered new interface driver usbfs [ 0.450075] usbcore: registered new interface driver hub [ 0.453102] usbcore: registered new device driver usb [ 0.455152] pps_core: LinuxPPS API ver. 1 registered [ 0.457012] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.461070] PTP clock support registered [ 0.464085] EDAC MC: Ver: 3.0.0 [ 0.465344] PCI: Using ACPI for IRQ routing [ 0.467829] NetLabel: Initializing [ 0.469010] NetLabel: domain hash size = 128 [ 0.471012] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.473079] NetLabel: unlabeled traffic allowed by default [ 0.475091] vgaarb: loaded [ 0.477286] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.478012] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.481171] clocksource: Switched to clocksource kvm-clock [ 0.587834] VFS: Disk quotas dquot_6.6.0 [ 0.589505] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.592694] *** VALIDATE ramfs *** [ 0.594023] *** VALIDATE hugetlbfs *** [ 0.595763] pnp: PnP ACPI init [ 0.598615] pnp: PnP ACPI: found 6 devices [ 0.618613] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.622078] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.624031] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.626236] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.628742] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.631354] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.634212] NET: Registered protocol family 2 [ 0.636616] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.641288] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.645408] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.651242] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.655142] TCP: Hash tables configured (established 65536 bind 65536) [ 0.658404] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.661457] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.663661] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.667034] NET: Registered protocol family 1 [ 0.669568] RPC: Registered named UNIX socket transport module. [ 0.671401] RPC: Registered udp transport module. [ 0.673434] RPC: Registered tcp transport module. [ 0.675165] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.677819] NET: Registered protocol family 44 [ 0.679640] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.681862] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.684203] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.686733] PCI: CLS 0 bytes, default 64 [ 0.688419] Unpacking initramfs... [ 2.079475] debug: unmapping init [mem 0xffff9dbefcc64000-0xffff9dbefffcffff] [ 2.083880] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.086219] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.089171] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 2.602328] Initialise system trusted keyrings [ 2.604930] Key type blacklist registered [ 2.607057] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.616405] zbud: loaded [ 2.619589] *** VALIDATE nfs *** [ 2.621047] *** VALIDATE nfs4 *** [ 2.622800] pstore: using deflate compression [ 2.626522] Platform Keyring initialized [ 2.723862] NET: Registered protocol family 38 [ 2.725620] Key type asymmetric registered [ 2.726838] Asymmetric key parser 'x509' registered [ 2.728923] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 2.731343] io scheduler mq-deadline registered [ 2.732661] io scheduler kyber registered [ 2.733971] io scheduler bfq registered [ 2.735685] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 2.737981] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 2.740158] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 2.742485] ACPI: Power Button [PWRF] [ 2.746239] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 2.752560] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 2.759861] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 2.786913] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 2.816373] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 2.822243] Non-volatile memory driver v1.3 [ 2.823956] Linux agpgart interface v0.103 [ 2.858216] virtio_blk virtio1: [vda] 146136 512-byte logical blocks (74.8 MB/71.4 MiB) [ 2.861311] vda: detected capacity change from 0 to 74821632 [ 2.876237] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 2.878393] vdb: detected capacity change from 0 to 1073741824 [ 2.889898] libphy: Fixed MDIO Bus: probed [ 2.904794] usbcore: registered new interface driver usbserial_generic [ 2.908766] usbserial: USB Serial support registered for generic [ 2.912937] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 2.919412] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 2.921838] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 2.924594] mousedev: PS/2 mouse device common for all mice [ 2.927770] rtc_cmos 00:05: RTC can wake from S4 [ 2.931896] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 2.934786] rtc_cmos 00:05: registered as rtc0 [ 2.936919] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 2.937552] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 2.943446] intel_pstate: CPU model not supported [ 2.946069] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 2.948857] hid: raw HID events driver (C) Jiri Kosina [ 2.952243] usbcore: registered new interface driver usbhid [ 2.954296] usbhid: USB HID core driver [ 2.955972] drop_monitor: Initializing network drop monitor service [ 2.958658] Initializing XFRM netlink socket [ 2.960731] NET: Registered protocol family 10 [ 2.963191] Segment Routing with IPv6 [ 2.965255] NET: Registered protocol family 17 [ 2.967871] mpls_gso: MPLS GSO support [ 2.972557] RAS: Correctable Errors collector initialized. [ 2.974489] AVX version of gcm_enc/dec engaged. [ 2.975646] AES CTR mode by8 optimization enabled [ 3.051061] sched_clock: Marking stable (3051031557, 0)->(4026627492, -975595935) [ 3.054576] registered taskstats version 1 [ 3.056745] Loading compiled-in X.509 certificates [ 3.059572] zswap: loaded using pool lzo/zbud [ 3.082147] Key type big_key registered [ 3.094679] Key type encrypted registered [ 3.096378] ima: No TPM chip found, activating TPM-bypass! [ 3.098534] ima: Allocated hash algorithm: sha1 [ 3.100360] ima: No architecture policies found [ 3.102067] evm: Initialising EVM extended attributes: [ 3.103893] evm: security.selinux [ 3.105150] evm: security.ima [ 3.106310] evm: security.capability [ 3.107803] evm: HMAC attrs: 0x1 [ 3.110125] rtc_cmos 00:05: setting system clock to 2026-08-23 04:47:43 UTC (1787460463) [ 3.116506] debug: unmapping init [mem 0xffffffff8cc03000-0xffffffff8cdfffff] [ 3.119548] debug: unmapping init [mem 0xffffffff8b982000-0xffffffff8bc58fff] [ 3.129127] Write protecting the kernel read-only data: 28672k [ 3.132335] debug: unmapping init [mem 0xffffffff8a003000-0xffffffff8a1fffff] [ 3.135314] debug: unmapping init [mem 0xffffffff8a914000-0xffffffff8a9fffff] [ 3.165119] 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.172345] systemd[1]: Detected virtualization kvm. [ 3.174050] systemd[1]: Detected architecture x86-64. [ 3.176063] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.202170] systemd[1]: No hostname configured. [ 3.204170] systemd[1]: Set hostname to . [ 3.206446] random: systemd: uninitialized urandom read (16 bytes read) [ 3.209198] systemd[1]: Initializing machine ID from random generator. [ 3.336801] random: systemd: uninitialized urandom read (16 bytes read) [ 3.340277] systemd[1]: Reached target Slices. [ OK ] Reached target Slices. [ 3.343960] random: systemd: uninitialized urandom read (16 bytes read) [ 3.346549] systemd[1]: Reached target Initrd Root Device. [ OK ] Reached target Initrd Root Device. [ 3.350794] systemd[1]: Started Dispatch Password Requests to Console Directory Watch. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Listening on Journal Socket. Starting Create list of required st…ce nodes for the current kernel... Starting Apply Kernel Variables... [ OK ] Listening on udev Control Socket. [ OK ] Reached target Timers. [ OK ] Listening on udev Kernel Socket. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Started Memstrack Anylazing Service. [ OK ] Listening on Journal Socket (/dev/log). Starting Journal Service... [ OK ] Reached target Local File Systems. Starting Create Volatile Files and Directories... Starting Setup Virtual Console... [ OK ] Reached target Swap. [ OK ] Reached target Sockets. [ OK ] Reached target Paths. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Apply Kernel Variables. [ 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 Journal Service. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 3.879667] device-mapper: uevent: version 1.0.3 [ 3.881127] device-mapper: ioctl: 4.46.0-ioctl (2022-02-22) initialised: dm-devel@redhat.com [ OK ] Started dracut pre-udev hook. Starting udev Kernel Device Manager... [ OK ] Started udev Kernel Device Manager. Starting dracut pre-trigger hook... [ OK ] Started dracut pre-trigger hook. Starting udev Coldplug all Devices... Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. Starting dracut initqueue hook... [ OK ] Reached target S[ 4.489176] virtio_net virtio0 ens2: renamed from eth0 ystem Initialization. [[ 4.493792] random: fast init done  OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ 4.592963] scsi host0: ata_piix [ 4.603641] scsi host1: ata_piix [ 4.605218] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc120 irq 14 [ 4.607860] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc128 irq 15 [ 9.075694] dracut-initqueue[592]: RTNETLINK answers: File exists [ 9.636529] random: crng init done [ 9.637959] random: 7 urandom warning(s) missed due to ratelimiting 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... [ 11.221269] 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 Initrd Default Target. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Timers. [ OK ] Stopped target Initrd Root Device. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Paths. [ OK ] Stopped target Slices. [ OK ] Stopped target Sockets. [ OK ] Stopped target System Initialization. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. Stopping udev Kernel Device Manager... [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped target Swap. [ 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 Kernel Socket. [ OK ] Closed udev Control Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 14.744699] printk: systemd: 25 output lines suppressed due to ratelimiting [ 15.755834] SELinux: Disabled at runtime. [ 15.955718] 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) [ 16.003753] systemd[1]: Detected virtualization kvm. [ 16.005158] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 19.117371] systemd[1]: initrd-switch-root.service: Succeeded. [ 19.144779] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 19.190589] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 19.207512] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 19.218339] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 19.241324] systemd[1]: Starting Journal Service... Starting Journal Service... [ 19.271728] systemd[1]: Mounting Huge Pages File System... Mounting Huge Pages File System... Mounting Kernel Debug File System... Activating swap /dev/disk/by-label/SWAP... [ OK ] Listening on Process Core Dump Socket. [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Listening on udev Kernel Socket. [ OK ] Created slice system-serial\x2dgetty.slice. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Created slice User and Session Slice. [ OK ] Reached target Slices. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Listening on initctl Compatibility Named Pipe. Starting Remount Root and Kernel File Systems... [ OK ] Listening on udev Control Socket. [ OK ] Stopped target Switch Root. [ 19.557947] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS [ OK ] Stopped target Initrd File Systems. Mounting POSIX Message Queue File System... [ OK ] Reached target Paths. [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Reached target rpc_pipefs.target. Starting udev Coldplug all Devices... [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 ] Reached target Local Encrypted Volumes. [ OK ] Created slice system-getty.slice. Starting Apply Kernel Variables... [ OK ] Stopped target Initrd Root File System. [ OK ] Mounted Huge Pages File System. [ OK ] Mounted Kernel Debug File System. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Journal Service. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Started Apply Kernel Variables. 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. [ 21.561996] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 23.052681] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 23.174992] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 24.067475] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 24.130293] EDAC sbridge: Ver: 1.1.2 [ 26.836799] Key type dns_resolver registered [ 27.725088] NFS: Registering the id_resolver key type [ 27.728860] Key type id_resolver registered [ 27.731172] Key type id_legacy registered [* ] A start job is running for Configur…-only root support (9s / no limit) [** ] A start job is running for Configur…-only root support (9s / no limit) [ 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 RPC Bind... Starting Update UTMP about System Boot/Shutdown... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Started irqbalance daemon. [ OK ] Started D-Bus System Message Bus. Starting Network Manager... [ OK ] Reached target sshd-keygen.target. Starting Restore /run/initramfs on shutdown... Starting Login Service... [ OK ] Started dnf makecache --timer. [ OK ] Reached target Timers. [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Network Manager. [ OK ] Reached target Network. Starting Dynamic System Tuning Daemon... Starting OpenSSH server daemon... Starting GSSAPI Proxy Daemon... Starting Network Manager Wait Online... Starting Hostname Service... [ OK ] Started Login Service. [ OK ] Started OpenSSH server daemon. [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... [ OK ] Started Permit User Sessions. [ OK ] Started Serial Getty on ttyS1. [ OK ] Started Command Scheduler. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Getty on tty1. [ OK ] Reached target Login Prompts. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting System Logging Service... Starting 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 oleg111-client login: [ 81.110036] hrtimer: interrupt took 6024709 ns [ 106.614359] libcfs: loading out-of-tree module taints kernel. [ 106.903780] Key type ._llcrypt registered [ 106.910791] Key type .llcrypt registered [ 107.626393] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [ 107.642812] alg: No test for adler32 (adler32-zlib) [ 109.420474] Lustre: Lustre: Build Version: 2.17.57_65_gc740cad [ 110.461587] LNet: Added LNI 192.168.201.11@tcp [8/256/0/180] [ 112.399979] Key type lgssc registered [ 114.379690] Lustre: Echo OBD driver; http://www.lustre.org/ [ 266.556514] Lustre: Mounted lustre-client - version 2.17.57_65_gc740cad [ 272.672928] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 290.089115] Lustre: DEBUG MARKER: oleg111-client.virtnet: executing check_logdir /tmp/testlogs/ [ 292.324115] Lustre: lustre-OST0000-osc-ffff9dbf512b1800: disconnect after 23s idle [ 295.235598] Lustre: DEBUG MARKER: oleg111-client.virtnet: executing yml_node [ 301.321549] Lustre: DEBUG MARKER: Client: 2.17.57.65 [ 304.188621] Lustre: DEBUG MARKER: MDS: 2.17.57.65 [ 307.714590] Lustre: DEBUG MARKER: OSS: 2.17.57.65 [ 309.851556] Lustre: DEBUG MARKER: -----============= acceptance-small: recovery-small ============----- Sun Aug 23 00:52:48 EDT 2026 [ 329.160643] Lustre: DEBUG MARKER: excepting tests: 136 [ 331.200824] Lustre: DEBUG MARKER: === recovery-small: start setup 00:53:10 (1787460790) === [ 337.972641] Lustre: DEBUG MARKER: oleg111-client.virtnet: executing check_config_client /mnt/lustre [ 360.353861] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 375.248842] Lustre: DEBUG MARKER: === recovery-small: finish setup 00:53:53 (1787460833) === [ 376.856225] Lustre: DEBUG MARKER: == recovery-small test 1: create, chmod, stat: drop req, drop rep ========================================================== 00:53:55 (1787460835) [ 393.695236] Lustre: 10038:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787460838/real 1787460838] req@ffff9dbf488a6d80 x1874288254661376/t0(0) o700->lustre-MDT0000-mdc-ffff9dbf512b1800@192.168.201.111@tcp:30/10 lens 264/248 e 0 to 1 dl 1787460854 ref 2 fl Rpc:XQr/200/ffffffff rc 0/-1 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 393.711653] Lustre: lustre-MDT0000-mdc-ffff9dbf512b1800: Connection to lustre-MDT0000 (at 192.168.201.111@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 393.735522] Lustre: lustre-MDT0000-mdc-ffff9dbf512b1800: Connection restored to 192.168.201.111@tcp (at 192.168.201.111@tcp) [ 411.619955] Lustre: 10059:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787460856/real 1787460856] req@ffff9dbf488a4e00 x1874288254663168/t0(0) o36->lustre-MDT0000-mdc-ffff9dbf512b1800@192.168.201.111@tcp:12/10 lens 520/576 e 0 to 1 dl 1787460872 ref 2 fl Rpc:XQr/200/ffffffff rc 0/-1 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 411.633183] Lustre: lustre-MDT0000-mdc-ffff9dbf512b1800: Connection to lustre-MDT0000 (at 192.168.201.111@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 411.692693] Lustre: lustre-MDT0000-mdc-ffff9dbf512b1800: Connection restored to 192.168.201.111@tcp (at 192.168.201.111@tcp) [ 430.559206] Lustre: 10085:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787460874/real 1787460874] req@ffff9dbf51f9d880 x1874288254664448/t0(0) o101->lustre-MDT0000-mdc-ffff9dbf512b1800@192.168.201.111@tcp:12/10 lens 576/1152 e 0 to 1 dl 1787460890 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'tchmod.0' uid:0 gid:0 projid:0 [ 430.611871] Lustre: lustre-MDT0000-mdc-ffff9dbf512b1800: Connection to lustre-MDT0000 (at 192.168.201.111@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 430.686164] Lustre: lustre-MDT0000-mdc-ffff9dbf512b1800: Connection restored to 192.168.201.111@tcp (at 192.168.201.111@tcp) [ 450.015452] Lustre: 10106:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787460894/real 1787460894] req@ffff9dbf524aad80 x1874288254666624/t0(0) o36->lustre-MDT0000-mdc-ffff9dbf512b1800@192.168.201.111@tcp:12/10 lens 488/512 e 0 to 1 dl 1787460910 ref 2 fl Rpc:XQr/200/ffffffff rc 0/-1 job:'tchmod.0' uid:0 gid:0 projid:4294967295 [ 450.043133] Lustre: lustre-MDT0000-mdc-ffff9dbf512b1800: Connection to lustre-MDT0000 (at 192.168.201.111@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 450.067256] Lustre: lustre-MDT0000-mdc-ffff9dbf512b1800: Connection restored to 192.168.201.111@tcp (at 192.168.201.111@tcp) [ 468.966853] Lustre: 10130:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787460913/real 1787460913] req@ffff9dbf49ad3800 x1874288254667904/t0(0) o34->lustre-MDT0000-mdc-ffff9dbf512b1800@192.168.201.111@tcp:12/10 lens 472/728 e 0 to 1 dl 1787460929 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'statone.0' uid:0 gid:0 projid:0 [ 469.016447] Lustre: lustre-MDT0000-mdc-ffff9dbf512b1800: Connection to lustre-MDT0000 (at 192.168.201.111@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 469.071344] Lustre: lustre-MDT0000-mdc-ffff9dbf512b1800: Connection restored to 192.168.201.111@tcp (at 192.168.201.111@tcp) [ 488.415193] Lustre: 10152:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787460932/real 1787460932] req@ffff9dbf49ad3800 x1874288254669184/t0(0) o34->lustre-MDT0000-mdc-ffff9dbf512b1800@192.168.201.111@tcp:12/10 lens 472/728 e 0 to 1 dl 1787460948 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'statone.0' uid:0 gid:0 projid:0 [ 488.449641] Lustre: lustre-MDT0000-mdc-ffff9dbf512b1800: Connection to lustre-MDT0000 (at 192.168.201.111@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 488.499572] Lustre: lustre-MDT0000-mdc-ffff9dbf512b1800: Connection restored to 192.168.201.111@tcp (at 192.168.201.111@tcp) [ 495.681632] Lustre: DEBUG MARKER: == recovery-small test 4: open: drop req, drop rep ======= 00:55:54 (1787460954) [ 513.503569] Lustre: 10757:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787460957/real 1787460957] req@ffff9dbf49ad3800 x1874288254671488/t0(0) o101->lustre-MDT0000-mdc-ffff9dbf512b1800@192.168.201.111@tcp:12/10 lens 576/1152 e 0 to 1 dl 1787460973 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'cat.0' uid:0 gid:0 projid:0 [ 513.545711] Lustre: lustre-MDT0000-mdc-ffff9dbf512b1800: Connection to lustre-MDT0000 (at 192.168.201.111@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 513.602937] Lustre: lustre-MDT0000-mdc-ffff9dbf512b1800: Connection restored to 192.168.201.111@tcp (at 192.168.201.111@tcp) [ 541.043883] Lustre: DEBUG MARKER: == recovery-small test 5: rename: drop req, drop rep ===== 00:56:39 (1787460999) [ 558.047240] Lustre: 11378:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787461002/real 1787461003] req@ffff9dbf488a4000 x1874288254678144/t0(0) o101->lustre-MDT0000-mdc-ffff9dbf512b1800@192.168.201.111@tcp:12/10 lens 576/1152 e 0 to 1 dl 1787461018 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'mv.0' uid:0 gid:0 projid:0 [ 558.087350] Lustre: 11378:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 558.097798] Lustre: lustre-MDT0000-mdc-ffff9dbf512b1800: Connection to lustre-MDT0000 (at 192.168.201.111@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 558.120964] Lustre: Skipped 1 previous similar message [ 558.201422] Lustre: lustre-MDT0000-mdc-ffff9dbf512b1800: Connection restored to 192.168.201.111@tcp (at 192.168.201.111@tcp) [ 558.211515] Lustre: Skipped 1 previous similar message [ 588.947867] Lustre: DEBUG MARKER: == recovery-small test 6: link, unlink: drop req, drop rep ========================================================== 00:57:27 (1787461047) [ 604.127856] Lustre: lustre-OST0000-osc-ffff9dbf512b1800: disconnect after 21s idle [ 604.141908] Lustre: Skipped 1 previous similar message [ 625.119241] Lustre: 12032:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787461069/real 1787461069] req@ffff9dbf51f9c700 x1874288254689280/t0(0) o36->lustre-MDT0000-mdc-ffff9dbf512b1800@192.168.201.111@tcp:12/10 lens 512/440 e 0 to 1 dl 1787461085 ref 2 fl Rpc:XQr/200/ffffffff rc 0/-1 job:'link.0' uid:0 gid:0 projid:4294967295 [ 625.170976] Lustre: 12032:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 625.180899] Lustre: lustre-MDT0000-mdc-ffff9dbf512b1800: Connection to lustre-MDT0000 (at 192.168.201.111@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 625.195435] Lustre: Skipped 2 previous similar messages [ 625.230297] Lustre: lustre-MDT0000-mdc-ffff9dbf512b1800: Connection restored to 192.168.201.111@tcp (at 192.168.201.111@tcp) [ 625.246328] Lustre: Skipped 2 previous similar messages [ 672.648743] Lustre: DEBUG MARKER: == recovery-small test 8: touch: drop rep (bug 1423) ===== 00:58:51 (1787461131) [ 698.496532] Lustre: DEBUG MARKER: == recovery-small test 9: pause bulk on OST (bug 1420) === 00:59:17 (1787461157) [ 714.972516] Lustre: DEBUG MARKER: == recovery-small test 10a: finish request on server after client eviction (bug 1521) ========================================================== 00:59:34 (1787461174) [ 715.497933] Lustre: *** cfs_fail_loc=305, val=0*** [ 732.143504] Lustre: *** cfs_fail_loc=305, val=0*** [ 735.721957] Lustre: lustre-OST0000-osc-ffff9dbf512b1800: disconnect after 25s idle [ 747.493441] Lustre: *** cfs_fail_loc=305, val=0*** [ 763.892050] Lustre: *** cfs_fail_loc=305, val=0*** [ 780.275279] Lustre: *** cfs_fail_loc=305, val=0*** [ 795.640765] Lustre: *** cfs_fail_loc=305, val=0*** [ 812.025890] Lustre: *** cfs_fail_loc=305, val=0*** [ 828.798115] LustreError: lustre-MDT0000-mdc-ffff9dbf512b1800: operation ldlm_enqueue to node 192.168.201.111@tcp failed: rc = -107 [ 828.810275] Lustre: lustre-MDT0000-mdc-ffff9dbf512b1800: Connection to lustre-MDT0000 (at 192.168.201.111@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 828.825612] Lustre: Skipped 3 previous similar messages [ 828.842589] LustreError: lustre-MDT0000-mdc-ffff9dbf512b1800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 828.870331] Lustre: lustre-MDT0000-mdc-ffff9dbf512b1800: Connection restored to 192.168.201.111@tcp (at 192.168.201.111@tcp) [ 828.889619] Lustre: Skipped 3 previous similar messages [ 838.329954] Lustre: DEBUG MARKER: == recovery-small test 10b: re-send BL AST =============== 01:01:37 (1787461297) [ 862.854960] Lustre: DEBUG MARKER: == recovery-small test 10c: re-send BL AST vs reconnect race (LU-5569) ========================================================== 01:02:01 (1787461321) [ 863.527642] Lustre: *** cfs_fail_loc=305, val=0*** [ 863.531623] Lustre: Skipped 1 previous similar message [ 872.314177] Lustre: DEBUG MARKER: == recovery-small test 10d: test failed blocking ast ===== 01:02:11 (1787461331) [ 876.396545] Lustre: Unmounted lustre-client [ 876.774961] Lustre: Mounted lustre-client - version 2.17.57_65_gc740cad [ 878.657539] LustreError: lustre-OST0000-osc-ffff9dbf4359f000: operation ost_statfs to node 192.168.201.111@tcp failed: rc = -107 [ 878.668666] LustreError: lustre-OST0000-osc-ffff9dbf4359f000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 878.678324] Lustre: 2360:0:(llite_lib.c:4342:ll_dirty_page_discard_warn()) lustre: dirty page discard: 192.168.201.111@tcp:/lustre/fid: [0x200000403:0x1:0x0]/ may get corrupted (rc -108) [ 881.524656] Lustre: Unmounted lustre-client [ 890.411306] Lustre: DEBUG MARKER: == recovery-small test 10e: re-send BL AST vs reconnect race 2 ========================================================== 01:02:28 (1787461348) [ 891.896480] Lustre: DEBUG MARKER: SKIP: recovery-small test_10e need two clients [ 894.495693] Lustre: DEBUG MARKER: == recovery-small test 11: wake up a thread waiting for completion after eviction (b=2460) ========================================================== 01:02:32 (1787461352) [ 921.203592] Lustre: DEBUG MARKER: == recovery-small test 12: recover from timed out resend in ptlrpcd (b=2494) ========================================================== 01:03:00 (1787461380) [ 921.436513] Lustre: DEBUG MARKER: multiop /mnt/lustre/f12.recovery-small OS_c [ 937.951150] Lustre: 17679:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787461382/real 1787461382] req@ffff9dbf51f9c000 x1874288254760320/t0(0) o35->lustre-MDT0000-mdc-ffff9dbf4359f000@192.168.201.111@tcp:23/10 lens 392/624 e 0 to 1 dl 1787461398 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'multiop.0' uid:0 gid:0 projid:0 [ 937.978895] Lustre: 17679:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 965.179546] Lustre: DEBUG MARKER: == recovery-small test 13: mdc_readpage restart test (bug 1138) ========================================================== 01:03:44 (1787461424) [ 991.506939] Lustre: DEBUG MARKER: == recovery-small test 14: mdc_readpage resend test (bug 1138) ========================================================== 01:04:10 (1787461450) [ 1000.856954] Lustre: DEBUG MARKER: == recovery-small test 15: failed open (-ENOMEM) ========= 01:04:20 (1787461460) [ 1008.471681] Lustre: DEBUG MARKER: == recovery-small test 16: timeout bulk put, don't evict client (2732) ========================================================== 01:04:27 (1787461467) [ 1055.626269] Lustre: DEBUG MARKER: == recovery-small test 17a: timeout bulk get, don't evict client (2732) ========================================================== 01:05:14 (1787461514) [ 1111.648448] Lustre: DEBUG MARKER: == recovery-small test 17b: timeout bulk get, dont evict client (3582) ========================================================== 01:06:10 (1787461570) [ 1113.116553] Lustre: DEBUG MARKER: SKIP: recovery-small test_17b Needs multiple clients [ 1115.060769] Lustre: DEBUG MARKER: == recovery-small test 18a: manual ost invalidate clears page cache immediately ========================================================== 01:06:13 (1787461573) [ 1116.254895] Lustre: setting import lustre-OST0001_UUID INACTIVE by administrator request [ 1116.308638] Lustre: lustre-OST0001-osc-ffff9dbf4359f000: Connection to lustre-OST0001 (at 192.168.201.111@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1116.317780] Lustre: Skipped 5 previous similar messages [ 1116.328480] LustreError: lustre-OST0001-osc-ffff9dbf4359f000: This client was evicted by lustre-OST0001; in progress operations using this service will fail. [ 1122.827504] Lustre: DEBUG MARKER: == recovery-small test 18b: eviction and reconnect clears page cache (2766) ========================================================== 01:06:21 (1787461581) [ 1128.969279] LustreError: lustre-OST0000-osc-ffff9dbf4359f000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 1129.002956] Lustre: lustre-OST0000-osc-ffff9dbf4359f000: Connection restored to 192.168.201.111@tcp (at 192.168.201.111@tcp) [ 1129.017484] Lustre: Skipped 4 previous similar messages [ 1154.948408] Lustre: DEBUG MARKER: == recovery-small test 18c: Dropped connect reply after eviction handing (14755) ========================================================== 01:06:53 (1787461613) [ 1159.430854] LustreError: lustre-OST0000-osc-ffff9dbf4359f000: operation ost_statfs to node 192.168.201.111@tcp failed: rc = -107 [ 1168.903244] Lustre: Evicted from lustre-OST0000_UUID (at 192.168.201.111@tcp) after server handle changed from 0x2e5b45f642dc5175 to 0x2e5b45f642dc52c5 [ 1168.913625] LustreError: lustre-OST0000-osc-ffff9dbf4359f000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 1179.686461] Lustre: DEBUG MARKER: == recovery-small test 19a: test expired_lock_main on mds (2867) ========================================================== 01:07:18 (1787461638) [ 1180.176955] Lustre: Mounted lustre-client - version 2.17.57_65_gc740cad [ 1180.179953] Lustre: Skipped 1 previous similar message [ 1198.560216] Lustre: 2362:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787461642/real 1787461642] req@ffff9dbf49ad1500 x1874288254818432/t0(0) o103->lustre-MDT0000-mdc-ffff9dbf4359f000@192.168.201.111@tcp:17/18 lens 328/224 e 0 to 1 dl 1787461658 ref 1 fl Rpc:XQr/200/ffffffff rc 0/-1 job:'ldlm_bl.0' uid:0 gid:0 projid:4294967295 [ 1198.616066] Lustre: 2362:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 1284.618650] LustreError: lustre-MDT0000-mdc-ffff9dbf4359f000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 1284.631309] LustreError: 23916:0:(file.c:251:ll_close_inode_openhandle()) lustre-clilmv-ffff9dbf4359f000: inode [0x200000403:0x1:0x0] mdc close failed: rc = -108 [ 1288.059610] Lustre: Unmounted lustre-client [ 1295.867434] Lustre: DEBUG MARKER: == recovery-small test 19b: test expired_lock_main on ost (2867) ========================================================== 01:09:14 (1787461754) [ 1296.422335] Lustre: Mounted lustre-client - version 2.17.57_65_gc740cad [ 1403.904450] LustreError: lustre-OST0001-osc-ffff9dbf4359f000: This client was evicted by lustre-OST0001; in progress operations using this service will fail. [ 1406.328109] Lustre: Unmounted lustre-client [ 1413.307430] Lustre: DEBUG MARKER: == recovery-small test 19c: check reconnect and lock resend do not trigger expired_lock_main ========================================================== 01:11:12 (1787461872) [ 1413.976195] Lustre: Mounted lustre-client - version 2.17.57_65_gc740cad [ 1419.135275] Lustre: Unmounted lustre-client [ 1432.532062] Lustre: DEBUG MARKER: == recovery-small test 20a: ldlm_handle_enqueue error (should return error) ========================================================== 01:11:31 (1787461891) [ 1434.294762] LustreError: lustre-OST0000-osc-ffff9dbf4359f000: operation ldlm_enqueue to node 192.168.201.111@tcp failed: rc = -12 [ 1442.318477] Lustre: DEBUG MARKER: == recovery-small test 20b: ldlm_handle_enqueue error (should return error) ========================================================== 01:11:41 (1787461901) [ 1443.850107] LustreError: lustre-OST0000-osc-ffff9dbf4359f000: operation ldlm_enqueue to node 192.168.201.111@tcp failed: rc = -12 [ 1450.585688] Lustre: DEBUG MARKER: == recovery-small test 21a: drop close request while close and open are both in flight ========================================================== 01:11:49 (1787461909) [ 1480.387423] Lustre: DEBUG MARKER: == recovery-small test 21b: drop open request while close and open are both in flight ========================================================== 01:12:19 (1787461939) [ 1627.727963] Lustre: DEBUG MARKER: == recovery-small test 21c: drop both request while close and open are both in flight ========================================================== 01:14:46 (1787462086) [ 1649.631403] Lustre: lustre-MDT0000-mdc-ffff9dbf4359f000: Connection to lustre-MDT0000 (at 192.168.201.111@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1649.655813] Lustre: Skipped 18 previous similar messages [ 1649.692075] Lustre: lustre-MDT0000-mdc-ffff9dbf4359f000: Connection restored to 192.168.201.111@tcp (at 192.168.201.111@tcp) [ 1649.709664] Lustre: Skipped 16 previous similar messages [ 1661.683356] Lustre: DEBUG MARKER: == recovery-small test 21d: drop close reply while close and open are both in flight ========================================================== 01:15:19 (1787462119) [ 1694.823469] Lustre: DEBUG MARKER: == recovery-small test 21e: drop open reply while close and open are both in flight ========================================================== 01:15:52 (1787462152) [ 1832.927256] Lustre: 29682:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787462156/real 1787462156] req@ffff9dbf49ad1880 x1874288254928128/t0(0) o36->lustre-MDT0000-mdc-ffff9dbf4359f000@192.168.201.111@tcp:12/10 lens 488/512 e 0 to 1 dl 1787462293 ref 2 fl Rpc:XQr/200/ffffffff rc 0/-1 job:'touch.0' uid:0 gid:0 projid:4294967295 [ 1832.968071] Lustre: 29682:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 15 previous similar messages [ 1834.852631] Lustre: DEBUG MARKER: == recovery-small test 21f: drop both reply while close and open are both in flight ========================================================== 01:18:13 (1787462293) [ 1863.898059] Lustre: DEBUG MARKER: == recovery-small test 21g: drop open reply and close request while close and open are both in flight ========================================================== 01:18:42 (1787462322) [ 1889.977890] Lustre: DEBUG MARKER: == recovery-small test 21h: drop open request and close reply while close and open are both in flight ========================================================== 01:19:08 (1787462348) [ 1915.597430] Lustre: DEBUG MARKER: == recovery-small test 22: drop close request and do mknod ========================================================== 01:19:34 (1787462374) [ 1940.805701] Lustre: DEBUG MARKER: == recovery-small test 23: client hang when close a file after mds crash ========================================================== 01:19:59 (1787462399) [ 1969.119483] LustreError: MGC192.168.201.111@tcp: Connection to MGS (at 192.168.201.111@tcp) was lost; in progress operations using this service will fail [ 1979.450234] Lustre: Evicted from MGS (at 192.168.201.111@tcp) after server handle changed from 0x2e5b45f642dc487d to 0x2e5b45f642dc6e01 [ 1994.587497] Lustre: DEBUG MARKER: oleg111-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1996.238992] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2004.228625] Lustre: DEBUG MARKER: == recovery-small test 24a: fsync error (should return error) ========================================================== 01:21:03 (1787462463) [ 2005.677669] LustreError: lustre-OST0000-osc-ffff9dbf4359f000: operation ost_write to node 192.168.201.111@tcp failed: rc = -107 [ 2005.689590] LustreError: lustre-OST0000-osc-ffff9dbf4359f000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 2005.694558] Lustre: 2359:0:(llite_lib.c:4342:ll_dirty_page_discard_warn()) lustre: dirty page discard: 192.168.201.111@tcp:/lustre/fid: [0x200000404:0x30:0x0]// may get corrupted (rc -5) [ 2011.364665] Lustre: DEBUG MARKER: == recovery-small test 24b: test dirty page discard due to client eviction ========================================================== 01:21:10 (1787462470) [ 2013.937348] LustreError: lustre-OST0000-osc-ffff9dbf4359f000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 2013.967802] Lustre: 2359:0:(llite_lib.c:4342:ll_dirty_page_discard_warn()) lustre: dirty page discard: 192.168.201.111@tcp:/lustre/fid: [0x200000404:0x35:0x0]// may get corrupted (rc -108) [ 2023.877822] Lustre: DEBUG MARKER: == recovery-small test 26a: evict dead exports =========== 01:21:22 (1787462482) [ 2027.844338] Lustre: DEBUG MARKER: SKIP: recovery-small test_26a msg and ost1 are at the same node [ 2031.447410] Lustre: DEBUG MARKER: == recovery-small test 26b: evict dead exports =========== 01:21:28 (1787462488) [ 2034.231901] Lustre: DEBUG MARKER: SKIP: recovery-small test_26b msg and ost1 are at the same node [ 2036.528721] Lustre: DEBUG MARKER: == recovery-small test 27: fail LOV while using OSC's ==== 01:21:34 (1787462494) [ 2040.635295] LustreError: lustre-MDT0000-mdc-ffff9dbf4359f000: operation mds_reint to node 192.168.201.111@tcp failed: rc = -19 [ 2040.640946] LustreError: Skipped 1 previous similar message [ 2059.743399] LustreError: MGC192.168.201.111@tcp: Connection to MGS (at 192.168.201.111@tcp) was lost; in progress operations using this service will fail [ 2069.935421] Lustre: Evicted from MGS (at 192.168.201.111@tcp) after server handle changed from 0x2e5b45f642dc6e01 to 0x2e5b45f642dc86a4 [ 2161.988237] LustreError: lustre-MDT0000-mdc-ffff9dbf4359f000: operation ldlm_enqueue to node 192.168.201.111@tcp failed: rc = -19 [ 2182.623316] LustreError: MGC192.168.201.111@tcp: Connection to MGS (at 192.168.201.111@tcp) was lost; in progress operations using this service will fail [ 2182.679814] Lustre: Evicted from MGS (at 192.168.201.111@tcp) after server handle changed from 0x2e5b45f642dc86a4 to 0x2e5b45f642de0e88 [ 2184.259317] Lustre: 15958:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.201.111@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 2207.735894] Lustre: DEBUG MARKER: == recovery-small test 28: handle error adding new clients (bug 6086) ========================================================== 01:24:26 (1787462666) [ 2208.464276] Lustre: *** cfs_fail_loc=305, val=0*** [ 2208.470505] Lustre: Skipped 2 previous similar messages [ 2227.499752] LustreError: lustre-OST0001-osc-ffff9dbf4359f000: operation ost_connect to node 192.168.201.111@tcp failed: rc = -75 [ 2253.280597] LustreError: MGC192.168.201.111@tcp: Connection to MGS (at 192.168.201.111@tcp) was lost; in progress operations using this service will fail [ 2253.308340] Lustre: Evicted from MGS (at 192.168.201.111@tcp) after server handle changed from 0x2e5b45f642de0e88 to 0x2e5b45f642de13dd [ 2253.316242] Lustre: MGC192.168.201.111@tcp: Connection restored to 192.168.201.111@tcp (at 192.168.201.111@tcp) [ 2253.326726] Lustre: Skipped 13 previous similar messages [ 2254.843422] Lustre: 15958:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.201.111@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 2262.502111] Lustre: lustre-MDT0000-mdc-ffff9dbf4359f000: Connection to lustre-MDT0000 (at 192.168.201.111@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 2262.520301] Lustre: Skipped 11 previous similar messages [ 2277.138800] Lustre: DEBUG MARKER: oleg111-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2279.019819] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2287.674598] Lustre: DEBUG MARKER: == recovery-small test 29a: error adding new clients doesn't cause LBUG (bug 22273) ========================================================== 01:25:46 (1787462746) [ 2303.477323] LustreError: MGC192.168.201.111@tcp: Connection to MGS (at 192.168.201.111@tcp) was lost; in progress operations using this service will fail [ 2303.499811] Lustre: Evicted from MGS (at 192.168.201.111@tcp) after server handle changed from 0x2e5b45f642de13dd to 0x2e5b45f642de19e8 [ 2303.587241] LustreError: lustre-MDT0000-mdc-ffff9dbf4359f000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 2327.571177] Lustre: DEBUG MARKER: == recovery-small test 29b: error adding new clients doesn't cause LBUG (bug 22273) ========================================================== 01:26:26 (1787462786) [ 2344.423877] LustreError: lustre-OST0000-osc-ffff9dbf4359f000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 2369.470622] Lustre: DEBUG MARKER: == recovery-small test 50: failover MDS under load ======= 01:27:07 (1787462827) [ 2384.633810] LustreError: lustre-MDT0000-mdc-ffff9dbf4359f000: operation mds_reint to node 192.168.201.111@tcp failed: rc = -19 [ 2400.735779] LustreError: MGC192.168.201.111@tcp: Connection to MGS (at 192.168.201.111@tcp) was lost; in progress operations using this service will fail [ 2410.923701] Lustre: Evicted from MGS (at 192.168.201.111@tcp) after server handle changed from 0x2e5b45f642de19e8 to 0x2e5b45f642de5f55 [ 2412.622638] Lustre: 15958:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.201.111@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 2438.994572] Lustre: DEBUG MARKER: oleg111-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2441.554192] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2527.719671] Lustre: 2362:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787462972/real 1787462972] req@ffff9dbf47c67800 x1874288257998720/t0(0) o400->MGC192.168.201.111@tcp@192.168.201.111@tcp:26/25 lens 224/224 e 0 to 1 dl 1787462988 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2527.752623] Lustre: 2362:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 15 previous similar messages [ 2527.757660] LustreError: MGC192.168.201.111@tcp: Connection to MGS (at 192.168.201.111@tcp) was lost; in progress operations using this service will fail [ 2527.797615] Lustre: Evicted from MGS (at 192.168.201.111@tcp) after server handle changed from 0x2e5b45f642de5f55 to 0x2e5b45f642dfef9e [ 2529.216898] Lustre: 15958:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.201.111@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 2555.507491] Lustre: DEBUG MARKER: oleg111-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2557.704995] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2645.343710] LustreError: MGC192.168.201.111@tcp: Connection to MGS (at 192.168.201.111@tcp) was lost; in progress operations using this service will fail [ 2655.525778] Lustre: Evicted from MGS (at 192.168.201.111@tcp) after server handle changed from 0x2e5b45f642dfef9e to 0x2e5b45f642e16a15 [ 2675.311851] Lustre: DEBUG MARKER: oleg111-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2677.425914] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2709.225621] Lustre: DEBUG MARKER: == recovery-small test 51: failover MDS during recovery == 01:32:48 (1787463168) [ 2714.198210] LustreError: lustre-MDT0000-mdc-ffff9dbf4359f000: operation ldlm_enqueue to node 192.168.201.111@tcp failed: rc = -19 [ 2714.213430] LustreError: Skipped 4 previous similar messages [ 2731.488396] LustreError: MGC192.168.201.111@tcp: Connection to MGS (at 192.168.201.111@tcp) was lost; in progress operations using this service will fail [ 2740.716642] Lustre: Evicted from MGS (at 192.168.201.111@tcp) after server handle changed from 0x2e5b45f642e16a15 to 0x2e5b45f642e22387 [ 2742.651539] Lustre: 15958:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.201.111@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 2756.387757] Lustre: DEBUG MARKER: test_51: failover in 1 sec [ 2797.542323] Lustre: DEBUG MARKER: test_51: failover in 5 sec [ 2827.586946] Lustre: 15958:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.201.111@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 2845.557560] Lustre: DEBUG MARKER: test_51: failover in 10 sec [ 2875.616932] LustreError: MGC192.168.201.111@tcp: Connection to MGS (at 192.168.201.111@tcp) was lost; in progress operations using this service will fail [ 2875.631887] LustreError: Skipped 2 previous similar messages [ 2885.821682] Lustre: Evicted from MGS (at 192.168.201.111@tcp) after server handle changed from 0x2e5b45f642e2708e to 0x2e5b45f642e2b721 [ 2885.832567] Lustre: Skipped 2 previous similar messages [ 2885.844752] Lustre: MGC192.168.201.111@tcp: Connection restored to 192.168.201.111@tcp (at 192.168.201.111@tcp) [ 2885.850546] Lustre: Skipped 16 previous similar messages [ 2898.127650] Lustre: DEBUG MARKER: test_51: failover in 20 sec [ 2922.494285] Lustre: lustre-MDT0000-mdc-ffff9dbf4359f000: Connection to lustre-MDT0000 (at 192.168.201.111@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 2922.519624] Lustre: Skipped 9 previous similar messages [ 2942.583525] Lustre: 15958:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.201.111@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 2959.835225] Lustre: DEBUG MARKER: test_51: failover in 25 sec [ 3030.660768] Lustre: DEBUG MARKER: test_51: failover in 30 sec [ 3130.018037] Lustre: DEBUG MARKER: == recovery-small test 52: failover OST under load ======= 01:39:49 (1787463589) [ 3190.985678] Lustre: DEBUG MARKER: oleg111-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 3194.105939] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 3477.289345] LustreError: lustre-OST0000-osc-ffff9dbf4359f000: operation ldlm_enqueue to node 192.168.201.111@tcp failed: rc = -107 [ 3477.301087] LustreError: Skipped 10 previous similar messages [ 3503.057294] Lustre: lustre-OST0000-osc-ffff9dbf4359f000: Connection restored to 192.168.201.111@tcp (at 192.168.201.111@tcp) [ 3503.062957] Lustre: Skipped 8 previous similar messages [ 3524.127603] Lustre: DEBUG MARKER: oleg111-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 3526.338479] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 3807.461699] Lustre: lustre-OST0000-osc-ffff9dbf4359f000: Connection to lustre-OST0000 (at 192.168.201.111@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 3807.479532] Lustre: Skipped 4 previous similar messages [ 3856.545122] Lustre: DEBUG MARKER: oleg111-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 3859.384184] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4106.268767] Lustre: DEBUG MARKER: == recovery-small test 53a: touch: drop rep ============== 01:56:04 (1787464564) [ 4123.615140] Lustre: 50614:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787464568/real 1787464568] req@ffff9dbf48ba4a80 x1874288278760960/t0(0) o101->lustre-MDT0000-mdc-ffff9dbf4359f000@192.168.201.111@tcp:12/10 lens 576/1152 e 0 to 1 dl 1787464584 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'openfile.0' uid:0 gid:0 projid:0 [ 4123.672211] Lustre: 50614:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 7 previous similar messages [ 4123.723160] Lustre: lustre-MDT0000-mdc-ffff9dbf4359f000: Connection restored to 192.168.201.111@tcp (at 192.168.201.111@tcp) [ 4123.734133] Lustre: Skipped 1 previous similar message [ 4133.403252] Lustre: DEBUG MARKER: == recovery-small test 53b: touch: drop rep ============== 01:56:31 (1787464591) [ 4160.136537] Lustre: DEBUG MARKER: == recovery-small test 53c: touch: drop rep ============== 01:56:59 (1787464619) [ 4189.766685] Lustre: DEBUG MARKER: == recovery-small test 54: back in time ================== 01:57:28 (1787464648) [ 4190.232080] Lustre: Mounted lustre-client - version 2.17.57_65_gc740cad [ 4220.704220] Lustre: 2359:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787464665/real 1787464665] req@ffff9dbf47dc8000 x1874288278778880/t0(0) o400->lustre-MDT0000-mdc-ffff9dbf4359f000@192.168.201.111@tcp:12/10 lens 224/224 e 0 to 1 dl 1787464681 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4220.729278] Lustre: 2359:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 4220.753164] LustreError: MGC192.168.201.111@tcp: Connection to MGS (at 192.168.201.111@tcp) was lost; in progress operations using this service will fail [ 4220.785313] LustreError: Skipped 3 previous similar messages [ 4231.152136] Lustre: Evicted from MGS (at 192.168.201.111@tcp) after server handle changed from 0x2e5b45f642e4a88a to 0x2e5b45f642f84fd8 [ 4231.163925] Lustre: Skipped 3 previous similar messages [ 4232.321280] Lustre: 15958:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.201.111@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 4252.838176] Lustre: DEBUG MARKER: oleg111-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4254.916451] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4257.398215] Lustre: Unmounted lustre-client [ 4264.771614] Lustre: DEBUG MARKER: == recovery-small test 55: ost_brw_read/write drops timed-out read/write request ========================================================== 01:58:43 (1787464723) [ 4373.471323] Lustre: 2361:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787464817/real 1787464817] req@ffff9dbf4697e680 x1874288278813440/t0(0) o4->lustre-OST0000-osc-ffff9dbf4359f000@192.168.201.111@tcp:6/4 lens 488/448 e 0 to 1 dl 1787464833 ref 2 fl Rpc:XQr/602/ffffffff rc -11/-1 job:'dd.0' uid:0 gid:0 projid:0 [ 4373.535801] Lustre: 2361:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 47 previous similar messages [ 4421.599773] Lustre: lustre-OST0000-osc-ffff9dbf4359f000: Connection to lustre-OST0000 (at 192.168.201.111@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 4421.620057] Lustre: Skipped 13 previous similar messages [ 4566.776613] Lustre: DEBUG MARKER: == recovery-small test 56: do not fail on getattr resend ========================================================== 02:03:45 (1787465025) [ 4619.407267] Lustre: DEBUG MARKER: == recovery-small test 57: read procfs entries causes kernel crash ========================================================== 02:04:38 (1787465078) [ 4622.901760] Lustre: Unmounted lustre-client [ 4650.284891] Lustre: Mounted lustre-client - version 2.17.57_65_gc740cad [ 4657.999653] Lustre: DEBUG MARKER: == recovery-small test 58: Eviction in the middle of open RPC reply processing ========================================================== 02:05:16 (1787465116) [ 4658.633493] LustreError: 56556:0:(mdc_locks.c:1337:mdc_finish_intent_lock()) cfs_fail_timeout id 801 sleeping for 20000ms [ 4659.716640] LustreError: 56556:0:(mdc_locks.c:1337:mdc_finish_intent_lock()) cfs_fail_timeout interrupted [ 4660.006984] Lustre: *** cfs_fail_loc=305, val=0*** [ 4685.222749] Lustre: DEBUG MARKER: == recovery-small test 59: Read cancel race on client eviction ========================================================== 02:05:43 (1787465143) [ 4685.735570] Lustre: Mounted lustre-client - version 2.17.57_65_gc740cad [ 4689.324601] Lustre: setting import lustre-MDT0000_UUID INACTIVE by administrator request [ 4699.713529] Lustre: Unmounted lustre-client [ 4709.823721] Lustre: DEBUG MARKER: == recovery-small test 60: Add Changelog entries during MDS failover ========================================================== 02:06:08 (1787465168) [ 4807.210115] LustreError: lustre-MDT0000-mdc-ffff9dbf48adc800: operation mds_reint to node 192.168.201.111@tcp failed: rc = -19 [ 4807.223431] LustreError: Skipped 1 previous similar message [ 4825.888224] Lustre: 2361:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787465270/real 1787465270] req@ffff9dbf4aa74700 x1874288281479424/t0(0) o400->MGC192.168.201.111@tcp@192.168.201.111@tcp:26/25 lens 224/224 e 0 to 1 dl 1787465286 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4825.909648] Lustre: 2361:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 87 previous similar messages [ 4825.926508] LustreError: MGC192.168.201.111@tcp: Connection to MGS (at 192.168.201.111@tcp) was lost; in progress operations using this service will fail [ 4836.151739] Lustre: Evicted from MGS (at 192.168.201.111@tcp) after server handle changed from 0x2e5b45f642f86962 to 0x2e5b45f642fb1b91 [ 4836.172966] Lustre: MGC192.168.201.111@tcp: Connection restored to 192.168.201.111@tcp (at 192.168.201.111@tcp) [ 4836.190113] Lustre: Skipped 24 previous similar messages [ 4838.133565] Lustre: 55954:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.201.111@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 5017.747135] Lustre: DEBUG MARKER: == recovery-small test 61: Verify to not reuse orphan objects - bug 17025 ========================================================== 02:11:16 (1787465476) [ 5025.183530] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5029.874386] Lustre: lustre-MDT0000-mdc-ffff9dbf48adc800: Connection to lustre-MDT0000 (at 192.168.201.111@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 5029.906783] Lustre: Skipped 11 previous similar messages [ 5045.237408] LustreError: MGC192.168.201.111@tcp: Connection to MGS (at 192.168.201.111@tcp) was lost; in progress operations using this service will fail [ 5045.288208] Lustre: Evicted from MGS (at 192.168.201.111@tcp) after server handle changed from 0x2e5b45f642fb1b91 to 0x2e5b45f642ffe9d8 [ 5050.625030] LustreError: lustre-MDT0000-mdc-ffff9dbf48adc800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5069.384932] Lustre: DEBUG MARKER: == recovery-small test 65: lock enqueue for destroyed export ========================================================== 02:12:08 (1787465528) [ 5070.524257] Lustre: Mounted lustre-client - version 2.17.57_65_gc740cad [ 5078.923206] LustreError: lustre-OST0000-osc-ffff9dbf48adc800: operation ldlm_enqueue to node 192.168.201.111@tcp failed: rc = -107 [ 5078.956061] LustreError: lustre-OST0000-osc-ffff9dbf48adc800: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 5092.748364] Lustre: Unmounted lustre-client [ 5102.498768] Lustre: DEBUG MARKER: == recovery-small test 66: lock enqueue re-send vs client eviction ========================================================== 02:12:40 (1787465560) [ 5110.262843] LustreError: lustre-MDT0000-mdc-ffff9dbf48adc800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5110.279382] LustreError: 60984:0:(file.c:6166:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -5 [ 5121.818216] Lustre: DEBUG MARKER: == recovery-small test 67: connect vs import invalidate race ========================================================== 02:13:00 (1787465580) [ 5122.102753] LustreError: 61662:0:(recover.c:329:ptlrpc_recover_import()) cfs_race id 531 sleeping [ 5127.135359] LustreError: 61662:0:(recover.c:329:ptlrpc_recover_import()) cfs_fail_race id 531 awake: rc=0 [ 5127.137680] LustreError: 61662:0:(import.c:711:ptlrpc_connect_import_locked()) already connected [ 5127.951808] LustreError: lustre-MDT0000-mdc-ffff9dbf48adc800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5127.975477] LustreError: 61684:0:(import.c:293:ptlrpc_invalidate_import()) cfs_fail_race id 531 waking [ 5128.075257] LustreError: 61690:0:(file.c:6166:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 5129.156621] LustreError: 61697:0:(file.c:6166:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 5129.173415] LustreError: 61697:0:(file.c:6166:ll_inode_revalidate_fini()) Skipped 5 previous similar messages [ 5131.791045] LustreError: 61719:0:(file.c:6166:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 5131.830279] LustreError: 61719:0:(file.c:6166:ll_inode_revalidate_fini()) Skipped 13 previous similar messages [ 5135.795568] LustreError: 61762:0:(file.c:6166:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 5135.816613] LustreError: 61762:0:(file.c:6166:ll_inode_revalidate_fini()) Skipped 26 previous similar messages [ 5149.242489] Lustre: DEBUG MARKER: == recovery-small test 100: IR: Make sure normal recovery still works w/o IR ========================================================== 02:13:27 (1787465607) [ 5194.757960] Lustre: DEBUG MARKER: oleg111-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 5197.062067] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 5210.793811] Lustre: DEBUG MARKER: == recovery-small test 101a: IR: Make sure IR works w/o normal recovery ========================================================== 02:14:29 (1787465669) [ 5255.438623] Lustre: DEBUG MARKER: oleg111-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 5257.252622] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 5270.970450] Lustre: DEBUG MARKER: == recovery-small test 101b: IR: Make sure IR works w/o normal recovery and proceed EAGAIN ========================================================== 02:15:29 (1787465729) [ 5343.634482] Lustre: DEBUG MARKER: oleg111-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 5345.211963] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 5355.594883] Lustre: DEBUG MARKER: == recovery-small test 102: IR: New client gets updated nidtbl after MGS restart ========================================================== 02:16:53 (1787465813) [ 5402.245051] Lustre: DEBUG MARKER: oleg111-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 5404.346344] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 5413.293676] Lustre: Unmounted lustre-client [ 5478.781570] Lustre: DEBUG MARKER: oleg111-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 5481.338807] Lustre: Mounted lustre-client - version 2.17.57_65_gc740cad [ 5488.773934] Lustre: DEBUG MARKER: == recovery-small test 103: IR: MDS can start w/o MGS and get updated nidtbl later ========================================================== 02:19:07 (1787465947) [ 5492.134692] Lustre: DEBUG MARKER: SKIP: recovery-small test_103 needs separate mgs and mds [ 5494.701943] Lustre: DEBUG MARKER: == recovery-small test 104: IR: ost can disable IR voluntarily ========================================================== 02:19:12 (1787465952) [ 5533.341538] Lustre: DEBUG MARKER: == recovery-small test 105: IR: NON IR clients support === 02:19:52 (1787465992) [ 5534.893960] Lustre: DEBUG MARKER: SKIP: recovery-small test_105 Needs multiple clients [ 5537.320780] Lustre: DEBUG MARKER: == recovery-small test 106: lightweight connection support ========================================================== 02:19:56 (1787465996) [ 5539.362264] Lustre: *** cfs_fail_loc=805, val=0*** [ 5539.422716] Lustre: Mounted lustre-client - version 2.17.57_65_gc740cad [ 5546.818349] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 5571.039956] Lustre: 2361:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787466015/real 1787466015] req@ffff9dbf51de3480 x1874288283540864/t0(0) o400->lustre-MDT0000-mdc-ffff9dbf512b1800@192.168.201.111@tcp:12/10 lens 224/224 e 0 to 1 dl 1787466031 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5571.074943] Lustre: 2361:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 5571.091809] LustreError: MGC192.168.201.111@tcp: Connection to MGS (at 192.168.201.111@tcp) was lost; in progress operations using this service will fail [ 5581.285894] Lustre: Evicted from MGS (at 192.168.201.111@tcp) after server handle changed from 0x2e5b45f642fff3fd to 0x2e5b45f642fff792 [ 5581.301842] Lustre: MGC192.168.201.111@tcp: Connection restored to 192.168.201.111@tcp (at 192.168.201.111@tcp) [ 5581.328515] Lustre: Skipped 11 previous similar messages [ 5592.187390] Lustre: Unmounted lustre-client [ 5600.682275] Lustre: DEBUG MARKER: == recovery-small test 107: drop reint reply, then restart MDT ========================================================== 02:20:59 (1787466059) [ 5634.815503] Lustre: 68335:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.201.111@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 5642.832492] LustreError: 2358:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9dbf47d2c000 x1874288283553024/t94489280516(94489280516) o101->lustre-MDT0000-mdc-ffff9dbf512b1800@192.168.201.111@tcp:12/10 lens 648/608 e 0 to 0 dl 1787466119 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'multiop.0' uid:0 gid:0 projid:0 [ 5659.969050] Lustre: DEBUG MARKER: oleg111-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5662.191074] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5673.319546] Lustre: DEBUG MARKER: == recovery-small test 108: client eviction don't crash == 02:22:12 (1787466132) [ 5674.980247] LustreError: lustre-OST0000-osc-ffff9dbf512b1800: operation ost_write to node 192.168.201.111@tcp failed: rc = -107 [ 5674.987249] LustreError: Skipped 2 previous similar messages [ 5675.003302] Lustre: lustre-OST0000-osc-ffff9dbf512b1800: Connection to lustre-OST0000 (at 192.168.201.111@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 5675.032667] Lustre: Skipped 12 previous similar messages [ 5675.055934] LustreError: lustre-OST0000-osc-ffff9dbf512b1800: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 5675.074408] Lustre: 2361:0:(llite_lib.c:4342:ll_dirty_page_discard_warn()) lustre: dirty page discard: 192.168.201.111@tcp:/lustre/fid: [0x20000a042:0x6:0x0]// may get corrupted (rc -5) [ 5675.111266] LustreError: 72878:0:(ldlm_resource.c:1207:ldlm_resource_complain()) lustre-OST0000-osc-ffff9dbf512b1800: namespace resource [0x240000400:0x3b02:0x0].0x0 (ffff9dbf4a019100) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 5686.202789] Lustre: DEBUG MARKER: == recovery-small test 110a: create remote directory: drop client req ========================================================== 02:22:24 (1787466144) [ 5689.367659] Lustre: DEBUG MARKER: SKIP: recovery-small test_110a needs >= 2 MDTs [ 5692.615717] Lustre: DEBUG MARKER: == recovery-small test 110b: create remote directory: drop Master rep ========================================================== 02:22:30 (1787466150) [ 5695.039351] Lustre: DEBUG MARKER: SKIP: recovery-small test_110b needs >= 2 MDTs [ 5697.492383] Lustre: DEBUG MARKER: == recovery-small test 110c: create remote directory: drop update rep on slave MDT ========================================================== 02:22:35 (1787466155) [ 5699.681037] Lustre: DEBUG MARKER: SKIP: recovery-small test_110c needs >= 2 MDTs [ 5702.370358] Lustre: DEBUG MARKER: == recovery-small test 110d: remove remote directory: drop client req ========================================================== 02:22:40 (1787466160) [ 5704.746030] Lustre: DEBUG MARKER: SKIP: recovery-small test_110d needs >= 2 MDTs [ 5708.085320] Lustre: DEBUG MARKER: == recovery-small test 110e: remove remote directory: drop master rep ========================================================== 02:22:45 (1787466165) [ 5709.607992] Lustre: DEBUG MARKER: SKIP: recovery-small test_110e needs >= 2 MDTs [ 5712.145095] Lustre: DEBUG MARKER: == recovery-small test 110f: remove remote directory: drop slave rep ========================================================== 02:22:50 (1787466170) [ 5714.272196] Lustre: DEBUG MARKER: SKIP: recovery-small test_110f needs >= 2 MDTs [ 5716.908845] Lustre: DEBUG MARKER: == recovery-small test 110g: drop reply during migration ========================================================== 02:22:55 (1787466175) [ 5719.334944] Lustre: DEBUG MARKER: SKIP: recovery-small test_110g needs >= 2 MDTs [ 5722.092575] Lustre: DEBUG MARKER: == recovery-small test 110h: drop update reply during cross-MDT file rename ========================================================== 02:23:00 (1787466180) [ 5723.137659] Lustre: DEBUG MARKER: SKIP: recovery-small test_110h needs >= 2 MDTs [ 5725.884239] Lustre: DEBUG MARKER: == recovery-small test 110i: drop update reply during cross-MDT dir rename ========================================================== 02:23:04 (1787466184) [ 5728.011494] Lustre: DEBUG MARKER: SKIP: recovery-small test_110i needs >= 2 MDTs [ 5730.921539] Lustre: DEBUG MARKER: == recovery-small test 110j: drop update reply during cross-MDT ln ========================================================== 02:23:08 (1787466188) [ 5733.080804] Lustre: DEBUG MARKER: SKIP: recovery-small test_110j needs >= 2 MDTs [ 5735.631496] Lustre: DEBUG MARKER: == recovery-small test 110k: FID_QUERY failed during recovery ========================================================== 02:23:13 (1787466193) [ 5737.838122] Lustre: DEBUG MARKER: SKIP: recovery-small test_110k needs >= 2 MDTS [ 5740.956624] Lustre: DEBUG MARKER: == recovery-small test 110m: update resent vs original RPC race ========================================================== 02:23:18 (1787466198) [ 5744.173259] Lustre: DEBUG MARKER: SKIP: recovery-small test_110m needs at least 2 MDTs [ 5746.879544] Lustre: DEBUG MARKER: == recovery-small test 111: mdd setup fail should not cause umount oops ========================================================== 02:23:25 (1787466205) [ 5789.766067] Lustre: DEBUG MARKER: == recovery-small test 112a: bulk resend while orignal request is in progress ========================================================== 02:24:07 (1787466247) [ 5822.289964] Lustre: DEBUG MARKER: == recovery-small test 115a: read: late REQ MDunlink and no bulk ========================================================== 02:24:40 (1787466280) [ 5823.333915] Lustre: *** cfs_fail_loc=51b, val=3*** [ 5836.395576] Lustre: DEBUG MARKER: == recovery-small test 115b: write: late REQ MDunlink and no bulk ========================================================== 02:24:55 (1787466295) [ 5836.937521] Lustre: *** cfs_fail_loc=51b, val=4*** [ 5851.069406] Lustre: DEBUG MARKER: == recovery-small test 115c: read: late Reply MDunlink and no bulk ========================================================== 02:25:09 (1787466309) [ 5851.821337] Lustre: *** cfs_fail_loc=50f, val=3*** [ 5862.765350] Lustre: DEBUG MARKER: == recovery-small test 115d: write: late Reply MDunlink and no bulk ========================================================== 02:25:21 (1787466321) [ 5863.001145] Lustre: *** cfs_fail_loc=50f, val=4*** [ 5873.427979] Lustre: DEBUG MARKER: == recovery-small test 115e: read: late Bulk MDunlink and no reply ========================================================== 02:25:31 (1787466331) [ 5873.983965] Lustre: *** cfs_fail_loc=510, val=3*** [ 5885.344555] Lustre: DEBUG MARKER: == recovery-small test 115f: read: late REQ MDunlink and no reply ========================================================== 02:25:43 (1787466343) [ 5885.820614] Lustre: *** cfs_fail_loc=51b, val=3*** [ 5899.495809] Lustre: DEBUG MARKER: == recovery-small test 115g: read: late REQ MDunlink and Reply MDunlink ========================================================== 02:25:57 (1787466357) [ 5900.080329] Lustre: *** cfs_fail_loc=51c, val=3*** [ 5969.732551] Lustre: DEBUG MARKER: == recovery-small test 120: flock race: completion vs. evict ========================================================== 02:27:08 (1787466428) [ 5970.186805] LustreError: 83095:0:(ldlm_flock.c:803:ldlm_flock_completion_ast()) cfs_fail_timeout id 320 sleeping for 4000ms [ 5974.263898] LustreError: 83095:0:(ldlm_flock.c:803:ldlm_flock_completion_ast()) cfs_fail_timeout id 320 awake [ 5974.565742] LustreError: lustre-MDT0000-mdc-ffff9dbf512b1800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5977.056242] LustreError: 83126:0:(ldlm_flock.c:803:ldlm_flock_completion_ast()) cfs_fail_timeout id 320 sleeping for 4000ms [ 5980.278188] LustreError: lustre-MDT0000-mdc-ffff9dbf512b1800: operation ldlm_enqueue to node 192.168.201.111@tcp failed: rc = -107 [ 5980.299304] LustreError: Skipped 1 previous similar message [ 5980.337792] LustreError: lustre-MDT0000-mdc-ffff9dbf512b1800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5980.353791] LustreError: 83140:0:(ldlm_resource.c:1207:ldlm_resource_complain()) lustre-MDT0000-mdc-ffff9dbf512b1800: namespace resource [0x20000a042:0x11:0x0].0xc (ffff9dbf4a019000) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 5981.063472] LustreError: 83126:0:(ldlm_flock.c:803:ldlm_flock_completion_ast()) cfs_fail_timeout id 320 awake [ 5988.275703] LustreError: lustre-MDT0000-mdc-ffff9dbf512b1800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5988.842265] LustreError: 83182:0:(ldlm_flock.c:808:ldlm_flock_completion_ast()) cfs_fail_timeout id 321 sleeping for 4000ms [ 5992.168899] LustreError: lustre-MDT0000-mdc-ffff9dbf512b1800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 5992.285278] LustreError: 83202:0:(file.c:6166:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 5992.316691] LustreError: 83202:0:(file.c:6166:ll_inode_revalidate_fini()) Skipped 14 previous similar messages [ 5992.935139] LustreError: 83182:0:(ldlm_flock.c:808:ldlm_flock_completion_ast()) cfs_fail_timeout id 321 awake [ 5992.947397] LustreError: 83182:0:(file.c:251:ll_close_inode_openhandle()) lustre-clilmv-ffff9dbf512b1800: inode [0x20000a042:0x11:0x0] mdc close failed: rc = -108 [ 5993.479237] LustreError: 83208:0:(file.c:6166:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 5993.483794] LustreError: 83208:0:(file.c:6166:ll_inode_revalidate_fini()) Skipped 5 previous similar messages [ 5995.799363] LustreError: 83230:0:(file.c:6166:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 5995.818620] LustreError: 83230:0:(file.c:6166:ll_inode_revalidate_fini()) Skipped 13 previous similar messages [ 5999.756671] LustreError: 83257:0:(ldlm_flock.c:808:ldlm_flock_completion_ast()) cfs_fail_timeout id 321 sleeping for 4000ms [ 6002.991220] LustreError: lustre-MDT0000-mdc-ffff9dbf512b1800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 6003.013793] LustreError: 83272:0:(ldlm_resource.c:1207:ldlm_resource_complain()) lustre-MDT0000-mdc-ffff9dbf512b1800: namespace resource [0x20000a042:0x11:0x0].0xc (ffff9dbf4aa8c200) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 6003.064499] LustreError: 83272:0:(ldlm_resource.c:1207:ldlm_resource_complain()) Skipped 1 previous similar message [ 6003.839406] LustreError: 83257:0:(ldlm_flock.c:808:ldlm_flock_completion_ast()) cfs_fail_timeout id 321 awake [ 6011.434541] LustreError: lustre-MDT0000-mdc-ffff9dbf512b1800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 6012.155432] LustreError: 83313:0:(ldlm_flock.c:857:ldlm_flock_completion_ast()) cfs_fail_timeout id 322 sleeping for 4000ms [ 6015.158655] LustreError: lustre-MDT0000-mdc-ffff9dbf512b1800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 6015.188758] LustreError: 83328:0:(ldlm_resource.c:1207:ldlm_resource_complain()) lustre-MDT0000-mdc-ffff9dbf512b1800: namespace resource [0x20000a042:0x11:0x0].0xc (ffff9dbf4aa8c800) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 6015.238658] LustreError: 83328:0:(ldlm_resource.c:1207:ldlm_resource_complain()) Skipped 1 previous similar message [ 6016.223418] LustreError: 83313:0:(ldlm_flock.c:857:ldlm_flock_completion_ast()) cfs_fail_timeout id 322 awake [ 6019.458765] LustreError: lustre-MDT0000-mdc-ffff9dbf512b1800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 6019.515625] LustreError: 83361:0:(file.c:6166:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 6019.523443] LustreError: 83361:0:(file.c:6166:ll_inode_revalidate_fini()) Skipped 6 previous similar messages [ 6020.471758] LustreError: 83342:0:(file.c:251:ll_close_inode_openhandle()) lustre-clilmv-ffff9dbf512b1800: inode [0x20000a042:0x11:0x0] mdc close failed: rc = -108 [ 6029.013408] LustreError: 83413:0:(ldlm_flock.c:803:ldlm_flock_completion_ast()) cfs_fail_timeout id 320 sleeping for 4000ms [ 6029.018692] LustreError: 83413:0:(ldlm_flock.c:803:ldlm_flock_completion_ast()) Skipped 1 previous similar message [ 6033.087183] LustreError: 83413:0:(ldlm_flock.c:803:ldlm_flock_completion_ast()) cfs_fail_timeout id 320 awake [ 6033.103994] LustreError: 83413:0:(ldlm_flock.c:803:ldlm_flock_completion_ast()) Skipped 1 previous similar message [ 6033.591414] LustreError: lustre-MDT0000-mdc-ffff9dbf512b1800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 6041.665197] Lustre: DEBUG MARKER: == recovery-small test 113: ldlm enqueue dropped reply should not cause deadlocks ========================================================== 02:28:20 (1787466500) [ 6062.109707] LustreError: 68333:0:(ldlm_lockd.c:2890:ldlm_bl_thread_blwi()) cfs_fail_timeout id 31f sleeping for 4000ms [ 6066.175258] LustreError: 68333:0:(ldlm_lockd.c:2890:ldlm_bl_thread_blwi()) cfs_fail_timeout id 31f awake [ 6073.714317] Lustre: DEBUG MARKER: == recovery-small test 130a: enqueue resend on not existing file ========================================================== 02:28:52 (1787466532) [ 6127.414210] Lustre: DEBUG MARKER: == recovery-small test 130b: enqueue resend on a stale inode ========================================================== 02:29:45 (1787466585) [ 6185.951341] Lustre: 85549:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787466590/real 1787466590] req@ffff9dbf4aa4b100 x1874288283677440/t0(0) o101->lustre-MDT0000-mdc-ffff9dbf512b1800@192.168.201.111@tcp:12/10 lens 576/1152 e 0 to 1 dl 1787466646 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'stat.0' uid:0 gid:0 projid:0 [ 6185.971896] Lustre: 85549:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 23 previous similar messages [ 6185.990232] Lustre: lustre-MDT0000-mdc-ffff9dbf512b1800: Connection restored to 192.168.201.111@tcp (at 192.168.201.111@tcp) [ 6185.996334] Lustre: Skipped 16 previous similar messages [ 6196.756629] Lustre: DEBUG MARKER: == recovery-small test 130c: layout intent resend on a stale inode ========================================================== 02:30:55 (1787466655) [ 6237.225263] Lustre: DEBUG MARKER: == recovery-small test 132: long punch =================== 02:31:35 (1787466695) [ 6237.844851] Lustre: Mounted lustre-client - version 2.17.57_65_gc740cad [ 6362.669123] Lustre: Unmounted lustre-client [ 6371.463918] Lustre: DEBUG MARKER: == recovery-small test 131: IO vs evict results to IO under staled lock ========================================================== 02:33:50 (1787466830) [ 6372.204600] LustreError: 87699:0:(osc_request.c:2990:osc_build_rpc()) cfs_fail_timeout id 414 sleeping for 10000ms [ 6375.463222] Lustre: lustre-OST0000-osc-ffff9dbf512b1800: Connection to lustre-OST0000 (at 192.168.201.111@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 6375.485919] Lustre: Skipped 14 previous similar messages [ 6375.533465] LustreError: lustre-OST0000-osc-ffff9dbf512b1800: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 6375.566666] LustreError: 87786:0:(ldlm_resource.c:1207:ldlm_resource_complain()) lustre-OST0000-osc-ffff9dbf512b1800: namespace resource [0x240000400:0x3b2d:0x0].0x0 (ffff9dbf4688fc00) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 6375.593299] LustreError: 87786:0:(ldlm_resource.c:1207:ldlm_resource_complain()) Skipped 1 previous similar message [ 6375.927229] LustreError: 87699:0:(osc_request.c:2990:osc_build_rpc()) cfs_fail_timeout interrupted [ 6375.935788] Lustre: 2362:0:(llite_lib.c:4342:ll_dirty_page_discard_warn()) lustre: dirty page discard: 192.168.201.111@tcp:/lustre/fid: [0x20000bf89:0x9:0x0]// may get corrupted (rc -108) [ 6387.608729] Lustre: DEBUG MARKER: == recovery-small test 133: don't fail on flock resend === 02:34:05 (1787466845) [ 6456.751397] Lustre: DEBUG MARKER: == recovery-small test 134: race between failover and search for reply data free slot ========================================================== 02:35:14 (1787466914) [ 6459.476517] Lustre: DEBUG MARKER: SKIP: recovery-small test_134 Need 2+ clients, have 1 [ 6462.663719] Lustre: DEBUG MARKER: == recovery-small test 135: DOM: open/create resend to return size ========================================================== 02:35:20 (1787466920) [ 6531.531755] Lustre: DEBUG MARKER: SKIP: recovery-small test_136 skipping excluded test 136 [ 6534.262209] Lustre: DEBUG MARKER: == recovery-small test 137: late resend must be skipped if already applied ========================================================== 02:36:32 (1787466992) [ 6595.152489] Lustre: DEBUG MARKER: == recovery-small test 138: Umount MDT during recovery === 02:37:34 (1787467054) [ 6599.322502] Lustre: DEBUG MARKER: SKIP: recovery-small test_138 needs >= 2 MDTs [ 6601.857229] Lustre: DEBUG MARKER: == recovery-small test 139: corrupted catid won't cause crash ========================================================== 02:37:40 (1787467060) [ 6603.583320] Lustre: DEBUG MARKER: SKIP: recovery-small test_139 needs >= 2 MDTs [ 6605.633652] Lustre: DEBUG MARKER: == recovery-small test 140a: local mount is flagged properly ========================================================== 02:37:44 (1787467064) [ 6650.316441] Lustre: DEBUG MARKER: == recovery-small test 140b: local mount is excluded from recovery ========================================================== 02:38:28 (1787467108) [ 6663.436502] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 6690.785097] LustreError: MGC192.168.201.111@tcp: Connection to MGS (at 192.168.201.111@tcp) was lost; in progress operations using this service will fail [ 6690.816628] LustreError: Skipped 2 previous similar messages [ 6701.051048] Lustre: Evicted from MGS (at 192.168.201.111@tcp) after server handle changed from 0x2e5b45f64300026d to 0x2e5b45f643001adf [ 6701.075776] Lustre: Skipped 2 previous similar messages [ 6722.711657] Lustre: DEBUG MARKER: oleg111-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6724.794483] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6738.458143] Lustre: DEBUG MARKER: == recovery-small test 141: do not lose locks on MGS restart ========================================================== 02:39:57 (1787467197) [ 6741.066918] Lustre: DEBUG MARKER: SKIP: recovery-small test_141 cannot run in local mode or from build tree [ 6742.990896] Lustre: DEBUG MARKER: == recovery-small test 142: orphan name stub can be cleaned up in startup ========================================================== 02:40:01 (1787467201) [ 6762.497859] LustreError: MGC192.168.201.111@tcp: Connection to MGS (at 192.168.201.111@tcp) was lost; in progress operations using this service will fail [ 6762.543844] Lustre: Evicted from MGS (at 192.168.201.111@tcp) after server handle changed from 0x2e5b45f643001adf to 0x2e5b45f643001f00 [ 6777.125288] Lustre: DEBUG MARKER: == recovery-small test 143: orphan cleanup thread shouldn't be blocked even delete failed ========================================================== 02:40:35 (1787467235) [ 6799.327703] Lustre: 2359:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787467243/real 1787467243] req@ffff9dbf47d2f100 x1874288283776128/t0(0) o400->MGC192.168.201.111@tcp@192.168.201.111@tcp:26/25 lens 224/224 e 0 to 1 dl 1787467259 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6799.357155] Lustre: 2359:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 9 previous similar messages [ 6809.594573] Lustre: MGC192.168.201.111@tcp: Connection restored to 192.168.201.111@tcp (at 192.168.201.111@tcp) [ 6809.624466] Lustre: Skipped 8 previous similar messages [ 6828.634455] Lustre: DEBUG MARKER: == recovery-small test 144a: MDT failover should stop precreation threads ========================================================== 02:41:27 (1787467287) [ 6836.852844] LustreError: lustre-OST0000-osc-ffff9dbf512b1800: operation ost_setattr to node 192.168.201.111@tcp failed: rc = -19 [ 6836.877487] LustreError: Skipped 19 previous similar messages [ 6903.528460] Lustre: DEBUG MARKER: oleg111-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 6909.215071] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 6978.538837] Lustre: lustre-MDT0000-mdc-ffff9dbf512b1800: Connection to lustre-MDT0000 (at 192.168.201.111@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 6978.576097] Lustre: Skipped 7 previous similar messages [ 7000.036069] LustreError: MGC192.168.201.111@tcp: Connection to MGS (at 192.168.201.111@tcp) was lost; in progress operations using this service will fail [ 7000.059321] LustreError: Skipped 1 previous similar message [ 7010.287542] Lustre: Evicted from MGS (at 192.168.201.111@tcp) after server handle changed from 0x2e5b45f643002209 to 0x2e5b45f6430030d4 [ 7010.297803] Lustre: Skipped 1 previous similar message [ 7026.910435] Lustre: DEBUG MARKER: oleg111-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 7029.782173] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7063.235766] Lustre: 68335:0:(mgc_request.c:1900:mgc_process_log()) MGC192.168.201.111@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 7081.570598] Lustre: DEBUG MARKER: oleg111-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 7083.397535] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7245.557482] Lustre: DEBUG MARKER: == recovery-small test 144b: orphan cleanup shouldn't be blocked for no objects+failover situation ========================================================== 02:48:24 (1787467704) [ 7332.028769] Lustre: DEBUG MARKER: oleg111-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 7337.134834] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 7604.374296] Lustre: DEBUG MARKER: == recovery-small test 144c: reconnection during orphan cleanup shouldn't lose LAST_ID synchronization ========================================================== 02:54:23 (1787468063) [ 7759.866508] Lustre: lustre-MDT0000-mdc-ffff9dbf512b1800: Connection to lustre-MDT0000 (at 192.168.201.111@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 7759.880410] Lustre: Skipped 2 previous similar messages [ 7775.210088] LustreError: MGC192.168.201.111@tcp: Connection to MGS (at 192.168.201.111@tcp) was lost; in progress operations using this service will fail [ 7775.215639] LustreError: Skipped 1 previous similar message [ 7775.239932] Lustre: Evicted from MGS (at 192.168.201.111@tcp) after server handle changed from 0x2e5b45f643003366 to 0x2e5b45f6430fd60f [ 7775.253493] Lustre: Skipped 1 previous similar message [ 7775.264766] Lustre: MGC192.168.201.111@tcp: Connection restored to 192.168.201.111@tcp (at 192.168.201.111@tcp) [ 7775.279705] Lustre: Skipped 5 previous similar messages [ 7812.536562] Lustre: DEBUG MARKER: == recovery-small test 145: connect mdtlovs and process update logs after recovery expire ========================================================== 02:57:51 (1787468271) [ 7813.845824] Lustre: DEBUG MARKER: SKIP: recovery-small test_145 needs >= 3 MDTs [ 7816.396184] Lustre: DEBUG MARKER: == recovery-small test 146: test eviction is counted properly ========================================================== 02:57:54 (1787468274) [ 7818.511205] LustreError: lustre-MDT0000-mdc-ffff9dbf512b1800: operation ldlm_enqueue to node 192.168.201.111@tcp failed: rc = -107 [ 7818.516894] LustreError: Skipped 172 previous similar messages [ 7818.539395] LustreError: lustre-MDT0000-mdc-ffff9dbf512b1800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 7828.790139] Lustre: DEBUG MARKER: == recovery-small test 147: Check client reconnect ======= 02:58:07 (1787468287) [ 7997.416627] Lustre: Evicted from lustre-OST0000_UUID (at 192.168.201.111@tcp) after server handle changed from 0x2e5b45f6430fdc44 to 0x2e5b45f6430fdd4e [ 7997.440837] LustreError: lustre-OST0000-osc-ffff9dbf512b1800: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 7999.890517] Lustre: DEBUG MARKER: == recovery-small test 148: data corruption through resend ========================================================== 03:00:58 (1787468458) [ 8026.079225] Lustre: 2360:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787468466/real 1787468466] req@ffff9dbf475c9880 x1874288301457408/t0(0) o4->lustre-OST0000-osc-ffff9dbf512b1800@192.168.201.111@tcp:6/4 lens 4584/448 e 0 to 1 dl 1787468486 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'dd.0' uid:0 gid:0 projid:0 [ 8026.131651] Lustre: 2360:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 10 previous similar messages [ 8046.273217] Lustre: DEBUG MARKER: == recovery-small test 149: skip orphan removal at umount ========================================================== 03:01:44 (1787468504) [ 8048.191091] Lustre: DEBUG MARKER: SKIP: recovery-small test_149 needs >= 2 MDTs [ 8049.978835] Lustre: DEBUG MARKER: == recovery-small test 150: statfs when MDT0 offline with lazystatfs option ========================================================== 03:01:48 (1787468508) [ 8051.702482] Lustre: DEBUG MARKER: SKIP: recovery-small test_150 needs >= 2 MDTs [ 8054.207855] Lustre: DEBUG MARKER: == recovery-small test 152: QoS object allocation could be awakened in case of OST failover ========================================================== 03:01:52 (1787468512) [ 8089.166697] Lustre: DEBUG MARKER: == recovery-small test 153: evict vs reconnect race ====== 03:02:28 (1787468548) [ 8128.521675] LustreError: MGC192.168.201.111@tcp: Connection to MGS (at 192.168.201.111@tcp) was lost; in progress operations using this service will fail [ 8128.549321] Lustre: Evicted from MGS (at 192.168.201.111@tcp) after server handle changed from 0x2e5b45f6430fd60f to 0x2e5b45f6430fff36 [ 8148.929440] Lustre: DEBUG MARKER: == recovery-small test 154a: corruption update llog can be skipped ========================================================== 03:03:27 (1787468607) [ 8150.285369] Lustre: DEBUG MARKER: SKIP: recovery-small test_154a needs >= 2 MDTs [ 8152.355081] Lustre: DEBUG MARKER: == recovery-small test 154b: restore update llog after failed recovery ========================================================== 03:03:31 (1787468611) [ 8154.284306] Lustre: DEBUG MARKER: SKIP: recovery-small test_154b needs >= 2 MDTs [ 8156.535519] Lustre: DEBUG MARKER: == recovery-small test 155: failover after client remount ========================================================== 03:03:35 (1787468615) [ 8159.072135] Lustre: 2361:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787468578/real 1787468578] req@ffff9dbf48bc4000 x1874288301613312/t0(0) o400->lustre-MDT0000-mdc-ffff9dbf512b1800@192.168.201.111@tcp:12/10 lens 224/224 e 0 to 1 dl 1787468618 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 8167.718927] Lustre: Unmounted lustre-client [ 8169.858065] Lustre: Mounted lustre-client - version 2.17.57_65_gc740cad [ 8172.733676] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-MDT0000 [ 8191.456870] LustreError: MGC192.168.201.111@tcp: Connection to MGS (at 192.168.201.111@tcp) was lost; in progress operations using this service will fail [ 8200.682343] Lustre: Evicted from MGS (at 192.168.201.111@tcp) after server handle changed from 0x2e5b45f643100a73 to 0x2e5b45f643100e6a [ 8207.631305] Lustre: DEBUG MARKER: == recovery-small test 156: tot_granted miscount after client eviction ========================================================== 03:04:26 (1787468666) [ 8214.831773] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-OST0000 [ 8242.734619] LustreError: 2358:0:(client.c:3533:ptlrpc_replay_req()) cfs_fail_timeout id 536 sleeping for 45000ms [ 8287.799131] LustreError: 2358:0:(client.c:3533:ptlrpc_replay_req()) cfs_fail_timeout id 536 awake [ 8287.829596] LustreError: lustre-OST0000-osc-ffff9dbf45fcf800: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 8294.319796] Lustre: DEBUG MARKER: oleg111-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 8295.996959] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 8309.474398] Lustre: DEBUG MARKER: == recovery-small test 157: eviction during mmaped i/o === 03:06:08 (1787468768) [ 8310.108975] LustreError: 109259:0:(vvp_io.c:1490:vvp_io_fault_start()) cfs_fail_timeout id 1432 sleeping for 3000ms [ 8313.127233] LustreError: 109259:0:(vvp_io.c:1490:vvp_io_fault_start()) cfs_fail_timeout id 1432 awake [ 8313.151933] LustreError: lustre-OST0000-osc-ffff9dbf45fcf800: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 8320.266256] Lustre: DEBUG MARKER: == recovery-small test 158a: connect without access right ========================================================== 03:06:18 (1787468778) [ 8321.574577] Lustre: DEBUG MARKER: SKIP: recovery-small test_158a needs >= 2 MDTS [ 8323.172804] Lustre: DEBUG MARKER: == recovery-small test 160: MDT destroys are blocked by grouplocks ========================================================== 03:06:22 (1787468782) [ 8326.979789] LustreError: lustre-MDT0000-mdc-ffff9dbf45fcf800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 8376.792500] Lustre: DEBUG MARKER: == recovery-small test 161: evict osp by ping evictor ==== 03:07:15 (1787468835) [ 8378.363536] Lustre: DEBUG MARKER: SKIP: recovery-small test_161 needs >= 2 MDTs [ 8380.515271] Lustre: DEBUG MARKER: == recovery-small test 162: File attributes should be persisted after MDS failover ========================================================== 03:07:19 (1787468839) [ 8396.274910] Lustre: lustre-MDT0000-mdc-ffff9dbf45fcf800: Connection to lustre-MDT0000 (at 192.168.201.111@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 8396.307108] Lustre: Skipped 8 previous similar messages [ 8396.324887] LustreError: MGC192.168.201.111@tcp: Connection to MGS (at 192.168.201.111@tcp) was lost; in progress operations using this service will fail [ 8396.384084] Lustre: Evicted from MGS (at 192.168.201.111@tcp) after server handle changed from 0x2e5b45f643100e6a to 0x2e5b45f643101fdc [ 8396.409166] Lustre: MGC192.168.201.111@tcp: Connection restored to 192.168.201.111@tcp (at 192.168.201.111@tcp) [ 8396.439717] Lustre: Skipped 9 previous similar messages [ 8397.752568] LustreError: 2358:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9dbf5d26a300 x1874288301741184/t137438953528(137438953528) o101->lustre-MDT0000-mdc-ffff9dbf45fcf800@192.168.201.111@tcp:12/10 lens 576/608 e 0 to 0 dl 1787468898 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'chattr.0' uid:0 gid:0 projid:0 [ 8418.876281] Lustre: DEBUG MARKER: == recovery-small test 163: changelog check for fail write and processing records ========================================================== 03:07:57 (1787468877) [ 8426.279026] Lustre: 2361:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787468846/real 1787468846] req@ffff9dbf48bc5500 x1874288301746688/t0(0) o400->lustre-MDT0000-mdc-ffff9dbf45fcf800@192.168.201.111@tcp:12/10 lens 224/224 e 0 to 1 dl 1787468886 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 8426.341206] Lustre: 2361:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 7 previous similar messages [ 8444.099026] Lustre: DEBUG MARKER: == recovery-small test 170: Reconnect after REPLAY_LOCKS hangs (LU-18154) ========================================================== 03:08:22 (1787468902) [ 8450.951471] Lustre: DEBUG MARKER: local REPLAY BARRIER on lustre-OST0000 [ 8488.866503] Lustre: *** cfs_fail_loc=537, val=0*** [ 8488.886443] LustreError: 2358:0:(import.c:717:ptlrpc_connect_import_locked()) already connecting [ 8490.739831] Lustre: DEBUG MARKER: oleg111-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 60 0 [ 8492.481960] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 8501.400748] Lustre: DEBUG MARKER: == recovery-small test complete, duration 8189 sec ======= 03:09:19 (1787468959) [ 8503.849443] Lustre: DEBUG MARKER: === recovery-small: start cleanup 03:09:21 (1787468961) === [ 8807.315228] Lustre: DEBUG MARKER: === recovery-small: finish cleanup 03:14:25 (1787469265) === [ 8831.463104] LustreError: MGC192.168.201.111@tcp: Connection to MGS (at 192.168.201.111@tcp) was lost; in progress operations using this service will fail [ 8831.521446] Lustre: Evicted from MGS (at 192.168.201.111@tcp) after server handle changed from 0x2e5b45f643101fdc to 0x2e5b45f643193dd0 [ 8861.836087] Lustre: DEBUG MARKER: oleg111-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 8865.017768] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8871.027213] Lustre: Unmounted lustre-client [ 8912.572136] Key type lgssc unregistered [ 8912.946175] LNet: 115925:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 8912.957475] LNetError: 115925:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 8912.985078] LNet: Removed LNI 192.168.201.11@tcp [ 8913.908180] Key type .llcrypt unregistered [ 8913.911889] Key type ._llcrypt unregistered