[ 0.000000] Linux version 4.18.0rh8.10-debug (green@maintenance) (gcc version 8.5.0 20210514 (Red Hat 8.5.0-26) (GCC)) #2 SMP Mon Jul 14 01:24:22 EDT 2025 [ 0.000000] Command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers' [ 0.000000] x86/fpu: xstate_offset[2]: 576, xstate_sizes[2]: 256 [ 0.000000] x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'standard' format. [ 0.000000] signal: max sigframe size: 1776 [ 0.000000] BIOS-provided physical RAM map: [ 0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable [ 0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000000100000-0x00000000bffd9fff] usable [ 0.000000] BIOS-e820: [mem 0x00000000bffda000-0x00000000bfffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000100000000-0x0000000146dfffff] usable [ 0.000000] NX (Execute Disable) protection: active [ 0.000000] SMBIOS 2.8 present. [ 0.000000] DMI: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.17.0-8.fc42 06/10/2025 [ 0.000000] Hypervisor detected: KVM [ 0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00 [ 0.000000] kvm-clock: using sched offset of 370476480 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2399.998 MHz processor [ 0.000000] last_pfn = 0x146e00 max_arch_pfn = 0x400000000 [ 0.000000] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT [ 0.000000] last_pfn = 0xbffda max_arch_pfn = 0x400000000 [ 0.000000] found SMP MP-table at [mem 0x000f54d0-0x000f54df] [ 0.000000] RAMDISK: [mem 0xbcc64000-0xbffcffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F52F0 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE2421 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE22BD 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 00227D (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE2331 000090 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE23C1 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE23F9 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe22bd-0xbffe2330] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe22bc] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe2331-0xbffe23c0] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe23c1-0xbffe23f8] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe23f9-0xbffe2420] [ 0.000000] No NUMA configuration found [ 0.000000] Faking a node at [mem 0x0000000000000000-0x0000000146dfffff] [ 0.000000] NODE_DATA(0) allocated [mem 0x1465a3000-0x1465cdfff] [ 0.000000] Reserving 256MB of memory at 2752MB for crashkernel (System RAM: 4205MB) [ 0.000000] Zone ranges: [ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.000000] DMA32 [mem 0x0000000001000000-0x00000000ffffffff] [ 0.000000] Normal [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Device empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff] [ 0.000000] node 0: [mem 0x0000000000100000-0x00000000bffd9fff] [ 0.000000] node 0: [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Zeroed struct page in unavailable ranges: 4744 pages [ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x0000000146dfffff] [ 0.000000] ACPI: PM-Timer IO Port: 0x608 [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) [ 0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) [ 0.000000] Using ACPI (MADT) for SMP configuration information [ 0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000] TSC deadline timer available [ 0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs [ 0.000000] kvm-guest: KVM setup pv remote TLB flush [ 0.000000] kvm-guest: setup PV sched yield [ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff] [ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff] [ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff] [ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff] [ 0.000000] PM: Registered nosave memory: [mem 0xbffda000-0xbfffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xc0000000-0xfeffbfff] [ 0.000000] PM: Registered nosave memory: [mem 0xfeffc000-0xfeffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xff000000-0xfffbffff] [ 0.000000] PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff] [ 0.000000] [mem 0xc0000000-0xfeffbfff] available for PCI devices [ 0.000000] Booting paravirtualized kernel on KVM [ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns [ 0.000000] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1 [ 0.000000] percpu: Embedded 63 pages/cpu s221184 r8192 d28672 u524288 [ 0.000000] kvm-guest: PV spinlocks enabled [ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1059618 [ 0.000000] Policy zone: Normal [ 0.000000] Kernel command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] Specific versions of hardware are certified with Red Hat Enterprise Linux 8. Please see the list of hardware certified with Red Hat Enterprise Linux 8 at https://catalog.redhat.com. [ 0.000000] audit: disabled (until reboot) [ 0.000000] software IO TLB: area num 4. [ 0.000000] Memory: 2829700K/4306400K available (18435K kernel code, 11221K rwdata, 7248K rodata, 2908K init, 18040K bss, 524580K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] ftrace: allocating 41240 entries in 162 pages [ 0.000000] ftrace: allocated 162 pages with 3 groups [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] rcu: RCU event tracing is enabled. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ 0.000000] rcu: RCU callback double-/use-after-free debug enabled. [ 0.000000] Rude variant of Tasks RCU enabled. [ 0.000000] Tracing variant of Tasks RCU enabled. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 0.000000] NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16 [ 0.000000] random: get_random_bytes called from start_kernel+0x622/0x9a8 with crng_init=0 [ 0.001000] Console: colour *CGA 80x25 [ 0.001000] printk: console [ttyS1] enabled [ 0.001000] ACPI: Core revision 20220331 [ 0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.001013] APIC: Switch to symmetric I/O mode setup [ 0.002271] x2apic enabled [ 0.003004] Switched APIC routing to physical x2apic. [ 0.004006] kvm-guest: setup PV IPIs [ 0.006286] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.007000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.007011] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.008005] pid_max: default: 32768 minimum: 301 [ 0.009082] LSM: Security Framework initializing [ 0.010026] Yama: becoming mindful. [ 0.011020] SELinux: Initializing. [ 0.012041] *** VALIDATE selinux *** [ 0.018626] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.022082] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.023078] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.024058] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.025059] *** VALIDATE tmpfs *** [ 0.026332] *** VALIDATE proc *** [ 0.027160] *** VALIDATE cgroup *** [ 0.028004] *** VALIDATE cgroup2 *** [ 0.029141] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.030100] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.031003] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.032019] Spectre V2 : User space: Vulnerable [ 0.033003] Speculative Store Bypass: Vulnerable [ 0.037360] debug: unmapping init [mem 0xffffffffb4c59000-0xffffffffb4c60fff] [ 0.039821] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.040415] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.041012] ... version: 2 [ 0.041756] ... bit width: 48 [ 0.042006] ... generic registers: 4 [ 0.042755] ... value mask: 0000ffffffffffff [ 0.043005] ... max period: 00007fffffffffff [ 0.044005] ... fixed-purpose events: 3 [ 0.044688] ... event mask: 000000070000000f [ 0.045208] rcu: Hierarchical SRCU implementation. [ 0.047239] smp: Bringing up secondary CPUs ... [ 0.048379] x86: Booting SMP configuration: [ 0.049016] .... node #0, CPUs: #1 #2 #3 [ 0.051648] smp: Brought up 1 node, 4 CPUs [ 0.052758] smpboot: Max logical packages: 1 [ 0.053006] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.233021] node 0 deferred pages initialised in 179ms [ 0.236007] devtmpfs: initialized [ 0.236801] x86/mm: Memory block size: 128MB [ 0.238013] gcov: version magic: 0x41383552 [ 0.240225] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.241050] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.242224] pinctrl core: initialized pinctrl subsystem [ 0.243097] [ 0.243443] ************************************************************* [ 0.245009] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.246006] ** ** [ 0.247005] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.248005] ** ** [ 0.250006] ** This means that this kernel is built to expose internal ** [ 0.251008] ** IOMMU data structures, which may compromise security on ** [ 0.252005] ** your system. ** [ 0.254007] ** ** [ 0.255005] ** If you see this message and you are not debugging the ** [ 0.256006] ** kernel, report this immediately to your vendor! ** [ 0.257005] ** ** [ 0.259008] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.260005] ************************************************************* [ 0.261541] NET: Registered protocol family 16 [ 0.262315] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.264027] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.265026] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.268015] cpuidle: using governor menu [ 0.268928] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.271106] PCI: Using configuration type 1 for base access [ 0.272103] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.278124] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.280012] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.281109] cryptd: max_cpu_qlen set to 1000 [ 0.283105] ACPI: Added _OSI(Module Device) [ 0.283934] ACPI: Added _OSI(Processor Device) [ 0.285010] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.285867] ACPI: Added _OSI(Processor Aggregator Device) [ 0.288037] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.292558] ACPI: Interpreter enabled [ 0.293036] ACPI: PM: (supports S0 S3 S4 S5) [ 0.293852] ACPI: Using IOAPIC for interrupt routing [ 0.295041] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.297220] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.303751] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.305018] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.306008] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.308032] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.310859] acpiphp: Slot [2] registered [ 0.312073] acpiphp: Slot [5] registered [ 0.312958] acpiphp: Slot [6] registered [ 0.313059] acpiphp: Slot [3] registered [ 0.313894] acpiphp: Slot [4] registered [ 0.315042] acpiphp: Slot [7] registered [ 0.316043] acpiphp: Slot [8] registered [ 0.316833] acpiphp: Slot [9] registered [ 0.318057] acpiphp: Slot [10] registered [ 0.318845] acpiphp: Slot [11] registered [ 0.319042] acpiphp: Slot [12] registered [ 0.319892] acpiphp: Slot [13] registered [ 0.321043] acpiphp: Slot [14] registered [ 0.321889] acpiphp: Slot [15] registered [ 0.322042] acpiphp: Slot [16] registered [ 0.322875] acpiphp: Slot [17] registered [ 0.324044] acpiphp: Slot [18] registered [ 0.324846] acpiphp: Slot [19] registered [ 0.326043] acpiphp: Slot [20] registered [ 0.326836] acpiphp: Slot [21] registered [ 0.327114] acpiphp: Slot [22] registered [ 0.329100] acpiphp: Slot [23] registered [ 0.330065] acpiphp: Slot [24] registered [ 0.331086] acpiphp: Slot [25] registered [ 0.333065] acpiphp: Slot [26] registered [ 0.334065] acpiphp: Slot [27] registered [ 0.335065] acpiphp: Slot [28] registered [ 0.336068] acpiphp: Slot [29] registered [ 0.338084] acpiphp: Slot [30] registered [ 0.339081] acpiphp: Slot [31] registered [ 0.340060] PCI host bridge to bus 0000:00 [ 0.342015] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.344012] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.346012] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.348012] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.350012] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.352015] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.354164] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.356931] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.359170] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.366005] pci 0000:00:01.1: reg 0x20: [io 0xc120-0xc12f] [ 0.370049] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.373011] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.374010] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.377011] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.378512] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.380511] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.382021] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.383424] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.386008] pci 0000:00:02.0: reg 0x10: [io 0xc100-0xc11f] [ 0.391826] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.393969] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.396954] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.401006] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.404007] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.411014] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.417097] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.419878] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.422766] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.431012] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.437651] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.439248] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.441184] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.442201] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.444115] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.447111] iommu: Default domain type: Passthrough [ 0.448273] SCSI subsystem initialized [ 0.449062] ACPI: bus type USB registered [ 0.449926] usbcore: registered new interface driver usbfs [ 0.451030] usbcore: registered new interface driver hub [ 0.452053] usbcore: registered new device driver usb [ 0.453091] pps_core: LinuxPPS API ver. 1 registered [ 0.454006] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.456017] PTP clock support registered [ 0.457084] EDAC MC: Ver: 3.0.0 [ 0.458087] PCI: Using ACPI for IRQ routing [ 0.459515] NetLabel: Initializing [ 0.460005] NetLabel: domain hash size = 128 [ 0.460881] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.462047] NetLabel: unlabeled traffic allowed by default [ 0.463094] vgaarb: loaded [ 0.464217] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.465009] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.469209] clocksource: Switched to clocksource kvm-clock [ 0.547201] VFS: Disk quotas dquot_6.6.0 [ 0.548190] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.549662] *** VALIDATE ramfs *** [ 0.550335] *** VALIDATE hugetlbfs *** [ 0.551189] pnp: PnP ACPI init [ 0.552772] pnp: PnP ACPI: found 6 devices [ 0.565305] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.567104] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.568329] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.569475] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.570837] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.572173] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.573816] NET: Registered protocol family 2 [ 0.575296] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.578451] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.580502] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.584135] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.586104] TCP: Hash tables configured (established 65536 bind 65536) [ 0.587693] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.589435] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.591081] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.592673] NET: Registered protocol family 1 [ 0.594201] RPC: Registered named UNIX socket transport module. [ 0.595416] RPC: Registered udp transport module. [ 0.596363] RPC: Registered tcp transport module. [ 0.597314] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.598804] NET: Registered protocol family 44 [ 0.599713] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.600911] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.602077] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.603345] PCI: CLS 0 bytes, default 64 [ 0.604339] Unpacking initramfs... [ 1.790567] debug: unmapping init [mem 0xffff95313cc64000-0xffff95313ffcffff] [ 1.796712] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 1.798191] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 1.802494] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 2.245678] Initialise system trusted keyrings [ 2.247318] Key type blacklist registered [ 2.248962] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.255936] zbud: loaded [ 2.258257] *** VALIDATE nfs *** [ 2.259045] *** VALIDATE nfs4 *** [ 2.260019] pstore: using deflate compression [ 2.261951] Platform Keyring initialized [ 2.326639] NET: Registered protocol family 38 [ 2.327770] Key type asymmetric registered [ 2.329037] Asymmetric key parser 'x509' registered [ 2.330043] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 2.331646] io scheduler mq-deadline registered [ 2.332595] io scheduler kyber registered [ 2.333576] io scheduler bfq registered [ 2.334566] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 2.336287] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 2.338059] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 2.339603] ACPI: Power Button [PWRF] [ 2.342945] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 2.347233] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 2.354119] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 2.379516] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 2.404484] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 2.407879] Non-volatile memory driver v1.3 [ 2.409594] Linux agpgart interface v0.103 [ 2.430714] virtio_blk virtio1: [vda] 134224 512-byte logical blocks (68.7 MB/65.5 MiB) [ 2.432312] vda: detected capacity change from 0 to 68722688 [ 2.442370] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 2.445123] vdb: detected capacity change from 0 to 1073741824 [ 2.450359] libphy: Fixed MDIO Bus: probed [ 2.454476] usbcore: registered new interface driver usbserial_generic [ 2.456040] usbserial: USB Serial support registered for generic [ 2.458288] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 2.462329] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 2.464064] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 2.466336] mousedev: PS/2 mouse device common for all mice [ 2.468547] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 2.470682] rtc_cmos 00:05: RTC can wake from S4 [ 2.472817] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 2.474459] rtc_cmos 00:05: registered as rtc0 [ 2.477079] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 2.479938] intel_pstate: CPU model not supported [ 2.481911] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 2.484943] hid: raw HID events driver (C) Jiri Kosina [ 2.487071] usbcore: registered new interface driver usbhid [ 2.489183] usbhid: USB HID core driver [ 2.490807] drop_monitor: Initializing network drop monitor service [ 2.493221] Initializing XFRM netlink socket [ 2.495225] NET: Registered protocol family 10 [ 2.497856] Segment Routing with IPv6 [ 2.498804] NET: Registered protocol family 17 [ 2.500026] mpls_gso: MPLS GSO support [ 2.505935] RAS: Correctable Errors collector initialized. [ 2.508823] AVX version of gcm_enc/dec engaged. [ 2.509844] AES CTR mode by8 optimization enabled [ 2.559840] sched_clock: Marking stable (2559821413, 0)->(3208059663, -648238250) [ 2.562111] registered taskstats version 1 [ 2.563816] Loading compiled-in X.509 certificates [ 2.565161] zswap: loaded using pool lzo/zbud [ 2.583215] Key type big_key registered [ 2.591499] Key type encrypted registered [ 2.593092] ima: No TPM chip found, activating TPM-bypass! [ 2.595306] ima: Allocated hash algorithm: sha1 [ 2.596946] ima: No architecture policies found [ 2.598558] evm: Initialising EVM extended attributes: [ 2.600328] evm: security.selinux [ 2.601589] evm: security.ima [ 2.602658] evm: security.capability [ 2.603956] evm: HMAC attrs: 0x1 [ 2.606080] rtc_cmos 00:05: setting system clock to 2026-02-07 03:38:09 UTC (1770435489) [ 2.612497] debug: unmapping init [mem 0xffffffffb5c03000-0xffffffffb5dfffff] [ 2.615396] debug: unmapping init [mem 0xffffffffb4982000-0xffffffffb4c58fff] [ 2.628082] Write protecting the kernel read-only data: 28672k [ 2.631557] debug: unmapping init [mem 0xffffffffb3003000-0xffffffffb31fffff] [ 2.634357] debug: unmapping init [mem 0xffffffffb3914000-0xffffffffb39fffff] [ 2.664562] 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) [ 2.673271] systemd[1]: Detected virtualization kvm. [ 2.674454] systemd[1]: Detected architecture x86-64. [ 2.675861] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 2.700645] systemd[1]: No hostname configured. [ 2.701777] systemd[1]: Set hostname to . [ 2.703164] random: systemd: uninitialized urandom read (16 bytes read) [ 2.705044] systemd[1]: Initializing machine ID from random generator. [ 2.754396] random: ln: uninitialized urandom read (6 bytes read) [ 2.848963] random: systemd: uninitialized urandom read (16 bytes read) [ 2.852059] systemd[1]: Listening on udev Kernel Socket. [ OK ] Listening on udev Kernel Socket. [ 2.856884] systemd[1]: Reached target Local File Systems. [ OK ] Reached target Local File Systems. [ 2.861271] systemd[1]: Listening on Journal Socket (/dev/log). [ OK ] Listening on Journal Socket (/dev/log). [ OK ] Reached target Slices. [ OK ] Reached target Timers. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. [ OK ] Reached target Initrd Root Device. [ OK ] Listening on Journal Socket. Starting Journal Service... Starting Setup Virtual Console... Starting Create list of required st…ce nodes for the current kernel... Starting Create Volatile Files and Directories... [ OK ] Started Memstrack Anylazing Service. [ OK ] Listening on udev Control Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Swap. Starting Apply Kernel Variables... [ OK ] Started Setup Virtual Console. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Journal Service. [ OK ] Started Apply Kernel Variables. Starting Create Static Device Nodes in /dev... Starting dracut cmdline hook... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 3.428104] device-mapper: uevent: version 1.0.3 [ 3.429517] device-mapper: ioctl: 4.46.0-ioctl (2022-02-22) initialised: dm-devel@redhat.com [ OK ] Started dracut pre-udev hook. Starting udev Kernel Device Manager... [ OK ] Started udev Kernel Device Manager. Starting dracut pre-trigger hook... [ OK ] Started dracut pre-trigger hook. Starting udev Coldplug all Devices... Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. Starting dracut initqueue hook... [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ 3.994925] virtio_net virtio0 ens2: renamed from eth0 [ 4.052498] random: fast init done [ 4.101615] scsi host0: ata_piix [ 4.113143] scsi host1: ata_piix [ 4.114587] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc120 irq 14 [ 4.117099] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc128 irq 15 [ 8.174364] dracut-initqueue[588]: RTNETLINK answers: File exists [ 9.205943] random: crng init done [ 9.208283] random: 7 urandom warning(s) missed due to ratelimiting 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. [ 9.970223] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped target Timers. [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target 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 Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target System Initialization. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. [ OK ] Stopped Apply Kernel Variables. Stopping udev Kernel Device Manager... [ OK ] Stopped target Swap. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. [ OK ] Stopped target Slices. [ OK ] Stopped target Paths. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped target Sockets. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Closed udev Kernel Socket. [ OK ] Closed udev Control Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 11.385918] printk: systemd: 21 output lines suppressed due to ratelimiting [ 11.834337] SELinux: Disabled at runtime. [ 11.901155] 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) [ 11.908295] systemd[1]: Detected virtualization kvm. [ 11.909926] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 12.779864] systemd[1]: initrd-switch-root.service: Succeeded. [ 12.783091] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 12.787870] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 12.791513] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 12.794794] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 12.802722] systemd[1]: Starting Journal Service... Starting Journal Service... [ 12.806476] systemd[1]: proc-sys-fs-binfmt_misc.automount: Refusing to start, unit to trigger not loaded. [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Listening on udev Kernel Socket. Starting Remount Root and Kernel File Systems... [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Stopped target Switch Root. [ OK ] Created slice User and Session Slice. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Listening on initctl Compatibility Named Pipe. Activating swap /dev/disk/by-label/SWAP... [ OK ] Listening on udev Control Socket. Starting udev Coldplug all Devices... [ OK ] Reached target Slices. [ OK ] Stopped target Initrd File Systems. Mounting Huge Pages File System... [ OK ] Started Forward Password Requests to Wall Directory Watch. [ 12.918717] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS [ OK ] Reached target Paths. [ OK ] Listening on Process Core Dump Socket. Starting Apply Kernel Variables... [ OK ] Reached target rpc_pipefs.target. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Created slice system-getty.slice. [ OK ] Stopped target Initrd Root File System. Mounting Kernel Debug File System... Mounting POSIX Message Queue File System... [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Reached target RPC Port Mapper. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Started Journal Service. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Mounted Huge Pages File System. [ OK ] Started Apply Kernel Variables. [ OK ] Mounted Kernel Debug File System. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Reached target Swap. Starting Configure read-only root support... Starting Create Static Device Nodes in /dev... Starting Flush Journal to Persistent Storage... [ OK ] Started udev Coldplug all Devices. [ OK ] Started Flush Journal to Persistent Storage. [ 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. [ 13.501775] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 14.057710] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 14.076459] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 14.466481] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 14.585851] EDAC sbridge: Ver: 1.1.2 [ 15.998470] Key type dns_resolver registered [ 16.326297] NFS: Registering the id_resolver key type [ 16.328380] Key type id_resolver registered [ 16.329978] Key type id_legacy registered [ OK ] Started Configure read-only root support. [ OK ] Reached target Local File Systems. Starting Create Volatile Files and Directories... Starting Rebuild Dynamic Linker Cache... Starting Mark the need to relabel after reboot... Starting Load/Save Random Seed... [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Load/Save Random Seed. [ OK ] Started Create Volatile Files and Directories. Starting RPC Bind... Starting Update UTMP about System Boot/Shutdown... [ OK ] Started RPC Bind. [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Started dnf makecache --timer. [ OK ] Reached target Timers. [ OK ] Reached target Basic System. Starting Login Service... Starting Restore /run/initramfs on shutdown... [ OK ] Reached target sshd-keygen.target. [ OK ] Started D-Bus System Message Bus. Starting Network Manager... [ OK ] Started irqbalance daemon. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Login Service. [ OK ] Started Network Manager. Starting Network Manager Wait Online... [ OK ] Reached target Network. Starting GSSAPI Proxy Daemon... Starting Dynamic System Tuning Daemon... Starting OpenSSH server daemon... 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 OpenSSH server daemon. [ OK ] Started Permit User Sessions. [ OK ] Started Command Scheduler. [ OK ] Started Serial Getty on ttyS1. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Getty on tty1. [ OK ] Reached target Login Prompts. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting Notify NFS peers of a restart... Starting System Logging Service... Starting Crash recovery kernel arming... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Starting Authorization Manager... Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg321-client login: [ 43.407103] libcfs: loading out-of-tree module taints kernel. [ 43.498258] Key type ._llcrypt registered [ 43.507249] Key type .llcrypt registered [ 43.684647] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [ 43.689972] alg: No test for adler32 (adler32-zlib) [ 44.625327] Lustre: Lustre: Build Version: 2.17.50_44_g630b48b [ 44.854340] LNet: Added LNI 192.168.203.21@tcp [8/256/0/180] [ 46.447132] Key type lgssc registered [ 46.916993] Lustre: Echo OBD driver; http://www.lustre.org/ [ 102.788113] Lustre: Mounted lustre-client [ 105.141294] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 119.762112] Lustre: DEBUG MARKER: oleg321-client.virtnet: executing check_logdir /tmp/testlogs/ [ 121.212537] Lustre: DEBUG MARKER: oleg321-client.virtnet: executing yml_node [ 122.487350] Lustre: DEBUG MARKER: Client: 2.17.50.44 [ 123.280243] Lustre: DEBUG MARKER: MDS: 2.17.50.44 [ 124.033523] Lustre: DEBUG MARKER: OSS: 2.17.50.44 [ 124.504206] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity ============----- Fri Feb 6 22:40:10 EST 2026 [ 128.480160] Lustre: lustre-OST0000-osc-ffff9531890ec800: disconnect after 24s idle [ 129.845241] Lustre: DEBUG MARKER: - need MDS1_VERSION <= 2.14.55-100-g8a84c7f9c7 (34681388 <= 34486116) for LU-14927, skip 0f [ 130.355420] Lustre: DEBUG MARKER: - need MDS1_VERSION < v2_14_55-100-g8a84c7f9c7 (34681388 < 34486116) for LU-14927, skip 0f [ 130.870173] Lustre: DEBUG MARKER: excepting tests: 225 255 256 400a 42a 42c 42b 118c 118d 407 119i 817 411a [ 131.376473] Lustre: DEBUG MARKER: skipping tests SLOW=no: 27m 60i 64b 68 71 135 136 230d 300o 842 [ 131.906197] Lustre: DEBUG MARKER: === sanity: start setup 22:40:18 (1770435618) === [ 133.165553] Lustre: DEBUG MARKER: oleg321-client.virtnet: executing check_config_client /mnt/lustre [ 139.429461] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 143.456422] Lustre: DEBUG MARKER: === sanity: finish setup 22:40:29 (1770435629) === [ 146.660196] Lustre: DEBUG MARKER: == sanity test 200: OST pools ============================ 22:40:33 (1770435633) [ 162.847808] Lustre: DEBUG MARKER: == sanity test 204a: Print default stripe attributes ===== 22:40:49 (1770435649) [ 165.126513] Lustre: DEBUG MARKER: == sanity test 204b: Print default stripe size and offset ========================================================== 22:40:51 (1770435651) [ 167.491333] Lustre: DEBUG MARKER: == sanity test 204c: Print default stripe count and offset ========================================================== 22:40:53 (1770435653) [ 169.971102] Lustre: DEBUG MARKER: == sanity test 204d: Print default stripe count and size ========================================================== 22:40:56 (1770435656) [ 172.200598] Lustre: DEBUG MARKER: == sanity test 204e: Print raw stripe attributes ========= 22:40:58 (1770435658) [ 174.657182] Lustre: DEBUG MARKER: == sanity test 204f: Print raw stripe size and offset ==== 22:41:00 (1770435660) [ 177.070448] Lustre: DEBUG MARKER: == sanity test 204g: Print raw stripe count and offset === 22:41:03 (1770435663) [ 179.420398] Lustre: DEBUG MARKER: == sanity test 204h: Print raw stripe count and size ===== 22:41:05 (1770435665) [ 181.793692] Lustre: DEBUG MARKER: == sanity test 205a: Verify job stats ==================== 22:41:08 (1770435668) [ 184.800255] Lustre: lustre-OST0000-osc-ffff9531890ec800: disconnect after 24s idle [ 184.804443] Lustre: Skipped 1 previous similar message [ 187.568486] Lustre: DEBUG MARKER: Test: /home/green/git/lustre-release/lustre/utils/lfs mkdir -i 0 -c 1 /mnt/lustre/d205a.sanity [ 188.125481] Lustre: DEBUG MARKER: Using JobID environment nodelocal=id.205a.lfs.18388 [ 188.922419] Lustre: DEBUG MARKER: Test: rmdir /mnt/lustre/d205a.sanity [ 189.444887] Lustre: DEBUG MARKER: Using JobID environment nodelocal=id.205a.rmdir.20257 [ 190.231118] Lustre: DEBUG MARKER: Test: lfs mkdir -i 1 /mnt/lustre/d205a.sanity.remote [ 190.719276] Lustre: DEBUG MARKER: Using JobID environment nodelocal=id.205a.lfs.3930 [ 191.546804] Lustre: DEBUG MARKER: Test: mknod /mnt/lustre/f205a.sanity c 1 3 [ 192.053391] Lustre: DEBUG MARKER: Using JobID environment nodelocal=id.205a.mknod.6057 [ 192.870485] Lustre: DEBUG MARKER: Test: rm -f /mnt/lustre/f205a.sanity [ 193.374914] Lustre: DEBUG MARKER: Using JobID environment nodelocal=id.205a.rm.25151 [ 194.196043] Lustre: DEBUG MARKER: Test: /home/green/git/lustre-release/lustre/utils/lfs setstripe -i 0 -c 1 /mnt/lustre/f205a.sanity [ 194.758702] Lustre: DEBUG MARKER: Using JobID environment nodelocal=id.205a.lfs.18182 [ 195.752438] Lustre: DEBUG MARKER: Test: touch /mnt/lustre/f205a.sanity [ 196.474550] Lustre: DEBUG MARKER: Using JobID environment nodelocal=id.205a.touch.2094 [ 197.650582] Lustre: DEBUG MARKER: Test: dd if=/dev/zero of=/mnt/lustre/f205a.sanity bs=1M count=1 oflag=sync [ 198.195827] Lustre: DEBUG MARKER: Using JobID environment nodelocal=id.205a.dd.10275 [ 199.069729] Lustre: DEBUG MARKER: Test: dd if=/mnt/lustre/f205a.sanity of=/dev/null bs=1M count=1 iflag=direct [ 199.577337] Lustre: DEBUG MARKER: Using JobID environment nodelocal=id.205a.dd.13971 [ 200.385819] Lustre: DEBUG MARKER: Test: /home/green/git/lustre-release/lustre/tests/truncate /mnt/lustre/f205a.sanity 0 [ 200.869072] Lustre: DEBUG MARKER: Using JobID environment nodelocal=id.205a.truncate.4753 [ 201.966888] Lustre: DEBUG MARKER: Test: mv -f /mnt/lustre/f205a.sanity /mnt/lustre/d205a.sanity.rename [ 202.474672] Lustre: DEBUG MARKER: Using JobID environment nodelocal=id.205a.mv.5245 [ 203.269975] Lustre: DEBUG MARKER: Test: /home/green/git/lustre-release/lustre/utils/lfs mkdir -i 0 -c 1 /mnt/lustre/d205a.sanity.expire [ 203.762098] Lustre: DEBUG MARKER: Using JobID environment nodelocal=id.205a.lfs.13864 [ 207.574466] Lustre: DEBUG MARKER: Test: touch /mnt/lustre/f205a.sanity [ 208.107202] Lustre: DEBUG MARKER: Using JobID environment USER=S.root.touch.0.oleg321-client.v [ 208.909870] Lustre: DEBUG MARKER: Test: touch /mnt/lustre/f205a.sanity [ 209.389635] Lustre: DEBUG MARKER: Using JobID environment USER=S.root.touch.0.oleg321-client.E [ 210.175126] Lustre: DEBUG MARKER: Test: touch /mnt/lustre/f205a.sanity [ 210.675222] Lustre: DEBUG MARKER: Using JobID environment session=S.root.touch.0.oleg321-client.v [ 217.393893] Lustre: DEBUG MARKER: == sanity test 205b: Verify job stats jobid and output format ========================================================== 22:41:43 (1770435703) [ 221.270556] Lustre: DEBUG MARKER: == sanity test 205c: Verify client stats format ========== 22:41:47 (1770435707) [ 223.506768] Lustre: DEBUG MARKER: == sanity test 205d: verify the format of some stats files ========================================================== 22:41:49 (1770435709) [ 228.168993] Lustre: DEBUG MARKER: == sanity test 205e: verify the output of lljobstat ====== 22:41:54 (1770435714) [ 233.292627] Lustre: DEBUG MARKER: == sanity test 205f: verify qos_ost_weights YAML format == 22:41:59 (1770435719) [ 236.119854] Lustre: DEBUG MARKER: == sanity test 205g: stress test for job_stats procfile == 22:42:02 (1770435722) [ 330.427131] Lustre: DEBUG MARKER: == sanity test 205h: check jobid xattr is stored correctly ========================================================== 22:43:36 (1770435816) [ 335.469598] Lustre: DEBUG MARKER: == sanity test 205i: check job_xattr parameter accepts and rejects values correctly ========================================================== 22:43:41 (1770435821) [ 341.388742] Lustre: DEBUG MARKER: == sanity test 205k: Verify '?' operator on job stats ==== 22:43:47 (1770435827) [ 345.714977] Lustre: DEBUG MARKER: == sanity test 205l: Verify job stats can scale ========== 22:43:52 (1770435832) [ 390.024981] Lustre: DEBUG MARKER: == sanity test 205m: Test width parsing of job_stats ===== 22:44:36 (1770435876) [ 396.280264] Lustre: DEBUG MARKER: == sanity test 206: fail lov_init_raid0() doesn't lbug === 22:44:42 (1770435882) [ 396.353870] Lustre: *** cfs_fail_loc=1403, val=1*** [ 396.356100] LustreError: 52392:0:(lcommon_cl.c:187:cl_file_inode_init()) lustre: failed to initialize cl_object [0x200000402:0x103c:0x0]: rc = -5 [ 396.362861] LustreError: 52392:0:(llite_lib.c:3782:ll_prep_inode()) lustre: new_inode - fatal error: rc = -5 [ 398.722370] Lustre: DEBUG MARKER: == sanity test 207a: can refresh layout at glimpse ======= 22:44:45 (1770435885) [ 401.048609] Lustre: DEBUG MARKER: == sanity test 207b: can refresh layout at open ========== 22:44:47 (1770435887) [ 403.381984] Lustre: DEBUG MARKER: == sanity test 208: Exclusive open ======================= 22:44:49 (1770435889) [ 415.201255] Lustre: lustre-MDT0000-mdc-ffff9531890ec800: Connection to lustre-MDT0000 (at 192.168.203.121@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 425.440100] Lustre: lustre-OST0000-osc-ffff9531890ec800: disconnect after 24s idle [ 425.441283] LustreError: MGC192.168.203.121@tcp: Connection to MGS (at 192.168.203.121@tcp) was lost; in progress operations using this service will fail [ 425.442580] Lustre: Skipped 1 previous similar message [ 425.449368] Lustre: Evicted from MGS (at 192.168.203.121@tcp) after server handle changed from 0x115a18b47cd99638 to 0x115a18b47cdecaa7 [ 425.453483] Lustre: MGC192.168.203.121@tcp: Connection restored to 192.168.203.121@tcp (at 192.168.203.121@tcp) [ 425.454326] LustreError: 2412:0:(mdc_request.c:667:mdc_replay_open()) @@@ cannot properly replay without open data req@ffff95318811c700 x1856436212460160/t4294980889(4294980889) o101->lustre-MDT0000-mdc-ffff9531890ec800@192.168.203.121@tcp:12/10 lens 608/608 e 0 to 0 dl 1770435928 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'touch.0' uid:0 gid:0 projid:0 [ 425.462101] LustreError: 2412:0:(client.c:3418:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff95318811c700 x1856436212460160/t4294980889(4294980889) o101->lustre-MDT0000-mdc-ffff9531890ec800@192.168.203.121@tcp:12/10 lens 608/608 e 0 to 0 dl 1770435928 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'touch.0' uid:0 gid:0 projid:0 [ 428.658759] Lustre: lustre-MDT0000-mdc-ffff9531890ec800: Connection restored to 192.168.203.121@tcp (at 192.168.203.121@tcp) [ 429.880993] Lustre: DEBUG MARKER: oleg321-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 430.531460] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 435.682187] Lustre: lustre-MDT0000-mdc-ffff9531890ec800: Connection to lustre-MDT0000 (at 192.168.203.121@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 451.042069] LustreError: MGC192.168.203.121@tcp: Connection to MGS (at 192.168.203.121@tcp) was lost; in progress operations using this service will fail [ 451.047993] Lustre: Evicted from MGS (at 192.168.203.121@tcp) after server handle changed from 0x115a18b47cdecaa7 to 0x115a18b47cdecf5b [ 451.051170] Lustre: MGC192.168.203.121@tcp: Connection restored to 192.168.203.121@tcp (at 192.168.203.121@tcp) [ 451.056605] LustreError: 2412:0:(mdc_request.c:667:mdc_replay_open()) @@@ cannot properly replay without open data req@ffff95318811c700 x1856436212460160/t4294980889(4294980889) o101->lustre-MDT0000-mdc-ffff9531890ec800@192.168.203.121@tcp:12/10 lens 608/608 e 0 to 0 dl 1770435953 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'touch.0' uid:0 gid:0 projid:0 [ 451.068144] LustreError: 2412:0:(client.c:3418:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff953198670700 x1856436212480512/t8589934595(8589934595) o101->lustre-MDT0000-mdc-ffff9531890ec800@192.168.203.121@tcp:12/10 lens 584/608 e 0 to 0 dl 1770435953 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'multiop.0' uid:0 gid:0 projid:0 [ 451.076737] LustreError: 2412:0:(client.c:3418:ptlrpc_replay_interpret()) Skipped 2 previous similar messages [ 453.747669] Lustre: DEBUG MARKER: oleg321-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 454.428685] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 459.457537] Lustre: DEBUG MARKER: == sanity test 209: read-only open/close requests should be freed promptly ========================================================== 22:45:45 (1770435945) [ 464.934652] bash (56145): drop_caches: 3 [ 468.178888] bash (56145): drop_caches: 3 [ 471.671914] Lustre: DEBUG MARKER: == sanity test 210: lfs getstripe does not break leases == 22:45:57 (1770435957) [ 476.963483] Lustre: DEBUG MARKER: == sanity test 212: Sendfile test ====================================================================================================== 22:46:03 (1770435963) [ 482.410460] Lustre: DEBUG MARKER: == sanity test 213: OSC lock completion and cancel race don't crash - bug 18829 ========================================================== 22:46:08 (1770435968) [ 482.562237] LustreError: 2416:0:(osc_request.c:3220:osc_enqueue_interpret()) cfs_fail_timeout id 40f sleeping for 10000ms [ 492.575083] LustreError: 2416:0:(osc_request.c:3220:osc_enqueue_interpret()) cfs_fail_timeout id 40f awake [ 495.655963] Lustre: DEBUG MARKER: == sanity test 214: hash-indexed directory test - bug 20133 ========================================================== 22:46:22 (1770435982) [ 512.737328] Lustre: DEBUG MARKER: == sanity test 215: lnet exists and has proper content - bugs 18102, 21079, 21517 ========================================================== 22:46:38 (1770435998) [ 516.280389] Lustre: DEBUG MARKER: == sanity test 216: check lockless direct write updates file size and kms correctly ========================================================== 22:46:42 (1770436002) [ 525.256268] Lustre: DEBUG MARKER: == sanity test 217: check lctl ping for hostnames with embedded hyphen ('-') ========================================================== 22:46:51 (1770436011) [ 529.737465] Lustre: DEBUG MARKER: == sanity test 218: parallel read and truncate should not deadlock ========================================================== 22:46:56 (1770436016) [ 530.450912] Lustre: DEBUG MARKER: creating a 10 Mb file [ 543.200512] Lustre: lustre-OST0000-osc-ffff9531890ec800: disconnect after 21s idle [ 543.914973] Lustre: DEBUG MARKER: starting reads [ 544.795358] Lustre: DEBUG MARKER: truncating the file [ 545.512630] Lustre: DEBUG MARKER: killing dd [ 546.239880] Lustre: DEBUG MARKER: removing the temporary file [ 549.089302] Lustre: DEBUG MARKER: == sanity test 219: LU-394: Write partial won't cause uncontiguous pages vec at LND ========================================================== 22:47:15 (1770436035) [ 549.217226] Lustre: *** cfs_fail_loc=411, val=0*** [ 552.085701] Lustre: DEBUG MARKER: == sanity test 220: preallocated MDS objects still used if ENOSPC from OST ========================================================== 22:47:18 (1770436038) [ 567.119413] Lustre: DEBUG MARKER: == sanity test 221: make sure fault and truncate race to not cause OOM ========================================================== 22:47:33 (1770436053) [ 572.784332] Lustre: DEBUG MARKER: == sanity test 222a: AGL for ls should not trigger CLIO lock failure ========================================================== 22:47:38 (1770436058) [ 576.776286] Lustre: DEBUG MARKER: == sanity test 222b: AGL for rmdir should not trigger CLIO lock failure ========================================================== 22:47:42 (1770436062) [ 580.620604] Lustre: DEBUG MARKER: == sanity test 223: osc reenqueue if without AGL lock granted ================================================================================= 22:47:46 (1770436066) [ 584.378638] Lustre: DEBUG MARKER: == sanity test 224a: Don't panic on bulk IO failure ====== 22:47:50 (1770436070) [ 584.517244] Lustre: *** cfs_fail_loc=508, val=2147483648*** [ 584.522493] LustreError: 2406:0:(events.c:192:client_bulk_callback()) event type 1, status -5, req ffff95318a82df80 desc ffff953198335400 mbits 1856436213136640 [ 584.527828] Lustre: 2413:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has failed due to network error: [sent 1770436071/real 1770436071] req@ffff95318a82df80 x1856436213136640/t4294971774(4294971774) o4->lustre-OST0001-osc-ffff9531890ec800@192.168.203.121@tcp:6/4 lens 488/448 e 0 to 1 dl 1770436087 ref 3 fl Bulk:ReXQU/604/0 rc 0/0 job:'dd.0' uid:0 gid:0 projid:0 [ 584.547938] Lustre: lustre-OST0001-osc-ffff9531890ec800: Connection to lustre-OST0001 (at 192.168.203.121@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 584.563598] Lustre: lustre-OST0001-osc-ffff9531890ec800: Connection restored to 192.168.203.121@tcp (at 192.168.203.121@tcp) [ 584.567336] Lustre: Skipped 1 previous similar message [ 588.905164] LustreError: 2413:0:(client.c:2349:ptlrpc_check_set()) @@@ bulk transfer failed 0/1048576/0 req@ffff95318a82df80 x1856436213136640/t4294971774(4294971774) o4->lustre-OST0001-osc-ffff9531890ec800@192.168.203.121@tcp:6/4 lens 488/448 e 0 to 1 dl 1770436087 ref 3 fl Bulk:ReXQU/604/0 rc 0/0 job:'dd.0' uid:0 gid:0 projid:0 [ 588.917976] LustreError: 2413:0:(osc_request.c:2516:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff95318a82df80 x1856436213136640/t4294971774(4294971774) o4->lustre-OST0001-osc-ffff9531890ec800@192.168.203.121@tcp:6/4 lens 488/448 e 0 to 1 dl 1770436087 ref 3 fl Interpret:ReXQU/604/0 rc -5/0 job:'dd.0' uid:0 gid:0 projid:0 [ 593.384510] Lustre: DEBUG MARKER: == sanity test 224b: Don't panic on bulk IO failure ====== 22:47:59 (1770436079) [ 603.843299] Lustre: DEBUG MARKER: == sanity test 224c: Don't hang if one of md lost during large bulk RPC ========================================================== 22:48:09 (1770436089) [ 613.343692] Lustre: lustre-OST0001-osc-ffff9531890ec800: disconnect after 20s idle [ 615.327185] Lustre: 2416:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1770436097/real 1770436097] req@ffff953191aab100 x1856436213151872/t0(0) o4->lustre-OST0000-osc-ffff9531890ec800@192.168.203.121@tcp:6/4 lens 488/448 e 0 to 1 dl 1770436102 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'dd.0' uid:0 gid:0 projid:0 [ 615.343065] Lustre: lustre-OST0000-osc-ffff9531890ec800: Connection to lustre-OST0000 (at 192.168.203.121@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 615.364087] Lustre: lustre-OST0000-osc-ffff9531890ec800: Connection restored to 192.168.203.121@tcp (at 192.168.203.121@tcp) [ 624.243916] Lustre: DEBUG MARKER: == sanity test 224d: Don't corrupt data on bulk IO timeout ========================================================== 22:48:30 (1770436110) [ 647.135154] Lustre: 2415:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1770436113/real 1770436113] req@ffff953191aa8000 x1856436213165056/t0(0) o3->lustre-OST0000-osc-ffff9531890ec800@192.168.203.121@tcp:6/4 lens 488/440 e 0 to 1 dl 1770436133 ref 2 fl Bulk:RXMQU/600/0 rc 0/0 job:'dd.0' uid:0 gid:0 projid:0 [ 647.142911] Lustre: lustre-OST0000-osc-ffff9531890ec800: Connection to lustre-OST0000 (at 192.168.203.121@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 647.147045] LustreError: 2415:0:(client.c:2349:ptlrpc_check_set()) @@@ bulk transfer failed 0/1048576/0 req@ffff953191aa8000 x1856436213165056/t0(0) o3->lustre-OST0000-osc-ffff9531890ec800@192.168.203.121@tcp:6/4 lens 488/440 e 0 to 1 dl 1770436133 ref 2 fl Bulk:ReXMQU/600/0 rc 0/0 job:'dd.0' uid:0 gid:0 projid:0 [ 647.153555] LustreError: 2415:0:(osc_request.c:2516:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff953191aa8000 x1856436213165056/t0(0) o3->lustre-OST0000-osc-ffff9531890ec800@192.168.203.121@tcp:6/4 lens 488/440 e 0 to 1 dl 1770436133 ref 2 fl Interpret:ReXMQU/600/0 rc -5/0 job:'dd.0' uid:0 gid:0 projid:0 [ 647.154463] Lustre: lustre-OST0000-osc-ffff9531890ec800: Connection restored to 192.168.203.121@tcp (at 192.168.203.121@tcp) [ 652.503898] Lustre: DEBUG MARKER: SKIP: sanity test_225a skipping excluded test 225a (base 225) [ 653.241120] Lustre: DEBUG MARKER: SKIP: sanity test_225b skipping excluded test 225b (base 225) [ 653.906532] Lustre: DEBUG MARKER: == sanity test 226a: call path2fid and fid2path on files of all type ========================================================== 22:49:00 (1770436140) [ 657.489930] Lustre: DEBUG MARKER: == sanity test 226b: call path2fid and fid2path on files of all type under remote dir ========================================================== 22:49:03 (1770436143) [ 660.679910] Lustre: DEBUG MARKER: == sanity test 226c: call path2fid and fid2path under remote dir with subdir mount ========================================================== 22:49:06 (1770436146) [ 661.054913] Lustre: Mounted lustre-client [ 661.152854] LustreError: 72194:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff9531a0521000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 661.163555] LustreError: 72194:0:(obd_class.h:479:obd_check_dev()) Device 12 not setup [ 661.200530] Lustre: Unmounted lustre-client [ 663.722450] LustreError: 72654:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff9531a0523000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 663.727254] LustreError: 72654:0:(lov_obd.c:783:lov_cleanup()) Skipped 1 previous similar message [ 663.734148] LustreError: 72654:0:(obd_class.h:479:obd_check_dev()) Device 12 not setup [ 663.737016] LustreError: 72654:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 663.773204] Lustre: Unmounted lustre-client [ 664.553864] Lustre: DEBUG MARKER: == sanity test 226d: verify fid2path with -n and -fn option ========================================================== 22:49:10 (1770436150) [ 667.914867] Lustre: DEBUG MARKER: == sanity test 226e: Verify path2fid -0 option with newline and space ========================================================== 22:49:14 (1770436154) [ 670.495265] Lustre: DEBUG MARKER: == sanity test 227: running truncated executable does not cause OOM ========================================================== 22:49:16 (1770436156) [ 673.613915] Lustre: DEBUG MARKER: == sanity test 228a: try to reuse idle OI blocks ========= 22:49:19 (1770436159) [ 674.713960] Lustre: *** cfs_fail_loc=1002, val=0*** [ 697.312102] Lustre: lustre-OST0001-osc-ffff9531890ec800: disconnect after 22s idle [ 757.427205] Lustre: DEBUG MARKER: == sanity test 228b: idle OI blocks can be reused after MDT restart ========================================================== 22:50:43 (1770436243) [ 758.847059] Lustre: *** cfs_fail_loc=1002, val=0*** [ 820.191324] Lustre: lustre-OST0001-osc-ffff9531890ec800: disconnect after 23s idle [ 830.434176] LustreError: MGC192.168.203.121@tcp: Connection to MGS (at 192.168.203.121@tcp) was lost; in progress operations using this service will fail [ 830.434355] Lustre: lustre-MDT0000-mdc-ffff9531890ec800: Connection to lustre-MDT0000 (at 192.168.203.121@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 830.443095] Lustre: Evicted from MGS (at 192.168.203.121@tcp) after server handle changed from 0x115a18b47cdecf5b to 0x115a18b47cf60734 [ 830.446874] Lustre: MGC192.168.203.121@tcp: Connection restored to 192.168.203.121@tcp (at 192.168.203.121@tcp) [ 830.458579] LustreError: 2412:0:(mdc_request.c:667:mdc_replay_open()) @@@ cannot properly replay without open data req@ffff95318811c700 x1856436212460160/t4294980889(4294980889) o101->lustre-MDT0000-mdc-ffff9531890ec800@192.168.203.121@tcp:12/10 lens 608/608 e 0 to 0 dl 1770436333 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'touch.0' uid:0 gid:0 projid:0 [ 855.620576] Lustre: DEBUG MARKER: == sanity test 228c: NOT shrink the last entry in OI index node to recycle idle leaf ========================================================== 22:52:21 (1770436341) [ 856.031898] Lustre: lustre-OST0001-osc-ffff9531890ec800: disconnect after 20s idle [ 857.018408] Lustre: *** cfs_fail_loc=1002, val=0*** [ 953.311261] Lustre: lustre-OST0001-osc-ffff9531890ec800: disconnect after 20s idle [ 1000.788850] Lustre: DEBUG MARKER: == sanity test 229: getstripe/stat/rm/attr changes work on released files ========================================================== 22:54:46 (1770436486) [ 1003.650752] Lustre: DEBUG MARKER: == sanity test 230a: Create remote directory and files under the remote directory ========================================================== 22:54:49 (1770436489) [ 1006.681531] Lustre: DEBUG MARKER: == sanity test 230b: migrate directory =================== 22:54:52 (1770436492) [ 1029.348296] Lustre: DEBUG MARKER: == sanity test 230c: check directory accessiblity if migration failed ========================================================== 22:55:15 (1770436515) [ 1036.856130] Lustre: DEBUG MARKER: SKIP: sanity test_230d skipping SLOW test 230d [ 1037.451190] Lustre: DEBUG MARKER: == sanity test 230e: migrate mulitple local link files === 22:55:23 (1770436523) [ 1041.700804] Lustre: DEBUG MARKER: == sanity test 230f: migrate mulitple remote link files == 22:55:27 (1770436527) [ 1046.380165] Lustre: DEBUG MARKER: == sanity test 230g: migrate dir to non-exist MDT ======== 22:55:32 (1770436532) [ 1049.495400] Lustre: DEBUG MARKER: == sanity test 230h: migrate .. and root ================= 22:55:35 (1770436535) [ 1052.926909] Lustre: DEBUG MARKER: == sanity test 230i: lfs migrate -m tolerates trailing slashes ========================================================== 22:55:39 (1770436539) [ 1056.509641] Lustre: DEBUG MARKER: == sanity test 230j: DoM file data not changed after dir migration ========================================================== 22:55:42 (1770436542) [ 1059.793654] Lustre: DEBUG MARKER: == sanity test 230k: file data not changed after dir migration ========================================================== 22:55:46 (1770436546) [ 1060.419901] Lustre: DEBUG MARKER: SKIP: sanity test_230k needs >= 4 MDTs [ 1061.384252] Lustre: DEBUG MARKER: == sanity test 230l: readdir between MDTs won't crash ==== 22:55:47 (1770436547) [ 1106.835855] Lustre: DEBUG MARKER: == sanity test 230m: xattrs not changed after dir migration ========================================================== 22:56:33 (1770436593) [ 1109.075542] bash (86056): drop_caches: 3 [ 1109.723704] bash (86056): drop_caches: 3 [ 1113.621975] Lustre: DEBUG MARKER: == sanity test 230n: Dir migration with mirrored file ==== 22:56:39 (1770436599) [ 1117.619558] Lustre: DEBUG MARKER: == sanity test 230o: dir split =========================== 22:56:43 (1770436603) [ 1133.297481] Lustre: DEBUG MARKER: == sanity test 230p: dir merge =========================== 22:56:59 (1770436619) [ 1146.313078] LustreError: 88526:0:(llite_lib.c:1897:ll_update_lsm_md()) lustre: [0x2000013a1:0x3498:0x0] dir layout mismatch: [ 1146.320696] LustreError: 88526: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= [ 1146.334426] LustreError: 88526:0:(lustre_lmv.h:167:lmv_stripe_object_dump()) stripe[0] [0x200001b70:0x7d:0x0] [ 1146.340921] LustreError: 88526: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= [ 1146.354291] LustreError: 88526:0:(llite_lib.c:3782:ll_prep_inode()) lustre: new_inode - fatal error: rc = -22 [ 1158.788256] Lustre: DEBUG MARKER: == sanity test 230q: dir auto split ====================== 22:57:24 (1770436644) [ 1177.113058] Lustre: DEBUG MARKER: == sanity test 230r: migrate with too many local locks === 22:57:43 (1770436663) [ 1180.934398] Lustre: DEBUG MARKER: == sanity test 230s: lfs mkdir should return -EEXIST if target exists ========================================================== 22:57:47 (1770436667) [ 1186.668981] Lustre: DEBUG MARKER: == sanity test 230t: migrate directory with project ID set ========================================================== 22:57:52 (1770436672) [ 1190.906117] Lustre: DEBUG MARKER: == sanity test 230u: migrate directory by QOS ============ 22:57:57 (1770436677) [ 1191.573405] Lustre: DEBUG MARKER: SKIP: sanity test_230u needs >= 4 MDTs [ 1192.261695] Lustre: DEBUG MARKER: == sanity test 230v: subdir migrated to the MDT where its parent is located ========================================================== 22:57:58 (1770436678) [ 1192.915590] Lustre: DEBUG MARKER: SKIP: sanity test_230v needs >= 4 MDTs [ 1193.917514] Lustre: DEBUG MARKER: == sanity test 230w: non-recursive mode dir migration ==== 22:57:59 (1770436679) [ 1199.215638] Lustre: DEBUG MARKER: == sanity test 230x: dir migration check space =========== 22:58:05 (1770436685) [ 1234.013454] Lustre: DEBUG MARKER: == sanity test 230y: unlink dir with bad hash type ======= 22:58:40 (1770436720) [ 1243.804855] Lustre: DEBUG MARKER: == sanity test 230z: resume dir migration with bad hash type ========================================================== 22:58:50 (1770436730) [ 1271.089562] Lustre: DEBUG MARKER: == sanity test 230A: dir migrate should update lmm_oi ==== 22:59:17 (1770436757) [ 1275.018645] Lustre: DEBUG MARKER: == sanity test 231a: checking that reading/writing of BRW RPC size results in one RPC ========================================================== 22:59:21 (1770436761) [ 1279.800765] Lustre: DEBUG MARKER: == sanity test 231b: must not assert on fully utilized OST request buffer ========================================================== 22:59:26 (1770436766) [ 1296.351753] Lustre: lustre-OST0000-osc-ffff9531890ec800: disconnect after 20s idle [ 1296.355891] Lustre: Skipped 1 previous similar message [ 1308.429333] Lustre: DEBUG MARKER: == sanity test 232a: failed lock should not block umount ========================================================== 22:59:54 (1770436794) [ 1309.043423] LustreError: lustre-OST0000-osc-ffff9531890ec800: operation ldlm_enqueue to node 192.168.203.121@tcp failed: rc = -12 [ 1309.878327] LustreError: 98246:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff9531890ec800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 1309.881858] LustreError: 98246:0:(lov_obd.c:783:lov_cleanup()) Skipped 1 previous similar message [ 1309.889673] LustreError: 98246:0:(obd_class.h:479:obd_check_dev()) Device 6 not setup [ 1309.891756] LustreError: 98246:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 1309.937556] Lustre: Unmounted lustre-client [ 1310.268500] Lustre: Mounted lustre-client [ 1310.270177] Lustre: Skipped 1 previous similar message [ 1315.303423] Lustre: lustre-OST0000-osc-ffff9531c0b56800: Connection to lustre-OST0000 (at 192.168.203.121@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1316.743471] Lustre: lustre-OST0000-osc-ffff9531c0b56800: Connection restored to 192.168.203.121@tcp (at 192.168.203.121@tcp) [ 1316.747908] Lustre: Skipped 1 previous similar message [ 1322.535687] Lustre: DEBUG MARKER: == sanity test 232b: failed data version lock should not block umount ========================================================== 23:00:08 (1770436808) [ 1324.065881] LustreError: 99159:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff9531c0b56800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 1324.070079] LustreError: 99159:0:(lov_obd.c:783:lov_cleanup()) Skipped 1 previous similar message [ 1324.076498] LustreError: 99159:0:(obd_class.h:479:obd_check_dev()) Device 6 not setup [ 1324.079379] LustreError: 99159:0:(obd_class.h:479:obd_check_dev()) Skipped 9 previous similar messages [ 1324.122222] Lustre: Unmounted lustre-client [ 1324.349295] Lustre: Mounted lustre-client [ 1336.794374] Lustre: DEBUG MARKER: == sanity test 233a: checking that OBF of the FS root succeeds ========================================================== 23:00:23 (1770436823) [ 1340.298588] Lustre: DEBUG MARKER: == sanity test 233b: checking that OBF of the FS .lustre succeeds ========================================================== 23:00:26 (1770436826) [ 1343.815311] Lustre: DEBUG MARKER: == sanity test 234: xattr cache should not crash on ENOMEM ========================================================== 23:00:29 (1770436829) [ 1343.989693] Lustre: *** cfs_fail_loc=1405, val=0*** [ 1347.200237] Lustre: DEBUG MARKER: == sanity test 235: LU-1715: flock deadlock detection does not work properly ========================================================== 23:00:33 (1770436833) [ 1352.634992] Lustre: DEBUG MARKER: == sanity test 236: Layout swap on open unlinked file ==== 23:00:38 (1770436838) [ 1356.681338] Lustre: DEBUG MARKER: == sanity test 238: Verify linkea consistency ============ 23:00:42 (1770436842) [ 1360.129820] Lustre: DEBUG MARKER: == sanity test 239A: osp_sync test ======================= 23:00:46 (1770436846) [ 1396.703484] Lustre: DEBUG MARKER: == sanity test 239a: process invalid osp sync record correctly ========================================================== 23:01:22 (1770436882) [ 1407.409665] Lustre: DEBUG MARKER: == sanity test 239b: process osp sync record with ENOMEM error correctly ========================================================== 23:01:32 (1770436892) [ 1422.981405] Lustre: DEBUG MARKER: == sanity test 240: race between ldlm enqueue and the connection RPC (no ASSERT) ========================================================== 23:01:48 (1770436908) [ 1425.081479] LustreError: 106460:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff953190a26000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 1425.095041] LustreError: 106460:0:(lov_obd.c:783:lov_cleanup()) Skipped 1 previous similar message [ 1425.105696] LustreError: 106460:0:(obd_class.h:479:obd_check_dev()) Device 6 not setup [ 1425.111750] LustreError: 106460:0:(obd_class.h:479:obd_check_dev()) Skipped 9 previous similar messages [ 1425.173918] Lustre: Unmounted lustre-client [ 1426.192601] Lustre: Mounted lustre-client [ 1432.050874] Lustre: DEBUG MARKER: == sanity test 241a: bio vs dio ========================== 23:01:58 (1770436918) [ 1471.510582] Lustre: DEBUG MARKER: == sanity test 241b: dio vs dio ========================== 23:02:37 (1770436957) [ 1488.734287] Lustre: DEBUG MARKER: == sanity test 242: mdt_readpage failure should not cause directory unreadable ========================================================== 23:02:55 (1770436975) [ 1489.270704] LustreError: lustre-MDT0000-mdc-ffff9531854bf000: operation mds_readpage to node 192.168.203.121@tcp failed: rc = -12 [ 1492.068813] Lustre: DEBUG MARKER: == sanity test 243: various group lock tests ============= 23:02:58 (1770436978) [ 1495.823809] Lustre: 117911:0:(file.c:3071:ll_get_grouplock()) lustre: group lock already exists with gid 97486 on [0x200001b73:0x5:0x0]: rc = -22 [ 1495.829193] Lustre: 117911:0:(file.c:3146:ll_put_grouplock()) lustre: no group lock held on [0x200001b73:0x5:0x0]: rc = -22 [ 1495.834658] Lustre: 117911:0:(file.c:3053:ll_get_grouplock()) lustre: group id for group lock on [0x200001b73:0x5:0x0] is 0: rc = -22 [ 1495.842222] Lustre: 117911:0:(file.c:3156:ll_put_grouplock()) lustre: group lock 4294967286 doesn't match current id 3543 on [0x200001b73:0x5:0x0]: rc = -22 [ 1603.062618] Lustre: 117911:0:(file.c:3146:ll_put_grouplock()) lustre: no group lock held on [0x200001b73:0xc:0x0]: rc = -22 [ 1603.081158] Lustre: 117911:0:(file.c:3053:ll_get_grouplock()) lustre: group id for group lock on [0x200001b73:0xc:0x0] is 0: rc = -22 [ 1606.465328] Lustre: DEBUG MARKER: == sanity test 244a: sendfile with group lock tests ====== 23:04:52 (1770437092) [ 1645.610075] Lustre: DEBUG MARKER: == sanity test 244b: multi-threaded write with group lock ========================================================== 23:05:31 (1770437131) [ 1648.299740] Lustre: DEBUG MARKER: == sanity test 245a: check mdc connection flag/data: multiple modify RPCs ========================================================== 23:05:34 (1770437134) [ 1650.302237] Lustre: DEBUG MARKER: == sanity test 245b: check osp connection flag/data: multiple modify RPCs ========================================================== 23:05:36 (1770437136) [ 1654.165668] Lustre: DEBUG MARKER: == sanity test 247a: mount subdir as fileset ============= 23:05:40 (1770437140) [ 1654.390847] Lustre: Mounted lustre-client [ 1654.466304] LustreError: 121023:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff9531a07c9800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 1654.470968] LustreError: 121023:0:(lov_obd.c:783:lov_cleanup()) Skipped 1 previous similar message [ 1654.477126] LustreError: 121023:0:(obd_class.h:479:obd_check_dev()) Device 12 not setup [ 1654.479748] LustreError: 121023:0:(obd_class.h:479:obd_check_dev()) Skipped 9 previous similar messages [ 1654.508138] Lustre: Unmounted lustre-client [ 1658.431226] Lustre: DEBUG MARKER: == sanity test 247b: mount subdir that dose not exist ==== 23:05:44 (1770437144) [ 1658.653811] LustreError: 121671:0:(llite_lib.c:502:client_common_fill_super()) lustre-clilmv-ffff9531890ea800: cannot mds_connect: rc = -2 [ 1658.680933] LustreError: 121671:0:(obd_class.h:479:obd_check_dev()) Device 9 not setup [ 1658.684096] LustreError: 121671:0:(obd_class.h:479:obd_check_dev()) Skipped 15 previous similar messages [ 1658.693388] Lustre: Unmounted lustre-client [ 1658.694786] Lustre: Skipped 1 previous similar message [ 1658.696555] LustreError: 121671:0:(super25.c:199:lustre_fill_super()) llite: Unable to mount : rc = -2 [ 1662.097888] Lustre: DEBUG MARKER: == sanity test 247c: running fid2path outside subdirectory root ========================================================== 23:05:48 (1770437148) [ 1662.428222] Lustre: Mounted lustre-client [ 1662.430219] Lustre: Skipped 1 previous similar message [ 1662.525578] LustreError: 122305:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff953187f65000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 1662.532183] LustreError: 122305:0:(lov_obd.c:783:lov_cleanup()) Skipped 3 previous similar messages [ 1666.514255] Lustre: DEBUG MARKER: == sanity test 247d: running fid2path inside subdirectory root ========================================================== 23:05:52 (1770437152) [ 1666.953753] LustreError: 122977:0:(obd_class.h:479:obd_check_dev()) Device 12 not setup [ 1666.958128] LustreError: 122977:0:(obd_class.h:479:obd_check_dev()) Skipped 23 previous similar messages [ 1667.003246] Lustre: Unmounted lustre-client [ 1667.006090] Lustre: Skipped 2 previous similar messages [ 1671.118797] Lustre: DEBUG MARKER: == sanity test 247e: mount .. as fileset ================= 23:05:57 (1770437157) [ 1671.358683] Lustre: Mounted lustre-client [ 1671.360816] Lustre: Skipped 3 previous similar messages [ 1671.447565] LustreError: 123654:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff9531a07c9800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 1671.452904] LustreError: 123654:0:(lov_obd.c:783:lov_cleanup()) Skipped 7 previous similar messages [ 1671.628281] LustreError: lustre-MDT0000-mdc-ffff9531b26d2000: operation mds_get_root to node 192.168.203.121@tcp failed: rc = -22 [ 1671.634883] LustreError: 123661:0:(llite_lib.c:502:client_common_fill_super()) lustre-clilmv-ffff9531b26d2000: cannot mds_connect: rc = -22 [ 1671.674707] LustreError: 123661:0:(super25.c:199:lustre_fill_super()) llite: Unable to mount : rc = -22 [ 1674.995742] Lustre: DEBUG MARKER: == sanity test 247f: mount striped or remote directory as fileset ========================================================== 23:06:01 (1770437161) [ 1682.510141] Lustre: DEBUG MARKER: == sanity test 247g: striped directory submount revalidate ROOT from cache ========================================================== 23:06:08 (1770437168) [ 1687.085468] LustreError: 125982:0:(obd_class.h:479:obd_check_dev()) Device 12 not setup [ 1687.088744] LustreError: 125982:0:(obd_class.h:479:obd_check_dev()) Skipped 119 previous similar messages [ 1687.123209] Lustre: Unmounted lustre-client [ 1687.125207] Lustre: Skipped 14 previous similar messages [ 1688.039044] Lustre: DEBUG MARKER: == sanity test 247h: remote directory submount revalidate ROOT from cache ========================================================== 23:06:14 (1770437174) [ 1688.406129] Lustre: Mounted lustre-client [ 1688.408880] Lustre: Skipped 12 previous similar messages [ 1688.488213] LustreError: 126182:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff953188259000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 1688.495070] LustreError: 126182:0:(lov_obd.c:783:lov_cleanup()) Skipped 25 previous similar messages [ 1695.974463] Lustre: DEBUG MARKER: == sanity test 248a: fast read verification ============== 23:06:22 (1770437182) [ 1758.005678] Lustre: DEBUG MARKER: == sanity test 248b: test short_io read and write for both small and large sizes ========================================================== 23:07:24 (1770437244) [ 1784.697461] Lustre: DEBUG MARKER: == sanity test 248c: verify whole file read behavior ===== 23:07:50 (1770437270) [ 1796.841624] Lustre: DEBUG MARKER: == sanity test 249: Write above 2T file size ============= 23:08:02 (1770437282) [ 1800.743957] Lustre: DEBUG MARKER: == sanity test 250: Write above 16T limit ================ 23:08:06 (1770437286) [ 1804.706140] Lustre: DEBUG MARKER: == sanity test 251a: Handling short read and write correctly ========================================================== 23:08:10 (1770437290) [ 1805.375237] Lustre: *** cfs_fail_loc=1407, val=0*** [ 1808.739561] Lustre: DEBUG MARKER: == sanity test 251b: short read restore offset correctly ========================================================== 23:08:14 (1770437294) [ 1808.857261] LustreError: 130718:0:(file.c:2514:do_file_read_iter()) cfs_fail_timeout id 1431 sleeping for 5000ms [ 1813.959108] LustreError: 130718:0:(file.c:2514:do_file_read_iter()) cfs_fail_timeout id 1431 awake [ 1817.192115] Lustre: DEBUG MARKER: == sanity test 252: check lr_reader tool ================= 23:08:23 (1770437303) [ 1822.858182] Lustre: DEBUG MARKER: == sanity test 253: Check object allocation limit ======== 23:08:28 (1770437308) [ 1896.094488] Lustre: DEBUG MARKER: == sanity test 254: Check changelog size ================= 23:09:42 (1770437382) [ 1905.990975] Lustre: DEBUG MARKER: SKIP: sanity test_255a skipping excluded test 255a (base 255) [ 1906.857333] Lustre: DEBUG MARKER: SKIP: sanity test_255b skipping excluded test 255b (base 255) [ 1907.763652] Lustre: DEBUG MARKER: SKIP: sanity test_255c skipping excluded test 255c (base 255) [ 1908.468092] Lustre: DEBUG MARKER: SKIP: sanity test_256 skipping excluded test 256 [ 1909.179266] Lustre: DEBUG MARKER: == sanity test 257: xattr locks are not lost ============= 23:09:55 (1770437395) [ 1910.197882] LustreError: lustre-MDT0001-mdc-ffff9531854bf000: operation ldlm_enqueue to node 192.168.203.121@tcp failed: rc = -14 [ 1911.267471] Lustre: lustre-MDT0001-mdc-ffff9531854bf000: Connection to lustre-MDT0001 (at 192.168.203.121@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1911.273127] Lustre: Skipped 1 previous similar message [ 1926.792201] Lustre: lustre-MDT0001-mdc-ffff9531854bf000: Connection restored to 192.168.203.121@tcp (at 192.168.203.121@tcp) [ 1926.798119] Lustre: Skipped 1 previous similar message [ 1934.064781] Lustre: DEBUG MARKER: == sanity test 258a: verify i_mutex security behavior when suid attributes is set ========================================================== 23:10:20 (1770437420) [ 1937.380723] Lustre: DEBUG MARKER: == sanity test 258b: verify i_mutex security behavior ==== 23:10:23 (1770437423) [ 1940.060320] Lustre: DEBUG MARKER: == sanity test 259: crash at delayed truncate ============ 23:10:26 (1770437426) [ 1966.645489] Lustre: DEBUG MARKER: == sanity test 260: Check mdc_close fail ================= 23:10:52 (1770437452) [ 1966.738877] Lustre: *** cfs_fail_loc=806, val=0*** [ 1966.744771] Lustre: 138368:0:(mdc_request.c:918:mdc_close()) lustre-MDT0000-mdc-ffff9531854bf000: close of FID [0x200001b73:0x52:0x0] failed, file reference will be dropped when this client unmounts or is evicted [ 1966.762906] LustreError: 138368:0:(file.c:249:ll_close_inode_openhandle()) lustre-clilmv-ffff9531854bf000: inode [0x200001b73:0x52:0x0] mdc close failed: rc = -12 [ 1970.143552] Lustre: DEBUG MARKER: == sanity test 270a: DoM: basic functionality tests ====== 23:10:56 (1770437456) [ 1977.221848] Lustre: DEBUG MARKER: == sanity test 270b: DoM: maximum size overflow checks for DoM-only file ========================================================== 23:11:03 (1770437463) [ 1981.072069] Lustre: DEBUG MARKER: == sanity test 270c: DoM: DoM EA inheritance tests ======= 23:11:07 (1770437467) [ 1984.826390] Lustre: DEBUG MARKER: == sanity test 270d: DoM: change striping from DoM to RAID0 ========================================================== 23:11:11 (1770437471) [ 1988.674712] Lustre: DEBUG MARKER: == sanity test 270e: DoM: lfs find with DoM files test === 23:11:14 (1770437474) [ 1992.822856] Lustre: DEBUG MARKER: == sanity test 270f: DoM: maximum DoM stripe size checks ========================================================== 23:11:19 (1770437479) [ 2001.536915] Lustre: DEBUG MARKER: == sanity test 270g: DoM: default DoM stripe size depends on free space ========================================================== 23:11:27 (1770437487) [ 2014.322186] Lustre: DEBUG MARKER: == sanity test 270h: DoM: DoM stripe removal when disabled on server ========================================================== 23:11:40 (1770437500) [ 2019.307560] Lustre: DEBUG MARKER: == sanity test 270i: DoM: setting invalid DoM striping should fail ========================================================== 23:11:45 (1770437505) [ 2022.860687] Lustre: DEBUG MARKER: == sanity test 270j: DoM migration: DOM file to the OST-striped file (plain) ========================================================== 23:11:48 (1770437508) [ 2027.056522] Lustre: DEBUG MARKER: == sanity test 271a: DoM: data is cached for read after write ========================================================== 23:11:53 (1770437513) [ 2030.784392] Lustre: DEBUG MARKER: == sanity test 271b: DoM: no glimpse RPC for stat (DoM only file) ========================================================== 23:11:56 (1770437516) [ 2034.356742] Lustre: DEBUG MARKER: == sanity test 271ba: DoM: no glimpse RPC for stat (combined file) ========================================================== 23:12:00 (1770437520) [ 2038.100404] Lustre: DEBUG MARKER: == sanity test 271c: DoM: IO lock at open saves enqueue RPCs ========================================================== 23:12:04 (1770437524) [ 2096.985122] Lustre: DEBUG MARKER: == sanity test 271d: DoM: read on open (1K file in reply buffer) ========================================================== 23:13:03 (1770437583) [ 2099.392584] Lustre: DEBUG MARKER: == sanity test 271f: DoM: read on open (200K file and read tail) ========================================================== 23:13:05 (1770437585) [ 2101.954448] Lustre: DEBUG MARKER: == sanity test 271g: Discard DoM data vs client flush race ========================================================== 23:13:08 (1770437588) [ 2103.051603] Lustre: *** cfs_fail_loc=314, val=0*** [ 2105.148493] Lustre: DEBUG MARKER: == sanity test 272a: DoM migration: new layout with the same DOM component ========================================================== 23:13:11 (1770437591) [ 2107.671791] Lustre: DEBUG MARKER: == sanity test 272b: DoM migration: DOM file to the OST-striped file (plain) ========================================================== 23:13:14 (1770437594) [ 2111.531494] Lustre: DEBUG MARKER: == sanity test 272c: DoM migration: DOM file to the OST-striped file (composite) ========================================================== 23:13:17 (1770437597) [ 2115.194263] Lustre: DEBUG MARKER: == sanity test 272d: DoM mirroring: OST-striped mirror to DOM file ========================================================== 23:13:21 (1770437601) [ 2116.219932] LustreError: 152122:0:(file.c:249:ll_close_inode_openhandle()) lustre-clilmv-ffff9531854bf000: inode [0x240000409:0x80c:0x0] mdc close failed: rc = -22 [ 2118.737588] Lustre: DEBUG MARKER: == sanity test 272e: DoM mirroring: DOM mirror to the OST-striped file ========================================================== 23:13:25 (1770437605) [ 2120.141694] LustreError: 152739:0:(file.c:249:ll_close_inode_openhandle()) lustre-clilmv-ffff9531854bf000: inode [0x200001b73:0x9d:0x0] mdc close failed: rc = -22 [ 2122.391781] Lustre: DEBUG MARKER: == sanity test 272f: DoM migration: OST-striped file to DOM file ========================================================== 23:13:28 (1770437608) [ 2123.057350] LustreError: 153340:0:(file.c:249:ll_close_inode_openhandle()) lustre-clilmv-ffff9531854bf000: inode [0x240000409:0x810:0x0] mdc close failed: rc = -22 [ 2125.498141] Lustre: DEBUG MARKER: == sanity test 273a: DoM: layout swapping should fail with DOM ========================================================== 23:13:31 (1770437611) [ 2128.060629] Lustre: DEBUG MARKER: == sanity test 273b: DoM: race writeback and object destroy ========================================================== 23:13:34 (1770437614) [ 2133.201650] Lustre: DEBUG MARKER: == sanity test 273c: race writeback and object destroy === 23:13:39 (1770437619) [ 2139.540713] Lustre: DEBUG MARKER: == sanity test 275: Read on a canceled duplicate lock ==== 23:13:45 (1770437625) [ 2140.166698] LustreError: 106493:0:(ldlm_lockd.c:2916:ldlm_bl_thread_blwi()) cfs_fail_timeout id 31f sleeping for 4000ms [ 2142.672120] LustreError: 106493:0:(ldlm_lockd.c:2916:ldlm_bl_thread_blwi()) cfs_fail_timeout interrupted [ 2145.174617] Lustre: DEBUG MARKER: == sanity test 276: Race between mount and obd_statfs ==== 23:13:51 (1770437631) [ 2147.812784] Lustre: lustre-OST0000-osc-ffff9531854bf000: Connection to lustre-OST0000 (at 192.168.203.121@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 2147.825437] Lustre: Skipped 1 previous similar message [ 2151.540594] Lustre: lustre-OST0000-osc-ffff9531854bf000: Connection restored to 192.168.203.121@tcp (at 192.168.203.121@tcp) [ 2280.931243] Lustre: lustre-OST0000-osc-ffff9531854bf000: Connection to lustre-OST0000 (at 192.168.203.121@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 2280.939685] Lustre: Skipped 18 previous similar messages [ 2288.809026] Lustre: DEBUG MARKER: == sanity test 277: Direct IO shall drop page cache ====== 23:16:15 (1770437775) [ 2290.962618] Lustre: DEBUG MARKER: == sanity test 278: Race starting MDS between MDTs stop/start ========================================================== 23:16:17 (1770437777) [ 2296.289554] LustreError: MGC192.168.203.121@tcp: Connection to MGS (at 192.168.203.121@tcp) was lost; in progress operations using this service will fail [ 2296.294533] Lustre: Evicted from MGS (at 192.168.203.121@tcp) after server handle changed from 0x115a18b47d19aafe to 0x115a18b47d248732 [ 2298.232315] LustreError: 2412:0:(client.c:3418:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff953188aed180 x1856436266482432/t17179898580(17179898580) o101->lustre-MDT0000-mdc-ffff9531854bf000@192.168.203.121@tcp:12/10 lens 584/608 e 0 to 0 dl 1770437801 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'touch.0' uid:0 gid:0 projid:0 [ 2298.238591] LustreError: 2412:0:(client.c:3418:ptlrpc_replay_interpret()) Skipped 2 previous similar messages [ 2313.405244] Lustre: DEBUG MARKER: == sanity test 280: Race between MGS umount and client llog processing ========================================================== 23:16:39 (1770437799) [ 2313.822632] LustreError: 163261:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff9531854bf000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 2313.826823] LustreError: 163261:0:(lov_obd.c:783:lov_cleanup()) Skipped 7 previous similar messages [ 2313.829654] LustreError: 163261:0:(obd_class.h:479:obd_check_dev()) Device 6 not setup [ 2313.831588] LustreError: 163261:0:(obd_class.h:479:obd_check_dev()) Skipped 39 previous similar messages [ 2313.859904] Lustre: Unmounted lustre-client [ 2313.862758] Lustre: Skipped 4 previous similar messages [ 2324.960776] LustreError: MGC192.168.203.121@tcp: Connection to MGS (at 192.168.203.121@tcp) was lost; in progress operations using this service will fail [ 2324.966766] LustreError: MGC192.168.203.121@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 [ 2324.973507] Lustre: Evicted from MGS (at 192.168.203.121@tcp) after server handle changed from 0x115a18b47d248d3d to 0x115a18b47d248f04 [ 2324.991151] LustreError: 163284:0:(super25.c:199:lustre_fill_super()) llite: Unable to mount : rc = -5 [ 2338.294596] Lustre: Mounted lustre-client [ 2338.295502] Lustre: Skipped 3 previous similar messages [ 2340.581848] Lustre: DEBUG MARKER: == sanity test 300a: basic striped dir sanity test ======= 23:17:07 (1770437827) [ 2343.499983] Lustre: DEBUG MARKER: == sanity test 300b: check ctime/mtime for striped dir === 23:17:09 (1770437829) [ 2367.520190] Lustre: DEBUG MARKER: == sanity test 300c: chown [ 2460.977952] Lustre: DEBUG MARKER: == sanity test 300d: check default stripe under striped directory ========================================================== 23:19:07 (1770437947) [ 2464.058344] Lustre: DEBUG MARKER: == sanity test 300e: check rename under striped directory ========================================================== 23:19:10 (1770437950) [ 2466.726079] Lustre: DEBUG MARKER: == sanity test 300f: check rename cross striped directory ========================================================== 23:19:13 (1770437953) [ 2469.395545] Lustre: DEBUG MARKER: == sanity test 300g: check default striped directory for normal directory ========================================================== 23:19:15 (1770437955) [ 2474.744960] Lustre: DEBUG MARKER: == sanity test 300h: check default striped directory for striped directory ========================================================== 23:19:21 (1770437961) [ 2479.439497] Lustre: DEBUG MARKER: == sanity test 300i: client handle unknown hash type striped directory ========================================================== 23:19:25 (1770437965) [ 2480.027356] LustreError: 169349:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff953188d9c000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 2480.030063] LustreError: 169349:0:(lov_obd.c:783:lov_cleanup()) Skipped 1 previous similar message [ 2480.034106] LustreError: 169349:0:(obd_class.h:479:obd_check_dev()) Device 6 not setup [ 2480.035521] LustreError: 169349:0:(obd_class.h:479:obd_check_dev()) Skipped 19 previous similar messages [ 2480.062922] Lustre: Unmounted lustre-client [ 2480.063828] Lustre: Skipped 1 previous similar message [ 2480.182694] Lustre: Mounted lustre-client [ 2480.524812] Lustre: *** cfs_fail_loc=1901, val=99*** [ 2480.543444] Lustre: *** cfs_fail_loc=1901, val=99*** [ 2511.682538] Lustre: Mounted lustre-client [ 2513.877095] Lustre: DEBUG MARKER: == sanity test 300j: test large update record ============ 23:20:00 (1770438000) [ 2516.174898] Lustre: DEBUG MARKER: == sanity test 300k: test large striped directory ======== 23:20:02 (1770438002) [ 2518.614938] Lustre: DEBUG MARKER: == sanity test 300l: non-root user to create dir under striped dir with stale layout ========================================================== 23:20:05 (1770438005) [ 2521.378780] Lustre: DEBUG MARKER: == sanity test 300m: setstriped directory on single MDT FS ========================================================== 23:20:07 (1770438007) [ 2521.915343] Lustre: DEBUG MARKER: SKIP: sanity test_300m Only for single MDT [ 2522.530962] Lustre: DEBUG MARKER: == sanity test 300n: non-root user to create dir under striped dir with default EA ========================================================== 23:20:08 (1770438008) [ 2527.969076] Lustre: DEBUG MARKER: SKIP: sanity test_300o skipping SLOW test 300o [ 2528.584550] Lustre: DEBUG MARKER: == sanity test 300p: create striped directory without space ========================================================== 23:20:14 (1770438014) [ 2531.340679] Lustre: DEBUG MARKER: == sanity test 300q: create remote directory under orphan directory ========================================================== 23:20:17 (1770438017) [ 2533.586621] Lustre: DEBUG MARKER: == sanity test 300r: test -1 striped directory =========== 23:20:19 (1770438019) [ 2535.969317] Lustre: DEBUG MARKER: == sanity test 300s: test lfs mkdir -c without -i ======== 23:20:22 (1770438022) [ 2539.256908] Lustre: DEBUG MARKER: == sanity test 300t: test max_mdt_stripecount ============ 23:20:25 (1770438025) [ 2545.171673] Lustre: DEBUG MARKER: == sanity test 300ua: basic overstriped dir sanity test == 23:20:31 (1770438031) [ 2550.636415] Lustre: DEBUG MARKER: == sanity test 300ub: test MDT overstriping interface [ 2555.602373] Lustre: DEBUG MARKER: == sanity test 300uc: test MDT overstriping as default [ 2559.728367] Lustre: DEBUG MARKER: == sanity test 300ud: dir split ========================== 23:20:45 (1770438045) [ 2650.397445] Lustre: DEBUG MARKER: == sanity test 300ue: dir merge ========================== 23:22:16 (1770438136) [ 2705.603215] Lustre: DEBUG MARKER: == sanity test 300uf: migrate with too many local locks == 23:23:11 (1770438191) [ 2705.679667] Lustre: DEBUG MARKER: touch/create [ 2705.939311] Lustre: DEBUG MARKER: hardlinks [ 2706.338526] Lustre: DEBUG MARKER: cancel lru [ 2706.410490] Lustre: DEBUG MARKER: migrate [ 2710.645881] Lustre: DEBUG MARKER: == sanity test 300ug: migrate overstriped dirs =========== 23:23:16 (1770438196) [ 2715.598521] Lustre: DEBUG MARKER: == sanity test 300uh: overstripe tunable max_stripes_per_mdt ========================================================== 23:23:21 (1770438201) [ 2720.351583] Lustre: DEBUG MARKER: == sanity test 300ui: overstripe is not supported on one MDT system ========================================================== 23:23:26 (1770438206) [ 2721.184712] Lustre: DEBUG MARKER: SKIP: sanity test_300ui 1 MDT only [ 2721.941444] Lustre: DEBUG MARKER: == sanity test 300uj: overstriped dir with -C -N sanity test ========================================================== 23:23:28 (1770438208) [ 2726.217205] Lustre: DEBUG MARKER: == sanity test 310a: open unlink remote file ============= 23:23:32 (1770438212) [ 2730.188578] Lustre: DEBUG MARKER: == sanity test 310b: unlink remote file with multiple links while open ========================================================== 23:23:36 (1770438216) [ 2734.188793] Lustre: DEBUG MARKER: == sanity test 310c: open-unlink remote file with multiple links ========================================================== 23:23:40 (1770438220) [ 2734.955784] Lustre: DEBUG MARKER: SKIP: sanity test_310c needs >= 4 MDTs [ 2735.988832] Lustre: DEBUG MARKER: == sanity test 311: disable OSP precreate, and unlink should destroy objs ========================================================== 23:23:42 (1770438222) [ 2759.942429] Lustre: DEBUG MARKER: == sanity test 312: make sure ZFS adjusts its block size by write pattern ========================================================== 23:24:06 (1770438246) [ 2760.852345] Lustre: DEBUG MARKER: SKIP: sanity test_312 the test only applies to zfs [ 2761.719633] Lustre: DEBUG MARKER: == sanity test 313: io should fail after last_rcvd update fail ========================================================== 23:24:07 (1770438247) [ 2766.277325] Lustre: DEBUG MARKER: == sanity test 314: OSP shouldn't fail after last_rcvd update failure ========================================================== 23:24:12 (1770438252) [ 2783.344964] Lustre: DEBUG MARKER: == sanity test 315: read should be accounted ============= 23:24:29 (1770438269) [ 2790.497780] Lustre: DEBUG MARKER: == sanity test 316: lfs migrate of file with large_xattr enabled ========================================================== 23:24:36 (1770438276) [ 2794.791383] Lustre: DEBUG MARKER: == sanity test 317: Verify blocks get correctly update after truncate ========================================================== 23:24:40 (1770438280) [ 2798.899300] Lustre: DEBUG MARKER: == sanity test 318: Verify async readahead tunables ====== 23:24:44 (1770438284) [ 2799.061889] LustreError: 191325:0:(lproc_llite.c:1836: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 [ 2802.548179] Lustre: DEBUG MARKER: == sanity test 319: lost lease lock on migrate error ===== 23:24:48 (1770438288) [ 2802.764802] LustreError: 191909:0:(ldlm_request.c:1660:ldlm_cli_cancel()) cfs_fail_timeout id 32c sleeping for 5000ms [ 2807.863118] LustreError: 191909:0:(ldlm_request.c:1660:ldlm_cli_cancel()) cfs_fail_timeout id 32c awake [ 2811.539466] Lustre: DEBUG MARKER: == sanity test 350: force NID mismatch path to be exercised ========================================================== 23:24:57 (1770438297) [ 2884.710768] Lustre: DEBUG MARKER: == sanity test 360: ldiskfs unlink in a separate thread == 23:26:10 (1770438370) [ 2902.369698] Lustre: DEBUG MARKER: == sanity test 398a: direct IO should cancel lock otherwise lockless ========================================================== 23:26:28 (1770438388) [ 2906.280977] Lustre: DEBUG MARKER: == sanity test 398b: DIO and buffer IO race ============== 23:26:32 (1770438392) [ 3047.834876] Lustre: DEBUG MARKER: == sanity test 398c: run fio to test AIO ================= 23:28:54 (1770438534) [ 3074.303332] Lustre: DEBUG MARKER: == sanity test 398d: run aiocp to verify block size > stripe size ========================================================== 23:29:20 (1770438560) [ 3091.267401] Lustre: DEBUG MARKER: == sanity test 398e: O_Direct open cleared by fcntl doesn't cause hang ========================================================== 23:29:37 (1770438577) [ 3094.876542] Lustre: DEBUG MARKER: == sanity test 398f: verify aio handles ll_direct_rw_pages errors correctly ========================================================== 23:29:41 (1770438581) [ 3101.844963] Lustre: DEBUG MARKER: == sanity test 398g: verify parallel dio async RPC submission ========================================================== 23:29:48 (1770438588) [ 3126.243902] Lustre: DEBUG MARKER: == sanity test 398h: verify correctness of read [ 3139.288563] Lustre: DEBUG MARKER: == sanity test 398i: verify parallel dio handles ll_direct_rw_pages errors correctly ========================================================== 23:30:25 (1770438625) [ 3141.142436] Lustre: *** cfs_fail_loc=1418, val=0*** [ 3143.782930] Lustre: DEBUG MARKER: == sanity test 398j: test parallel dio where stripe size > rpc_size ========================================================== 23:30:29 (1770438629) [ 3158.859759] Lustre: DEBUG MARKER: == sanity test 398k: test enospc on first stripe ========= 23:30:44 (1770438644) [ 3173.595554] Lustre: DEBUG MARKER: SKIP: sanity test_398k 7205876 > 600000 skipping out-of-space test on OST0 [ 3174.564689] Lustre: DEBUG MARKER: == sanity test 398l: test enospc on intermediate stripe/RPC ========================================================== 23:31:00 (1770438660) [ 3181.005704] Lustre: DEBUG MARKER: SKIP: sanity test_398l 7187012 > 600000 skipping out-of-space test on OST0 [ 3195.526552] Lustre: DEBUG MARKER: == sanity test 398m: test RPC failures with parallel dio ========================================================== 23:31:21 (1770438681) [ 3196.222756] LustreError: lustre-OST0000-osc-ffff9531a08e8800: operation ost_write to node 192.168.203.121@tcp failed: rc = -5 [ 3196.226377] LustreError: 2414:0:(osc_request.c:2516:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff9531b1988700 x1856436286921984/t0(0) o4->lustre-OST0000-osc-ffff9531a08e8800@192.168.203.121@tcp:6/4 lens 488/224 e 0 to 0 dl 1770438699 ref 2 fl Interpret:ReMQU/600/0 rc -5/-5 job:'dd.0' uid:0 gid:0 projid:0 [ 3197.348832] LustreError: lustre-OST0000-osc-ffff9531a08e8800: operation ost_write to node 192.168.203.121@tcp failed: rc = -5 [ 3197.351840] LustreError: Skipped 3 previous similar messages [ 3197.353371] LustreError: 2414:0:(osc_request.c:2516:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff9531b1989880 x1856436286923136/t0(0) o4->lustre-OST0000-osc-ffff9531a08e8800@192.168.203.121@tcp:6/4 lens 488/224 e 0 to 0 dl 1770438700 ref 2 fl Interpret:ReMQU/600/0 rc -5/-5 job:'ptlrpcd_00_00.0' uid:0 gid:0 projid:0 [ 3197.360420] LustreError: 2414:0:(osc_request.c:2516:osc_brw_redo_request()) Skipped 3 previous similar messages [ 3199.457837] LustreError: lustre-OST0000-osc-ffff9531a08e8800: operation ost_write to node 192.168.203.121@tcp failed: rc = -5 [ 3199.461741] LustreError: Skipped 3 previous similar messages [ 3199.464169] LustreError: 2415:0:(osc_request.c:2516:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff9531b94faa00 x1856436286924160/t0(0) o4->lustre-OST0000-osc-ffff9531a08e8800@192.168.203.121@tcp:6/4 lens 488/224 e 0 to 0 dl 1770438702 ref 2 fl Interpret:ReMQU/600/0 rc -5/-5 job:'ptlrpcd_01_01.0' uid:0 gid:0 projid:0 [ 3199.474945] LustreError: 2415:0:(osc_request.c:2516:osc_brw_redo_request()) Skipped 3 previous similar messages [ 3202.530812] LustreError: lustre-OST0000-osc-ffff9531a08e8800: operation ost_write to node 192.168.203.121@tcp failed: rc = -5 [ 3202.536265] LustreError: Skipped 3 previous similar messages [ 3202.539367] LustreError: 2416:0:(osc_request.c:2516:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff9531c1c9bb80 x1856436286924800/t0(0) o4->lustre-OST0000-osc-ffff9531a08e8800@192.168.203.121@tcp:6/4 lens 488/224 e 0 to 0 dl 1770438705 ref 2 fl Interpret:ReMQU/600/0 rc -5/-5 job:'ptlrpcd_01_00.0' uid:0 gid:0 projid:0 [ 3202.555457] LustreError: 2416:0:(osc_request.c:2516:osc_brw_redo_request()) Skipped 3 previous similar messages [ 3206.626539] LustreError: lustre-OST0000-osc-ffff9531a08e8800: operation ost_write to node 192.168.203.121@tcp failed: rc = -5 [ 3206.636580] LustreError: Skipped 3 previous similar messages [ 3206.641308] LustreError: 2415:0:(osc_request.c:2516:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff9531b94f9500 x1856436286925312/t0(0) o4->lustre-OST0000-osc-ffff9531a08e8800@192.168.203.121@tcp:6/4 lens 488/224 e 0 to 0 dl 1770438709 ref 2 fl Interpret:ReMQU/600/0 rc -5/-5 job:'ptlrpcd_01_01.0' uid:0 gid:0 projid:0 [ 3206.664377] LustreError: 2415:0:(osc_request.c:2516:osc_brw_redo_request()) Skipped 3 previous similar messages [ 3217.314944] LustreError: lustre-OST0000-osc-ffff9531a08e8800: operation ost_write to node 192.168.203.121@tcp failed: rc = -5 [ 3217.323327] LustreError: Skipped 7 previous similar messages [ 3217.326212] LustreError: 2414:0:(osc_request.c:2516:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff9531b198a680 x1856436286927616/t0(0) o4->lustre-OST0000-osc-ffff9531a08e8800@192.168.203.121@tcp:6/4 lens 488/224 e 0 to 0 dl 1770438720 ref 2 fl Interpret:ReMQU/600/0 rc -5/-5 job:'ptlrpcd_00_00.0' uid:0 gid:0 projid:0 [ 3217.339785] LustreError: 2414:0:(osc_request.c:2516:osc_brw_redo_request()) Skipped 7 previous similar messages [ 3241.889571] LustreError: lustre-OST0000-osc-ffff9531a08e8800: operation ost_write to node 192.168.203.121@tcp failed: rc = -5 [ 3241.891680] LustreError: Skipped 11 previous similar messages [ 3241.892809] LustreError: 2416:0:(osc_request.c:2516:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff9531c1c9ad80 x1856436286931712/t0(0) o4->lustre-OST0000-osc-ffff9531a08e8800@192.168.203.121@tcp:6/4 lens 488/224 e 0 to 0 dl 1770438744 ref 2 fl Interpret:ReMQU/600/0 rc -5/-5 job:'ptlrpcd_01_00.0' uid:0 gid:0 projid:0 [ 3241.899929] LustreError: 2416:0:(osc_request.c:2516:osc_brw_redo_request()) Skipped 11 previous similar messages [ 3251.170413] LustreError: 2415:0:(osc_request.c:2673:brw_interpret()) lustre-OST0000-osc-ffff9531a08e8800: too many resent retries for object: 10737419265:8507: rc = -5 [ 3252.195410] LustreError: 2414:0:(osc_request.c:2673:brw_interpret()) lustre-OST0000-osc-ffff9531a08e8800: too many resent retries for object: 10737419265:8506: rc = -5 [ 3252.203575] LustreError: 2414:0:(osc_request.c:2673:brw_interpret()) Skipped 1 previous similar message [ 3275.748520] LustreError: lustre-OST0000-osc-ffff9531a08e8800: operation ost_read to node 192.168.203.121@tcp failed: rc = -5 [ 3275.749178] LustreError: 2413:0:(osc_request.c:2516:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff953188d98000 x1856436286952960/t0(0) o3->lustre-OST0000-osc-ffff9531a08e8800@192.168.203.121@tcp:6/4 lens 488/440 e 0 to 0 dl 1770438778 ref 2 fl Interpret:ReMQU/600/0 rc -5/-5 job:'ptlrpcd_00_01.0' uid:0 gid:0 projid:0 [ 3275.755448] LustreError: Skipped 32 previous similar messages [ 3275.774038] LustreError: 2413:0:(osc_request.c:2516:osc_brw_redo_request()) Skipped 27 previous similar messages [ 3310.564421] LustreError: 2413:0:(osc_request.c:2673:brw_interpret()) lustre-OST0000-osc-ffff9531a08e8800: too many resent retries for object: 10737419265:8506: rc = -5 [ 3310.572887] LustreError: 2413:0:(osc_request.c:2673:brw_interpret()) Skipped 2 previous similar messages [ 3340.193618] LustreError: lustre-OST0001-osc-ffff9531a08e8800: operation ost_write to node 192.168.203.121@tcp failed: rc = -5 [ 3340.195979] LustreError: Skipped 46 previous similar messages [ 3340.197191] LustreError: 2416:0:(osc_request.c:2516:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff9531c1c9aa00 x1856436286972288/t0(0) o4->lustre-OST0001-osc-ffff9531a08e8800@192.168.203.121@tcp:6/4 lens 488/224 e 0 to 0 dl 1770438843 ref 2 fl Interpret:ReMQU/600/0 rc -5/-5 job:'ptlrpcd_01_00.0' uid:0 gid:0 projid:0 [ 3340.202389] LustreError: 2416:0:(osc_request.c:2516:osc_brw_redo_request()) Skipped 42 previous similar messages [ 3367.906201] LustreError: 2413:0:(osc_request.c:2673:brw_interpret()) lustre-OST0001-osc-ffff9531a08e8800: too many resent retries for object: 11811161089:8436: rc = -5 [ 3367.912169] LustreError: 2413:0:(osc_request.c:2673:brw_interpret()) Skipped 3 previous similar messages [ 3426.212213] LustreError: 2415:0:(osc_request.c:2673:brw_interpret()) lustre-OST0001-osc-ffff9531a08e8800: too many resent retries for object: 11811161089:8435: rc = -5 [ 3426.215632] LustreError: 2415:0:(osc_request.c:2673:brw_interpret()) Skipped 2 previous similar messages [ 3431.255186] Lustre: DEBUG MARKER: == sanity test 398n: test append with parallel DIO ======= 23:35:17 (1770438917) [ 3445.571931] Lustre: DEBUG MARKER: == sanity test 398o: right kms with DIO ================== 23:35:31 (1770438931) [ 3448.716907] Lustre: DEBUG MARKER: == sanity test 398p: race aio with buffered i/o ========== 23:35:35 (1770438935) [ 3502.163836] Lustre: DEBUG MARKER: == sanity test 398q: race dio with buffered i/o ========== 23:36:28 (1770438988) [ 3556.103602] Lustre: DEBUG MARKER: == sanity test 398r: i/o error on file read ============== 23:37:22 (1770439042) [ 3556.654820] LustreError: lustre-OST0000-osc-ffff9531a08e8800: operation ost_read to node 192.168.203.121@tcp failed: rc = -5 [ 3556.658397] LustreError: Skipped 59 previous similar messages [ 3556.660089] LustreError: 2416:0:(osc_request.c:2516:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff9531c1c98000 x1856436290206720/t0(0) o3->lustre-OST0000-osc-ffff9531a08e8800@192.168.203.121@tcp:6/4 lens 488/4536 e 0 to 0 dl 1770439059 ref 2 fl Interpret:RMQU/600/0 rc -5/-5 job:'cat.0' uid:0 gid:0 projid:0 [ 3556.666122] LustreError: 2416:0:(osc_request.c:2516:osc_brw_redo_request()) Skipped 51 previous similar messages [ 3612.643542] LustreError: 2415:0:(osc_request.c:2673:brw_interpret()) lustre-OST0000-osc-ffff9531a08e8800: too many resent retries for object: 10737419265:8518: rc = -5 [ 3612.647143] LustreError: 2415:0:(osc_request.c:2673:brw_interpret()) Skipped 3 previous similar messages [ 3615.068976] Lustre: DEBUG MARKER: == sanity test 398s: i/o error on mirror file read ======= 23:38:21 (1770439101) [ 3618.132686] Lustre: DEBUG MARKER: == sanity test 399a: fake write should not be slower than normal write ========================================================== 23:38:24 (1770439104) [ 3650.044325] Lustre: DEBUG MARKER: == sanity test 399b: fake read should not be slower than normal read ========================================================== 23:38:56 (1770439136) [ 3665.801636] Lustre: DEBUG MARKER: SKIP: sanity test_400a skipping excluded test 400a [ 3666.468706] Lustre: DEBUG MARKER: == sanity test 400b: packaged headers can be compiled ==== 23:39:12 (1770439152) [ 3668.997578] Lustre: DEBUG MARKER: == sanity test 401a: Verify if 'lctl list_param -R' can list parameters recursively ========================================================== 23:39:15 (1770439155) [ 3671.210549] Lustre: DEBUG MARKER: == sanity test 401aa: Verify that 'lctl list_param -p' lists the correct path names ========================================================== 23:39:17 (1770439157) [ 3673.976988] Lustre: DEBUG MARKER: == sanity test 401ab: Check that 'lctl list_param -r' lists only readable params ========================================================== 23:39:20 (1770439160) [ 3676.509559] Lustre: DEBUG MARKER: == sanity test 401ac: Check that 'lctl list_param -w' lists only writable params ========================================================== 23:39:22 (1770439162) [ 3679.301048] Lustre: DEBUG MARKER: == sanity test 401ad: Check that 'lctl list_param -wr' is conjunctive ========================================================== 23:39:25 (1770439165) [ 3681.548877] Lustre: DEBUG MARKER: == sanity test 401b: Verify 'lctl get_param' set_param' continue after error ========================================================== 23:39:27 (1770439167) [ 3683.749994] Lustre: DEBUG MARKER: == sanity test 401c: Verify 'lctl set_param' without value fails in either format. ========================================================== 23:39:30 (1770439170) [ 3685.897307] Lustre: DEBUG MARKER: == sanity test 401d: Verify 'lctl set_param' accepts values containing '=' ========================================================== 23:39:32 (1770439172) [ 3688.213575] Lustre: DEBUG MARKER: == sanity test 401db: Verify 'lctl set_param' does not add trailing '=' ========================================================== 23:39:34 (1770439174) [ 3786.863225] Lustre: DEBUG MARKER: == sanity test 401e: verify 'lctl get_param' works with NID in parameter ========================================================== 23:41:12 (1770439272) [ 3790.508762] Lustre: DEBUG MARKER: == sanity test 401f: check 'lctl list_param' doesn't follow symlinks with --no-links ========================================================== 23:41:16 (1770439276) [ 3793.972390] Lustre: DEBUG MARKER: == sanity test 401ga: check 'set_param -C' sets params upon mount ========================================================== 23:41:20 (1770439280) [ 3794.416606] LustreError: 216125:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff9531a08e8800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 3794.420274] LustreError: 216125:0:(lov_obd.c:783:lov_cleanup()) Skipped 3 previous similar messages [ 3794.423737] LustreError: 216125:0:(obd_class.h:479:obd_check_dev()) Device 6 not setup [ 3794.425581] LustreError: 216125:0:(obd_class.h:479:obd_check_dev()) Skipped 19 previous similar messages [ 3794.449185] Lustre: Unmounted lustre-client [ 3794.450209] Lustre: Skipped 1 previous similar message [ 3794.611698] Lustre: Mounted lustre-client [ 3797.744591] Lustre: DEBUG MARKER: == sanity test 401gb: check 'set_param -d -C' removes client params ========================================================== 23:41:23 (1770439283) [ 3798.406623] Lustre: Mounted lustre-client [ 3801.826175] Lustre: DEBUG MARKER: == sanity test 401gc: check 'lctl find_param' can find params using regex ========================================================== 23:41:28 (1770439288) [ 3806.063866] Lustre: DEBUG MARKER: == sanity test 402: Return ENOENT to lod_generate_and_set_lovea ========================================================== 23:41:32 (1770439292) [ 3810.486913] Lustre: DEBUG MARKER: == sanity test 403: i_nlink should not drop to zero due to aliasing ========================================================== 23:41:36 (1770439296) [ 3810.843274] sysctl (218647): drop_caches: 2 [ 3814.553937] Lustre: DEBUG MARKER: == sanity test 404: validate manual {de}activated works properly for OSPs ========================================================== 23:41:40 (1770439300) [ 3824.839345] Lustre: DEBUG MARKER: == sanity test 405: Various layout swap lock tests ======= 23:41:50 (1770439310) [ 3829.603093] Lustre: DEBUG MARKER: SKIP: sanity test_405 layout swap does not support DOM files so far [ 3830.546853] Lustre: DEBUG MARKER: == sanity test 406: DNE support fs default striping ====== 23:41:56 (1770439316) [ 3851.676689] Lustre: DEBUG MARKER: SKIP: sanity test_407 skipping ALWAYS excluded test 407 [ 3852.536190] Lustre: DEBUG MARKER: == sanity test 408: drop_caches should not hang due to page leaks ========================================================== 23:42:18 (1770439338) [ 3852.672561] Lustre: *** cfs_fail_loc=40a, val=0*** [ 3852.673964] LustreError: 221294:0:(osc_request.c:2979:osc_build_rpc()) lustre-OST0000-osc-ffff9531872a9800: prep_req failed: rc = -22 [ 3852.676496] LustreError: 221294:0:(osc_cache.c:2868:osc_check_rpcs()) Read request failed with -22 [ 3856.464262] bash (221148): drop_caches: 2 [ 3859.462193] Lustre: DEBUG MARKER: == sanity test 409: Large amount of cross-MDTs hard links on the same file ========================================================== 23:42:25 (1770439345) [ 3891.738493] Lustre: DEBUG MARKER: == sanity test 410: Test inode number returned from kernel thread ========================================================== 23:42:57 (1770439377) [ 3891.918747] lustre_kinode_1263: CONFIG_X86_X32 is not set [ 3891.928528] lustre_kinode_1263: inode is 144115373111771250 [ 3891.931793] lustre_kinode_1263: inode is 144115373111771250 [ 3891.935136] lustre_kinode_1263: inode numbers are identical: 144115373111771250 [ 3895.712911] Lustre: DEBUG MARKER: SKIP: sanity test_411a skipping ALWAYS excluded test 411a [ 3896.727915] Lustre: DEBUG MARKER: == sanity test 411b: confirm Lustre can avoid OOM with reasonable cgroups limits ========================================================== 23:43:02 (1770439382) [ 4251.287896] Lustre: DEBUG MARKER: SKIP: sanity test_411b OST space are too small: 3601012K [ 4252.255996] Lustre: DEBUG MARKER: == sanity test 412: mkdir on specific MDTs =============== 23:48:58 (1770439738) [ 4257.424231] Lustre: DEBUG MARKER: == sanity test 413A: get and set qos_rr_index on all clients ========================================================== 23:49:03 (1770439743) [ 4261.377352] Lustre: DEBUG MARKER: == sanity test 413a: QoS mkdir with 'lfs mkdir -i -1' ==== 23:49:07 (1770439747) [ 4517.948495] Lustre: DEBUG MARKER: == sanity test 413b: QoS mkdir under dir whose default LMV starting MDT offset is -1 ========================================================== 23:53:23 (1770440003) [ 4571.000995] Lustre: DEBUG MARKER: == sanity test 413c: mkdir with default LMV max inherit rr ========================================================== 23:54:17 (1770440057) [ 4624.655134] Lustre: DEBUG MARKER: == sanity test 413d: inherit ROOT default LMV ============ 23:55:10 (1770440110) [ 4634.140378] Lustre: DEBUG MARKER: == sanity test 413e: check default max-inherit value ===== 23:55:20 (1770440120) [ 4638.548228] Lustre: DEBUG MARKER: == sanity test 413f: lfs getdirstripe -D list ROOT default LMV if it's not set on dir ========================================================== 23:55:24 (1770440124) [ 4642.914918] Lustre: DEBUG MARKER: == sanity test 413g: enforce ROOT default LMV on subdir mount ========================================================== 23:55:28 (1770440128) [ 4643.393280] Lustre: Mounted lustre-client [ 4643.519460] LustreError: 238712:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff9531882d8800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 4643.525676] LustreError: 238712:0:(lov_obd.c:783:lov_cleanup()) Skipped 3 previous similar messages [ 4643.535923] LustreError: 238712:0:(obd_class.h:479:obd_check_dev()) Device 12 not setup [ 4643.539708] LustreError: 238712:0:(obd_class.h:479:obd_check_dev()) Skipped 19 previous similar messages [ 4643.585305] Lustre: Unmounted lustre-client [ 4643.587789] Lustre: Skipped 1 previous similar message [ 4655.661139] LustreError: 239393:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff9531a9d52000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 4655.669111] LustreError: 239393:0:(lov_obd.c:783:lov_cleanup()) Skipped 1 previous similar message [ 4655.679678] LustreError: 239393:0:(obd_class.h:479:obd_check_dev()) Device 12 not setup [ 4655.684349] LustreError: 239393:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 4655.775284] Lustre: Unmounted lustre-client [ 4656.840916] Lustre: DEBUG MARKER: == sanity test 413h: don't stick to parent for round-robin dirs ========================================================== 23:55:42 (1770440142) [ 4658.620656] Lustre: DEBUG MARKER: dir=/mnt/lustre/d413h.sanity/l1/l2/l3/l4/l5: [ 4662.408252] Lustre: DEBUG MARKER: dir=/mnt/lustre/d413h.sanity/l1/l2/l3/l4/l5/d0: [ 4666.238649] Lustre: DEBUG MARKER: dir=/mnt/lustre/d413h.sanity/l1/l2/l3/l4/l5/d0/d0: [ 4669.856362] Lustre: DEBUG MARKER: dir=/mnt/lustre/d413h.sanity/l1/l2/l3/l4/l5/d0/d0/d0: [ 4673.464007] Lustre: DEBUG MARKER: dir=/mnt/lustre/d413h.sanity/l1/l2/l3/l4/l5/d0/d0/d0/d0: [ 4677.165925] Lustre: DEBUG MARKER: dir=/mnt/lustre/d413h.sanity/l1/l2/l3/l4/l5/d0/d0/d0/d0/d0: [ 4680.883949] Lustre: DEBUG MARKER: dir=/mnt/lustre/d413h.sanity/l1/l2/l3/l4/l5/d0/d0/d0/d0/d0/d0: [ 4694.114753] Lustre: DEBUG MARKER: == sanity test 413i: check default layout inheritance ==== 23:56:20 (1770440180) [ 4698.105093] Lustre: DEBUG MARKER: == sanity test 413j: set default LMV by setxattr ========= 23:56:24 (1770440184) [ 4704.011047] Lustre: DEBUG MARKER: == sanity test 413k: QoS mkdir exclude prefixes ========== 23:56:30 (1770440190) [ 4708.467650] Lustre: DEBUG MARKER: == sanity test 413l: QoS mkdir exclude patterns ========== 23:56:34 (1770440194) [ 4711.881625] Lustre: DEBUG MARKER: == sanity test 413z: 413 test cleanup ==================== 23:56:38 (1770440198) [ 4741.801547] Lustre: DEBUG MARKER: == sanity test 414: simulate ENOMEM in ptlrpc_register_bulk() ========================================================== 23:57:08 (1770440228) [ 4741.872642] Lustre: *** cfs_fail_loc=521, val=0*** [ 4741.873668] LustreError: 2414:0:(niobuf.c:412:ptlrpc_register_bulk()) lustre-OST0001-osc-ffff9531872a9800: LNetMEAttach failed x1856436306201985/1: rc = -12 [ 4742.266923] LustreError: 249642:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff9531872a9800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 4742.269808] LustreError: 249642:0:(lov_obd.c:783:lov_cleanup()) Skipped 1 previous similar message [ 4742.274560] LustreError: 249642:0:(obd_class.h:479:obd_check_dev()) Device 6 not setup [ 4742.276323] LustreError: 249642:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 4742.382286] Lustre: Unmounted lustre-client [ 4742.632792] Lustre: Mounted lustre-client [ 4742.635117] Lustre: Skipped 1 previous similar message [ 4746.466843] Lustre: DEBUG MARKER: == sanity test 415: lock revoke is not missing =========== 23:57:12 (1770440232) [ 4811.649955] Lustre: DEBUG MARKER: == sanity test 416: transaction start failure won't cause system hung ========================================================== 23:58:17 (1770440297) [ 4815.603374] Lustre: DEBUG MARKER: == sanity test 417: disable remote dir, striped dir and dir migration ========================================================== 23:58:21 (1770440301) [ 4824.303588] Lustre: DEBUG MARKER: == sanity test 418: df and lfs df outputs match ========== 23:58:30 (1770440310) [ 4856.692802] Lustre: DEBUG MARKER: == sanity test 419: Verify open file by name doesn't crash kernel ========================================================== 23:59:02 (1770440342) [ 4859.757870] Lustre: DEBUG MARKER: == sanity test 420: clear SGID bit on non-directories for non-members ========================================================== 23:59:06 (1770440346) [ 4863.465813] Lustre: DEBUG MARKER: == sanity test 421a: simple rm by fid ==================== 23:59:09 (1770440349) [ 4867.501904] Lustre: DEBUG MARKER: == sanity test 421b: rm by fid on open file ============== 23:59:13 (1770440353) [ 4870.818956] Lustre: DEBUG MARKER: == sanity test 421c: rm by fid against hardlinked files == 23:59:16 (1770440356) [ 4879.439974] Lustre: DEBUG MARKER: == sanity test 421d: rmfid en masse ====================== 23:59:25 (1770440365) [ 4932.587743] Lustre: DEBUG MARKER: == sanity test 421e: rmfid in DNE ======================== 00:00:18 (1770440418) [ 4943.846866] Lustre: DEBUG MARKER: == sanity test 421f: rmfid checks permissions ============ 00:00:29 (1770440429) [ 4944.883841] Lustre: Mounted lustre-client [ 4948.282167] LustreError: 261015:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff9531a99a6800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 4948.285748] LustreError: 261015:0:(lov_obd.c:783:lov_cleanup()) Skipped 1 previous similar message [ 4948.290652] LustreError: 261015:0:(obd_class.h:479:obd_check_dev()) Device 12 not setup [ 4948.293853] LustreError: 261015:0:(obd_class.h:479:obd_check_dev()) Skipped 9 previous similar messages [ 4948.329119] Lustre: Unmounted lustre-client [ 4949.290058] Lustre: DEBUG MARKER: == sanity test 421g: rmfid to return errors properly ===== 00:00:35 (1770440435) [ 4961.815829] Lustre: DEBUG MARKER: == sanity test 421h: rmfid with fileset mount ============ 00:00:48 (1770440448) [ 4962.703748] Lustre: Mounted lustre-client [ 4967.455946] Lustre: DEBUG MARKER: == sanity test 422: kill a process with RPC in progress == 00:00:53 (1770440453) [ 4989.919159] Lustre: 262817:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1770440456/real 1770440456] req@ffff953183073800 x1856436312976128/t0(0) o101->lustre-MDT0000-mdc-ffff9531a9941800@192.168.203.121@tcp:12/10 lens 576/1584 e 0 to 1 dl 1770440476 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'touch.0' uid:0 gid:0 projid:0 [ 4989.938429] Lustre: lustre-MDT0000-mdc-ffff9531a9941800: Connection to lustre-MDT0000 (at 192.168.203.121@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 4989.949482] Lustre: Skipped 2 previous similar messages [ 4989.969824] Lustre: lustre-MDT0000-mdc-ffff9531a9941800: Connection restored to 192.168.203.121@tcp (at 192.168.203.121@tcp) [ 4989.975310] Lustre: Skipped 23 previous similar messages [ 5010.399146] Lustre: 262828:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1770440476/real 1770440476] req@ffff9531b1172680 x1856436312977280/t0(0) o36->lustre-MDT0000-mdc-ffff9531a9941800@192.168.203.121@tcp:13/10 lens 504/840 e 0 to 1 dl 1770440496 ref 2 fl Rpc:XQr/202/ffffffff rc -11/-1 job:'mv.0' uid:0 gid:0 projid:4294967295 [ 5010.413251] Lustre: 262828:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 5013.174638] Lustre: DEBUG MARKER: touch [ 5030.879200] Lustre: 262817:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1770440497/real 1770440497] req@ffff953183073800 x1856436312976128/t0(0) o101->lustre-MDT0000-mdc-ffff9531a9941800@192.168.203.121@tcp:12/10 lens 576/1584 e 0 to 1 dl 1770440517 ref 2 fl Rpc:XQr/602/ffffffff rc 0/-1 job:'touch.0' uid:0 gid:0 projid:0 [ 5030.896366] Lustre: lustre-MDT0000-mdc-ffff9531a9941800: Connection to lustre-MDT0000 (at 192.168.203.121@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 5030.905078] Lustre: Skipped 1 previous similar message [ 5030.917138] Lustre: lustre-MDT0000-mdc-ffff9531a9941800: Connection restored to 192.168.203.121@tcp (at 192.168.203.121@tcp) [ 5030.924976] Lustre: Skipped 1 previous similar message [ 5036.225889] Lustre: DEBUG MARKER: == sanity test 423: statfs should return a right data ==== 00:02:02 (1770440522) [ 5041.635716] Lustre: DEBUG MARKER: == sanity test 424: simulate ENOMEM in ptl_send_rpc bulk reply ME attach ========================================================== 00:02:07 (1770440527) [ 5041.720642] Lustre: *** cfs_fail_loc=522, val=0*** [ 5041.723508] LustreError: 2416:0:(niobuf.c:1044:ptl_send_rpc()) LNetMEAttach failed: -12 [ 5045.262516] Lustre: DEBUG MARKER: == sanity test 425: lock count should not exceed lru size ========================================================== 00:02:11 (1770440531) [ 5059.507781] Lustre: DEBUG MARKER: == sanity test 426: splice test on Lustre ================ 00:02:25 (1770440545) [ 5063.893170] Lustre: DEBUG MARKER: == sanity test 427: Failed DNE2 update request shouldn't corrupt updatelog ========================================================== 00:02:30 (1770440550) [ 5096.069823] Lustre: DEBUG MARKER: oleg321-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 5096.901167] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5104.173753] Lustre: DEBUG MARKER: == sanity test 428: large block size IO should not hang == 00:03:10 (1770440590) [ 5129.631718] Lustre: DEBUG MARKER: == sanity test 429: verify if opencache flag on client side does work ========================================================== 00:03:35 (1770440615) [ 5133.332149] Lustre: DEBUG MARKER: == sanity test 430a: lseek: SEEK_DATA/SEEK_HOLE basic functionality ========================================================== 00:03:39 (1770440619) [ 5140.775982] Lustre: DEBUG MARKER: == sanity test 430b: lseek: SEEK_DATA/SEEK_HOLE special cases ========================================================== 00:03:46 (1770440626) [ 5145.354125] Lustre: DEBUG MARKER: == sanity test 430c: lseek: external tools check ========= 00:03:51 (1770440631) [ 5149.560820] Lustre: DEBUG MARKER: == sanity test 431: Restart transaction for IO =========== 00:03:55 (1770440635) [ 5153.012367] bash (270558): drop_caches: 3 [ 5157.348370] Lustre: DEBUG MARKER: == sanity test 432: mv dir from outside Lustre =========== 00:04:03 (1770440643) [ 5168.967416] Lustre: DEBUG MARKER: == sanity test 433: ldlm lock cancel releases dentries and inodes ========================================================== 00:04:14 (1770440654) [ 5185.296711] Lustre: DEBUG MARKER: == sanity test 434: Client should not send RPCs for security.selinux with SElinux disabled ========================================================== 00:04:31 (1770440671) [ 5192.579238] Lustre: DEBUG MARKER: == sanity test 440: bash completion for lfs, lctl ======== 00:04:38 (1770440678) [ 5196.000601] Lustre: DEBUG MARKER: == sanity test 442: truncate vs read/write should not panic ========================================================== 00:04:42 (1770440682) [ 5197.166444] LustreError: 274730:0:(llite_lib.c:3162:ll_truncate_inode_pages_final()) cfs_fail_timeout id 1430 sleeping for 5000ms [ 5202.167101] LustreError: 274730:0:(llite_lib.c:3162:ll_truncate_inode_pages_final()) cfs_fail_timeout id 1430 awake [ 5202.171886] LustreError: 274731:0:(llite_lib.c:3162:ll_truncate_inode_pages_final()) cfs_fail_timeout id 1430 sleeping for 5000ms [ 5207.271074] LustreError: 274731:0:(llite_lib.c:3162:ll_truncate_inode_pages_final()) cfs_fail_timeout id 1430 awake [ 5207.275667] LustreError: 274730:0:(llite_lib.c:3162:ll_truncate_inode_pages_final()) cfs_fail_timeout id 1430 sleeping for 5000ms [ 5212.375094] LustreError: 274730:0:(llite_lib.c:3162:ll_truncate_inode_pages_final()) cfs_fail_timeout id 1430 awake [ 5212.380209] LustreError: 274731:0:(llite_lib.c:3162:ll_truncate_inode_pages_final()) cfs_fail_timeout id 1430 sleeping for 5000ms [ 5217.479078] LustreError: 274731:0:(llite_lib.c:3162:ll_truncate_inode_pages_final()) cfs_fail_timeout id 1430 awake [ 5217.484257] LustreError: 274730:0:(llite_lib.c:3162:ll_truncate_inode_pages_final()) cfs_fail_timeout id 1430 sleeping for 5000ms [ 5222.583119] LustreError: 274730:0:(llite_lib.c:3162:ll_truncate_inode_pages_final()) cfs_fail_timeout id 1430 awake [ 5227.688059] LustreError: 274730:0:(llite_lib.c:3162:ll_truncate_inode_pages_final()) cfs_fail_timeout id 1430 sleeping for 5000ms [ 5227.694672] LustreError: 274730:0:(llite_lib.c:3162:ll_truncate_inode_pages_final()) Skipped 1 previous similar message [ 5232.695126] LustreError: 274730:0:(llite_lib.c:3162:ll_truncate_inode_pages_final()) cfs_fail_timeout id 1430 awake [ 5232.700976] LustreError: 274730:0:(llite_lib.c:3162:ll_truncate_inode_pages_final()) Skipped 1 previous similar message [ 5247.999876] LustreError: 274730:0:(llite_lib.c:3162:ll_truncate_inode_pages_final()) cfs_fail_timeout id 1430 sleeping for 5000ms [ 5248.005025] LustreError: 274730:0:(llite_lib.c:3162:ll_truncate_inode_pages_final()) Skipped 3 previous similar messages [ 5253.103132] LustreError: 274730:0:(llite_lib.c:3162:ll_truncate_inode_pages_final()) cfs_fail_timeout id 1430 awake [ 5253.112278] LustreError: 274730:0:(llite_lib.c:3162:ll_truncate_inode_pages_final()) Skipped 3 previous similar messages [ 5283.696133] LustreError: 274731:0:(llite_lib.c:3162:ll_truncate_inode_pages_final()) cfs_fail_timeout id 1430 sleeping for 5000ms [ 5283.701696] LustreError: 274731:0:(llite_lib.c:3162:ll_truncate_inode_pages_final()) Skipped 6 previous similar messages [ 5288.799164] LustreError: 274731:0:(llite_lib.c:3162:ll_truncate_inode_pages_final()) cfs_fail_timeout id 1430 awake [ 5288.804294] LustreError: 274731:0:(llite_lib.c:3162:ll_truncate_inode_pages_final()) Skipped 6 previous similar messages [ 5349.960146] LustreError: 274730:0:(llite_lib.c:3162:ll_truncate_inode_pages_final()) cfs_fail_timeout id 1430 sleeping for 5000ms [ 5349.966353] LustreError: 274730:0:(llite_lib.c:3162:ll_truncate_inode_pages_final()) Skipped 12 previous similar messages [ 5354.967129] LustreError: 274730:0:(llite_lib.c:3162:ll_truncate_inode_pages_final()) cfs_fail_timeout id 1430 awake [ 5354.972826] LustreError: 274730:0:(llite_lib.c:3162:ll_truncate_inode_pages_final()) Skipped 12 previous similar messages [ 5482.384060] LustreError: 274730:0:(llite_lib.c:3162:ll_truncate_inode_pages_final()) cfs_fail_timeout id 1430 sleeping for 5000ms [ 5482.390258] LustreError: 274730:0:(llite_lib.c:3162:ll_truncate_inode_pages_final()) Skipped 25 previous similar messages [ 5487.391116] LustreError: 274730:0:(llite_lib.c:3162:ll_truncate_inode_pages_final()) cfs_fail_timeout id 1430 awake [ 5487.393877] LustreError: 274730:0:(llite_lib.c:3162:ll_truncate_inode_pages_final()) Skipped 25 previous similar messages [ 5531.978294] Lustre: DEBUG MARKER: == sanity test 460d: Check encrypt pools output ========== 00:10:18 (1770441018) [ 5535.657735] Lustre: DEBUG MARKER: == sanity test 600a: basic test for mlock()ed file ======= 00:10:21 (1770441021) [ 5536.653390] Lustre: DEBUG MARKER: SKIP: sanity test_600a This test needs vmtouch utility [ 5537.617771] Lustre: DEBUG MARKER: == sanity test 600b: mlock a file (via vmtouch) larger than max_cached_mb ========================================================== 00:10:23 (1770441023) [ 5538.614185] Lustre: DEBUG MARKER: SKIP: sanity test_600b This test needs vmtouch utility [ 5539.405630] Lustre: DEBUG MARKER: == sanity test 600c: Test I/O when mlocked page count > @max_cached_mb ========================================================== 00:10:25 (1770441025) [ 5540.353574] Lustre: DEBUG MARKER: SKIP: sanity test_600c This test needs vmtouch utility [ 5541.276672] Lustre: DEBUG MARKER: == sanity test 600d: Test I/O with limited LRU page slots (some was mlocked) ========================================================== 00:10:27 (1770441027) [ 5542.323956] Lustre: DEBUG MARKER: SKIP: sanity test_600d This test needs vmtouch utility [ 5543.311501] Lustre: DEBUG MARKER: == sanity test 801a: write barrier user interfaces and stat machine ========================================================== 00:10:29 (1770441029) [ 5581.497948] Lustre: DEBUG MARKER: == sanity test 801b: modification will be blocked by write barrier ========================================================== 00:11:07 (1770441067) [ 5586.090253] Lustre: 278549:0:(client.c:1637:after_reply()) @@@ resending request on EINPROGRESS req@ffff9531ba096300 x1856436314118528/t0(0) o36->lustre-MDT0001-mdc-ffff9531a9941800@192.168.203.121@tcp:12/10 lens 496/440 e 0 to 0 dl 1770441127 ref 2 fl Rpc:RQU/202/0 rc 0/-115 job:'ln.0' uid:0 gid:0 projid:4294967295 [ 5586.106793] Lustre: 278549:0:(client.c:1637:after_reply()) Skipped 2 previous similar messages [ 5599.085923] Lustre: DEBUG MARKER: == sanity test 801c: rescan barrier bitmap =============== 00:11:25 (1770441085) [ 5602.279646] Lustre: lustre-MDT0001-mdc-ffff9531a9941800: Connection to lustre-MDT0001 (at 192.168.203.121@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 5602.289306] Lustre: Skipped 1 previous similar message [ 5614.716219] Lustre: lustre-MDT0001-mdc-ffff9531a9941800: Connection restored to 192.168.203.121@tcp (at 192.168.203.121@tcp) [ 5614.719214] Lustre: Skipped 1 previous similar message [ 5616.139494] Lustre: DEBUG MARKER: == sanity test 802b: be able to set MDTs to readonly ===== 00:11:42 (1770441102) [ 5623.605777] Lustre: DEBUG MARKER: == sanity test 802c: be able to set OFDs to readonly ===== 00:11:49 (1770441109) [ 5630.242501] Lustre: DEBUG MARKER: == sanity test 803a: verify agent object for remote object ========================================================== 00:11:56 (1770441116) [ 5648.543645] Lustre: DEBUG MARKER: == sanity test 803b: remote object can getattr from cache ========================================================== 00:12:14 (1770441134) [ 5653.515690] Lustre: DEBUG MARKER: == sanity test 804: verify agent entry for remote entry == 00:12:19 (1770441139) [ 5671.013380] LustreError: 283867:0:(lmv_obd.c:1435:lmv_statfs()) lustre-MDT0000-mdc-ffff9531a9941800: can't stat MDS #0: rc = -19 [ 5672.932778] LustreError: MGC192.168.203.121@tcp: Connection to MGS (at 192.168.203.121@tcp) was lost; in progress operations using this service will fail [ 5672.947286] Lustre: Evicted from MGS (at 192.168.203.121@tcp) after server handle changed from 0x115a18b47d457d0a to 0x115a18b47d5265f8 [ 5686.263974] Lustre: DEBUG MARKER: == sanity test 805: ZFS can remove from full fs ========== 00:12:52 (1770441172) [ 5687.541392] Lustre: DEBUG MARKER: SKIP: sanity test_805 ZFS specific test [ 5688.112258] Lustre: DEBUG MARKER: == sanity test 806: Verify Lazy Size on MDS ============== 00:12:54 (1770441174) [ 5704.291902] Lustre: DEBUG MARKER: == sanity test 807a: verify LSOM syncing tool ============ 00:13:10 (1770441190) [ 5709.834564] Lustre: DEBUG MARKER: oleg321-client.virtnet: executing cancel_lru_locks osc [ 5723.159819] Lustre: DEBUG MARKER: == sanity test 807b: verify lfs somsync utility ========== 00:13:29 (1770441209) [ 5725.151829] Lustre: DEBUG MARKER: oleg321-client.virtnet: executing cancel_lru_locks osc [ 5734.214585] Lustre: DEBUG MARKER: == sanity test 808: Check trusted.som xattr not logged in Changelogs ========================================================== 00:13:40 (1770441220) [ 5744.924406] Lustre: DEBUG MARKER: == sanity test 809: Verify no SOM xattr store for DoM-only files ========================================================== 00:13:50 (1770441230) [ 5748.780354] Lustre: DEBUG MARKER: == sanity test 810: partial page writes on ZFS (LU-11663) ========================================================== 00:13:54 (1770441234) [ 5748.945979] Lustre: *** cfs_fail_loc=411, val=0*** [ 5748.948673] Lustre: Skipped 1 previous similar message [ 5749.523526] Lustre: *** cfs_fail_loc=411, val=0*** [ 5749.526126] Lustre: Skipped 7 previous similar messages [ 5750.617958] Lustre: *** cfs_fail_loc=411, val=0*** [ 5750.620394] Lustre: Skipped 15 previous similar messages [ 5756.058949] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 5757.153516] Lustre: DEBUG MARKER: == sanity test 812a: do not drop reqs generated when imp is going to idle (LU-11951) ========================================================== 00:14:03 (1770441243) [ 5758.975895] Lustre: DEBUG MARKER: oleg321-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9531a9941800.ost_server_uuid 50 [ 5759.766620] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9531a9941800.ost_server_uuid in FULL state after 0 sec [ 5762.218197] Lustre: DEBUG MARKER: oleg321-client.virtnet: executing wait_import_state CONNECTING osc.lustre-OST0000-osc-ffff9531a9941800.ost_server_uuid 50 [ 5771.244129] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9531a9941800.ost_server_uuid in CONNECTING state after 8 sec [ 5775.247911] Lustre: DEBUG MARKER: == sanity test 812b: do not drop no resend request for idle connect ========================================================== 00:14:21 (1770441261) [ 5777.141640] Lustre: DEBUG MARKER: oleg321-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9531a9941800.ost_server_uuid 50 [ 5777.879395] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9531a9941800.ost_server_uuid in FULL state after 0 sec [ 5780.128927] Lustre: DEBUG MARKER: oleg321-client.virtnet: executing wait_import_state CONNECTING osc.lustre-OST0000-osc-ffff9531a9941800.ost_server_uuid 50 [ 5792.299467] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9531a9941800.ost_server_uuid in CONNECTING state after 11 sec [ 5794.861209] Lustre: DEBUG MARKER: oleg321-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff9531a9941800.ost_server_uuid 50 [ 5806.915441] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9531a9941800.ost_server_uuid in IDLE state after 11 sec [ 5810.775936] Lustre: DEBUG MARKER: == sanity test 812c: idle import vs lock enqueue race ==== 00:14:56 (1770441296) [ 5812.639422] Lustre: DEBUG MARKER: oleg321-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9531a9941800.ost_server_uuid 50 [ 5813.373220] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9531a9941800.ost_server_uuid in FULL state after 0 sec [ 5826.527658] LustreError: 276847:0:(import.c:2064:ptlrpc_disconnect_and_idle_import()) cfs_race id 533 sleeping [ 5828.508459] LustreError: 293711:0:(osc_lock.c:1033:osc_lock_enqueue()) cfs_fail_race id 533 waking [ 5828.515821] LustreError: 276847:0:(import.c:2064:ptlrpc_disconnect_and_idle_import()) cfs_fail_race id 533 awake: rc=3018 [ 5829.028348] LustreError: 293711:0:(osc_lock.c:1033:osc_lock_enqueue()) cfs_fail_race id 533 waking [ 5833.464828] Lustre: DEBUG MARKER: == sanity test 813: File heat verfication ================ 00:15:19 (1770441319) [ 5964.710992] Lustre: DEBUG MARKER: == sanity test 814: sparse cp works as expected (LU-12361) ========================================================== 00:17:30 (1770441450) [ 5968.174742] Lustre: DEBUG MARKER: == sanity test 815: zero byte tiny write doesn't hang (LU-12382) ========================================================== 00:17:34 (1770441454) [ 5971.810645] Lustre: DEBUG MARKER: == sanity test 816: do not reset lru_resize on idle reconnect ========================================================== 00:17:37 (1770441457) [ 5973.678492] Lustre: DEBUG MARKER: oleg321-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9531a9941800.ost_server_uuid 50 [ 5974.371150] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9531a9941800.ost_server_uuid in FULL state after 0 sec [ 5976.355672] Lustre: DEBUG MARKER: oleg321-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff9531a9941800.ost_server_uuid 50 [ 5989.475978] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9531a9941800.ost_server_uuid in IDLE state after 12 sec [ 5993.302462] Lustre: DEBUG MARKER: SKIP: sanity test_817 skipping ALWAYS excluded test 817 [ 5994.261198] Lustre: DEBUG MARKER: == sanity test 818: unlink with failed llog ============== 00:18:00 (1770441480) [ 5998.563824] Lustre: lustre-MDT0000-mdc-ffff9531a9941800: Connection to lustre-MDT0000 (at 192.168.203.121@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 5998.569044] Lustre: Skipped 2 previous similar messages [ 6003.683448] LustreError: MGC192.168.203.121@tcp: Connection to MGS (at 192.168.203.121@tcp) was lost; in progress operations using this service will fail [ 6003.694644] Lustre: Evicted from MGS (at 192.168.203.121@tcp) after server handle changed from 0x115a18b47d5265f8 to 0x115a18b47d529952 [ 6003.701923] Lustre: MGC192.168.203.121@tcp: Connection restored to 192.168.203.121@tcp (at 192.168.203.121@tcp) [ 6003.706680] Lustre: Skipped 3 previous similar messages [ 6003.727928] LustreError: 2412:0:(client.c:3418:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9531b1173100 x1856436314275840/t30064771231(30064771231) o101->lustre-MDT0000-mdc-ffff9531a9941800@192.168.203.121@tcp:12/10 lens 576/608 e 0 to 0 dl 1770441545 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'md5sum.0' uid:0 gid:0 projid:0 [ 6029.279102] Lustre: 2413:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1770441500/real 1770441500] req@ffff9531ba094380 x1856436314457344/t0(0) o400->MGC192.168.203.121@tcp@192.168.203.121@tcp:26/25 lens 224/224 e 0 to 1 dl 1770441516 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6029.285097] LustreError: MGC192.168.203.121@tcp: Connection to MGS (at 192.168.203.121@tcp) was lost; in progress operations using this service will fail [ 6029.291993] Lustre: Evicted from MGS (at 192.168.203.121@tcp) after server handle changed from 0x115a18b47d529952 to 0x115a18b47d529ddc [ 6029.309839] LustreError: 2412:0:(client.c:3418:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9531b1173100 x1856436314275840/t30064771231(30064771231) o101->lustre-MDT0000-mdc-ffff9531a9941800@192.168.203.121@tcp:12/10 lens 576/608 e 0 to 0 dl 1770441571 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'md5sum.0' uid:0 gid:0 projid:0 [ 6029.315359] LustreError: 2412:0:(client.c:3418:ptlrpc_replay_interpret()) Skipped 4 previous similar messages [ 6031.687792] Lustre: DEBUG MARKER: oleg321-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 6032.237927] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6034.387407] Lustre: DEBUG MARKER: == sanity test 819a: too big niobuf in read ============== 00:18:40 (1770441520) [ 6037.925494] Lustre: DEBUG MARKER: == sanity test 819b: too big niobuf in write ============= 00:18:44 (1770441524) [ 6054.879248] Lustre: 2414:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1770441525/real 1770441525] req@ffff9531ba097480 x1856436314466432/t0(0) o4->lustre-OST0000-osc-ffff9531a9941800@192.168.203.121@tcp:6/4 lens 488/448 e 0 to 1 dl 1770441541 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'dd.0' uid:0 gid:0 projid:0 [ 6059.401924] Lustre: DEBUG MARKER: == sanity test 820: update max EA from open intent ======= 00:19:05 (1770441545) [ 6059.929701] LustreError: 300650:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff9531a9941800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 6059.935109] LustreError: 300650:0:(lov_obd.c:783:lov_cleanup()) Skipped 5 previous similar messages [ 6059.941878] LustreError: 300650:0:(obd_class.h:479:obd_check_dev()) Device 6 not setup [ 6059.945033] LustreError: 300650:0:(obd_class.h:479:obd_check_dev()) Skipped 23 previous similar messages [ 6059.975141] Lustre: Unmounted lustre-client [ 6059.976312] Lustre: Skipped 2 previous similar messages [ 6064.335727] Lustre: Mounted lustre-client [ 6064.337357] Lustre: Skipped 1 previous similar message [ 6074.855843] LustreError: lustre-OST0000-osc-ffff9531c0ad1800: operation ost_connect to node 192.168.203.121@tcp failed: rc = -16 [ 6074.859892] LustreError: Skipped 19 previous similar messages [ 6083.877717] Lustre: DEBUG MARKER: == sanity test 823: Setting create_count > OST_MAX_PRECREATE is lowered to maximum ========================================================== 00:19:29 (1770441569) [ 6086.661168] Lustre: DEBUG MARKER: setting create_count to 100200: [ 6087.161880] Lustre: DEBUG MARKER: -result- count: 9984 with max: 20000, expecting: 9984 [ 6089.860618] Lustre: DEBUG MARKER: == sanity test 831: throttling unlink/setattr queuing on OSP ========================================================== 00:19:36 (1770441576) [ 6100.712170] Lustre: 303062:0:(client.c:1637:after_reply()) @@@ resending request on EINPROGRESS req@ffff9531c0a63800 x1856436315025664/t0(0) o36->lustre-MDT0000-mdc-ffff9531c0ad1800@192.168.203.121@tcp:12/10 lens 488/456 e 0 to 0 dl 1770441642 ref 2 fl Rpc:RQU/202/0 rc 0/-115 job:'unlinkmany.0' uid:0 gid:0 projid:4294967295 [ 6103.777774] Lustre: 303062:0:(client.c:1637:after_reply()) @@@ resending request on EINPROGRESS req@ffff9531c0a63100 x1856436315026432/t0(0) o36->lustre-MDT0000-mdc-ffff9531c0ad1800@192.168.203.121@tcp:12/10 lens 488/456 e 0 to 0 dl 1770441645 ref 2 fl Rpc:RQU/202/0 rc 0/-115 job:'unlinkmany.0' uid:0 gid:0 projid:4294967295 [ 6110.189117] Lustre: 303062:0:(client.c:1637:after_reply()) @@@ resending request on EINPROGRESS req@ffff9531b8afd180 x1856436315053568/t0(0) o36->lustre-MDT0000-mdc-ffff9531c0ad1800@192.168.203.121@tcp:12/10 lens 488/456 e 0 to 0 dl 1770441652 ref 2 fl Rpc:RQU/202/0 rc 0/-115 job:'unlinkmany.0' uid:0 gid:0 projid:4294967295 [ 6116.384550] Lustre: 303062:0:(client.c:1637:after_reply()) @@@ resending request on EINPROGRESS req@ffff9531c0a62a00 x1856436315080960/t0(0) o36->lustre-MDT0000-mdc-ffff9531c0ad1800@192.168.203.121@tcp:12/10 lens 488/456 e 0 to 0 dl 1770441658 ref 2 fl Rpc:RQU/202/0 rc 0/-115 job:'unlinkmany.0' uid:0 gid:0 projid:4294967295 [ 6128.738153] Lustre: 303062:0:(client.c:1637:after_reply()) @@@ resending request on EINPROGRESS req@ffff953190a09c00 x1856436315109632/t0(0) o36->lustre-MDT0000-mdc-ffff9531c0ad1800@192.168.203.121@tcp:12/10 lens 488/456 e 0 to 0 dl 1770441670 ref 2 fl Rpc:RQU/202/0 rc 0/-115 job:'unlinkmany.0' uid:0 gid:0 projid:4294967295 [ 6128.745646] Lustre: 303062:0:(client.c:1637:after_reply()) Skipped 1 previous similar message [ 6147.745765] Lustre: 303062:0:(client.c:1637:after_reply()) @@@ resending request on EINPROGRESS req@ffff9531a98dc700 x1856436315191936/t0(0) o36->lustre-MDT0000-mdc-ffff9531c0ad1800@192.168.203.121@tcp:12/10 lens 488/456 e 0 to 0 dl 1770441689 ref 2 fl Rpc:RQU/202/0 rc 0/-115 job:'unlinkmany.0' uid:0 gid:0 projid:4294967295 [ 6147.753528] Lustre: 303062:0:(client.c:1637:after_reply()) Skipped 3 previous similar messages [ 6167.193544] Lustre: DEBUG MARKER: == sanity test 832: lfs rm_entry ========================= 00:20:53 (1770441653) [ 6169.849893] Lustre: DEBUG MARKER: == sanity test 833: Mixed buffered/direct read and write should not return -EIO ========================================================== 00:20:56 (1770441656) [ 6211.188415] Lustre: DEBUG MARKER: == sanity test 834: mmap readahead for madvise with MADV_HUGEPAGE ========================================================== 00:21:37 (1770441697) [ 6560.488953] Lustre: DEBUG MARKER: SKIP: sanity test_842 skipping SLOW test 842 [ 6561.124901] Lustre: DEBUG MARKER: == sanity test 850: lljobstat can parse living and aggregated job_stats ========================================================== 00:27:27 (1770442047) [ 6563.919955] Lustre: DEBUG MARKER: == sanity test 851: fanotify can monitor open/read/write/close events for lustre fs ========================================================== 00:27:30 (1770442050) [ 6566.502229] Lustre: DEBUG MARKER: == sanity test 852: mkdir using intent lock for striped directory ========================================================== 00:27:32 (1770442052) [ 6569.181673] Lustre: DEBUG MARKER: == sanity test 853: Verify that random fadvise works as expected ========================================================== 00:27:35 (1770442055) [ 6593.728500] Lustre: DEBUG MARKER: == sanity test 854: verify llite.*.max_cached_mb setting ========================================================== 00:28:00 (1770442080) [ 6594.363343] Lustre: DEBUG MARKER: Initial readahead: 256/64/4 MB [ 6594.966177] Lustre: DEBUG MARKER: Initial max_cached_mb: 1846 MB [ 6595.586673] Lustre: DEBUG MARKER: Total RAM: 3693 MB [ 6596.187173] Lustre: DEBUG MARKER: max_cached_mb=75%: 2769 MB, expect ~2769 MB [ 6596.754123] Lustre: DEBUG MARKER: max_ra_mb=25%: got 924 MB, expect ~923 MB [ 6597.311368] Lustre: DEBUG MARKER: max_ra_per_file_mb=5%: got 185 MB, expect ~184 [ 6597.859923] Lustre: DEBUG MARKER: max_ra_whole_mb=1%: got 37 MB, expect ~36 [ 6598.419415] Lustre: DEBUG MARKER: Testing if max_read_ahead_mb=51% is capped at 50% [ 6598.435284] Lustre: 309761:0:(lproc_llite.c:436:max_read_ahead_mb_store()) lustre: limit max_read_ahead_mb=1884 to totalram/2=1846MB [ 6598.997836] Lustre: DEBUG MARKER: max_read_ahead_mb is 1846 MB [ 6599.582767] Lustre: DEBUG MARKER: Value correctly capped at ~50% of RAM (1846 <= 1846) [ 6600.163849] Lustre: DEBUG MARKER: Testing if max_read_ahead_mb=90% is capped at 50% [ 6600.184688] Lustre: 310178:0:(lproc_llite.c:436:max_read_ahead_mb_store()) lustre: limit max_read_ahead_mb=3324 to totalram/2=1846MB [ 6600.782220] Lustre: DEBUG MARKER: max_read_ahead_mb is 1846 MB [ 6601.376982] Lustre: DEBUG MARKER: Value correctly capped at ~50% of RAM (1846 <= 1846) [ 6601.930484] Lustre: DEBUG MARKER: Test if max_read_ahead_per_file_mb > max_read_ahead_mb is capped [ 6601.950912] Lustre: 310594:0:(lproc_llite.c:484:max_read_ahead_per_file_mb_store()) lustre: limit max_read_ahead_per_file_mb=2216 to max_read_ahead_mb=1846 [ 6602.497312] Lustre: DEBUG MARKER: max_read_ahead_per_file_mb is 1846 MB [ 6603.031841] Lustre: DEBUG MARKER: Value capped at max_read_ahead_mb (1846 <= 1846) [ 6603.585731] Lustre: DEBUG MARKER: Test if max_read_ahead_whole_mb > max_read_ahead_per_file_mb capped [ 6603.606390] Lustre: 311010:0:(lproc_llite.c:536:max_read_ahead_whole_mb_store()) lustre: limit max_read_ahead_whole_mb=2586 to max_read_ahead_per_file_mb=1846 [ 6604.148537] Lustre: DEBUG MARKER: max_read_ahead_whole_mb is 1846 MB [ 6604.707500] Lustre: DEBUG MARKER: Value capped at max_read_ahead_per_file_mb (1846 <= 1846) [ 6605.293182] Lustre: DEBUG MARKER: Final max_cached_mb: 2769 MB [ 6605.859091] Lustre: DEBUG MARKER: max_cached_mb percentage functionality verified successfully [ 6608.172376] Lustre: DEBUG MARKER: == sanity test 855: readdir on open validation =========== 00:28:14 (1770442094) [ 6617.135473] Lustre: DEBUG MARKER: == sanity test 856a: Verify that read holes generated by truncate works as expected ========================================================== 00:28:23 (1770442103) [ 6652.367371] hrtimer: interrupt took 7983967 ns [ 6669.419072] Lustre: DEBUG MARKER: == sanity test 856b: Client-side hole caching for PFL file with DoM component ========================================================== 00:29:15 (1770442155) [ 6672.789993] Lustre: DEBUG MARKER: == sanity test 856c: Shrink truncate a file with hole extents ========================================================== 00:29:18 (1770442158) [ 6676.007168] Lustre: DEBUG MARKER: == sanity test 856d: Hole extents should be cleared during umount() ========================================================== 00:29:22 (1770442162) [ 6676.764231] LustreError: 315083:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff9531c0ad1800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 6676.768953] LustreError: 315083:0:(lov_obd.c:783:lov_cleanup()) Skipped 1 previous similar message [ 6676.778654] LustreError: 315083:0:(obd_class.h:479:obd_check_dev()) Device 6 not setup [ 6676.781304] LustreError: 315083:0:(obd_class.h:479:obd_check_dev()) Skipped 9 previous similar messages [ 6676.830701] Lustre: Unmounted lustre-client [ 6677.165452] Lustre: Mounted lustre-client [ 6680.307416] Lustre: DEBUG MARKER: == sanity test 856e: Setting minimum client-side hole extent size (in kiB) ========================================================== 00:29:26 (1770442166) [ 6683.773880] Lustre: DEBUG MARKER: == sanity test 856f: Read DLM extent lock could populate the hole extent cache ========================================================== 00:29:30 (1770442170) [ 6688.662293] Lustre: DEBUG MARKER: == sanity test 856g: Read RPC could pupulate the hole extent cache ========================================================== 00:29:34 (1770442174) [ 6694.814425] Lustre: DEBUG MARKER: == sanity test 856h: Testing hole_detect_policy setting interface ========================================================== 00:29:40 (1770442180) [ 6698.141732] Lustre: DEBUG MARKER: == sanity test 856i: Contigous hole extents can be merged ========================================================== 00:29:44 (1770442184) [ 6701.437623] Lustre: DEBUG MARKER: == sanity test 856j: Testing Hole extents generated by punch hole ========================================================== 00:29:47 (1770442187) [ 6713.830465] Lustre: DEBUG MARKER: == sanity test 856k: Testing Hole purge that generated by punch hole ========================================================== 00:30:00 (1770442200) [ 6723.490221] Lustre: DEBUG MARKER: == sanity test 856l: Testing hole detect to pupulate holes into client-side cache ========================================================== 00:30:09 (1770442209) [ 6737.176195] Lustre: DEBUG MARKER: == sanity test 856m: Hole detect for a file with more than one stripes ========================================================== 00:30:23 (1770442223) [ 6748.539565] Lustre: DEBUG MARKER: == sanity test 856n: Lock revocation should clear holes populated by hole detect ========================================================== 00:30:34 (1770442234) [ 6752.108496] Lustre: DEBUG MARKER: == sanity test 856o: Evaluate the auto hole detect for read ========================================================== 00:30:38 (1770442238) [ 6791.343113] Lustre: DEBUG MARKER: == sanity test 856p: Add hole read optimization for random read ========================================================== 00:31:17 (1770442277) [ 6831.380660] Lustre: DEBUG MARKER: == sanity test 856q: Server side hole ahead detection for sequential read ========================================================== 00:31:57 (1770442317) [ 6916.819495] Lustre: DEBUG MARKER: Hole page count with hole ahead is 1329 < 1408 [ 6953.008117] Lustre: DEBUG MARKER: == sanity test 856r: Client side hole cache LRU management per OSC object ========================================================== 00:33:59 (1770442439) [ 6978.883079] Lustre: DEBUG MARKER: == sanity test 860: verify multiop Xe (SEEK_END) command ========================================================== 00:34:25 (1770442465) [ 6981.474767] Lustre: DEBUG MARKER: == sanity test 900: umount should not race with any mgc requeue thread ========================================================== 00:34:27 (1770442467) [ 6984.676651] Lustre: lustre-MDT0000-mdc-ffff953190a21800: Connection to lustre-MDT0000 (at 192.168.203.121@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 6984.681445] Lustre: Skipped 2 previous similar messages [ 7000.033426] LustreError: MGC192.168.203.121@tcp: Connection to MGS (at 192.168.203.121@tcp) was lost; in progress operations using this service will fail [ 7000.039533] Lustre: Evicted from MGS (at 192.168.203.121@tcp) after server handle changed from 0x115a18b47d54fd62 to 0x115a18b47d56d3ce [ 7000.043434] Lustre: MGC192.168.203.121@tcp: Connection restored to 192.168.203.121@tcp (at 192.168.203.121@tcp) [ 7000.047143] Lustre: Skipped 3 previous similar messages [ 7000.049621] LustreError: 2412:0:(client.c:3418:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9531c04eca80 x1856436318772096/t38654716385(38654716385) o101->lustre-MDT0000-mdc-ffff953190a21800@192.168.203.121@tcp:12/10 lens 576/608 e 0 to 0 dl 1770442502 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'fio.0' uid:0 gid:0 projid:0 [ 7000.059555] LustreError: 2412:0:(client.c:3418:ptlrpc_replay_interpret()) Skipped 4 previous similar messages [ 7001.119095] LustreError: 315109:0:(mgc_request.c:1809:mgc_process_log()) cfs_fail_timeout id 903 sleeping for 20000ms [ 7001.122700] LustreError: 315109:0:(mgc_request.c:1809:mgc_process_log()) Skipped 9 previous similar messages [ 7004.460567] Lustre: DEBUG MARKER: oleg321-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 7005.009481] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7021.199086] LustreError: 315109:0:(mgc_request.c:1809:mgc_process_log()) cfs_fail_timeout id 903 awake [ 7021.200831] LustreError: 315109:0:(mgc_request.c:1809:mgc_process_log()) Skipped 9 previous similar messages [ 7041.285155] LustreError: 315109:0:(mgc_request.c:1809:mgc_process_log()) cfs_fail_timeout id 903 sleeping for 20000ms [ 7041.286178] LustreError: 330756:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff953190a21800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 7041.287746] LustreError: 315109:0:(mgc_request.c:1809:mgc_process_log()) Skipped 1 previous similar message [ 7041.290278] LustreError: 330756:0:(lov_obd.c:783:lov_cleanup()) Skipped 1 previous similar message [ 7041.296852] LustreError: 330756:0:(obd_class.h:479:obd_check_dev()) Device 6 not setup [ 7041.299078] LustreError: 330756:0:(obd_class.h:479:obd_check_dev()) Skipped 9 previous similar messages [ 7041.322170] Lustre: Unmounted lustre-client [ 7061.367082] LustreError: 315109:0:(mgc_request.c:1809:mgc_process_log()) cfs_fail_timeout id 903 awake [ 7061.369928] LustreError: 315109:0:(mgc_request.c:1809:mgc_process_log()) Skipped 1 previous similar message [ 7061.373145] LustreError: 315109:0:(mgc_request.c:614:do_requeue()) failed processing log: -108 [ 7061.378159] LustreError: 330756:0:(obd_class.h:479:obd_check_dev()) Device 0 not setup [ 7061.380436] LustreError: 330756:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 7101.132472] Key type lgssc unregistered [ 7101.244360] LNet: 331415:0:(lib-ptl.c:967:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 7101.247135] LNetError: 331415:0:(acceptor.c:264:lnet_acceptor_remove_socket()) Interface ens2 not found [ 7101.254853] LNet: Removed LNI 192.168.203.21@tcp [ 7101.557114] Key type .llcrypt unregistered [ 7101.558079] Key type ._llcrypt unregistered [ 7105.378804] Key type ._llcrypt registered [ 7105.379824] Key type .llcrypt registered [ 7105.724890] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [ 7105.729688] alg: No test for adler32 (adler32-zlib) [ 7106.707994] Lustre: Lustre: Build Version: 2.17.50_44_g630b48b [ 7107.002870] LNet: Added LNI 192.168.203.21@tcp [8/256/0/180] [ 7108.623146] Key type lgssc registered [ 7109.262576] Lustre: Echo OBD driver; http://www.lustre.org/ [ 7156.717916] Lustre: Mounted lustre-client [ 7159.317527] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 7168.844303] Lustre: DEBUG MARKER: == sanity test 901: don't leak a mgc lock on client umount ========================================================== 00:37:35 (1770442655) [ 7170.178235] LustreError: 334897:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff95318a989000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 7170.185200] LustreError: 334897:0:(obd_class.h:479:obd_check_dev()) Device 6 not setup [ 7170.207168] Lustre: Unmounted lustre-client [ 7170.345577] Lustre: Mounted lustre-client [ 7172.810243] Lustre: DEBUG MARKER: == sanity test 902: test short write doesn't hang lustre ========================================================== 00:37:39 (1770442659) [ 7172.927945] Lustre: *** cfs_fail_loc=2001415, val=0*** [ 7175.492516] Lustre: DEBUG MARKER: == sanity test 903: Test long page discard does not cause evictions ========================================================== 00:37:41 (1770442661) [ 7180.911954] LustreError: 334923:0:(osc_cache.c:4072:osc_page_gang_lookup()) cfs_fail_timeout id 417 sleeping for 20000ms [ 7200.983124] LustreError: 334923:0:(osc_cache.c:4072:osc_page_gang_lookup()) cfs_fail_timeout id 417 awake [ 7200.999965] LustreError: 334923:0:(osc_cache.c:4072:osc_page_gang_lookup()) cfs_fail_timeout id 417 sleeping for 20000ms [ 7221.071054] LustreError: 334923:0:(osc_cache.c:4072:osc_page_gang_lookup()) cfs_fail_timeout id 417 awake [ 7221.088378] LustreError: 334923:0:(osc_cache.c:4072:osc_page_gang_lookup()) cfs_fail_timeout id 417 sleeping for 20000ms [ 7241.159068] LustreError: 334923:0:(osc_cache.c:4072:osc_page_gang_lookup()) cfs_fail_timeout id 417 awake [ 7241.174306] LustreError: 334923:0:(osc_cache.c:4072:osc_page_gang_lookup()) cfs_fail_timeout id 417 sleeping for 20000ms [ 7261.247111] LustreError: 334923:0:(osc_cache.c:4072:osc_page_gang_lookup()) cfs_fail_timeout id 417 awake [ 7261.262300] LustreError: 334923:0:(osc_cache.c:4072:osc_page_gang_lookup()) cfs_fail_timeout id 417 sleeping for 20000ms [ 7281.335049] LustreError: 334923:0:(osc_cache.c:4072:osc_page_gang_lookup()) cfs_fail_timeout id 417 awake [ 7281.348340] LustreError: 334923:0:(osc_cache.c:4072:osc_page_gang_lookup()) cfs_fail_timeout id 417 sleeping for 20000ms [ 7301.423096] LustreError: 334923:0:(osc_cache.c:4072:osc_page_gang_lookup()) cfs_fail_timeout id 417 awake [ 7314.498697] Lustre: DEBUG MARKER: == sanity test 904: virtual project ID xattr ============= 00:40:00 (1770442800) [ 7318.965985] Lustre: DEBUG MARKER: == sanity test 905: bad or new opcode should not stuck client ========================================================== 00:40:05 (1770442805) [ 7319.495702] LustreError: lustre-OST0001-osc-ffff95319853d000: operation ost_ladvise to node 192.168.203.121@tcp failed: rc = -95 [ 7322.104259] Lustre: DEBUG MARKER: == sanity test 906: Simple test for io_uring I/O engine via fio ========================================================== 00:40:08 (1770442808) [ 7322.678710] Lustre: DEBUG MARKER: SKIP: sanity test_906 kernel does not support io_uring fully [ 7323.333740] Lustre: DEBUG MARKER: == sanity test 907: write rpc error during unlink ======== 00:40:09 (1770442809) [ 7324.963338] LustreError: lustre-OST0000-osc-ffff95319853d000: operation ost_write to node 192.168.203.121@tcp failed: rc = -3 [ 7324.967099] LustreError: Skipped 3 previous similar messages [ 7327.391187] Lustre: DEBUG MARKER: == sanity test 908a: llog created with valid ctime ======= 00:40:13 (1770442813) [ 7330.246152] Lustre: DEBUG MARKER: == sanity test 908b: changelog stores valid mtime ======== 00:40:16 (1770442816) [ 7345.911429] Lustre: DEBUG MARKER: == sanity test 909: Verify mdt index ===================== 00:40:32 (1770442832) [ 7348.577948] Lustre: DEBUG MARKER: == sanity test 910: Test the erasure_coding module ======= 00:40:34 (1770442834) [ 7348.656338] lustre_ec_test_3554: EC test passed [ 7351.143364] Lustre: DEBUG MARKER: == sanity test complete, duration 7226 sec =============== 00:40:37 (1770442837) [ 7351.796404] Lustre: DEBUG MARKER: === sanity: start cleanup 00:40:38 (1770442838) === [ 7457.277320] Lustre: DEBUG MARKER: === sanity: finish cleanup 00:42:23 (1770442943) === [ 7457.621071] LustreError: 346137:0:(lov_obd.c:783:lov_cleanup()) lustre-clilov-ffff95319853d000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 7457.623598] LustreError: 346137:0:(lov_obd.c:783:lov_cleanup()) Skipped 1 previous similar message [ 7457.629312] LustreError: 346137:0:(obd_class.h:479:obd_check_dev()) Device 6 not setup [ 7457.630891] LustreError: 346137:0:(obd_class.h:479:obd_check_dev()) Skipped 9 previous similar messages [ 7457.651102] Lustre: Unmounted lustre-client [ 7493.162926] Key type lgssc unregistered [ 7493.288596] LNet: 346821:0:(lib-ptl.c:967:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 7493.290919] LNetError: 346821:0:(acceptor.c:264:lnet_acceptor_remove_socket()) Interface ens2 not found [ 7493.299993] LNet: Removed LNI 192.168.203.21@tcp [ 7493.559131] Key type .llcrypt unregistered [ 7493.561091] Key type ._llcrypt unregistered