[ 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 459793045 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.001022] APIC: Switch to symmetric I/O mode setup [ 0.003347] x2apic enabled [ 0.004009] Switched APIC routing to physical x2apic. [ 0.006010] kvm-guest: setup PV IPIs [ 0.009000] ..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.009021] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.010011] pid_max: default: 32768 minimum: 301 [ 0.011135] LSM: Security Framework initializing [ 0.012061] Yama: becoming mindful. [ 0.013037] SELinux: Initializing. [ 0.014000] *** VALIDATE selinux *** [ 0.021767] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.026531] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.027145] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.028109] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.029114] *** VALIDATE tmpfs *** [ 0.031389] *** VALIDATE proc *** [ 0.032281] *** VALIDATE cgroup *** [ 0.033011] *** VALIDATE cgroup2 *** [ 0.034247] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.035154] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.036006] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.037027] Spectre V2 : User space: Vulnerable [ 0.038009] Speculative Store Bypass: Vulnerable [ 0.040848] debug: unmapping init [mem 0xffffffff8fe59000-0xffffffff8fe60fff] [ 0.042974] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.043691] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.044022] ... version: 2 [ 0.045011] ... bit width: 48 [ 0.046012] ... generic registers: 4 [ 0.047012] ... value mask: 0000ffffffffffff [ 0.048015] ... max period: 00007fffffffffff [ 0.049014] ... fixed-purpose events: 3 [ 0.050012] ... event mask: 000000070000000f [ 0.051321] rcu: Hierarchical SRCU implementation. [ 0.053420] smp: Bringing up secondary CPUs ... [ 0.054622] x86: Booting SMP configuration: [ 0.055024] .... node #0, CPUs: #1 #2 #3 [ 0.058232] smp: Brought up 1 node, 4 CPUs [ 0.060012] smpboot: Max logical packages: 1 [ 0.061023] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.142646] node 0 deferred pages initialised in 78ms [ 0.145357] devtmpfs: initialized [ 0.146186] x86/mm: Memory block size: 128MB [ 0.148730] gcov: version magic: 0x41383552 [ 0.150326] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.151086] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.152219] pinctrl core: initialized pinctrl subsystem [ 0.153170] [ 0.153679] ************************************************************* [ 0.154011] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.155012] ** ** [ 0.156013] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.157013] ** ** [ 0.158014] ** This means that this kernel is built to expose internal ** [ 0.159013] ** IOMMU data structures, which may compromise security on ** [ 0.160013] ** your system. ** [ 0.161010] ** ** [ 0.162011] ** If you see this message and you are not debugging the ** [ 0.163015] ** kernel, report this immediately to your vendor! ** [ 0.164012] ** ** [ 0.165012] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.166013] ************************************************************* [ 0.167868] NET: Registered protocol family 16 [ 0.168451] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.169061] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.170058] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.172104] cpuidle: using governor menu [ 0.173782] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.176372] PCI: Using configuration type 1 for base access [ 0.178116] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.188053] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.190098] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.193073] cryptd: max_cpu_qlen set to 1000 [ 0.196197] ACPI: Added _OSI(Module Device) [ 0.197011] ACPI: Added _OSI(Processor Device) [ 0.199023] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.201018] ACPI: Added _OSI(Processor Aggregator Device) [ 0.206103] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.212595] ACPI: Interpreter enabled [ 0.213075] ACPI: PM: (supports S0 S3 S4 S5) [ 0.214028] ACPI: Using IOAPIC for interrupt routing [ 0.215182] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.218392] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.229069] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.231051] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.233020] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.236080] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.241390] acpiphp: Slot [2] registered [ 0.243117] acpiphp: Slot [5] registered [ 0.244118] acpiphp: Slot [6] registered [ 0.246120] acpiphp: Slot [3] registered [ 0.247120] acpiphp: Slot [4] registered [ 0.248087] acpiphp: Slot [7] registered [ 0.250086] acpiphp: Slot [8] registered [ 0.251122] acpiphp: Slot [9] registered [ 0.252111] acpiphp: Slot [10] registered [ 0.254107] acpiphp: Slot [11] registered [ 0.255093] acpiphp: Slot [12] registered [ 0.257099] acpiphp: Slot [13] registered [ 0.258097] acpiphp: Slot [14] registered [ 0.259150] acpiphp: Slot [15] registered [ 0.260126] acpiphp: Slot [16] registered [ 0.262100] acpiphp: Slot [17] registered [ 0.263145] acpiphp: Slot [18] registered [ 0.264075] acpiphp: Slot [19] registered [ 0.265089] acpiphp: Slot [20] registered [ 0.267103] acpiphp: Slot [21] registered [ 0.268139] acpiphp: Slot [22] registered [ 0.270078] acpiphp: Slot [23] registered [ 0.271091] acpiphp: Slot [24] registered [ 0.273117] acpiphp: Slot [25] registered [ 0.274098] acpiphp: Slot [26] registered [ 0.275171] acpiphp: Slot [27] registered [ 0.277130] acpiphp: Slot [28] registered [ 0.278195] acpiphp: Slot [29] registered [ 0.280107] acpiphp: Slot [30] registered [ 0.281124] acpiphp: Slot [31] registered [ 0.282121] PCI host bridge to bus 0000:00 [ 0.284025] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.286030] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.288028] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.290032] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.292028] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.295035] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.296198] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.300043] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.302290] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.309512] pci 0000:00:01.1: reg 0x20: [io 0xc120-0xc12f] [ 0.313071] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.317026] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.319023] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.321023] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.323655] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.326882] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.329051] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.331872] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.335795] pci 0000:00:02.0: reg 0x10: [io 0xc100-0xc11f] [ 0.344020] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.349019] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.355867] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.368020] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.377020] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.398017] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.407257] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.416018] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.422022] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.437977] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.448987] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.451422] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.453393] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.457349] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.458197] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.464052] iommu: Default domain type: Passthrough [ 0.466415] SCSI subsystem initialized [ 0.467139] ACPI: bus type USB registered [ 0.469135] usbcore: registered new interface driver usbfs [ 0.471076] usbcore: registered new interface driver hub [ 0.473100] usbcore: registered new device driver usb [ 0.475174] pps_core: LinuxPPS API ver. 1 registered [ 0.477011] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.480044] PTP clock support registered [ 0.482103] EDAC MC: Ver: 3.0.0 [ 0.485141] PCI: Using ACPI for IRQ routing [ 0.486702] NetLabel: Initializing [ 0.489011] NetLabel: domain hash size = 128 [ 0.490009] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.493077] NetLabel: unlabeled traffic allowed by default [ 0.496145] vgaarb: loaded [ 0.498184] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.500012] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.504326] clocksource: Switched to clocksource kvm-clock [ 0.608359] VFS: Disk quotas dquot_6.6.0 [ 0.609942] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.612544] *** VALIDATE ramfs *** [ 0.613878] *** VALIDATE hugetlbfs *** [ 0.615465] pnp: PnP ACPI init [ 0.617902] pnp: PnP ACPI: found 6 devices [ 0.638135] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.641390] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.643369] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.645482] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.647911] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.650401] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.653447] NET: Registered protocol family 2 [ 0.656068] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.661162] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.664824] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.669988] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.673388] TCP: Hash tables configured (established 65536 bind 65536) [ 0.676219] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.679089] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.681679] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.684347] NET: Registered protocol family 1 [ 0.686880] RPC: Registered named UNIX socket transport module. [ 0.688648] RPC: Registered udp transport module. [ 0.690204] RPC: Registered tcp transport module. [ 0.691656] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.693496] NET: Registered protocol family 44 [ 0.694822] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.696562] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.698314] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.700177] PCI: CLS 0 bytes, default 64 [ 0.701436] Unpacking initramfs... [ 2.117675] debug: unmapping init [mem 0xffff9a447cc64000-0xffff9a447ffcffff] [ 2.121557] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.123821] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.126337] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 2.659349] Initialise system trusted keyrings [ 2.661637] Key type blacklist registered [ 2.665634] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.680304] zbud: loaded [ 2.685437] *** VALIDATE nfs *** [ 2.687443] *** VALIDATE nfs4 *** [ 2.693955] pstore: using deflate compression [ 2.698414] Platform Keyring initialized [ 2.820432] NET: Registered protocol family 38 [ 2.822413] Key type asymmetric registered [ 2.823823] Asymmetric key parser 'x509' registered [ 2.825427] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 2.828513] io scheduler mq-deadline registered [ 2.830769] io scheduler kyber registered [ 2.832296] io scheduler bfq registered [ 2.834651] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 2.836741] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 2.840037] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 2.842913] ACPI: Power Button [PWRF] [ 2.850473] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 2.858716] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 2.871259] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 2.908560] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 2.943738] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 2.948108] Non-volatile memory driver v1.3 [ 2.949462] Linux agpgart interface v0.103 [ 2.983454] virtio_blk virtio1: [vda] 149768 512-byte logical blocks (76.7 MB/73.1 MiB) [ 2.986334] vda: detected capacity change from 0 to 76681216 [ 3.001662] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.004863] vdb: detected capacity change from 0 to 1073741824 [ 3.011494] libphy: Fixed MDIO Bus: probed [ 3.017242] usbcore: registered new interface driver usbserial_generic [ 3.020278] usbserial: USB Serial support registered for generic [ 3.023092] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.027902] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.029979] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.032698] mousedev: PS/2 mouse device common for all mice [ 3.035841] rtc_cmos 00:05: RTC can wake from S4 [ 3.038800] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.038928] rtc_cmos 00:05: registered as rtc0 [ 3.044239] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.045025] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.049584] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.050991] intel_pstate: CPU model not supported [ 3.057691] hid: raw HID events driver (C) Jiri Kosina [ 3.059808] usbcore: registered new interface driver usbhid [ 3.061599] usbhid: USB HID core driver [ 3.063247] drop_monitor: Initializing network drop monitor service [ 3.065527] Initializing XFRM netlink socket [ 3.067537] NET: Registered protocol family 10 [ 3.070847] Segment Routing with IPv6 [ 3.072401] NET: Registered protocol family 17 [ 3.075057] mpls_gso: MPLS GSO support [ 3.081865] RAS: Correctable Errors collector initialized. [ 3.084123] AVX version of gcm_enc/dec engaged. [ 3.086080] AES CTR mode by8 optimization enabled [ 3.177252] sched_clock: Marking stable (3177196029, 0)->(4111444101, -934248072) [ 3.181312] registered taskstats version 1 [ 3.185246] Loading compiled-in X.509 certificates [ 3.187138] zswap: loaded using pool lzo/zbud [ 3.211743] Key type big_key registered [ 3.223880] Key type encrypted registered [ 3.225273] ima: No TPM chip found, activating TPM-bypass! [ 3.226984] ima: Allocated hash algorithm: sha1 [ 3.228496] ima: No architecture policies found [ 3.230195] evm: Initialising EVM extended attributes: [ 3.232052] evm: security.selinux [ 3.233276] evm: security.ima [ 3.234371] evm: security.capability [ 3.235741] evm: HMAC attrs: 0x1 [ 3.239515] rtc_cmos 00:05: setting system clock to 2026-09-03 19:21:20 UTC (1788463280) [ 3.245928] debug: unmapping init [mem 0xffffffff90e03000-0xffffffff90ffffff] [ 3.248820] debug: unmapping init [mem 0xffffffff8fb82000-0xffffffff8fe58fff] [ 3.258107] Write protecting the kernel read-only data: 28672k [ 3.261396] debug: unmapping init [mem 0xffffffff8e203000-0xffffffff8e3fffff] [ 3.264063] debug: unmapping init [mem 0xffffffff8eb14000-0xffffffff8ebfffff] [ 3.313135] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 3.321294] systemd[1]: Detected virtualization kvm. [ 3.323505] systemd[1]: Detected architecture x86-64. [ 3.325077] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.348801] systemd[1]: No hostname configured. [ 3.350813] systemd[1]: Set hostname to . [ 3.354624] random: systemd: uninitialized urandom read (16 bytes read) [ 3.357093] systemd[1]: Initializing machine ID from random generator. [ 3.407666] random: ln: uninitialized urandom read (6 bytes read) [ 3.487534] random: systemd: uninitialized urandom read (16 bytes read) [ 3.489925] systemd[1]: Reached target Local File Systems. [ OK ] Reached target Local File Systems. [ 3.494825] systemd[1]: Listening on udev Kernel Socket. [ OK ] Listening on udev Kernel Socket. [ 3.500951] systemd[1]: Reached target Timers. [ OK ] Reached target Timers. [ OK ] Reached target Slices. [ OK ] Reached target Swap. [ OK ] Listening on Journal Socket (/dev/log). [ OK ] Listening on Journal Socket. [ OK ] Started Memstrack Anylazing Service. Starting Create Volatile Files and Directories... Starting Apply Kernel Variables... Starting Setup Virtual Console... Starting Create list of required st…ce nodes for the current kernel... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Paths. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Initrd Root Device. Starting Journal Service... [ OK ] Listening on udev Control Socket. [ OK ] Reached target Sockets. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Apply Kernel Variables. [ OK ] Started Setup Virtual Console. [ 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... [ 4.100117] device-mapper: uevent: version 1.0.3 [ 4.102152] 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. [ 4.668578] random: fast init done [ 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.823556] virtio_net virtio0 ens2: renamed from eth0 [ 4.954203] scsi host0: ata_piix [ 4.982241] scsi host1: ata_piix [ 4.983768] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc120 irq 14 [ 4.986033] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc128 irq 15 [ 9.294227] dracut-initqueue[589]: RTNETLINK answers: File exists [ 9.751091] random: crng init done [ 9.752623] 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... [ 10.139274] 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 target Timers. [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Initrd Default Target. [ 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 ] Stopped target Basic System. [ OK ] Stopped target Sockets. [ OK ] Stopped target Slices. [ OK ] Stopped target Paths. [ OK ] Stopped target System Initialization. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. [ OK ] Stopped target Swap. [ OK ] Stopped target Local File Systems. Stopping udev Kernel Device Manager... [ OK ] Started Cleaning Up and Shutting Down Daemons. [ 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.367931] printk: systemd: 26 output lines suppressed due to ratelimiting [ 11.634549] SELinux: Disabled at runtime. [ 11.697586] 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.706688] systemd[1]: Detected virtualization kvm. [ 11.708615] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 12.229601] systemd[1]: initrd-switch-root.service: Succeeded. [ 12.232624] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 12.237343] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 12.242314] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 12.246309] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 12.256828] systemd[1]: Starting Journal Service... Starting Journal Service... [ 12.264234] systemd[1]: Starting Create list of required static device nodes for the current kernel... Starting Create list of required st…ce nodes for the current kernel... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Listening on udev Kernel Socket. Mounting Huge Pages File System... Mounting Kernel Debug File System... [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Reached target Paths. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Reached target rpc_pipefs.target. [ OK ] Created slice User and Session Slice. [ OK ] Reached target Slices. Activating swap /dev/disk/by-label/SWAP... Starting Apply Kernel Variables... [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd File Systems. [ 12.347708] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS Starting Remount Root and Kernel File Systems... [ OK ] Listening on udev Control Socket. Starting udev Coldplug all Devices... [ OK ] Reached target RPC Port Mapper. [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Stopped target Initrd Root File System. Mounting POSIX Message Queue File System... [ OK ] Created slice system-getty.slice. [ OK ] Listening on Process Core Dump Socket. [ 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 ] Started Journal Service. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Mounted Huge Pages File System. [ OK ] Mounted Kernel Debug File System. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Started Apply Kernel Variables. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Mounted POSIX Message Queue File System. Starting Configure read-only root support... [ OK ] Reached target Swap. Starting Create Static Device Nodes in /dev... 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 /home/green/git/lustre-release... Mounting /mnt... [ OK ] Started udev Coldplug all Devices. [ OK ] Mounted /mnt. [ 12.754814] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 13.557099] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 13.622523] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 13.930137] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 13.959773] EDAC sbridge: Ver: 1.1.2 [ 17.497064] Key type dns_resolver registered [ 18.164137] NFS: Registering the id_resolver key type [ 18.165991] Key type id_resolver registered [ 18.167674] Key type id_legacy registered [ 18.191428] hrtimer: interrupt took 3994897 ns [* ] A start job is running for Configur…-only root support (6s / no limit) [ 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 Create Volatile Files and Directories... Starting Load/Save Random Seed... [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Load/Save Random Seed. [ OK ] Started Create Volatile Files and Directories. Starting RPC Bind... Starting Update UTMP about System Boot/Shutdown... [ OK ] Started 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 ] Reached target Basic System. Starting Restore /run/initramfs on shutdown... Starting Login Service... [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Started dnf makecache --timer. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Started D-Bus System Message Bus. Starting Network Manager... [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Reached target Timers. [ OK ] Started irqbalance daemon. [ OK ] Reached target sshd-keygen.target. [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Login Service. [ OK ] Started Network Manager. [ OK ] Reached target Network. Starting OpenSSH server daemon... Starting Dynamic System Tuning Daemon... Starting GSSAPI Proxy Daemon... Starting Network Manager Wait Online... [ OK ] Started OpenSSH server daemon. Starting Hostname Service... [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... [ OK ] Started Permit User Sessions. [ OK ] Started Serial Getty on ttyS1. [ OK ] Started Getty on tty1. [ OK ] Started Serial Getty on ttyS0. [ OK ] Reached target Login Prompts. [ OK ] Started Command Scheduler. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting Crash recovery kernel arming... Starting System Logging Service... Starting Notify NFS peers of a restart... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg603-client login: [ 77.648393] libcfs: loading out-of-tree module taints kernel. [ 77.790445] Key type ._llcrypt registered [ 77.794550] Key type .llcrypt registered [ 78.293453] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [ 78.315427] alg: No test for adler32 (adler32-zlib) [ 79.852763] Lustre: Lustre: Build Version: 2.17.58_2_gdacfdd2 [ 81.044986] LNet: Added LNI 192.168.206.3@tcp [8/256/0/180] [ 82.960153] Key type lgssc registered [ 84.971911] Lustre: Echo OBD driver; http://www.lustre.org/ [ 214.801789] Lustre: Mounted lustre-client - version 2.17.58_2_gdacfdd2 [ 220.674261] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 238.921641] Lustre: DEBUG MARKER: oleg603-client.virtnet: executing check_logdir /tmp/testlogs/ [ 240.608355] Lustre: lustre-OST0000-osc-ffff9a44c5288800: disconnect after 23s idle [ 245.283544] Lustre: DEBUG MARKER: oleg603-client.virtnet: executing yml_node [ 249.813562] Lustre: DEBUG MARKER: Client: 2.17.58.2 [ 252.616656] Lustre: DEBUG MARKER: MDS: 2.17.58.2 [ 254.926396] Lustre: DEBUG MARKER: OSS: 2.17.58.2 [ 256.586540] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity ============----- Thu Sep 3 15:25:32 EDT 2026 [ 274.161131] Lustre: DEBUG MARKER: - need MDS1_VERSION <= 2.16.61-1-g89cf292a8c2 (34683394 <= 34618625) for LU-18938, skip 360 [ 276.323394] Lustre: DEBUG MARKER: - need MDS1_VERSION < v2_14_55-100-g8a84c7f9c7 (34683394 < 34486116) for LU-14927, skip 0f [ 277.554039] Lustre: DEBUG MARKER: - need OST1_VERSION < v2_17_50-410-gbd8e7b9555 (34683394 < 34681754) for LU-12550, skip 216 [ 279.934192] Lustre: DEBUG MARKER: excepting tests: 42a 42c 42b 118c 118d 407 119i 216 817 411a 130b 130c 130d 130e 130f 130g [ 281.374050] Lustre: DEBUG MARKER: skipping tests SLOW=no: 27m 60i 64b 68 71 135 136 230d 300o 842 51b 51c 51e 834 [ 283.298986] Lustre: DEBUG MARKER: === sanity: start setup 15:25:58 (1788463558) === [ 289.798951] Lustre: DEBUG MARKER: oleg603-client.virtnet: executing check_config_client /mnt/lustre [ 307.746473] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 318.386464] Lustre: DEBUG MARKER: === sanity: finish setup 15:26:34 (1788463594) === [ 326.707211] Lustre: DEBUG MARKER: == sanity test 60a: llog_test run from kernel module and test llog_reader ========================================================== 15:26:41 (1788463601) [ 331.860349] Lustre: DEBUG MARKER: SKIP: sanity test_60a missing subtest run-llog.sh [ 334.381353] Lustre: DEBUG MARKER: == sanity test 60b: limit repeated messages from CERROR/CWARN ========================================================== 15:26:49 (1788463609) [ 343.010675] Lustre: lustre-OST0000-osc-ffff9a44c5288800: disconnect after 24s idle [ 343.027174] Lustre: Skipped 1 previous similar message [ 344.622399] Lustre: DEBUG MARKER: == sanity test 60c: unlink file when mds full ============ 15:27:00 (1788463620) [ 541.215467] Lustre: DEBUG MARKER: == sanity test 60d: test printk console message masking == 15:30:17 (1788463817) [ 541.349528] Lustre: DEBUG MARKER: test message ID 15229 7648 [ 547.160845] Lustre: DEBUG MARKER: == sanity test 60e: no space while new llog is being created ========================================================== 15:30:22 (1788463822) [ 555.419110] Lustre: DEBUG MARKER: == sanity test 60f: change debug_path works ============== 15:30:31 (1788463831) [ 555.878353] LustreError: dumping log to /tmp/f60f.sanity.1788463833.13921 [ 564.543961] Lustre: DEBUG MARKER: == sanity test 60g: transaction abort won't cause MDT hung ========================================================== 15:30:39 (1788463839) [ 676.869798] Lustre: DEBUG MARKER: == sanity test 60h: striped directory with missing stripes can be accessed ========================================================== 15:32:32 (1788463952) [ 678.712351] Lustre: DEBUG MARKER: SKIP: sanity test_60h Need at least 2 MDTs [ 680.268655] Lustre: DEBUG MARKER: SKIP: sanity test_60i skipping SLOW test 60i [ 682.113428] Lustre: DEBUG MARKER: == sanity test 60j: llog_reader reports corruptions ====== 15:32:37 (1788463957) [ 684.100404] Lustre: DEBUG MARKER: SKIP: sanity test_60j ldiskfs only test [ 685.950292] Lustre: DEBUG MARKER: == sanity test 61a: mmap() writes don't make sync hang ========================================================================== 15:32:41 (1788463961) [ 693.807912] Lustre: DEBUG MARKER: == sanity test 61b: mmap() of unstriped file is successful ========================================================== 15:32:49 (1788463969) [ 703.478739] Lustre: DEBUG MARKER: == sanity test 63a: Verify oig_wait interruption does not crash ================================================================= 15:32:58 (1788463978) [ 773.455928] Lustre: DEBUG MARKER: == sanity test 63b: async write errors should be returned to fsync ============================================================= 15:34:09 (1788464049) [ 775.067774] Lustre: *** cfs_fail_loc=406, val=0*** [ 775.080038] LustreError: 20831:0:(osc_request.c:2918:osc_build_rpc()) lustre-OST0000-osc-ffff9a44c5288800: prep_req failed: rc = -12 [ 775.096386] LustreError: 20831:0:(osc_cache.c:2419:osc_check_rpcs()) Write request failed with -12 [ 787.602217] Lustre: DEBUG MARKER: == sanity test 63c: test sync_on_close=1 ================= 15:34:23 (1788464063) [ 800.323352] LNet: 21647:0:(debug.c:375:cfs_str2mask()) unknown mask 'entry'. [ 800.323352] mask usage: [+|-] ... [ 811.634410] Lustre: DEBUG MARKER: == sanity test 64a: verify filter grant calculations (in kernel) =============================================================== 15:34:47 (1788464087) [ 820.075577] Lustre: DEBUG MARKER: SKIP: sanity test_64b skipping SLOW test 64b [ 821.983393] Lustre: DEBUG MARKER: == sanity test 64c: verify grant shrink ================== 15:34:57 (1788464097) [ 831.576691] Lustre: DEBUG MARKER: == sanity test 64d: check grant limit exceed ============= 15:35:07 (1788464107) [ 898.388821] Lustre: DEBUG MARKER: == sanity test 64e: check grant consumption (no grant allocation) ========================================================== 15:36:13 (1788464173) [ 903.060250] Lustre: Unmounted lustre-client [ 903.538932] Lustre: Mounted lustre-client - version 2.17.58_2_gdacfdd2 [ 909.084064] Lustre: Unmounted lustre-client [ 909.706838] Lustre: Mounted lustre-client - version 2.17.58_2_gdacfdd2 [ 920.770737] Lustre: DEBUG MARKER: == sanity test 64f: check grant consumption (with grant allocation) ========================================================== 15:36:36 (1788464196) [ 922.693075] Lustre: Unmounted lustre-client [ 923.061506] Lustre: Mounted lustre-client - version 2.17.58_2_gdacfdd2 [ 926.607367] Lustre: Unmounted lustre-client [ 927.181782] Lustre: Mounted lustre-client - version 2.17.58_2_gdacfdd2 [ 936.042948] Lustre: DEBUG MARKER: == sanity test 64g: grant shrink on MDT ================== 15:36:51 (1788464211) [ 966.488520] Lustre: DEBUG MARKER: == sanity test 64h: grant shrink on read ================= 15:37:22 (1788464242) [ 986.917643] Lustre: DEBUG MARKER: == sanity test 64i: shrink on reconnect ================== 15:37:43 (1788464263) [ 998.886078] Lustre: lustre-OST0000-osc-ffff9a44c9754000: Connection to lustre-OST0000 (at 192.168.206.103@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1012.192168] Lustre: 2351:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788464273/real 1788464273] req@ffff9a43fc7daa00 x1875339760582144/t0(0) o17->lustre-OST0000-osc-ffff9a44c9754000@192.168.206.103@tcp:28/4 lens 456/432 e 0 to 1 dl 1788464289 ref 1 fl Rpc:XQr/200/ffffffff rc 0/-1 job:'lctl.0' uid:0 gid:0 projid:4294967295 [ 1033.962825] Lustre: DEBUG MARKER: oleg603-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 1035.723474] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 1049.399072] Lustre: DEBUG MARKER: == sanity test 64j: check grants on re-done rpc ========== 15:38:45 (1788464325) [ 1050.988644] LustreError: 2351:0:(osc_request.c:2451:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff9a43fc7d8a80 x1875339760593536/t0(0) o4->lustre-OST0000-osc-ffff9a44c9754000@192.168.206.103@tcp:6/4 lens 4584/448 e 0 to 0 dl 1788464344 ref 2 fl Interpret:RMQU/600/0 rc -5/-5 job:'multiop.0' uid:0 gid:0 projid:0 [ 1061.275555] Lustre: DEBUG MARKER: == sanity test 65a: directory with no stripe info ======== 15:38:57 (1788464337) [ 1068.363198] Lustre: DEBUG MARKER: == sanity test 65b: directory setstripe -S stripe_size*2 -i 0 -c 1 ========================================================== 15:39:04 (1788464344) [ 1074.959919] Lustre: DEBUG MARKER: == sanity test 65c: directory setstripe -S stripe_size*4 -i 1 -c 1 ========================================================== 15:39:10 (1788464350) [ 1083.644697] Lustre: DEBUG MARKER: == sanity test 65d: directory setstripe -S stripe_size -c stripe_count ========================================================== 15:39:18 (1788464358) [ 1091.177334] Lustre: DEBUG MARKER: == sanity test 65e: directory setstripe defaults ========= 15:39:27 (1788464367) [ 1098.638114] Lustre: DEBUG MARKER: == sanity test 65f: dir setstripe permission (should return error) ============================================================= 15:39:34 (1788464374) [ 1106.771613] Lustre: DEBUG MARKER: == sanity test 65g: directory setstripe -d =============== 15:39:42 (1788464382) [ 1114.178631] Lustre: DEBUG MARKER: == sanity test 65h: directory stripe info inherit ============================================================================== 15:39:49 (1788464389) [ 1120.171050] Lustre: DEBUG MARKER: == sanity test 65i: various tests to set root directory striping ========================================================== 15:39:56 (1788464396) [ 1127.212493] Lustre: DEBUG MARKER: == sanity test 65j: set default striping on root directory (bug 6367)=========================================================== 15:40:03 (1788464403) [ 1134.129176] Lustre: DEBUG MARKER: == sanity test 65k: validate manual striping works properly with deactivated OSCs ========================================================== 15:40:10 (1788464410) [ 1230.863308] Lustre: DEBUG MARKER: == sanity test 65l: lfs find on -1 stripe dir ================================================================================== 15:41:46 (1788464506) [ 1237.361793] Lustre: DEBUG MARKER: == sanity test 65m: normal user can't set filesystem default stripe ========================================================== 15:41:53 (1788464513) [ 1243.183886] Lustre: DEBUG MARKER: == sanity test 65n: don't inherit default layout from root for new subdirectories ========================================================== 15:41:58 (1788464518) [ 1253.712996] Lustre: DEBUG MARKER: SKIP: sanity test_65n needs >= 2 MDTs [ 1268.742953] Lustre: DEBUG MARKER: == sanity test 65o: pool inheritance for mdt component === 15:42:24 (1788464544) [ 1295.714488] Lustre: DEBUG MARKER: == sanity test 65p: setstripe with yaml file and huge number ========================================================== 15:42:51 (1788464571) [ 1303.241885] Lustre: DEBUG MARKER: == sanity test 65q: setstripe with >=8E offset should fail ========================================================== 15:42:58 (1788464578) [ 1310.488980] Lustre: DEBUG MARKER: == sanity test 65r: prevent all-zero offsets ============= 15:43:05 (1788464585) [ 1318.823859] Lustre: DEBUG MARKER: == sanity test 66: update inode blocks count on client ========================================================================= 15:43:14 (1788464594) [ 1335.560421] Lustre: DEBUG MARKER: == sanity test 69: verify oa2dentry return -ENOENT doesn't LBUG ================================================================ 15:43:30 (1788464610) [ 1353.436844] Lustre: DEBUG MARKER: == sanity test 70a: verify health_check, health_write don't explode (on OST) ========================================================== 15:43:48 (1788464628) [ 1371.398562] Lustre: DEBUG MARKER: SKIP: sanity test_71 skipping SLOW test 71 [ 1373.904964] Lustre: DEBUG MARKER: == sanity test 72a: Test that remove suid works properly (bug5695) ============================================================== 15:44:09 (1788464649) [ 1384.603666] Lustre: DEBUG MARKER: == sanity test 72b: Test that we keep mode setting if without file data changed (bug 24226) ========================================================== 15:44:20 (1788464660) [ 1400.465933] Lustre: DEBUG MARKER: == sanity test 73: multiple MDC requests (should not deadlock) ========================================================== 15:44:34 (1788464674) [ 1436.165436] Lustre: DEBUG MARKER: == sanity test 74a: ldlm_enqueue freed-export error path, ls (shouldn't LBUG) ========================================================== 15:45:11 (1788464711) [ 1443.677795] Lustre: DEBUG MARKER: == sanity test 74b: ldlm_enqueue freed-export error path, touch (shouldn't LBUG) ========================================================== 15:45:19 (1788464719) [ 1451.226743] Lustre: DEBUG MARKER: == sanity test 74c: ldlm_lock_create error path, (shouldn't LBUG) ========================================================== 15:45:26 (1788464726) [ 1451.390861] Lustre: *** cfs_fail_loc=319, val=0*** [ 1457.787211] Lustre: DEBUG MARKER: == sanity test 76a: confirm clients recycle inodes properly ============================================================== 15:45:33 (1788464733) [ 1539.170033] Lustre: DEBUG MARKER: == sanity test 76b: confirm clients recycle directory inodes properly ============================================================== 15:46:54 (1788464814) [ 1592.287063] Lustre: DEBUG MARKER: == sanity test 77a: normal checksum read/write operation ========================================================== 15:47:47 (1788464867) [ 1601.417345] Lustre: DEBUG MARKER: == sanity test 77b: checksum error on client write, read ========================================================== 15:47:56 (1788464876) [ 1601.747788] Lustre: *** cfs_fail_loc=409, val=0*** [ 1601.971526] LustreError: lustre-OST0001-osc-ffff9a44c9754000: BAD WRITE CHECKSUM: changed on the client after we checksummed it - likely false positive due to mmap IO (bug 11742): from 192.168.206.103@tcp inode [0x200000406:0xc33:0x0] object 0x280000400:3788 extent [0-1048575], original client csum f2d712a3 (type 10), server csum f2d712a2 (type 10), client csum now f2d712a2 [ 1602.022237] LustreError: 2351:0:(osc_request.c:2451:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff9a44fecc9f80 x1875339763791744/t4294971527(4294971527) o4->lustre-OST0001-osc-ffff9a44c9754000@192.168.206.103@tcp:6/4 lens 488/448 e 0 to 0 dl 1788464895 ref 3 fl Interpret:RQU/604/0 rc 0/0 job:'dd.0' uid:0 gid:0 projid:0 [ 1607.014643] Lustre: DEBUG MARKER: set checksum type to crc32, rc = 0 [ 1607.329559] Lustre: *** cfs_fail_loc=408, val=0*** [ 1607.342258] LustreError: lustre-OST0001-osc-ffff9a44c9754000: BAD READ CHECKSUM: from 192.168.206.103@tcp inode [0x200000406:0xc33:0x0] object 0x280000400:3788 extent [0-1048575], client fe1725ac/fe1725ac, server c6de6416, cksum_type 1 [ 1607.361863] LustreError: 2349:0:(osc_request.c:2451:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff9a44f6300e00 x1875339763794432/t0(0) o3->lustre-OST0001-osc-ffff9a44c9754000@192.168.206.103@tcp:6/4 lens 488/440 e 0 to 0 dl 1788464900 ref 2 fl Interpret:RMQU/600/0 rc 1048576/1048576 job:'cmp.0' uid:0 gid:0 projid:0 [ 1611.238192] Lustre: DEBUG MARKER: set checksum type to adler, rc = 0 [ 1611.784789] Lustre: *** cfs_fail_loc=408, val=0*** [ 1611.797667] LustreError: lustre-OST0001-osc-ffff9a44c9754000: BAD READ CHECKSUM: from 192.168.206.103@tcp inode [0x200000406:0xc33:0x0] object 0x280000400:3788 extent [1048576-2097151], client fc61f833/fc61f833, server b998f8ff, cksum_type 2 [ 1611.834219] LustreError: 2352:0:(osc_request.c:2451:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff9a44ed7df100 x1875339763797120/t0(0) o3->lustre-OST0001-osc-ffff9a44c9754000@192.168.206.103@tcp:6/4 lens 488/440 e 0 to 0 dl 1788464904 ref 2 fl Interpret:RMQU/600/0 rc 1048576/1048576 job:'cmp.0' uid:0 gid:0 projid:0 [ 1615.781334] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 1616.270178] Lustre: *** cfs_fail_loc=408, val=0*** [ 1616.296200] LustreError: lustre-OST0001-osc-ffff9a44c9754000: BAD READ CHECKSUM: from 192.168.206.103@tcp inode [0x200000406:0xc33:0x0] object 0x280000400:3788 extent [0-1048575], client adf3d5d6/adf3d5d6, server 48f4835c, cksum_type 4 [ 1616.317258] LustreError: 2351:0:(osc_request.c:2451:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff9a44ed7ded80 x1875339763799552/t0(0) o3->lustre-OST0001-osc-ffff9a44c9754000@192.168.206.103@tcp:6/4 lens 488/440 e 0 to 0 dl 1788464909 ref 2 fl Interpret:RMQU/600/0 rc 1048576/1048576 job:'cmp.0' uid:0 gid:0 projid:0 [ 1620.255239] Lustre: DEBUG MARKER: set checksum type to t10ip512, rc = 0 [ 1620.666105] Lustre: *** cfs_fail_loc=408, val=0*** [ 1620.681921] LustreError: lustre-OST0001-osc-ffff9a44c9754000: BAD READ CHECKSUM: from 192.168.206.103@tcp inode [0x200000406:0xc33:0x0] object 0x280000400:3788 extent [1048576-2097151], client 3affa3d/3affa3d, server 2449fb6f, cksum_type 10 [ 1624.617503] Lustre: DEBUG MARKER: set checksum type to t10ip4K, rc = 0 [ 1625.211638] LustreError: lustre-OST0001-osc-ffff9a44c9754000: BAD READ CHECKSUM: from 192.168.206.103@tcp inode [0x200000406:0xc33:0x0] object 0x280000400:3788 extent [0-1048575], client 89a9fae2/89a9fae2, server 5824fa49, cksum_type 20 [ 1625.238156] LustreError: 2352:0:(osc_request.c:2451:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff9a44feccbb80 x1875339763803648/t0(0) o3->lustre-OST0001-osc-ffff9a44c9754000@192.168.206.103@tcp:6/4 lens 488/440 e 0 to 0 dl 1788464918 ref 2 fl Interpret:RMQU/600/0 rc 1048576/1048576 job:'cmp.0' uid:0 gid:0 projid:0 [ 1625.261960] LustreError: 2352:0:(osc_request.c:2451:osc_brw_redo_request()) Skipped 1 previous similar message [ 1629.059845] Lustre: DEBUG MARKER: set checksum type to t10crc512, rc = 0 [ 1629.501509] Lustre: *** cfs_fail_loc=408, val=0*** [ 1629.504210] Lustre: Skipped 1 previous similar message [ 1633.459934] Lustre: DEBUG MARKER: set checksum type to t10crc4K, rc = 0 [ 1633.749811] LustreError: lustre-OST0001-osc-ffff9a44c9754000: BAD READ CHECKSUM: from 192.168.206.103@tcp inode [0x200000406:0xc33:0x0] object 0x280000400:3788 extent [0-1048575], client 760fff42/760fff42, server ec30fe7d, cksum_type 80 [ 1633.758970] LustreError: Skipped 1 previous similar message [ 1637.176883] Lustre: DEBUG MARKER: set checksum type to t10ip512, rc = 0 [ 1644.413527] Lustre: DEBUG MARKER: == sanity test 77c: checksum error on client read with debug ========================================================== 15:48:40 (1788464920) [ 1648.875565] Lustre: *** cfs_fail_loc=408, val=0*** [ 1648.878247] Lustre: Skipped 1 previous similar message [ 1648.884255] Lustre: 2352:0:(osc_request.c:2035:dump_all_bulk_pages()) /tmp/lustre-log-checksum_dump-osc-[0x200000406:0xc34:0x0]:[0-1048575]-92f3123c-f2d712a2: dumping checksum data [ 1648.897463] LustreError: dumping log to /tmp/lustre-log.1788464926.2352 [ 1651.776720] LustreError: lustre-OST0000-osc-ffff9a44c9754000: BAD READ CHECKSUM: from 192.168.206.103@tcp inode [0x200000406:0xc34:0x0] object 0x240000400:3798 extent [0-1048575], client 92f3123c/92f3123c, server f2d712a2, cksum_type 10 [ 1651.790845] LustreError: 2352:0:(osc_request.c:2451:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff9a44ed7ddf80 x1875339763814272/t0(0) o3->lustre-OST0000-osc-ffff9a44c9754000@192.168.206.103@tcp:6/4 lens 488/440 e 0 to 0 dl 1788464942 ref 2 fl Interpret:RMQU/600/0 rc 1048576/1048576 job:'dd.0' uid:0 gid:0 projid:0 [ 1651.823561] LustreError: 2352:0:(osc_request.c:2451:osc_brw_redo_request()) Skipped 2 previous similar messages [ 1686.939162] Lustre: DEBUG MARKER: == sanity test 77d: checksum error on OST direct write, read ========================================================== 15:49:22 (1788464962) [ 1687.528332] Lustre: *** cfs_fail_loc=409, val=0*** [ 1687.564754] LustreError: 2348:0:(osc_request.c:1024:osc_init_grant()) lustre-OST0000-osc-ffff9a44c9754000: granted 3407872 but already consumed 13631488 [ 1687.984604] LustreError: lustre-OST0000-osc-ffff9a44c9754000: BAD WRITE CHECKSUM: changed on the client after we checksummed it - likely false positive due to mmap IO (bug 11742): from 192.168.206.103@tcp inode [0x200000406:0xc36:0x0] object 0x240000400:3799 extent [0-1048575], original client csum 3dbc503e (type 10), server csum 3dbc503d (type 10), client csum now 3dbc503d [ 1688.035262] LustreError: 2349:0:(osc_request.c:2451:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff9a44f6301180 x1875339763819776/t8589936191(8589936191) o4->lustre-OST0000-osc-ffff9a44c9754000@192.168.206.103@tcp:6/4 lens 488/448 e 0 to 0 dl 1788464980 ref 2 fl Interpret:RMQU/600/0 rc 0/0 job:'directio.0' uid:0 gid:0 projid:0 [ 1689.960443] LustreError: lustre-OST0000-osc-ffff9a44c9754000: BAD READ CHECKSUM: from 192.168.206.103@tcp inode [0x200000406:0xc36:0x0] object 0x240000400:3799 extent [0-1048575], client 4e6150ce/4e6150ce, server 3dbc503d, cksum_type 10 [ 1697.473981] Lustre: DEBUG MARKER: == sanity test 77f: repeat checksum error on write (expect error) ========================================================== 15:49:33 (1788464973) [ 1699.378751] Lustre: DEBUG MARKER: set checksum type to crc32, rc = 0 [ 1699.760932] LustreError: 2348:0:(osc_request.c:1024:osc_init_grant()) lustre-OST0001-osc-ffff9a44c9754000: granted 3407872 but already consumed 13631488 [ 1700.029350] LustreError: lustre-OST0001-osc-ffff9a44c9754000: BAD WRITE CHECKSUM: changed in transit before arrival at OST: from 192.168.206.103@tcp inode [0x200000406:0xc37:0x0] object 0x280000400:3789 extent [0-1048575], original client csum b2f1b12 (type 1), server csum b2f1b11 (type 1), client csum now b2f1b12 [ 1700.065348] LustreError: Skipped 2 previous similar messages [ 1701.263368] LustreError: 2350:0:(osc_request.c:2608:brw_interpret()) lustre-OST0001-osc-ffff9a44c9754000: too many resent retries for object: 10737419264:3789: rc = -11 [ 1703.339807] Lustre: DEBUG MARKER: set checksum type to adler, rc = 0 [ 1703.860956] LustreError: lustre-OST0000-osc-ffff9a44c9754000: BAD WRITE CHECKSUM: changed in transit before arrival at OST: from 192.168.206.103@tcp inode [0x200000406:0xc38:0x0] object 0x240000400:3800 extent [2097152-3145727], original client csum 19eeae62 (type 2), server csum 19eeae61 (type 2), client csum now 19eeae62 [ 1703.905697] LustreError: Skipped 13 previous similar messages [ 1705.170521] LustreError: 2352:0:(osc_request.c:2608:brw_interpret()) lustre-OST0000-osc-ffff9a44c9754000: too many resent retries for object: 9663677440:3800: rc = -11 [ 1705.184392] LustreError: 2352:0:(osc_request.c:2608:brw_interpret()) Skipped 7 previous similar messages [ 1706.674418] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 1708.453172] LustreError: lustre-OST0001-osc-ffff9a44c9754000: BAD WRITE CHECKSUM: changed in transit before arrival at OST: from 192.168.206.103@tcp inode [0x200000406:0xc39:0x0] object 0x280000400:3790 extent [3145728-4194303], original client csum b5ea7f3c (type 4), server csum b5ea7f3b (type 4), client csum now b5ea7f3c [ 1708.475555] LustreError: Skipped 23 previous similar messages [ 1708.478948] LustreError: 2351:0:(osc_request.c:2608:brw_interpret()) lustre-OST0001-osc-ffff9a44c9754000: too many resent retries for object: 10737419264:3790: rc = -11 [ 1708.486602] LustreError: 2351:0:(osc_request.c:2608:brw_interpret()) Skipped 7 previous similar messages [ 1710.147685] Lustre: DEBUG MARKER: set checksum type to t10ip512, rc = 0 [ 1711.819096] LustreError: 2352:0:(osc_request.c:2608:brw_interpret()) lustre-OST0000-osc-ffff9a44c9754000: too many resent retries for object: 9663677440:3801: rc = -11 [ 1711.831156] LustreError: 2352:0:(osc_request.c:2608:brw_interpret()) Skipped 7 previous similar messages [ 1713.777689] Lustre: DEBUG MARKER: set checksum type to t10ip4K, rc = 0 [ 1715.819660] LustreError: 2351:0:(osc_request.c:2608:brw_interpret()) lustre-OST0001-osc-ffff9a44c9754000: too many resent retries for object: 10737419264:3791: rc = -11 [ 1715.826606] LustreError: 2351:0:(osc_request.c:2608:brw_interpret()) Skipped 11 previous similar messages [ 1717.263127] Lustre: DEBUG MARKER: set checksum type to t10crc512, rc = 0 [ 1718.142147] LustreError: lustre-OST0000-osc-ffff9a44c9754000: BAD WRITE CHECKSUM: changed in transit before arrival at OST: from 192.168.206.103@tcp inode [0x200000406:0xc3c:0x0] object 0x240000400:3802 extent [1048576-2097151], original client csum 887488b6 (type 40), server csum 887488b5 (type 40), client csum now 887488b6 [ 1718.200027] LustreError: Skipped 40 previous similar messages [ 1721.291606] Lustre: DEBUG MARKER: set checksum type to t10crc4K, rc = 0 [ 1732.623484] Lustre: DEBUG MARKER: set checksum type to t10ip512, rc = 0 [ 1734.102840] Lustre: DEBUG MARKER: == sanity test 77g: checksum error on OST write, read ==== 15:50:10 (1788465010) [ 1736.513666] LustreError: lustre-OST0000-osc-ffff9a44c9754000: BAD WRITE CHECKSUM: changed in transit before arrival at OST: from 192.168.206.103@tcp inode [0x200000406:0xc3e:0x0] object 0x240000400:3803 extent [0-1048575], original client csum f2d712a2 (type 10), server csum d55ed67 (type 10), client csum now f2d712a2 [ 1736.529452] LustreError: Skipped 30 previous similar messages [ 1751.114374] Lustre: DEBUG MARKER: == sanity test 77k: enable/disable checksum correctly ==== 15:50:26 (1788465026) [ 1756.346049] Lustre: Unmounted lustre-client [ 1756.831544] Lustre: Mounted lustre-client - version 2.17.58_2_gdacfdd2 [ 1762.483031] Lustre: Unmounted lustre-client [ 1762.997338] Lustre: Mounted lustre-client - version 2.17.58_2_gdacfdd2 [ 1767.306935] Lustre: Unmounted lustre-client [ 1767.766597] Lustre: Mounted lustre-client - version 2.17.58_2_gdacfdd2 [ 1769.629815] Lustre: Unmounted lustre-client [ 1770.134228] Lustre: Mounted lustre-client - version 2.17.58_2_gdacfdd2 [ 1782.103664] Lustre: DEBUG MARKER: == sanity test 77l: preferred checksum type is remembered after reconnected ========================================================== 15:50:57 (1788465057) [ 1783.875575] Lustre: DEBUG MARKER: set checksum type to invalid, rc = 22 [ 1785.630787] Lustre: DEBUG MARKER: set checksum type to crc32, rc = 0 [ 1793.815664] Lustre: DEBUG MARKER: oleg603-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff9a44fecd8800.ost_server_uuid 50 [ 1796.669372] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9a44fecd8800.ost_server_uuid in IDLE state after 0 sec [ 1806.748791] Lustre: DEBUG MARKER: oleg603-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9a44fecd8800.ost_server_uuid 50 [ 1809.000716] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9a44fecd8800.ost_server_uuid in FULL state after 0 sec [ 1812.383858] Lustre: DEBUG MARKER: set checksum type to adler, rc = 0 [ 1823.540134] Lustre: DEBUG MARKER: oleg603-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff9a44fecd8800.ost_server_uuid 50 [ 1827.329287] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9a44fecd8800.ost_server_uuid in IDLE state after 1 sec [ 1834.806124] Lustre: DEBUG MARKER: oleg603-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9a44fecd8800.ost_server_uuid 50 [ 1836.349691] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9a44fecd8800.ost_server_uuid in FULL state after 0 sec [ 1837.976694] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 1844.396967] Lustre: DEBUG MARKER: oleg603-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff9a44fecd8800.ost_server_uuid 50 [ 1851.417504] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9a44fecd8800.ost_server_uuid in IDLE state after 5 sec [ 1859.411892] Lustre: DEBUG MARKER: oleg603-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9a44fecd8800.ost_server_uuid 50 [ 1862.436920] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9a44fecd8800.ost_server_uuid in FULL state after 0 sec [ 1864.564254] Lustre: DEBUG MARKER: set checksum type to t10ip512, rc = 0 [ 1871.852934] Lustre: DEBUG MARKER: oleg603-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff9a44fecd8800.ost_server_uuid 50 [ 1877.376049] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9a44fecd8800.ost_server_uuid in IDLE state after 3 sec [ 1883.932276] Lustre: DEBUG MARKER: oleg603-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9a44fecd8800.ost_server_uuid 50 [ 1886.542408] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9a44fecd8800.ost_server_uuid in FULL state after 0 sec [ 1888.800801] Lustre: DEBUG MARKER: set checksum type to t10ip4K, rc = 0 [ 1896.019706] Lustre: DEBUG MARKER: oleg603-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff9a44fecd8800.ost_server_uuid 50 [ 1901.976660] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9a44fecd8800.ost_server_uuid in IDLE state after 4 sec [ 1908.230797] Lustre: DEBUG MARKER: oleg603-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9a44fecd8800.ost_server_uuid 50 [ 1910.147891] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9a44fecd8800.ost_server_uuid in FULL state after 0 sec [ 1911.969888] Lustre: DEBUG MARKER: set checksum type to t10crc512, rc = 0 [ 1918.274638] Lustre: DEBUG MARKER: oleg603-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff9a44fecd8800.ost_server_uuid 50 [ 1928.153118] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9a44fecd8800.ost_server_uuid in IDLE state after 8 sec [ 1934.642669] Lustre: DEBUG MARKER: oleg603-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9a44fecd8800.ost_server_uuid 50 [ 1935.765832] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9a44fecd8800.ost_server_uuid in FULL state after 0 sec [ 1937.741859] Lustre: DEBUG MARKER: set checksum type to t10crc4K, rc = 0 [ 1945.281851] Lustre: DEBUG MARKER: oleg603-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff9a44fecd8800.ost_server_uuid 50 [ 1953.324573] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9a44fecd8800.ost_server_uuid in IDLE state after 6 sec [ 1960.624774] Lustre: DEBUG MARKER: oleg603-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9a44fecd8800.ost_server_uuid 50 [ 1962.254989] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9a44fecd8800.ost_server_uuid in FULL state after 0 sec [ 1969.850893] Lustre: DEBUG MARKER: set checksum type to t10ip512, rc = 0 [ 1971.541901] Lustre: DEBUG MARKER: == sanity test 77m: Verify checksum_speed is correctly read ========================================================== 15:54:07 (1788465247) [ 1977.917336] Lustre: DEBUG MARKER: == sanity test 77n: Verify read from a hole inside contiguous blocks with T10PI ========================================================== 15:54:13 (1788465253) [ 1979.859877] Lustre: DEBUG MARKER: SKIP: sanity test_77n f77n.sanity blocks not contiguous around hole [ 1981.750453] Lustre: DEBUG MARKER: == sanity test 77o: Verify checksum_type for server (mdt and ofd(obdfilter)) ========================================================== 15:54:17 (1788465257) [ 1994.184373] Lustre: DEBUG MARKER: == sanity test 78: handle large O_DIRECT writes correctly ====================================================================== 15:54:29 (1788465269) [ 2005.967267] Lustre: DEBUG MARKER: == sanity test 79: df report consistency check =========== 15:54:41 (1788465281) [ 2026.788914] Lustre: DEBUG MARKER: == sanity test 80: Page eviction is equally fast at high offsets too ========================================================== 15:55:02 (1788465302) [ 2035.651606] Lustre: DEBUG MARKER: == sanity test 81a: OST should retry write when get -ENOSPC ========================================================================= 15:55:11 (1788465311) [ 2044.224461] Lustre: DEBUG MARKER: == sanity test 81b: OST should return -ENOSPC when retry still fails ================================================================= 15:55:19 (1788465319) [ 2053.823380] Lustre: DEBUG MARKER: == sanity test 99: cvs strange file/directory operations ========================================================== 15:55:29 (1788465329) [ 2084.311540] Lustre: DEBUG MARKER: == sanity test 100: check local port using privileged port ========================================================== 15:56:00 (1788465360) [ 2092.906295] Lustre: DEBUG MARKER: == sanity test 101a: check read-ahead for random reads === 15:56:08 (1788465368) [ 2279.957908] Lustre: DEBUG MARKER: == sanity test 101b: check stride-io mode read-ahead =========================================================================== 15:59:16 (1788465556) [ 2315.261047] Lustre: DEBUG MARKER: == sanity test 101c: check stripe_size aligned read-ahead ========================================================== 15:59:51 (1788465591) [ 2395.697695] Lustre: DEBUG MARKER: == sanity test 101d: file read with and without read-ahead enabled ========================================================== 16:01:11 (1788465671) [ 2710.498118] Lustre: DEBUG MARKER: == sanity test 101e: check read-ahead for small read(1k) for small files(500k) ========================================================== 16:06:25 (1788465985) [ 2802.241789] Lustre: DEBUG MARKER: == sanity test 101f: check mmap read performance ========= 16:07:58 (1788466078) [ 2814.931721] Lustre: DEBUG MARKER: == sanity test 101g: Big bulk(4/16 MiB) readahead ======== 16:08:10 (1788466090) [ 2823.635538] Lustre: Unmounted lustre-client [ 2823.646096] Lustre: Skipped 1 previous similar message [ 2824.202322] Lustre: Mounted lustre-client - version 2.17.58_2_gdacfdd2 [ 2824.207474] Lustre: Skipped 1 previous similar message [ 2864.566513] Lustre: Unmounted lustre-client [ 2865.030650] Lustre: Mounted lustre-client - version 2.17.58_2_gdacfdd2 [ 2908.027159] Lustre: DEBUG MARKER: == sanity test 101h: Readahead should cover current read window ========================================================== 16:09:43 (1788466183) [ 2926.504692] Lustre: DEBUG MARKER: == sanity test 101i: allow current readahead to exceed reservation ========================================================== 16:10:02 (1788466202) [ 2938.927667] Lustre: DEBUG MARKER: == sanity test 101j: A complete read block should be submitted when no RA ========================================================== 16:10:14 (1788466214) [ 2999.059814] Lustre: DEBUG MARKER: == sanity test 101m: read ahead for small file and last stripe of the file ========================================================== 16:11:14 (1788466274) [ 3001.524220] Lustre: DEBUG MARKER: SKIP: sanity test_101m fallocate not supported [ 3003.450433] Lustre: DEBUG MARKER: == sanity test 102a: user xattr test ============================================================================================ 16:11:19 (1788466279) [ 3010.283841] Lustre: DEBUG MARKER: == sanity test 102b: getfattr/setfattr for trusted.lov EAs ========================================================== 16:11:26 (1788466286) [ 3020.869870] Lustre: DEBUG MARKER: == sanity test 102c: non-root getfattr/setfattr for lustre.lov EAs ===================================================================== 16:11:36 (1788466296) [ 3027.681712] Lustre: DEBUG MARKER: == sanity test 102d: tar restore stripe info from tarfile,not keep osts ========================================================== 16:11:43 (1788466303) [ 3043.856436] Lustre: DEBUG MARKER: == sanity test 102f: tar copy files, not keep osts ======= 16:11:59 (1788466319) [ 3062.503426] Lustre: DEBUG MARKER: == sanity test 102h: grow xattr from inside inode to external block ========================================================== 16:12:18 (1788466338) [ 3065.138437] Lustre: DEBUG MARKER: save trusted.big on /mnt/lustre/f102h.sanity [ 3066.931740] Lustre: DEBUG MARKER: save trusted.sml on /mnt/lustre/f102h.sanity [ 3068.447478] Lustre: DEBUG MARKER: grow trusted.sml on /mnt/lustre/f102h.sanity [ 3070.365262] Lustre: DEBUG MARKER: trusted.big still valid after growing trusted.sml [ 3077.071392] Lustre: DEBUG MARKER: == sanity test 102ha: grow xattr from inside inode to external inode ========================================================== 16:12:32 (1788466352) [ 3079.747440] Lustre: DEBUG MARKER: save trusted.big on /mnt/lustre/f102ha.sanity [ 3081.660366] Lustre: DEBUG MARKER: save trusted.sml on /mnt/lustre/f102ha.sanity [ 3083.776317] Lustre: DEBUG MARKER: grow trusted.sml on /mnt/lustre/f102ha.sanity [ 3085.751249] Lustre: DEBUG MARKER: trusted.big still valid after growing trusted.sml [ 3087.807415] Lustre: DEBUG MARKER: save trusted.big on /mnt/lustre/f102ha.sanity [ 3096.316166] Lustre: DEBUG MARKER: == sanity test 102i: lgetxattr test on symbolic link ====================================================================== 16:12:51 (1788466371) [ 3102.949099] Lustre: DEBUG MARKER: == sanity test 102j: non-root tar restore stripe info from tarfile, not keep osts ============================================================= 16:12:59 (1788466379) [ 3117.631791] Lustre: DEBUG MARKER: == sanity test 102k: setfattr without parameter of value shouldn't cause a crash ========================================================== 16:13:13 (1788466393) [ 3124.224858] Lustre: DEBUG MARKER: == sanity test 102l: listxattr size test ============================================================================================ 16:13:20 (1788466400) [ 3130.455229] Lustre: DEBUG MARKER: == sanity test 102m: Ensure listxattr fails on small bufffer ================================================================== 16:13:26 (1788466406) [ 3136.799172] Lustre: DEBUG MARKER: == sanity test 102n: silently ignore setxattr on internal trusted xattrs ========================================================== 16:13:32 (1788466412) [ 3144.479809] Lustre: DEBUG MARKER: == sanity test 102p: check setxattr(2) correctly fails without permission ========================================================== 16:13:40 (1788466420) [ 3151.006822] Lustre: DEBUG MARKER: == sanity test 102q: flistxattr should not return trusted.link EAs for orphans ========================================================== 16:13:46 (1788466426) [ 3157.614968] Lustre: DEBUG MARKER: == sanity test 102r: set EAs with empty values =========== 16:13:53 (1788466433) [ 3164.465146] Lustre: DEBUG MARKER: == sanity test 102s: getting nonexistent xattrs should fail ========================================================== 16:14:00 (1788466440) [ 3171.540207] Lustre: DEBUG MARKER: == sanity test 102t: zero length xattr values handled correctly ========================================================== 16:14:07 (1788466447) [ 3178.779401] Lustre: DEBUG MARKER: == sanity test 103a: acl test ============================ 16:14:14 (1788466454) [ 3457.933470] Lustre: DEBUG MARKER: == sanity test 103b: umask lfs setstripe ================= 16:18:53 (1788466733) [ 3616.208633] Lustre: DEBUG MARKER: == sanity test 103c: 'cp -rp' won't set empty acl ======== 16:21:32 (1788466892) [ 3624.493744] Lustre: DEBUG MARKER: == sanity test 103e: inheritance of big amount of default ACLs ========================================================== 16:21:40 (1788466900) [ 3652.707310] Lustre: DEBUG MARKER: == sanity test 103f: changelog doesn't interfere with default ACLs buffers ========================================================== 16:22:08 (1788466928) [ 3664.901181] Lustre: DEBUG MARKER: == sanity test 103g: no MDS_GETXATTR storm for inodes without ACL_ACCESS (LU-17238) ========================================================== 16:22:20 (1788466940) [ 3671.942254] Lustre: DEBUG MARKER: == sanity test 104a: lfs df [-ih] [path] test =================================================================================== 16:22:28 (1788466948) [ 3672.473631] Lustre: setting import lustre-OST0000_UUID INACTIVE by administrator request [ 3672.536088] Lustre: lustre-OST0000-osc-ffff9a44c3312800: Connection to lustre-OST0000 (at 192.168.206.103@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 3672.569372] LustreError: lustre-OST0000-osc-ffff9a44c3312800: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 3677.602671] Lustre: DEBUG MARKER: oleg603-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0000-osc-ffff9a44c3312800.ost_server_uuid 50 [ 3678.850436] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9a44c3312800.ost_server_uuid in FULL state after 0 sec [ 3684.247300] Lustre: DEBUG MARKER: == sanity test 104b: runas -u 500 -g 500 lfs check servers test ============================================================================== 16:22:40 (1788466960) [ 3689.634740] Lustre: DEBUG MARKER: == sanity test 104c: Verify df vs lfs_df stays same after recordsize change ========================================================== 16:22:45 (1788466965) [ 3706.816204] Lustre: DEBUG MARKER: == sanity test 104d: runas -u 500 -g 500 lctl dl test ==== 16:23:02 (1788466982) [ 3712.154356] Lustre: DEBUG MARKER: == sanity test 105a: flock when mounted without -o flock test ================================================================== 16:23:08 (1788466988) [ 3717.450968] Lustre: DEBUG MARKER: == sanity test 105b: fcntl when mounted without -o flock test ================================================================== 16:23:13 (1788466993) [ 3723.154400] Lustre: DEBUG MARKER: == sanity test 105c: lockf when mounted without -o flock test ========================================================== 16:23:19 (1788466999) [ 3728.628708] Lustre: DEBUG MARKER: == sanity test 105d: flock race (should not freeze) ================================================================== 16:23:24 (1788467004) [ 3728.911131] LustreError: 111820:0:(ldlm_flock.c:850:ldlm_flock_completion_ast()) cfs_fail_timeout id 315 sleeping for 10000ms [ 3739.010469] LustreError: 111820:0:(ldlm_flock.c:850:ldlm_flock_completion_ast()) cfs_fail_timeout id 315 awake [ 3746.046040] Lustre: DEBUG MARKER: == sanity test 105e: Two conflicting flocks from same process ========================================================== 16:23:41 (1788467021) [ 3753.485833] Lustre: DEBUG MARKER: == sanity test 105f: Enqueue same range flocks =========== 16:23:49 (1788467029) [ 3762.054812] Lustre: DEBUG MARKER: == sanity test 105g: ldlm_lock_debug stack test ========== 16:23:57 (1788467037) [ 3762.371707] Lustre: *** cfs_fail_loc=32f, val=0*** [ 3762.377902] LustreError: 113629:0:(ldlm_flock.c:802:ldlm_flock_completion_ast()) ### Test ldlm error stack ns: lustre-MDT0000-mdc-ffff9a44c3312800 lock: ffff9a43c555c800/0x54557291cc6dd096 lrc: 4/0,1 mode: PW/PW res: [0x200000409:0xb6a:0x0].0xc rrc: 2 type: FLK pid: 113628 [0->9223372036854775807] flags: 0x0 nid: local remote: 0x4ce47c24e3ccc0ea expref: -99 pid: 113629 timeout: 0 [ 3762.414455] CPU: 1 PID: 113629 Comm: flocks_test Kdump: loaded Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 3762.423911] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.17.0-10.fc44 06/10/2025 [ 3762.431050] Call Trace: [ 3762.433428] ? dump_stack+0xbb/0x10e [ 3762.436026] ? ldlm_flock_completion_ast.cold.17+0xd/0x27 [ptlrpc] [ 3762.439557] ? _raw_spin_unlock+0x12/0x30 [ 3762.441281] ? unlock_res_and_lock+0x23/0x30 [ptlrpc] [ 3762.446351] ? ldlm_lock_enqueue+0x3a1/0xcd0 [ptlrpc] [ 3762.451268] ? ldlm_cli_enqueue_fini+0xadc/0x1500 [ptlrpc] [ 3762.454498] ? ldlm_cli_enqueue+0x47f/0xe40 [ptlrpc] [ 3762.458258] ? ldlm_flock_completion_ast_async+0xb30/0xb30 [ptlrpc] [ 3762.462422] ? mdc_changelog_cdev_finish+0x2c0/0x2c0 [mdc] [ 3762.466422] ? mdc_enqueue_base+0x456/0x1dd0 [mdc] [ 3762.471286] ? mdc_enqueue+0x1c/0x30 [mdc] [ 3762.474228] ? lmv_enqueue+0x28a/0x530 [lmv] [ 3762.475809] ? ll_file_flock+0x962/0x1420 [lustre] [ 3762.485719] ? ldlm_flock_completion_ast_async+0xb30/0xb30 [ptlrpc] [ 3762.490335] ? mdc_changelog_cdev_finish+0x2c0/0x2c0 [mdc] [ 3762.497043] ? filemap_map_pages+0x3f8/0x770 [ 3762.499252] ? slab_post_alloc_hook+0x66/0x380 [ 3762.503565] ? locks_alloc_lock+0x1f/0x90 [ 3762.504703] ? kmem_cache_alloc+0x184/0x430 [ 3762.510388] ? vfs_lock_file+0x22/0x50 [ 3762.515007] ? fcntl_setlk+0xde/0x4e0 [ 3762.518712] ? __might_sleep+0x59/0xc0 [ 3762.520035] ? do_fcntl+0x7da/0xb80 [ 3762.521009] ? __x64_sys_fcntl+0xc4/0x110 [ 3762.523515] ? do_syscall_64+0xc1/0x440 [ 3762.525411] ? entry_SYSCALL_64_after_hwframe+0x49/0xae [ 3769.740289] Lustre: DEBUG MARKER: == sanity test 105h: Flock functional verify ============= 16:24:05 (1788467045) [ 3776.336862] Lustre: DEBUG MARKER: == sanity test 105i: Flock deadlock verify =============== 16:24:12 (1788467052) [ 3781.560577] LustreError: lustre-MDT0000-mdc-ffff9a44c3312800: operation ldlm_enqueue to node 192.168.206.103@tcp failed: rc = -35 [ 3788.166646] Lustre: DEBUG MARKER: == sanity test 106: attempt exec of dir followed by chown of that dir ========================================================== 16:24:23 (1788467063) [ 3793.951349] Lustre: DEBUG MARKER: == sanity test 107: Coredump on SIG ====================== 16:24:29 (1788467069) [ 3802.127549] Lustre: DEBUG MARKER: == sanity test 110: filename length checking ============= 16:24:38 (1788467078) [ 3809.273862] Lustre: DEBUG MARKER: == sanity test 116a: stripe QOS: free space balance ============================================================================= 16:24:44 (1788467084) [ 3998.504893] Lustre: DEBUG MARKER: sanity test_116a: @@@@@@ IGNORE (LU-9): stripe QOS didn't balance free space [ 4045.454280] Lustre: DEBUG MARKER: == sanity test 116b: QoS shouldn't LBUG if not enough OSTs found on the 2nd pass ========================================================== 16:28:41 (1788467321) [ 4055.707598] Lustre: DEBUG MARKER: == sanity test 117: verify osd extend ==================== 16:28:51 (1788467331) [ 4061.542124] Lustre: DEBUG MARKER: == sanity test 118a: verify O_SYNC works ================= 16:28:57 (1788467337) [ 4066.833392] Lustre: DEBUG MARKER: == sanity test 118b: Reclaim dirty pages on fatal error ==================================================================== 16:29:03 (1788467343) [ 4074.352458] Lustre: DEBUG MARKER: SKIP: sanity test_118c skipping ALWAYS excluded test 118c [ 4075.854538] Lustre: DEBUG MARKER: SKIP: sanity test_118d skipping ALWAYS excluded test 118d [ 4077.183818] Lustre: DEBUG MARKER: == sanity test 118f: Simulate unrecoverable OSC side error ==================================================================== 16:29:13 (1788467353) [ 4077.681736] Lustre: *** cfs_fail_loc=40a, val=0*** [ 4077.685395] Lustre: Skipped 225 previous similar messages [ 4077.691048] LustreError: 123572:0:(osc_request.c:2918:osc_build_rpc()) lustre-OST0001-osc-ffff9a44c3312800: prep_req failed: rc = -22 [ 4077.704763] LustreError: 123572:0:(osc_cache.c:2419:osc_check_rpcs()) Write request failed with -22 [ 4083.760577] Lustre: DEBUG MARKER: == sanity test 118g: Don't stay in wait if we got local -ENOMEM ==================================================================== 16:29:19 (1788467359) [ 4084.185532] LustreError: 124160:0:(osc_request.c:2918:osc_build_rpc()) lustre-OST0000-osc-ffff9a44c3312800: prep_req failed: rc = -12 [ 4084.195582] LustreError: 124160:0:(osc_cache.c:2419:osc_check_rpcs()) Write request failed with -12 [ 4090.219858] Lustre: DEBUG MARKER: == sanity test 118h: Verify timeout in handling recoverables errors ==================================================================== 16:29:26 (1788467366) [ 4091.970343] LustreError: lustre-OST0001-osc-ffff9a44c3312800: operation ost_write to node 192.168.206.103@tcp failed: rc = -5 [ 4091.982900] LustreError: 2352:0:(osc_request.c:2451:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff9a43ed873b80 x1875339779154176/t0(0) o4->lustre-OST0001-osc-ffff9a44c3312800@192.168.206.103@tcp:6/4 lens 4584/224 e 0 to 0 dl 1788467385 ref 2 fl Interpret:RMQU/600/0 rc -5/-5 job:'multiop.0' uid:0 gid:0 projid:0 [ 4092.000432] LustreError: 2352:0:(osc_request.c:2451:osc_brw_redo_request()) Skipped 59 previous similar messages [ 4093.045758] LustreError: lustre-OST0001-osc-ffff9a44c3312800: operation ost_write to node 192.168.206.103@tcp failed: rc = -5 [ 4095.082229] LustreError: lustre-OST0001-osc-ffff9a44c3312800: operation ost_write to node 192.168.206.103@tcp failed: rc = -5 [ 4102.192816] LustreError: lustre-OST0001-osc-ffff9a44c3312800: operation ost_write to node 192.168.206.103@tcp failed: rc = -5 [ 4102.200666] LustreError: Skipped 1 previous similar message [ 4102.208678] LustreError: 2352:0:(osc_request.c:2608:brw_interpret()) lustre-OST0001-osc-ffff9a44c3312800: too many resent retries for object: 10737419264:6306: rc = -5 [ 4102.219863] LustreError: 2352:0:(osc_request.c:2608:brw_interpret()) Skipped 18 previous similar messages [ 4102.226214] Lustre: 2352:0:(llite_lib.c:4341:ll_dirty_page_discard_warn()) lustre: dirty page discard: 192.168.206.103@tcp:/lustre/fid: [0x200000409:0xf51:0x0]// may get corrupted (rc -5) [ 4109.440438] Lustre: DEBUG MARKER: == sanity test 118i: Fix error before timeout in recoverable error ==================================================================== 16:29:45 (1788467385) [ 4111.262272] LustreError: lustre-OST0001-osc-ffff9a44c3312800: operation ost_write to node 192.168.206.103@tcp failed: rc = -5 [ 4111.270216] LustreError: 2349:0:(osc_request.c:2451:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff9a43f0f14700 x1875339779162112/t0(0) o4->lustre-OST0001-osc-ffff9a44c3312800@192.168.206.103@tcp:6/4 lens 4584/224 e 0 to 0 dl 1788467404 ref 2 fl Interpret:RMQU/600/0 rc -5/-5 job:'multiop.0' uid:0 gid:0 projid:0 [ 4111.293725] LustreError: 2349:0:(osc_request.c:2451:osc_brw_redo_request()) Skipped 3 previous similar messages [ 4127.535550] Lustre: DEBUG MARKER: == sanity test 118j: Simulate unrecoverable OST side error ==================================================================== 16:30:03 (1788467403) [ 4129.409961] LustreError: lustre-OST0001-osc-ffff9a44c3312800: operation ost_write to node 192.168.206.103@tcp failed: rc = -14 [ 4129.424520] LustreError: Skipped 3 previous similar messages [ 4136.219849] Lustre: DEBUG MARKER: == sanity test 118k: bio alloc -ENOMEM and IO TERM handling =================================================================== 16:30:12 (1788467412) [ 4137.768894] LustreError: 2352:0:(osc_request.c:2451:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff9a43ed870e00 x1875339779172736/t0(0) o4->lustre-OST0000-osc-ffff9a44c3312800@192.168.206.103@tcp:6/4 lens 488/224 e 0 to 0 dl 1788467431 ref 2 fl Interpret:ReMQU/600/0 rc -5/-5 job:'dd.0' uid:0 gid:0 projid:0 [ 4137.789164] LustreError: 2352:0:(osc_request.c:2451:osc_brw_redo_request()) Skipped 3 previous similar messages [ 4154.214833] Lustre: DEBUG MARKER: == sanity test 118l: fsync dir =========================== 16:30:30 (1788467430) [ 4159.700817] Lustre: DEBUG MARKER: == sanity test 118m: fdatasync dir ======================= 16:30:35 (1788467435) [ 4165.319809] Lustre: DEBUG MARKER: == sanity test 118n: statfs() sends OST_STATFS requests in parallel ========================================================== 16:30:41 (1788467441) [ 4175.884624] Lustre: DEBUG MARKER: == sanity test 119a: Short directIO read must return actual read amount ========================================================== 16:30:51 (1788467451) [ 4182.193345] Lustre: DEBUG MARKER: == sanity test 119b: Sparse directIO read must return actual read amount ========================================================== 16:30:58 (1788467458) [ 4187.988252] Lustre: DEBUG MARKER: == sanity test 119c: Testing for direct read hitting hole ========================================================== 16:31:04 (1788467464) [ 4193.575476] Lustre: DEBUG MARKER: == sanity test 119e: Basic tests of dio read and write at various sizes ========================================================== 16:31:09 (1788467469) [ 4235.239713] Lustre: DEBUG MARKER: == sanity test 119f: dio vs dio race ===================== 16:31:51 (1788467511) [ 4275.816833] Lustre: DEBUG MARKER: == sanity test 119g: dio vs buffered I/O race ============ 16:32:31 (1788467551) [ 4315.889242] Lustre: DEBUG MARKER: == sanity test 119h: basic tests of memory unaligned dio ========================================================== 16:33:12 (1788467592) [ 4341.814588] Lustre: DEBUG MARKER: SKIP: sanity test_119i skipping ALWAYS excluded test 119i [ 4343.103698] Lustre: DEBUG MARKER: == sanity test 119j: basic tests of hybrid IO switching == 16:33:39 (1788467619) [ 4343.554075] Lustre: *** cfs_fail_loc=1429, val=0*** [ 4350.095870] Lustre: DEBUG MARKER: == sanity test 119k: hybrid IO counting with stats and disabling ========================================================== 16:33:45 (1788467625) [ 4366.930741] Lustre: DEBUG MARKER: == sanity test 119m: Test DIO readv/writev: exercise iter duplication ========================================================== 16:34:02 (1788467642) [ 4373.444262] Lustre: DEBUG MARKER: == sanity test 119n: Test Unaligned DIO readv() and writev() with unpatched ZFS ========================================================== 16:34:09 (1788467649) [ 4374.658417] Lustre: DEBUG MARKER: SKIP: sanity test_119n zfs server without 'unaligned_dio' support [ 4376.491129] Lustre: DEBUG MARKER: == sanity test 119o: Test Unaligned DIO readv() and writev() with unpatched servers ========================================================== 16:34:12 (1788467652) [ 4377.884527] Lustre: DEBUG MARKER: SKIP: sanity test_119o need ldiskfs without 'unaligned_dio' support [ 4379.371173] Lustre: DEBUG MARKER: == sanity test 119p: Test Unaligned DIO readv() and writev() with patched servers ========================================================== 16:34:15 (1788467655) [ 4386.323232] Lustre: DEBUG MARKER: == sanity test 119q: Test patchded Unaligned DIO readv() and writev() ========================================================== 16:34:22 (1788467662) [ 4400.995489] Lustre: DEBUG MARKER: == sanity test 119r: Test error handling in unaligned DIO user copy ========================================================== 16:34:37 (1788467677) [ 4401.627189] Lustre: *** cfs_fail_loc=1437, val=0*** [ 4401.631387] LustreError: 120781:0:(osc_cache.c:2419:osc_check_rpcs()) Write request failed with -14 [ 4407.542792] Lustre: DEBUG MARKER: == sanity test 119s: full-size unaligned DIO packs matching bulk MDs ========================================================== 16:34:43 (1788467683) [ 4409.388313] Lustre: DEBUG MARKER: SKIP: sanity test_119s need client page size larger than the server's [ 4410.938490] Lustre: DEBUG MARKER: == sanity test 120a: Early Lock Cancel: mkdir test ======= 16:34:46 (1788467686) [ 4419.862816] Lustre: DEBUG MARKER: == sanity test 120b: Early Lock Cancel: create test ====== 16:34:55 (1788467695) [ 4429.969323] Lustre: DEBUG MARKER: == sanity test 120c: Early Lock Cancel: link test ======== 16:35:05 (1788467705) [ 4441.483696] Lustre: DEBUG MARKER: == sanity test 120d: Early Lock Cancel: setattr test ===== 16:35:16 (1788467716) [ 4451.553855] Lustre: DEBUG MARKER: == sanity test 120e: Early Lock Cancel: unlink test ====== 16:35:27 (1788467727) [ 4468.282854] Lustre: DEBUG MARKER: == sanity test 120f: Early Lock Cancel: rename test ====== 16:35:44 (1788467744) [ 4487.818968] Lustre: DEBUG MARKER: == sanity test 120g: Early Lock Cancel: performance test ========================================================== 16:36:03 (1788467763) [ 4994.325473] Lustre: DEBUG MARKER: == sanity test 121: read cancel race ===================== 16:44:30 (1788468270) [ 4994.593134] Lustre: *** cfs_fail_loc=310, val=0*** [ 5001.612549] Lustre: DEBUG MARKER: == sanity test 123aa: verify statahead work ============== 16:44:36 (1788468276) [ 5012.344967] Lustre: DEBUG MARKER: 'ls -l' 100 files without statahead: 3 sec [ 5015.484305] Lustre: DEBUG MARKER: 'ls -l' 100 files with statahead: 0 sec [ 5057.932772] Lustre: DEBUG MARKER: 'ls -l' 1000 files without statahead: 22 sec [ 5067.850808] Lustre: DEBUG MARKER: 'ls -l' 1000 files with statahead: 6 sec [ 5069.486868] Lustre: DEBUG MARKER: 'ls -l' done [ 5092.118991] Lustre: DEBUG MARKER: unlink + rm -r /mnt/lustre/d123aa.sanity: 21 seconds [ 5105.535542] Lustre: DEBUG MARKER: == sanity test 123ab: verify statahead work by using statx ========================================================== 16:46:21 (1788468381) [ 5116.180384] Lustre: DEBUG MARKER: 'statx -l' 100 files without statahead: 3 sec [ 5119.500018] Lustre: DEBUG MARKER: 'statx -l' 100 files with statahead: 1 sec [ 5168.343624] Lustre: DEBUG MARKER: 'statx -l' 1000 files without statahead: 23 sec [ 5178.702931] Lustre: DEBUG MARKER: 'statx -l' 1000 files with statahead: 7 sec [ 5180.243892] Lustre: DEBUG MARKER: 'statx -l' done [ 5204.997691] Lustre: DEBUG MARKER: unlink + rm -r /mnt/lustre/d123ab.sanity: 23 seconds [ 5217.174201] Lustre: DEBUG MARKER: == sanity test 123ac: verify statahead work by using statx without glimpse RPCs ========================================================== 16:48:13 (1788468493) [ 5225.862633] Lustre: DEBUG MARKER: 'statx -c 0 [ 5228.269419] Lustre: DEBUG MARKER: 'statx -c 0 [ 5262.220707] Lustre: DEBUG MARKER: 'statx -c 0 [ 5269.321510] Lustre: DEBUG MARKER: 'statx -c 0 [ 5271.442589] Lustre: DEBUG MARKER: 'statx -c 0 [ 5296.512915] Lustre: DEBUG MARKER: unlink + rm -r /mnt/lustre/d123ac.sanity: 24 seconds [ 5304.746869] Lustre: DEBUG MARKER: 'statx --cached=always -D' 100 files without statahead: 0 sec [ 5306.697070] Lustre: DEBUG MARKER: 'statx --cached=always -D' 100 files with statahead: 0 sec [ 5326.467241] Lustre: DEBUG MARKER: 'statx --cached=always -D' 1000 files without statahead: 0 sec [ 5328.207050] Lustre: DEBUG MARKER: 'statx --cached=always -D' 1000 files with statahead: 0 sec [ 5464.110898] Lustre: DEBUG MARKER: 'statx --cached=always -D' 10000 files without statahead: 0 sec [ 5466.689621] Lustre: DEBUG MARKER: 'statx --cached=always -D' 10000 files with statahead: 1 sec [ 5468.670629] Lustre: DEBUG MARKER: 'statx --cached=always -D' done [ 5822.235258] Lustre: DEBUG MARKER: unlink + rm -r /mnt/lustre/d123ac.sanity: 353 seconds [ 5842.482502] Lustre: DEBUG MARKER: == sanity test 123ad: Verify batching statahead works correctly ========================================================== 16:58:37 (1788469117) [ 5854.218675] Lustre: DEBUG MARKER: 'ls -l' 100 files without statahead: 3 sec [ 5857.598573] Lustre: DEBUG MARKER: 'ls -l' 100 files with statahead: 1 sec [ 5901.078681] Lustre: DEBUG MARKER: 'ls -l' 1000 files without statahead: 21 sec [ 5912.674714] Lustre: DEBUG MARKER: 'ls -l' 1000 files with statahead: 8 sec [ 5914.483965] Lustre: DEBUG MARKER: 'ls -l' done [ 5936.883631] Lustre: DEBUG MARKER: unlink + rm -r /mnt/lustre/d123ad.sanity: 21 seconds [ 6625.663797] Lustre: DEBUG MARKER: 'ls -l' 100 files without statahead: 3 sec [ 6628.827355] Lustre: DEBUG MARKER: 'ls -l' 100 files with statahead: 0 sec [ 6678.793236] Lustre: DEBUG MARKER: 'ls -l' 1000 files without statahead: 25 sec [ 6690.772285] Lustre: DEBUG MARKER: 'ls -l' 1000 files with statahead: 7 sec [ 6694.118183] Lustre: DEBUG MARKER: 'ls -l' done [ 6725.407575] Lustre: DEBUG MARKER: unlink + rm -r /mnt/lustre/d123ad.sanity: 30 seconds [ 7348.335742] Lustre: DEBUG MARKER: == sanity test 123b: not panic with network error in statahead enqueue (bug 15027) ========================================================== 17:23:43 (1788470623) [ 7376.768530] Lustre: DEBUG MARKER: ls done [ 7407.623959] Lustre: DEBUG MARKER: == sanity test 123c: Can not initialize inode warning on DNE statahead ========================================================== 17:24:43 (1788470683) [ 7409.341047] Lustre: DEBUG MARKER: SKIP: sanity test_123c needs >= 2 MDTs [ 7411.505734] Lustre: DEBUG MARKER: == sanity test 123d: Statahead on striped directories works correctly ========================================================== 17:24:47 (1788470687) [ 7416.108602] Lustre: Unmounted lustre-client [ 7416.642627] Lustre: Mounted lustre-client - version 2.17.58_2_gdacfdd2 [ 7429.928183] Lustre: DEBUG MARKER: == sanity test 123e: statahead with large wide striping == 17:25:04 (1788470704) [ 7778.614451] Lustre: DEBUG MARKER: == sanity test 123f: Retry mechanism with large wide striping files ========================================================== 17:30:53 (1788471053) [ 9170.936723] Lustre: DEBUG MARKER: == sanity test 123g: Test for stat-ahead advise ========== 17:54:06 (1788472446) [ 9259.915613] Lustre: DEBUG MARKER: == sanity test 123h: Verify statahead work with the fname pattern via du ========================================================== 17:55:35 (1788472535) [11046.012887] Lustre: DEBUG MARKER: == sanity test 123i: Verify statahead work with the fname indexing pattern ========================================================== 18:25:21 (1788474321) [11189.272564] Lustre: DEBUG MARKER: == sanity test 123j: -ENOENT error from batched statahead be handled correctly ========================================================== 18:27:45 (1788474465) [11190.707894] Lustre: DEBUG MARKER: SKIP: sanity test_123j needs >= 2 MDTs [11193.091663] Lustre: DEBUG MARKER: == sanity test 123k: Verify statahead work with mdtest shared stat() mode ========================================================== 18:27:48 (1788474468) [11194.962524] Lustre: DEBUG MARKER: SKIP: sanity test_123k mdtest not found [11196.924777] Lustre: DEBUG MARKER: == sanity test 123l: Avoid panic when revalidate a local cached entry ========================================================== 18:27:52 (1788474472) [11203.467491] LustreError: 179127:0:(statahead.c:360:sa_put()) cfs_fail_timeout id 1433 sleeping for 35000ms [11238.508044] LustreError: 179127:0:(statahead.c:360:sa_put()) cfs_fail_timeout id 1433 awake [11280.325886] Lustre: DEBUG MARKER: == sanity test 124a: lru resize ================================================================================================= 18:29:15 (1788474555) [11281.799321] Lustre: DEBUG MARKER: create 2000 files at /mnt/lustre/d124a.sanity [11334.354467] Lustre: DEBUG MARKER: NSDIR=ldlm.namespaces.lustre-MDT0000-mdc-ffff9a43c5536000 [11336.739600] Lustre: DEBUG MARKER: NS=ldlm.namespaces.lustre-MDT0000-mdc-ffff9a43c5536000 [11338.165873] Lustre: DEBUG MARKER: LRU=2003 [11339.667997] Lustre: DEBUG MARKER: LIMIT=61549 [11341.497648] Lustre: DEBUG MARKER: LVF=3687400 [11343.037865] Lustre: DEBUG MARKER: OLD_LVF=100 [11344.666106] Lustre: DEBUG MARKER: Sleep 50 sec [11396.797309] Lustre: DEBUG MARKER: Dropped 1065 locks in 50s [11398.854644] Lustre: DEBUG MARKER: unlink 2000 files at /mnt/lustre/d124a.sanity [11440.021226] Lustre: DEBUG MARKER: == sanity test 124b: lru resize (performance test) ================================================================================= 18:31:55 (1788474715) [11563.056385] Lustre: DEBUG MARKER: doing ls -la /mnt/lustre/d124b.sanity/disable_lru_resize 3 times [11728.293201] Lustre: DEBUG MARKER: ls -la time: 164 seconds [11730.888843] Lustre: DEBUG MARKER: lru_size = 400 [11987.820216] Lustre: DEBUG MARKER: doing ls -la /mnt/lustre/d124b.sanity/enable_lru_resize 3 times [12090.493977] Lustre: DEBUG MARKER: ls -la time: 96 seconds [12093.694963] Lustre: DEBUG MARKER: lru_size = 8005 [12095.820424] Lustre: DEBUG MARKER: ls -la is 41% faster with lru resize enabled [12200.317571] Lustre: DEBUG MARKER: == sanity test 124c: LRUR cancel very aged locks ========= 18:44:36 (1788475476) [12236.027292] Lustre: DEBUG MARKER: == sanity test 124d: cancel very aged locks if lru-resize disabled ========================================================== 18:45:12 (1788475512) [12272.246787] Lustre: DEBUG MARKER: == sanity test 124e: LFRU keep priv locks from eviction == 18:45:47 (1788475547) [12320.304832] Lustre: DEBUG MARKER: == sanity test 124f: LFRU priv threshold inc/dec adjustment ========================================================== 18:46:36 (1788475596) [12414.717035] Lustre: DEBUG MARKER: == sanity test 124g: LFRU performance test =============== 18:48:10 (1788475690) [13306.363765] Lustre: DEBUG MARKER: == sanity test 125: don't return EPROTO when a dir has a non-default striping and ACLs ========================================================== 19:03:02 (1788476582) [13315.087395] Lustre: DEBUG MARKER: == sanity test 126: check that the fsgid provided by the client is taken into account ========================================================== 19:03:10 (1788476590) [13321.989373] Lustre: DEBUG MARKER: == sanity test 127a: verify the client stats are sane ==== 19:03:17 (1788476597) [13331.176801] Lustre: DEBUG MARKER: == sanity test 127b: verify the llite client stats are sane ========================================================== 19:03:27 (1788476607) [13338.987423] Lustre: DEBUG MARKER: == sanity test 127c: test llite extent stats with regular [13380.527845] Lustre: DEBUG MARKER: == sanity test 127d: OSC RPC latency histograms for read and write latency ========================================================== 19:04:16 (1788476656) [13390.732788] Lustre: DEBUG MARKER: == sanity test 127e: client IO latency histograms by size ========================================================== 19:04:26 (1788476666) [13410.312525] Lustre: DEBUG MARKER: == sanity test 127f: OST IO latency histograms by size === 19:04:45 (1788476685) [13411.842622] Lustre: DEBUG MARKER: SKIP: sanity test_127f ldiskfs only [13414.228844] Lustre: DEBUG MARKER: == sanity test 127g: cached_read_bytes tracks page cache hits ========================================================== 19:04:49 (1788476689) [13416.055481] bash (222703): drop_caches: 3 [13417.153686] bash (222703): drop_caches: 3 [13418.498038] bash (222703): drop_caches: 3 [13426.917294] Lustre: DEBUG MARKER: == sanity test 128: interactive lfs for 2 consecutive find's ========================================================== 19:05:02 (1788476702) [13434.395902] Lustre: DEBUG MARKER: == sanity test 129: test directory size limit ================================================================================== 19:05:10 (1788476710) [13436.097516] Lustre: DEBUG MARKER: SKIP: sanity test_129 ldiskfs only test [13437.570355] Lustre: DEBUG MARKER: == sanity test 130a: FIEMAP (1-stripe file) ============== 19:05:13 (1788476713) [13439.765765] Lustre: DEBUG MARKER: SKIP: sanity test_130a LU-1941: FIEMAP unimplemented on ZFS [13441.541737] Lustre: DEBUG MARKER: SKIP: sanity test_130b skipping ALWAYS excluded test 130b [13443.293092] Lustre: DEBUG MARKER: SKIP: sanity test_130c skipping ALWAYS excluded test 130c [13444.986955] Lustre: DEBUG MARKER: SKIP: sanity test_130d skipping ALWAYS excluded test 130d [13446.372240] Lustre: DEBUG MARKER: SKIP: sanity test_130e skipping ALWAYS excluded test 130e [13447.988764] Lustre: DEBUG MARKER: SKIP: sanity test_130f skipping ALWAYS excluded test 130f [13449.636818] Lustre: DEBUG MARKER: SKIP: sanity test_130g skipping ALWAYS excluded test 130g [13451.186141] Lustre: DEBUG MARKER: == sanity test 130h: FIEMAP deadlock ===================== 19:05:27 (1788476727) [13453.231356] LustreError: 225494:0:(osc_object.c:271:osc_object_fiemap()) cfs_fail_timeout id 418 sleeping for 5000ms [13458.241620] LustreError: 225494:0:(osc_object.c:271:osc_object_fiemap()) cfs_fail_timeout id 418 awake [13464.622772] Lustre: DEBUG MARKER: == sanity test 130i: FIEMAP (DoM file) =================== 19:05:40 (1788476740) [13466.473431] Lustre: DEBUG MARKER: SKIP: sanity test_130i LU-1941: FIEMAP unimplemented on ZFS [13468.565673] Lustre: DEBUG MARKER: == sanity test 131a: test iov's crossing stripe boundary for writev/readv ========================================================== 19:05:44 (1788476744) [13475.395514] Lustre: DEBUG MARKER: == sanity test 131b: test append writev ================== 19:05:51 (1788476751) [13482.100259] Lustre: DEBUG MARKER: == sanity test 131c: test read/write on file w/o objects ========================================================== 19:05:58 (1788476758) [13487.494628] Lustre: DEBUG MARKER: == sanity test 131d: test short read ===================== 19:06:03 (1788476763) [13494.929370] Lustre: DEBUG MARKER: == sanity test 131e: test read hitting hole ============== 19:06:10 (1788476770) [13501.725748] Lustre: DEBUG MARKER: == sanity test 133a: Verifying MDT stats ================================================================================================== 19:06:17 (1788476777) [13524.533859] Lustre: DEBUG MARKER: == sanity test 133b: Verifying extra MDT stats ============================================================================================ 19:06:40 (1788476800) [13545.514432] Lustre: DEBUG MARKER: == sanity test 133c: Verifying OST stats ================================================================================================== 19:07:01 (1788476821) [13590.517943] Lustre: DEBUG MARKER: == sanity test 133d: Verifying rename_stats ================================================================================================== 19:07:46 (1788476866) [13629.854141] Lustre: DEBUG MARKER: == sanity test 133e: Verifying OST read_bytes write_bytes nid stats =========================================================================== 19:08:25 (1788476905) [13641.873465] Lustre: DEBUG MARKER: == sanity test 133f: Check reads/writes of client lustre proc files with bad area io ========================================================== 19:08:37 (1788476917) [13644.008846] LNet: 233790:0:(debug.c:375:cfs_str2mask()) unknown mask ''. [13644.008846] mask usage: [+|-] ... [13644.477949] Lustre: DEBUG MARKER:  [13644.481466] Lustre: DEBUG MARKER:  [13644.738494] LNet: 233856:0:(debug.c:375:cfs_str2mask()) unknown mask ''. [13644.738494] mask usage: [+|-] ... [13644.744806] LNet: 233856:0:(debug.c:375:cfs_str2mask()) Skipped 6 previous similar messages [13655.330378] Lustre: Unmounted lustre-client [13674.177848] Key type lgssc unregistered [13674.444363] LNet: 234817:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [13674.452134] LNetError: 234817:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [13674.479166] LNet: Removed LNI 192.168.206.3@tcp [13676.057737] Key type .llcrypt unregistered [13676.059991] Key type ._llcrypt unregistered [13686.528103] Key type ._llcrypt registered [13686.530073] Key type .llcrypt registered [13687.010229] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [13687.026946] alg: No test for adler32 (adler32-zlib) [13688.449317] Lustre: Lustre: Build Version: 2.17.58_2_gdacfdd2 [13689.294386] LNet: Added LNI 192.168.206.3@tcp [8/256/0/180] [13691.008428] Key type lgssc registered [13692.556096] Lustre: Echo OBD driver; http://www.lustre.org/ [13769.268626] Lustre: Mounted lustre-client - version 2.17.58_2_gdacfdd2 [13773.885622] Lustre: DEBUG MARKER: Using TIMEOUT=20 [13785.100170] Lustre: DEBUG MARKER: == sanity test 133g: Check reads/writes of server lustre proc files with bad area io ========================================================== 19:11:01 (1788477061) [13794.785804] Lustre: lustre-OST0000-osc-ffff9a43c7127000: disconnect after 24s idle [13859.180329] Lustre: Unmounted lustre-client [13887.074349] Key type lgssc unregistered [13887.321749] LNet: 238588:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [13887.335961] LNetError: 238588:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [13887.374067] LNet: Removed LNI 192.168.206.3@tcp [13888.103514] Key type .llcrypt unregistered [13888.110532] Key type ._llcrypt unregistered [13897.945356] Key type ._llcrypt registered [13897.993987] Key type .llcrypt registered [13898.481781] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [13898.501019] alg: No test for adler32 (adler32-zlib) [13899.605667] Lustre: Lustre: Build Version: 2.17.58_2_gdacfdd2 [13899.875825] LNet: Added LNI 192.168.206.3@tcp [8/256/0/180] [13901.530623] Key type lgssc registered [13902.500697] Lustre: Echo OBD driver; http://www.lustre.org/ [13977.310474] Lustre: Mounted lustre-client - version 2.17.58_2_gdacfdd2 [13983.090242] Lustre: DEBUG MARKER: Using TIMEOUT=20 [13996.208712] Lustre: DEBUG MARKER: == sanity test 133h: Proc files should end with newlines ========================================================== 19:14:31 (1788477271) [14003.168521] Lustre: lustre-OST0000-osc-ffff9a44f72ed000: disconnect after 23s idle [14033.888850] Lustre: lustre-OST0000-osc-ffff9a44f72ed000: disconnect after 23s idle [14033.899547] Lustre: Skipped 1 previous similar message [14059.495537] Lustre: lustre-OST0000-osc-ffff9a44f72ed000: disconnect after 22s idle [14059.510912] Lustre: Skipped 1 previous similar message [14064.613615] Lustre: lustre-OST0001-osc-ffff9a44f72ed000: disconnect after 24s idle [15013.334872] Lustre: DEBUG MARKER: == sanity test 134a: Server reclaims locks when reaching lock_reclaim_threshold ========================================================== 19:31:28 (1788478288) [15073.249510] Lustre: lustre-OST0001-osc-ffff9a44f72ed000: disconnect after 21s idle [15073.650209] Lustre: DEBUG MARKER: == sanity test 134b: Server rejects lock request when reaching lock_limit_mb ========================================================== 19:32:29 (1788478349) [15120.190186] Lustre: DEBUG MARKER: == sanity test 134c: Lock memory accounting includes associated structures ========================================================== 19:33:15 (1788478395) [15135.645981] Lustre: DEBUG MARKER: SKIP: sanity test_135 skipping SLOW test 135 [15137.295152] Lustre: DEBUG MARKER: SKIP: sanity test_136 skipping SLOW test 136 [15139.161283] Lustre: DEBUG MARKER: == sanity test 140: Check reasonable stack depth (shouldn't LBUG) ============================================================== 19:33:34 (1788478414) [15187.258625] Lustre: DEBUG MARKER: == sanity test 150a: truncate/append tests =============== 19:34:23 (1788478463) [15208.233326] Lustre: Unmounted lustre-client [15209.067214] Lustre: Mounted lustre-client - version 2.17.58_2_gdacfdd2 [15243.525734] Lustre: DEBUG MARKER: == sanity test 150b: Verify fallocate (prealloc) functionality ========================================================== 19:35:19 (1788478519) [15251.601213] Lustre: DEBUG MARKER: SKIP: sanity test_150b fallocate failed, error Operation not supported, mode 0, offset 41943040, len 4194304|check_fallocate failed [15274.645437] Lustre: DEBUG MARKER: == sanity test 150bb: Verify fallocate modes both zero space ========================================================== 19:35:50 (1788478550) [15277.196354] Lustre: DEBUG MARKER: SKIP: sanity test_150bb fallocate not supported [15279.128970] Lustre: DEBUG MARKER: == sanity test 150c: Verify fallocate Size and Blocks ==== 19:35:54 (1788478554) [15282.088345] Lustre: DEBUG MARKER: SKIP: sanity test_150c fallocate not supported [15283.986985] Lustre: DEBUG MARKER: == sanity test 150d: Verify fallocate Size and Blocks - Non zero start ========================================================== 19:35:59 (1788478559) [15286.371974] Lustre: DEBUG MARKER: SKIP: sanity test_150d fallocate not supported [15287.970505] Lustre: DEBUG MARKER: == sanity test 150e: Verify 60% of available OST space consumed by fallocate ========================================================== 19:36:04 (1788478564) [15290.363416] Lustre: DEBUG MARKER: SKIP: sanity test_150e fallocate not supported [15292.114299] Lustre: DEBUG MARKER: == sanity test 150f: Verify fallocate punch functionality ========================================================== 19:36:07 (1788478567) [15357.821479] Lustre: DEBUG MARKER: == sanity test 150g: Verify fallocate punch on large range ========================================================== 19:37:13 (1788478633) [15361.218488] Lustre: DEBUG MARKER: SKIP: sanity test_150g fallocate not supported [15363.111623] Lustre: DEBUG MARKER: == sanity test 150h: Verify extend fallocate updates the file size ========================================================== 19:37:18 (1788478638) [15365.841957] Lustre: DEBUG MARKER: SKIP: sanity test_150h fallocate not supported [15368.624590] Lustre: DEBUG MARKER: == sanity test 150ia: Verify fallocate zero-range ZERO functionality ========================================================== 19:37:23 (1788478643) [15370.415769] Lustre: DEBUG MARKER: SKIP: sanity test_150ia zero-range mode is not implemented on OSD ZFS [15372.330820] Lustre: DEBUG MARKER: == sanity test 150ib: Verify fallocate zero-range PREALLOC functionality ========================================================== 19:37:28 (1788478648) [15373.796632] Lustre: DEBUG MARKER: SKIP: sanity test_150ib zero-range mode is not implemented on OSD ZFS [15375.717714] Lustre: DEBUG MARKER: == sanity test 150ic: Verify fallocate LARGE zero PREALLOC functionality ========================================================== 19:37:31 (1788478651) [15377.405520] Lustre: DEBUG MARKER: SKIP: sanity test_150ic zero-range mode is not implemented on OSD ZFS [15379.576682] Lustre: DEBUG MARKER: == sanity test 150id: fallocate that fails must not leave a dirty page behind ========================================================== 19:37:35 (1788478655) [15381.408694] Lustre: DEBUG MARKER: SKIP: sanity test_150id fallocate zero-range is ldiskfs only [15383.360987] Lustre: DEBUG MARKER: == sanity test 151: test cache on oss and controls ========================================================================================= 19:37:39 (1788478659) [15387.576901] Lustre: DEBUG MARKER: SKIP: sanity test_151 not cache-capable obdfilter [15389.409845] Lustre: DEBUG MARKER: == sanity test 152: test read/write with enomem ====================================================================================== 19:37:45 (1788478665) [15397.842662] Lustre: DEBUG MARKER: == sanity test 153: test if fdatasync does not crash ================================================================================= 19:37:53 (1788478673) [15405.375647] Lustre: DEBUG MARKER: == sanity test 154A: lfs path2fid and fid2path basic checks ========================================================== 19:38:01 (1788478681) [15412.361984] Lustre: DEBUG MARKER: == sanity test 154B: verify the ll_decode_linkea tool ==== 19:38:08 (1788478688) [15420.396393] Lustre: DEBUG MARKER: == sanity test 154C: lfs fid2path on OST FID ============= 19:38:15 (1788478695) [15449.761862] Lustre: DEBUG MARKER: == sanity test 154a: Open-by-FID ========================= 19:38:45 (1788478725) [15461.213438] Lustre: DEBUG MARKER: == sanity test 154b: Open-by-FID for remote directory ==== 19:38:56 (1788478736) [15462.803164] Lustre: DEBUG MARKER: SKIP: sanity test_154b needs >= 2 MDTs [15464.835856] Lustre: DEBUG MARKER: == sanity test 154c: lfs path2fid and fid2path multiple arguments ========================================================== 19:39:00 (1788478740) [15471.741684] Lustre: DEBUG MARKER: == sanity test 154d: Verify open file fid ================ 19:39:07 (1788478747) [15480.638896] Lustre: DEBUG MARKER: == sanity test 154db: fid is stored in dir entries ======= 19:39:16 (1788478756) [15482.276560] Lustre: DEBUG MARKER: SKIP: sanity test_154db ldiskfs only test [15484.268659] Lustre: DEBUG MARKER: == sanity test 154e: .lustre is not returned by readdir == 19:39:20 (1788478760) [15491.658979] Lustre: DEBUG MARKER: == sanity test 154ea: .lustre is not returned by readdir (2) ========================================================== 19:39:27 (1788478767) [15551.351147] Lustre: DEBUG MARKER: == sanity test 154f: get parent fids by reading link ea == 19:40:27 (1788478827) [15559.409800] Lustre: DEBUG MARKER: == sanity test 154g: various llapi FID tests ============= 19:40:35 (1788478835) [16773.030764] Lustre: DEBUG MARKER: == sanity test 154h: Verify interactive path2fid ========= 20:00:48 (1788480048) [16779.725511] Lustre: DEBUG MARKER: == sanity test 154i: fid2path for path longer than PATH_MAX ========================================================== 20:00:55 (1788480055) [16823.436679] Lustre: DEBUG MARKER: == sanity test 154j: fid2path for long path crossing MDT boundary ========================================================== 20:01:39 (1788480099) [16825.094690] Lustre: DEBUG MARKER: SKIP: sanity test_154j needs >= 2 MDTs [16826.833437] Lustre: DEBUG MARKER: == sanity test 155a: Verify small file correctness: read cache:on write_cache:on ========================================================== 20:01:42 (1788480102) [16840.011941] Lustre: DEBUG MARKER: == sanity test 155b: Verify small file correctness: read cache:on write_cache:off ========================================================== 20:01:55 (1788480115) [16854.364194] Lustre: DEBUG MARKER: == sanity test 155c: Verify small file correctness: read cache:off write_cache:on ========================================================== 20:02:09 (1788480129) [16868.007275] Lustre: DEBUG MARKER: == sanity test 155d: Verify small file correctness: read cache:off write_cache:off ========================================================== 20:02:23 (1788480143) [16883.147670] Lustre: DEBUG MARKER: == sanity test 155e: Verify big file correctness: read cache:on write_cache:on ========================================================== 20:02:38 (1788480158) [16939.469028] Lustre: DEBUG MARKER: == sanity test 155f: Verify big file correctness: read cache:on write_cache:off ========================================================== 20:03:35 (1788480215) [16990.353624] Lustre: DEBUG MARKER: == sanity test 155g: Verify big file correctness: read cache:off write_cache:on ========================================================== 20:04:26 (1788480266) [17043.460737] Lustre: DEBUG MARKER: == sanity test 155h: Verify big file correctness: read cache:off write_cache:off ========================================================== 20:05:19 (1788480319) [17103.622565] Lustre: DEBUG MARKER: == sanity test 156: Verification of tunables ============= 20:06:19 (1788480379) [17105.444258] Lustre: DEBUG MARKER: SKIP: sanity test_156 LU-1956/LU-2261: stats not implemented on OSD ZFS [17107.280929] Lustre: DEBUG MARKER: == sanity test 157a: llapi pool pinning API tests ======== 20:06:23 (1788480383) [17116.395368] Lustre: DEBUG MARKER: == sanity test 157b: lustre.pin inheritance on create ==== 20:06:32 (1788480392) [17124.290896] Lustre: DEBUG MARKER: == sanity test 160a: changelog sanity ==================== 20:06:40 (1788480400) [17154.535677] Lustre: lustre-MDT0000-mdc-ffff9a44c81a2000: Connection to lustre-MDT0000 (at 192.168.206.103@tcp) was lost; in progress operations using this service will wait for recovery to complete [17154.566377] LustreError: MGC192.168.206.103@tcp: Connection to MGS (at 192.168.206.103@tcp) was lost; in progress operations using this service will fail [17154.598836] Lustre: Evicted from MGS (at 192.168.206.103@tcp) after server handle changed from 0xe96e08d2bee0b1c2 to 0xe96e08d2bee9ca99 [17154.610917] Lustre: MGC192.168.206.103@tcp: Connection restored to 192.168.206.103@tcp (at 192.168.206.103@tcp) [17154.655986] LustreError: 238917:0:(client.c:3449:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9a44e7d4c380 x1875354247151744/t12884908733(12884908733) o101->lustre-MDT0000-mdc-ffff9a44c81a2000@192.168.206.103@tcp:12/10 lens 968/608 e 0 to 0 dl 1788480447 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'lfs.0' uid:0 gid:0 projid:0 [17155.155969] LustreError: 238917:0:(client.c:3449:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9a44e7d4f100 x1875354253917568/t12884924431(12884924431) o101->lustre-MDT0000-mdc-ffff9a44c81a2000@192.168.206.103@tcp:12/10 lens 968/608 e 0 to 0 dl 1788480448 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'bash.0' uid:0 gid:0 projid:0 [17155.176272] LustreError: 238917:0:(client.c:3449:ptlrpc_replay_interpret()) Skipped 43 previous similar messages [17155.700288] Lustre: lustre-MDT0000-mdc-ffff9a44c81a2000: Connection restored to 192.168.206.103@tcp (at 192.168.206.103@tcp) [17160.481987] Lustre: 238920:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788480421/real 1788480421] req@ffff9a44f6063480 x1875354254219776/t0(0) o400->lustre-MDT0000-mdc-ffff9a44c81a2000@192.168.206.103@tcp:12/10 lens 224/224 e 0 to 1 dl 1788480437 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [17164.770123] Lustre: 238919:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788480426/real 1788480426] req@ffff9a4500480000 x1875354254220288/t0(0) o400->lustre-MDT0000-mdc-ffff9a44c81a2000@192.168.206.103@tcp:12/10 lens 224/224 e 0 to 1 dl 1788480442 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [17169.803961] Lustre: DEBUG MARKER: == sanity test 160b: Verify that very long rename doesn't crash in changelog ========================================================== 20:07:25 (1788480445) [17185.453199] Lustre: DEBUG MARKER: == sanity test 160c: verify that changelog log catch the truncate event ========================================================== 20:07:41 (1788480461) [17203.566618] Lustre: DEBUG MARKER: == sanity test 160d: verify that changelog log catch the migrate event ========================================================== 20:07:58 (1788480478) [17207.271298] Lustre: DEBUG MARKER: SKIP: sanity test_160d needs >= 2 MDTs [17210.479647] Lustre: DEBUG MARKER: == sanity test 160e: changelog negative testing (should return errors) ========================================================== 20:08:05 (1788480485) [17231.427091] Lustre: DEBUG MARKER: == sanity test 160f: changelog garbage collect (timestamped users) ========================================================== 20:08:26 (1788480506) [17239.264395] Lustre: DEBUG MARKER: 1788480515: creating first dirs [17277.312615] Lustre: DEBUG MARKER: == sanity test 160g: changelog garbage collect on idle records ========================================================== 20:09:13 (1788480553) [17310.711676] Lustre: DEBUG MARKER: == sanity test 160h: changelog gc thread stop upon umount, orphan records delete ========================================================== 20:09:46 (1788480586) [17343.985384] Lustre: lustre-MDT0000-mdc-ffff9a44c81a2000: Connection to lustre-MDT0000 (at 192.168.206.103@tcp) was lost; in progress operations using this service will wait for recovery to complete [17354.215237] LustreError: MGC192.168.206.103@tcp: Connection to MGS (at 192.168.206.103@tcp) was lost; in progress operations using this service will fail [17354.231864] Lustre: Evicted from MGS (at 192.168.206.103@tcp) after server handle changed from 0xe96e08d2bee9ca99 to 0xe96e08d2bee9dce4 [17354.252492] Lustre: MGC192.168.206.103@tcp: Connection restored to 192.168.206.103@tcp (at 192.168.206.103@tcp) [17364.571743] LustreError: 238917:0:(client.c:3449:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9a4500462680 x1875354253901824/t12884924390(12884924390) o101->lustre-MDT0000-mdc-ffff9a44c81a2000@192.168.206.103@tcp:12/10 lens 968/608 e 0 to 0 dl 1788480657 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'bash.0' uid:0 gid:0 projid:0 [17364.603437] LustreError: 238917:0:(client.c:3449:ptlrpc_replay_interpret()) Skipped 28 previous similar messages [17365.582512] Lustre: lustre-MDT0000-mdc-ffff9a44c81a2000: Connection restored to 192.168.206.103@tcp (at 192.168.206.103@tcp) [17380.410401] Lustre: DEBUG MARKER: == sanity test 160i: changelog user register/unregister race ========================================================== 20:10:56 (1788480656) [17402.795301] Lustre: DEBUG MARKER: == sanity test 160j: client can be umounted while its chanangelog is being used ========================================================== 20:11:18 (1788480678) [17403.706782] Lustre: Mounted lustre-client - version 2.17.58_2_gdacfdd2 [17408.156251] Lustre: Unmounted lustre-client [17415.419985] Lustre: Mounted lustre-client - version 2.17.58_2_gdacfdd2 [17419.637982] Lustre: Unmounted lustre-client [17421.591879] Lustre: DEBUG MARKER: == sanity test 160k: Verify that changelog records are not lost ========================================================== 20:11:37 (1788480697) [17443.333537] Lustre: DEBUG MARKER: == sanity test 160l: Verify that MTIME changelog records contain the parent FID ========================================================== 20:11:58 (1788480718) [17464.212208] Lustre: DEBUG MARKER: == sanity test 160m: Changelog clear race ================ 20:12:19 (1788480739) [17492.909449] Lustre: DEBUG MARKER: == sanity test 160n: Changelog destroy race ============== 20:12:48 (1788480768) [19864.886902] Lustre: DEBUG MARKER: == sanity test 160o: changelog user name and mask ======== 20:52:20 (1788483140) [19902.034365] Lustre: DEBUG MARKER: == sanity test 160p: Changelog orphan cleanup with no users ========================================================== 20:52:57 (1788483177) [19904.114809] Lustre: DEBUG MARKER: SKIP: sanity test_160p ldiskfs only test [19906.162938] Lustre: DEBUG MARKER: == sanity test 160q: changelog effective mask is DEFMASK if not set ========================================================== 20:53:01 (1788483181) [19919.476620] Lustre: DEBUG MARKER: == sanity test 160s: changelog garbage collect on idle records * time ========================================================== 20:53:15 (1788483195) [19959.216789] Lustre: DEBUG MARKER: == sanity test 160t: changelog garbage collect on lack of space ========================================================== 20:53:54 (1788483234) [20084.378058] Lustre: DEBUG MARKER: == sanity test 160u: changelog rename record type name and sname strings are correct ========================================================== 20:56:00 (1788483360) [20103.820306] Lustre: DEBUG MARKER: == sanity test 160v: setattr preserves mtime update despite inter-client clock skew ========================================================== 20:56:18 (1788483378) [20106.241985] Lustre: DEBUG MARKER: SKIP: sanity test_160v need >= 2 clients [20108.516853] Lustre: DEBUG MARKER: == sanity test 160w: lfs changelog --user --mask ========= 20:56:23 (1788483383) [20136.197814] Lustre: DEBUG MARKER: == sanity test 160x: changelog users do not disappear ==== 20:56:51 (1788483411) [20197.654942] Lustre: DEBUG MARKER: == sanity test 161a: link ea sanity ====================== 20:57:53 (1788483473) [20242.364917] Lustre: DEBUG MARKER: == sanity test 161b: link ea sanity under remote directory ========================================================== 20:58:37 (1788483517) [20243.985456] Lustre: DEBUG MARKER: SKIP: sanity test_161b skipping remote directory test [20246.134824] Lustre: DEBUG MARKER: == sanity test 161c: check CL_RENME[UNLINK] changelog record flags ========================================================== 20:58:41 (1788483521) [20264.127687] Lustre: DEBUG MARKER: == sanity test 161d: create with concurrent .lustre/fid access ========================================================== 20:58:59 (1788483539) [20267.776152] LustreError: 344445:0:(namei.c:1587:ll_create_node()) cfs_fail_timeout id 140c sleeping for 5000ms [20270.400890] LustreError: 344445:0:(namei.c:1587:ll_create_node()) cfs_fail_timeout interrupted [20280.058262] Lustre: DEBUG MARKER: == sanity test 162a: path lookup sanity ================== 20:59:15 (1788483555) [20290.189138] Lustre: DEBUG MARKER: == sanity test 162b: striped directory path lookup sanity ========================================================== 20:59:25 (1788483565) [20292.708145] Lustre: DEBUG MARKER: SKIP: sanity test_162b needs >= 2 MDTs [20295.275187] Lustre: DEBUG MARKER: == sanity test 162c: fid2path works with paths 100 or more directories deep ========================================================== 20:59:30 (1788483570) [20370.116641] Lustre: DEBUG MARKER: == sanity test 165a: ofd access log discovery ============ 21:00:44 (1788483644) [20380.149555] Lustre: lustre-OST0000-osc-ffff9a44f404d800: Connection to lustre-OST0000 (at 192.168.206.103@tcp) was lost; in progress operations using this service will wait for recovery to complete [20417.684707] Lustre: DEBUG MARKER: == sanity test 165b: ofd access log entries are produced and consumed ========================================================== 21:01:33 (1788483693) [20456.954289] Lustre: lustre-OST0000-osc-ffff9a44f404d800: Connection to lustre-OST0000 (at 192.168.206.103@tcp) was lost; in progress operations using this service will wait for recovery to complete [20465.841533] Lustre: lustre-OST0000-osc-ffff9a44f404d800: Connection restored to 192.168.206.103@tcp (at 192.168.206.103@tcp) [20476.052698] Lustre: DEBUG MARKER: == sanity test 165c: full ofd access logs do not block IOs ========================================================== 21:02:31 (1788483751) [20513.268889] Lustre: lustre-OST0000-osc-ffff9a44f404d800: Connection to lustre-OST0000 (at 192.168.206.103@tcp) was lost; in progress operations using this service will wait for recovery to complete [20523.982692] Lustre: lustre-OST0000-osc-ffff9a44f404d800: Connection restored to 192.168.206.103@tcp (at 192.168.206.103@tcp) [20533.779787] Lustre: DEBUG MARKER: == sanity test 165d: ofd_access_log mask works =========== 21:03:28 (1788483808) [20584.944704] Lustre: lustre-OST0000-osc-ffff9a44f404d800: Connection to lustre-OST0000 (at 192.168.206.103@tcp) was lost; in progress operations using this service will wait for recovery to complete [20595.008421] Lustre: lustre-OST0000-osc-ffff9a44f404d800: Connection restored to 192.168.206.103@tcp (at 192.168.206.103@tcp) [20604.332560] Lustre: DEBUG MARKER: == sanity test 165e: ofd_access_log MDT index filter works ========================================================== 21:04:39 (1788483879) [20606.785488] Lustre: DEBUG MARKER: SKIP: sanity test_165e needs >= 2 MDTs [20608.903564] Lustre: DEBUG MARKER: == sanity test 165f: ofd_access_log_reader --exit-on-close works ========================================================== 21:04:44 (1788483884) [20620.787344] Lustre: lustre-OST0000-osc-ffff9a44f404d800: Connection to lustre-OST0000 (at 192.168.206.103@tcp) was lost; in progress operations using this service will wait for recovery to complete [20644.962724] Lustre: lustre-OST0000-osc-ffff9a44f404d800: Connection restored to 192.168.206.103@tcp (at 192.168.206.103@tcp) [20654.272772] Lustre: DEBUG MARKER: == sanity test 165g: ofd_access_log_reader --keepalive works ========================================================== 21:05:29 (1788483929) [20702.696869] Lustre: lustre-OST0000-osc-ffff9a44f404d800: Connection to lustre-OST0000 (at 192.168.206.103@tcp) was lost; in progress operations using this service will wait for recovery to complete [20720.310081] Lustre: lustre-OST0000-osc-ffff9a44f404d800: Connection restored to 192.168.206.103@tcp (at 192.168.206.103@tcp) [20732.656319] Lustre: DEBUG MARKER: == sanity test 169: parallel read and truncate should not deadlock ========================================================== 21:06:47 (1788484007) [20735.173094] Lustre: DEBUG MARKER: creating a 10 Mb file [20826.649824] Lustre: DEBUG MARKER: starting reads [20829.966162] Lustre: DEBUG MARKER: truncating the file [20832.551545] Lustre: DEBUG MARKER: killing dd [20834.177415] Lustre: DEBUG MARKER: removing the temporary file [20842.003444] Lustre: DEBUG MARKER: == sanity test 170a: test lctl df to handle corrupted log ========================================================== 21:08:37 (1788484117) [20842.510488] Lustre: debug daemon will attempt to start writing to /tmp/f170a.sanity_log_good (512000kB max) [20842.682431] Lustre: shutting down debug daemon thread... [20842.778988] Lustre: debug daemon will attempt to start writing to /tmp/f170a.sanity_log_good (512000kB max) [20842.885394] Lustre: shutting down debug daemon thread... [20852.636503] Lustre: DEBUG MARKER: == sanity test 170b: check filename encoding ============= 21:08:48 (1788484128) [20886.952632] Lustre: DEBUG MARKER: == sanity test 171: test libcfs_debug_dumplog_thread stuck in do_exit() ================================================================ 21:09:22 (1788484162) [20887.432816] LustreError: 358094:0:(file.c:513:ll_file_release()) cfs_fail_timeout id 50e sleeping for 3000ms [20890.464127] LustreError: 358094:0:(file.c:513:ll_file_release()) cfs_fail_timeout id 50e awake [20890.471552] LustreError: dumping log to /tmp/lustre-log.1788484167.358094 [20897.220690] Lustre: DEBUG MARKER: == sanity test 172: manual device removal with lctl cleanup/detach ================================================================ 21:09:32 (1788484172) [20899.460372] Lustre: *** cfs_fail_loc=60e, val=0*** [20899.464903] Lustre: Unmounted lustre-client [20905.359107] Lustre: Mounted lustre-client - version 2.17.58_2_gdacfdd2 [20907.592959] Lustre: DEBUG MARKER: == sanity test 180a: test obdecho on osc ================= 21:09:43 (1788484183) [20909.758515] Lustre: DEBUG MARKER: SKIP: sanity test_180a obdecho on osc is no longer supported [20911.664843] Lustre: DEBUG MARKER: == sanity test 180b: test obdecho directly on obdfilter == 21:09:47 (1788484187) [20938.339518] Lustre: DEBUG MARKER: == sanity test 180c: test huge bulk I/O size on obdfilter, don't LASSERT ========================================================== 21:10:14 (1788484214) [20964.131465] Lustre: DEBUG MARKER: == sanity test 181: Test open-unlinked dir ================================================================================== 21:10:39 (1788484239) [21079.497420] Lustre: DEBUG MARKER: == sanity test 182a: Test parallel modify metadata operations from mdc ========================================================== 21:12:35 (1788484355) [21207.760995] Lustre: DEBUG MARKER: == sanity test 182b: Test parallel modify metadata operations from osp ========================================================== 21:14:43 (1788484483) [21210.316734] Lustre: DEBUG MARKER: SKIP: sanity test_182b needs >= 2 MDTs [21212.874917] Lustre: DEBUG MARKER: == sanity test 183: No crash or request leak in case of strange dispositions ================================================================== 21:14:48 (1788484488) [21227.169809] Lustre: DEBUG MARKER: == sanity test 184a: Basic layout swap =================== 21:15:02 (1788484502) [21240.821141] Lustre: DEBUG MARKER: == sanity test 184b: Forbidden layout swap (will generate errors) ========================================================== 21:15:16 (1788484516) [21249.918938] Lustre: DEBUG MARKER: == sanity test 184c: Concurrent write and layout swap ==== 21:15:25 (1788484525) [21298.545114] Lustre: DEBUG MARKER: == sanity test 184d: allow stripeless layouts swap ======= 21:16:14 (1788484574) [21322.942149] Lustre: DEBUG MARKER: == sanity test 184e: Recreate layout after stripeless layout swaps ========================================================== 21:16:38 (1788484598) [21345.519256] Lustre: DEBUG MARKER: == sanity test 184f: IOC_MDC_GETFILEINFO for files with long names but no striping ========================================================== 21:17:01 (1788484621) [21353.045328] Lustre: DEBUG MARKER: == sanity test 185: Volatile file support ================ 21:17:08 (1788484628) [21361.980643] Lustre: DEBUG MARKER: == sanity test 185a: Volatile file creation in .lustre/fid/ ========================================================== 21:17:17 (1788484637) [21373.257629] Lustre: DEBUG MARKER: == sanity test 187a: Test data version change ============ 21:17:28 (1788484648) [21384.377592] Lustre: DEBUG MARKER: == sanity test 187b: Test data version change on volatile file ========================================================== 21:17:39 (1788484659) [21392.644398] Lustre: DEBUG MARKER: == sanity test 190a: check lfs project -p works with project name ========================================================== 21:17:48 (1788484668) [21400.284762] Lustre: DEBUG MARKER: == sanity test 190b: check lfs find --project works with project name ========================================================== 21:17:55 (1788484675) [21497.793608] Lustre: DEBUG MARKER: == sanity test 190c: check lfs project -p works with u:USERNAME ========================================================== 21:19:32 (1788484772) [21517.302333] Lustre: DEBUG MARKER: == sanity test complete, duration 21259 sec ============== 21:19:52 (1788484792) [21519.601786] Lustre: DEBUG MARKER: === sanity: start cleanup 21:19:54 (1788484794) === [21571.411266] Lustre: DEBUG MARKER: === sanity: finish cleanup 21:20:46 (1788484846) === [21574.379661] Lustre: Unmounted lustre-client [21601.966425] Key type lgssc unregistered [21602.220256] LNet: 377166:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [21602.234721] LNetError: 377166:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [21602.259080] LNet: Removed LNI 192.168.206.3@tcp [21603.250154] Key type .llcrypt unregistered [21603.252156] Key type ._llcrypt unregistered