[ 0.000000] Linux version 4.18.0rh8.10-debug (green@maintenance) (gcc version 8.5.0 20210514 (Red Hat 8.5.0-26) (GCC)) #2 SMP Mon Jul 14 01:24:22 EDT 2025 [ 0.000000] Command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers' [ 0.000000] x86/fpu: xstate_offset[2]: 576, xstate_sizes[2]: 256 [ 0.000000] x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'standard' format. [ 0.000000] signal: max sigframe size: 1776 [ 0.000000] BIOS-provided physical RAM map: [ 0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable [ 0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000000100000-0x00000000bffd9fff] usable [ 0.000000] BIOS-e820: [mem 0x00000000bffda000-0x00000000bfffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000100000000-0x0000000146dfffff] usable [ 0.000000] NX (Execute Disable) protection: active [ 0.000000] SMBIOS 2.8 present. [ 0.000000] DMI: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.16.2-1.fc38 04/01/2014 [ 0.000000] Hypervisor detected: KVM [ 0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00 [ 0.000000] kvm-clock: using sched offset of 443076420 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2399.998 MHz processor [ 0.000000] last_pfn = 0x146e00 max_arch_pfn = 0x400000000 [ 0.000000] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT [ 0.000000] last_pfn = 0xbffda max_arch_pfn = 0x400000000 [ 0.000000] found SMP MP-table at [mem 0x000f5b50-0x000f5b5f] [ 0.000000] RAMDISK: [mem 0xbcc64000-0xbffcffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F5970 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE1BB7 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE1A53 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 001A13 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE1AC7 000090 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE1B57 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE1B8F 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe1a53-0xbffe1ac6] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe1a52] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe1ac7-0xbffe1b56] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe1b57-0xbffe1b8e] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe1b8f-0xbffe1bb6] [ 0.000000] No NUMA configuration found [ 0.000000] Faking a node at [mem 0x0000000000000000-0x0000000146dfffff] [ 0.000000] NODE_DATA(0) allocated [mem 0x1465a3000-0x1465cdfff] [ 0.000000] Reserving 256MB of memory at 2752MB for crashkernel (System RAM: 4205MB) [ 0.000000] Zone ranges: [ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.000000] DMA32 [mem 0x0000000001000000-0x00000000ffffffff] [ 0.000000] Normal [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Device empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff] [ 0.000000] node 0: [mem 0x0000000000100000-0x00000000bffd9fff] [ 0.000000] node 0: [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Zeroed struct page in unavailable ranges: 4744 pages [ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x0000000146dfffff] [ 0.000000] ACPI: PM-Timer IO Port: 0x608 [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) [ 0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) [ 0.000000] Using ACPI (MADT) for SMP configuration information [ 0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000] TSC deadline timer available [ 0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs [ 0.000000] kvm-guest: KVM setup pv remote TLB flush [ 0.000000] kvm-guest: setup PV sched yield [ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff] [ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff] [ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff] [ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff] [ 0.000000] PM: Registered nosave memory: [mem 0xbffda000-0xbfffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xc0000000-0xfeffbfff] [ 0.000000] PM: Registered nosave memory: [mem 0xfeffc000-0xfeffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xff000000-0xfffbffff] [ 0.000000] PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff] [ 0.000000] [mem 0xc0000000-0xfeffbfff] available for PCI devices [ 0.000000] Booting paravirtualized kernel on KVM [ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns [ 0.000000] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1 [ 0.000000] percpu: Embedded 63 pages/cpu s221184 r8192 d28672 u524288 [ 0.000000] kvm-guest: PV spinlocks enabled [ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1059618 [ 0.000000] Policy zone: Normal [ 0.000000] Kernel command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] Specific versions of hardware are certified with Red Hat Enterprise Linux 8. Please see the list of hardware certified with Red Hat Enterprise Linux 8 at https://catalog.redhat.com. [ 0.000000] audit: disabled (until reboot) [ 0.000000] software IO TLB: area num 4. [ 0.000000] Memory: 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.001012] APIC: Switch to symmetric I/O mode setup [ 0.002306] x2apic enabled [ 0.003004] Switched APIC routing to physical x2apic. [ 0.004008] kvm-guest: setup PV IPIs [ 0.007296] ..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.008022] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.009011] pid_max: default: 32768 minimum: 301 [ 0.011024] LSM: Security Framework initializing [ 0.012029] Yama: becoming mindful. [ 0.013027] SELinux: Initializing. [ 0.014055] *** VALIDATE selinux *** [ 0.022195] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.027324] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.029149] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.030092] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.031128] *** VALIDATE tmpfs *** [ 0.033093] *** VALIDATE proc *** [ 0.034308] *** VALIDATE cgroup *** [ 0.035008] *** VALIDATE cgroup2 *** [ 0.037231] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.039063] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.040005] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.041023] Spectre V2 : User space: Vulnerable [ 0.042004] Speculative Store Bypass: Vulnerable [ 0.044511] debug: unmapping init [mem 0xffffffff9d459000-0xffffffff9d460fff] [ 0.047000] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.047785] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.048023] ... version: 2 [ 0.049009] ... bit width: 48 [ 0.049927] ... generic registers: 4 [ 0.050008] ... value mask: 0000ffffffffffff [ 0.051006] ... max period: 00007fffffffffff [ 0.052007] ... fixed-purpose events: 3 [ 0.052882] ... event mask: 000000070000000f [ 0.054055] rcu: Hierarchical SRCU implementation. [ 0.056282] smp: Bringing up secondary CPUs ... [ 0.057488] x86: Booting SMP configuration: [ 0.058021] .... node #0, CPUs: #1 #2 #3 [ 0.061054] smp: Brought up 1 node, 4 CPUs [ 0.063009] smpboot: Max logical packages: 1 [ 0.064013] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.264633] node 0 deferred pages initialised in 198ms [ 0.268013] devtmpfs: initialized [ 0.269200] x86/mm: Memory block size: 128MB [ 0.271806] gcov: version magic: 0x41383552 [ 0.274164] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.277072] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.279299] pinctrl core: initialized pinctrl subsystem [ 0.281141] [ 0.281620] ************************************************************* [ 0.283021] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.285011] ** ** [ 0.287010] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.289016] ** ** [ 0.291011] ** This means that this kernel is built to expose internal ** [ 0.293016] ** IOMMU data structures, which may compromise security on ** [ 0.295016] ** your system. ** [ 0.297010] ** ** [ 0.299010] ** If you see this message and you are not debugging the ** [ 0.300019] ** kernel, report this immediately to your vendor! ** [ 0.302011] ** ** [ 0.304039] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.306016] ************************************************************* [ 0.308531] NET: Registered protocol family 16 [ 0.309395] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.312058] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.314079] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.317209] cpuidle: using governor menu [ 0.318367] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.320589] PCI: Using configuration type 1 for base access [ 0.322144] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.330325] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.332035] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.335168] cryptd: max_cpu_qlen set to 1000 [ 0.339028] ACPI: Added _OSI(Module Device) [ 0.340016] ACPI: Added _OSI(Processor Device) [ 0.341000] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.341000] ACPI: Added _OSI(Processor Aggregator Device) [ 0.345774] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.351476] ACPI: Interpreter enabled [ 0.352048] ACPI: PM: (supports S0 S3 S4 S5) [ 0.354020] ACPI: Using IOAPIC for interrupt routing [ 0.355176] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.358452] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.368336] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.370072] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.372027] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.375108] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.380435] acpiphp: Slot [2] registered [ 0.382210] acpiphp: Slot [3] registered [ 0.384124] acpiphp: Slot [4] registered [ 0.385121] acpiphp: Slot [5] registered [ 0.386210] acpiphp: Slot [6] registered [ 0.388141] acpiphp: Slot [7] registered [ 0.389140] acpiphp: Slot [8] registered [ 0.391167] acpiphp: Slot [9] registered [ 0.393449] acpiphp: Slot [10] registered [ 0.397334] acpiphp: Slot [11] registered [ 0.400208] acpiphp: Slot [12] registered [ 0.401129] acpiphp: Slot [13] registered [ 0.402059] acpiphp: Slot [14] registered [ 0.404190] acpiphp: Slot [15] registered [ 0.405057] acpiphp: Slot [16] registered [ 0.406079] acpiphp: Slot [17] registered [ 0.407058] acpiphp: Slot [18] registered [ 0.408072] acpiphp: Slot [19] registered [ 0.410068] acpiphp: Slot [20] registered [ 0.411058] acpiphp: Slot [21] registered [ 0.412078] acpiphp: Slot [22] registered [ 0.413056] acpiphp: Slot [23] registered [ 0.414062] acpiphp: Slot [24] registered [ 0.415073] acpiphp: Slot [25] registered [ 0.417056] acpiphp: Slot [26] registered [ 0.418053] acpiphp: Slot [27] registered [ 0.419078] acpiphp: Slot [28] registered [ 0.420053] acpiphp: Slot [29] registered [ 0.421084] acpiphp: Slot [30] registered [ 0.422178] acpiphp: Slot [31] registered [ 0.423063] PCI host bridge to bus 0000:00 [ 0.424027] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.426017] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.427017] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.429021] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.431013] pci_bus 0000:00: root bus resource [mem 0x180000000-0x1ffffffff window] [ 0.433016] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.434168] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.438000] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.440947] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.447015] pci 0000:00:01.1: reg 0x20: [io 0xc120-0xc12f] [ 0.452057] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.455030] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.458019] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.461015] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.463518] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.466762] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.469037] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.471590] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.474012] pci 0000:00:02.0: reg 0x10: [io 0xc100-0xc11f] [ 0.481027] pci 0000:00:02.0: reg 0x20: [mem 0xfebf4000-0xfebf7fff 64bit pref] [ 0.485014] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.490923] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.515024] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.522027] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.534018] pci 0000:00:05.0: reg 0x20: [mem 0xfebf8000-0xfebfbfff 64bit pref] [ 0.541028] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.549034] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.560027] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.576024] pci 0000:00:06.0: reg 0x20: [mem 0xfebfc000-0xfebfffff 64bit pref] [ 0.587584] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.591782] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.594382] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.596349] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.598192] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.603236] iommu: Default domain type: Passthrough [ 0.604507] SCSI subsystem initialized [ 0.605175] ACPI: bus type USB registered [ 0.606126] usbcore: registered new interface driver usbfs [ 0.608069] usbcore: registered new interface driver hub [ 0.610073] usbcore: registered new device driver usb [ 0.611171] pps_core: LinuxPPS API ver. 1 registered [ 0.613013] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.616056] PTP clock support registered [ 0.618143] EDAC MC: Ver: 3.0.0 [ 0.620028] PCI: Using ACPI for IRQ routing [ 0.621739] NetLabel: Initializing [ 0.623011] NetLabel: domain hash size = 128 [ 0.625015] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.627078] NetLabel: unlabeled traffic allowed by default [ 0.630045] vgaarb: loaded [ 0.632291] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.633007] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.637311] clocksource: Switched to clocksource kvm-clock [ 0.756507] VFS: Disk quotas dquot_6.6.0 [ 0.758085] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.760950] *** VALIDATE ramfs *** [ 0.761986] *** VALIDATE hugetlbfs *** [ 0.764338] pnp: PnP ACPI init [ 0.766490] pnp: PnP ACPI: found 6 devices [ 0.787206] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.790393] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.792363] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.794481] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.796986] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.799017] pci_bus 0000:00: resource 8 [mem 0x180000000-0x1ffffffff window] [ 0.802196] NET: Registered protocol family 2 [ 0.804840] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.809184] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.812392] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.817355] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.820518] TCP: Hash tables configured (established 65536 bind 65536) [ 0.823117] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.825633] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.828012] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.830597] NET: Registered protocol family 1 [ 0.833414] RPC: Registered named UNIX socket transport module. [ 0.835351] RPC: Registered udp transport module. [ 0.836902] RPC: Registered tcp transport module. [ 0.838502] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.840907] NET: Registered protocol family 44 [ 0.842564] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.844701] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.846920] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.848854] PCI: CLS 0 bytes, default 64 [ 0.851173] Unpacking initramfs... [ 2.425928] debug: unmapping init [mem 0xffff89bb3cc64000-0xffff89bb3ffcffff] [ 2.431328] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.433667] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.436707] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 2.961876] Initialise system trusted keyrings [ 2.963230] Key type blacklist registered [ 2.965423] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.973876] zbud: loaded [ 2.976905] *** VALIDATE nfs *** [ 2.978160] *** VALIDATE nfs4 *** [ 2.979365] pstore: using deflate compression [ 2.982933] Platform Keyring initialized [ 3.143429] NET: Registered protocol family 38 [ 3.146645] Key type asymmetric registered [ 3.148631] Asymmetric key parser 'x509' registered [ 3.151368] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 3.156316] io scheduler mq-deadline registered [ 3.161223] io scheduler kyber registered [ 3.162860] io scheduler bfq registered [ 3.164478] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 3.167841] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 3.170288] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 3.173205] ACPI: Power Button [PWRF] [ 3.281898] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 3.382364] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 3.490485] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 3.519097] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.549307] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.554344] Non-volatile memory driver v1.3 [ 3.555780] Linux agpgart interface v0.103 [ 3.590070] virtio_blk virtio1: [vda] 132696 512-byte logical blocks (67.9 MB/64.8 MiB) [ 3.592989] vda: detected capacity change from 0 to 67940352 [ 3.624838] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.632409] vdb: detected capacity change from 0 to 1073741824 [ 3.647435] libphy: Fixed MDIO Bus: probed [ 3.664630] usbcore: registered new interface driver usbserial_generic [ 3.668085] usbserial: USB Serial support registered for generic [ 3.674787] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.689602] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.692807] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.696495] mousedev: PS/2 mouse device common for all mice [ 3.699745] rtc_cmos 00:05: RTC can wake from S4 [ 3.703521] rtc_cmos 00:05: registered as rtc0 [ 3.705605] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.707929] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.713507] intel_pstate: CPU model not supported [ 3.727321] hid: raw HID events driver (C) Jiri Kosina [ 3.730080] usbcore: registered new interface driver usbhid [ 3.739547] usbhid: USB HID core driver [ 3.741039] drop_monitor: Initializing network drop monitor service [ 3.743812] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.747232] Initializing XFRM netlink socket [ 3.750186] NET: Registered protocol family 10 [ 3.754575] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.757863] Segment Routing with IPv6 [ 3.759061] NET: Registered protocol family 17 [ 3.761486] mpls_gso: MPLS GSO support [ 3.768596] RAS: Correctable Errors collector initialized. [ 3.770576] AVX version of gcm_enc/dec engaged. [ 3.772241] AES CTR mode by8 optimization enabled [ 3.884390] sched_clock: Marking stable (3884189476, 0)->(4766331883, -882142407) [ 3.887844] registered taskstats version 1 [ 3.889450] Loading compiled-in X.509 certificates [ 3.891913] zswap: loaded using pool lzo/zbud [ 3.929132] Key type big_key registered [ 3.950665] Key type encrypted registered [ 3.952216] ima: No TPM chip found, activating TPM-bypass! [ 3.954195] ima: Allocated hash algorithm: sha1 [ 3.955895] ima: No architecture policies found [ 3.957438] evm: Initialising EVM extended attributes: [ 3.959173] evm: security.selinux [ 3.960340] evm: security.ima [ 3.961436] evm: security.capability [ 3.962742] evm: HMAC attrs: 0x1 [ 3.976385] rtc_cmos 00:05: setting system clock to 2025-07-16 17:41:49 UTC (1752687709) [ 3.983581] debug: unmapping init [mem 0xffffffff9e403000-0xffffffff9e5fffff] [ 3.995527] debug: unmapping init [mem 0xffffffff9d182000-0xffffffff9d458fff] [ 4.000123] Write protecting the kernel read-only data: 28672k [ 4.005180] debug: unmapping init [mem 0xffffffff9b803000-0xffffffff9b9fffff] [ 4.007720] debug: unmapping init [mem 0xffffffff9c114000-0xffffffff9c1fffff] [ 4.043819] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 4.054816] systemd[1]: Detected virtualization kvm. [ 4.057432] systemd[1]: Detected architecture x86-64. [ 4.060135] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 4.090283] systemd[1]: No hostname configured. [ 4.091870] systemd[1]: Set hostname to . [ 4.096154] random: systemd: uninitialized urandom read (16 bytes read) [ 4.103170] systemd[1]: Initializing machine ID from random generator. [ 4.215831] random: ln: uninitialized urandom read (6 bytes read) [ 4.440886] random: systemd: uninitialized urandom read (16 bytes read) [ 4.446487] systemd[1]: Listening on udev Kernel Socket. [ OK ] Listening on udev Kernel Socket. [ 4.457440] systemd[1]: Reached target Swap. [ OK ] Reached target Swap. [ 4.465276] systemd[1]: Reached target Slices. [ OK ] Reached target Slices. [ OK ] Listening on udev Control Socket. [ OK ] Listening on Journal Socket (/dev/log). [ OK ] Reached target Initrd Root Device. [ OK ] Reached target Timers. [ OK ] Reached target Local File Systems. [ OK ] Listening on Journal Socket. Starting Journal Service... [ OK ] Started Memstrack Anylazing Service. Starting Create Volatile Files and Directories... Starting Create list of required st…ce nodes for the current kernel... [ OK ] Reached target Sockets. Starting Setup Virtual Console... Starting Apply Kernel Variables... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Setup Virtual Console. [ OK ] Started Apply Kernel Variables. Starting dracut cmdline hook... Starting Create Static Device Nodes in /dev... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started Journal Service. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 5.928847] device-mapper: uevent: version 1.0.3 [ 5.935919] 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 [ 6.954353] random: fast init done ] Started udev Coldplug all Devices. [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting dracut initqueue hook... [ 7.140504] virtio_net virtio0 ens2: renamed from eth0 [ 7.789159] scsi host0: ata_piix [ 7.849378] scsi host1: ata_piix [ 7.850766] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc120 irq 14 [ 7.861717] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc128 irq 15 [ 12.512905] random: crng init done [ 12.514241] random: 7 urandom warning(s) missed due to ratelimiting [ 14.536796] dracut-initqueue[585]: RTNETLINK answers: File exists Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. Mounting /sysroot... [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. [ 15.916734] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped target Timers. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Paths. [ OK ] Stopped target Slices. [ OK ] Stopped target Sockets. [ OK ] Stopped target System Initialization. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. [ OK ] Stopped target Local File Systems. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. Stopping udev Kernel Device Manager... [ OK ] Stopped target Swap. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped udev Kernel Device Manager. [ 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... [ 17.436178] printk: systemd: 26 output lines suppressed due to ratelimiting [ 17.872651] SELinux: Disabled at runtime. [ 17.945660] 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) [ 17.961197] systemd[1]: Detected virtualization kvm. [ 17.962952] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 19.034678] systemd[1]: initrd-switch-root.service: Succeeded. [ 19.040792] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 19.056178] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 19.064473] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 19.073445] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 19.090617] systemd[1]: Starting Journal Service... Starting Journal Service... [ 19.100459] systemd[1]: Created slice User and Session Slice. [ OK ] Created slice User and Session Slice. [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Listening on Process Core Dump Socket. [ OK ] Listening on RPCbind Server Activation Socket. [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. Activating swap /dev/disk/by-label/SWAP... [ OK ] Reached target RPC Port Mapper. [ OK ] Reached target Slices. Mounting Huge Pages File System... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Listening on udev Control Socket. [ 19.245672] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS Starting Create list of required st…ce nodes for the current kernel... Starting Remount Root and Kernel File Systems... [ OK ] Listening on udev Kernel Socket. Starting udev Coldplug all Devices... [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd File Systems. [ OK ] Stopped target Initrd Root File System. [ OK ] Reached target rpc_pipefs.target. Mounting Kernel Debug File System... [ OK ] Created slice system-getty.slice. Starting Apply Kernel Variables... Mounting POSIX Message Queue File System... [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Started Journal Service. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Mounted Huge Pages File System. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Mounted Kernel Debug File System. [ OK ] Started Apply Kernel Variables. [ OK ] Mounted POSIX Message Queue File System. Starting Configure read-only root support... Starting Create Static Device Nodes in /dev... [ OK ] Reached target Swap. Starting Flush Journal to Persistent Storage... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started udev Coldplug all Devices. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Reached target Local File Systems (Pre). Mounting /mnt... Mounting /home/green/git/lustre-release... Starting udev Kernel Device Manager... [ OK ] Mounted /mnt. [ 19.776678] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 20.247819] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 20.406982] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 20.502698] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 20.541390] EDAC sbridge: Ver: 1.1.2 [ 22.775861] Key type dns_resolver registered [ 23.141655] NFS: Registering the id_resolver key type [ 23.143726] Key type id_resolver registered [ 23.149475] Key type id_legacy registered [ OK ] Started Configure read-only root support. Starting Load/Save Random Seed... [ OK ] Reached target Local File Systems. Starting Rebuild Dynamic Linker Cache... Starting Mark the need to relabel after reboot... Starting Create Volatile Files and Directories... [ OK ] Started Load/Save Random Seed. [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Create Volatile Files and Directories. Starting 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 update of the root trust anchor for DNSSEC. [ OK ] Started dnf makecache --timer. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Reached target Timers. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. Starting Login Service... Starting Restore /run/initramfs on shutdown... [ OK ] Started irqbalance daemon. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Started D-Bus System Message Bus. Starting Network Manager... [ OK ] Reached target sshd-keygen.target. [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Login Service. [ OK ] Started Network Manager. [ OK ] Reached target Network. Starting Dynamic System Tuning Daemon... Starting GSSAPI Proxy Daemon... Starting OpenSSH server daemon... Starting Network Manager Wait Online... Starting Hostname Service... [ OK ] Started GSSAPI Proxy Daemon. [ OK ] 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 Getty on tty1. [ OK ] Started Serial Getty on ttyS1. [ OK ] Started Serial Getty on ttyS0. [ OK ] Reached target Login Prompts. [ OK ] Started Command Scheduler. [ OK ] Started OpenSSH server daemon. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting Crash recovery kernel arming... Starting Notify NFS peers of a restart... Starting System Logging Service... [ 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 oleg303-client login: [ 56.381587] libcfs: loading out-of-tree module taints kernel. [ 56.404490] Key type ._llcrypt registered [ 56.406701] Key type .llcrypt registered [ 56.660850] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [ 56.665341] alg: No test for adler32 (adler32-zlib) [ 57.628370] Lustre: Lustre: Build Version: 2.16.57_1_gf739d57 [ 57.863106] LNet: Added LNI 192.168.203.3@tcp [8/256/0/180] [ 57.864535] LNet: Accept secure, port 988 [ 59.456132] Key type lgssc registered [ 59.882376] Lustre: Echo OBD driver; http://www.lustre.org/ [ 117.187310] Lustre: Mounted lustre-client [ 119.646968] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 133.086332] Lustre: DEBUG MARKER: oleg303-client.virtnet: executing check_logdir /tmp/testlogs/ [ 134.518103] Lustre: DEBUG MARKER: oleg303-client.virtnet: executing yml_node [ 136.019924] Lustre: DEBUG MARKER: Client: 2.16.57.1 [ 136.807779] Lustre: DEBUG MARKER: MDS: 2.16.57.1 [ 137.604690] Lustre: DEBUG MARKER: OSS: 2.16.57.1 [ 138.127550] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity ============----- Wed Jul 16 13:44:03 EDT 2025 [ 142.816202] Lustre: lustre-OST0000-osc-ffff89bba0294800: disconnect after 24s idle [ 143.848072] Lustre: DEBUG MARKER: - need mds1 <= 2.14.55-100-g8a84c7f9c7 for LU-14927, skip 0f [ 144.357176] Lustre: DEBUG MARKER: - need mds1 < v2_14_55-100-g8a84c7f9c7 for LU-14927, skip 0f [ 144.875183] Lustre: DEBUG MARKER: excepting tests: 225 255 256 400a 42a 42c 42b 118c 118d 407 119i 817 411a [ 145.434176] Lustre: DEBUG MARKER: skipping tests SLOW=no: 27m 60i 64b 68 71 135 136 230d 300o 842 [ 145.922480] Lustre: DEBUG MARKER: === sanity: start setup 13:44:10 (1752687850) === [ 147.136758] Lustre: DEBUG MARKER: oleg303-client.virtnet: executing check_config_client /mnt/lustre [ 153.326199] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 157.340746] Lustre: DEBUG MARKER: === sanity: finish setup 13:44:22 (1752687862) === [ 160.908911] Lustre: DEBUG MARKER: == sanity test 200: OST pools ============================ 13:44:25 (1752687865) [ 178.608844] Lustre: DEBUG MARKER: == sanity test 204a: Print default stripe attributes ===== 13:44:43 (1752687883) [ 181.040738] Lustre: DEBUG MARKER: == sanity test 204b: Print default stripe size and offset ========================================================== 13:44:46 (1752687886) [ 183.455319] Lustre: DEBUG MARKER: == sanity test 204c: Print default stripe count and offset ========================================================== 13:44:48 (1752687888) [ 185.877170] Lustre: DEBUG MARKER: == sanity test 204d: Print default stripe count and size ========================================================== 13:44:50 (1752687890) [ 188.398315] Lustre: DEBUG MARKER: == sanity test 204e: Print raw stripe attributes ========= 13:44:53 (1752687893) [ 191.006317] Lustre: DEBUG MARKER: == sanity test 204f: Print raw stripe size and offset ==== 13:44:55 (1752687895) [ 193.551570] Lustre: DEBUG MARKER: == sanity test 204g: Print raw stripe count and offset === 13:44:58 (1752687898) [ 196.021105] Lustre: DEBUG MARKER: == sanity test 204h: Print raw stripe count and size ===== 13:45:01 (1752687901) [ 198.567355] Lustre: DEBUG MARKER: == sanity test 205a: Verify job stats ==================== 13:45:03 (1752687903) [ 199.136476] Lustre: lustre-OST0000-osc-ffff89bba0294800: disconnect after 23s idle [ 199.139690] Lustre: Skipped 1 previous similar message [ 204.474165] Lustre: DEBUG MARKER: Test: /home/green/git/lustre-release/lustre/utils/lfs mkdir -i 0 -c 1 /mnt/lustre/d205a.sanity [ 205.141328] Lustre: DEBUG MARKER: Using JobID environment nodelocal=id.205a.lfs.17468 [ 206.071616] Lustre: DEBUG MARKER: Test: rmdir /mnt/lustre/d205a.sanity [ 206.608238] Lustre: DEBUG MARKER: Using JobID environment nodelocal=id.205a.rmdir.18207 [ 207.504355] Lustre: DEBUG MARKER: Test: lfs mkdir -i 1 /mnt/lustre/d205a.sanity.remote [ 208.049159] Lustre: DEBUG MARKER: Using JobID environment nodelocal=id.205a.lfs.31286 [ 208.935601] Lustre: DEBUG MARKER: Test: mknod /mnt/lustre/f205a.sanity c 1 3 [ 209.474478] Lustre: DEBUG MARKER: Using JobID environment nodelocal=id.205a.mknod.4102 [ 210.399850] Lustre: DEBUG MARKER: Test: rm -f /mnt/lustre/f205a.sanity [ 210.973805] Lustre: DEBUG MARKER: Using JobID environment nodelocal=id.205a.rm.7923 [ 211.869893] Lustre: DEBUG MARKER: Test: /home/green/git/lustre-release/lustre/utils/lfs setstripe -i 0 -c 1 /mnt/lustre/f205a.sanity [ 212.457487] Lustre: DEBUG MARKER: Using JobID environment nodelocal=id.205a.lfs.32371 [ 213.375169] Lustre: DEBUG MARKER: Test: touch /mnt/lustre/f205a.sanity [ 213.964328] Lustre: DEBUG MARKER: Using JobID environment nodelocal=id.205a.touch.26417 [ 215.137739] Lustre: DEBUG MARKER: Test: dd if=/dev/zero of=/mnt/lustre/f205a.sanity bs=1M count=1 oflag=sync [ 215.709324] Lustre: DEBUG MARKER: Using JobID environment nodelocal=id.205a.dd.20697 [ 216.706895] Lustre: DEBUG MARKER: Test: dd if=/mnt/lustre/f205a.sanity of=/dev/null bs=1M count=1 iflag=direct [ 217.273771] Lustre: DEBUG MARKER: Using JobID environment nodelocal=id.205a.dd.28054 [ 218.180981] Lustre: DEBUG MARKER: Test: /home/green/git/lustre-release/lustre/tests/truncate /mnt/lustre/f205a.sanity 0 [ 218.765227] Lustre: DEBUG MARKER: Using JobID environment nodelocal=id.205a.truncate.13856 [ 220.011607] Lustre: DEBUG MARKER: Test: mv -f /mnt/lustre/f205a.sanity /mnt/lustre/d205a.sanity.rename [ 220.598309] Lustre: DEBUG MARKER: Using JobID environment nodelocal=id.205a.mv.32381 [ 221.484596] Lustre: DEBUG MARKER: Test: /home/green/git/lustre-release/lustre/utils/lfs mkdir -i 0 -c 1 /mnt/lustre/d205a.sanity.expire [ 222.033475] Lustre: DEBUG MARKER: Using JobID environment nodelocal=id.205a.lfs.20015 [ 226.107325] Lustre: DEBUG MARKER: Test: touch /mnt/lustre/f205a.sanity [ 226.687228] Lustre: DEBUG MARKER: Using JobID environment USER=S.root.touch.0.oleg303-client.v [ 227.588701] Lustre: DEBUG MARKER: Test: touch /mnt/lustre/f205a.sanity [ 228.161110] Lustre: DEBUG MARKER: Using JobID environment USER=S.root.touch.0.oleg303-client.E [ 229.059233] Lustre: DEBUG MARKER: Test: touch /mnt/lustre/f205a.sanity [ 229.667074] Lustre: DEBUG MARKER: Using JobID environment session=S.root.touch.0.oleg303-client.v [ 237.090168] Lustre: DEBUG MARKER: == sanity test 205b: Verify job stats jobid and output format ========================================================== 13:45:42 (1752687942) [ 241.421064] Lustre: DEBUG MARKER: == sanity test 205c: Verify client stats format ========== 13:45:46 (1752687946) [ 243.807305] Lustre: DEBUG MARKER: == sanity test 205d: verify the format of some stats files ========================================================== 13:45:48 (1752687948) [ 249.004640] Lustre: DEBUG MARKER: == sanity test 205e: verify the output of lljobstat ====== 13:45:53 (1752687953) [ 254.814690] Lustre: DEBUG MARKER: == sanity test 205f: verify qos_ost_weights YAML format == 13:45:59 (1752687959) [ 257.944276] Lustre: DEBUG MARKER: == sanity test 205g: stress test for job_stats procfile == 13:46:02 (1752687962) [ 352.557456] Lustre: DEBUG MARKER: == sanity test 205h: check jobid xattr is stored correctly ========================================================== 13:47:37 (1752688057) [ 356.867343] Lustre: DEBUG MARKER: == sanity test 205i: check job_xattr parameter accepts and rejects values correctly ========================================================== 13:47:41 (1752688061) [ 361.818544] Lustre: DEBUG MARKER: == sanity test 205k: Verify '?' operator on job stats ==== 13:47:46 (1752688066) [ 366.053441] Lustre: DEBUG MARKER: == sanity test 205l: Verify job stats can scale ========== 13:47:50 (1752688070) [ 446.479209] Lustre: DEBUG MARKER: == sanity test 205m: Test width parsing of job_stats ===== 13:49:11 (1752688151) [ 455.519130] Lustre: DEBUG MARKER: == sanity test 206: fail lov_init_raid0() doesn't lbug === 13:49:20 (1752688160) [ 455.646076] Lustre: *** cfs_fail_loc=1403, val=1*** [ 455.648150] LustreError: 50631:0:(lcommon_cl.c:188:cl_file_inode_init()) lustre: failed to initialize cl_object [0x200000402:0xdc4:0x0]: rc = -5 [ 455.652362] LustreError: 50631:0:(llite_lib.c:3770:ll_prep_inode()) lustre: new_inode - fatal error: rc = -5 [ 458.992407] Lustre: DEBUG MARKER: == sanity test 207a: can refresh layout at glimpse ======= 13:49:23 (1752688163) [ 462.415371] Lustre: DEBUG MARKER: == sanity test 207b: can refresh layout at open ========== 13:49:27 (1752688167) [ 466.101861] Lustre: DEBUG MARKER: == sanity test 208: Exclusive open ======================= 13:49:30 (1752688170) [ 475.625989] Lustre: lustre-MDT0000-mdc-ffff89bba0294800: Connection to lustre-MDT0000 (at 192.168.203.103@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 485.856485] Lustre: lustre-OST0000-osc-ffff89bba0294800: disconnect after 22s idle [ 485.860173] Lustre: Skipped 1 previous similar message [ 490.985822] LustreError: MGC192.168.203.103@tcp: Connection to MGS (at 192.168.203.103@tcp) was lost; in progress operations using this service will fail [ 490.995711] Lustre: Evicted from MGS (at 192.168.203.103@tcp) after server handle changed from 0xe47d86e6846b2b29 to 0xe47d86e6846fd3ad [ 491.001871] Lustre: MGC192.168.203.103@tcp: Connection restored to 192.168.203.103@tcp (at 192.168.203.103@tcp) [ 491.006520] LustreError: 2400:0:(mdc_request.c:660:mdc_replay_open()) @@@ cannot properly replay without open data req@ffff89bb87f2df80 x1837826328229632/t4294978968(4294978968) o101->lustre-MDT0000-mdc-ffff89bba0294800@192.168.203.103@tcp:12/10 lens 608/608 e 0 to 0 dl 1752688212 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'touch.0' uid:0 gid:0 projid:0 [ 491.018321] LustreError: 2400:0:(client.c:3395:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff89bb87f2df80 x1837826328229632/t4294978968(4294978968) o101->lustre-MDT0000-mdc-ffff89bba0294800@192.168.203.103@tcp:12/10 lens 608/608 e 0 to 0 dl 1752688212 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'touch.0' uid:0 gid:0 projid:0 [ 493.388223] Lustre: lustre-MDT0000-mdc-ffff89bba0294800: Connection restored to 192.168.203.103@tcp (at 192.168.203.103@tcp) [ 494.919616] Lustre: DEBUG MARKER: oleg303-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 495.694501] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 501.221266] Lustre: lustre-MDT0000-mdc-ffff89bba0294800: Connection to lustre-MDT0000 (at 192.168.203.103@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 516.576750] Lustre: 2401:0:(client.c:2453:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1752688206/real 1752688206] req@ffff89bb98025880 x1837826328251520/t0(0) o400->MGC192.168.203.103@tcp@192.168.203.103@tcp:26/25 lens 224/224 e 0 to 1 dl 1752688222 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 516.577189] Lustre: lustre-OST0000-osc-ffff89bba0294800: disconnect after 20s idle [ 516.580882] LustreError: MGC192.168.203.103@tcp: Connection to MGS (at 192.168.203.103@tcp) was lost; in progress operations using this service will fail [ 516.585980] Lustre: Evicted from MGS (at 192.168.203.103@tcp) after server handle changed from 0xe47d86e6846fd3ad to 0xe47d86e6846fd86f [ 516.592251] Lustre: MGC192.168.203.103@tcp: Connection restored to 192.168.203.103@tcp (at 192.168.203.103@tcp) [ 516.593603] Lustre: Skipped 1 previous similar message [ 516.600593] LustreError: 2400:0:(mdc_request.c:660:mdc_replay_open()) @@@ cannot properly replay without open data req@ffff89bb87f2df80 x1837826328229632/t4294978968(4294978968) o101->lustre-MDT0000-mdc-ffff89bba0294800@192.168.203.103@tcp:12/10 lens 608/608 e 0 to 0 dl 1752688238 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'touch.0' uid:0 gid:0 projid:0 [ 516.624134] LustreError: 2400:0:(client.c:3395:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff89bb87f2f100 x1837826328250752/t8589934595(8589934595) o101->lustre-MDT0000-mdc-ffff89bba0294800@192.168.203.103@tcp:12/10 lens 584/608 e 0 to 0 dl 1752688238 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'multiop.0' uid:0 gid:0 projid:0 [ 516.633720] LustreError: 2400:0:(client.c:3395:ptlrpc_replay_interpret()) Skipped 2 previous similar messages [ 518.985727] Lustre: lustre-MDT0000-mdc-ffff89bba0294800: Connection restored to 192.168.203.103@tcp (at 192.168.203.103@tcp) [ 520.548699] Lustre: DEBUG MARKER: oleg303-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 521.231499] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 525.481342] Lustre: DEBUG MARKER: == sanity test 209: read-only open/close requests should be freed promptly ========================================================== 13:50:30 (1752688230) [ 530.939827] bash (54385): drop_caches: 3 [ 535.095094] bash (54385): drop_caches: 3 [ 538.515246] Lustre: DEBUG MARKER: == sanity test 210: lfs getstripe does not break leases == 13:50:43 (1752688243) [ 543.509325] Lustre: DEBUG MARKER: == sanity test 212: Sendfile test ====================================================================================================== 13:50:48 (1752688248) [ 547.381711] Lustre: DEBUG MARKER: == sanity test 213: OSC lock completion and cancel race don't crash - bug 18829 ========================================================== 13:50:52 (1752688252) [ 547.483965] LustreError: 2403:0:(osc_request.c:3107:osc_enqueue_interpret()) cfs_fail_timeout id 40f sleeping for 10000ms [ 557.513418] LustreError: 2403:0:(osc_request.c:3107:osc_enqueue_interpret()) cfs_fail_timeout id 40f awake [ 561.560833] Lustre: DEBUG MARKER: == sanity test 214: hash-indexed directory test - bug 20133 ========================================================== 13:51:06 (1752688266) [ 584.584707] Lustre: DEBUG MARKER: == sanity test 215: lnet exists and has proper content - bugs 18102, 21079, 21517 ========================================================== 13:51:29 (1752688289) [ 588.299884] Lustre: DEBUG MARKER: == sanity test 216: check lockless direct write updates file size and kms correctly ========================================================== 13:51:33 (1752688293) [ 597.665543] Lustre: DEBUG MARKER: == sanity test 217: check lctl ping for hostnames with embedded hyphen ('-') ========================================================== 13:51:42 (1752688302) [ 602.137996] Lustre: DEBUG MARKER: == sanity test 218: parallel read and truncate should not deadlock ========================================================== 13:51:46 (1752688306) [ 602.981148] Lustre: DEBUG MARKER: creating a 10 Mb file [ 618.976376] Lustre: lustre-OST0000-osc-ffff89bba0294800: disconnect after 23s idle [ 618.978580] Lustre: Skipped 1 previous similar message [ 631.596218] Lustre: DEBUG MARKER: starting reads [ 632.607429] Lustre: DEBUG MARKER: truncating the file [ 633.535798] Lustre: DEBUG MARKER: killing dd [ 634.243671] Lustre: DEBUG MARKER: removing the temporary file [ 637.249994] Lustre: DEBUG MARKER: == sanity test 219: LU-394: Write partial won't cause uncontiguous pages vec at LND ========================================================== 13:52:22 (1752688342) [ 637.341413] Lustre: *** cfs_fail_loc=411, val=0*** [ 640.622818] Lustre: DEBUG MARKER: == sanity test 220: preallocated MDS objects still used if ENOSPC from OST ========================================================== 13:52:25 (1752688345) [ 657.591216] Lustre: DEBUG MARKER: == sanity test 221: make sure fault and truncate race to not cause OOM ========================================================== 13:52:42 (1752688362) [ 663.519338] Lustre: DEBUG MARKER: == sanity test 222a: AGL for ls should not trigger CLIO lock failure ========================================================== 13:52:48 (1752688368) [ 666.972775] Lustre: DEBUG MARKER: == sanity test 222b: AGL for rmdir should not trigger CLIO lock failure ========================================================== 13:52:51 (1752688371) [ 670.502461] Lustre: DEBUG MARKER: == sanity test 223: osc reenqueue if without AGL lock granted ================================================================================= 13:52:55 (1752688375) [ 674.100636] Lustre: DEBUG MARKER: == sanity test 224a: Don't panic on bulk IO failure ====== 13:52:58 (1752688378) [ 674.302559] Lustre: *** cfs_fail_loc=508, val=2147483648*** [ 674.306688] LustreError: 2393:0:(events.c:193:client_bulk_callback()) event type 1, status -5, desc ffff89bb87fbcc00 [ 674.313176] Lustre: 2403:0:(client.c:2453:ptlrpc_expire_one_request()) @@@ Request sent has failed due to network error: [sent 1752688379/real 1752688379] req@ffff89bb87e6c000 x1837826328909056/t0(0) o4->lustre-OST0001-osc-ffff89bba0294800@192.168.203.103@tcp:6/4 lens 488/448 e 0 to 1 dl 1752688395 ref 2 fl Rpc:eXQr/600/ffffffff rc 0/-1 job:'dd.0' uid:0 gid:0 projid:0 [ 674.324661] Lustre: lustre-OST0001-osc-ffff89bba0294800: Connection to lustre-OST0001 (at 192.168.203.103@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 674.342233] Lustre: lustre-OST0001-osc-ffff89bba0294800: Connection restored to 192.168.203.103@tcp (at 192.168.203.103@tcp) [ 678.544697] Lustre: DEBUG MARKER: == sanity test 224b: Don't panic on bulk IO failure ====== 13:53:03 (1752688383) [ 688.091604] Lustre: DEBUG MARKER: == sanity test 224c: Don't hang if one of md lost during large bulk RPC ========================================================== 13:53:12 (1752688392) [ 699.872576] Lustre: lustre-OST0001-osc-ffff89bba0294800: disconnect after 21s idle [ 701.344191] Lustre: 2402:0:(client.c:2453:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1752688401/real 1752688401] req@ffff89bb9803a680 x1837826328923264/t0(0) o4->lustre-OST0000-osc-ffff89bba0294800@192.168.203.103@tcp:6/4 lens 488/448 e 0 to 1 dl 1752688406 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'dd.0' uid:0 gid:0 projid:0 [ 701.356298] Lustre: lustre-OST0000-osc-ffff89bba0294800: Connection to lustre-OST0000 (at 192.168.203.103@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 701.377941] Lustre: lustre-OST0000-osc-ffff89bba0294800: Connection restored to 192.168.203.103@tcp (at 192.168.203.103@tcp) [ 710.386707] Lustre: DEBUG MARKER: == sanity test 224d: Don't corrupt data on bulk IO timeout ========================================================== 13:53:35 (1752688415) [ 733.152154] Lustre: 2401:0:(client.c:2453:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1752688418/real 1752688418] req@ffff89bb9803a680 x1837826328935168/t0(0) o3->lustre-OST0000-osc-ffff89bba0294800@192.168.203.103@tcp:6/4 lens 488/440 e 0 to 1 dl 1752688438 ref 2 fl Bulk:RXMQU/600/0 rc 0/0 job:'dd.0' uid:0 gid:0 projid:0 [ 733.164510] Lustre: lustre-OST0000-osc-ffff89bba0294800: Connection to lustre-OST0000 (at 192.168.203.103@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 733.171690] LustreError: 2401:0:(client.c:2322:ptlrpc_check_set()) @@@ bulk transfer failed 0/1048576/0 req@ffff89bb9803a680 x1837826328935168/t0(0) o3->lustre-OST0000-osc-ffff89bba0294800@192.168.203.103@tcp:6/4 lens 488/440 e 0 to 1 dl 1752688438 ref 2 fl Bulk:ReXMQU/600/0 rc 0/0 job:'dd.0' uid:0 gid:0 projid:0 [ 733.188048] Lustre: lustre-OST0000-osc-ffff89bba0294800: Connection restored to 192.168.203.103@tcp (at 192.168.203.103@tcp) [ 733.188653] LustreError: 2401:0:(osc_request.c:2446:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff89bb9803a680 x1837826328935168/t0(0) o3->lustre-OST0000-osc-ffff89bba0294800@192.168.203.103@tcp:6/4 lens 488/440 e 0 to 1 dl 1752688438 ref 2 fl Interpret:ReXMQU/600/0 rc -5/0 job:'dd.0' uid:0 gid:0 projid:0 [ 738.761102] Lustre: DEBUG MARKER: SKIP: sanity test_225a skipping excluded test 225a (base 225) [ 739.610949] Lustre: DEBUG MARKER: SKIP: sanity test_225b skipping excluded test 225b (base 225) [ 740.483786] Lustre: DEBUG MARKER: == sanity test 226a: call path2fid and fid2path on files of all type ========================================================== 13:54:05 (1752688445) [ 744.332637] Lustre: DEBUG MARKER: == sanity test 226b: call path2fid and fid2path on files of all type under remote dir ========================================================== 13:54:09 (1752688449) [ 747.831463] Lustre: DEBUG MARKER: == sanity test 226c: call path2fid and fid2path under remote dir with subdir mount ========================================================== 13:54:12 (1752688452) [ 748.204271] Lustre: Mounted lustre-client [ 748.302564] LustreError: 70435:0:(lov_obd.c:784:lov_cleanup()) lustre-clilov-ffff89bb860f0800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 748.310949] LustreError: 70435:0:(obd_class.h:479:obd_check_dev()) Device 12 not setup [ 748.346130] Lustre: Unmounted lustre-client [ 750.869344] LustreError: 70897:0:(lov_obd.c:784:lov_cleanup()) lustre-clilov-ffff89bb98651800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 750.875634] LustreError: 70897:0:(lov_obd.c:784:lov_cleanup()) Skipped 1 previous similar message [ 750.886136] LustreError: 70897:0:(obd_class.h:479:obd_check_dev()) Device 12 not setup [ 750.889326] LustreError: 70897:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 750.930680] Lustre: Unmounted lustre-client [ 751.744254] Lustre: DEBUG MARKER: == sanity test 226d: verify fid2path with -n and -fn option ========================================================== 13:54:16 (1752688456) [ 755.182897] Lustre: DEBUG MARKER: == sanity test 226e: Verify path2fid -0 option with newline and space ========================================================== 13:54:20 (1752688460) [ 758.546206] Lustre: DEBUG MARKER: == sanity test 227: running truncated executable does not cause OOM ========================================================== 13:54:23 (1752688463) [ 761.949270] Lustre: DEBUG MARKER: == sanity test 228a: try to reuse idle OI blocks ========= 13:54:26 (1752688466) [ 763.162204] Lustre: *** cfs_fail_loc=1002, val=0*** [ 784.352263] Lustre: lustre-OST0001-osc-ffff89bba0294800: disconnect after 20s idle [ 845.792193] Lustre: lustre-OST0001-osc-ffff89bba0294800: disconnect after 21s idle [ 876.457317] Lustre: DEBUG MARKER: == sanity test 228b: idle OI blocks can be reused after MDT restart ========================================================== 13:56:21 (1752688581) [ 877.514448] Lustre: *** cfs_fail_loc=1002, val=0*** [ 937.952144] Lustre: lustre-OST0001-osc-ffff89bba0294800: disconnect after 24s idle [ 943.076402] Lustre: lustre-MDT0000-mdc-ffff89bba0294800: Connection to lustre-MDT0000 (at 192.168.203.103@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 948.195430] LustreError: MGC192.168.203.103@tcp: Connection to MGS (at 192.168.203.103@tcp) was lost; in progress operations using this service will fail [ 948.203122] Lustre: Evicted from MGS (at 192.168.203.103@tcp) after server handle changed from 0xe47d86e6846fd86f to 0xe47d86e684870fca [ 948.208539] Lustre: MGC192.168.203.103@tcp: Connection restored to 192.168.203.103@tcp (at 192.168.203.103@tcp) [ 948.214963] LustreError: 2400:0:(mdc_request.c:660:mdc_replay_open()) @@@ cannot properly replay without open data req@ffff89bb87f2df80 x1837826328229632/t4294978968(4294978968) o101->lustre-MDT0000-mdc-ffff89bba0294800@192.168.203.103@tcp:12/10 lens 608/608 e 0 to 0 dl 1752688669 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'touch.0' uid:0 gid:0 projid:0 [ 971.231528] Lustre: DEBUG MARKER: == sanity test 228c: NOT shrink the last entry in OI index node to recycle idle leaf ========================================================== 13:57:56 (1752688676) [ 972.293160] Lustre: *** cfs_fail_loc=1002, val=0*** [ 1116.509130] Lustre: DEBUG MARKER: == sanity test 229: getstripe/stat/rm/attr changes work on released files ========================================================== 14:00:21 (1752688821) [ 1119.253690] Lustre: DEBUG MARKER: == sanity test 230a: Create remote directory and files under the remote directory ========================================================== 14:00:24 (1752688824) [ 1122.508707] Lustre: DEBUG MARKER: == sanity test 230b: migrate directory =================== 14:00:27 (1752688827) [ 1144.473850] Lustre: DEBUG MARKER: == sanity test 230c: check directory accessiblity if migration failed ========================================================== 14:00:49 (1752688849) [ 1151.201139] Lustre: DEBUG MARKER: SKIP: sanity test_230d skipping SLOW test 230d [ 1151.933778] Lustre: DEBUG MARKER: == sanity test 230e: migrate mulitple local link files === 14:00:56 (1752688856) [ 1155.243605] Lustre: DEBUG MARKER: == sanity test 230f: migrate mulitple remote link files == 14:01:00 (1752688860) [ 1159.051626] Lustre: DEBUG MARKER: == sanity test 230g: migrate dir to non-exist MDT ======== 14:01:03 (1752688863) [ 1161.829349] Lustre: DEBUG MARKER: == sanity test 230h: migrate .. and root ================= 14:01:06 (1752688866) [ 1164.679375] Lustre: DEBUG MARKER: == sanity test 230i: lfs migrate -m tolerates trailing slashes ========================================================== 14:01:09 (1752688869) [ 1167.455366] Lustre: DEBUG MARKER: == sanity test 230j: DoM file data not changed after dir migration ========================================================== 14:01:12 (1752688872) [ 1170.218536] Lustre: DEBUG MARKER: == sanity test 230k: file data not changed after dir migration ========================================================== 14:01:15 (1752688875) [ 1170.806675] Lustre: DEBUG MARKER: SKIP: sanity test_230k needs >= 4 MDTs [ 1171.514036] Lustre: DEBUG MARKER: == sanity test 230l: readdir between MDTs won't crash ==== 14:01:16 (1752688876) [ 1210.227744] Lustre: DEBUG MARKER: == sanity test 230m: xattrs not changed after dir migration ========================================================== 14:01:55 (1752688915) [ 1212.726109] bash (84251): drop_caches: 3 [ 1213.302678] bash (84251): drop_caches: 3 [ 1216.303439] Lustre: DEBUG MARKER: == sanity test 230n: Dir migration with mirrored file ==== 14:02:01 (1752688921) [ 1219.334759] Lustre: DEBUG MARKER: == sanity test 230o: dir split =========================== 14:02:04 (1752688924) [ 1234.258469] Lustre: DEBUG MARKER: == sanity test 230p: dir merge =========================== 14:02:19 (1752688939) [ 1245.765373] LustreError: 86725:0:(llite_lib.c:1872:ll_update_lsm_md()) lustre: [0x2000013a1:0x3498:0x0] dir layout mismatch: [ 1245.769110] LustreError: 86725:0:(lustre_lmv.h:160:lmv_stripe_object_dump()) dump LMV: magic=0xcd20cd0 refs=1 count=1 index=0 hash=crush:0x2000003 max_inherit=0 max_inherit_rr=0 version=2 migrate_offset=0 migrate_hash=invalid:0 pool= [ 1245.775453] LustreError: 86725:0:(lustre_lmv.h:167:lmv_stripe_object_dump()) stripe[0] [0x200001b70:0x7d:0x0] [ 1245.779098] LustreError: 86725:0:(lustre_lmv.h:160:lmv_stripe_object_dump()) dump LMV: magic=0xcd20cd0 refs=1 count=2 index=0 hash=crush:0x88000003 max_inherit=0 max_inherit_rr=0 version=2 migrate_offset=1 migrate_hash=crush:86000003 pool= [ 1245.786910] LustreError: 86725:0:(llite_lib.c:3770:ll_prep_inode()) lustre: new_inode - fatal error: rc = -22 [ 1256.807689] Lustre: DEBUG MARKER: == sanity test 230q: dir auto split ====================== 14:02:41 (1752688961) [ 1277.664104] Lustre: DEBUG MARKER: == sanity test 230r: migrate with too many local locks === 14:03:02 (1752688982) [ 1281.061456] Lustre: DEBUG MARKER: == sanity test 230s: lfs mkdir should return -EEXIST if target exists ========================================================== 14:03:05 (1752688985) [ 1285.681534] Lustre: DEBUG MARKER: == sanity test 230t: migrate directory with project ID set ========================================================== 14:03:10 (1752688990) [ 1288.904561] Lustre: DEBUG MARKER: == sanity test 230u: migrate directory by QOS ============ 14:03:13 (1752688993) [ 1289.444091] Lustre: DEBUG MARKER: SKIP: sanity test_230u needs >= 4 MDTs [ 1290.145734] Lustre: DEBUG MARKER: == sanity test 230v: subdir migrated to the MDT where its parent is located ========================================================== 14:03:15 (1752688995) [ 1290.756824] Lustre: DEBUG MARKER: SKIP: sanity test_230v needs >= 4 MDTs [ 1291.416417] Lustre: DEBUG MARKER: == sanity test 230w: non-recursive mode dir migration ==== 14:03:16 (1752688996) [ 1295.165405] Lustre: DEBUG MARKER: == sanity test 230x: dir migration check space =========== 14:03:20 (1752689000) [ 1321.594172] Lustre: DEBUG MARKER: == sanity test 230y: unlink dir with bad hash type ======= 14:03:46 (1752689026) [ 1329.269511] Lustre: DEBUG MARKER: == sanity test 230z: resume dir migration with bad hash type ========================================================== 14:03:54 (1752689034) [ 1350.200972] Lustre: DEBUG MARKER: == sanity test 231a: checking that reading/writing of BRW RPC size results in one RPC ========================================================== 14:04:15 (1752689055) [ 1354.485030] Lustre: DEBUG MARKER: == sanity test 231b: must not assert on fully utilized OST request buffer ========================================================== 14:04:19 (1752689059) [ 1373.153471] Lustre: lustre-OST0001-osc-ffff89bba0294800: disconnect after 21s idle [ 1373.155300] Lustre: Skipped 1 previous similar message [ 1378.121157] Lustre: DEBUG MARKER: == sanity test 232a: failed lock should not block umount ========================================================== 14:04:43 (1752689083) [ 1378.554761] LustreError: lustre-OST0000-osc-ffff89bba0294800: operation ldlm_enqueue to node 192.168.203.103@tcp failed: rc = -12 [ 1379.312802] LustreError: 95871:0:(lov_obd.c:784:lov_cleanup()) lustre-clilov-ffff89bba0294800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 1379.317379] LustreError: 95871:0:(lov_obd.c:784:lov_cleanup()) Skipped 1 previous similar message [ 1379.321292] LustreError: 95871:0:(obd_class.h:479:obd_check_dev()) Device 6 not setup [ 1379.324036] LustreError: 95871:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 1379.359208] Lustre: Unmounted lustre-client [ 1379.615460] Lustre: Mounted lustre-client [ 1379.617307] Lustre: Skipped 1 previous similar message [ 1384.932909] Lustre: lustre-OST0000-osc-ffff89bb84fa2000: Connection to lustre-OST0000 (at 192.168.203.103@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1385.862532] Lustre: lustre-OST0000-osc-ffff89bb84fa2000: Connection restored to 192.168.203.103@tcp (at 192.168.203.103@tcp) [ 1385.866360] Lustre: Skipped 1 previous similar message [ 1390.066904] Lustre: DEBUG MARKER: == sanity test 232b: failed data version lock should not block umount ========================================================== 14:04:54 (1752689094) [ 1391.400496] LustreError: 96780:0:(lov_obd.c:784:lov_cleanup()) lustre-clilov-ffff89bb84fa2000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 1391.406056] LustreError: 96780:0:(lov_obd.c:784:lov_cleanup()) Skipped 1 previous similar message [ 1391.412382] LustreError: 96780:0:(obd_class.h:479:obd_check_dev()) Device 6 not setup [ 1391.415127] LustreError: 96780:0:(obd_class.h:479:obd_check_dev()) Skipped 9 previous similar messages [ 1391.442217] Lustre: Unmounted lustre-client [ 1391.629956] Lustre: Mounted lustre-client [ 1401.960232] Lustre: DEBUG MARKER: == sanity test 233a: checking that OBF of the FS root succeeds ========================================================== 14:05:06 (1752689106) [ 1404.882607] Lustre: DEBUG MARKER: == sanity test 233b: checking that OBF of the FS .lustre succeeds ========================================================== 14:05:09 (1752689109) [ 1407.856738] Lustre: DEBUG MARKER: == sanity test 234: xattr cache should not crash on ENOMEM ========================================================== 14:05:12 (1752689112) [ 1408.024557] Lustre: *** cfs_fail_loc=1405, val=0*** [ 1410.819373] Lustre: DEBUG MARKER: == sanity test 235: LU-1715: flock deadlock detection does not work properly ========================================================== 14:05:15 (1752689115) [ 1415.411924] Lustre: DEBUG MARKER: == sanity test 236: Layout swap on open unlinked file ==== 14:05:20 (1752689120) [ 1418.501731] Lustre: DEBUG MARKER: == sanity test 238: Verify linkea consistency ============ 14:05:23 (1752689123) [ 1421.465958] Lustre: DEBUG MARKER: == sanity test 239A: osp_sync test ======================= 14:05:26 (1752689126) [ 1456.737801] Lustre: DEBUG MARKER: == sanity test 239a: process invalid osp sync record correctly ========================================================== 14:06:01 (1752689161) [ 1464.949981] Lustre: DEBUG MARKER: == sanity test 239b: process osp sync record with ENOMEM error correctly ========================================================== 14:06:09 (1752689169) [ 1470.845411] Lustre: DEBUG MARKER: == sanity test 240: race between ldlm enqueue and the connection RPC (no ASSERT) ========================================================== 14:06:15 (1752689175) [ 1471.364597] LustreError: 104058:0:(lov_obd.c:784:lov_cleanup()) lustre-clilov-ffff89bb8625e000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 1471.368261] LustreError: 104058:0:(lov_obd.c:784:lov_cleanup()) Skipped 1 previous similar message [ 1471.371415] LustreError: 104058:0:(obd_class.h:479:obd_check_dev()) Device 6 not setup [ 1471.374515] LustreError: 104058:0:(obd_class.h:479:obd_check_dev()) Skipped 9 previous similar messages [ 1471.402148] Lustre: Unmounted lustre-client [ 1471.838067] Lustre: Mounted lustre-client [ 1477.510929] Lustre: DEBUG MARKER: == sanity test 241a: bio vs dio ========================== 14:06:22 (1752689182) [ 1518.036442] Lustre: DEBUG MARKER: == sanity test 241b: dio vs dio ========================== 14:07:02 (1752689222) [ 1531.309199] Lustre: DEBUG MARKER: == sanity test 242: mdt_readpage failure should not cause directory unreadable ========================================================== 14:07:16 (1752689236) [ 1531.788696] LustreError: lustre-MDT0000-mdc-ffff89bb87d66000: operation mds_readpage to node 192.168.203.103@tcp failed: rc = -12 [ 1534.416263] Lustre: DEBUG MARKER: == sanity test 243: various group lock tests ============= 14:07:19 (1752689239) [ 1538.024600] Lustre: 115507:0:(file.c:3144:ll_get_grouplock()) lustre: group lock already exists with gid 97486 on [0x200001b73:0x5:0x0]: rc = -22 [ 1538.030178] Lustre: 115507:0:(file.c:3219:ll_put_grouplock()) lustre: no group lock held on [0x200001b73:0x5:0x0]: rc = -22 [ 1538.034879] Lustre: 115507:0:(file.c:3126:ll_get_grouplock()) lustre: group id for group lock on [0x200001b73:0x5:0x0] is 0: rc = -22 [ 1538.042445] Lustre: 115507:0:(file.c:3229:ll_put_grouplock()) lustre: group lock 4294967286 doesn't match current id 3543 on [0x200001b73:0x5:0x0]: rc = -22 [ 1629.694405] Lustre: 115507:0:(file.c:3219:ll_put_grouplock()) lustre: no group lock held on [0x200001b73:0xc:0x0]: rc = -22 [ 1629.707161] Lustre: 115507:0:(file.c:3126:ll_get_grouplock()) lustre: group id for group lock on [0x200001b73:0xc:0x0] is 0: rc = -22 [ 1632.287136] Lustre: DEBUG MARKER: == sanity test 244a: sendfile with group lock tests ====== 14:08:57 (1752689337) [ 1668.491352] Lustre: DEBUG MARKER: == sanity test 244b: multi-threaded write with group lock ========================================================== 14:09:33 (1752689373) [ 1671.358467] Lustre: DEBUG MARKER: == sanity test 245a: check mdc connection flag/data: multiple modify RPCs ========================================================== 14:09:36 (1752689376) [ 1673.758445] Lustre: DEBUG MARKER: == sanity test 245b: check osp connection flag/data: multiple modify RPCs ========================================================== 14:09:38 (1752689378) [ 1677.249242] Lustre: DEBUG MARKER: == sanity test 247a: mount subdir as fileset ============= 14:09:42 (1752689382) [ 1677.452140] Lustre: Mounted lustre-client [ 1677.525808] LustreError: 118617:0:(lov_obd.c:784:lov_cleanup()) lustre-clilov-ffff89bba0c4c000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 1677.531021] LustreError: 118617:0:(lov_obd.c:784:lov_cleanup()) Skipped 1 previous similar message [ 1677.538259] LustreError: 118617:0:(obd_class.h:479:obd_check_dev()) Device 12 not setup [ 1677.540477] LustreError: 118617:0:(obd_class.h:479:obd_check_dev()) Skipped 9 previous similar messages [ 1677.579242] Lustre: Unmounted lustre-client [ 1680.706800] Lustre: DEBUG MARKER: == sanity test 247b: mount subdir that dose not exist ==== 14:09:45 (1752689385) [ 1680.894141] LustreError: 119262:0:(llite_lib.c:690:client_common_fill_super()) cannot mds_connect: rc = -2 [ 1680.927420] LustreError: 119262:0:(super25.c:181:lustre_fill_super()) llite: Unable to mount : rc = -2 [ 1683.444246] Lustre: DEBUG MARKER: == sanity test 247c: running fid2path outside subdirectory root ========================================================== 14:09:48 (1752689388) [ 1683.669755] Lustre: Mounted lustre-client [ 1683.671395] Lustre: Skipped 1 previous similar message [ 1683.735716] LustreError: 119894:0:(lov_obd.c:784:lov_cleanup()) lustre-clilov-ffff89bb84a60800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 1683.738833] LustreError: 119894:0:(lov_obd.c:784:lov_cleanup()) Skipped 3 previous similar messages [ 1683.744985] LustreError: 119894:0:(obd_class.h:479:obd_check_dev()) Device 12 not setup [ 1683.746958] LustreError: 119894:0:(obd_class.h:479:obd_check_dev()) Skipped 23 previous similar messages [ 1683.773187] Lustre: Unmounted lustre-client [ 1683.774989] Lustre: Skipped 2 previous similar messages [ 1686.759772] Lustre: DEBUG MARKER: == sanity test 247d: running fid2path inside subdirectory root ========================================================== 14:09:51 (1752689391) [ 1690.135494] Lustre: DEBUG MARKER: == sanity test 247e: mount .. as fileset ================= 14:09:55 (1752689395) [ 1690.530490] LustreError: lustre-MDT0000-mdc-ffff89bb90df3000: operation mds_get_root to node 192.168.203.103@tcp failed: rc = -22 [ 1690.534600] LustreError: 121251:0:(llite_lib.c:690:client_common_fill_super()) cannot mds_connect: rc = -22 [ 1690.566318] LustreError: 121251:0:(super25.c:181:lustre_fill_super()) llite: Unable to mount : rc = -22 [ 1693.108332] Lustre: DEBUG MARKER: == sanity test 247f: mount striped or remote directory as fileset ========================================================== 14:09:58 (1752689398) [ 1693.921662] Lustre: Mounted lustre-client [ 1693.923378] Lustre: Skipped 4 previous similar messages [ 1694.000847] LustreError: 121962:0:(lov_obd.c:784:lov_cleanup()) lustre-clilov-ffff89bb85c0c800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 1694.004081] LustreError: 121962:0:(lov_obd.c:784:lov_cleanup()) Skipped 9 previous similar messages [ 1694.008604] LustreError: 121962:0:(obd_class.h:479:obd_check_dev()) Device 12 not setup [ 1694.010513] LustreError: 121962:0:(obd_class.h:479:obd_check_dev()) Skipped 47 previous similar messages [ 1694.035733] Lustre: Unmounted lustre-client [ 1694.037191] Lustre: Skipped 5 previous similar messages [ 1699.706496] Lustre: DEBUG MARKER: == sanity test 247g: striped directory submount revalidate ROOT from cache ========================================================== 14:10:04 (1752689404) [ 1703.516324] Lustre: DEBUG MARKER: == sanity test 247h: remote directory submount revalidate ROOT from cache ========================================================== 14:10:08 (1752689408) [ 1709.098156] Lustre: DEBUG MARKER: == sanity test 248a: fast read verification ============== 14:10:14 (1752689414) [ 1782.859391] Lustre: DEBUG MARKER: == sanity test 248b: test short_io read and write for both small and large sizes ========================================================== 14:11:27 (1752689487) [ 1798.750173] Lustre: DEBUG MARKER: == sanity test 248c: verify whole file read behavior ===== 14:11:43 (1752689503) [ 1809.540810] Lustre: DEBUG MARKER: == sanity test 249: Write above 2T file size ============= 14:11:54 (1752689514) [ 1812.062854] Lustre: DEBUG MARKER: == sanity test 250: Write above 16T limit ================ 14:11:57 (1752689517) [ 1814.557227] Lustre: DEBUG MARKER: == sanity test 251a: Handling short read and write correctly ========================================================== 14:11:59 (1752689519) [ 1815.266769] Lustre: *** cfs_fail_loc=1407, val=0*** [ 1817.921694] Lustre: DEBUG MARKER: == sanity test 251b: short read restore offset correctly ========================================================== 14:12:02 (1752689522) [ 1817.998904] LustreError: 128329:0:(file.c:2465:do_file_read_iter()) cfs_fail_timeout id 1431 sleeping for 5000ms [ 1823.096122] LustreError: 128329:0:(file.c:2465:do_file_read_iter()) cfs_fail_timeout id 1431 awake [ 1825.683166] Lustre: DEBUG MARKER: == sanity test 252: check lr_reader tool ================= 14:12:10 (1752689530) [ 1829.910831] Lustre: DEBUG MARKER: == sanity test 253: Check object allocation limit ======== 14:12:14 (1752689534) [ 1901.030728] Lustre: DEBUG MARKER: == sanity test 254: Check changelog size ================= 14:13:25 (1752689605) [ 1908.605166] Lustre: DEBUG MARKER: SKIP: sanity test_255a skipping excluded test 255a (base 255) [ 1909.258329] Lustre: DEBUG MARKER: SKIP: sanity test_255b skipping excluded test 255b (base 255) [ 1909.864685] Lustre: DEBUG MARKER: SKIP: sanity test_255c skipping excluded test 255c (base 255) [ 1910.442888] Lustre: DEBUG MARKER: SKIP: sanity test_256 skipping excluded test 256 [ 1911.088744] Lustre: DEBUG MARKER: == sanity test 257: xattr locks are not lost ============= 14:13:36 (1752689616) [ 1911.763942] LustreError: lustre-MDT0001-mdc-ffff89bb87d66000: operation ldlm_enqueue to node 192.168.203.103@tcp failed: rc = -14 [ 1915.363127] Lustre: lustre-MDT0001-mdc-ffff89bb87d66000: Connection to lustre-MDT0001 (at 192.168.203.103@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1915.368188] Lustre: Skipped 1 previous similar message [ 1926.970467] Lustre: lustre-MDT0001-mdc-ffff89bb87d66000: Connection restored to 192.168.203.103@tcp (at 192.168.203.103@tcp) [ 1926.973328] Lustre: Skipped 1 previous similar message [ 1932.365614] Lustre: DEBUG MARKER: == sanity test 258a: verify i_mutex security behavior when suid attributes is set ========================================================== 14:13:57 (1752689637) [ 1934.875748] Lustre: DEBUG MARKER: == sanity test 258b: verify i_mutex security behavior ==== 14:13:59 (1752689639) [ 1937.420984] Lustre: DEBUG MARKER: == sanity test 259: crash at delayed truncate ============ 14:14:02 (1752689642) [ 1962.696399] Lustre: DEBUG MARKER: == sanity test 260: Check mdc_close fail ================= 14:14:27 (1752689667) [ 1962.739652] Lustre: *** cfs_fail_loc=806, val=0*** [ 1962.741319] Lustre: 136129:0:(mdc_request.c:911:mdc_close()) lustre-MDT0000-mdc-ffff89bb87d66000: close of FID [0x200001b73:0x4b:0x0] failed, file reference will be dropped when this client unmounts or is evicted [ 1962.746311] LustreError: 136129:0:(file.c:248:ll_close_inode_openhandle()) lustre-clilmv-ffff89bb87d66000: inode [0x200001b73:0x4b:0x0] mdc close failed: rc = -12 [ 1965.283335] Lustre: DEBUG MARKER: == sanity test 270a: DoM: basic functionality tests ====== 14:14:30 (1752689670) [ 1970.964424] Lustre: DEBUG MARKER: == sanity test 270b: DoM: maximum size overflow checks for DoM-only file ========================================================== 14:14:35 (1752689675) [ 1973.889246] Lustre: DEBUG MARKER: == sanity test 270c: DoM: DoM EA inheritance tests ======= 14:14:38 (1752689678) [ 1976.692619] Lustre: DEBUG MARKER: == sanity test 270d: DoM: change striping from DoM to RAID0 ========================================================== 14:14:41 (1752689681) [ 1979.514926] Lustre: DEBUG MARKER: == sanity test 270e: DoM: lfs find with DoM files test === 14:14:44 (1752689684) [ 1982.709786] Lustre: DEBUG MARKER: == sanity test 270f: DoM: maximum DoM stripe size checks ========================================================== 14:14:47 (1752689687) [ 1989.421909] Lustre: DEBUG MARKER: == sanity test 270g: DoM: default DoM stripe size depends on free space ========================================================== 14:14:54 (1752689694) [ 1999.025365] Lustre: DEBUG MARKER: == sanity test 270h: DoM: DoM stripe removal when disabled on server ========================================================== 14:15:03 (1752689703) [ 2002.836589] Lustre: DEBUG MARKER: == sanity test 270i: DoM: setting invalid DoM striping should fail ========================================================== 14:15:07 (1752689707) [ 2005.598309] Lustre: DEBUG MARKER: == sanity test 270j: DoM migration: DOM file to the OST-striped file (plain) ========================================================== 14:15:10 (1752689710) [ 2008.896560] Lustre: DEBUG MARKER: == sanity test 271a: DoM: data is cached for read after write ========================================================== 14:15:13 (1752689713) [ 2011.527149] Lustre: DEBUG MARKER: == sanity test 271b: DoM: no glimpse RPC for stat (DoM only file) ========================================================== 14:15:16 (1752689716) [ 2013.933766] Lustre: DEBUG MARKER: == sanity test 271ba: DoM: no glimpse RPC for stat (combined file) ========================================================== 14:15:18 (1752689718) [ 2016.572913] Lustre: DEBUG MARKER: == sanity test 271c: DoM: IO lock at open saves enqueue RPCs ========================================================== 14:15:21 (1752689721) [ 2053.293083] Lustre: DEBUG MARKER: == sanity test 271d: DoM: read on open (1K file in reply buffer) ========================================================== 14:15:58 (1752689758) [ 2056.508353] Lustre: DEBUG MARKER: == sanity test 271f: DoM: read on open (200K file and read tail) ========================================================== 14:16:01 (1752689761) [ 2059.552731] Lustre: DEBUG MARKER: == sanity test 271g: Discard DoM data vs client flush race ========================================================== 14:16:04 (1752689764) [ 2060.661695] Lustre: *** cfs_fail_loc=314, val=0*** [ 2063.189094] Lustre: DEBUG MARKER: == sanity test 272a: DoM migration: new layout with the same DOM component ========================================================== 14:16:08 (1752689768) [ 2066.308474] Lustre: DEBUG MARKER: == sanity test 272b: DoM migration: DOM file to the OST-striped file (plain) ========================================================== 14:16:11 (1752689771) [ 2070.667992] Lustre: DEBUG MARKER: == sanity test 272c: DoM migration: DOM file to the OST-striped file (composite) ========================================================== 14:16:15 (1752689775) [ 2074.555240] Lustre: DEBUG MARKER: == sanity test 272d: DoM mirroring: OST-striped mirror to DOM file ========================================================== 14:16:19 (1752689779) [ 2075.645285] LustreError: 149836:0:(file.c:248:ll_close_inode_openhandle()) lustre-clilmv-ffff89bb87d66000: inode [0x240000409:0x802:0x0] mdc close failed: rc = -22 [ 2078.710240] Lustre: DEBUG MARKER: == sanity test 272e: DoM mirroring: DOM mirror to the OST-striped file ========================================================== 14:16:23 (1752689783) [ 2080.539423] LustreError: 150452:0:(file.c:248:ll_close_inode_openhandle()) lustre-clilmv-ffff89bb87d66000: inode [0x200001b73:0x96:0x0] mdc close failed: rc = -22 [ 2083.202767] Lustre: DEBUG MARKER: == sanity test 272f: DoM migration: OST-striped file to DOM file ========================================================== 14:16:28 (1752689788) [ 2083.908341] LustreError: 151055:0:(file.c:248:ll_close_inode_openhandle()) lustre-clilmv-ffff89bb87d66000: inode [0x240000409:0x806:0x0] mdc close failed: rc = -22 [ 2086.669558] Lustre: DEBUG MARKER: == sanity test 273a: DoM: layout swapping should fail with DOM ========================================================== 14:16:31 (1752689791) [ 2089.645266] Lustre: DEBUG MARKER: == sanity test 273b: DoM: race writeback and object destroy ========================================================== 14:16:34 (1752689794) [ 2095.381371] Lustre: DEBUG MARKER: == sanity test 273c: race writeback and object destroy === 14:16:40 (1752689800) [ 2098.796365] Lustre: DEBUG MARKER: == sanity test 275: Read on a canceled duplicate lock ==== 14:16:43 (1752689803) [ 2099.310468] LustreError: 116153:0:(ldlm_lockd.c:2902:ldlm_bl_thread_blwi()) cfs_fail_timeout id 31f sleeping for 4000ms [ 2101.392372] LustreError: 116153:0:(ldlm_lockd.c:2902:ldlm_bl_thread_blwi()) cfs_fail_timeout interrupted [ 2103.316817] Lustre: DEBUG MARKER: == sanity test 276: Race between mount and obd_statfs ==== 14:16:48 (1752689808) [ 2107.876711] Lustre: lustre-OST0000-osc-ffff89bb87d66000: Connection to lustre-OST0000 (at 192.168.203.103@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 2107.881105] Lustre: Skipped 1 previous similar message [ 2184.683704] Lustre: lustre-OST0000-osc-ffff89bb87d66000: Connection restored to 192.168.203.103@tcp (at 192.168.203.103@tcp) [ 2184.686873] Lustre: Skipped 9 previous similar messages [ 2246.117865] Lustre: lustre-OST0000-osc-ffff89bb87d66000: Connection to lustre-OST0000 (at 192.168.203.103@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 2246.122474] Lustre: Skipped 18 previous similar messages [ 2251.912282] Lustre: DEBUG MARKER: == sanity test 277: Direct IO shall drop page cache ====== 14:19:16 (1752689956) [ 2254.598173] Lustre: DEBUG MARKER: == sanity test 278: Race starting MDS between MDTs stop/start ========================================================== 14:19:19 (1752689959) [ 2261.474734] LustreError: MGC192.168.203.103@tcp: Connection to MGS (at 192.168.203.103@tcp) was lost; in progress operations using this service will fail [ 2261.483229] Lustre: Evicted from MGS (at 192.168.203.103@tcp) after server handle changed from 0xe47d86e684aac171 to 0xe47d86e684b598d5 [ 2262.713387] LustreError: 2400:0:(client.c:3395:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff89bba90b4e00 x1837826383006976/t17179898385(17179898385) o101->lustre-MDT0000-mdc-ffff89bb87d66000@192.168.203.103@tcp:12/10 lens 584/608 e 0 to 0 dl 1752689984 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'touch.0' uid:0 gid:0 projid:0 [ 2262.720285] LustreError: 2400:0:(client.c:3395:ptlrpc_replay_interpret()) Skipped 2 previous similar messages [ 2276.718244] Lustre: DEBUG MARKER: == sanity test 280: Race between MGS umount and client llog processing ========================================================== 14:19:41 (1752689981) [ 2277.169662] LustreError: 160975:0:(lov_obd.c:784:lov_cleanup()) lustre-clilov-ffff89bb87d66000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 2277.175107] LustreError: 160975:0:(lov_obd.c:784:lov_cleanup()) Skipped 31 previous similar messages [ 2277.178239] LustreError: 160975:0:(obd_class.h:479:obd_check_dev()) Device 6 not setup [ 2277.180254] LustreError: 160975:0:(obd_class.h:479:obd_check_dev()) Skipped 127 previous similar messages [ 2277.202196] Lustre: Unmounted lustre-client [ 2277.204061] Lustre: Skipped 15 previous similar messages [ 2288.099120] LustreError: MGC192.168.203.103@tcp: Connection to MGS (at 192.168.203.103@tcp) was lost; in progress operations using this service will fail [ 2288.108918] LustreError: MGC192.168.203.103@tcp: Confguration from log lustre-client failed from MGS -5. Communication error between node & MGS, a bad configuration, or other errors. See syslog for more info [ 2288.110994] Lustre: Evicted from MGS (at 192.168.203.103@tcp) after server handle changed from 0xe47d86e684b59d74 to 0xe47d86e684b59f1f [ 2288.152382] LustreError: 160998:0:(super25.c:181:lustre_fill_super()) llite: Unable to mount : rc = -5 [ 2302.672994] Lustre: Mounted lustre-client [ 2302.675403] Lustre: Skipped 15 previous similar messages [ 2305.354822] Lustre: DEBUG MARKER: == sanity test 300a: basic striped dir sanity test ======= 14:20:10 (1752690010) [ 2308.713415] Lustre: DEBUG MARKER: == sanity test 300b: check ctime/mtime for striped dir === 14:20:13 (1752690013) [ 2332.397351] Lustre: DEBUG MARKER: == sanity test 300c: chown [ 2392.443881] Lustre: DEBUG MARKER: == sanity test 300d: check default stripe under striped directory ========================================================== 14:21:37 (1752690097) [ 2396.302451] Lustre: DEBUG MARKER: == sanity test 300e: check rename under striped directory ========================================================== 14:21:41 (1752690101) [ 2399.500094] Lustre: DEBUG MARKER: == sanity test 300f: check rename cross striped directory ========================================================== 14:21:44 (1752690104) [ 2402.297159] Lustre: DEBUG MARKER: == sanity test 300g: check default striped directory for normal directory ========================================================== 14:21:47 (1752690107) [ 2407.254823] Lustre: DEBUG MARKER: == sanity test 300h: check default striped directory for striped directory ========================================================== 14:21:52 (1752690112) [ 2412.894760] Lustre: DEBUG MARKER: == sanity test 300i: client handle unknown hash type striped directory ========================================================== 14:21:57 (1752690117) [ 2413.598501] LustreError: 167059:0:(lov_obd.c:784:lov_cleanup()) lustre-clilov-ffff89bba01ec800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 2413.603916] LustreError: 167059:0:(lov_obd.c:784:lov_cleanup()) Skipped 1 previous similar message [ 2413.610728] LustreError: 167059:0:(obd_class.h:479:obd_check_dev()) Device 6 not setup [ 2413.614091] LustreError: 167059:0:(obd_class.h:479:obd_check_dev()) Skipped 19 previous similar messages [ 2413.649113] Lustre: Unmounted lustre-client [ 2413.650279] Lustre: Skipped 1 previous similar message [ 2413.807154] Lustre: Mounted lustre-client [ 2414.322692] Lustre: *** cfs_fail_loc=1901, val=99*** [ 2414.351225] Lustre: *** cfs_fail_loc=1901, val=99*** [ 2448.223642] Lustre: DEBUG MARKER: == sanity test 300j: test large update record ============ 14:22:33 (1752690153) [ 2450.861949] Lustre: DEBUG MARKER: == sanity test 300k: test large striped directory ======== 14:22:35 (1752690155) [ 2453.686638] Lustre: DEBUG MARKER: == sanity test 300l: non-root user to create dir under striped dir with stale layout ========================================================== 14:22:38 (1752690158) [ 2457.551446] Lustre: DEBUG MARKER: == sanity test 300m: setstriped directory on single MDT FS ========================================================== 14:22:42 (1752690162) [ 2458.396736] Lustre: DEBUG MARKER: SKIP: sanity test_300m Only for single MDT [ 2459.320844] Lustre: DEBUG MARKER: == sanity test 300n: non-root user to create dir under striped dir with default EA ========================================================== 14:22:44 (1752690164) [ 2465.854448] Lustre: DEBUG MARKER: SKIP: sanity test_300o skipping SLOW test 300o [ 2466.744697] Lustre: DEBUG MARKER: == sanity test 300p: create striped directory without space ========================================================== 14:22:51 (1752690171) [ 2470.506018] Lustre: DEBUG MARKER: == sanity test 300q: create remote directory under orphan directory ========================================================== 14:22:55 (1752690175) [ 2473.368926] Lustre: DEBUG MARKER: == sanity test 300r: test -1 striped directory =========== 14:22:58 (1752690178) [ 2476.439552] Lustre: DEBUG MARKER: == sanity test 300s: test lfs mkdir -c without -i ======== 14:23:01 (1752690181) [ 2480.034171] Lustre: DEBUG MARKER: == sanity test 300t: test max_mdt_stripecount ============ 14:23:04 (1752690184) [ 2485.289174] Lustre: DEBUG MARKER: == sanity test 300ua: basic overstriped dir sanity test == 14:23:10 (1752690190) [ 2489.366825] Lustre: DEBUG MARKER: == sanity test 300ub: test MDT overstriping interface [ 2492.643242] Lustre: DEBUG MARKER: == sanity test 300uc: test MDT overstriping as default [ 2495.132607] Lustre: DEBUG MARKER: == sanity test 300ud: dir split ========================== 14:23:20 (1752690200) [ 2580.721829] Lustre: DEBUG MARKER: == sanity test 300ue: dir merge ========================== 14:24:45 (1752690285) [ 2639.993442] Lustre: DEBUG MARKER: == sanity test 300uf: migrate with too many local locks == 14:25:44 (1752690344) [ 2640.054893] Lustre: DEBUG MARKER: touch/create [ 2640.229150] Lustre: DEBUG MARKER: hardlinks [ 2640.484990] Lustre: DEBUG MARKER: cancel lru [ 2640.553660] Lustre: DEBUG MARKER: migrate [ 2644.338642] Lustre: DEBUG MARKER: == sanity test 300ug: migrate overstriped dirs =========== 14:25:49 (1752690349) [ 2648.415685] Lustre: DEBUG MARKER: == sanity test 300uh: overstripe tunable max_stripes_per_mdt ========================================================== 14:25:53 (1752690353) [ 2652.231291] Lustre: DEBUG MARKER: == sanity test 300ui: overstripe is not supported on one MDT system ========================================================== 14:25:57 (1752690357) [ 2652.797816] Lustre: DEBUG MARKER: SKIP: sanity test_300ui 1 MDT only [ 2653.365067] Lustre: DEBUG MARKER: == sanity test 300uj: overstriped dir with -C -N sanity test ========================================================== 14:25:58 (1752690358) [ 2656.018314] Lustre: DEBUG MARKER: == sanity test 310a: open unlink remote file ============= 14:26:01 (1752690361) [ 2658.818286] Lustre: DEBUG MARKER: == sanity test 310b: unlink remote file with multiple links while open ========================================================== 14:26:03 (1752690363) [ 2661.497897] Lustre: DEBUG MARKER: == sanity test 310c: open-unlink remote file with multiple links ========================================================== 14:26:06 (1752690366) [ 2662.039294] Lustre: DEBUG MARKER: SKIP: sanity test_310c needs >= 4 MDTs [ 2662.597820] Lustre: DEBUG MARKER: == sanity test 311: disable OSP precreate, and unlink should destroy objs ========================================================== 14:26:07 (1752690367) [ 2679.558912] Lustre: DEBUG MARKER: == sanity test 312: make sure ZFS adjusts its block size by write pattern ========================================================== 14:26:24 (1752690384) [ 2680.104909] Lustre: DEBUG MARKER: SKIP: sanity test_312 the test only applies to zfs [ 2680.669409] Lustre: DEBUG MARKER: == sanity test 313: io should fail after last_rcvd update fail ========================================================== 14:26:25 (1752690385) [ 2683.630654] Lustre: DEBUG MARKER: == sanity test 314: OSP shouldn't fail after last_rcvd update failure ========================================================== 14:26:28 (1752690388) [ 2694.206730] Lustre: DEBUG MARKER: == sanity test 315: read should be accounted ============= 14:26:39 (1752690399) [ 2700.511413] Lustre: DEBUG MARKER: == sanity test 316: lfs migrate of file with large_xattr enabled ========================================================== 14:26:45 (1752690405) [ 2703.606850] Lustre: DEBUG MARKER: == sanity test 317: Verify blocks get correctly update after truncate ========================================================== 14:26:48 (1752690408) [ 2706.658189] Lustre: DEBUG MARKER: == sanity test 318: Verify async readahead tunables ====== 14:26:51 (1752690411) [ 2706.755491] LustreError: 189061:0:(lproc_llite.c:1814:read_ahead_async_file_threshold_mb_store()) lustre: can't set read_ahead_async_file_threshold_mb=65 > max_read_readahead_per_file_mb=64 [ 2708.887320] Lustre: DEBUG MARKER: == sanity test 319: lost lease lock on migrate error ===== 14:26:53 (1752690413) [ 2709.048881] LustreError: 189644:0:(ldlm_request.c:1659:ldlm_cli_cancel()) cfs_fail_timeout id 32c sleeping for 5000ms [ 2714.144227] LustreError: 189644:0:(ldlm_request.c:1659:ldlm_cli_cancel()) cfs_fail_timeout id 32c awake [ 2716.646145] Lustre: DEBUG MARKER: == sanity test 350: force NID mismatch path to be exercised ========================================================== 14:27:01 (1752690421) [ 2766.261784] Lustre: DEBUG MARKER: == sanity test 360: ldiskfs unlink in a separate thread == 14:27:51 (1752690471) [ 2783.078811] Lustre: DEBUG MARKER: == sanity test 398a: direct IO should cancel lock otherwise lockless ========================================================== 14:28:07 (1752690487) [ 2786.730772] Lustre: DEBUG MARKER: == sanity test 398b: DIO and buffer IO race ============== 14:28:11 (1752690491) [ 2929.432981] Lustre: DEBUG MARKER: == sanity test 398c: run fio to test AIO ================= 14:30:34 (1752690634) [ 2953.554225] Lustre: DEBUG MARKER: == sanity test 398d: run aiocp to verify block size > stripe size ========================================================== 14:30:58 (1752690658) [ 2970.797885] Lustre: DEBUG MARKER: == sanity test 398e: O_Direct open cleared by fcntl doesn't cause hang ========================================================== 14:31:15 (1752690675) [ 2972.987802] Lustre: DEBUG MARKER: == sanity test 398f: verify aio handles ll_direct_rw_pages errors correctly ========================================================== 14:31:18 (1752690678) [ 2979.321820] Lustre: DEBUG MARKER: == sanity test 398g: verify parallel dio async RPC submission ========================================================== 14:31:24 (1752690684) [ 3002.667539] Lustre: DEBUG MARKER: == sanity test 398h: verify correctness of read [ 3018.828662] Lustre: DEBUG MARKER: == sanity test 398i: verify parallel dio handles ll_direct_rw_pages errors correctly ========================================================== 14:32:03 (1752690723) [ 3020.796669] Lustre: *** cfs_fail_loc=1418, val=0*** [ 3023.244085] Lustre: DEBUG MARKER: == sanity test 398j: test parallel dio where stripe size > rpc_size ========================================================== 14:32:08 (1752690728) [ 3036.278581] Lustre: DEBUG MARKER: == sanity test 398k: test enospc on first stripe ========= 14:32:21 (1752690741) [ 3049.516904] Lustre: DEBUG MARKER: SKIP: sanity test_398k 7204844 > 600000 skipping out-of-space test on OST0 [ 3050.378801] Lustre: DEBUG MARKER: == sanity test 398l: test enospc on intermediate stripe/RPC ========================================================== 14:32:35 (1752690755) [ 3056.017436] Lustre: DEBUG MARKER: SKIP: sanity test_398l 7188076 > 600000 skipping out-of-space test on OST0 [ 3071.534909] Lustre: DEBUG MARKER: == sanity test 398m: test RPC failures with parallel dio ========================================================== 14:32:56 (1752690776) [ 3072.021250] LustreError: lustre-OST0000-osc-ffff89bb84fa0800: operation ost_write to node 192.168.203.103@tcp failed: rc = -5 [ 3072.026081] LustreError: 2402:0:(osc_request.c:2446:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff89bb90245880 x1837826407498368/t0(0) o4->lustre-OST0000-osc-ffff89bb84fa0800@192.168.203.103@tcp:6/4 lens 488/224 e 0 to 0 dl 1752690793 ref 2 fl Interpret:ReMQU/600/0 rc -5/-5 job:'dd.0' uid:0 gid:0 projid:0 [ 3073.186366] LustreError: lustre-OST0000-osc-ffff89bb84fa0800: operation ost_write to node 192.168.203.103@tcp failed: rc = -5 [ 3073.188779] LustreError: Skipped 3 previous similar messages [ 3073.190299] LustreError: 2402:0:(osc_request.c:2446:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff89bb90245c00 x1837826407498752/t0(0) o4->lustre-OST0000-osc-ffff89bb84fa0800@192.168.203.103@tcp:6/4 lens 488/224 e 0 to 0 dl 1752690794 ref 2 fl Interpret:ReMQU/600/0 rc -5/-5 job:'ptlrpcd_00_01.0' uid:0 gid:0 projid:0 [ 3073.196300] LustreError: 2402:0:(osc_request.c:2446:osc_brw_redo_request()) Skipped 3 previous similar messages [ 3075.234990] LustreError: lustre-OST0000-osc-ffff89bb84fa0800: operation ost_write to node 192.168.203.103@tcp failed: rc = -5 [ 3075.235120] LustreError: 2402:0:(osc_request.c:2446:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff89bb84bb9500 x1837826407501312/t0(0) o4->lustre-OST0000-osc-ffff89bb84fa0800@192.168.203.103@tcp:6/4 lens 488/224 e 0 to 0 dl 1752690796 ref 2 fl Interpret:ReMQU/600/0 rc -5/-5 job:'ptlrpcd_00_00.0' uid:0 gid:0 projid:0 [ 3075.238881] LustreError: Skipped 4 previous similar messages [ 3075.244555] LustreError: 2402:0:(osc_request.c:2446:osc_brw_redo_request()) Skipped 3 previous similar messages [ 3078.306873] LustreError: lustre-OST0000-osc-ffff89bb84fa0800: operation ost_write to node 192.168.203.103@tcp failed: rc = -5 [ 3078.309384] LustreError: Skipped 2 previous similar messages [ 3078.310605] LustreError: 2401:0:(osc_request.c:2446:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff89bb90246d80 x1837826407501952/t0(0) o4->lustre-OST0000-osc-ffff89bb84fa0800@192.168.203.103@tcp:6/4 lens 488/224 e 0 to 0 dl 1752690799 ref 2 fl Interpret:ReMQU/600/0 rc -5/-5 job:'ptlrpcd_00_01.0' uid:0 gid:0 projid:0 [ 3078.316587] LustreError: 2401:0:(osc_request.c:2446:osc_brw_redo_request()) Skipped 2 previous similar messages [ 3086.818848] LustreError: lustre-OST0000-osc-ffff89bb84fa0800: operation ost_write to node 192.168.203.103@tcp failed: rc = -5 [ 3086.821235] LustreError: Skipped 7 previous similar messages [ 3086.822400] LustreError: 2401:0:(osc_request.c:2446:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff89bb84bbaa00 x1837826407504000/t0(0) o4->lustre-OST0000-osc-ffff89bb84fa0800@192.168.203.103@tcp:6/4 lens 488/224 e 0 to 0 dl 1752690808 ref 2 fl Interpret:ReMQU/600/0 rc -5/-5 job:'ptlrpcd_00_01.0' uid:0 gid:0 projid:0 [ 3086.827927] LustreError: 2401:0:(osc_request.c:2446:osc_brw_redo_request()) Skipped 7 previous similar messages [ 3100.067085] LustreError: lustre-OST0000-osc-ffff89bb84fa0800: operation ost_write to node 192.168.203.103@tcp failed: rc = -5 [ 3100.071191] LustreError: Skipped 7 previous similar messages [ 3100.073291] LustreError: 2401:0:(osc_request.c:2446:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff89bb84bb8a80 x1837826407506432/t0(0) o4->lustre-OST0000-osc-ffff89bb84fa0800@192.168.203.103@tcp:6/4 lens 488/224 e 0 to 0 dl 1752690821 ref 2 fl Interpret:ReMQU/600/0 rc -5/-5 job:'ptlrpcd_00_01.0' uid:0 gid:0 projid:0 [ 3100.083379] LustreError: 2401:0:(osc_request.c:2446:osc_brw_redo_request()) Skipped 7 previous similar messages [ 3116.519304] LustreError: lustre-OST0000-osc-ffff89bb84fa0800: operation ost_write to node 192.168.203.103@tcp failed: rc = -5 [ 3116.524591] LustreError: Skipped 7 previous similar messages [ 3116.527229] LustreError: 2401:0:(osc_request.c:2446:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff89bb84bb8380 x1837826407509376/t0(0) o4->lustre-OST0000-osc-ffff89bb84fa0800@192.168.203.103@tcp:6/4 lens 488/224 e 0 to 0 dl 1752690838 ref 2 fl Interpret:ReMQU/600/0 rc -5/-5 job:'ptlrpcd_00_01.0' uid:0 gid:0 projid:0 [ 3116.538714] LustreError: 2401:0:(osc_request.c:2446:osc_brw_redo_request()) Skipped 7 previous similar messages [ 3126.755451] LustreError: 2402:0:(osc_request.c:2601:brw_interpret()) lustre-OST0000-osc-ffff89bb84fa0800: too many resent retries for object: 10737419265:8522: rc = -5 [ 3151.330967] LustreError: lustre-OST0000-osc-ffff89bb84fa0800: operation ost_read to node 192.168.203.103@tcp failed: rc = -5 [ 3151.333674] LustreError: Skipped 31 previous similar messages [ 3151.335707] LustreError: 2404:0:(osc_request.c:2446:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff89bba1b03800 x1837826407539456/t0(0) o3->lustre-OST0000-osc-ffff89bb84fa0800@192.168.203.103@tcp:6/4 lens 488/440 e 0 to 0 dl 1752690872 ref 2 fl Interpret:ReMQU/600/0 rc -5/-5 job:'ptlrpcd_01_00.0' uid:0 gid:0 projid:0 [ 3151.343697] LustreError: 2404:0:(osc_request.c:2446:osc_brw_redo_request()) Skipped 27 previous similar messages [ 3186.147553] LustreError: 2404:0:(osc_request.c:2601:brw_interpret()) lustre-OST0000-osc-ffff89bb84fa0800: too many resent retries for object: 10737419265:8522: rc = -5 [ 3186.159772] LustreError: 2404:0:(osc_request.c:2601:brw_interpret()) Skipped 3 previous similar messages [ 3215.843870] LustreError: lustre-OST0001-osc-ffff89bb84fa0800: operation ost_write to node 192.168.203.103@tcp failed: rc = -5 [ 3215.846230] LustreError: Skipped 47 previous similar messages [ 3215.847387] LustreError: 2402:0:(osc_request.c:2446:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff89bb84bb9880 x1837826407560448/t0(0) o4->lustre-OST0001-osc-ffff89bb84fa0800@192.168.203.103@tcp:6/4 lens 488/224 e 0 to 0 dl 1752690937 ref 2 fl Interpret:ReMQU/600/0 rc -5/-5 job:'ptlrpcd_00_00.0' uid:0 gid:0 projid:0 [ 3215.856895] LustreError: 2402:0:(osc_request.c:2446:osc_brw_redo_request()) Skipped 43 previous similar messages [ 3243.427811] LustreError: 2401:0:(osc_request.c:2601:brw_interpret()) lustre-OST0001-osc-ffff89bb84fa0800: too many resent retries for object: 11811161089:8448: rc = -5 [ 3243.434588] LustreError: 2401:0:(osc_request.c:2601:brw_interpret()) Skipped 3 previous similar messages [ 3301.861446] LustreError: 2404:0:(osc_request.c:2601:brw_interpret()) lustre-OST0001-osc-ffff89bb84fa0800: too many resent retries for object: 11811161089:8447: rc = -5 [ 3301.867787] LustreError: 2404:0:(osc_request.c:2601:brw_interpret()) Skipped 3 previous similar messages [ 3305.405508] Lustre: DEBUG MARKER: == sanity test 398n: test append with parallel DIO ======= 14:36:50 (1752691010) [ 3315.836673] Lustre: DEBUG MARKER: == sanity test 398o: right kms with DIO ================== 14:37:00 (1752691020) [ 3318.780930] Lustre: DEBUG MARKER: == sanity test 398p: race aio with buffered i/o ========== 14:37:03 (1752691023) [ 3367.826204] Lustre: DEBUG MARKER: == sanity test 398q: race dio with buffered i/o ========== 14:37:52 (1752691072) [ 3420.956858] Lustre: DEBUG MARKER: == sanity test 398r: i/o error on file read ============== 14:38:45 (1752691125) [ 3421.505082] LustreError: lustre-OST0000-osc-ffff89bb84fa0800: operation ost_read to node 192.168.203.103@tcp failed: rc = -5 [ 3421.507599] LustreError: Skipped 59 previous similar messages [ 3421.508782] LustreError: 2404:0:(osc_request.c:2446:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff89bba1b02d80 x1837826413523328/t0(0) o3->lustre-OST0000-osc-ffff89bb84fa0800@192.168.203.103@tcp:6/4 lens 488/4536 e 0 to 0 dl 1752691143 ref 2 fl Interpret:RMQU/600/0 rc -5/-5 job:'cat.0' uid:0 gid:0 projid:0 [ 3421.515123] LustreError: 2404:0:(osc_request.c:2446:osc_brw_redo_request()) Skipped 51 previous similar messages [ 3477.987248] LustreError: 2404:0:(osc_request.c:2601:brw_interpret()) lustre-OST0000-osc-ffff89bb84fa0800: too many resent retries for object: 10737419265:8534: rc = -5 [ 3477.995080] LustreError: 2404:0:(osc_request.c:2601:brw_interpret()) Skipped 3 previous similar messages [ 3481.170983] Lustre: DEBUG MARKER: == sanity test 398s: i/o error on mirror file read ======= 14:39:46 (1752691186) [ 3483.690426] Lustre: DEBUG MARKER: == sanity test 399a: fake write should not be slower than normal write ========================================================== 14:39:48 (1752691188) [ 3516.129175] Lustre: DEBUG MARKER: sanity test_399a: @@@@@@ IGNORE (env=kvm): fake write is slower [ 3520.308946] Lustre: DEBUG MARKER: == sanity test 399b: fake read should not be slower than normal read ========================================================== 14:40:25 (1752691225) [ 3540.736561] Lustre: DEBUG MARKER: SKIP: sanity test_400a skipping excluded test 400a [ 3541.722299] Lustre: DEBUG MARKER: == sanity test 400b: packaged headers can be compiled ==== 14:40:46 (1752691246) [ 3544.739822] Lustre: DEBUG MARKER: == sanity test 401a: Verify if 'lctl list_param -R' can list parameters recursively ========================================================== 14:40:49 (1752691249) [ 3548.430524] Lustre: DEBUG MARKER: == sanity test 401aa: Verify that 'lctl list_param -p' lists the correct path names ========================================================== 14:40:53 (1752691253) [ 3551.867731] Lustre: DEBUG MARKER: == sanity test 401ab: Check that 'lctl list_param -r' lists only readable params ========================================================== 14:40:56 (1752691256) [ 3555.255214] Lustre: DEBUG MARKER: == sanity test 401ac: Check that 'lctl list_param -w' lists only writable params ========================================================== 14:41:00 (1752691260) [ 3558.732504] Lustre: DEBUG MARKER: == sanity test 401ad: Check that 'lctl list_param -wr' is conjunctive ========================================================== 14:41:03 (1752691263) [ 3562.181044] Lustre: DEBUG MARKER: == sanity test 401b: Verify 'lctl get_param' set_param' continue after error ========================================================== 14:41:06 (1752691266) [ 3565.604805] Lustre: DEBUG MARKER: == sanity test 401c: Verify 'lctl set_param' without value fails in either format. ========================================================== 14:41:10 (1752691270) [ 3569.090675] Lustre: DEBUG MARKER: == sanity test 401d: Verify 'lctl set_param' accepts values containing '=' ========================================================== 14:41:13 (1752691273) [ 3572.308482] Lustre: DEBUG MARKER: == sanity test 401db: Verify 'lctl set_param' does not add trailing '=' ========================================================== 14:41:17 (1752691277) [ 3672.094627] Lustre: DEBUG MARKER: == sanity test 401e: verify 'lctl get_param' works with NID in parameter ========================================================== 14:42:56 (1752691376) [ 3675.439168] Lustre: DEBUG MARKER: == sanity test 401f: check 'lctl list_param' doesn't follow symlinks with --no-links ========================================================== 14:43:00 (1752691380) [ 3678.878642] Lustre: DEBUG MARKER: == sanity test 401ga: check 'set_param -C' sets params upon mount ========================================================== 14:43:03 (1752691383) [ 3679.418926] LustreError: 214851:0:(lov_obd.c:784:lov_cleanup()) lustre-clilov-ffff89bb84fa0800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 3679.421803] LustreError: 214851:0:(lov_obd.c:784:lov_cleanup()) Skipped 3 previous similar messages [ 3679.426719] LustreError: 214851:0:(obd_class.h:479:obd_check_dev()) Device 6 not setup [ 3679.430422] LustreError: 214851:0:(obd_class.h:479:obd_check_dev()) Skipped 19 previous similar messages [ 3679.465899] Lustre: Unmounted lustre-client [ 3679.467964] Lustre: Skipped 1 previous similar message [ 3679.691966] Lustre: Mounted lustre-client [ 3679.692778] Lustre: Skipped 1 previous similar message [ 3683.085205] Lustre: DEBUG MARKER: == sanity test 401gb: check 'set_param -d -C' removes client params ========================================================== 14:43:07 (1752691387) [ 3686.883757] Lustre: DEBUG MARKER: == sanity test 402: Return ENOENT to lod_generate_and_set_lovea ========================================================== 14:43:11 (1752691391) [ 3690.894218] Lustre: DEBUG MARKER: == sanity test 403: i_nlink should not drop to zero due to aliasing ========================================================== 14:43:15 (1752691395) [ 3691.199851] sysctl (216788): drop_caches: 2 [ 3694.597189] Lustre: DEBUG MARKER: == sanity test 404: validate manual {de}activated works properly for OSPs ========================================================== 14:43:19 (1752691399) [ 3705.235069] Lustre: DEBUG MARKER: == sanity test 405: Various layout swap lock tests ======= 14:43:29 (1752691409) [ 3708.039974] Lustre: DEBUG MARKER: SKIP: sanity test_405 layout swap does not support DOM files so far [ 3708.630508] Lustre: DEBUG MARKER: == sanity test 406: DNE support fs default striping ====== 14:43:33 (1752691413) [ 3724.180251] Lustre: DEBUG MARKER: SKIP: sanity test_407 skipping ALWAYS excluded test 407 [ 3724.936953] Lustre: DEBUG MARKER: == sanity test 408: drop_caches should not hang due to page leaks ========================================================== 14:43:49 (1752691429) [ 3725.026576] Lustre: *** cfs_fail_loc=40a, val=0*** [ 3725.027577] LustreError: 2404:0:(osc_request.c:2868:osc_build_rpc()) lustre-OST0001-osc-ffff89bb8625c800: prep_req failed: rc = -22 [ 3725.029870] LustreError: 2404:0:(osc_cache.c:2217:osc_check_rpcs()) Read request failed with -22 [ 3727.809417] bash (219288): drop_caches: 2 [ 3730.168975] Lustre: DEBUG MARKER: == sanity test 409: Large amount of cross-MDTs hard links on the same file ========================================================== 14:43:55 (1752691435) [ 3754.697743] Lustre: DEBUG MARKER: == sanity test 410: Test inode number returned from kernel thread ========================================================== 14:44:19 (1752691459) [ 3754.813234] lustre_kinode_31320: CONFIG_X86_X32 is not set [ 3754.818914] lustre_kinode_31320: inode is 144115373111771250 [ 3754.821890] lustre_kinode_31320: inode is 144115373111771250 [ 3754.824222] lustre_kinode_31320: inode numbers are identical: 144115373111771250 [ 3758.141290] Lustre: DEBUG MARKER: SKIP: sanity test_411a skipping ALWAYS excluded test 411a [ 3758.944227] Lustre: DEBUG MARKER: == sanity test 411b: confirm Lustre can avoid OOM with reasonable cgroups limits ========================================================== 14:44:23 (1752691463) [ 4194.675236] Lustre: DEBUG MARKER: SKIP: sanity test_411b OST space are too small: 3601008K [ 4196.162985] Lustre: DEBUG MARKER: == sanity test 412: mkdir on specific MDTs =============== 14:51:40 (1752691900) [ 4200.158474] Lustre: DEBUG MARKER: == sanity test 413a: QoS mkdir with 'lfs mkdir -i -1' ==== 14:51:44 (1752691904) [ 4446.533808] Lustre: DEBUG MARKER: == sanity test 413b: QoS mkdir under dir whose default LMV starting MDT offset is -1 ========================================================== 14:55:51 (1752692151) [ 4490.832819] Lustre: DEBUG MARKER: == sanity test 413c: mkdir with default LMV max inherit rr ========================================================== 14:56:35 (1752692195) [ 4534.307406] Lustre: DEBUG MARKER: == sanity test 413d: inherit ROOT default LMV ============ 14:57:19 (1752692239) [ 4543.279343] Lustre: DEBUG MARKER: == sanity test 413e: check default max-inherit value ===== 14:57:28 (1752692248) [ 4546.825838] Lustre: DEBUG MARKER: == sanity test 413f: lfs getdirstripe -D list ROOT default LMV if it's not set on dir ========================================================== 14:57:31 (1752692251) [ 4550.152764] Lustre: DEBUG MARKER: == sanity test 413g: enforce ROOT default LMV on subdir mount ========================================================== 14:57:34 (1752692254) [ 4550.477679] Lustre: Mounted lustre-client [ 4550.479599] Lustre: Skipped 1 previous similar message [ 4550.577202] LustreError: 236298:0:(lov_obd.c:784:lov_cleanup()) lustre-clilov-ffff89bb98a44000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 4550.582153] LustreError: 236298:0:(lov_obd.c:784:lov_cleanup()) Skipped 3 previous similar messages [ 4550.589473] LustreError: 236298:0:(obd_class.h:479:obd_check_dev()) Device 12 not setup [ 4550.592319] LustreError: 236298:0:(obd_class.h:479:obd_check_dev()) Skipped 19 previous similar messages [ 4550.632205] Lustre: Unmounted lustre-client [ 4550.633970] Lustre: Skipped 1 previous similar message [ 4559.464985] LustreError: 236973:0:(lov_obd.c:784:lov_cleanup()) lustre-clilov-ffff89bbbde91000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 4559.468666] LustreError: 236973:0:(lov_obd.c:784:lov_cleanup()) Skipped 1 previous similar message [ 4559.474065] LustreError: 236973:0:(obd_class.h:479:obd_check_dev()) Device 12 not setup [ 4559.476397] LustreError: 236973:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 4559.523321] Lustre: Unmounted lustre-client [ 4560.456783] Lustre: DEBUG MARKER: == sanity test 413h: don't stick to parent for round-robin dirs ========================================================== 14:57:45 (1752692265) [ 4562.041197] Lustre: DEBUG MARKER: dir=/mnt/lustre/d413h.sanity/l1/l2/l3/l4/l5: [ 4564.421741] Lustre: DEBUG MARKER: dir=/mnt/lustre/d413h.sanity/l1/l2/l3/l4/l5/d0: [ 4567.620793] Lustre: DEBUG MARKER: dir=/mnt/lustre/d413h.sanity/l1/l2/l3/l4/l5/d0/d0: [ 4570.249184] Lustre: DEBUG MARKER: dir=/mnt/lustre/d413h.sanity/l1/l2/l3/l4/l5/d0/d0/d0: [ 4573.083091] Lustre: DEBUG MARKER: dir=/mnt/lustre/d413h.sanity/l1/l2/l3/l4/l5/d0/d0/d0/d0: [ 4576.133217] Lustre: DEBUG MARKER: dir=/mnt/lustre/d413h.sanity/l1/l2/l3/l4/l5/d0/d0/d0/d0/d0: [ 4578.623314] Lustre: DEBUG MARKER: dir=/mnt/lustre/d413h.sanity/l1/l2/l3/l4/l5/d0/d0/d0/d0/d0/d0: [ 4592.030899] Lustre: DEBUG MARKER: == sanity test 413i: check default layout inheritance ==== 14:58:16 (1752692296) [ 4596.500106] Lustre: DEBUG MARKER: == sanity test 413j: set default LMV by setxattr ========= 14:58:21 (1752692301) [ 4602.971689] Lustre: DEBUG MARKER: == sanity test 413k: QoS mkdir exclude prefixes ========== 14:58:27 (1752692307) [ 4607.662511] Lustre: DEBUG MARKER: == sanity test 413z: 413 test cleanup ==================== 14:58:32 (1752692312) [ 4633.117682] Lustre: DEBUG MARKER: == sanity test 414: simulate ENOMEM in ptlrpc_register_bulk() ========================================================== 14:58:58 (1752692338) [ 4633.240563] Lustre: *** cfs_fail_loc=521, val=0*** [ 4633.241893] LustreError: 2404:0:(niobuf.c:386:ptlrpc_register_bulk()) lustre-OST0001-osc-ffff89bb8625c800: LNetMEAttach failed x1837826428773761/1: rc = -12 [ 4638.375201] LustreError: 246168:0:(lov_obd.c:784:lov_cleanup()) lustre-clilov-ffff89bb8625c800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 4638.381554] LustreError: 246168:0:(lov_obd.c:784:lov_cleanup()) Skipped 1 previous similar message [ 4638.389734] LustreError: 246168:0:(obd_class.h:479:obd_check_dev()) Device 6 not setup [ 4638.393458] LustreError: 246168:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 4638.472139] Lustre: Unmounted lustre-client [ 4638.664787] Lustre: Mounted lustre-client [ 4638.666208] Lustre: Skipped 1 previous similar message [ 4642.608413] Lustre: DEBUG MARKER: == sanity test 415: lock revoke is not missing =========== 14:59:07 (1752692347) [ 4713.482984] Lustre: DEBUG MARKER: == sanity test 416: transaction start failure won't cause system hung ========================================================== 15:00:18 (1752692418) [ 4718.136635] Lustre: DEBUG MARKER: == sanity test 417: disable remote dir, striped dir and dir migration ========================================================== 15:00:22 (1752692422) [ 4729.318439] Lustre: DEBUG MARKER: == sanity test 418: df and lfs df outputs match ========== 15:00:33 (1752692433) [ 4757.587809] Lustre: DEBUG MARKER: == sanity test 419: Verify open file by name doesn't crash kernel ========================================================== 15:01:02 (1752692462) [ 4761.203328] Lustre: DEBUG MARKER: == sanity test 420: clear SGID bit on non-directories for non-members ========================================================== 15:01:05 (1752692465) [ 4765.155127] Lustre: DEBUG MARKER: == sanity test 421a: simple rm by fid ==================== 15:01:09 (1752692469) [ 4769.543650] Lustre: DEBUG MARKER: == sanity test 421b: rm by fid on open file ============== 15:01:14 (1752692474) [ 4773.326733] Lustre: DEBUG MARKER: == sanity test 421c: rm by fid against hardlinked files == 15:01:17 (1752692477) [ 4782.486723] Lustre: DEBUG MARKER: == sanity test 421d: rmfid en masse ====================== 15:01:27 (1752692487) [ 4839.907880] Lustre: DEBUG MARKER: == sanity test 421e: rmfid in DNE ======================== 15:02:24 (1752692544) [ 4849.929578] Lustre: DEBUG MARKER: == sanity test 421f: rmfid checks permissions ============ 15:02:34 (1752692554) [ 4850.980473] Lustre: Mounted lustre-client [ 4853.634422] LustreError: 257803:0:(lov_obd.c:784:lov_cleanup()) lustre-clilov-ffff89bbb79da800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 4853.638471] LustreError: 257803:0:(lov_obd.c:784:lov_cleanup()) Skipped 1 previous similar message [ 4853.643216] LustreError: 257803:0:(obd_class.h:479:obd_check_dev()) Device 12 not setup [ 4853.645207] LustreError: 257803:0:(obd_class.h:479:obd_check_dev()) Skipped 9 previous similar messages [ 4853.672671] Lustre: Unmounted lustre-client [ 4854.320082] Lustre: DEBUG MARKER: == sanity test 421g: rmfid to return errors properly ===== 15:02:39 (1752692559) [ 4865.254627] Lustre: DEBUG MARKER: == sanity test 421h: rmfid with fileset mount ============ 15:02:50 (1752692570) [ 4866.647564] Lustre: Mounted lustre-client [ 4866.724552] LustreError: 258819:0:(lov_obd.c:784:lov_cleanup()) lustre-clilov-ffff89bbb7aea800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 4866.729832] LustreError: 258819:0:(lov_obd.c:784:lov_cleanup()) Skipped 1 previous similar message [ 4866.736208] LustreError: 258819:0:(obd_class.h:479:obd_check_dev()) Device 12 not setup [ 4866.738749] LustreError: 258819:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 4866.770135] Lustre: Unmounted lustre-client [ 4869.609480] Lustre: DEBUG MARKER: == sanity test 422: kill a process with RPC in progress == 15:02:54 (1752692574) [ 4892.128206] Lustre: 259593:0:(client.c:2453:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1752692577/real 1752692577] req@ffff89bbb7ba5f80 x1837826434462848/t0(0) o101->lustre-MDT0000-mdc-ffff89bb83e75000@192.168.203.103@tcp:12/10 lens 576/1584 e 0 to 1 dl 1752692597 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'touch.0' uid:0 gid:0 projid:0 [ 4892.143708] Lustre: lustre-MDT0000-mdc-ffff89bb83e75000: Connection to lustre-MDT0000 (at 192.168.203.103@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 4892.151709] Lustre: Skipped 2 previous similar messages [ 4892.170121] Lustre: lustre-MDT0000-mdc-ffff89bb83e75000: Connection restored to 192.168.203.103@tcp (at 192.168.203.103@tcp) [ 4892.175525] Lustre: Skipped 13 previous similar messages [ 4912.608146] Lustre: 259593:0:(client.c:2453:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1752692597/real 1752692597] req@ffff89bbb7ba5f80 x1837826434462848/t0(0) o101->lustre-MDT0000-mdc-ffff89bb83e75000@192.168.203.103@tcp:12/10 lens 576/1584 e 0 to 1 dl 1752692617 ref 2 fl Rpc:XQr/602/ffffffff rc 0/-1 job:'touch.0' uid:0 gid:0 projid:0 [ 4912.625541] Lustre: 259593:0:(client.c:2453:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 4915.158287] Lustre: DEBUG MARKER: touch [ 4933.088211] Lustre: 259593:0:(client.c:2453:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1752692618/real 1752692618] req@ffff89bbb7ba5f80 x1837826434462848/t0(0) o101->lustre-MDT0000-mdc-ffff89bb83e75000@192.168.203.103@tcp:12/10 lens 576/1584 e 0 to 1 dl 1752692638 ref 2 fl Rpc:XQr/602/ffffffff rc -11/-1 job:'touch.0' uid:0 gid:0 projid:0 [ 4933.105273] Lustre: lustre-MDT0000-mdc-ffff89bb83e75000: Connection to lustre-MDT0000 (at 192.168.203.103@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 4933.113634] Lustre: Skipped 1 previous similar message [ 4938.180818] Lustre: DEBUG MARKER: == sanity test 423: statfs should return a right data ==== 15:04:02 (1752692642) [ 4943.791530] Lustre: DEBUG MARKER: == sanity test 424: simulate ENOMEM in ptl_send_rpc bulk reply ME attach ========================================================== 15:04:08 (1752692648) [ 4943.964068] Lustre: *** cfs_fail_loc=522, val=0*** [ 4943.966545] LustreError: 2403:0:(niobuf.c:1007:ptl_send_rpc()) LNetMEAttach failed: -12 [ 4947.596908] Lustre: DEBUG MARKER: == sanity test 425: lock count should not exceed lru size ========================================================== 15:04:12 (1752692652) [ 4961.489396] Lustre: DEBUG MARKER: == sanity test 426: splice test on Lustre ================ 15:04:26 (1752692666) [ 4964.086749] Lustre: DEBUG MARKER: == sanity test 427: Failed DNE2 update request shouldn't corrupt updatelog ========================================================== 15:04:29 (1752692669) [ 4992.332957] Lustre: lustre-MDT0001-mdc-ffff89bb83e75000: Connection restored to 192.168.203.103@tcp (at 192.168.203.103@tcp) [ 4992.335251] Lustre: Skipped 2 previous similar messages [ 4993.373362] Lustre: DEBUG MARKER: oleg303-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 4993.875554] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4999.608949] Lustre: DEBUG MARKER: == sanity test 428: large block size IO should not hang == 15:05:04 (1752692704) [ 5185.071469] Lustre: DEBUG MARKER: == sanity test 429: verify if opencache flag on client side does work ========================================================== 15:08:09 (1752692889) [ 5189.163414] Lustre: DEBUG MARKER: == sanity test 430a: lseek: SEEK_DATA/SEEK_HOLE basic functionality ========================================================== 15:08:13 (1752692893) [ 5196.586210] Lustre: DEBUG MARKER: == sanity test 430b: lseek: SEEK_DATA/SEEK_HOLE special cases ========================================================== 15:08:21 (1752692901) [ 5200.980805] Lustre: DEBUG MARKER: == sanity test 430c: lseek: external tools check ========= 15:08:25 (1752692905) [ 5204.878661] Lustre: DEBUG MARKER: == sanity test 431: Restart transaction for IO =========== 15:08:29 (1752692909) [ 5208.408690] bash (267348): drop_caches: 3 [ 5212.499365] Lustre: DEBUG MARKER: == sanity test 432: mv dir from outside Lustre =========== 15:08:37 (1752692917) [ 5264.380259] Lustre: DEBUG MARKER: == sanity test 433: ldlm lock cancel releases dentries and inodes ========================================================== 15:09:29 (1752692969) [ 5275.266146] Lustre: DEBUG MARKER: == sanity test 434: Client should not send RPCs for security.selinux with SElinux disabled ========================================================== 15:09:40 (1752692980) [ 5280.165150] Lustre: DEBUG MARKER: == sanity test 440: bash completion for lfs, lctl ======== 15:09:45 (1752692985) [ 5282.541702] Lustre: DEBUG MARKER: == sanity test 442: truncate vs read/write should not panic ========================================================== 15:09:47 (1752692987) [ 5283.693276] LustreError: 271526:0:(llite_lib.c:3149:ll_truncate_inode_pages_final()) cfs_fail_timeout id 1430 sleeping for 5000ms [ 5288.792128] LustreError: 271526:0:(llite_lib.c:3149:ll_truncate_inode_pages_final()) cfs_fail_timeout id 1430 awake [ 5290.704319] Lustre: DEBUG MARKER: == sanity test 460d: Check encrypt pools output ========== 15:09:55 (1752692995) [ 5293.215705] Lustre: DEBUG MARKER: == sanity test 600a: basic test for mlock()ed file ======= 15:09:58 (1752692998) [ 5294.027575] Lustre: DEBUG MARKER: SKIP: sanity test_600a This test needs vmtouch utility [ 5294.859646] Lustre: DEBUG MARKER: == sanity test 600b: mlock a file (via vmtouch) larger than max_cached_mb ========================================================== 15:09:59 (1752692999) [ 5295.774569] Lustre: DEBUG MARKER: SKIP: sanity test_600b This test needs vmtouch utility [ 5296.767201] Lustre: DEBUG MARKER: == sanity test 600c: Test I/O when mlocked page count > @max_cached_mb ========================================================== 15:10:01 (1752693001) [ 5297.627339] Lustre: DEBUG MARKER: SKIP: sanity test_600c This test needs vmtouch utility [ 5298.660489] Lustre: DEBUG MARKER: == sanity test 600d: Test I/O with limited LRU page slots (some was mlocked) ========================================================== 15:10:03 (1752693003) [ 5299.654734] Lustre: DEBUG MARKER: SKIP: sanity test_600d This test needs vmtouch utility [ 5300.200790] Lustre: DEBUG MARKER: == sanity test 801a: write barrier user interfaces and stat machine ========================================================== 15:10:05 (1752693005) [ 5335.535907] Lustre: DEBUG MARKER: == sanity test 801b: modification will be blocked by write barrier ========================================================== 15:10:40 (1752693040) [ 5339.310283] Lustre: 275272:0:(client.c:1611:after_reply()) @@@ resending request on EINPROGRESS req@ffff89bbb7acdc00 x1837826435905920/t0(0) o36->lustre-MDT0001-mdc-ffff89bb83e75000@192.168.203.103@tcp:12/10 lens 488/456 e 0 to 0 dl 1752693100 ref 2 fl Rpc:RQU/202/0 rc 0/-115 job:'rm.0' uid:0 gid:0 projid:4294967295 [ 5352.267946] Lustre: DEBUG MARKER: == sanity test 801c: rescan barrier bitmap =============== 15:10:57 (1752693057) [ 5358.053431] Lustre: lustre-MDT0001-mdc-ffff89bb83e75000: Connection to lustre-MDT0001 (at 192.168.203.103@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 5358.061822] Lustre: Skipped 1 previous similar message [ 5366.072122] Lustre: lustre-MDT0001-mdc-ffff89bb83e75000: Connection restored to 192.168.203.103@tcp (at 192.168.203.103@tcp) [ 5367.653244] Lustre: DEBUG MARKER: == sanity test 802b: be able to set MDTs to readonly ===== 15:11:12 (1752693072) [ 5373.501580] Lustre: DEBUG MARKER: == sanity test 802c: be able to set OFDs to readonly ===== 15:11:18 (1752693078) [ 5379.181384] Lustre: DEBUG MARKER: == sanity test 803a: verify agent object for remote object ========================================================== 15:11:23 (1752693083) [ 5396.250921] Lustre: DEBUG MARKER: == sanity test 803b: remote object can getattr from cache ========================================================== 15:11:40 (1752693100) [ 5401.749599] Lustre: DEBUG MARKER: == sanity test 804: verify agent entry for remote entry == 15:11:46 (1752693106) [ 5413.352870] LustreError: MGC192.168.203.103@tcp: Connection to MGS (at 192.168.203.103@tcp) was lost; in progress operations using this service will fail [ 5413.365411] Lustre: Evicted from MGS (at 192.168.203.103@tcp) after server handle changed from 0xe47d86e684d4ae77 to 0xe47d86e684dfc2c7 [ 5413.404192] LustreError: 2400:0:(client.c:3395:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff89bbbf606d80 x1837826435927424/t25769847813(25769847813) o101->lustre-MDT0000-mdc-ffff89bb83e75000@192.168.203.103@tcp:12/10 lens 520/664 e 0 to 0 dl 1752693173 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'lfs.0' uid:0 gid:0 projid:0 [ 5429.539388] Lustre: DEBUG MARKER: == sanity test 805: ZFS can remove from full fs ========== 15:12:14 (1752693134) [ 5430.908801] Lustre: DEBUG MARKER: SKIP: sanity test_805 ZFS specific test [ 5431.956057] Lustre: DEBUG MARKER: == sanity test 806: Verify Lazy Size on MDS ============== 15:12:16 (1752693136) [ 5446.300712] Lustre: DEBUG MARKER: == sanity test 807a: verify LSOM syncing tool ============ 15:12:31 (1752693151) [ 5449.716631] Lustre: DEBUG MARKER: oleg303-client.virtnet: executing cancel_lru_locks osc [ 5459.736494] Lustre: DEBUG MARKER: == sanity test 807b: verify lfs somsync utility ========== 15:12:44 (1752693164) [ 5461.153901] Lustre: DEBUG MARKER: oleg303-client.virtnet: executing cancel_lru_locks osc [ 5468.935430] Lustre: DEBUG MARKER: == sanity test 808: Check trusted.som xattr not logged in Changelogs ========================================================== 15:12:53 (1752693173) [ 5475.444345] Lustre: DEBUG MARKER: == sanity test 809: Verify no SOM xattr store for DoM-only files ========================================================== 15:13:00 (1752693180) [ 5477.850445] Lustre: DEBUG MARKER: == sanity test 810: partial page writes on ZFS (LU-11663) ========================================================== 15:13:02 (1752693182) [ 5477.955875] Lustre: *** cfs_fail_loc=411, val=0*** [ 5477.956908] Lustre: Skipped 1 previous similar message [ 5478.461396] Lustre: *** cfs_fail_loc=411, val=0*** [ 5478.462485] Lustre: Skipped 13 previous similar messages [ 5479.466129] Lustre: *** cfs_fail_loc=411, val=0*** [ 5479.467174] Lustre: Skipped 27 previous similar messages [ 5482.203822] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 5482.802768] Lustre: DEBUG MARKER: == sanity test 812a: do not drop reqs generated when imp is going to idle (LU-11951) ========================================================== 15:13:07 (1752693187) [ 5483.992448] Lustre: DEBUG MARKER: oleg303-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff89bb83e75000.ost_server_uuid 50 [ 5484.515245] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff89bb83e75000.ost_server_uuid in FULL state after 0 sec [ 5486.212547] Lustre: DEBUG MARKER: oleg303-client.virtnet: executing wait_import_state CONNECTING osc.lustre-OST0000-osc-ffff89bb83e75000.ost_server_uuid 50 [ 5495.929409] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff89bb83e75000.ost_server_uuid in CONNECTING state after 9 sec [ 5498.526641] Lustre: DEBUG MARKER: == sanity test 812b: do not drop no resend request for idle connect ========================================================== 15:13:23 (1752693203) [ 5499.678417] Lustre: DEBUG MARKER: oleg303-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff89bb83e75000.ost_server_uuid 50 [ 5500.195398] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff89bb83e75000.ost_server_uuid in FULL state after 0 sec [ 5501.616837] Lustre: DEBUG MARKER: oleg303-client.virtnet: executing wait_import_state CONNECTING osc.lustre-OST0000-osc-ffff89bb83e75000.ost_server_uuid 50 [ 5511.284193] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff89bb83e75000.ost_server_uuid in CONNECTING state after 9 sec [ 5512.810195] Lustre: DEBUG MARKER: oleg303-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff89bb83e75000.ost_server_uuid 50 [ 5526.744791] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff89bb83e75000.ost_server_uuid in IDLE state after 13 sec [ 5530.491490] Lustre: DEBUG MARKER: == sanity test 812c: idle import vs lock enqueue race ==== 15:13:55 (1752693235) [ 5532.099924] Lustre: DEBUG MARKER: oleg303-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff89bb83e75000.ost_server_uuid 50 [ 5532.907924] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff89bb83e75000.ost_server_uuid in FULL state after 0 sec [ 5546.464349] LustreError: 11024:0:(import.c:2064:ptlrpc_disconnect_and_idle_import()) cfs_race id 533 sleeping [ 5548.062406] LustreError: 290428:0:(osc_lock.c:1027:osc_lock_enqueue()) cfs_fail_race id 533 waking [ 5548.066803] LustreError: 11024:0:(import.c:2064:ptlrpc_disconnect_and_idle_import()) cfs_fail_race id 533 awake: rc=3401 [ 5548.573142] LustreError: 290428:0:(osc_lock.c:1027:osc_lock_enqueue()) cfs_fail_race id 533 waking [ 5552.161549] Lustre: DEBUG MARKER: == sanity test 813: File heat verfication ================ 15:14:17 (1752693257) [ 5683.526509] Lustre: DEBUG MARKER: == sanity test 814: sparse cp works as expected (LU-12361) ========================================================== 15:16:28 (1752693388) [ 5687.114794] Lustre: DEBUG MARKER: == sanity test 815: zero byte tiny write doesn't hang (LU-12382) ========================================================== 15:16:31 (1752693391) [ 5690.559494] Lustre: DEBUG MARKER: == sanity test 816: do not reset lru_resize on idle reconnect ========================================================== 15:16:35 (1752693395) [ 5692.222841] Lustre: DEBUG MARKER: oleg303-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff89bb83e75000.ost_server_uuid 50 [ 5692.981087] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff89bb83e75000.ost_server_uuid in FULL state after 0 sec [ 5694.737478] Lustre: DEBUG MARKER: oleg303-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff89bb83e75000.ost_server_uuid 50 [ 5703.738056] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff89bb83e75000.ost_server_uuid in IDLE state after 8 sec [ 5706.664749] Lustre: DEBUG MARKER: SKIP: sanity test_817 skipping ALWAYS excluded test 817 [ 5707.499580] Lustre: DEBUG MARKER: == sanity test 818: unlink with failed llog ============== 15:16:52 (1752693412) [ 5712.869732] Lustre: lustre-MDT0000-mdc-ffff89bb83e75000: Connection to lustre-MDT0000 (at 192.168.203.103@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 5712.878355] Lustre: Skipped 2 previous similar messages [ 5717.989480] LustreError: MGC192.168.203.103@tcp: Connection to MGS (at 192.168.203.103@tcp) was lost; in progress operations using this service will fail [ 5717.999664] Lustre: Evicted from MGS (at 192.168.203.103@tcp) after server handle changed from 0xe47d86e684dfc2c7 to 0xe47d86e684dff580 [ 5718.006468] Lustre: MGC192.168.203.103@tcp: Connection restored to 192.168.203.103@tcp (at 192.168.203.103@tcp) [ 5718.011118] Lustre: Skipped 3 previous similar messages [ 5718.040434] LustreError: 2400:0:(client.c:3395:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff89bbbf604e00 x1837826436055168/t30064771236(30064771236) o101->lustre-MDT0000-mdc-ffff89bb83e75000@192.168.203.103@tcp:12/10 lens 576/608 e 0 to 0 dl 1752693478 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'md5sum.0' uid:0 gid:0 projid:0 [ 5743.584239] Lustre: 2404:0:(client.c:2453:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1752693433/real 1752693433] req@ffff89bbbf604380 x1837826436247424/t0(0) o400->MGC192.168.203.103@tcp@192.168.203.103@tcp:26/25 lens 224/224 e 0 to 1 dl 1752693449 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5743.591281] LustreError: MGC192.168.203.103@tcp: Connection to MGS (at 192.168.203.103@tcp) was lost; in progress operations using this service will fail [ 5743.597642] Lustre: Evicted from MGS (at 192.168.203.103@tcp) after server handle changed from 0xe47d86e684dff580 to 0xe47d86e684dffa0a [ 5743.613610] LustreError: 2400:0:(client.c:3395:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff89bbbf604e00 x1837826436055168/t30064771236(30064771236) o101->lustre-MDT0000-mdc-ffff89bb83e75000@192.168.203.103@tcp:12/10 lens 576/608 e 0 to 0 dl 1752693504 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'md5sum.0' uid:0 gid:0 projid:0 [ 5743.619151] LustreError: 2400:0:(client.c:3395:ptlrpc_replay_interpret()) Skipped 4 previous similar messages [ 5746.030224] Lustre: DEBUG MARKER: oleg303-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 5746.562617] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5748.623259] Lustre: DEBUG MARKER: == sanity test 819a: too big niobuf in read ============== 15:17:33 (1752693453) [ 5751.695490] Lustre: DEBUG MARKER: == sanity test 819b: too big niobuf in write ============= 15:17:36 (1752693456) [ 5768.160185] Lustre: 2401:0:(client.c:2453:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1752693457/real 1752693457] req@ffff89bbab371500 x1837826436256640/t0(0) o4->lustre-OST0000-osc-ffff89bb83e75000@192.168.203.103@tcp:6/4 lens 488/448 e 0 to 1 dl 1752693473 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'dd.0' uid:0 gid:0 projid:0 [ 5771.627220] Lustre: DEBUG MARKER: == sanity test 820: update max EA from open intent ======= 15:17:56 (1752693476) [ 5771.992267] LustreError: 297336:0:(lov_obd.c:784:lov_cleanup()) lustre-clilov-ffff89bb83e75000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 5771.995127] LustreError: 297336:0:(lov_obd.c:784:lov_cleanup()) Skipped 3 previous similar messages [ 5771.999349] LustreError: 297336:0:(obd_class.h:479:obd_check_dev()) Device 6 not setup [ 5772.000937] LustreError: 297336:0:(obd_class.h:479:obd_check_dev()) Skipped 15 previous similar messages [ 5772.026168] Lustre: Unmounted lustre-client [ 5772.027113] Lustre: Skipped 1 previous similar message [ 5774.639786] Lustre: Mounted lustre-client [ 5774.640722] Lustre: Skipped 1 previous similar message [ 5787.634176] LustreError: lustre-OST0001-osc-ffff89bbbdec5800: operation ost_connect to node 192.168.203.103@tcp failed: rc = -16 [ 5787.636637] LustreError: Skipped 19 previous similar messages [ 5793.663795] Lustre: DEBUG MARKER: == sanity test 823: Setting create_count > OST_MAX_PRECREATE is lowered to maximum ========================================================== 15:18:18 (1752693498) [ 5796.577435] Lustre: DEBUG MARKER: setting create_count to 100200: [ 5797.077274] Lustre: DEBUG MARKER: -result- count: 9984 with max: 20000, expecting: 9984 [ 5799.925077] Lustre: DEBUG MARKER: == sanity test 831: throttling unlink/setattr queuing on OSP ========================================================== 15:18:24 (1752693504) [ 5806.629347] Lustre: 299723:0:(client.c:1611:after_reply()) @@@ resending request on EINPROGRESS req@ffff89bb905b4e00 x1837826436815360/t0(0) o36->lustre-MDT0000-mdc-ffff89bbbdec5800@192.168.203.103@tcp:12/10 lens 488/456 e 0 to 0 dl 1752693567 ref 2 fl Rpc:RQU/202/0 rc 0/-115 job:'unlinkmany.0' uid:0 gid:0 projid:4294967295 [ 5806.637995] Lustre: 299723:0:(client.c:1611:after_reply()) Skipped 2 previous similar messages [ 5812.833739] Lustre: 299723:0:(client.c:1611:after_reply()) @@@ resending request on EINPROGRESS req@ffff89bbbe5f2680 x1837826436842496/t0(0) o36->lustre-MDT0000-mdc-ffff89bbbdec5800@192.168.203.103@tcp:12/10 lens 488/456 e 0 to 0 dl 1752693573 ref 2 fl Rpc:RQU/202/0 rc 0/-115 job:'unlinkmany.0' uid:0 gid:0 projid:4294967295 [ 5819.041656] Lustre: 299723:0:(client.c:1611:after_reply()) @@@ resending request on EINPROGRESS req@ffff89bbbe5f1180 x1837826436869632/t0(0) o36->lustre-MDT0000-mdc-ffff89bbbdec5800@192.168.203.103@tcp:12/10 lens 488/456 e 0 to 0 dl 1752693579 ref 2 fl Rpc:RQU/202/0 rc 0/-115 job:'unlinkmany.0' uid:0 gid:0 projid:4294967295 [ 5825.249645] Lustre: 299723:0:(client.c:1611:after_reply()) @@@ resending request on EINPROGRESS req@ffff89bbbe5f3100 x1837826436896768/t0(0) o36->lustre-MDT0000-mdc-ffff89bbbdec5800@192.168.203.103@tcp:12/10 lens 488/456 e 0 to 0 dl 1752693585 ref 2 fl Rpc:RQU/202/0 rc 0/-115 job:'unlinkmany.0' uid:0 gid:0 projid:4294967295 [ 5837.665721] Lustre: 299723:0:(client.c:1611:after_reply()) @@@ resending request on EINPROGRESS req@ffff89bbbe7ef480 x1837826436951552/t0(0) o36->lustre-MDT0000-mdc-ffff89bbbdec5800@192.168.203.103@tcp:12/10 lens 488/456 e 0 to 0 dl 1752693598 ref 2 fl Rpc:RQU/202/0 rc 0/-115 job:'unlinkmany.0' uid:0 gid:0 projid:4294967295 [ 5837.671030] Lustre: 299723:0:(client.c:1611:after_reply()) Skipped 1 previous similar message [ 5859.361913] Lustre: 299723:0:(client.c:1611:after_reply()) @@@ resending request on EINPROGRESS req@ffff89bbba3a9c00 x1837826437034240/t0(0) o36->lustre-MDT0000-mdc-ffff89bbbdec5800@192.168.203.103@tcp:12/10 lens 488/456 e 0 to 0 dl 1752693619 ref 2 fl Rpc:RQU/202/0 rc 0/-115 job:'unlinkmany.0' uid:0 gid:0 projid:4294967295 [ 5859.368567] Lustre: 299723:0:(client.c:1611:after_reply()) Skipped 3 previous similar messages [ 5869.970319] Lustre: DEBUG MARKER: == sanity test 832: lfs rm_entry ========================= 15:19:35 (1752693575) [ 5872.389523] Lustre: DEBUG MARKER: == sanity test 833: Mixed buffered/direct read and write should not return -EIO ========================================================== 15:19:37 (1752693577) [ 5912.852113] Lustre: DEBUG MARKER: SKIP: sanity test_842 skipping SLOW test 842 [ 5913.411892] Lustre: DEBUG MARKER: == sanity test 850: lljobstat can parse living and aggregated job_stats ========================================================== 15:20:18 (1752693618) [ 5915.889479] Lustre: DEBUG MARKER: == sanity test 851: fanotify can monitor open/read/write/close events for lustre fs ========================================================== 15:20:20 (1752693620) [ 5918.401059] Lustre: DEBUG MARKER: == sanity test 852: mkdir using intent lock for striped directory ========================================================== 15:20:23 (1752693623) [ 5920.730854] Lustre: DEBUG MARKER: == sanity test 853: Verify that random fadvise works as expected ========================================================== 15:20:25 (1752693625) [ 5931.536157] Lustre: DEBUG MARKER: == sanity test 900: umount should not race with any mgc requeue thread ========================================================== 15:20:36 (1752693636) [ 5948.901105] LustreError: MGC192.168.203.103@tcp: Connection to MGS (at 192.168.203.103@tcp) was lost; in progress operations using this service will fail [ 5948.906964] Lustre: Evicted from MGS (at 192.168.203.103@tcp) after server handle changed from 0xe47d86e684dffdb4 to 0xe47d86e684e12749 [ 5948.914659] LustreError: 2400:0:(client.c:3395:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff89bb905b5f80 x1837826437061504/t38654708692(38654708692) o101->lustre-MDT0000-mdc-ffff89bbbdec5800@192.168.203.103@tcp:12/10 lens 520/664 e 0 to 0 dl 1752693709 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'lfs.0' uid:0 gid:0 projid:0 [ 5948.920187] LustreError: 2400:0:(client.c:3395:ptlrpc_replay_interpret()) Skipped 4 previous similar messages [ 5950.688140] LustreError: 297447:0:(mgc_request.c:1780:mgc_process_log()) cfs_fail_timeout id 903 sleeping for 20000ms [ 5953.325794] Lustre: DEBUG MARKER: oleg303-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 5953.785619] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5970.760062] LustreError: 297447:0:(mgc_request.c:1780:mgc_process_log()) cfs_fail_timeout id 903 awake [ 5970.767067] LustreError: 297447:0:(mgc_request.c:1780:mgc_process_log()) cfs_fail_timeout id 903 sleeping for 20000ms [ 5990.840059] LustreError: 297447:0:(mgc_request.c:1780:mgc_process_log()) cfs_fail_timeout id 903 awake [ 5990.848706] LustreError: 297447:0:(mgc_request.c:1780:mgc_process_log()) cfs_fail_timeout id 903 sleeping for 20000ms [ 5990.850246] LustreError: 305511:0:(lov_obd.c:784:lov_cleanup()) lustre-clilov-ffff89bbbdec5800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 5990.853639] LustreError: 305511:0:(lov_obd.c:784:lov_cleanup()) Skipped 1 previous similar message [ 5990.855975] LustreError: 305511:0:(obd_class.h:479:obd_check_dev()) Device 6 not setup [ 5990.857402] LustreError: 305511:0:(obd_class.h:479:obd_check_dev()) Skipped 9 previous similar messages [ 5990.882181] Lustre: Unmounted lustre-client [ 6010.920067] LustreError: 297447:0:(mgc_request.c:1780:mgc_process_log()) cfs_fail_timeout id 903 awake [ 6010.922457] LustreError: 297447:0:(mgc_request.c:614:do_requeue()) failed processing log: -5 [ 6010.927243] LustreError: 305511:0:(obd_class.h:479:obd_check_dev()) Device 0 not setup [ 6010.929871] LustreError: 305511:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 6049.412950] Key type lgssc unregistered [ 6049.542744] LNet: 306171:0:(lib-ptl.c:966:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 6050.599560] LNet: Removed LNI 192.168.203.3@tcp [ 6050.894131] Key type .llcrypt unregistered [ 6050.895136] Key type ._llcrypt unregistered [ 6055.301431] Key type ._llcrypt registered [ 6055.302353] Key type .llcrypt registered [ 6055.584451] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [ 6055.588997] alg: No test for adler32 (adler32-zlib) [ 6056.551420] Lustre: Lustre: Build Version: 2.16.57_1_gf739d57 [ 6056.802175] LNet: Added LNI 192.168.203.3@tcp [8/256/0/180] [ 6056.803651] LNet: Accept secure, port 988 [ 6058.408121] Key type lgssc registered [ 6058.963141] Lustre: Echo OBD driver; http://www.lustre.org/ [ 6106.606181] Lustre: Mounted lustre-client [ 6109.194158] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 6118.157719] Lustre: DEBUG MARKER: == sanity test 901: don't leak a mgc lock on client umount ========================================================== 15:23:43 (1752693823) [ 6119.451876] LustreError: 309619:0:(lov_obd.c:784:lov_cleanup()) lustre-clilov-ffff89bbbf699000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 6119.457079] LustreError: 309619:0:(obd_class.h:479:obd_check_dev()) Device 6 not setup [ 6119.476294] Lustre: Unmounted lustre-client [ 6119.597491] Lustre: Mounted lustre-client [ 6121.796900] Lustre: DEBUG MARKER: == sanity test 902: test short write doesn't hang lustre ========================================================== 15:23:46 (1752693826) [ 6121.884248] Lustre: *** cfs_fail_loc=2001415, val=0*** [ 6124.183888] Lustre: DEBUG MARKER: == sanity test 903: Test long page discard does not cause evictions ========================================================== 15:23:49 (1752693829) [ 6130.488813] LustreError: 309644:0:(osc_cache.c:3385:osc_page_gang_lookup()) cfs_fail_timeout id 417 sleeping for 20000ms [ 6150.560060] LustreError: 309644:0:(osc_cache.c:3385:osc_page_gang_lookup()) cfs_fail_timeout id 417 awake [ 6150.572611] LustreError: 309644:0:(osc_cache.c:3385:osc_page_gang_lookup()) cfs_fail_timeout id 417 sleeping for 20000ms [ 6170.648061] LustreError: 309644:0:(osc_cache.c:3385:osc_page_gang_lookup()) cfs_fail_timeout id 417 awake [ 6170.660431] LustreError: 309644:0:(osc_cache.c:3385:osc_page_gang_lookup()) cfs_fail_timeout id 417 sleeping for 20000ms [ 6190.736059] LustreError: 309644:0:(osc_cache.c:3385:osc_page_gang_lookup()) cfs_fail_timeout id 417 awake [ 6190.748418] LustreError: 309644:0:(osc_cache.c:3385:osc_page_gang_lookup()) cfs_fail_timeout id 417 sleeping for 20000ms [ 6210.824059] LustreError: 309644:0:(osc_cache.c:3385:osc_page_gang_lookup()) cfs_fail_timeout id 417 awake [ 6210.836480] LustreError: 309644:0:(osc_cache.c:3385:osc_page_gang_lookup()) cfs_fail_timeout id 417 sleeping for 20000ms [ 6230.912062] LustreError: 309644:0:(osc_cache.c:3385:osc_page_gang_lookup()) cfs_fail_timeout id 417 awake [ 6230.924698] LustreError: 309644:0:(osc_cache.c:3385:osc_page_gang_lookup()) cfs_fail_timeout id 417 sleeping for 20000ms [ 6251.000059] LustreError: 309644:0:(osc_cache.c:3385:osc_page_gang_lookup()) cfs_fail_timeout id 417 awake [ 6263.534390] Lustre: DEBUG MARKER: == sanity test 904: virtual project ID xattr ============= 15:26:08 (1752693968) [ 6267.335803] Lustre: DEBUG MARKER: == sanity test 905: bad or new opcode should not stuck client ========================================================== 15:26:12 (1752693972) [ 6267.774670] LustreError: lustre-OST0001-osc-ffff89bbb79d9000: operation ost_ladvise to node 192.168.203.103@tcp failed: rc = -95 [ 6269.782680] Lustre: DEBUG MARKER: == sanity test 906: Simple test for io_uring I/O engine via fio ========================================================== 15:26:14 (1752693974) [ 6270.282421] Lustre: DEBUG MARKER: SKIP: sanity test_906 kernel does not support io_uring fully [ 6270.822245] Lustre: DEBUG MARKER: == sanity test 907: write rpc error during unlink ======== 15:26:15 (1752693975) [ 6272.397480] LustreError: lustre-OST0000-osc-ffff89bbb79d9000: operation ost_write to node 192.168.203.103@tcp failed: rc = -3 [ 6272.399815] LustreError: Skipped 3 previous similar messages [ 6274.451850] Lustre: DEBUG MARKER: == sanity test 908a: llog created with valid ctime ======= 15:26:19 (1752693979) [ 6276.987984] Lustre: DEBUG MARKER: == sanity test 908b: changelog stores valid mtime ======== 15:26:21 (1752693981) [ 6291.475865] Lustre: DEBUG MARKER: == sanity test complete, duration 6153 sec =============== 15:26:36 (1752693996) [ 6292.043345] Lustre: DEBUG MARKER: === sanity: start cleanup 15:26:37 (1752693997) === [ 6399.852532] Lustre: DEBUG MARKER: === sanity: finish cleanup 15:28:24 (1752694104) === [ 6400.153400] LustreError: 319837:0:(lov_obd.c:784:lov_cleanup()) lustre-clilov-ffff89bbb79d9000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 6400.158143] LustreError: 319837:0:(lov_obd.c:784:lov_cleanup()) Skipped 1 previous similar message [ 6400.165926] LustreError: 319837:0:(obd_class.h:479:obd_check_dev()) Device 6 not setup [ 6400.167948] LustreError: 319837:0:(obd_class.h:479:obd_check_dev()) Skipped 9 previous similar messages [ 6400.197999] Lustre: Unmounted lustre-client [ 6435.136748] Key type lgssc unregistered [ 6435.245463] LNet: 320515:0:(lib-ptl.c:966:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 6436.263086] LNet: Removed LNI 192.168.203.3@tcp [ 6436.513518] Key type .llcrypt unregistered [ 6436.514458] Key type ._llcrypt unregistered