[ 0.000000] Linux version 4.18.0rh8.10-debug (green@maintenance) (gcc version 8.5.0 20210514 (Red Hat 8.5.0-26) (GCC)) #2 SMP Mon Jul 14 01:24:22 EDT 2025 [ 0.000000] Command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers' [ 0.000000] x86/fpu: xstate_offset[2]: 576, xstate_sizes[2]: 256 [ 0.000000] x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'standard' format. [ 0.000000] signal: max sigframe size: 1776 [ 0.000000] BIOS-provided physical RAM map: [ 0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable [ 0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000000100000-0x00000000bffd9fff] usable [ 0.000000] BIOS-e820: [mem 0x00000000bffda000-0x00000000bfffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000100000000-0x0000000146dfffff] usable [ 0.000000] NX (Execute Disable) protection: active [ 0.000000] SMBIOS 2.8 present. [ 0.000000] DMI: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.17.0-10.fc44 06/10/2025 [ 0.000000] Hypervisor detected: KVM [ 0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00 [ 0.000000] kvm-clock: using sched offset of 424888378 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2399.998 MHz processor [ 0.000000] last_pfn = 0x146e00 max_arch_pfn = 0x400000000 [ 0.000000] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT [ 0.000000] last_pfn = 0xbffda max_arch_pfn = 0x400000000 [ 0.000000] found SMP MP-table at [mem 0x000f54d0-0x000f54df] [ 0.000000] RAMDISK: [mem 0xbcc64000-0xbffcffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F52F0 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE2464 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE2300 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 0022C0 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE2374 000090 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE2404 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE243C 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe2300-0xbffe2373] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe22ff] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe2374-0xbffe2403] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe2404-0xbffe243b] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe243c-0xbffe2463] [ 0.000000] No NUMA configuration found [ 0.000000] Faking a node at [mem 0x0000000000000000-0x0000000146dfffff] [ 0.000000] NODE_DATA(0) allocated [mem 0x1465a3000-0x1465cdfff] [ 0.000000] Reserving 256MB of memory at 2752MB for crashkernel (System RAM: 4205MB) [ 0.000000] Zone ranges: [ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.000000] DMA32 [mem 0x0000000001000000-0x00000000ffffffff] [ 0.000000] Normal [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Device empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff] [ 0.000000] node 0: [mem 0x0000000000100000-0x00000000bffd9fff] [ 0.000000] node 0: [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Zeroed struct page in unavailable ranges: 4744 pages [ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x0000000146dfffff] [ 0.000000] ACPI: PM-Timer IO Port: 0x608 [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) [ 0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) [ 0.000000] Using ACPI (MADT) for SMP configuration information [ 0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000] TSC deadline timer available [ 0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs [ 0.000000] kvm-guest: KVM setup pv remote TLB flush [ 0.000000] kvm-guest: setup PV sched yield [ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff] [ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff] [ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff] [ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff] [ 0.000000] PM: Registered nosave memory: [mem 0xbffda000-0xbfffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xc0000000-0xfeffbfff] [ 0.000000] PM: Registered nosave memory: [mem 0xfeffc000-0xfeffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xff000000-0xfffbffff] [ 0.000000] PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff] [ 0.000000] [mem 0xc0000000-0xfeffbfff] available for PCI devices [ 0.000000] Booting paravirtualized kernel on KVM [ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns [ 0.000000] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1 [ 0.000000] percpu: Embedded 63 pages/cpu s221184 r8192 d28672 u524288 [ 0.000000] kvm-guest: PV spinlocks enabled [ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1059618 [ 0.000000] Policy zone: Normal [ 0.000000] Kernel command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] Specific versions of hardware are certified with Red Hat Enterprise Linux 8. Please see the list of hardware certified with Red Hat Enterprise Linux 8 at https://catalog.redhat.com. [ 0.000000] audit: disabled (until reboot) [ 0.000000] software IO TLB: area num 4. [ 0.000000] Memory: 2829700K/4306400K available (18435K kernel code, 11221K rwdata, 7248K rodata, 2908K init, 18040K bss, 524580K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] ftrace: allocating 41240 entries in 162 pages [ 0.000000] ftrace: allocated 162 pages with 3 groups [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] rcu: RCU event tracing is enabled. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ 0.000000] rcu: RCU callback double-/use-after-free debug enabled. [ 0.000000] Rude variant of Tasks RCU enabled. [ 0.000000] Tracing variant of Tasks RCU enabled. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 0.000000] NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16 [ 0.000000] random: get_random_bytes called from start_kernel+0x622/0x9a8 with crng_init=0 [ 0.001000] Console: colour *CGA 80x25 [ 0.001000] printk: console [ttyS1] enabled [ 0.001000] ACPI: Core revision 20220331 [ 0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.001012] APIC: Switch to symmetric I/O mode setup [ 0.003194] x2apic enabled [ 0.004009] Switched APIC routing to physical x2apic. [ 0.005018] kvm-guest: setup PV IPIs [ 0.008516] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.009000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.009023] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.010024] pid_max: default: 32768 minimum: 301 [ 0.012139] LSM: Security Framework initializing [ 0.013060] Yama: becoming mindful. [ 0.014050] SELinux: Initializing. [ 0.015069] *** VALIDATE selinux *** [ 0.023413] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.027828] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.029154] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.030114] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.031120] *** VALIDATE tmpfs *** [ 0.033472] *** VALIDATE proc *** [ 0.034265] *** VALIDATE cgroup *** [ 0.036007] *** VALIDATE cgroup2 *** [ 0.037265] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.038152] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.039009] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.040036] Spectre V2 : User space: Vulnerable [ 0.041010] Speculative Store Bypass: Vulnerable [ 0.044560] debug: unmapping init [mem 0xffffffff87259000-0xffffffff87260fff] [ 0.046198] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.047747] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.048026] ... version: 2 [ 0.049015] ... bit width: 48 [ 0.050014] ... generic registers: 4 [ 0.051014] ... value mask: 0000ffffffffffff [ 0.052017] ... max period: 00007fffffffffff [ 0.053020] ... fixed-purpose events: 3 [ 0.054014] ... event mask: 000000070000000f [ 0.055358] rcu: Hierarchical SRCU implementation. [ 0.057548] smp: Bringing up secondary CPUs ... [ 0.058604] x86: Booting SMP configuration: [ 0.059029] .... node #0, CPUs: #1 #2 #3 [ 0.062155] smp: Brought up 1 node, 4 CPUs [ 0.064012] smpboot: Max logical packages: 1 [ 0.065014] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.148080] node 0 deferred pages initialised in 82ms [ 0.152116] devtmpfs: initialized [ 0.153299] x86/mm: Memory block size: 128MB [ 0.156987] gcov: version magic: 0x41383552 [ 0.160019] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.161087] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.162275] pinctrl core: initialized pinctrl subsystem [ 0.163193] [ 0.163763] ************************************************************* [ 0.164016] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.165014] ** ** [ 0.166016] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.167014] ** ** [ 0.168015] ** This means that this kernel is built to expose internal ** [ 0.169012] ** IOMMU data structures, which may compromise security on ** [ 0.170014] ** your system. ** [ 0.171016] ** ** [ 0.172016] ** If you see this message and you are not debugging the ** [ 0.173016] ** kernel, report this immediately to your vendor! ** [ 0.174020] ** ** [ 0.175014] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.176016] ************************************************************* [ 0.177432] NET: Registered protocol family 16 [ 0.179542] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.182062] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.185064] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.189084] cpuidle: using governor menu [ 0.190650] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.193456] PCI: Using configuration type 1 for base access [ 0.195137] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.204114] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.207042] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.210190] cryptd: max_cpu_qlen set to 1000 [ 0.214404] ACPI: Added _OSI(Module Device) [ 0.216024] ACPI: Added _OSI(Processor Device) [ 0.217012] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.219017] ACPI: Added _OSI(Processor Aggregator Device) [ 0.224510] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.230424] ACPI: Interpreter enabled [ 0.232062] ACPI: PM: (supports S0 S3 S4 S5) [ 0.233014] ACPI: Using IOAPIC for interrupt routing [ 0.235110] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.238404] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.248589] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.251049] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.253019] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.257092] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.261442] acpiphp: Slot [2] registered [ 0.263154] acpiphp: Slot [5] registered [ 0.265209] acpiphp: Slot [6] registered [ 0.266119] acpiphp: Slot [3] registered [ 0.268137] acpiphp: Slot [4] registered [ 0.269112] acpiphp: Slot [7] registered [ 0.270109] acpiphp: Slot [8] registered [ 0.272075] acpiphp: Slot [9] registered [ 0.273082] acpiphp: Slot [10] registered [ 0.274084] acpiphp: Slot [11] registered [ 0.275122] acpiphp: Slot [12] registered [ 0.276164] acpiphp: Slot [13] registered [ 0.278138] acpiphp: Slot [14] registered [ 0.280115] acpiphp: Slot [15] registered [ 0.282144] acpiphp: Slot [16] registered [ 0.283182] acpiphp: Slot [17] registered [ 0.285120] acpiphp: Slot [18] registered [ 0.287211] acpiphp: Slot [19] registered [ 0.289117] acpiphp: Slot [20] registered [ 0.292138] acpiphp: Slot [21] registered [ 0.293113] acpiphp: Slot [22] registered [ 0.295120] acpiphp: Slot [23] registered [ 0.296105] acpiphp: Slot [24] registered [ 0.298127] acpiphp: Slot [25] registered [ 0.299119] acpiphp: Slot [26] registered [ 0.301108] acpiphp: Slot [27] registered [ 0.302104] acpiphp: Slot [28] registered [ 0.304120] acpiphp: Slot [29] registered [ 0.305112] acpiphp: Slot [30] registered [ 0.307127] acpiphp: Slot [31] registered [ 0.308125] PCI host bridge to bus 0000:00 [ 0.310035] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.312026] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.314016] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.316024] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.319023] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.321019] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.322201] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.325998] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.329261] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.336016] pci 0000:00:01.1: reg 0x20: [io 0xc120-0xc12f] [ 0.340074] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.343020] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.346020] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.348020] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.351126] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.353671] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.355039] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.358803] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.363013] pci 0000:00:02.0: reg 0x10: [io 0xc100-0xc11f] [ 0.373018] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.377019] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.382665] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.388018] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.391017] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.397985] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.403000] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.410020] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.415015] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.424016] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.434533] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.438554] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.440406] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.443424] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.445241] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.450211] iommu: Default domain type: Passthrough [ 0.452392] SCSI subsystem initialized [ 0.453113] ACPI: bus type USB registered [ 0.454077] usbcore: registered new interface driver usbfs [ 0.455118] usbcore: registered new interface driver hub [ 0.458081] usbcore: registered new device driver usb [ 0.459169] pps_core: LinuxPPS API ver. 1 registered [ 0.461012] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.465062] PTP clock support registered [ 0.467083] EDAC MC: Ver: 3.0.0 [ 0.469177] PCI: Using ACPI for IRQ routing [ 0.470796] NetLabel: Initializing [ 0.472011] NetLabel: domain hash size = 128 [ 0.474013] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.476078] NetLabel: unlabeled traffic allowed by default [ 0.478110] vgaarb: loaded [ 0.479290] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.481020] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.489036] clocksource: Switched to clocksource kvm-clock [ 0.581187] VFS: Disk quotas dquot_6.6.0 [ 0.582561] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.584942] *** VALIDATE ramfs *** [ 0.586269] *** VALIDATE hugetlbfs *** [ 0.588469] pnp: PnP ACPI init [ 0.590192] pnp: PnP ACPI: found 6 devices [ 0.607736] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.610995] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.613253] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.615490] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.617528] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.619403] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.622179] NET: Registered protocol family 2 [ 0.623931] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.627900] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.630537] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.634873] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.637349] TCP: Hash tables configured (established 65536 bind 65536) [ 0.639919] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.642871] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.644777] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.646549] NET: Registered protocol family 1 [ 0.648761] RPC: Registered named UNIX socket transport module. [ 0.650393] RPC: Registered udp transport module. [ 0.652152] RPC: Registered tcp transport module. [ 0.653835] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.656276] NET: Registered protocol family 44 [ 0.657469] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.659100] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.660811] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.662749] PCI: CLS 0 bytes, default 64 [ 0.664401] Unpacking initramfs... [ 2.032803] debug: unmapping init [mem 0xffff8a157cc64000-0xffff8a157ffcffff] [ 2.035568] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.037471] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.039907] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 2.466525] Initialise system trusted keyrings [ 2.467593] Key type blacklist registered [ 2.468838] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.475163] zbud: loaded [ 2.477202] *** VALIDATE nfs *** [ 2.478015] *** VALIDATE nfs4 *** [ 2.479056] pstore: using deflate compression [ 2.481738] Platform Keyring initialized [ 2.560666] NET: Registered protocol family 38 [ 2.561737] Key type asymmetric registered [ 2.562923] Asymmetric key parser 'x509' registered [ 2.564243] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 2.565985] io scheduler mq-deadline registered [ 2.567141] io scheduler kyber registered [ 2.568157] io scheduler bfq registered [ 2.569291] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 2.571060] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 2.572664] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 2.574458] ACPI: Power Button [PWRF] [ 2.578742] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 2.584811] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 2.596192] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 2.623599] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 2.651330] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 2.656419] Non-volatile memory driver v1.3 [ 2.657783] Linux agpgart interface v0.103 [ 2.686990] virtio_blk virtio1: [vda] 150056 512-byte logical blocks (76.8 MB/73.3 MiB) [ 2.689802] vda: detected capacity change from 0 to 76828672 [ 2.704885] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 2.708013] vdb: detected capacity change from 0 to 1073741824 [ 2.714894] libphy: Fixed MDIO Bus: probed [ 2.727293] usbcore: registered new interface driver usbserial_generic [ 2.729537] usbserial: USB Serial support registered for generic [ 2.732103] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 2.735953] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 2.737698] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 2.739882] mousedev: PS/2 mouse device common for all mice [ 2.742742] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 2.746119] rtc_cmos 00:05: RTC can wake from S4 [ 2.748606] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 2.753558] rtc_cmos 00:05: registered as rtc0 [ 2.756576] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 2.759027] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 2.765106] intel_pstate: CPU model not supported [ 2.768695] hid: raw HID events driver (C) Jiri Kosina [ 2.770974] usbcore: registered new interface driver usbhid [ 2.772599] usbhid: USB HID core driver [ 2.774090] drop_monitor: Initializing network drop monitor service [ 2.775596] Initializing XFRM netlink socket [ 2.778307] NET: Registered protocol family 10 [ 2.781684] Segment Routing with IPv6 [ 2.782991] NET: Registered protocol family 17 [ 2.785225] mpls_gso: MPLS GSO support [ 2.790325] RAS: Correctable Errors collector initialized. [ 2.793758] AVX version of gcm_enc/dec engaged. [ 2.795475] AES CTR mode by8 optimization enabled [ 2.870640] sched_clock: Marking stable (2870497532, 0)->(3769885221, -899387689) [ 2.874389] registered taskstats version 1 [ 2.877142] Loading compiled-in X.509 certificates [ 2.879226] zswap: loaded using pool lzo/zbud [ 2.905672] Key type big_key registered [ 2.919649] Key type encrypted registered [ 2.921525] ima: No TPM chip found, activating TPM-bypass! [ 2.924232] ima: Allocated hash algorithm: sha1 [ 2.926131] ima: No architecture policies found [ 2.927838] evm: Initialising EVM extended attributes: [ 2.929736] evm: security.selinux [ 2.931113] evm: security.ima [ 2.932177] evm: security.capability [ 2.933326] evm: HMAC attrs: 0x1 [ 2.935602] rtc_cmos 00:05: setting system clock to 2026-09-07 01:32:36 UTC (1788744756) [ 2.942216] debug: unmapping init [mem 0xffffffff88203000-0xffffffff883fffff] [ 2.945327] debug: unmapping init [mem 0xffffffff86f82000-0xffffffff87258fff] [ 2.954086] Write protecting the kernel read-only data: 28672k [ 2.957452] debug: unmapping init [mem 0xffffffff85603000-0xffffffff857fffff] [ 2.959806] debug: unmapping init [mem 0xffffffff85f14000-0xffffffff85ffffff] [ 2.987832] 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.996653] systemd[1]: Detected virtualization kvm. [ 2.998227] systemd[1]: Detected architecture x86-64. [ 3.000040] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.024808] systemd[1]: No hostname configured. [ 3.026106] systemd[1]: Set hostname to . [ 3.028050] random: systemd: uninitialized urandom read (16 bytes read) [ 3.030473] systemd[1]: Initializing machine ID from random generator. [ 3.144689] random: systemd: uninitialized urandom read (16 bytes read) [ 3.147517] systemd[1]: Listening on Journal Socket (/dev/log). [ OK ] Listening on Journal Socket (/dev/log). [ 3.151693] random: systemd: uninitialized urandom read (16 bytes read) [ 3.154056] systemd[1]: Started Dispatch Password Requests to Console Directory Watch. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ 3.159032] systemd[1]: Reached target Slices. [ OK ] Reached target Slices. [ OK ] Listening on udev Control Socket. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Listening on udev Kernel Socket. [ OK ] Reached target Swap. [ OK ] Reached target Paths. [ OK ] Listening on Journal Socket. Starting Setup Virtual Console... [ OK ] Started Memstrack Anylazing Service. Starting Journal Service... [ OK ] Reached target Initrd Root Device. Starting Apply Kernel Variables... [ OK ] Reached target Timers. [ OK ] Reached target Local File Systems. Starting Create Volatile Files and Directories... Starting Create list of required st…ce nodes for the current kernel... [ OK ] Reached target Sockets. [ OK ] Started Setup Virtual Console. [ OK ] Started Apply Kernel Variables. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Create list of required sta…vice nodes for the current kernel. Starting Create Static Device Nodes in /dev... Starting dracut cmdline hook... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started Journal Service. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 3.668592] device-mapper: uevent: version 1.0.3 [ 3.670514] 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. [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting dracut initqueue hook... [ 4.280859] virtio_net virtio0 ens2: renamed from eth0 [ 4.352629] scsi host0: ata_piix [ 4.369422] scsi host1: ata_piix [ 4.385504] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc120 irq 14 [ 4.388389] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc128 irq 15 [ 8.016942] dracut-initqueue[584]: RTNETLINK answers: File exists [ 9.438351] random: crng init done [ 9.440289] random: 7 urandom warning(s) missed due to ratelimiting Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Mounting /sysroot... [ 9.743846] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Timers. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped target Basic System. [ OK ] Stopped target Slices. [ OK ] Stopped target System Initialization. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. [ OK ] Stopped target Local File Systems. [ OK ] Stopped target Swap. [ OK ] Stopped target Local Encrypted Volumes. Stopping udev Kernel Device Manager... [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped target Sockets. [ OK ] Stopped target Paths. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Closed udev Control Socket. [ OK ] Closed udev Kernel Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 11.012228] printk: systemd: 26 output lines suppressed due to ratelimiting [ 11.269424] SELinux: Disabled at runtime. [ 11.333577] 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.341682] systemd[1]: Detected virtualization kvm. [ 11.343315] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 11.825321] systemd[1]: initrd-switch-root.service: Succeeded. [ 11.828510] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 11.834492] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 11.839964] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 11.843378] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 11.852566] systemd[1]: Starting Journal Service... Starting Journal Service... [ 11.861671] systemd[1]: Mounting Kernel Debug File System... Mounting Kernel Debug File System... [ OK ] Created slice system-getty.slice. Activating swap /dev/disk/by-label/SWAP... [ OK ] Listening on Process Core Dump Socket. [ 11.915669] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Listening on udev Control Socket. Starting Apply Kernel Variables... [ OK ] Created slice system-serial\x2dgetty.slice. [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Created slice system-sshd\x2dkeygen.slice. Starting Create list of required st…ce nodes for the current kernel... Mounting POSIX Message Queue File System... [ OK ] Reached target RPC Port Mapper. [ OK ] Reached target rpc_pipefs.target. [ OK ] Created slice User and Session Slice. [ OK ] Reached target Slices. Starting Remount Root and Kernel File Systems... [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd File Systems. [ OK ] Stopped target Initrd Root File System. [ OK ] Reached target Paths. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Listening on udev Kernel Socket. Starting udev Coldplug all Devices... Mounting Huge Pages File System... [ OK ] Started Journal Service. [ OK ] Mounted Kernel Debug File System. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Started Apply Kernel Variables. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Mounted POSIX Message Queue File System. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Mounted Huge Pages File System. Starting Configure read-only root support... Starting Create Static Device Nodes in /dev... [ OK ] Reached target Swap. Starting Flush Journal to Persistent Storage... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. Starting udev Kernel Device Manager... [ OK ] Reached target Local File Systems (Pre). Mounting /mnt... Mounting /home/green/git/lustre-release... [ OK ] Mounted /mnt. [ 12.369621] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Coldplug all Devices. [ OK ] Started udev Kernel Device Manager. [ 12.706189] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 12.742405] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 12.859893] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 12.882567] EDAC sbridge: Ver: 1.1.2 [ 14.044251] Key type dns_resolver registered [ 14.340249] NFS: Registering the id_resolver key type [ 14.342109] Key type id_resolver registered [ 14.343589] Key type id_legacy registered [ OK ] Started Configure read-only root support. [ OK ] Reached target Local File Systems. Starting Rebuild Dynamic Linker Cache... Starting Mark the need to relabel after reboot... Starting Load/Save Random Seed... Starting Create Volatile Files and Directories... [ 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 Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Started dnf makecache --timer. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Reached target Timers. [ OK ] Reached target Basic System. Starting Restore /run/initramfs on shutdown... [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Started irqbalance daemon. Starting Login Service... [ OK ] Started D-Bus System Message Bus. Starting Network Manager... [ OK ] Reached target sshd-keygen.target. [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Login Service. [ OK ] Started Network Manager. Starting Network Manager Wait Online... [ OK ] Reached target Network. Starting GSSAPI Proxy Daemon... Starting Dynamic System Tuning Daemon... Starting OpenSSH server daemon... [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... Starting Hostname Service... [ OK ] Started OpenSSH server daemon. [ OK ] Started Permit User Sessions. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Getty on tty1. [ OK ] Started Command Scheduler. [ OK ] Started Serial Getty on ttyS1. [ 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 Crash recovery kernel arming... Starting System Logging Service... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Starting Authorization Manager... [ OK ] Started Authorization Manager. [ OK ] Started Dynamic System Tuning Daemon. [ OK ] Reached target Multi-User System. [ OK ] Reached target Graphical Interface. Starting Update UTMP about System Runlevel Changes... [ OK ] Started Update UTMP about System Runlevel Changes. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg154-client login: [ 70.502770] libcfs: loading out-of-tree module taints kernel. [ 70.688904] Key type ._llcrypt registered [ 70.696271] Key type .llcrypt registered [ 71.307290] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [ 71.332748] alg: No test for adler32 (adler32-zlib) [ 72.958135] Lustre: Lustre: Build Version: 2.17.58_40_g869f601 [ 73.896811] LNet: Added LNI 192.168.201.54@tcp [8/256/0/180] [ 75.704124] Key type lgssc registered [ 77.870867] Lustre: Echo OBD driver; http://www.lustre.org/ [ 151.101854] hrtimer: interrupt took 4574595 ns [ 254.112468] Lustre: Mounted lustre-client - version 2.17.58_40_g869f601 [ 259.194491] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 273.852710] Lustre: DEBUG MARKER: oleg154-client.virtnet: executing check_logdir /tmp/testlogs/ [ 279.489942] Lustre: DEBUG MARKER: oleg154-client.virtnet: executing yml_node [ 280.032382] Lustre: lustre-OST0000-osc-ffff8a15c2bc4000: disconnect after 24s idle [ 283.921733] Lustre: DEBUG MARKER: Client: 2.17.58.40 [ 286.495394] Lustre: DEBUG MARKER: MDS: 2.17.58.40 [ 289.550422] Lustre: DEBUG MARKER: OSS: 2.17.58.40 [ 291.692704] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity ============----- Sun Sep 6 21:37:23 EDT 2026 [ 310.603431] Lustre: DEBUG MARKER: - need MDS1_VERSION <= 2.16.61-1-g89cf292a8c2 (34683432 <= 34618625) for LU-18938, skip 360 [ 312.295481] Lustre: DEBUG MARKER: - need MDS1_VERSION < v2_14_55-100-g8a84c7f9c7 (34683432 < 34486116) for LU-14927, skip 0f [ 313.772669] Lustre: DEBUG MARKER: - need OST1_VERSION < v2_17_50-410-gbd8e7b9555 (34683432 < 34681754) for LU-12550, skip 216 [ 315.468616] Lustre: DEBUG MARKER: excepting tests: 42a 42c 42b 118c 118d 407 119i 216 817 411a [ 316.949760] Lustre: DEBUG MARKER: skipping tests SLOW=no: 27m 60i 64b 68 71 135 136 230d 300o 842 51c 51e 834 [ 318.643900] Lustre: DEBUG MARKER: === sanity: start setup 21:37:50 (1788745070) === [ 324.523938] Lustre: DEBUG MARKER: oleg154-client.virtnet: executing check_config_client /mnt/lustre [ 345.675961] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 359.775764] Lustre: DEBUG MARKER: === sanity: finish setup 21:38:31 (1788745111) === [ 368.639678] Lustre: DEBUG MARKER: == sanity test 60a: llog_test run from kernel module and test llog_reader ========================================================== 21:38:40 (1788745120) [ 372.710558] Lustre: DEBUG MARKER: SKIP: sanity test_60a missing subtest run-llog.sh [ 375.524230] Lustre: DEBUG MARKER: == sanity test 60b: limit repeated messages from CERROR/CWARN ========================================================== 21:38:46 (1788745126) [ 382.431528] Lustre: lustre-OST0001-osc-ffff8a15c2bc4000: disconnect after 22s idle [ 382.438465] Lustre: Skipped 1 previous similar message [ 386.488994] Lustre: DEBUG MARKER: == sanity test 60c: unlink file when mds full ============ 21:38:57 (1788745137) [ 581.514284] Lustre: DEBUG MARKER: == sanity test 60d: test printk console message masking == 21:42:13 (1788745333) [ 581.643892] Lustre: DEBUG MARKER: test message ID 22217 8228 [ 588.265673] Lustre: DEBUG MARKER: == sanity test 60e: no space while new llog is being created ========================================================== 21:42:20 (1788745340) [ 596.054624] Lustre: DEBUG MARKER: == sanity test 60f: change debug_path works ============== 21:42:28 (1788745348) [ 596.991311] LustreError: dumping log to /tmp/f60f.sanity.1788745350.14757 [ 606.196487] Lustre: DEBUG MARKER: == sanity test 60g: transaction abort won't cause MDT hung ========================================================== 21:42:37 (1788745357) [ 708.127887] Lustre: dir [0x240000402:0x22:0x0] stripe 1 readdir failed: -2, directory is partially accessed! [ 708.956626] Lustre: dir [0x240000402:0x22:0x0] stripe 1 readdir failed: -2, directory is partially accessed! [ 717.403914] Lustre: DEBUG MARKER: == sanity test 60h: striped directory with missing stripes can be accessed ========================================================== 21:44:29 (1788745469) [ 718.928498] Lustre: dir [0x240000402:0x170:0x0] stripe 2 readdir failed: -2, directory is partially accessed! [ 721.725563] Lustre: dir [0x240000402:0x177:0x0] stripe 2 readdir failed: -2, directory is partially accessed! [ 721.731184] Lustre: Skipped 3 previous similar messages [ 730.065460] Lustre: DEBUG MARKER: SKIP: sanity test_60i skipping SLOW test 60i [ 732.069904] Lustre: DEBUG MARKER: == sanity test 60j: llog_reader reports corruptions ====== 21:44:44 (1788745484) [ 748.465472] Lustre: DEBUG MARKER: SKIP: sanity test_60j path oi.1/0x1:0xc:0x0 is not in 'O/1/d/' format [ 756.827358] Lustre: DEBUG MARKER: == sanity test 61a: mmap() writes don't make sync hang ========================================================================== 21:45:08 (1788745508) [ 765.094876] Lustre: DEBUG MARKER: == sanity test 61b: mmap() of unstriped file is successful ========================================================== 21:45:17 (1788745517) [ 773.338888] Lustre: DEBUG MARKER: == sanity test 63a: Verify oig_wait interruption does not crash ================================================================= 21:45:25 (1788745525) [ 843.333201] Lustre: DEBUG MARKER: == sanity test 63b: async write errors should be returned to fsync ============================================================= 21:46:35 (1788745595) [ 844.778866] Lustre: *** cfs_fail_loc=406, val=0*** [ 844.785599] LustreError: 21469:0:(osc_request.c:2918:osc_build_rpc()) lustre-OST0001-osc-ffff8a15c2bc4000: prep_req failed: rc = -12 [ 844.806757] LustreError: 21469:0:(osc_cache.c:2419:osc_check_rpcs()) Write request failed with -12 [ 858.871682] Lustre: DEBUG MARKER: == sanity test 63c: test sync_on_close=1 ================= 21:46:50 (1788745610) [ 865.756988] LNet: 22292:0:(debug.c:375:cfs_str2mask()) unknown mask 'entry'. [ 865.756988] mask usage: [+|-] ... [ 876.978478] Lustre: DEBUG MARKER: == sanity test 64a: verify filter grant calculations (in kernel) =============================================================== 21:47:09 (1788745629) [ 886.136590] Lustre: DEBUG MARKER: SKIP: sanity test_64b skipping SLOW test 64b [ 888.460575] Lustre: DEBUG MARKER: == sanity test 64c: verify grant shrink ================== 21:47:20 (1788745640) [ 900.214461] Lustre: DEBUG MARKER: == sanity test 64d: check grant limit exceed ============= 21:47:31 (1788745651) [ 964.324711] Lustre: DEBUG MARKER: == sanity test 64e: check grant consumption (no grant allocation) ========================================================== 21:48:36 (1788745716) [ 968.788486] Lustre: Unmounted lustre-client [ 969.247491] Lustre: Mounted lustre-client - version 2.17.58_40_g869f601 [ 974.657391] Lustre: Unmounted lustre-client [ 975.336676] Lustre: Mounted lustre-client - version 2.17.58_40_g869f601 [ 988.140487] Lustre: DEBUG MARKER: == sanity test 64f: check grant consumption (with grant allocation) ========================================================== 21:48:59 (1788745739) [ 991.118392] Lustre: Unmounted lustre-client [ 991.499757] Lustre: Mounted lustre-client - version 2.17.58_40_g869f601 [ 995.631208] Lustre: Unmounted lustre-client [ 996.176915] Lustre: Mounted lustre-client - version 2.17.58_40_g869f601 [ 1004.526651] Lustre: DEBUG MARKER: == sanity test 64g: grant shrink on MDT ================== 21:49:16 (1788745756) [ 1033.001386] Lustre: DEBUG MARKER: == sanity test 64h: grant shrink on read ================= 21:49:45 (1788745785) [ 1056.787363] Lustre: DEBUG MARKER: == sanity test 64i: shrink on reconnect ================== 21:50:08 (1788745808) [ 1071.031967] Lustre: lustre-OST0000-osc-ffff8a15c956a800: Connection to lustre-OST0000 (at 192.168.201.154@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1083.359288] Lustre: 2403:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788745820/real 1788745820] req@ffff8a15c3136a00 x1875634902077312/t0(0) o17->lustre-OST0000-osc-ffff8a15c956a800@192.168.201.154@tcp:28/4 lens 456/432 e 0 to 1 dl 1788745836 ref 1 fl Rpc:XQr/200/ffffffff rc 0/-1 job:'lctl.0' uid:0 gid:0 projid:4294967295 [ 1112.652903] Lustre: DEBUG MARKER: oleg154-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 1115.138898] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 1128.312103] Lustre: DEBUG MARKER: == sanity test 64j: check grants on re-done rpc ========== 21:51:20 (1788745880) [ 1129.606324] LustreError: 2402:0:(osc_request.c:2451:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff8a15c3137100 x1875634902090240/t0(0) o4->lustre-OST0000-osc-ffff8a15c956a800@192.168.201.154@tcp:6/4 lens 4584/448 e 0 to 0 dl 1788745899 ref 2 fl Interpret:RMQU/600/0 rc -5/-5 job:'multiop.0' uid:0 gid:0 projid:0 [ 1139.608166] Lustre: DEBUG MARKER: == sanity test 65a: directory with no stripe info ======== 21:51:31 (1788745891) [ 1146.845122] Lustre: DEBUG MARKER: == sanity test 65b: directory setstripe -S stripe_size*2 -i 0 -c 1 ========================================================== 21:51:38 (1788745898) [ 1154.554710] Lustre: DEBUG MARKER: == sanity test 65c: directory setstripe -S stripe_size*4 -i 1 -c 1 ========================================================== 21:51:46 (1788745906) [ 1161.522622] Lustre: DEBUG MARKER: == sanity test 65d: directory setstripe -S stripe_size -c stripe_count ========================================================== 21:51:53 (1788745913) [ 1168.432165] Lustre: DEBUG MARKER: == sanity test 65e: directory setstripe defaults ========= 21:52:00 (1788745920) [ 1175.091946] Lustre: DEBUG MARKER: == sanity test 65f: dir setstripe permission (should return error) ============================================================= 21:52:07 (1788745927) [ 1182.093641] Lustre: DEBUG MARKER: == sanity test 65g: directory setstripe -d =============== 21:52:14 (1788745934) [ 1189.492220] Lustre: DEBUG MARKER: == sanity test 65h: directory stripe info inherit ============================================================================== 21:52:21 (1788745941) [ 1197.054141] Lustre: DEBUG MARKER: == sanity test 65i: various tests to set root directory striping ========================================================== 21:52:29 (1788745949) [ 1204.672743] Lustre: DEBUG MARKER: == sanity test 65j: set default striping on root directory (bug 6367)=========================================================== 21:52:36 (1788745956) [ 1213.447462] Lustre: DEBUG MARKER: == sanity test 65k: validate manual striping works properly with deactivated OSCs ========================================================== 21:52:45 (1788745965) [ 1415.715029] Lustre: DEBUG MARKER: == sanity test 65l: lfs find on -1 stripe dir ================================================================================== 21:56:07 (1788746167) [ 1424.986743] Lustre: DEBUG MARKER: == sanity test 65m: normal user can't set filesystem default stripe ========================================================== 21:56:16 (1788746176) [ 1433.383733] Lustre: DEBUG MARKER: == sanity test 65n: don't inherit default layout from root for new subdirectories ========================================================== 21:56:24 (1788746184) [ 1470.206783] Lustre: DEBUG MARKER: == sanity test 65o: pool inheritance for mdt component === 21:57:01 (1788746221) [ 1502.868354] Lustre: DEBUG MARKER: == sanity test 65p: setstripe with yaml file and huge number ========================================================== 21:57:34 (1788746254) [ 1513.454789] Lustre: DEBUG MARKER: == sanity test 65q: setstripe with >=8E offset should fail ========================================================== 21:57:44 (1788746264) [ 1524.317508] Lustre: DEBUG MARKER: == sanity test 65r: prevent all-zero offsets ============= 21:57:55 (1788746275) [ 1535.667952] Lustre: DEBUG MARKER: == sanity test 66: update inode blocks count on client ========================================================================= 21:58:06 (1788746286) [ 1556.734703] Lustre: DEBUG MARKER: == sanity test 69: verify oa2dentry return -ENOENT doesn't LBUG ================================================================ 21:58:28 (1788746308) [ 1579.313533] Lustre: DEBUG MARKER: == sanity test 70a: verify health_check, health_write don't explode (on OST) ========================================================== 21:58:49 (1788746329) [ 1598.755926] Lustre: DEBUG MARKER: SKIP: sanity test_71 skipping SLOW test 71 [ 1600.676383] Lustre: DEBUG MARKER: == sanity test 72a: Test that remove suid works properly (bug5695) ============================================================== 21:59:12 (1788746352) [ 1611.098880] Lustre: DEBUG MARKER: == sanity test 72b: Test that we keep mode setting if without file data changed (bug 24226) ========================================================== 21:59:22 (1788746362) [ 1620.594456] Lustre: DEBUG MARKER: == sanity test 73: multiple MDC requests (should not deadlock) ========================================================== 21:59:32 (1788746372) [ 1660.519312] Lustre: DEBUG MARKER: == sanity test 74a: ldlm_enqueue freed-export error path, ls (shouldn't LBUG) ========================================================== 22:00:12 (1788746412) [ 1669.025715] Lustre: DEBUG MARKER: == sanity test 74b: ldlm_enqueue freed-export error path, touch (shouldn't LBUG) ========================================================== 22:00:20 (1788746420) [ 1679.281127] Lustre: DEBUG MARKER: == sanity test 74c: ldlm_lock_create error path, (shouldn't LBUG) ========================================================== 22:00:30 (1788746430) [ 1679.395734] Lustre: *** cfs_fail_loc=319, val=0*** [ 1688.093241] Lustre: DEBUG MARKER: == sanity test 76a: confirm clients recycle inodes properly ============================================================== 22:00:39 (1788746439) [ 1788.480248] Lustre: DEBUG MARKER: == sanity test 76b: confirm clients recycle directory inodes properly ============================================================== 22:02:20 (1788746540) [ 1849.921983] Lustre: DEBUG MARKER: == sanity test 77a: normal checksum read/write operation ========================================================== 22:03:21 (1788746601) [ 1859.070552] Lustre: DEBUG MARKER: == sanity test 77b: checksum error on client write, read ========================================================== 22:03:30 (1788746610) [ 1860.107045] Lustre: *** cfs_fail_loc=409, val=0*** [ 1860.300768] LustreError: lustre-OST0001-osc-ffff8a15c956a800: BAD WRITE CHECKSUM: changed on the client after we checksummed it - likely false positive due to mmap IO (bug 11742): from 192.168.201.154@tcp inode [0x200000407:0xc1e:0x0] object 0x2c0000401:3829 extent [0-4194303], original client csum abe19cca (type 4), server csum abe19cc9 (type 4), client csum now abe19cc9 [ 1860.322986] LustreError: 2400:0:(osc_request.c:2451:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff8a15c8254a80 x1875634906886400/t4294972672(4294972672) o4->lustre-OST0001-osc-ffff8a15c956a800@192.168.201.154@tcp:6/4 lens 488/448 e 0 to 0 dl 1788746629 ref 3 fl Interpret:RQU/604/0 rc 0/0 job:'dd.0' uid:0 gid:0 projid:0 [ 1862.614552] Lustre: DEBUG MARKER: set checksum type to crc32, rc = 0 [ 1862.992650] Lustre: *** cfs_fail_loc=408, val=0*** [ 1863.035172] LustreError: lustre-OST0001-osc-ffff8a15c956a800: BAD READ CHECKSUM: from 192.168.201.154@tcp inode [0x200000407:0xc1e:0x0] object 0x2c0000401:3829 extent [0-4194303], client 763a1075/763a1075, server 10f23c0d, cksum_type 1 [ 1863.052765] LustreError: 2403:0:(osc_request.c:2451:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff8a15c624aa00 x1875634906887808/t0(0) o3->lustre-OST0001-osc-ffff8a15c956a800@192.168.201.154@tcp:6/4 lens 488/440 e 0 to 0 dl 1788746632 ref 2 fl Interpret:RMQU/600/0 rc 4194304/4194304 job:'cmp.0' uid:0 gid:0 projid:0 [ 1867.464767] Lustre: DEBUG MARKER: set checksum type to adler, rc = 0 [ 1867.915770] Lustre: *** cfs_fail_loc=408, val=0*** [ 1867.969347] LustreError: lustre-OST0001-osc-ffff8a15c956a800: BAD READ CHECKSUM: from 192.168.201.154@tcp inode [0x200000407:0xc1e:0x0] object 0x2c0000401:3829 extent [0-4194303], client c961db66/c961db66, server f4b7dbb6, cksum_type 2 [ 1867.988139] LustreError: 2402:0:(osc_request.c:2451:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff8a15c6248700 x1875634906889600/t0(0) o3->lustre-OST0001-osc-ffff8a15c956a800@192.168.201.154@tcp:6/4 lens 488/440 e 0 to 0 dl 1788746637 ref 2 fl Interpret:RMQU/600/0 rc 4194304/4194304 job:'cmp.0' uid:0 gid:0 projid:0 [ 1872.605216] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 1873.012622] Lustre: *** cfs_fail_loc=408, val=0*** [ 1873.029755] LustreError: lustre-OST0001-osc-ffff8a15c956a800: BAD READ CHECKSUM: from 192.168.201.154@tcp inode [0x200000407:0xc1e:0x0] object 0x2c0000401:3829 extent [0-4194303], client dab1552f/dab1552f, server abe19cc9, cksum_type 4 [ 1873.039525] LustreError: 2403:0:(osc_request.c:2451:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff8a15c6248700 x1875634906891392/t0(0) o3->lustre-OST0001-osc-ffff8a15c956a800@192.168.201.154@tcp:6/4 lens 488/440 e 0 to 0 dl 1788746642 ref 2 fl Interpret:RMQU/600/0 rc 4194304/4194304 job:'cmp.0' uid:0 gid:0 projid:0 [ 1877.965131] Lustre: DEBUG MARKER: set checksum type to t10ip512, rc = 0 [ 1878.514352] Lustre: *** cfs_fail_loc=408, val=0*** [ 1878.525787] LustreError: lustre-OST0001-osc-ffff8a15c956a800: BAD READ CHECKSUM: from 192.168.201.154@tcp inode [0x200000407:0xc1e:0x0] object 0x2c0000401:3829 extent [0-4194303], client 7f58d3c9/7f58d3c9, server 7e06d379, cksum_type 10 [ 1878.547303] LustreError: 2401:0:(osc_request.c:2451:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff8a15ef882d80 x1875634906893056/t0(0) o3->lustre-OST0001-osc-ffff8a15c956a800@192.168.201.154@tcp:6/4 lens 488/440 e 0 to 0 dl 1788746647 ref 2 fl Interpret:RMQU/600/0 rc 4194304/4194304 job:'cmp.0' uid:0 gid:0 projid:0 [ 1882.464434] Lustre: DEBUG MARKER: set checksum type to t10ip4K, rc = 0 [ 1883.043641] LustreError: lustre-OST0001-osc-ffff8a15c956a800: BAD READ CHECKSUM: from 192.168.201.154@tcp inode [0x200000407:0xc1e:0x0] object 0x2c0000401:3829 extent [0-4194303], client 4e010e14/4e010e14, server cdae0dc4, cksum_type 20 [ 1887.139365] Lustre: DEBUG MARKER: set checksum type to t10crc512, rc = 0 [ 1887.990465] Lustre: *** cfs_fail_loc=408, val=0*** [ 1887.992273] Lustre: Skipped 1 previous similar message [ 1888.030601] LustreError: 2402:0:(osc_request.c:2451:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff8a15c624a680 x1875634906895488/t0(0) o3->lustre-OST0001-osc-ffff8a15c956a800@192.168.201.154@tcp:6/4 lens 488/440 e 0 to 0 dl 1788746657 ref 2 fl Interpret:RMQU/600/0 rc 4194304/4194304 job:'cmp.0' uid:0 gid:0 projid:0 [ 1888.068161] LustreError: 2402:0:(osc_request.c:2451:osc_brw_redo_request()) Skipped 1 previous similar message [ 1892.045899] Lustre: DEBUG MARKER: set checksum type to t10crc4K, rc = 0 [ 1892.991759] LustreError: lustre-OST0001-osc-ffff8a15c956a800: BAD READ CHECKSUM: from 192.168.201.154@tcp inode [0x200000407:0xc1e:0x0] object 0x2c0000401:3829 extent [0-4194303], client 7fc015af/7fc015af, server 47651508, cksum_type 80 [ 1893.003469] LustreError: Skipped 1 previous similar message [ 1896.396859] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 1904.026899] Lustre: DEBUG MARKER: == sanity test 77c: checksum error on client read with debug ========================================================== 22:04:16 (1788746656) [ 1909.331313] Lustre: *** cfs_fail_loc=408, val=0*** [ 1909.334863] Lustre: Skipped 1 previous similar message [ 1909.343900] Lustre: 2402:0:(osc_request.c:2035:dump_all_bulk_pages()) /tmp/lustre-log-checksum_dump-osc-[0x200000407:0xc1f:0x0]:[0-1048575]-87853250-5eed7a73: dumping checksum data [ 1909.356626] LustreError: dumping log to /tmp/lustre-log.1788746662.2402 [ 1912.888788] LustreError: lustre-OST0000-osc-ffff8a15c956a800: BAD READ CHECKSUM: from 192.168.201.154@tcp inode [0x200000407:0xc1f:0x0] object 0x280000401:3840 extent [0-1048575], client 87853250/87853250, server 5eed7a73, cksum_type 4 [ 1912.915718] LustreError: 2402:0:(osc_request.c:2451:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff8a15c6248000 x1875634906903168/t0(0) o3->lustre-OST0000-osc-ffff8a15c956a800@192.168.201.154@tcp:6/4 lens 488/440 e 0 to 0 dl 1788746678 ref 2 fl Interpret:RMQU/600/0 rc 1048576/1048576 job:'dd.0' uid:0 gid:0 projid:0 [ 1912.940978] LustreError: 2402:0:(osc_request.c:2451:osc_brw_redo_request()) Skipped 1 previous similar message [ 1949.429154] Lustre: DEBUG MARKER: == sanity test 77d: checksum error on OST direct write, read ========================================================== 22:05:01 (1788746701) [ 1950.178425] Lustre: *** cfs_fail_loc=409, val=0*** [ 1950.372923] LustreError: lustre-OST0000-osc-ffff8a15c956a800: BAD WRITE CHECKSUM: changed on the client after we checksummed it - likely false positive due to mmap IO (bug 11742): from 192.168.201.154@tcp inode [0x200000407:0xc21:0x0] object 0x280000401:3841 extent [0-4194303], original client csum de2bf73f (type 4), server csum de2bf73e (type 4), client csum now de2bf73e [ 1950.380712] LustreError: 2402:0:(osc_request.c:2451:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff8a15c624bb80 x1875634906909056/t8589937217(8589937217) o4->lustre-OST0000-osc-ffff8a15c956a800@192.168.201.154@tcp:6/4 lens 488/448 e 0 to 0 dl 1788746719 ref 2 fl Interpret:RMQU/600/0 rc 0/0 job:'directio.0' uid:0 gid:0 projid:0 [ 1952.022439] LustreError: lustre-OST0000-osc-ffff8a15c956a800: BAD READ CHECKSUM: from 192.168.201.154@tcp inode [0x200000407:0xc21:0x0] object 0x280000401:3841 extent [0-4194303], client f5a99216/f5a99216, server de2bf73e, cksum_type 4 [ 1961.201989] Lustre: DEBUG MARKER: == sanity test 77f: repeat checksum error on write (expect error) ========================================================== 22:05:12 (1788746712) [ 1963.236684] Lustre: DEBUG MARKER: set checksum type to crc32, rc = 0 [ 1964.121623] LustreError: lustre-OST0001-osc-ffff8a15c956a800: BAD WRITE CHECKSUM: changed in transit before arrival at OST: from 192.168.201.154@tcp inode [0x200000407:0xc22:0x0] object 0x2c0000401:3830 extent [0-4194303], original client csum 8b19b060 (type 1), server csum 8b19b05f (type 1), client csum now 8b19b060 [ 1964.146419] LustreError: Skipped 1 previous similar message [ 1965.339169] LustreError: 2403:0:(osc_request.c:2608:brw_interpret()) lustre-OST0001-osc-ffff8a15c956a800: too many resent retries for object: 11811161089:3830: rc = -11 [ 1967.428366] Lustre: DEBUG MARKER: set checksum type to adler, rc = 0 [ 1967.928799] LustreError: lustre-OST0000-osc-ffff8a15c956a800: BAD WRITE CHECKSUM: changed in transit before arrival at OST: from 192.168.201.154@tcp inode [0x200000407:0xc23:0x0] object 0x280000401:3842 extent [0-4194303], original client csum 7d33b9a0 (type 2), server csum 7d33b99f (type 2), client csum now 7d33b9a0 [ 1967.949659] LustreError: Skipped 2 previous similar messages [ 1969.253591] LustreError: 2400:0:(osc_request.c:2608:brw_interpret()) lustre-OST0000-osc-ffff8a15c956a800: too many resent retries for object: 10737419265:3842: rc = -11 [ 1969.270327] LustreError: 2400:0:(osc_request.c:2608:brw_interpret()) Skipped 1 previous similar message [ 1970.978639] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 1972.912972] LustreError: lustre-OST0001-osc-ffff8a15c956a800: BAD WRITE CHECKSUM: changed in transit before arrival at OST: from 192.168.201.154@tcp inode [0x200000407:0xc24:0x0] object 0x2c0000401:3831 extent [0-4194303], original client csum de2bf73f (type 4), server csum de2bf73e (type 4), client csum now de2bf73f [ 1972.930775] LustreError: Skipped 5 previous similar messages [ 1972.934789] LustreError: 2401:0:(osc_request.c:2608:brw_interpret()) lustre-OST0001-osc-ffff8a15c956a800: too many resent retries for object: 11811161089:3831: rc = -11 [ 1972.958918] LustreError: 2401:0:(osc_request.c:2608:brw_interpret()) Skipped 2 previous similar messages [ 1974.455597] Lustre: DEBUG MARKER: set checksum type to t10ip512, rc = 0 [ 1976.470951] LustreError: 2400:0:(osc_request.c:2608:brw_interpret()) lustre-OST0000-osc-ffff8a15c956a800: too many resent retries for object: 10737419265:3843: rc = -11 [ 1978.108043] Lustre: DEBUG MARKER: set checksum type to t10ip4K, rc = 0 [ 1981.622090] Lustre: DEBUG MARKER: set checksum type to t10crc512, rc = 0 [ 1982.119770] LustreError: lustre-OST0000-osc-ffff8a15c956a800: BAD WRITE CHECKSUM: changed in transit before arrival at OST: from 192.168.201.154@tcp inode [0x200000407:0xc27:0x0] object 0x280000401:3844 extent [4194304-8388607], original client csum a30822f0 (type 40), server csum a30822ef (type 40), client csum now a30822f0 [ 1982.138714] LustreError: Skipped 9 previous similar messages [ 1982.571426] LustreError: 2400:0:(osc_request.c:2608:brw_interpret()) lustre-OST0000-osc-ffff8a15c956a800: too many resent retries for object: 10737419265:3844: rc = -11 [ 1982.581893] LustreError: 2400:0:(osc_request.c:2608:brw_interpret()) Skipped 3 previous similar messages [ 1984.277617] Lustre: DEBUG MARKER: set checksum type to t10crc4K, rc = 0 [ 1993.619318] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 1995.572935] Lustre: DEBUG MARKER: == sanity test 77g: checksum error on OST write, read ==== 22:05:47 (1788746747) [ 2012.332858] Lustre: DEBUG MARKER: == sanity test 77k: enable/disable checksum correctly ==== 22:06:04 (1788746764) [ 2018.000823] Lustre: Unmounted lustre-client [ 2018.417997] Lustre: Mounted lustre-client - version 2.17.58_40_g869f601 [ 2023.974301] Lustre: Unmounted lustre-client [ 2024.457584] Lustre: Mounted lustre-client - version 2.17.58_40_g869f601 [ 2028.745683] Lustre: Unmounted lustre-client [ 2029.361372] Lustre: Mounted lustre-client - version 2.17.58_40_g869f601 [ 2031.360364] Lustre: Unmounted lustre-client [ 2031.810684] Lustre: Mounted lustre-client - version 2.17.58_40_g869f601 [ 2044.215274] Lustre: DEBUG MARKER: == sanity test 77l: preferred checksum type is remembered after reconnected ========================================================== 22:06:35 (1788746795) [ 2046.006629] Lustre: DEBUG MARKER: set checksum type to invalid, rc = 22 [ 2047.606891] Lustre: DEBUG MARKER: set checksum type to crc32, rc = 0 [ 2053.837526] Lustre: DEBUG MARKER: oleg154-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff8a15d0839000.ost_server_uuid 50 [ 2055.274274] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff8a15d0839000.ost_server_uuid in IDLE state after 0 sec [ 2061.165738] Lustre: DEBUG MARKER: oleg154-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff8a15d0839000.ost_server_uuid 50 [ 2062.932967] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff8a15d0839000.ost_server_uuid in FULL state after 0 sec [ 2064.759571] Lustre: DEBUG MARKER: set checksum type to adler, rc = 0 [ 2071.026422] Lustre: DEBUG MARKER: oleg154-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff8a15d0839000.ost_server_uuid 50 [ 2077.140425] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff8a15d0839000.ost_server_uuid in IDLE state after 4 sec [ 2083.688535] Lustre: DEBUG MARKER: oleg154-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff8a15d0839000.ost_server_uuid 50 [ 2085.723194] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff8a15d0839000.ost_server_uuid in FULL state after 0 sec [ 2087.979901] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 2095.177414] Lustre: DEBUG MARKER: oleg154-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff8a15d0839000.ost_server_uuid 50 [ 2102.234333] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff8a15d0839000.ost_server_uuid in IDLE state after 5 sec [ 2108.700814] Lustre: DEBUG MARKER: oleg154-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff8a15d0839000.ost_server_uuid 50 [ 2110.392723] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff8a15d0839000.ost_server_uuid in FULL state after 0 sec [ 2112.596770] Lustre: DEBUG MARKER: set checksum type to t10ip512, rc = 0 [ 2118.726640] Lustre: DEBUG MARKER: oleg154-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff8a15d0839000.ost_server_uuid 50 [ 2128.053720] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff8a15d0839000.ost_server_uuid in IDLE state after 7 sec [ 2133.321648] Lustre: DEBUG MARKER: oleg154-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff8a15d0839000.ost_server_uuid 50 [ 2134.682418] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff8a15d0839000.ost_server_uuid in FULL state after 0 sec [ 2136.493836] Lustre: DEBUG MARKER: set checksum type to t10ip4K, rc = 0 [ 2141.774373] Lustre: DEBUG MARKER: oleg154-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff8a15d0839000.ost_server_uuid 50 [ 2148.741758] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff8a15d0839000.ost_server_uuid in IDLE state after 5 sec [ 2153.432221] Lustre: DEBUG MARKER: oleg154-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff8a15d0839000.ost_server_uuid 50 [ 2154.708305] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff8a15d0839000.ost_server_uuid in FULL state after 0 sec [ 2156.099710] Lustre: DEBUG MARKER: set checksum type to t10crc512, rc = 0 [ 2161.550691] Lustre: DEBUG MARKER: oleg154-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff8a15d0839000.ost_server_uuid 50 [ 2169.563957] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff8a15d0839000.ost_server_uuid in IDLE state after 6 sec [ 2175.393552] Lustre: DEBUG MARKER: oleg154-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff8a15d0839000.ost_server_uuid 50 [ 2176.779277] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff8a15d0839000.ost_server_uuid in FULL state after 0 sec [ 2178.735895] Lustre: DEBUG MARKER: set checksum type to t10crc4K, rc = 0 [ 2184.324771] Lustre: DEBUG MARKER: oleg154-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff8a15d0839000.ost_server_uuid 50 [ 2194.990927] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff8a15d0839000.ost_server_uuid in IDLE state after 8 sec [ 2201.927844] Lustre: DEBUG MARKER: oleg154-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff8a15d0839000.ost_server_uuid 50 [ 2203.778441] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff8a15d0839000.ost_server_uuid in FULL state after 0 sec [ 2211.773035] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 2213.461601] Lustre: DEBUG MARKER: == sanity test 77m: Verify checksum_speed is correctly read ========================================================== 22:09:25 (1788746965) [ 2220.179294] Lustre: DEBUG MARKER: == sanity test 77n: Verify read from a hole inside contiguous blocks with T10PI ========================================================== 22:09:32 (1788746972) [ 2222.223946] Lustre: DEBUG MARKER: set checksum type to t10ip512, rc = 0 [ 2223.894936] Lustre: DEBUG MARKER: set checksum type to t10ip4K, rc = 0 [ 2225.828176] Lustre: DEBUG MARKER: set checksum type to t10crc512, rc = 0 [ 2227.209584] Lustre: DEBUG MARKER: set checksum type to t10crc4K, rc = 0 [ 2234.673211] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 2236.590080] Lustre: DEBUG MARKER: == sanity test 77o: Verify checksum_type for server (mdt and ofd(obdfilter)) ========================================================== 22:09:48 (1788746988) [ 2249.216465] Lustre: DEBUG MARKER: == sanity test 78: handle large O_DIRECT writes correctly ====================================================================== 22:10:01 (1788747001) [ 2259.150883] Lustre: DEBUG MARKER: == sanity test 79: df report consistency check =========== 22:10:11 (1788747011) [ 2275.552289] Lustre: DEBUG MARKER: == sanity test 80: Page eviction is equally fast at high offsets too ========================================================== 22:10:28 (1788747028) [ 2283.404642] Lustre: DEBUG MARKER: == sanity test 81a: OST should retry write when get -ENOSPC ========================================================================= 22:10:35 (1788747035) [ 2290.888262] Lustre: DEBUG MARKER: == sanity test 81b: OST should return -ENOSPC when retry still fails ================================================================= 22:10:43 (1788747043) [ 2298.389571] Lustre: DEBUG MARKER: == sanity test 99: cvs strange file/directory operations ========================================================== 22:10:50 (1788747050) [ 2320.655298] Lustre: DEBUG MARKER: == sanity test 100: check local port using privileged port ========================================================== 22:11:12 (1788747072) [ 2328.239137] Lustre: DEBUG MARKER: == sanity test 101a: check read-ahead for random reads === 22:11:20 (1788747080) [ 2532.406526] Lustre: DEBUG MARKER: == sanity test 101b: check stride-io mode read-ahead =========================================================================== 22:14:44 (1788747284) [ 2571.087219] Lustre: DEBUG MARKER: == sanity test 101c: check stripe_size aligned read-ahead ========================================================== 22:15:22 (1788747322) [ 2673.534299] Lustre: DEBUG MARKER: == sanity test 101d: file read with and without read-ahead enabled ========================================================== 22:17:05 (1788747425) [ 2976.411307] Lustre: DEBUG MARKER: == sanity test 101e: check read-ahead for small read(1k) for small files(500k) ========================================================== 22:22:08 (1788747728) [ 3092.072982] Lustre: DEBUG MARKER: == sanity test 101f: check mmap read performance ========= 22:24:03 (1788747843) [ 3104.296900] Lustre: DEBUG MARKER: == sanity test 101g: Big bulk(4/16 MiB) readahead ======== 22:24:16 (1788747856) [ 3113.648841] Lustre: Unmounted lustre-client [ 3113.651376] Lustre: Skipped 1 previous similar message [ 3114.198768] Lustre: Mounted lustre-client - version 2.17.58_40_g869f601 [ 3114.200593] Lustre: Skipped 1 previous similar message [ 3153.207115] Lustre: Unmounted lustre-client [ 3153.901363] Lustre: Mounted lustre-client - version 2.17.58_40_g869f601 [ 3186.326545] Lustre: DEBUG MARKER: == sanity test 101h: Readahead should cover current read window ========================================================== 22:25:37 (1788747937) [ 3210.310236] Lustre: DEBUG MARKER: == sanity test 101i: allow current readahead to exceed reservation ========================================================== 22:26:02 (1788747962) [ 3224.216449] Lustre: DEBUG MARKER: == sanity test 101j: A complete read block should be submitted when no RA ========================================================== 22:26:15 (1788747975) [ 3294.552334] Lustre: DEBUG MARKER: == sanity test 101m: read ahead for small file and last stripe of the file ========================================================== 22:27:26 (1788748046) [ 3297.111496] Lustre: DEBUG MARKER: Test readahead: size=4096 ramax= iosz=1048576 [ 3297.574727] Lustre: DEBUG MARKER: Test readahead: size=16384 ramax= iosz=1048576 [ 3298.044779] Lustre: DEBUG MARKER: Test readahead: size=16385 ramax= iosz=1048576 [ 3298.618158] Lustre: DEBUG MARKER: Test readahead: size=16383 ramax= iosz=1048576 [ 3299.214837] Lustre: DEBUG MARKER: Test readahead: size=1048577 ramax= iosz=2097152 [ 3300.121351] Lustre: DEBUG MARKER: Test readahead: size=1064960 ramax= iosz=2097152 [ 3301.188745] Lustre: DEBUG MARKER: Test readahead: size=1064960 ramax= iosz=2097152 [ 3302.161640] Lustre: DEBUG MARKER: Test readahead: size=2113536 ramax= iosz=3145728 [ 3303.526856] Lustre: DEBUG MARKER: Test readahead: size=4210688 ramax= iosz=5242880 [ 3312.984448] Lustre: DEBUG MARKER: == sanity test 102a: user xattr test ============================================================================================ 22:27:44 (1788748064) [ 3323.613076] Lustre: DEBUG MARKER: == sanity test 102b: getfattr/setfattr for trusted.lov EAs ========================================================== 22:27:55 (1788748075) [ 3337.678249] Lustre: DEBUG MARKER: == sanity test 102c: non-root getfattr/setfattr for lustre.lov EAs ===================================================================== 22:28:09 (1788748089) [ 3346.937766] Lustre: DEBUG MARKER: == sanity test 102d: tar restore stripe info from tarfile,not keep osts ========================================================== 22:28:18 (1788748098) [ 3373.629255] Lustre: DEBUG MARKER: == sanity test 102f: tar copy files, not keep osts ======= 22:28:45 (1788748125) [ 3406.065944] Lustre: DEBUG MARKER: == sanity test 102h: grow xattr from inside inode to external block ========================================================== 22:29:17 (1788748157) [ 3408.928559] Lustre: DEBUG MARKER: save trusted.big on /mnt/lustre/f102h.sanity [ 3411.486979] Lustre: DEBUG MARKER: save trusted.sml on /mnt/lustre/f102h.sanity [ 3413.682579] Lustre: DEBUG MARKER: grow trusted.sml on /mnt/lustre/f102h.sanity [ 3415.767321] Lustre: DEBUG MARKER: trusted.big still valid after growing trusted.sml [ 3422.800716] Lustre: DEBUG MARKER: == sanity test 102ha: grow xattr from inside inode to external inode ========================================================== 22:29:34 (1788748174) [ 3426.353843] Lustre: DEBUG MARKER: save trusted.big on /mnt/lustre/f102ha.sanity [ 3428.026838] Lustre: DEBUG MARKER: save trusted.sml on /mnt/lustre/f102ha.sanity [ 3429.472807] Lustre: DEBUG MARKER: grow trusted.sml on /mnt/lustre/f102ha.sanity [ 3432.204072] Lustre: DEBUG MARKER: trusted.big still valid after growing trusted.sml [ 3434.897199] Lustre: DEBUG MARKER: save trusted.big on /mnt/lustre/f102ha.sanity [ 3442.465415] Lustre: DEBUG MARKER: == sanity test 102i: lgetxattr test on symbolic link ====================================================================== 22:29:54 (1788748194) [ 3451.398760] Lustre: DEBUG MARKER: == sanity test 102j: non-root tar restore stripe info from tarfile, not keep osts ============================================================= 22:30:02 (1788748202) [ 3475.140512] Lustre: DEBUG MARKER: == sanity test 102k: setfattr without parameter of value shouldn't cause a crash ========================================================== 22:30:27 (1788748227) [ 3487.285541] Lustre: DEBUG MARKER: == sanity test 102l: listxattr size test ============================================================================================ 22:30:38 (1788748238) [ 3500.467258] Lustre: DEBUG MARKER: == sanity test 102m: Ensure listxattr fails on small bufffer ================================================================== 22:30:50 (1788748250) [ 3509.367171] Lustre: DEBUG MARKER: == sanity test 102n: silently ignore setxattr on internal trusted xattrs ========================================================== 22:31:01 (1788748261) [ 3520.432687] Lustre: DEBUG MARKER: == sanity test 102p: check setxattr(2) correctly fails without permission ========================================================== 22:31:12 (1788748272) [ 3529.733843] Lustre: DEBUG MARKER: == sanity test 102q: flistxattr should not return trusted.link EAs for orphans ========================================================== 22:31:21 (1788748281) [ 3539.020812] Lustre: DEBUG MARKER: == sanity test 102r: set EAs with empty values =========== 22:31:30 (1788748290) [ 3548.758056] Lustre: DEBUG MARKER: == sanity test 102s: getting nonexistent xattrs should fail ========================================================== 22:31:40 (1788748300) [ 3549.283059] LustreError: lustre-MDT0000-mdc-ffff8a15d083a000: operation mds_getxattr to node 192.168.201.154@tcp failed: rc = -95 [ 3559.371037] Lustre: DEBUG MARKER: == sanity test 102t: zero length xattr values handled correctly ========================================================== 22:31:50 (1788748310) [ 3571.385495] Lustre: DEBUG MARKER: == sanity test 103a: acl test ============================ 22:32:02 (1788748322) [ 3879.254763] Lustre: DEBUG MARKER: == sanity test 103b: umask lfs setstripe ================= 22:37:10 (1788748630) [ 4069.994248] Lustre: DEBUG MARKER: == sanity test 103c: 'cp -rp' won't set empty acl ======== 22:40:22 (1788748822) [ 4077.609890] Lustre: DEBUG MARKER: == sanity test 103e: inheritance of big amount of default ACLs ========================================================== 22:40:29 (1788748829) [ 4107.453818] Lustre: DEBUG MARKER: == sanity test 103f: changelog doesn't interfere with default ACLs buffers ========================================================== 22:40:58 (1788748858) [ 4125.538991] Lustre: DEBUG MARKER: == sanity test 103g: no MDS_GETXATTR storm for inodes without ACL_ACCESS (LU-17238) ========================================================== 22:41:17 (1788748877) [ 4133.185954] Lustre: DEBUG MARKER: == sanity test 104a: lfs df [-ih] [path] test =================================================================================== 22:41:25 (1788748885) [ 4133.656676] Lustre: setting import lustre-OST0000_UUID INACTIVE by administrator request [ 4133.689619] Lustre: lustre-OST0000-osc-ffff8a15d083a000: Connection to lustre-OST0000 (at 192.168.201.154@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 4133.707540] LustreError: lustre-OST0000-osc-ffff8a15d083a000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 4138.822796] Lustre: DEBUG MARKER: oleg154-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0000-osc-ffff8a15d083a000.ost_server_uuid 50 [ 4140.191572] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff8a15d083a000.ost_server_uuid in FULL state after 0 sec [ 4146.511096] Lustre: DEBUG MARKER: == sanity test 104b: runas -u 500 -g 500 lfs check servers test ============================================================================== 22:41:38 (1788748898) [ 4153.565276] Lustre: DEBUG MARKER: == sanity test 104c: Verify df vs lfs_df stays same after recordsize change ========================================================== 22:41:45 (1788748905) [ 4155.098169] Lustre: DEBUG MARKER: SKIP: sanity test_104c zfs only test [ 4156.820126] Lustre: DEBUG MARKER: == sanity test 104d: runas -u 500 -g 500 lctl dl test ==== 22:41:48 (1788748908) [ 4163.758169] Lustre: DEBUG MARKER: == sanity test 105a: flock when mounted without -o flock test ================================================================== 22:41:55 (1788748915) [ 4171.039956] Lustre: DEBUG MARKER: == sanity test 105b: fcntl when mounted without -o flock test ================================================================== 22:42:03 (1788748923) [ 4177.194559] Lustre: DEBUG MARKER: == sanity test 105c: lockf when mounted without -o flock test ========================================================== 22:42:09 (1788748929) [ 4184.014416] Lustre: DEBUG MARKER: == sanity test 105d: flock race (should not freeze) ================================================================== 22:42:16 (1788748936) [ 4184.664741] LustreError: 116580:0:(ldlm_flock.c:850:ldlm_flock_completion_ast()) cfs_fail_timeout id 315 sleeping for 10000ms [ 4194.687774] LustreError: 116580:0:(ldlm_flock.c:850:ldlm_flock_completion_ast()) cfs_fail_timeout id 315 awake [ 4201.186427] Lustre: DEBUG MARKER: == sanity test 105e: Two conflicting flocks from same process ========================================================== 22:42:33 (1788748953) [ 4208.338501] Lustre: DEBUG MARKER: == sanity test 105f: Enqueue same range flocks =========== 22:42:40 (1788748960) [ 4216.982559] Lustre: DEBUG MARKER: == sanity test 105g: ldlm_lock_debug stack test ========== 22:42:49 (1788748969) [ 4217.302949] Lustre: *** cfs_fail_loc=32f, val=0*** [ 4217.304323] LustreError: 118429:0:(ldlm_flock.c:802:ldlm_flock_completion_ast()) ### Test ldlm error stack ns: lustre-MDT0000-mdc-ffff8a15d083a000 lock: ffff8a14f3436400/0x281fdd7597b9a084 lrc: 4/0,1 mode: PW/PW res: [0x20000040a:0xb3e:0x0].0xc rrc: 2 type: FLK pid: 118428 [0->9223372036854775807] flags: 0x0 nid: local remote: 0x52ab9fab9b5505a7 expref: -99 pid: 118429 timeout: 0 [ 4217.314950] CPU: 0 PID: 118429 Comm: flocks_test Kdump: loaded Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 4217.319092] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.17.0-10.fc44 06/10/2025 [ 4217.321719] Call Trace: [ 4217.323159] ? dump_stack+0xbb/0x10e [ 4217.325089] ? ldlm_flock_completion_ast.cold.17+0xd/0x27 [ptlrpc] [ 4217.326971] ? _raw_spin_unlock+0x12/0x30 [ 4217.327975] ? unlock_res_and_lock+0x23/0x30 [ptlrpc] [ 4217.330373] ? ldlm_lock_enqueue+0x3a1/0xcd0 [ptlrpc] [ 4217.334082] ? ldlm_cli_enqueue_fini+0xadc/0x1500 [ptlrpc] [ 4217.338086] ? ldlm_cli_enqueue+0x47f/0xe40 [ptlrpc] [ 4217.341084] ? ldlm_flock_completion_ast_async+0xb30/0xb30 [ptlrpc] [ 4217.343879] ? mdc_changelog_cdev_finish+0x2c0/0x2c0 [mdc] [ 4217.345193] ? mdc_enqueue_base+0x456/0x1dd0 [mdc] [ 4217.346449] ? mdc_enqueue+0x1c/0x30 [mdc] [ 4217.347421] ? lmv_enqueue+0x28a/0x530 [lmv] [ 4217.348435] ? ll_file_flock+0x962/0x1420 [lustre] [ 4217.349694] ? ldlm_flock_completion_ast_async+0xb30/0xb30 [ptlrpc] [ 4217.351441] ? mdc_changelog_cdev_finish+0x2c0/0x2c0 [mdc] [ 4217.352829] ? __mod_memcg_lruvec_state+0x5e/0x130 [ 4217.353955] ? __mod_lruvec_state+0x5a/0x80 [ 4217.354877] ? page_add_new_anon_rmap+0x77/0x1c0 [ 4217.355831] ? slab_post_alloc_hook+0x66/0x380 [ 4217.356804] ? locks_alloc_lock+0x1f/0x90 [ 4217.357676] ? kmem_cache_alloc+0x184/0x430 [ 4217.358495] ? vfs_lock_file+0x22/0x50 [ 4217.359288] ? fcntl_setlk+0xde/0x4e0 [ 4217.360068] ? __might_sleep+0x59/0xc0 [ 4217.361270] ? do_fcntl+0x7da/0xb80 [ 4217.362021] ? __x64_sys_fcntl+0xc4/0x110 [ 4217.362793] ? do_syscall_64+0xc1/0x440 [ 4217.363873] ? entry_SYSCALL_64_after_hwframe+0x49/0xae [ 4225.520265] Lustre: DEBUG MARKER: == sanity test 105h: Flock functional verify ============= 22:42:57 (1788748977) [ 4233.356442] Lustre: DEBUG MARKER: == sanity test 105i: Flock deadlock verify =============== 22:43:05 (1788748985) [ 4238.612927] LustreError: lustre-MDT0000-mdc-ffff8a15d083a000: operation ldlm_enqueue to node 192.168.201.154@tcp failed: rc = -35 [ 4244.993747] Lustre: DEBUG MARKER: == sanity test 106: attempt exec of dir followed by chown of that dir ========================================================== 22:43:16 (1788748996) [ 4251.143146] Lustre: DEBUG MARKER: == sanity test 107: Coredump on SIG ====================== 22:43:23 (1788749003) [ 4258.814507] Lustre: DEBUG MARKER: == sanity test 110: filename length checking ============= 22:43:31 (1788749011) [ 4265.624568] Lustre: DEBUG MARKER: == sanity test 116a: stripe QOS: free space balance ============================================================================= 22:43:38 (1788749018) [ 4419.468608] Lustre: DEBUG MARKER: == sanity test 116b: QoS shouldn't LBUG if not enough OSTs found on the 2nd pass ========================================================== 22:46:11 (1788749171) [ 4429.312975] Lustre: DEBUG MARKER: == sanity test 117: verify osd extend ==================== 22:46:21 (1788749181) [ 4435.790396] Lustre: DEBUG MARKER: == sanity test 118a: verify O_SYNC works ================= 22:46:27 (1788749187) [ 4442.122889] Lustre: DEBUG MARKER: == sanity test 118b: Reclaim dirty pages on fatal error ==================================================================== 22:46:34 (1788749194) [ 4451.005487] Lustre: DEBUG MARKER: SKIP: sanity test_118c skipping ALWAYS excluded test 118c [ 4452.805982] Lustre: DEBUG MARKER: SKIP: sanity test_118d skipping ALWAYS excluded test 118d [ 4454.167539] Lustre: DEBUG MARKER: == sanity test 118f: Simulate unrecoverable OSC side error ==================================================================== 22:46:46 (1788749206) [ 4454.643306] Lustre: *** cfs_fail_loc=40a, val=0*** [ 4454.644748] Lustre: Skipped 57 previous similar messages [ 4454.646781] LustreError: 127435:0:(osc_request.c:2918:osc_build_rpc()) lustre-OST0001-osc-ffff8a15d083a000: prep_req failed: rc = -22 [ 4454.651497] LustreError: 127435:0:(osc_cache.c:2419:osc_check_rpcs()) Write request failed with -22 [ 4459.713960] Lustre: DEBUG MARKER: == sanity test 118g: Don't stay in wait if we got local -ENOMEM ==================================================================== 22:46:52 (1788749212) [ 4460.181939] LustreError: 128032:0:(osc_request.c:2918:osc_build_rpc()) lustre-OST0000-osc-ffff8a15d083a000: prep_req failed: rc = -12 [ 4460.200913] LustreError: 128032:0:(osc_cache.c:2419:osc_check_rpcs()) Write request failed with -12 [ 4465.204572] Lustre: DEBUG MARKER: == sanity test 118h: Verify timeout in handling recoverables errors ==================================================================== 22:46:57 (1788749217) [ 4466.939282] LustreError: lustre-OST0001-osc-ffff8a15d083a000: operation ost_write to node 192.168.201.154@tcp failed: rc = -5 [ 4466.949372] LustreError: 2400:0:(osc_request.c:2451:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff8a14f34ed500 x1875634922800896/t0(0) o4->lustre-OST0001-osc-ffff8a15d083a000@192.168.201.154@tcp:6/4 lens 4584/224 e 0 to 0 dl 1788749236 ref 2 fl Interpret:RMQU/600/0 rc -5/-5 job:'multiop.0' uid:0 gid:0 projid:0 [ 4466.968661] LustreError: 2400:0:(osc_request.c:2451:osc_brw_redo_request()) Skipped 17 previous similar messages [ 4468.010197] LustreError: lustre-OST0001-osc-ffff8a15d083a000: operation ost_write to node 192.168.201.154@tcp failed: rc = -5 [ 4470.064556] LustreError: lustre-OST0001-osc-ffff8a15d083a000: operation ost_write to node 192.168.201.154@tcp failed: rc = -5 [ 4476.525021] LustreError: lustre-OST0001-osc-ffff8a15d083a000: operation ost_write to node 192.168.201.154@tcp failed: rc = -5 [ 4476.531718] LustreError: Skipped 1 previous similar message [ 4476.533829] LustreError: 2401:0:(osc_request.c:2608:brw_interpret()) lustre-OST0001-osc-ffff8a15d083a000: too many resent retries for object: 11811161089:6458: rc = -5 [ 4476.539798] LustreError: 2401:0:(osc_request.c:2608:brw_interpret()) Skipped 3 previous similar messages [ 4476.542883] Lustre: 2401:0:(llite_lib.c:4342:ll_dirty_page_discard_warn()) lustre: dirty page discard: 192.168.201.154@tcp:/lustre/fid: [0x20000040a:0xe7e:0x0]// may get corrupted (rc -5) [ 4482.495263] Lustre: DEBUG MARKER: == sanity test 118i: Fix error before timeout in recoverable error ==================================================================== 22:47:15 (1788749235) [ 4484.078854] LustreError: 2403:0:(osc_request.c:2451:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff8a15c54b8e00 x1875634922808960/t0(0) o4->lustre-OST0001-osc-ffff8a15d083a000@192.168.201.154@tcp:6/4 lens 4584/224 e 0 to 0 dl 1788749253 ref 2 fl Interpret:RMQU/600/0 rc -5/-5 job:'multiop.0' uid:0 gid:0 projid:0 [ 4484.104641] LustreError: 2403:0:(osc_request.c:2451:osc_brw_redo_request()) Skipped 3 previous similar messages [ 4485.106302] LustreError: lustre-OST0001-osc-ffff8a15d083a000: operation ost_write to node 192.168.201.154@tcp failed: rc = -5 [ 4485.112750] LustreError: Skipped 1 previous similar message [ 4494.772960] Lustre: DEBUG MARKER: == sanity test 118j: Simulate unrecoverable OST side error ==================================================================== 22:47:27 (1788749247) [ 4503.354825] Lustre: DEBUG MARKER: == sanity test 118k: bio alloc -ENOMEM and IO TERM handling =================================================================== 22:47:35 (1788749255) [ 4505.434387] LustreError: lustre-OST0000-osc-ffff8a15d083a000: operation ost_write to node 192.168.201.154@tcp failed: rc = -5 [ 4505.438718] LustreError: Skipped 2 previous similar messages [ 4505.441652] LustreError: 2403:0:(osc_request.c:2451:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff8a15c54bb100 x1875634922820096/t0(0) o4->lustre-OST0000-osc-ffff8a15d083a000@192.168.201.154@tcp:6/4 lens 488/224 e 0 to 0 dl 1788749274 ref 2 fl Interpret:ReMQU/600/0 rc -5/-5 job:'dd.0' uid:0 gid:0 projid:0 [ 4505.452453] LustreError: 2403:0:(osc_request.c:2451:osc_brw_redo_request()) Skipped 2 previous similar messages [ 4522.931157] Lustre: DEBUG MARKER: == sanity test 118l: fsync dir =========================== 22:47:55 (1788749275) [ 4528.399993] Lustre: DEBUG MARKER: == sanity test 118m: fdatasync dir ======================= 22:48:00 (1788749280) [ 4533.278520] Lustre: DEBUG MARKER: == sanity test 118n: statfs() sends OST_STATFS requests in parallel ========================================================== 22:48:05 (1788749285) [ 4541.903440] Lustre: DEBUG MARKER: == sanity test 119a: Short directIO read must return actual read amount ========================================================== 22:48:14 (1788749294) [ 4547.580828] Lustre: DEBUG MARKER: == sanity test 119b: Sparse directIO read must return actual read amount ========================================================== 22:48:20 (1788749300) [ 4553.135804] Lustre: DEBUG MARKER: == sanity test 119c: Testing for direct read hitting hole ========================================================== 22:48:25 (1788749305) [ 4558.267920] Lustre: DEBUG MARKER: == sanity test 119e: Basic tests of dio read and write at various sizes ========================================================== 22:48:30 (1788749310) [ 4584.862721] Lustre: DEBUG MARKER: == sanity test 119f: dio vs dio race ===================== 22:48:57 (1788749337) [ 4614.467601] Lustre: DEBUG MARKER: == sanity test 119g: dio vs buffered I/O race ============ 22:49:26 (1788749366) [ 4636.930941] Lustre: DEBUG MARKER: == sanity test 119h: basic tests of memory unaligned dio ========================================================== 22:49:49 (1788749389) [ 4653.098482] Lustre: DEBUG MARKER: SKIP: sanity test_119i skipping ALWAYS excluded test 119i [ 4654.116615] Lustre: DEBUG MARKER: == sanity test 119j: basic tests of hybrid IO switching == 22:50:06 (1788749406) [ 4654.457656] Lustre: *** cfs_fail_loc=1429, val=0*** [ 4658.607413] Lustre: DEBUG MARKER: == sanity test 119k: hybrid IO counting with stats and disabling ========================================================== 22:50:11 (1788749411) [ 4668.538471] Lustre: DEBUG MARKER: == sanity test 119m: Test DIO readv/writev: exercise iter duplication ========================================================== 22:50:21 (1788749421) [ 4672.849505] Lustre: DEBUG MARKER: == sanity test 119n: Test Unaligned DIO readv() and writev() with unpatched ZFS ========================================================== 22:50:25 (1788749425) [ 4673.919982] Lustre: DEBUG MARKER: SKIP: sanity test_119n need ZFS server without unaligned_dio support [ 4675.191883] Lustre: DEBUG MARKER: == sanity test 119o: Test Unaligned DIO readv() and writev() with unpatched servers ========================================================== 22:50:27 (1788749427) [ 4676.148936] Lustre: DEBUG MARKER: SKIP: sanity test_119o need ldiskfs without unaligned_dio support. [ 4677.531144] Lustre: DEBUG MARKER: == sanity test 119p: Test Unaligned DIO readv() and writev() with patched servers ========================================================== 22:50:29 (1788749429) [ 4682.503633] Lustre: DEBUG MARKER: == sanity test 119q: Test patchded Unaligned DIO readv() and writev() ========================================================== 22:50:35 (1788749435) [ 4690.823685] Lustre: DEBUG MARKER: == sanity test 119r: Test error handling in unaligned DIO user copy ========================================================== 22:50:43 (1788749443) [ 4691.297077] Lustre: *** cfs_fail_loc=1437, val=0*** [ 4691.300935] LustreError: 117970:0:(osc_cache.c:2419:osc_check_rpcs()) Write request failed with -14 [ 4695.365907] Lustre: DEBUG MARKER: == sanity test 119s: full-size unaligned DIO packs matching bulk MDs ========================================================== 22:50:48 (1788749448) [ 4696.501549] Lustre: DEBUG MARKER: SKIP: sanity test_119s need client page size larger than the server's [ 4697.529652] Lustre: DEBUG MARKER: == sanity test 120a: Early Lock Cancel: mkdir test ======= 22:50:50 (1788749450) [ 4703.911687] Lustre: DEBUG MARKER: == sanity test 120b: Early Lock Cancel: create test ====== 22:50:56 (1788749456) [ 4710.455061] Lustre: DEBUG MARKER: == sanity test 120c: Early Lock Cancel: link test ======== 22:51:03 (1788749463) [ 4717.115270] Lustre: DEBUG MARKER: == sanity test 120d: Early Lock Cancel: setattr test ===== 22:51:09 (1788749469) [ 4723.293805] Lustre: DEBUG MARKER: == sanity test 120e: Early Lock Cancel: unlink test ====== 22:51:16 (1788749476) [ 4736.149800] Lustre: DEBUG MARKER: == sanity test 120f: Early Lock Cancel: rename test ====== 22:51:28 (1788749488) [ 4749.445974] Lustre: DEBUG MARKER: == sanity test 120g: Early Lock Cancel: performance test ========================================================== 22:51:42 (1788749502) [ 5217.478928] Lustre: DEBUG MARKER: == sanity test 121: read cancel race ===================== 22:59:29 (1788749969) [ 5217.946101] Lustre: *** cfs_fail_loc=310, val=0*** [ 5225.533261] Lustre: DEBUG MARKER: == sanity test 123aa: verify statahead work ============== 22:59:37 (1788749977) [ 5234.658552] Lustre: DEBUG MARKER: 'ls -l' 100 files without statahead: 3 sec [ 5237.184789] Lustre: DEBUG MARKER: 'ls -l' 100 files with statahead: 1 sec [ 5279.635395] Lustre: DEBUG MARKER: 'ls -l' 1000 files without statahead: 23 sec [ 5289.599276] Lustre: DEBUG MARKER: 'ls -l' 1000 files with statahead: 6 sec [ 5291.548733] Lustre: DEBUG MARKER: 'ls -l' done [ 5314.256240] Lustre: DEBUG MARKER: unlink + rm -r /mnt/lustre/d123aa.sanity: 21 seconds [ 5327.107168] Lustre: DEBUG MARKER: == sanity test 123ab: verify statahead work by using statx ========================================================== 23:01:19 (1788750079) [ 5337.394589] Lustre: DEBUG MARKER: 'statx -l' 100 files without statahead: 3 sec [ 5340.378864] Lustre: DEBUG MARKER: 'statx -l' 100 files with statahead: 1 sec [ 5381.016700] Lustre: DEBUG MARKER: 'statx -l' 1000 files without statahead: 21 sec [ 5390.432366] Lustre: DEBUG MARKER: 'statx -l' 1000 files with statahead: 6 sec [ 5392.297775] Lustre: DEBUG MARKER: 'statx -l' done [ 5415.097497] Lustre: DEBUG MARKER: unlink + rm -r /mnt/lustre/d123ab.sanity: 22 seconds [ 5429.550527] Lustre: DEBUG MARKER: == sanity test 123ac: verify statahead work by using statx without glimpse RPCs ========================================================== 23:03:01 (1788750181) [ 5438.423453] Lustre: DEBUG MARKER: 'statx -c 0 [ 5441.133144] Lustre: DEBUG MARKER: 'statx -c 0 [ 5481.274256] Lustre: DEBUG MARKER: 'statx -c 0 [ 5488.194580] Lustre: DEBUG MARKER: 'statx -c 0 [ 5490.216837] Lustre: DEBUG MARKER: 'statx -c 0 [ 5509.073108] Lustre: DEBUG MARKER: unlink + rm -r /mnt/lustre/d123ac.sanity: 18 seconds [ 5517.991569] Lustre: DEBUG MARKER: 'statx --cached=always -D' 100 files without statahead: 0 sec [ 5520.845349] Lustre: DEBUG MARKER: 'statx --cached=always -D' 100 files with statahead: 1 sec [ 5542.142808] Lustre: DEBUG MARKER: 'statx --cached=always -D' 1000 files without statahead: 1 sec [ 5545.015723] Lustre: DEBUG MARKER: 'statx --cached=always -D' 1000 files with statahead: 0 sec [ 5681.534678] Lustre: DEBUG MARKER: 'statx --cached=always -D' 10000 files without statahead: 1 sec [ 5684.781867] Lustre: DEBUG MARKER: 'statx --cached=always -D' 10000 files with statahead: 1 sec [ 5686.534560] Lustre: DEBUG MARKER: 'statx --cached=always -D' done [ 6003.183828] Lustre: DEBUG MARKER: unlink + rm -r /mnt/lustre/d123ac.sanity: 315 seconds [ 6023.699883] Lustre: DEBUG MARKER: == sanity test 123ad: Verify batching statahead works correctly ========================================================== 23:12:55 (1788750775) [ 6034.461990] Lustre: DEBUG MARKER: 'ls -l' 100 files without statahead: 2 sec [ 6037.656301] Lustre: DEBUG MARKER: 'ls -l' 100 files with statahead: 1 sec [ 6077.957200] Lustre: DEBUG MARKER: 'ls -l' 1000 files without statahead: 21 sec [ 6092.263933] Lustre: DEBUG MARKER: 'ls -l' 1000 files with statahead: 10 sec [ 6094.929881] Lustre: DEBUG MARKER: 'ls -l' done [ 6117.117951] Lustre: DEBUG MARKER: unlink + rm -r /mnt/lustre/d123ad.sanity: 20 seconds [ 6668.262331] Lustre: DEBUG MARKER: 'ls -l' 100 files without statahead: 2 sec [ 6671.667896] Lustre: DEBUG MARKER: 'ls -l' 100 files with statahead: 1 sec [ 6706.875633] Lustre: DEBUG MARKER: 'ls -l' 1000 files without statahead: 18 sec [ 6715.891301] Lustre: DEBUG MARKER: 'ls -l' 1000 files with statahead: 5 sec [ 6717.727722] Lustre: DEBUG MARKER: 'ls -l' done [ 6739.393876] Lustre: DEBUG MARKER: unlink + rm -r /mnt/lustre/d123ad.sanity: 20 seconds [ 7164.487294] Lustre: DEBUG MARKER: == sanity test 123b: not panic with network error in statahead enqueue (bug 15027) ========================================================== 23:31:56 (1788751916) [ 7188.538723] Lustre: DEBUG MARKER: ls done [ 7214.130526] Lustre: DEBUG MARKER: == sanity test 123c: Can not initialize inode warning on DNE statahead ========================================================== 23:32:45 (1788751965) [ 7217.395808] Lustre: Unmounted lustre-client [ 7217.866205] Lustre: Mounted lustre-client - version 2.17.58_40_g869f601 [ 7226.525529] Lustre: DEBUG MARKER: == sanity test 123d: Statahead on striped directories works correctly ========================================================== 23:32:58 (1788751978) [ 7233.154288] Lustre: Unmounted lustre-client [ 7233.637090] Lustre: Mounted lustre-client - version 2.17.58_40_g869f601 [ 7250.891256] Lustre: DEBUG MARKER: == sanity test 123e: statahead with large wide striping == 23:33:22 (1788752002) [ 7507.715862] Lustre: DEBUG MARKER: == sanity test 123f: Retry mechanism with large wide striping files ========================================================== 23:37:39 (1788752259) [ 8573.299742] Lustre: DEBUG MARKER: == sanity test 123g: Test for stat-ahead advise ========== 23:55:25 (1788753325) [ 8660.040767] Lustre: DEBUG MARKER: == sanity test 123h: Verify statahead work with the fname pattern ========================================================== 23:56:52 (1788753412) [10086.410238] Lustre: DEBUG MARKER: == sanity test 123i: Verify statahead work with the fname indexing pattern ========================================================== 00:20:38 (1788754838) [10204.709209] Lustre: DEBUG MARKER: == sanity test 123j: -ENOENT error from batched statahead be handled correctly ========================================================== 00:22:36 (1788754956) [10213.095736] Lustre: DEBUG MARKER: == sanity test 123k: Verify statahead work with mdtest shared stat() mode ========================================================== 00:22:45 (1788754965) [10214.803762] Lustre: DEBUG MARKER: SKIP: sanity test_123k mdtest not found [10216.797761] Lustre: DEBUG MARKER: == sanity test 123l: Avoid panic when revalidate a local cached entry ========================================================== 00:22:48 (1788754968) [10221.517514] LustreError: 184180:0:(statahead.c:360:sa_put()) cfs_fail_timeout id 1433 sleeping for 35000ms [10256.520087] LustreError: 184180:0:(statahead.c:360:sa_put()) cfs_fail_timeout id 1433 awake [10297.942678] Lustre: DEBUG MARKER: == sanity test 124a: lru resize ================================================================================================= 00:24:09 (1788755049) [10299.659847] Lustre: DEBUG MARKER: create 2000 files at /mnt/lustre/d124a.sanity [10338.357836] Lustre: DEBUG MARKER: NSDIR=ldlm.namespaces.lustre-MDT0000-mdc-ffff8a15ca010800 [10340.410300] Lustre: DEBUG MARKER: NS=ldlm.namespaces.lustre-MDT0000-mdc-ffff8a15ca010800 [10341.995403] Lustre: DEBUG MARKER: LRU=1015 [10343.724620] Lustre: DEBUG MARKER: LIMIT=46162 [10345.455226] Lustre: DEBUG MARKER: LVF=5457500 [10346.986979] Lustre: DEBUG MARKER: OLD_LVF=100 [10348.712880] Lustre: DEBUG MARKER: Sleep 50 sec [10400.690586] Lustre: DEBUG MARKER: Dropped 540 locks in 50s [10403.206131] Lustre: DEBUG MARKER: unlink 2000 files at /mnt/lustre/d124a.sanity [10430.349301] Lustre: DEBUG MARKER: == sanity test 124b: lru resize (performance test) ================================================================================= 00:26:22 (1788755182) [10524.325786] Lustre: DEBUG MARKER: doing ls -la /mnt/lustre/d124b.sanity/disable_lru_resize 3 times [10660.315496] Lustre: DEBUG MARKER: ls -la time: 134 seconds [10662.880967] Lustre: DEBUG MARKER: lru_size = 400 [10855.121987] Lustre: DEBUG MARKER: doing ls -la /mnt/lustre/d124b.sanity/enable_lru_resize 3 times [10958.751844] Lustre: DEBUG MARKER: ls -la time: 98 seconds [10961.819703] Lustre: DEBUG MARKER: lru_size = 4052 [10964.022853] Lustre: DEBUG MARKER: ls -la is 26% faster with lru resize enabled [11027.853463] Lustre: DEBUG MARKER: == sanity test 124c: LRUR cancel very aged locks ========= 00:36:19 (1788755779) [11061.129568] Lustre: DEBUG MARKER: == sanity test 124d: cancel very aged locks if lru-resize disabled ========================================================== 00:36:53 (1788755813) [11093.912248] Lustre: DEBUG MARKER: == sanity test 124e: LFRU keep priv locks from eviction == 00:37:26 (1788755846) [11141.975943] Lustre: DEBUG MARKER: == sanity test 124f: LFRU priv threshold inc/dec adjustment ========================================================== 00:38:13 (1788755893) [11234.729549] Lustre: DEBUG MARKER: == sanity test 124g: LFRU performance test =============== 00:39:46 (1788755986) [12116.120258] Lustre: DEBUG MARKER: == sanity test 125: don't return EPROTO when a dir has a non-default striping and ACLs ========================================================== 00:54:28 (1788756868) [12123.224066] Lustre: DEBUG MARKER: == sanity test 126: check that the fsgid provided by the client is taken into account ========================================================== 00:54:35 (1788756875) [12130.354500] Lustre: DEBUG MARKER: == sanity test 127a: verify the client stats are sane ==== 00:54:41 (1788756881) [12138.484401] Lustre: DEBUG MARKER: == sanity test 127b: verify the llite client stats are sane ========================================================== 00:54:50 (1788756890) [12145.362137] Lustre: DEBUG MARKER: == sanity test 127c: test llite extent stats with regular [12171.622863] Lustre: DEBUG MARKER: == sanity test 127d: OSC RPC latency histograms for read and write latency ========================================================== 00:55:23 (1788756923) [12180.186340] Lustre: DEBUG MARKER: == sanity test 127e: client IO latency histograms by size ========================================================== 00:55:32 (1788756932) [12194.798950] Lustre: DEBUG MARKER: == sanity test 127f: OST IO latency histograms by size === 00:55:47 (1788756947) [12217.204167] Lustre: DEBUG MARKER: == sanity test 127g: cached_read_bytes tracks page cache hits ========================================================== 00:56:09 (1788756969) [12219.819438] bash (228297): drop_caches: 3 [12221.103542] bash (228297): drop_caches: 3 [12223.010351] bash (228297): drop_caches: 3 [12231.217072] Lustre: DEBUG MARKER: == sanity test 128: interactive lfs for 2 consecutive find's ========================================================== 00:56:23 (1788756983) [12239.067949] Lustre: DEBUG MARKER: == sanity test 129: test directory size limit ================================================================================== 00:56:30 (1788756990) [12306.228607] Lustre: DEBUG MARKER: == sanity test 130a: FIEMAP (1-stripe file) ============== 00:57:38 (1788757058) [12312.750921] Lustre: DEBUG MARKER: == sanity test 130b: FIEMAP (2-stripe file) ============== 00:57:45 (1788757065) [12320.351420] Lustre: DEBUG MARKER: == sanity test 130c: FIEMAP (2-stripe file with hole) ==== 00:57:52 (1788757072) [12327.288338] Lustre: DEBUG MARKER: == sanity test 130d: FIEMAP (N-stripe file) ============== 00:57:59 (1788757079) [12328.762390] Lustre: DEBUG MARKER: SKIP: sanity test_130d needs >= 3 OSTs [12330.848185] Lustre: DEBUG MARKER: == sanity test 130e: FIEMAP (test continuation FIEMAP calls) ========================================================== 00:58:02 (1788757082) [12388.994811] Lustre: DEBUG MARKER: == sanity test 130f: FIEMAP (unstriped file) ============= 00:59:01 (1788757141) [12396.573070] Lustre: DEBUG MARKER: == sanity test 130g: FIEMAP (overstripe file) ============ 00:59:08 (1788757148) [12442.483190] Lustre: DEBUG MARKER: == sanity test 130h: FIEMAP deadlock ===================== 00:59:54 (1788757194) [12445.469519] LustreError: 239297:0:(osc_object.c:271:osc_object_fiemap()) cfs_fail_timeout id 418 sleeping for 5000ms [12450.487791] LustreError: 239297:0:(osc_object.c:271:osc_object_fiemap()) cfs_fail_timeout id 418 awake [12456.942598] Lustre: DEBUG MARKER: == sanity test 130i: FIEMAP (DoM file) =================== 01:00:09 (1788757209) [12504.664350] Lustre: DEBUG MARKER: == sanity test 131a: test iov's crossing stripe boundary for writev/readv ========================================================== 01:00:56 (1788757256) [12513.088200] Lustre: DEBUG MARKER: == sanity test 131b: test append writev ================== 01:01:05 (1788757265) [12521.228783] Lustre: DEBUG MARKER: == sanity test 131c: test read/write on file w/o objects ========================================================== 01:01:13 (1788757273) [12528.650035] Lustre: DEBUG MARKER: == sanity test 131d: test short read ===================== 01:01:20 (1788757280) [12536.685140] Lustre: DEBUG MARKER: == sanity test 131e: test read hitting hole ============== 01:01:28 (1788757288) [12544.011112] Lustre: DEBUG MARKER: == sanity test 133a: Verifying MDT stats ================================================================================================== 01:01:36 (1788757296) [12567.226287] Lustre: DEBUG MARKER: == sanity test 133b: Verifying extra MDT stats ============================================================================================ 01:01:59 (1788757319) [12582.245988] Lustre: DEBUG MARKER: == sanity test 133c: Verifying OST stats ================================================================================================== 01:02:14 (1788757334) [12616.513996] Lustre: DEBUG MARKER: == sanity test 133d: Verifying rename_stats ================================================================================================== 01:02:48 (1788757368) [12653.788497] Lustre: DEBUG MARKER: == sanity test 133e: Verifying OST read_bytes write_bytes nid stats =========================================================================== 01:03:25 (1788757405) [12669.066456] Lustre: DEBUG MARKER: == sanity test 133f: Check reads/writes of client lustre proc files with bad area io ========================================================== 01:03:40 (1788757420) [12671.766786] LNet: 250678:0:(debug.c:375:cfs_str2mask()) unknown mask ''. [12671.766786] mask usage: [+|-] ... [12672.307090] Lustre: DEBUG MARKER:  [12672.309927] Lustre: DEBUG MARKER:  [12672.526021] LNet: 250742:0:(debug.c:375:cfs_str2mask()) unknown mask ''. [12672.526021] mask usage: [+|-] ... [12672.536543] LNet: 250742:0:(debug.c:375:cfs_str2mask()) Skipped 6 previous similar messages [12689.239537] Lustre: Unmounted lustre-client [12744.551166] Key type lgssc unregistered [12744.938510] LNet: 252012:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [12744.948822] LNetError: 252012:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [12744.963914] LNet: Removed LNI 192.168.201.54@tcp [12746.590341] Key type .llcrypt unregistered [12746.593423] Key type ._llcrypt unregistered [12758.850617] Key type ._llcrypt registered [12758.856373] Key type .llcrypt registered [12759.653628] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [12759.677207] alg: No test for adler32 (adler32-zlib) [12761.364323] Lustre: Lustre: Build Version: 2.17.58_40_g869f601 [12762.430649] LNet: Added LNI 192.168.201.54@tcp [8/256/0/180] [12764.263406] Key type lgssc registered [12766.503876] Lustre: Echo OBD driver; http://www.lustre.org/ [12887.444166] Lustre: Mounted lustre-client - version 2.17.58_40_g869f601 [12893.137895] Lustre: DEBUG MARKER: Using TIMEOUT=20 [12905.677929] Lustre: DEBUG MARKER: == sanity test 133g: Check reads/writes of server lustre proc files with bad area io ========================================================== 01:07:37 (1788757657) [12913.121589] Lustre: lustre-OST0000-osc-ffff8a15c2bc5000: disconnect after 23s idle [13060.517823] Lustre: Unmounted lustre-client [13121.803059] Key type lgssc unregistered [13122.093321] LNet: 256349:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [13122.100960] LNetError: 256349:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [13122.120428] LNet: Removed LNI 192.168.201.54@tcp [13122.804573] Key type .llcrypt unregistered [13122.806143] Key type ._llcrypt unregistered [13135.142096] Key type ._llcrypt registered [13135.195499] Key type .llcrypt registered [13135.731259] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [13135.745249] alg: No test for adler32 (adler32-zlib) [13136.934358] Lustre: Lustre: Build Version: 2.17.58_40_g869f601 [13137.265579] LNet: Added LNI 192.168.201.54@tcp [8/256/0/180] [13138.975357] Key type lgssc registered [13140.809447] Lustre: Echo OBD driver; http://www.lustre.org/ [13264.118649] Lustre: Mounted lustre-client - version 2.17.58_40_g869f601 [13270.204769] Lustre: DEBUG MARKER: Using TIMEOUT=20 [13283.391554] Lustre: DEBUG MARKER: == sanity test 133h: Proc files should end with newlines ========================================================== 01:13:55 (1788758035) [13289.953613] Lustre: lustre-OST0000-osc-ffff8a15c9522800: disconnect after 23s idle [13336.033279] Lustre: lustre-OST0000-osc-ffff8a15c9522800: disconnect after 24s idle [13336.040035] Lustre: Skipped 1 previous similar message [13382.111415] Lustre: lustre-OST0000-osc-ffff8a15c9522800: disconnect after 24s idle [13382.113888] Lustre: Skipped 1 previous similar message [14644.466800] Lustre: DEBUG MARKER: == sanity test 134a: Server reclaims locks when reaching lock_reclaim_threshold ========================================================== 01:36:36 (1788759396) [14694.467519] Lustre: DEBUG MARKER: == sanity test 134b: Server rejects lock request when reaching lock_limit_mb ========================================================== 01:37:26 (1788759446) [14701.024821] Lustre: lustre-OST0000-osc-ffff8a15c9522800: disconnect after 20s idle [14701.033339] Lustre: Skipped 1 previous similar message [14743.256354] Lustre: DEBUG MARKER: == sanity test 134c: Lock memory accounting includes associated structures ========================================================== 01:38:15 (1788759495) [14762.685675] Lustre: DEBUG MARKER: SKIP: sanity test_135 skipping SLOW test 135 [14764.945267] Lustre: DEBUG MARKER: SKIP: sanity test_136 skipping SLOW test 136 [14767.219736] Lustre: DEBUG MARKER: == sanity test 140: Check reasonable stack depth (shouldn't LBUG) ============================================================== 01:38:38 (1788759518) [14817.766227] Lustre: DEBUG MARKER: == sanity test 150a: truncate/append tests =============== 01:39:29 (1788759569) [14838.245728] Lustre: Unmounted lustre-client [14839.097958] Lustre: Mounted lustre-client - version 2.17.58_40_g869f601 [14864.411200] Lustre: DEBUG MARKER: == sanity test 150b: Verify fallocate (prealloc) functionality ========================================================== 01:40:16 (1788759616) [14897.503564] Lustre: DEBUG MARKER: == sanity test 150bb: Verify fallocate modes both zero space ========================================================== 01:40:49 (1788759649) [14937.049617] Lustre: DEBUG MARKER: == sanity test 150c: Verify fallocate Size and Blocks ==== 01:41:29 (1788759689) [14958.307756] Lustre: DEBUG MARKER: == sanity test 150d: Verify fallocate Size and Blocks - Non zero start ========================================================== 01:41:50 (1788759710) [14978.761911] Lustre: DEBUG MARKER: == sanity test 150e: Verify 60% of available OST space consumed by fallocate ========================================================== 01:42:10 (1788759730) [15011.007565] Lustre: DEBUG MARKER: == sanity test 150f: Verify fallocate punch functionality ========================================================== 01:42:42 (1788759762) [15044.268407] Lustre: DEBUG MARKER: == sanity test 150g: Verify fallocate punch on large range ========================================================== 01:43:16 (1788759796) [15077.987039] Lustre: DEBUG MARKER: == sanity test 150h: Verify extend fallocate updates the file size ========================================================== 01:43:49 (1788759829) [15088.525806] Lustre: DEBUG MARKER: == sanity test 150ia: Verify fallocate zero-range ZERO functionality ========================================================== 01:44:00 (1788759840) [15109.730405] Lustre: DEBUG MARKER: == sanity test 150ib: Verify fallocate zero-range PREALLOC functionality ========================================================== 01:44:21 (1788759861) [15129.692631] Lustre: DEBUG MARKER: == sanity test 150ic: Verify fallocate LARGE zero PREALLOC functionality ========================================================== 01:44:41 (1788759881) [15131.328882] Lustre: DEBUG MARKER: SKIP: sanity test_150ic only check on DoM component [15133.386465] Lustre: DEBUG MARKER: == sanity test 150id: fallocate that fails must not leave a dirty page behind ========================================================== 01:44:45 (1788759885) [15813.599970] Lustre: DEBUG MARKER: == sanity test 151: test cache on oss and controls ========================================================================================= 01:56:05 (1788760565) [15844.009358] Lustre: DEBUG MARKER: == sanity test 152: test read/write with enomem ====================================================================================== 01:56:36 (1788760596) [15852.066942] Lustre: DEBUG MARKER: == sanity test 153: test if fdatasync does not crash ================================================================================= 01:56:44 (1788760604) [15859.179554] Lustre: DEBUG MARKER: == sanity test 154A: lfs path2fid and fid2path basic checks ========================================================== 01:56:51 (1788760611) [15868.546066] Lustre: DEBUG MARKER: == sanity test 154B: verify the ll_decode_linkea tool ==== 01:56:59 (1788760619) [15878.290551] Lustre: DEBUG MARKER: == sanity test 154C: lfs fid2path on OST FID ============= 01:57:10 (1788760630) [15903.621938] Lustre: DEBUG MARKER: == sanity test 154a: Open-by-FID ========================= 01:57:35 (1788760655) [15905.935256] LustreError: 298697:0:(lmv_fld.c:51:lmv_fld_lookup()) lustre-clilmv-ffff8a15f391c800: Error while looking for mds number. Seq 0xf00000400: rc = -2 [15907.704760] Lustre: dir [0x240000402:0x11b:0x0] stripe 0 readdir failed: -2, directory is partially accessed! [15915.644989] Lustre: DEBUG MARKER: == sanity test 154b: Open-by-FID for remote directory ==== 01:57:47 (1788760667) [15917.314809] LustreError: 299341:0:(lmv_fld.c:51:lmv_fld_lookup()) lustre-clilmv-ffff8a15f391c800: Error while looking for mds number. Seq 0xf00000400: rc = -2 [15917.325420] LustreError: 299341:0:(lmv_fld.c:51:lmv_fld_lookup()) Skipped 1 previous similar message [15925.906807] Lustre: DEBUG MARKER: == sanity test 154c: lfs path2fid and fid2path multiple arguments ========================================================== 01:57:58 (1788760678) [15934.649637] Lustre: DEBUG MARKER: == sanity test 154d: Verify open file fid ================ 01:58:06 (1788760686) [15944.506365] Lustre: DEBUG MARKER: == sanity test 154db: fid is stored in dir entries ======= 01:58:16 (1788760696) [15955.842894] Lustre: DEBUG MARKER: == sanity test 154e: .lustre is not returned by readdir == 01:58:27 (1788760707) [15962.201774] Lustre: DEBUG MARKER: == sanity test 154ea: .lustre is not returned by readdir (2) ========================================================== 01:58:34 (1788760714) [16028.582952] Lustre: DEBUG MARKER: == sanity test 154f: get parent fids by reading link ea == 01:59:40 (1788760780) [16042.889408] Lustre: DEBUG MARKER: == sanity test 154g: various llapi FID tests ============= 01:59:54 (1788760794) [17386.920775] Lustre: DEBUG MARKER: == sanity test 154h: Verify interactive path2fid ========= 02:22:18 (1788762138) [17395.080261] Lustre: DEBUG MARKER: == sanity test 154i: fid2path for path longer than PATH_MAX ========================================================== 02:22:26 (1788762146) [17439.929897] Lustre: DEBUG MARKER: == sanity test 154j: fid2path for long path crossing MDT boundary ========================================================== 02:23:11 (1788762191) [17468.550465] Lustre: DEBUG MARKER: == sanity test 155a: Verify small file correctness: read cache:on write_cache:on ========================================================== 02:23:39 (1788762219) [17483.242275] Lustre: DEBUG MARKER: == sanity test 155b: Verify small file correctness: read cache:on write_cache:off ========================================================== 02:23:54 (1788762234) [17501.222478] Lustre: DEBUG MARKER: == sanity test 155c: Verify small file correctness: read cache:off write_cache:on ========================================================== 02:24:13 (1788762253) [17518.166324] Lustre: DEBUG MARKER: == sanity test 155d: Verify small file correctness: read cache:off write_cache:off ========================================================== 02:24:29 (1788762269) [17533.570356] Lustre: DEBUG MARKER: == sanity test 155e: Verify big file correctness: read cache:on write_cache:on ========================================================== 02:24:45 (1788762285) [17590.019907] Lustre: DEBUG MARKER: == sanity test 155f: Verify big file correctness: read cache:on write_cache:off ========================================================== 02:25:41 (1788762341) [17643.151679] Lustre: DEBUG MARKER: == sanity test 155g: Verify big file correctness: read cache:off write_cache:on ========================================================== 02:26:34 (1788762394) [17693.654482] Lustre: DEBUG MARKER: == sanity test 155h: Verify big file correctness: read cache:off write_cache:off ========================================================== 02:27:25 (1788762445) [17746.240042] Lustre: DEBUG MARKER: == sanity test 156: Verification of tunables ============= 02:28:18 (1788762498) [17759.064101] Lustre: DEBUG MARKER: Turn on read and write cache [17764.106645] Lustre: DEBUG MARKER: Write data and read it back. [17766.035955] Lustre: DEBUG MARKER: Read should be satisfied from the cache. [17770.564937] Lustre: DEBUG MARKER: cache hits: before: 28721, after: 28724 [17772.329660] Lustre: DEBUG MARKER: Read again; it should be satisfied from the cache. [17774.939976] Lustre: DEBUG MARKER: cache hits:: before: 28724, after: 28727 [17777.005920] Lustre: DEBUG MARKER: Turn off the read cache and turn on the write cache [17781.468851] Lustre: DEBUG MARKER: Read again; it should be satisfied from the cache. [17785.733212] Lustre: DEBUG MARKER: cache hits:: before: 28727, after: 28730 [17787.491541] Lustre: DEBUG MARKER: Write data and read it back. [17789.237731] Lustre: DEBUG MARKER: Read should be satisfied from the cache. [17793.798894] Lustre: DEBUG MARKER: cache hits:: before: 28730, after: 28733 [17795.802862] Lustre: DEBUG MARKER: Turn off read and write cache [17799.887275] Lustre: DEBUG MARKER: Write data and read it back [17801.623696] Lustre: DEBUG MARKER: It should not be satisfied from the cache. [17808.020355] Lustre: DEBUG MARKER: cache hits:: before: 28733, after: 28733 [17809.774746] Lustre: DEBUG MARKER: Turn on the read cache and turn off the write cache [17814.618901] Lustre: DEBUG MARKER: Write data and read it back [17816.842496] Lustre: DEBUG MARKER: It should not be satisfied from the cache. [17822.238411] Lustre: DEBUG MARKER: cache hits:: before: 28733, after: 28733 [17824.177097] Lustre: DEBUG MARKER: Read again; it should be satisfied from the cache. [17829.925131] Lustre: DEBUG MARKER: cache hits:: before: 28733, after: 28736 [17841.311375] Lustre: DEBUG MARKER: == sanity test 157a: llapi pool pinning API tests ======== 02:29:52 (1788762592) [17849.993534] Lustre: DEBUG MARKER: == sanity test 157b: lustre.pin inheritance on create ==== 02:30:02 (1788762602) [17859.969261] Lustre: DEBUG MARKER: == sanity test 160a: changelog sanity ==================== 02:30:11 (1788762611) [17890.798524] Lustre: lustre-MDT0000-mdc-ffff8a15f391c800: Connection to lustre-MDT0000 (at 192.168.201.154@tcp) was lost; in progress operations using this service will wait for recovery to complete [17901.041056] LustreError: MGC192.168.201.154@tcp: Connection to MGS (at 192.168.201.154@tcp) was lost; in progress operations using this service will fail [17901.073839] Lustre: Evicted from MGS (at 192.168.201.154@tcp) after server handle changed from 0x35648f441e442780 to 0x35648f441e4ef949 [17901.104697] Lustre: MGC192.168.201.154@tcp: Connection restored to 192.168.201.154@tcp (at 192.168.201.154@tcp) [17901.143625] LustreError: 256679:0:(client.c:3449:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff8a15f4174000 x1875648599356416/t12884912529(12884912529) o101->lustre-MDT0000-mdc-ffff8a15f391c800@192.168.201.154@tcp:12/10 lens 912/608 e 0 to 0 dl 1788762670 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'bash.0' uid:0 gid:0 projid:0 [17901.654217] LustreError: 256679:0:(client.c:3449:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff8a15e5516a00 x1875648607062400/t12884930217(12884930217) o101->lustre-MDT0000-mdc-ffff8a15f391c800@192.168.201.154@tcp:12/10 lens 968/608 e 0 to 0 dl 1788762671 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'bash.0' uid:0 gid:0 projid:0 [17901.716806] LustreError: 256679:0:(client.c:3449:ptlrpc_replay_interpret()) Skipped 29 previous similar messages [17903.536419] Lustre: lustre-MDT0000-mdc-ffff8a15f391c800: Connection restored to 192.168.201.154@tcp (at 192.168.201.154@tcp) [17923.255146] Lustre: DEBUG MARKER: == sanity test 160b: Verify that very long rename doesn't crash in changelog ========================================================== 02:31:15 (1788762675) [17942.895245] Lustre: DEBUG MARKER: == sanity test 160c: verify that changelog log catch the truncate event ========================================================== 02:31:34 (1788762694) [17963.998628] Lustre: DEBUG MARKER: == sanity test 160d: verify that changelog log catch the migrate event ========================================================== 02:31:56 (1788762716) [17984.294688] Lustre: DEBUG MARKER: == sanity test 160e: changelog negative testing (should return errors) ========================================================== 02:32:16 (1788762736) [18008.272104] Lustre: DEBUG MARKER: == sanity test 160f: changelog garbage collect (timestamped users) ========================================================== 02:32:39 (1788762759) [18024.746248] Lustre: DEBUG MARKER: 1788762776: creating first dirs [18089.805673] Lustre: DEBUG MARKER: == sanity test 160g: changelog garbage collect on idle records ========================================================== 02:34:00 (1788762840) [18143.257456] Lustre: DEBUG MARKER: == sanity test 160h: changelog gc thread stop upon umount, orphan records delete ========================================================== 02:34:55 (1788762895) [18187.772439] Lustre: lustre-MDT0000-mdc-ffff8a15f391c800: Connection to lustre-MDT0000 (at 192.168.201.154@tcp) was lost; in progress operations using this service will wait for recovery to complete [18208.231657] LustreError: MGC192.168.201.154@tcp: Connection to MGS (at 192.168.201.154@tcp) was lost; in progress operations using this service will fail [18208.246883] Lustre: Evicted from MGS (at 192.168.201.154@tcp) after server handle changed from 0x35648f441e4ef949 to 0x35648f441e4f1201 [18208.264110] Lustre: MGC192.168.201.154@tcp: Connection restored to 192.168.201.154@tcp (at 192.168.201.154@tcp) [18217.579728] LustreError: 256679:0:(client.c:3449:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff8a15dd2ed500 x1875648607051008/t12884930187(12884930187) o101->lustre-MDT0000-mdc-ffff8a15f391c800@192.168.201.154@tcp:12/10 lens 968/608 e 0 to 0 dl 1788762987 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'bash.0' uid:0 gid:0 projid:0 [18217.605236] LustreError: 256679:0:(client.c:3449:ptlrpc_replay_interpret()) Skipped 40 previous similar messages [18229.421184] Lustre: lustre-MDT0000-mdc-ffff8a15f391c800: Connection restored to 192.168.201.154@tcp (at 192.168.201.154@tcp) [18260.665592] Lustre: DEBUG MARKER: == sanity test 160i: changelog user register/unregister race ========================================================== 02:36:52 (1788763012) [18301.087107] Lustre: DEBUG MARKER: == sanity test 160j: client can be umounted while its chanangelog is being used ========================================================== 02:37:33 (1788763053) [18301.970466] Lustre: Mounted lustre-client - version 2.17.58_40_g869f601 [18309.621350] Lustre: Unmounted lustre-client [18316.473142] Lustre: Mounted lustre-client - version 2.17.58_40_g869f601 [18323.536715] Lustre: Unmounted lustre-client [18325.612143] Lustre: DEBUG MARKER: == sanity test 160k: Verify that changelog records are not lost ========================================================== 02:37:57 (1788763077) [18357.191668] Lustre: DEBUG MARKER: == sanity test 160l: Verify that MTIME changelog records contain the parent FID ========================================================== 02:38:29 (1788763109) [18388.513098] Lustre: DEBUG MARKER: == sanity test 160m: Changelog clear race ================ 02:38:59 (1788763139) [18430.522482] Lustre: DEBUG MARKER: == sanity test 160n: Changelog destroy race ============== 02:39:41 (1788763181) [20469.368233] Lustre: DEBUG MARKER: == sanity test 160o: changelog user name and mask ======== 03:13:41 (1788765221) [20511.241909] Lustre: DEBUG MARKER: == sanity test 160p: Changelog orphan cleanup with no users ========================================================== 03:14:23 (1788765263) [20523.503434] Lustre: lustre-MDT0000-mdc-ffff8a15dd3a1800: Connection to lustre-MDT0000 (at 192.168.201.154@tcp) was lost; in progress operations using this service will wait for recovery to complete [20523.519685] Lustre: Skipped 1 previous similar message [20533.737197] LustreError: MGC192.168.201.154@tcp: Connection to MGS (at 192.168.201.154@tcp) was lost; in progress operations using this service will fail [20533.783839] Lustre: Evicted from MGS (at 192.168.201.154@tcp) after server handle changed from 0x35648f441e4f1201 to 0x35648f441e928d4b [20533.803899] Lustre: MGC192.168.201.154@tcp: Connection restored to 192.168.201.154@tcp (at 192.168.201.154@tcp) [20533.814466] Lustre: Skipped 1 previous similar message [20535.565971] Lustre: lustre-MDT0000-mdc-ffff8a15dd3a1800: Connection restored to 192.168.201.154@tcp (at 192.168.201.154@tcp) [20549.917944] Lustre: DEBUG MARKER: == sanity test 160q: changelog effective mask is DEFMASK if not set ========================================================== 03:15:01 (1788765301) [20563.578513] Lustre: DEBUG MARKER: == sanity test 160s: changelog garbage collect on idle records * time ========================================================== 03:15:15 (1788765315) [20605.327593] Lustre: DEBUG MARKER: == sanity test 160t: changelog garbage collect on lack of space ========================================================== 03:15:57 (1788765357) [20721.416384] Lustre: DEBUG MARKER: == sanity test 160u: changelog rename record type name and sname strings are correct ========================================================== 03:17:53 (1788765473) [20744.883183] Lustre: DEBUG MARKER: == sanity test 160v: setattr preserves mtime update despite inter-client clock skew ========================================================== 03:18:16 (1788765496) [20747.015780] Lustre: DEBUG MARKER: SKIP: sanity test_160v need >= 2 clients [20748.957549] Lustre: DEBUG MARKER: == sanity test 160w: lfs changelog --user --mask ========= 03:18:20 (1788765500) [20785.270521] Lustre: DEBUG MARKER: == sanity test 160x: changelog users do not disappear ==== 03:18:57 (1788765537) [20851.681985] Lustre: DEBUG MARKER: == sanity test 161a: link ea sanity ====================== 03:20:03 (1788765603) [20892.176919] Lustre: DEBUG MARKER: == sanity test 161b: link ea sanity under remote directory ========================================================== 03:20:43 (1788765643) [20935.907284] Lustre: DEBUG MARKER: == sanity test 161c: check CL_RENME[UNLINK] changelog record flags ========================================================== 03:21:28 (1788765688) [20965.596917] Lustre: DEBUG MARKER: == sanity test 161d: create with concurrent .lustre/fid access ========================================================== 03:21:57 (1788765717) [20977.115327] LustreError: 383654:0:(namei.c:1587:ll_create_node()) cfs_fail_timeout id 140c sleeping for 5000ms [20980.007263] LustreError: 383654:0:(namei.c:1587:ll_create_node()) cfs_fail_timeout interrupted [20998.242396] Lustre: DEBUG MARKER: == sanity test 162a: path lookup sanity ================== 03:22:29 (1788765749) [21008.634781] Lustre: DEBUG MARKER: == sanity test 162b: striped directory path lookup sanity ========================================================== 03:22:40 (1788765760) [21017.876597] Lustre: DEBUG MARKER: == sanity test 162c: fid2path works with paths 100 or more directories deep ========================================================== 03:22:49 (1788765769) [21141.565218] Lustre: DEBUG MARKER: == sanity test 165a: ofd access log discovery ============ 03:24:53 (1788765893) [21153.264924] Lustre: lustre-OST0000-osc-ffff8a15dd3a1800: Connection to lustre-OST0000 (at 192.168.201.154@tcp) was lost; in progress operations using this service will wait for recovery to complete [21183.194744] Lustre: DEBUG MARKER: == sanity test 165b: ofd access log entries are produced and consumed ========================================================== 03:25:35 (1788765935) [21219.823456] Lustre: lustre-OST0000-osc-ffff8a15dd3a1800: Connection to lustre-OST0000 (at 192.168.201.154@tcp) was lost; in progress operations using this service will wait for recovery to complete [21230.135050] Lustre: lustre-OST0000-osc-ffff8a15dd3a1800: Connection restored to 192.168.201.154@tcp (at 192.168.201.154@tcp) [21238.774824] Lustre: DEBUG MARKER: == sanity test 165c: full ofd access logs do not block IOs ========================================================== 03:26:30 (1788765990) [21270.021329] Lustre: lustre-OST0000-osc-ffff8a15dd3a1800: Connection to lustre-OST0000 (at 192.168.201.154@tcp) was lost; in progress operations using this service will wait for recovery to complete [21282.325257] Lustre: lustre-OST0000-osc-ffff8a15dd3a1800: Connection restored to 192.168.201.154@tcp (at 192.168.201.154@tcp) [21291.690922] Lustre: DEBUG MARKER: == sanity test 165d: ofd_access_log mask works =========== 03:27:23 (1788766043) [21336.551146] Lustre: lustre-OST0000-osc-ffff8a15dd3a1800: Connection to lustre-OST0000 (at 192.168.201.154@tcp) was lost; in progress operations using this service will wait for recovery to complete [21348.729558] Lustre: lustre-OST0000-osc-ffff8a15dd3a1800: Connection restored to 192.168.201.154@tcp (at 192.168.201.154@tcp) [21356.439692] Lustre: DEBUG MARKER: == sanity test 165e: ofd_access_log MDT index filter works ========================================================== 03:28:28 (1788766108) [21377.525358] Lustre: lustre-OST0000-osc-ffff8a15dd3a1800: Connection to lustre-OST0000 (at 192.168.201.154@tcp) was lost; in progress operations using this service will wait for recovery to complete [21388.662449] Lustre: lustre-OST0000-osc-ffff8a15dd3a1800: Connection restored to 192.168.201.154@tcp (at 192.168.201.154@tcp) [21398.388979] Lustre: DEBUG MARKER: == sanity test 165f: ofd_access_log_reader --exit-on-close works ========================================================== 03:29:09 (1788766149) [21408.235859] Lustre: lustre-OST0000-osc-ffff8a15dd3a1800: Connection to lustre-OST0000 (at 192.168.201.154@tcp) was lost; in progress operations using this service will wait for recovery to complete [21426.276677] Lustre: lustre-OST0000-osc-ffff8a15dd3a1800: Connection restored to 192.168.201.154@tcp (at 192.168.201.154@tcp) [21436.395648] Lustre: DEBUG MARKER: == sanity test 165g: ofd_access_log_reader --keepalive works ========================================================== 03:29:48 (1788766188) [21485.052606] Lustre: lustre-OST0000-osc-ffff8a15dd3a1800: Connection to lustre-OST0000 (at 192.168.201.154@tcp) was lost; in progress operations using this service will wait for recovery to complete [21503.868177] Lustre: lustre-OST0000-osc-ffff8a15dd3a1800: Connection restored to 192.168.201.154@tcp (at 192.168.201.154@tcp) [21515.433677] Lustre: DEBUG MARKER: == sanity test 169: parallel read and truncate should not deadlock ========================================================== 03:31:06 (1788766266) [21517.556563] Lustre: DEBUG MARKER: creating a 10 Mb file [21613.311357] Lustre: DEBUG MARKER: starting reads [21616.212531] Lustre: DEBUG MARKER: truncating the file [21618.583510] Lustre: DEBUG MARKER: killing dd [21620.205550] Lustre: DEBUG MARKER: removing the temporary file [21627.942858] Lustre: DEBUG MARKER: == sanity test 170a: test lctl df to handle corrupted log ========================================================== 03:32:59 (1788766379) [21628.167636] Lustre: debug daemon will attempt to start writing to /tmp/f170a.sanity_log_good (512000kB max) [21628.346943] Lustre: shutting down debug daemon thread... [21628.421951] Lustre: debug daemon will attempt to start writing to /tmp/f170a.sanity_log_good (512000kB max) [21628.553058] Lustre: shutting down debug daemon thread... [21637.250261] Lustre: DEBUG MARKER: == sanity test 170b: check filename encoding ============= 03:33:09 (1788766389) [21672.129843] Lustre: DEBUG MARKER: == sanity test 171: test libcfs_debug_dumplog_thread stuck in do_exit() ================================================================ 03:33:44 (1788766424) [21672.400424] LustreError: 398784:0:(file.c:513:ll_file_release()) cfs_fail_timeout id 50e sleeping for 3000ms [21675.431256] LustreError: 398784:0:(file.c:513:ll_file_release()) cfs_fail_timeout id 50e awake [21675.437435] LustreError: dumping log to /tmp/lustre-log.1788766429.398784 [21682.017383] Lustre: DEBUG MARKER: == sanity test 172: manual device removal with lctl cleanup/detach ================================================================ 03:33:53 (1788766433) [21684.658347] Lustre: *** cfs_fail_loc=60e, val=0*** [21684.661153] Lustre: Unmounted lustre-client [21691.181331] Lustre: Mounted lustre-client - version 2.17.58_40_g869f601 [21693.479951] Lustre: DEBUG MARKER: == sanity test 180a: test obdecho on osc ================= 03:34:05 (1788766445) [21696.179308] Lustre: DEBUG MARKER: SKIP: sanity test_180a obdecho on osc is no longer supported [21698.202391] Lustre: DEBUG MARKER: == sanity test 180b: test obdecho directly on obdfilter == 03:34:10 (1788766450) [21723.040889] Lustre: DEBUG MARKER: == sanity test 180c: test huge bulk I/O size on obdfilter, don't LASSERT ========================================================== 03:34:35 (1788766475) [21750.651907] Lustre: DEBUG MARKER: == sanity test 181: Test open-unlinked dir ================================================================================== 03:35:02 (1788766502) [21834.258779] Lustre: DEBUG MARKER: == sanity test 182a: Test parallel modify metadata operations from mdc ========================================================== 03:36:26 (1788766586) [21941.429881] Lustre: DEBUG MARKER: == sanity test 182b: Test parallel modify metadata operations from osp ========================================================== 03:38:13 (1788766693) [22712.421904] Lustre: DEBUG MARKER: == sanity test 183: No crash or request leak in case of strange dispositions ================================================================== 03:51:04 (1788767464) [22722.281922] Lustre: DEBUG MARKER: == sanity test 184a: Basic layout swap =================== 03:51:14 (1788767474) [22734.413347] Lustre: DEBUG MARKER: == sanity test 184b: Forbidden layout swap (will generate errors) ========================================================== 03:51:26 (1788767486) [22742.959232] Lustre: DEBUG MARKER: == sanity test 184c: Concurrent write and layout swap ==== 03:51:34 (1788767494) [22806.622890] Lustre: DEBUG MARKER: == sanity test 184d: allow stripeless layouts swap ======= 03:52:38 (1788767558) [22828.635804] Lustre: DEBUG MARKER: == sanity test 184e: Recreate layout after stripeless layout swaps ========================================================== 03:53:00 (1788767580) [22851.166713] Lustre: DEBUG MARKER: == sanity test 184f: IOC_MDC_GETFILEINFO for files with long names but no striping ========================================================== 03:53:22 (1788767602) [22861.209915] Lustre: DEBUG MARKER: == sanity test 185: Volatile file support ================ 03:53:32 (1788767612) [22873.601919] Lustre: DEBUG MARKER: == sanity test 185a: Volatile file creation in .lustre/fid/ ========================================================== 03:53:45 (1788767625) [22886.491371] Lustre: DEBUG MARKER: == sanity test 187a: Test data version change ============ 03:53:58 (1788767638) [22896.209379] Lustre: DEBUG MARKER: == sanity test 187b: Test data version change on volatile file ========================================================== 03:54:08 (1788767648) [22904.173251] Lustre: DEBUG MARKER: == sanity test 190a: check lfs project -p works with project name ========================================================== 03:54:16 (1788767656) [22912.198790] Lustre: DEBUG MARKER: == sanity test 190b: check lfs find --project works with project name ========================================================== 03:54:23 (1788767663) [22999.199628] Lustre: DEBUG MARKER: == sanity test 190c: check lfs project -p works with u:USERNAME ========================================================== 03:55:50 (1788767750) [23018.415870] Lustre: DEBUG MARKER: == sanity test complete, duration 22725 sec ============== 03:56:10 (1788767770) [23020.752416] Lustre: DEBUG MARKER: === sanity: start cleanup 03:56:12 (1788767772) === [23070.448585] Lustre: DEBUG MARKER: === sanity: finish cleanup 03:57:02 (1788767822) === [23073.190143] Lustre: Unmounted lustre-client [23130.765943] Key type lgssc unregistered [23131.053851] LNet: 430486:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [23131.066559] LNetError: 430486:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [23131.091356] LNet: Removed LNI 192.168.201.54@tcp [23132.112255] Key type .llcrypt unregistered [23132.119175] Key type ._llcrypt unregistered