[ 0.000000] Linux version 4.18.0rh8.10-debug (green@maintenance) (gcc version 8.5.0 20210514 (Red Hat 8.5.0-26) (GCC)) #2 SMP Mon Jul 14 01:24:22 EDT 2025 [ 0.000000] Command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers' [ 0.000000] x86/fpu: xstate_offset[2]: 576, xstate_sizes[2]: 256 [ 0.000000] x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'standard' format. [ 0.000000] signal: max sigframe size: 1776 [ 0.000000] BIOS-provided physical RAM map: [ 0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable [ 0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000000100000-0x00000000bffd9fff] usable [ 0.000000] BIOS-e820: [mem 0x00000000bffda000-0x00000000bfffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000100000000-0x0000000146dfffff] usable [ 0.000000] NX (Execute Disable) protection: active [ 0.000000] SMBIOS 2.8 present. [ 0.000000] DMI: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.17.0-8.fc42 06/10/2025 [ 0.000000] Hypervisor detected: KVM [ 0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00 [ 0.000000] kvm-clock: using sched offset of 559407339 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2399.998 MHz processor [ 0.000000] last_pfn = 0x146e00 max_arch_pfn = 0x400000000 [ 0.000000] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT [ 0.000000] last_pfn = 0xbffda max_arch_pfn = 0x400000000 [ 0.000000] found SMP MP-table at [mem 0x000f54d0-0x000f54df] [ 0.000000] RAMDISK: [mem 0xbcc64000-0xbffcffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F52F0 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE2421 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE22BD 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 00227D (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE2331 000090 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE23C1 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE23F9 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe22bd-0xbffe2330] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe22bc] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe2331-0xbffe23c0] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe23c1-0xbffe23f8] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe23f9-0xbffe2420] [ 0.000000] No NUMA configuration found [ 0.000000] Faking a node at [mem 0x0000000000000000-0x0000000146dfffff] [ 0.000000] NODE_DATA(0) allocated [mem 0x1465a3000-0x1465cdfff] [ 0.000000] Reserving 256MB of memory at 2752MB for crashkernel (System RAM: 4205MB) [ 0.000000] Zone ranges: [ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.000000] DMA32 [mem 0x0000000001000000-0x00000000ffffffff] [ 0.000000] Normal [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Device empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff] [ 0.000000] node 0: [mem 0x0000000000100000-0x00000000bffd9fff] [ 0.000000] node 0: [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Zeroed struct page in unavailable ranges: 4744 pages [ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x0000000146dfffff] [ 0.000000] ACPI: PM-Timer IO Port: 0x608 [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) [ 0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) [ 0.000000] Using ACPI (MADT) for SMP configuration information [ 0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000] TSC deadline timer available [ 0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs [ 0.000000] kvm-guest: KVM setup pv remote TLB flush [ 0.000000] kvm-guest: setup PV sched yield [ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff] [ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff] [ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff] [ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff] [ 0.000000] PM: Registered nosave memory: [mem 0xbffda000-0xbfffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xc0000000-0xfeffbfff] [ 0.000000] PM: Registered nosave memory: [mem 0xfeffc000-0xfeffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xff000000-0xfffbffff] [ 0.000000] PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff] [ 0.000000] [mem 0xc0000000-0xfeffbfff] available for PCI devices [ 0.000000] Booting paravirtualized kernel on KVM [ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns [ 0.000000] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1 [ 0.000000] percpu: Embedded 63 pages/cpu s221184 r8192 d28672 u524288 [ 0.000000] kvm-guest: PV spinlocks enabled [ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1059618 [ 0.000000] Policy zone: Normal [ 0.000000] Kernel command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] Specific versions of hardware are certified with Red Hat Enterprise Linux 8. Please see the list of hardware certified with Red Hat Enterprise Linux 8 at https://catalog.redhat.com. [ 0.000000] audit: disabled (until reboot) [ 0.000000] software IO TLB: area num 4. [ 0.000000] Memory: 2829700K/4306400K available (18435K kernel code, 11221K rwdata, 7248K rodata, 2908K init, 18040K bss, 524580K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] ftrace: allocating 41240 entries in 162 pages [ 0.000000] ftrace: allocated 162 pages with 3 groups [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] rcu: RCU event tracing is enabled. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ 0.000000] rcu: RCU callback double-/use-after-free debug enabled. [ 0.000000] Rude variant of Tasks RCU enabled. [ 0.000000] Tracing variant of Tasks RCU enabled. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 0.000000] NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16 [ 0.000000] random: get_random_bytes called from start_kernel+0x622/0x9a8 with crng_init=0 [ 0.001000] Console: colour *CGA 80x25 [ 0.001000] printk: console [ttyS1] enabled [ 0.001000] ACPI: Core revision 20220331 [ 0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.001011] APIC: Switch to symmetric I/O mode setup [ 0.003334] x2apic enabled [ 0.004008] Switched APIC routing to physical x2apic. [ 0.005012] kvm-guest: setup PV IPIs [ 0.008449] ..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.009022] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.010012] pid_max: default: 32768 minimum: 301 [ 0.011137] LSM: Security Framework initializing [ 0.012058] Yama: becoming mindful. [ 0.013036] SELinux: Initializing. [ 0.014078] *** VALIDATE selinux *** [ 0.023384] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.028517] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.029144] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.030117] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.031117] *** VALIDATE tmpfs *** [ 0.032474] *** VALIDATE proc *** [ 0.034204] *** VALIDATE cgroup *** [ 0.035010] *** VALIDATE cgroup2 *** [ 0.037186] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.038161] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.039011] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.040030] Spectre V2 : User space: Vulnerable [ 0.041010] Speculative Store Bypass: Vulnerable [ 0.044011] debug: unmapping init [mem 0xffffffffb3859000-0xffffffffb3860fff] [ 0.047000] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.047795] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.048028] ... version: 2 [ 0.049014] ... bit width: 48 [ 0.050012] ... generic registers: 4 [ 0.051013] ... value mask: 0000ffffffffffff [ 0.052013] ... max period: 00007fffffffffff [ 0.053016] ... fixed-purpose events: 3 [ 0.054010] ... event mask: 000000070000000f [ 0.055303] rcu: Hierarchical SRCU implementation. [ 0.057669] smp: Bringing up secondary CPUs ... [ 0.058625] x86: Booting SMP configuration: [ 0.059025] .... node #0, CPUs: #1 #2 #3 [ 0.063231] smp: Brought up 1 node, 4 CPUs [ 0.065014] smpboot: Max logical packages: 1 [ 0.066016] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.094019] node 0 deferred pages initialised in 26ms [ 0.097356] devtmpfs: initialized [ 0.098272] x86/mm: Memory block size: 128MB [ 0.101137] gcov: version magic: 0x41383552 [ 0.103182] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.104083] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.105278] pinctrl core: initialized pinctrl subsystem [ 0.106295] [ 0.106932] ************************************************************* [ 0.107015] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.108013] ** ** [ 0.109012] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.110018] ** ** [ 0.111011] ** This means that this kernel is built to expose internal ** [ 0.112018] ** IOMMU data structures, which may compromise security on ** [ 0.113016] ** your system. ** [ 0.114014] ** ** [ 0.115016] ** If you see this message and you are not debugging the ** [ 0.116015] ** kernel, report this immediately to your vendor! ** [ 0.117016] ** ** [ 0.118018] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.119015] ************************************************************* [ 0.120913] NET: Registered protocol family 16 [ 0.121536] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.122046] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.123049] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.125123] cpuidle: using governor menu [ 0.126923] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.130609] PCI: Using configuration type 1 for base access [ 0.133211] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.145027] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.148015] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.152156] cryptd: max_cpu_qlen set to 1000 [ 0.154057] ACPI: Added _OSI(Module Device) [ 0.155008] ACPI: Added _OSI(Processor Device) [ 0.156029] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.157016] ACPI: Added _OSI(Processor Aggregator Device) [ 0.162368] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.166794] ACPI: Interpreter enabled [ 0.167068] ACPI: PM: (supports S0 S3 S4 S5) [ 0.168013] ACPI: Using IOAPIC for interrupt routing [ 0.169098] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.170401] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.185951] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.187047] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.188100] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.189077] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.192266] acpiphp: Slot [2] registered [ 0.193180] acpiphp: Slot [5] registered [ 0.194147] acpiphp: Slot [6] registered [ 0.196086] acpiphp: Slot [3] registered [ 0.197054] acpiphp: Slot [4] registered [ 0.198070] acpiphp: Slot [7] registered [ 0.199177] acpiphp: Slot [8] registered [ 0.201107] acpiphp: Slot [9] registered [ 0.203109] acpiphp: Slot [10] registered [ 0.205142] acpiphp: Slot [11] registered [ 0.207189] acpiphp: Slot [12] registered [ 0.209156] acpiphp: Slot [13] registered [ 0.211227] acpiphp: Slot [14] registered [ 0.212104] acpiphp: Slot [15] registered [ 0.214111] acpiphp: Slot [16] registered [ 0.216108] acpiphp: Slot [17] registered [ 0.218124] acpiphp: Slot [18] registered [ 0.220109] acpiphp: Slot [19] registered [ 0.222095] acpiphp: Slot [20] registered [ 0.223252] acpiphp: Slot [21] registered [ 0.225122] acpiphp: Slot [22] registered [ 0.227234] acpiphp: Slot [23] registered [ 0.229253] acpiphp: Slot [24] registered [ 0.231285] acpiphp: Slot [25] registered [ 0.233120] acpiphp: Slot [26] registered [ 0.235292] acpiphp: Slot [27] registered [ 0.237241] acpiphp: Slot [28] registered [ 0.238440] acpiphp: Slot [29] registered [ 0.241109] acpiphp: Slot [30] registered [ 0.242104] acpiphp: Slot [31] registered [ 0.243088] PCI host bridge to bus 0000:00 [ 0.245022] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.248025] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.251026] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.254030] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.257028] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.261054] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.263406] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.267506] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.271538] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.281504] pci 0000:00:01.1: reg 0x20: [io 0xc120-0xc12f] [ 0.286062] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.289023] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.292023] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.295019] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.298145] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.300997] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.304295] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.307840] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.312013] pci 0000:00:02.0: reg 0x10: [io 0xc100-0xc11f] [ 0.325016] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.330011] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.335280] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.342016] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.347015] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.361017] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.370541] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.376015] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.380017] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.393016] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.403617] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.406496] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.408428] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.410286] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.412292] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.416212] iommu: Default domain type: Passthrough [ 0.419584] SCSI subsystem initialized [ 0.422139] ACPI: bus type USB registered [ 0.423118] usbcore: registered new interface driver usbfs [ 0.425078] usbcore: registered new interface driver hub [ 0.427102] usbcore: registered new device driver usb [ 0.428159] pps_core: LinuxPPS API ver. 1 registered [ 0.431014] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.435067] PTP clock support registered [ 0.437355] EDAC MC: Ver: 3.0.0 [ 0.438140] PCI: Using ACPI for IRQ routing [ 0.441432] NetLabel: Initializing [ 0.443145] NetLabel: domain hash size = 128 [ 0.445012] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.447075] NetLabel: unlabeled traffic allowed by default [ 0.450560] vgaarb: loaded [ 0.453009] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.455009] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.464326] clocksource: Switched to clocksource kvm-clock [ 0.605761] VFS: Disk quotas dquot_6.6.0 [ 0.607336] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.610120] *** VALIDATE ramfs *** [ 0.611715] *** VALIDATE hugetlbfs *** [ 0.613338] pnp: PnP ACPI init [ 0.616107] pnp: PnP ACPI: found 6 devices [ 0.634792] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.638548] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.640945] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.643086] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.645296] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.647981] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.649666] NET: Registered protocol family 2 [ 0.686220] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.691896] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.696183] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.703390] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.707318] TCP: Hash tables configured (established 65536 bind 65536) [ 0.709962] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.712252] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.714481] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.717952] NET: Registered protocol family 1 [ 0.720811] RPC: Registered named UNIX socket transport module. [ 0.726678] RPC: Registered udp transport module. [ 0.728399] RPC: Registered tcp transport module. [ 0.729973] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.732615] NET: Registered protocol family 44 [ 0.734302] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.736846] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.739080] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.741311] PCI: CLS 0 bytes, default 64 [ 0.742870] Unpacking initramfs... [ 2.364320] debug: unmapping init [mem 0xffff9e34fcc64000-0xffff9e34fffcffff] [ 2.368348] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.370022] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.372104] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 2.878441] Initialise system trusted keyrings [ 2.879900] Key type blacklist registered [ 2.881314] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.889463] zbud: loaded [ 2.892022] *** VALIDATE nfs *** [ 2.893052] *** VALIDATE nfs4 *** [ 2.894201] pstore: using deflate compression [ 2.897175] Platform Keyring initialized [ 3.005679] NET: Registered protocol family 38 [ 3.006891] Key type asymmetric registered [ 3.173465] Asymmetric key parser 'x509' registered [ 3.188445] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 3.203025] io scheduler mq-deadline registered [ 3.207430] io scheduler kyber registered [ 3.262668] io scheduler bfq registered [ 3.312093] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 3.315369] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 3.318955] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 3.321879] ACPI: Power Button [PWRF] [ 3.329884] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 3.340884] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 3.412268] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 3.441803] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.471493] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.476652] Non-volatile memory driver v1.3 [ 3.478174] Linux agpgart interface v0.103 [ 3.507946] virtio_blk virtio1: [vda] 141800 512-byte logical blocks (72.6 MB/69.2 MiB) [ 3.510464] vda: detected capacity change from 0 to 72601600 [ 3.528968] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.530946] vdb: detected capacity change from 0 to 1073741824 [ 3.535398] libphy: Fixed MDIO Bus: probed [ 3.561786] usbcore: registered new interface driver usbserial_generic [ 3.567324] usbserial: USB Serial support registered for generic [ 3.571908] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.580521] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.583151] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.588267] mousedev: PS/2 mouse device common for all mice [ 3.592990] rtc_cmos 00:05: RTC can wake from S4 [ 3.598643] rtc_cmos 00:05: registered as rtc0 [ 3.599852] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.603662] intel_pstate: CPU model not supported [ 3.606370] hid: raw HID events driver (C) Jiri Kosina [ 3.608405] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.610848] usbcore: registered new interface driver usbhid [ 3.616254] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.617595] usbhid: USB HID core driver [ 3.622452] drop_monitor: Initializing network drop monitor service [ 3.625705] Initializing XFRM netlink socket [ 3.627520] NET: Registered protocol family 10 [ 3.629843] Segment Routing with IPv6 [ 3.631115] NET: Registered protocol family 17 [ 3.632825] mpls_gso: MPLS GSO support [ 3.635225] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.641773] RAS: Correctable Errors collector initialized. [ 3.643208] AVX version of gcm_enc/dec engaged. [ 3.644314] AES CTR mode by8 optimization enabled [ 3.726766] sched_clock: Marking stable (3726734435, 0)->(4755698125, -1028963690) [ 3.730981] registered taskstats version 1 [ 3.732983] Loading compiled-in X.509 certificates [ 3.734938] zswap: loaded using pool lzo/zbud [ 3.762419] Key type big_key registered [ 3.775594] Key type encrypted registered [ 3.777350] ima: No TPM chip found, activating TPM-bypass! [ 3.779265] ima: Allocated hash algorithm: sha1 [ 3.780716] ima: No architecture policies found [ 3.782348] evm: Initialising EVM extended attributes: [ 3.783921] evm: security.selinux [ 3.784893] evm: security.ima [ 3.785852] evm: security.capability [ 3.786892] evm: HMAC attrs: 0x1 [ 3.789262] rtc_cmos 00:05: setting system clock to 2026-05-18 08:35:03 UTC (1779093303) [ 3.796734] debug: unmapping init [mem 0xffffffffb4803000-0xffffffffb49fffff] [ 3.799698] debug: unmapping init [mem 0xffffffffb3582000-0xffffffffb3858fff] [ 3.806166] Write protecting the kernel read-only data: 28672k [ 3.809328] debug: unmapping init [mem 0xffffffffb1c03000-0xffffffffb1dfffff] [ 3.811514] debug: unmapping init [mem 0xffffffffb2514000-0xffffffffb25fffff] [ 3.843169] 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.849828] systemd[1]: Detected virtualization kvm. [ 3.851380] systemd[1]: Detected architecture x86-64. [ 3.852821] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.878899] systemd[1]: No hostname configured. [ 3.880287] systemd[1]: Set hostname to . [ 3.881994] random: systemd: uninitialized urandom read (16 bytes read) [ 3.884185] systemd[1]: Initializing machine ID from random generator. [ 4.051464] random: systemd: uninitialized urandom read (16 bytes read) [ 4.053884] systemd[1]: Listening on Journal Socket (/dev/log). [ OK ] Listening on Journal Socket (/dev/log). [ 4.058791] random: systemd: uninitialized urandom read (16 bytes read) [ 4.060703] systemd[1]: Started Dispatch Password Requests to Console Directory Watch. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ 4.065224] systemd[1]: Reached target Swap. [ OK ] Reached target Swap. [ OK ] Listening on udev Control Socket. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Listening on udev Kernel Socket. [ OK ] Reached target Slices. [ OK ] Reached target Initrd Root Device. [ OK ] Reached target Local File Systems. [ OK ] Reached target Paths. [ OK ] Listening on Journal Socket. [ OK ] Started Memstrack Anylazing Service. Starting Apply Kernel Variables... [ OK ] Reached target Sockets. Starting Setup Virtual Console... Starting Create list of required st…ce nodes for the current kernel... Starting Create Volatile Files and Directories... Starting Journal Service... [ OK ] Reached target Timers. [ OK ] Started Apply Kernel Variables. [ OK ] Started Setup Virtual Console. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Create Volatile Files and Directories. 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.782405] device-mapper: uevent: version 1.0.3 [ 4.787636] device-mapper: ioctl: 4.46.0-ioctl (2022-02-22) initialised: dm-devel@redhat.com [ OK ] Started dracut pre-udev hook. Starting udev Kernel Device Manager... [ OK ] Started udev Kernel Device Manager. Starting dracut pre-trigger hook... [ OK ] Started dracut pre-trigger hook. Starting udev Coldplug all Devices... Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. Starting dracut initqueue hook... [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ 5.534320] virtio_net virtio0 ens2: renamed from eth0 [ 5.570235] random: fast init done [ 5.620318] scsi host0: ata_piix [ 5.680759] scsi host1: ata_piix [ 5.683639] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc120 irq 14 [ 5.689304] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc128 irq 15 [ 10.501215] random: crng init done [ 10.502910] random: 7 urandom warning(s) missed due to ratelimiting [ 10.654333] dracut-initqueue[580]: RTNETLINK answers: File exists Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. Mounting /sysroot... [ OK ] Reached target Remote File Systems (Pre). [ OK [ 13.080466] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) ] Reached target Remote File Systems. [ 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. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped target Basic System. [ OK ] Stopped target Sockets. [ OK ] Stopped target Slices. [ OK ] Stopped target Paths. [ OK ] Stopped target System Initialization. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. Stopping udev Kernel Device Manager... [ OK ] Stopped target Swap. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Closed udev Control Socket. [ OK ] Closed udev Kernel Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 17.062225] printk: systemd: 26 output lines suppressed due to ratelimiting [ 18.241452] SELinux: Disabled at runtime. [ 18.411991] 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) [ 18.453849] systemd[1]: Detected virtualization kvm. [ 18.460301] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 20.840097] systemd[1]: initrd-switch-root.service: Succeeded. [ 20.845602] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 20.858378] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 20.870351] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 20.883153] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 20.904719] systemd[1]: Starting Journal Service... Starting Journal Service... [ 20.922995] systemd[1]: Listening on udev Kernel Socket. [ OK ] Listening on udev Kernel Socket. Starting Remount Root and Kernel File Systems... [ OK ] Listening on udev Control Socket. Starting udev Coldplug all Devices... [ OK ] Reached target rpc_pipefs.target. [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd Root File System. Mounting Kernel Debug File System... [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Listening on Process Core Dump Socket. [ OK ] Created slice User and Session Slice. [ OK ] Reached target Slices. [ OK ] Stopped target Initrd File Systems. [ OK ] Created slice system-getty.slice. Mounting POSIX Message Queue File System... Starting Apply Kernel Variables... [ OK ] Started Dispatch Password Requests to Console Directory Watch. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Reached target RPC Port Mapper. Activating swap /dev/disk/by-label/SWAP... [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 Forward Password Requests to Wall Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ 21.585908] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS [ OK ] Reached target Paths. [ OK ] Listening on initctl Compatibility Named Pipe. Mounting Huge Pages File System... [ OK ] Started Journal Service. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Mounted Kernel Debug File System. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Started Apply Kernel Variables. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Mounted Huge Pages File System. [ OK ] Reached target Swap. Starting Create Static Device Nodes in /dev... Starting Configure read-only root support... Starting Flush Journal to Persistent Storage... [ OK ] Started udev Coldplug all Devices. [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Reached target Local File Systems (Pre). Mounting /home/green/git/lustre-release... Mounting /mnt... Starting udev Kernel Device Manager... [ OK ] Mounted /mnt. [ 22.877327] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 24.340971] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 24.386768] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 24.967178] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 25.090275] EDAC sbridge: Ver: 1.1.2 [* ] A start job is running for Configur…-only root support (8s / no limit)[ 29.336661] Key type dns_resolver registered [** ] A start job is running for Configur…-only root support (8s / no limit) [*** ] A start job is running for Configur…-only root support (9s / no limit)[ 30.196085] NFS: Registering the id_resolver key type [ 30.206345] Key type id_resolver registered [ 30.211228] Key type id_legacy registered [ *** ] A start job is running for Configur…-only root support (9s / no limit) [ OK ] Started Configure read-only root support. Starting Load/Save Random Seed... [ OK ] Reached target Local File Systems. Starting Mark the need to relabel after reboot... Starting Rebuild Dynamic Linker Cache... Starting Create Volatile Files and Directories... [ OK ] Started Load/Save Random Seed. [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Create Volatile Files and Directories. Starting RPC Bind... Starting Update UTMP about System Boot/Shutdown... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Started dnf makecache --timer. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Reached target Timers. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. [ OK ] Started D-Bus System Message Bus. Starting Login Service... [ OK ] Reached target sshd-keygen.target. [ OK ] Started irqbalance daemon. Starting Restore /run/initramfs on shutdown... [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting Network Manager... [ OK ] Started Restore /run/initramfs on shutdown. [ 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. [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Started Login Service. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... Starting Hostname Service... [ OK ] Started Permit User Sessions. [ OK ] Started Command Scheduler. [ OK ] Started Serial Getty on ttyS1. [ OK ] Started Getty on tty1. [ OK ] Started Serial Getty on ttyS0. [ OK ] Reached target Login Prompts. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting Crash recovery kernel arming... Starting Notify NFS peers of a restart... Starting System Logging Service... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg231-client login: [ 89.875597] hrtimer: interrupt took 1693781 ns [ 106.292139] libcfs: loading out-of-tree module taints kernel. [ 106.588300] Key type ._llcrypt registered [ 106.613448] Key type .llcrypt registered [ 107.140203] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [ 107.150473] alg: No test for adler32 (adler32-zlib) [ 109.460347] Lustre: Lustre: Build Version: 2.17.53_24_g2ff46d7 [ 110.258322] LNet: Added LNI 192.168.202.31@tcp [8/256/0/180] [ 112.072121] Key type lgssc registered [ 114.906519] Lustre: Echo OBD driver; http://www.lustre.org/ [ 325.600141] Lustre: Mounted lustre-client [ 333.505588] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 351.202069] Lustre: lustre-OST0000-osc-ffff9e35488c5800: disconnect after 22s idle [ 355.087241] Lustre: DEBUG MARKER: oleg231-client.virtnet: executing check_logdir /tmp/testlogs/ [ 362.662376] Lustre: DEBUG MARKER: oleg231-client.virtnet: executing yml_node [ 368.214327] Lustre: DEBUG MARKER: Client: 2.17.53.24 [ 371.232354] Lustre: DEBUG MARKER: MDS: 2.17.53.24 [ 374.797772] Lustre: DEBUG MARKER: OSS: 2.17.53.24 [ 376.972522] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity ============----- Mon May 18 04:41:14 EDT 2026 [ 398.651052] Lustre: DEBUG MARKER: - need MDS1_VERSION <= 2.16.61-1-g89cf292a8c2 (34682136 <= 34618625) for LU-18938, skip 360 [ 400.594809] Lustre: DEBUG MARKER: - need MDS1_VERSION < v2_14_55-100-g8a84c7f9c7 (34682136 < 34486116) for LU-14927, skip 0f [ 402.642200] Lustre: DEBUG MARKER: excepting tests: 42a 42c 42b 118c 118d 407 119i 817 411a [ 404.292825] Lustre: DEBUG MARKER: skipping tests SLOW=no: 27m 60i 64b 68 71 135 136 230d 300o 842 51c 51e 834 [ 406.008903] Lustre: DEBUG MARKER: === sanity: start setup 04:41:44 (1779093704) === [ 410.444750] Lustre: DEBUG MARKER: oleg231-client.virtnet: executing check_config_client /mnt/lustre [ 433.081482] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 447.731352] Lustre: DEBUG MARKER: === sanity: finish setup 04:42:26 (1779093746) === [ 455.569373] Lustre: DEBUG MARKER: == sanity test 60a: llog_test run from kernel module and test llog_reader ========================================================== 04:42:33 (1779093753) [ 459.470569] Lustre: DEBUG MARKER: SKIP: sanity test_60a missing subtest run-llog.sh [ 461.771037] Lustre: DEBUG MARKER: == sanity test 60b: limit repeated messages from CERROR/CWARN ========================================================== 04:42:39 (1779093759) [ 468.987595] Lustre: lustre-OST0000-osc-ffff9e35488c5800: disconnect after 21s idle [ 468.994165] Lustre: Skipped 1 previous similar message [ 469.781661] Lustre: DEBUG MARKER: == sanity test 60c: unlink file when mds full ============ 04:42:48 (1779093768) [ 682.502923] Lustre: DEBUG MARKER: == sanity test 60d: test printk console message masking == 04:46:20 (1779093980) [ 682.758816] Lustre: DEBUG MARKER: test message ID 24882 8246 [ 689.238397] Lustre: DEBUG MARKER: == sanity test 60e: no space while new llog is being created ========================================================== 04:46:27 (1779093987) [ 697.778640] Lustre: DEBUG MARKER: == sanity test 60f: change debug_path works ============== 04:46:35 (1779093995) [ 698.581372] LustreError: dumping log to /tmp/f60f.sanity.1779093998.14621 [ 706.294778] Lustre: DEBUG MARKER: == sanity test 60g: transaction abort won't cause MDT hung ========================================================== 04:46:44 (1779094004) [ 818.444391] Lustre: dir [0x200000402:0x1503:0x0] stripe 0 readdir failed: -2, directory is partially accessed! [ 819.508655] Lustre: dir [0x200000402:0x1503:0x0] stripe 0 readdir failed: -2, directory is partially accessed! [ 827.071518] Lustre: DEBUG MARKER: == sanity test 60h: striped directory with missing stripes can be accessed ========================================================== 04:48:45 (1779094125) [ 828.944524] Lustre: dir [0x240000402:0x18a:0x0] stripe 2 readdir failed: -2, directory is partially accessed! [ 831.657489] Lustre: dir [0x240000402:0x191:0x0] stripe 2 readdir failed: -2, directory is partially accessed! [ 831.665821] Lustre: Skipped 3 previous similar messages [ 841.982521] Lustre: DEBUG MARKER: SKIP: sanity test_60i skipping SLOW test 60i [ 844.778293] Lustre: DEBUG MARKER: == sanity test 60j: llog_reader reports corruptions ====== 04:49:02 (1779094142) [ 865.045483] Lustre: DEBUG MARKER: SKIP: sanity test_60j path oi.1/0x1:0xb:0x0 is not in 'O/1/d/' format [ 874.122667] Lustre: DEBUG MARKER: == sanity test 61a: mmap() writes don't make sync hang ========================================================================== 04:49:32 (1779094172) [ 881.670352] Lustre: DEBUG MARKER: == sanity test 61b: mmap() of unstriped file is successful ========================================================== 04:49:39 (1779094179) [ 888.412923] Lustre: DEBUG MARKER: == sanity test 63a: Verify oig_wait interruption does not crash ================================================================= 04:49:46 (1779094186) [ 964.710568] Lustre: DEBUG MARKER: == sanity test 63b: async write errors should be returned to fsync ============================================================= 04:51:01 (1779094261) [ 967.053923] Lustre: *** cfs_fail_loc=406, val=0*** [ 967.055466] LustreError: 21424:0:(osc_request.c:2917:osc_build_rpc()) lustre-OST0001-osc-ffff9e35488c5800: prep_req failed: rc = -12 [ 967.065529] LustreError: 21424:0:(osc_cache.c:2367:osc_check_rpcs()) Write request failed with -12 [ 983.827416] Lustre: DEBUG MARKER: == sanity test 64a: verify filter grant calculations (in kernel) =============================================================== 04:51:22 (1779094282) [ 992.000390] Lustre: DEBUG MARKER: SKIP: sanity test_64b skipping SLOW test 64b [ 994.194793] Lustre: DEBUG MARKER: == sanity test 64c: verify grant shrink ================== 04:51:32 (1779094292) [ 1005.701411] Lustre: DEBUG MARKER: == sanity test 64d: check grant limit exceed ============= 04:51:43 (1779094303) [ 1078.536038] Lustre: DEBUG MARKER: == sanity test 64e: check grant consumption (no grant allocation) ========================================================== 04:52:56 (1779094376) [ 1081.423393] LustreError: 24754:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9e35488c5800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 1081.496419] Lustre: Unmounted lustre-client [ 1081.986762] Lustre: Mounted lustre-client [ 1085.629508] LustreError: 24865:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9e354894a000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 1085.636978] LustreError: 24865:0:(lov_obd.c:792:lov_cleanup()) Skipped 1 previous similar message [ 1085.692735] Lustre: Unmounted lustre-client [ 1086.160913] Lustre: Mounted lustre-client [ 1104.824361] Lustre: DEBUG MARKER: == sanity test 64f: check grant consumption (with grant allocation) ========================================================== 04:53:22 (1779094402) [ 1107.397441] LustreError: 25541:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9e35505d1000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 1107.406980] LustreError: 25541:0:(lov_obd.c:792:lov_cleanup()) Skipped 1 previous similar message [ 1107.494634] Lustre: Unmounted lustre-client [ 1108.159058] Lustre: Mounted lustre-client [ 1110.829535] LustreError: 25641:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9e354bcfb000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 1110.843755] LustreError: 25641:0:(lov_obd.c:792:lov_cleanup()) Skipped 1 previous similar message [ 1110.918958] Lustre: Unmounted lustre-client [ 1111.535457] Lustre: Mounted lustre-client [ 1120.657884] Lustre: DEBUG MARKER: == sanity test 64g: grant shrink on MDT ================== 04:53:38 (1779094418) [ 1152.613236] Lustre: DEBUG MARKER: == sanity test 64h: grant shrink on read ================= 04:54:10 (1779094450) [ 1179.424724] Lustre: DEBUG MARKER: == sanity test 64i: shrink on reconnect ================== 04:54:37 (1779094477) [ 1193.467441] Lustre: lustre-OST0000-osc-ffff9e354b58d000: Connection to lustre-OST0000 (at 192.168.202.131@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1206.239162] Lustre: 2410:0:(client.c:2480:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1779094489/real 1779094489] req@ffff9e354a9f6a00 x1865514656739456/t0(0) o17->lustre-OST0000-osc-ffff9e354b58d000@192.168.202.131@tcp:28/4 lens 456/432 e 0 to 1 dl 1779094505 ref 1 fl Rpc:XQr/200/ffffffff rc 0/-1 job:'lctl.0' uid:0 gid:0 projid:4294967295 [ 1236.095985] Lustre: DEBUG MARKER: oleg231-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 1237.691628] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 1252.161375] Lustre: DEBUG MARKER: == sanity test 64j: check grants on re-done rpc ========== 04:55:49 (1779094549) [ 1254.102235] LustreError: 2409:0:(osc_request.c:2450:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff9e35485e0380 x1865514656752768/t0(0) o4->lustre-OST0000-osc-ffff9e354b58d000@192.168.202.131@tcp:6/4 lens 4584/448 e 0 to 0 dl 1779094569 ref 2 fl Interpret:RMQU/600/0 rc -5/-5 job:'multiop.0' uid:0 gid:0 projid:0 [ 1264.881428] Lustre: DEBUG MARKER: == sanity test 65a: directory with no stripe info ======== 04:56:02 (1779094562) [ 1273.607064] Lustre: DEBUG MARKER: == sanity test 65b: directory setstripe -S stripe_size*2 -i 0 -c 1 ========================================================== 04:56:11 (1779094571) [ 1280.953833] Lustre: DEBUG MARKER: == sanity test 65c: directory setstripe -S stripe_size*4 -i 1 -c 1 ========================================================== 04:56:19 (1779094579) [ 1290.315818] Lustre: DEBUG MARKER: == sanity test 65d: directory setstripe -S stripe_size -c stripe_count ========================================================== 04:56:28 (1779094588) [ 1301.288637] Lustre: DEBUG MARKER: == sanity test 65e: directory setstripe defaults ========= 04:56:38 (1779094598) [ 1312.017257] Lustre: DEBUG MARKER: == sanity test 65f: dir setstripe permission (should return error) ============================================================= 04:56:49 (1779094609) [ 1319.690590] Lustre: DEBUG MARKER: == sanity test 65g: directory setstripe -d =============== 04:56:57 (1779094617) [ 1326.694800] Lustre: DEBUG MARKER: == sanity test 65h: directory stripe info inherit ============================================================================== 04:57:04 (1779094624) [ 1335.106707] Lustre: DEBUG MARKER: == sanity test 65i: various tests to set root directory striping ========================================================== 04:57:13 (1779094633) [ 1344.672323] Lustre: DEBUG MARKER: == sanity test 65j: set default striping on root directory (bug 6367)=========================================================== 04:57:22 (1779094642) [ 1353.776371] Lustre: DEBUG MARKER: == sanity test 65k: validate manual striping works properly with deactivated OSCs ========================================================== 04:57:31 (1779094651) [ 1576.306381] Lustre: DEBUG MARKER: == sanity test 65l: lfs find on -1 stripe dir ================================================================================== 05:01:13 (1779094873) [ 1587.702586] Lustre: DEBUG MARKER: == sanity test 65m: normal user can't set filesystem default stripe ========================================================== 05:01:25 (1779094885) [ 1595.404953] Lustre: DEBUG MARKER: == sanity test 65n: don't inherit default layout from root for new subdirectories ========================================================== 05:01:33 (1779094893) [ 1634.270841] Lustre: DEBUG MARKER: == sanity test 65o: pool inheritance for mdt component === 05:02:11 (1779094931) [ 1668.817609] Lustre: DEBUG MARKER: == sanity test 65p: setstripe with yaml file and huge number ========================================================== 05:02:46 (1779094966) [ 1677.657468] Lustre: DEBUG MARKER: == sanity test 65q: setstripe with >=8E offset should fail ========================================================== 05:02:55 (1779094975) [ 1686.621218] Lustre: DEBUG MARKER: == sanity test 65r: prevent all-zero offsets ============= 05:03:04 (1779094984) [ 1695.925874] Lustre: DEBUG MARKER: == sanity test 66: update inode blocks count on client ========================================================================= 05:03:13 (1779094993) [ 1714.239699] Lustre: DEBUG MARKER: == sanity test 69: verify oa2dentry return -ENOENT doesn't LBUG ================================================================ 05:03:32 (1779095012) [ 1728.649360] Lustre: DEBUG MARKER: == sanity test 70a: verify health_check, health_write don't explode (on OST) ========================================================== 05:03:46 (1779095026) [ 1744.264914] Lustre: DEBUG MARKER: SKIP: sanity test_71 skipping SLOW test 71 [ 1746.621475] Lustre: DEBUG MARKER: == sanity test 72a: Test that remove suid works properly (bug5695) ============================================================== 05:04:04 (1779095044) [ 1755.792493] Lustre: DEBUG MARKER: == sanity test 72b: Test that we keep mode setting if without file data changed (bug 24226) ========================================================== 05:04:13 (1779095053) [ 1766.568398] Lustre: DEBUG MARKER: == sanity test 73: multiple MDC requests (should not deadlock) ========================================================== 05:04:24 (1779095064) [ 1802.926673] Lustre: DEBUG MARKER: == sanity test 74a: ldlm_enqueue freed-export error path, ls (shouldn't LBUG) ========================================================== 05:05:00 (1779095100) [ 1811.674540] Lustre: DEBUG MARKER: == sanity test 74b: ldlm_enqueue freed-export error path, touch (shouldn't LBUG) ========================================================== 05:05:09 (1779095109) [ 1819.707789] Lustre: DEBUG MARKER: == sanity test 74c: ldlm_lock_create error path, (shouldn't LBUG) ========================================================== 05:05:17 (1779095117) [ 1819.804813] Lustre: *** cfs_fail_loc=319, val=0*** [ 1827.276554] Lustre: DEBUG MARKER: == sanity test 76a: confirm clients recycle inodes properly ============================================================== 05:05:25 (1779095125) [ 1902.231726] Lustre: DEBUG MARKER: == sanity test 76b: confirm clients recycle directory inodes properly ============================================================== 05:06:40 (1779095200) [ 1958.145438] Lustre: DEBUG MARKER: == sanity test 77a: normal checksum read/write operation ========================================================== 05:07:36 (1779095256) [ 1967.411203] Lustre: DEBUG MARKER: == sanity test 77b: checksum error on client write, read ========================================================== 05:07:45 (1779095265) [ 1968.257713] Lustre: *** cfs_fail_loc=409, val=0*** [ 1968.417421] LustreError: lustre-OST0001-osc-ffff9e354b58d000: BAD WRITE CHECKSUM: changed on the client after we checksummed it - likely false positive due to mmap IO (bug 11742): from 192.168.202.131@tcp inode [0x200000407:0xc1f:0x0] object 0x2c0000401:3829 extent [0-4194303], original client csum 77e0fc27 (type 20), server csum 77e0fc26 (type 20), client csum now 77e0fc26 [ 1968.449718] LustreError: 2410:0:(osc_request.c:2450:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff9e3544dd5c00 x1865514661545856/t4294972583(4294972583) o4->lustre-OST0001-osc-ffff9e354b58d000@192.168.202.131@tcp:6/4 lens 488/448 e 0 to 0 dl 1779095283 ref 3 fl Interpret:RQU/604/0 rc 0/0 job:'dd.0' uid:0 gid:0 projid:0 [ 1971.143846] Lustre: DEBUG MARKER: set checksum type to crc32, rc = 0 [ 1971.934579] Lustre: *** cfs_fail_loc=408, val=0*** [ 1971.972761] LustreError: lustre-OST0001-osc-ffff9e354b58d000: BAD READ CHECKSUM: from 192.168.202.131@tcp inode [0x200000407:0xc1f:0x0] object 0x2c0000401:3829 extent [0-4194303], client cb80279/cb80279, server 2ca50ea6, cksum_type 1 [ 1971.986963] LustreError: 2409:0:(osc_request.c:2450:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff9e354647b800 x1865514661547648/t0(0) o3->lustre-OST0001-osc-ffff9e354b58d000@192.168.202.131@tcp:6/4 lens 488/440 e 0 to 0 dl 1779095287 ref 2 fl Interpret:RMQU/600/0 rc 4194304/4194304 job:'cmp.0' uid:0 gid:0 projid:0 [ 1976.399794] Lustre: DEBUG MARKER: set checksum type to adler, rc = 0 [ 1977.247509] Lustre: *** cfs_fail_loc=408, val=0*** [ 1977.325794] LustreError: lustre-OST0001-osc-ffff9e354b58d000: BAD READ CHECKSUM: from 192.168.202.131@tcp inode [0x200000407:0xc1f:0x0] object 0x2c0000401:3829 extent [0-4194303], client 85dd5faa/85dd5faa, server f4460e0, cksum_type 2 [ 1977.347750] LustreError: 2411:0:(osc_request.c:2450:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff9e3545bead80 x1865514661549312/t0(0) o3->lustre-OST0001-osc-ffff9e354b58d000@192.168.202.131@tcp:6/4 lens 488/440 e 0 to 0 dl 1779095292 ref 2 fl Interpret:RMQU/600/0 rc 4194304/4194304 job:'cmp.0' uid:0 gid:0 projid:0 [ 1981.725522] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 1982.191205] Lustre: *** cfs_fail_loc=408, val=0*** [ 1982.218361] LustreError: lustre-OST0001-osc-ffff9e354b58d000: BAD READ CHECKSUM: from 192.168.202.131@tcp inode [0x200000407:0xc1f:0x0] object 0x2c0000401:3829 extent [0-4194303], client 609c20c0/609c20c0, server 3df96f70, cksum_type 4 [ 1982.234876] LustreError: 2410:0:(osc_request.c:2450:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff9e3545be8a80 x1865514661550976/t0(0) o3->lustre-OST0001-osc-ffff9e354b58d000@192.168.202.131@tcp:6/4 lens 488/440 e 0 to 0 dl 1779095297 ref 2 fl Interpret:RMQU/600/0 rc 4194304/4194304 job:'cmp.0' uid:0 gid:0 projid:0 [ 1986.778899] Lustre: DEBUG MARKER: set checksum type to t10ip512, rc = 0 [ 1987.197864] Lustre: *** cfs_fail_loc=408, val=0*** [ 1987.211051] LustreError: lustre-OST0001-osc-ffff9e354b58d000: BAD READ CHECKSUM: from 192.168.202.131@tcp inode [0x200000407:0xc1f:0x0] object 0x2c0000401:3829 extent [0-4194303], client 771ad80b/771ad80b, server 7981d8d3, cksum_type 10 [ 1987.226285] LustreError: 2411:0:(osc_request.c:2450:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff9e3544dd5f80 x1865514661552768/t0(0) o3->lustre-OST0001-osc-ffff9e354b58d000@192.168.202.131@tcp:6/4 lens 488/440 e 0 to 0 dl 1779095302 ref 2 fl Interpret:RMQU/600/0 rc 4194304/4194304 job:'cmp.0' uid:0 gid:0 projid:0 [ 1991.439519] Lustre: DEBUG MARKER: set checksum type to t10ip4K, rc = 0 [ 1992.050973] LustreError: lustre-OST0001-osc-ffff9e354b58d000: BAD READ CHECKSUM: from 192.168.202.131@tcp inode [0x200000407:0xc1f:0x0] object 0x2c0000401:3829 extent [0-4194303], client 380dfb5e/380dfb5e, server 77e0fc26, cksum_type 20 [ 1996.386334] Lustre: DEBUG MARKER: set checksum type to t10ip4K, rc = 0 [ 2004.642496] Lustre: DEBUG MARKER: == sanity test 77c: checksum error on client read with debug ========================================================== 05:08:22 (1779095302) [ 2010.720152] Lustre: *** cfs_fail_loc=408, val=0*** [ 2010.724761] Lustre: Skipped 1 previous similar message [ 2010.729936] Lustre: 2410:0:(osc_request.c:2035:dump_all_bulk_pages()) /tmp/lustre-log-checksum_dump-osc-[0x200000407:0xc20:0x0]:[0-1048575]-5fe00085-ef68014d: dumping checksum data [ 2010.749540] LustreError: dumping log to /tmp/lustre-log.1779095310.2410 [ 2010.924180] LustreError: lustre-OST0000-osc-ffff9e354b58d000: BAD READ CHECKSUM: from 192.168.202.131@tcp inode [0x200000407:0xc20:0x0] object 0x280000401:3841 extent [0-1048575], client 5fe00085/5fe00085, server ef68014d, cksum_type 20 [ 2010.949486] LustreError: 2410:0:(osc_request.c:2450:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff9e3545bebb80 x1865514661560320/t0(0) o3->lustre-OST0000-osc-ffff9e354b58d000@192.168.202.131@tcp:6/4 lens 488/440 e 0 to 0 dl 1779095326 ref 2 fl Interpret:RMQU/600/0 rc 1048576/1048576 job:'dd.0' uid:0 gid:0 projid:0 [ 2010.971436] LustreError: 2410:0:(osc_request.c:2450:osc_brw_redo_request()) Skipped 1 previous similar message [ 2050.097259] Lustre: DEBUG MARKER: == sanity test 77d: checksum error on OST direct write, read ========================================================== 05:09:08 (1779095348) [ 2050.515903] Lustre: *** cfs_fail_loc=409, val=0*** [ 2050.714108] LustreError: lustre-OST0000-osc-ffff9e354b58d000: BAD WRITE CHECKSUM: changed on the client after we checksummed it - likely false positive due to mmap IO (bug 11742): from 192.168.202.131@tcp inode [0x200000407:0xc22:0x0] object 0x280000401:3842 extent [0-4194303], original client csum fec05011 (type 20), server csum fec05010 (type 20), client csum now fec05010 [ 2050.756549] LustreError: 2408:0:(osc_request.c:2450:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff9e35485c0000 x1865514661566208/t8589937215(8589937215) o4->lustre-OST0000-osc-ffff9e354b58d000@192.168.202.131@tcp:6/4 lens 488/448 e 0 to 0 dl 1779095366 ref 2 fl Interpret:RMQU/600/0 rc 0/0 job:'directio.0' uid:0 gid:0 projid:0 [ 2052.625255] LustreError: lustre-OST0000-osc-ffff9e354b58d000: BAD READ CHECKSUM: from 192.168.202.131@tcp inode [0x200000407:0xc22:0x0] object 0x280000401:3842 extent [0-4194303], client 872950a1/872950a1, server fec05010, cksum_type 20 [ 2062.908239] Lustre: DEBUG MARKER: == sanity test 77f: repeat checksum error on write (expect error) ========================================================== 05:09:20 (1779095360) [ 2065.309719] Lustre: DEBUG MARKER: set checksum type to crc32, rc = 0 [ 2065.905603] LustreError: lustre-OST0001-osc-ffff9e354b58d000: BAD WRITE CHECKSUM: changed in transit before arrival at OST: from 192.168.202.131@tcp inode [0x200000407:0xc23:0x0] object 0x2c0000401:3830 extent [0-4194303], original client csum 8b19b060 (type 1), server csum 8b19b05f (type 1), client csum now 8b19b060 [ 2065.931910] LustreError: Skipped 1 previous similar message [ 2067.091553] LustreError: 2411:0:(osc_request.c:2607:brw_interpret()) lustre-OST0001-osc-ffff9e354b58d000: too many resent retries for object: 11811161089:3830: rc = -11 [ 2068.551746] Lustre: DEBUG MARKER: set checksum type to adler, rc = 0 [ 2069.181627] LustreError: lustre-OST0000-osc-ffff9e354b58d000: BAD WRITE CHECKSUM: changed in transit before arrival at OST: from 192.168.202.131@tcp inode [0x200000407:0xc24:0x0] object 0x280000401:3843 extent [4194304-8388607], original client csum 7d33b9a0 (type 2), server csum 7d33b99f (type 2), client csum now 7d33b9a0 [ 2069.207020] LustreError: Skipped 2 previous similar messages [ 2070.499493] LustreError: 2409:0:(osc_request.c:2607:brw_interpret()) lustre-OST0000-osc-ffff9e354b58d000: too many resent retries for object: 10737419265:3843: rc = -11 [ 2070.510122] LustreError: 2409:0:(osc_request.c:2607:brw_interpret()) Skipped 1 previous similar message [ 2072.276616] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 2074.253412] LustreError: lustre-OST0001-osc-ffff9e354b58d000: BAD WRITE CHECKSUM: changed in transit before arrival at OST: from 192.168.202.131@tcp inode [0x200000407:0xc25:0x0] object 0x2c0000401:3831 extent [4194304-8388607], original client csum de2bf73f (type 4), server csum de2bf73e (type 4), client csum now de2bf73f [ 2074.256128] LustreError: 2410:0:(osc_request.c:2607:brw_interpret()) lustre-OST0001-osc-ffff9e354b58d000: too many resent retries for object: 11811161089:3831: rc = -11 [ 2074.294224] LustreError: Skipped 6 previous similar messages [ 2074.340893] LustreError: 2410:0:(osc_request.c:2607:brw_interpret()) Skipped 2 previous similar messages [ 2076.181258] Lustre: DEBUG MARKER: set checksum type to t10ip512, rc = 0 [ 2078.162102] LustreError: 2410:0:(osc_request.c:2607:brw_interpret()) lustre-OST0000-osc-ffff9e354b58d000: too many resent retries for object: 10737419265:3844: rc = -11 [ 2080.346253] Lustre: DEBUG MARKER: set checksum type to t10ip4K, rc = 0 [ 2090.629857] Lustre: DEBUG MARKER: set checksum type to t10ip4K, rc = 0 [ 2092.521906] Lustre: DEBUG MARKER: == sanity test 77g: checksum error on OST write, read ==== 05:09:50 (1779095390) [ 2094.248667] LustreError: lustre-OST0000-osc-ffff9e354b58d000: BAD WRITE CHECKSUM: changed in transit before arrival at OST: from 192.168.202.131@tcp inode [0x200000407:0xc28:0x0] object 0x280000401:3845 extent [0-1048575], original client csum ef68014d (type 20), server csum 3a271545 (type 20), client csum now ef68014d [ 2094.262019] LustreError: Skipped 8 previous similar messages [ 2094.264617] LustreError: 2410:0:(osc_request.c:2450:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff9e3544dd5880 x1865514661584640/t8589937229(8589937229) o4->lustre-OST0000-osc-ffff9e354b58d000@192.168.202.131@tcp:6/4 lens 488/448 e 0 to 0 dl 1779095409 ref 2 fl Interpret:RMQU/600/0 rc 0/0 job:'dd.0' uid:0 gid:0 projid:0 [ 2094.277020] LustreError: 2410:0:(osc_request.c:2450:osc_brw_redo_request()) Skipped 11 previous similar messages [ 2099.653933] LustreError: lustre-OST0000-osc-ffff9e354b58d000: BAD READ CHECKSUM: from 192.168.202.131@tcp inode [0x200000407:0xc28:0x0] object 0x280000401:3845 extent [0-4194303], client 77e0fc26/77e0fc26, server 8c9011c4, cksum_type 20 [ 2111.215655] Lustre: DEBUG MARKER: == sanity test 77k: enable/disable checksum correctly ==== 05:10:09 (1779095409) [ 2117.564231] LustreError: 58222:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9e354b58d000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 2117.578790] LustreError: 58222:0:(lov_obd.c:792:lov_cleanup()) Skipped 1 previous similar message [ 2117.708322] Lustre: Unmounted lustre-client [ 2118.282622] Lustre: Mounted lustre-client [ 2124.594834] LustreError: 58325:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9e354c5ec000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 2124.602429] LustreError: 58325:0:(lov_obd.c:792:lov_cleanup()) Skipped 1 previous similar message [ 2124.719183] Lustre: Unmounted lustre-client [ 2125.328804] Lustre: Mounted lustre-client [ 2130.094424] LustreError: 58412:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9e354c5ec000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 2130.106446] LustreError: 58412:0:(lov_obd.c:792:lov_cleanup()) Skipped 1 previous similar message [ 2130.268344] Lustre: Unmounted lustre-client [ 2130.983550] Lustre: Mounted lustre-client [ 2132.747680] LustreError: 58488:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9e3545397000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 2132.770186] LustreError: 58488:0:(lov_obd.c:792:lov_cleanup()) Skipped 1 previous similar message [ 2132.852356] Lustre: Unmounted lustre-client [ 2133.310913] Lustre: Mounted lustre-client [ 2148.015891] Lustre: DEBUG MARKER: == sanity test 77l: preferred checksum type is remembered after reconnected ========================================================== 05:10:46 (1779095446) [ 2149.831906] Lustre: DEBUG MARKER: set checksum type to invalid, rc = 22 [ 2151.668671] Lustre: DEBUG MARKER: set checksum type to crc32, rc = 0 [ 2156.711292] Lustre: DEBUG MARKER: oleg231-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff9e354b58e000.ost_server_uuid 50 [ 2158.386105] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9e354b58e000.ost_server_uuid in IDLE state after 0 sec [ 2162.331490] Lustre: DEBUG MARKER: oleg231-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9e354b58e000.ost_server_uuid 50 [ 2164.113697] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9e354b58e000.ost_server_uuid in FULL state after 0 sec [ 2165.863593] Lustre: DEBUG MARKER: set checksum type to adler, rc = 0 [ 2170.505612] Lustre: DEBUG MARKER: oleg231-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff9e354b58e000.ost_server_uuid 50 [ 2179.604842] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9e354b58e000.ost_server_uuid in IDLE state after 7 sec [ 2183.390254] Lustre: DEBUG MARKER: oleg231-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9e354b58e000.ost_server_uuid 50 [ 2184.892828] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9e354b58e000.ost_server_uuid in FULL state after 0 sec [ 2186.537816] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 2190.893502] Lustre: DEBUG MARKER: oleg231-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff9e354b58e000.ost_server_uuid 50 [ 2199.794789] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9e354b58e000.ost_server_uuid in IDLE state after 7 sec [ 2204.439327] Lustre: DEBUG MARKER: oleg231-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9e354b58e000.ost_server_uuid 50 [ 2206.347462] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9e354b58e000.ost_server_uuid in FULL state after 0 sec [ 2208.409606] Lustre: DEBUG MARKER: set checksum type to t10ip512, rc = 0 [ 2212.996152] Lustre: DEBUG MARKER: oleg231-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff9e354b58e000.ost_server_uuid 50 [ 2220.855668] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9e354b58e000.ost_server_uuid in IDLE state after 5 sec [ 2226.818317] Lustre: DEBUG MARKER: oleg231-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9e354b58e000.ost_server_uuid 50 [ 2229.177987] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9e354b58e000.ost_server_uuid in FULL state after 0 sec [ 2231.887343] Lustre: DEBUG MARKER: set checksum type to t10ip4K, rc = 0 [ 2236.988949] Lustre: DEBUG MARKER: oleg231-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff9e354b58e000.ost_server_uuid 50 [ 2246.205137] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9e354b58e000.ost_server_uuid in IDLE state after 7 sec [ 2249.946604] Lustre: DEBUG MARKER: oleg231-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9e354b58e000.ost_server_uuid 50 [ 2251.166198] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9e354b58e000.ost_server_uuid in FULL state after 0 sec [ 2258.288506] Lustre: DEBUG MARKER: set checksum type to t10ip4K, rc = 0 [ 2260.427888] Lustre: DEBUG MARKER: == sanity test 77m: Verify checksum_speed is correctly read ========================================================== 05:12:38 (1779095558) [ 2266.496953] Lustre: DEBUG MARKER: == sanity test 77n: Verify read from a hole inside contiguous blocks with T10PI ========================================================== 05:12:44 (1779095564) [ 2268.433860] Lustre: DEBUG MARKER: set checksum type to t10ip512, rc = 0 [ 2270.087392] Lustre: DEBUG MARKER: set checksum type to t10ip4K, rc = 0 [ 2276.451679] Lustre: DEBUG MARKER: set checksum type to t10ip4K, rc = 0 [ 2278.274578] Lustre: DEBUG MARKER: == sanity test 77o: Verify checksum_type for server (mdt and ofd(obdfilter)) ========================================================== 05:12:56 (1779095576) [ 2290.541674] Lustre: DEBUG MARKER: == sanity test 78: handle large O_DIRECT writes correctly ====================================================================== 05:13:08 (1779095588) [ 2300.954228] Lustre: DEBUG MARKER: == sanity test 79: df report consistency check =========== 05:13:19 (1779095599) [ 2318.860889] Lustre: DEBUG MARKER: == sanity test 80: Page eviction is equally fast at high offsets too ========================================================== 05:13:37 (1779095617) [ 2327.217579] Lustre: DEBUG MARKER: == sanity test 81a: OST should retry write when get -ENOSPC ========================================================================= 05:13:45 (1779095625) [ 2335.419249] Lustre: DEBUG MARKER: == sanity test 81b: OST should return -ENOSPC when retry still fails ================================================================= 05:13:53 (1779095633) [ 2343.756741] Lustre: DEBUG MARKER: == sanity test 84: lz4/lz4hc compression/decompression kernel module ========================================================== 05:14:01 (1779095641) [ 2344.181611] lustre_kcompr_7642: ***** [ 2344.183243] lustre_kcompr_7642: (de)compression test on random binary data [ 2344.193689] lustre_kcompr_7642: ***** [ 2344.210859] lustre_kcompr_7642: compr lz4(1) in 64kB chunks took 2958 us (1352 MB/s), compress ratio: 96.13 [ 2344.222424] lustre_kcompr_7642: compr lz4(1) in 128kB chunks took 3506 us (1140 MB/s), compress ratio: 101.31 [ 2344.231565] lustre_kcompr_7642: compr lz4(1) in 256kB chunks took 3252 us (1230 MB/s), compress ratio: 103.83 [ 2344.239623] lustre_kcompr_7642: compr lz4(1) in 512kB chunks took 3251 us (1230 MB/s), compress ratio: 105.04 [ 2344.249719] lustre_kcompr_7642: compr lz4(1) in 1024kB chunks took 1367 us (2926 MB/s), compress ratio: 106.51 [ 2344.270567] lustre_kcompr_7642: compr lz4(1) in 2048kB chunks took 7439 us (537 MB/s), compress ratio: 106.94 [ 2344.289072] lustre_kcompr_7642: compr lz4(1) in 4096kB chunks took 1430 us (2797 MB/s), compress ratio: 106.98 [ 2344.333144] lustre_kcompr_7642: decompr lz4(1) took 5614 us (6 MB/s) [ 2344.335975] lustre_kcompr_7642: test_comp_compress_decompress(lz4,1) ret 0 [ 2344.358695] lustre_kcompr_7642: acompr lz4(1) of 128kB chunks took 93 us (1344 MB/s), compress ratio: 104.94 [ 2344.383957] lustre_kcompr_7642: adecompr lz4(1) took 106 us (11 MB/s) [ 2344.390362] lustre_kcompr_7642: test_acomp_compress_decompress(lz4,1) ret 0 [ 2344.408516] lustre_kcompr_7642: compr lz4(4) in 64kB chunks took 3254 us (1229 MB/s), compress ratio: 82.02 [ 2344.416507] lustre_kcompr_7642: compr lz4(4) in 128kB chunks took 2148 us (1862 MB/s), compress ratio: 92.30 [ 2344.433764] lustre_kcompr_7642: compr lz4(4) in 256kB chunks took 1351 us (2960 MB/s), compress ratio: 98.64 [ 2344.441629] lustre_kcompr_7642: compr lz4(4) in 512kB chunks took 2549 us (1569 MB/s), compress ratio: 101.81 [ 2344.455285] lustre_kcompr_7642: compr lz4(4) in 1024kB chunks took 1393 us (2871 MB/s), compress ratio: 103.70 [ 2344.464662] lustre_kcompr_7642: compr lz4(4) in 2048kB chunks took 2169 us (1844 MB/s), compress ratio: 104.58 [ 2344.473546] lustre_kcompr_7642: compr lz4(4) in 4096kB chunks took 2358 us (1696 MB/s), compress ratio: 105.28 [ 2344.499943] lustre_kcompr_7642: decompr lz4(4) took 3719 us (10 MB/s) [ 2344.507347] lustre_kcompr_7642: test_comp_compress_decompress(lz4,4) ret 0 [ 2344.518361] lustre_kcompr_7642: acompr lz4(4) of 128kB chunks took 97 us (1288 MB/s), compress ratio: 94.77 [ 2344.524738] lustre_kcompr_7642: adecompr lz4(4) took 99 us (13 MB/s) [ 2344.529815] lustre_kcompr_7642: test_acomp_compress_decompress(lz4,4) ret 0 [ 2344.544394] lustre_kcompr_7642: compr lz4(9) in 64kB chunks took 2600 us (1538 MB/s), compress ratio: 61.37 [ 2344.552982] lustre_kcompr_7642: compr lz4(9) in 128kB chunks took 2389 us (1674 MB/s), compress ratio: 75.71 [ 2344.566264] lustre_kcompr_7642: compr lz4(9) in 256kB chunks took 2840 us (1408 MB/s), compress ratio: 87.02 [ 2344.572513] lustre_kcompr_7642: compr lz4(9) in 512kB chunks took 2486 us (1609 MB/s), compress ratio: 93.77 [ 2344.579889] lustre_kcompr_7642: compr lz4(9) in 1024kB chunks took 2529 us (1581 MB/s), compress ratio: 97.73 [ 2344.586810] lustre_kcompr_7642: compr lz4(9) in 2048kB chunks took 1551 us (2578 MB/s), compress ratio: 99.46 [ 2344.592614] lustre_kcompr_7642: compr lz4(9) in 4096kB chunks took 1944 us (2057 MB/s), compress ratio: 100.80 [ 2344.608902] lustre_kcompr_7642: decompr lz4(9) took 2027 us (19 MB/s) [ 2344.614073] lustre_kcompr_7642: test_comp_compress_decompress(lz4,9) ret 0 [ 2344.619419] lustre_kcompr_7642: acompr lz4(9) of 128kB chunks took 295 us (423 MB/s), compress ratio: 72.69 [ 2344.624351] lustre_kcompr_7642: adecompr lz4(9) took 123 us (13 MB/s) [ 2344.630619] lustre_kcompr_7642: test_acomp_compress_decompress(lz4,9) ret 0 [ 2344.661704] lustre_kcompr_7642: compr lz4(15) in 64kB chunks took 3143 us (1272 MB/s), compress ratio: 29.33 [ 2344.672346] lustre_kcompr_7642: compr lz4(15) in 128kB chunks took 3967 us (1008 MB/s), compress ratio: 43.93 [ 2344.681404] lustre_kcompr_7642: compr lz4(15) in 256kB chunks took 2522 us (1586 MB/s), compress ratio: 59.14 [ 2344.689939] lustre_kcompr_7642: compr lz4(15) in 512kB chunks took 1688 us (2369 MB/s), compress ratio: 72.11 [ 2344.697320] lustre_kcompr_7642: compr lz4(15) in 1024kB chunks took 2572 us (1555 MB/s), compress ratio: 78.98 [ 2344.703400] lustre_kcompr_7642: compr lz4(15) in 2048kB chunks took 1691 us (2365 MB/s), compress ratio: 83.86 [ 2344.709724] lustre_kcompr_7642: compr lz4(15) in 4096kB chunks took 1778 us (2249 MB/s), compress ratio: 86.32 [ 2344.724403] lustre_kcompr_7642: decompr lz4(15) took 2549 us (18 MB/s) [ 2344.731684] lustre_kcompr_7642: test_comp_compress_decompress(lz4,15) ret 0 [ 2344.741256] lustre_kcompr_7642: acompr lz4(15) of 128kB chunks took 89 us (1404 MB/s), compress ratio: 42.34 [ 2344.747541] lustre_kcompr_7642: adecompr lz4(15) took 330 us (8 MB/s) [ 2344.754398] lustre_kcompr_7642: test_acomp_compress_decompress(lz4,15) ret 0 [ 2344.807539] lustre_kcompr_7642: compr lz4hc(1) in 64kB chunks took 38968 us (102 MB/s), compress ratio: 97.17 [ 2344.852436] lustre_kcompr_7642: compr lz4hc(1) in 128kB chunks took 39030 us (102 MB/s), compress ratio: 103.05 [ 2344.894539] lustre_kcompr_7642: compr lz4hc(1) in 256kB chunks took 36058 us (110 MB/s), compress ratio: 106.27 [ 2344.975767] lustre_kcompr_7642: compr lz4hc(1) in 512kB chunks took 76139 us (52 MB/s), compress ratio: 107.94 [ 2345.030980] lustre_kcompr_7642: compr lz4hc(1) in 1024kB chunks took 45175 us (88 MB/s), compress ratio: 108.78 [ 2345.076728] lustre_kcompr_7642: compr lz4hc(1) in 2048kB chunks took 33021 us (121 MB/s), compress ratio: 109.22 [ 2345.127175] lustre_kcompr_7642: compr lz4hc(1) in 4096kB chunks took 46198 us (86 MB/s), compress ratio: 109.44 [ 2345.143504] lustre_kcompr_7642: decompr lz4hc(1) took 3135 us (11 MB/s) [ 2345.148644] lustre_kcompr_7642: test_comp_compress_decompress(lz4hc,1) ret 0 [ 2345.166736] lustre_kcompr_7642: acompr lz4hc(1) of 128kB chunks took 615 us (203 MB/s), compress ratio: 105.78 [ 2345.173666] lustre_kcompr_7642: adecompr lz4hc(1) took 80 us (14 MB/s) [ 2345.205828] lustre_kcompr_7642: test_acomp_compress_decompress(lz4hc,1) ret 0 [ 2345.295503] lustre_kcompr_7642: compr lz4hc(3) in 64kB chunks took 66038 us (60 MB/s), compress ratio: 97.69 [ 2345.369436] lustre_kcompr_7642: compr lz4hc(3) in 128kB chunks took 67014 us (59 MB/s), compress ratio: 103.62 [ 2345.416438] lustre_kcompr_7642: compr lz4hc(3) in 256kB chunks took 41759 us (95 MB/s), compress ratio: 106.86 [ 2345.534093] lustre_kcompr_7642: compr lz4hc(3) in 512kB chunks took 113060 us (35 MB/s), compress ratio: 108.54 [ 2345.580912] lustre_kcompr_7642: compr lz4hc(3) in 1024kB chunks took 36395 us (109 MB/s), compress ratio: 109.41 [ 2345.630614] lustre_kcompr_7642: compr lz4hc(3) in 2048kB chunks took 45863 us (87 MB/s), compress ratio: 109.85 [ 2345.691957] lustre_kcompr_7642: compr lz4hc(3) in 4096kB chunks took 53035 us (75 MB/s), compress ratio: 110.07 [ 2345.720702] lustre_kcompr_7642: decompr lz4hc(3) took 1368 us (26 MB/s) [ 2345.726794] lustre_kcompr_7642: test_comp_compress_decompress(lz4hc,3) ret 0 [ 2345.747945] lustre_kcompr_7642: acompr lz4hc(3) of 128kB chunks took 3050 us (40 MB/s), compress ratio: 106.73 [ 2345.766645] lustre_kcompr_7642: adecompr lz4hc(3) took 95 us (12 MB/s) [ 2345.791579] lustre_kcompr_7642: test_acomp_compress_decompress(lz4hc,3) ret 0 [ 2346.754118] lustre_kcompr_7642: compr lz4hc(8) in 64kB chunks took 932458 us (4 MB/s), compress ratio: 104.19 [ 2347.620932] lustre_kcompr_7642: compr lz4hc(8) in 128kB chunks took 861533 us (4 MB/s), compress ratio: 111.23 [ 2348.627449] lustre_kcompr_7642: compr lz4hc(8) in 256kB chunks took 997927 us (4 MB/s), compress ratio: 115.14 [ 2349.673910] lustre_kcompr_7642: compr lz4hc(8) in 512kB chunks took 1040069 us (3 MB/s), compress ratio: 117.18 [ 2350.541641] lustre_kcompr_7642: compr lz4hc(8) in 1024kB chunks took 853584 us (4 MB/s), compress ratio: 118.28 [ 2351.496161] lustre_kcompr_7642: compr lz4hc(8) in 2048kB chunks took 948733 us (4 MB/s), compress ratio: 118.80 [ 2352.317272] lustre_kcompr_7642: compr lz4hc(8) in 4096kB chunks took 812169 us (4 MB/s), compress ratio: 119.09 [ 2352.341675] lustre_kcompr_7642: decompr lz4hc(8) took 1393 us (24 MB/s) [ 2352.346573] lustre_kcompr_7642: test_comp_compress_decompress(lz4hc,8) ret 0 [ 2352.372761] lustre_kcompr_7642: acompr lz4hc(8) of 128kB chunks took 17488 us (7 MB/s), compress ratio: 114.17 [ 2352.380151] lustre_kcompr_7642: adecompr lz4hc(8) took 1412 us (0 MB/s) [ 2352.387928] lustre_kcompr_7642: test_acomp_compress_decompress(lz4hc,8) ret 0 [ 2353.298771] lustre_kcompr_7642: compr lz4hc(15) in 64kB chunks took 879332 us (4 MB/s), compress ratio: 104.72 [ 2354.509982] lustre_kcompr_7642: compr lz4hc(15) in 128kB chunks took 1205775 us (3 MB/s), compress ratio: 112.30 [ 2355.655385] lustre_kcompr_7642: compr lz4hc(15) in 256kB chunks took 1138123 us (3 MB/s), compress ratio: 116.46 [ 2357.196869] lustre_kcompr_7642: compr lz4hc(15) in 512kB chunks took 1530142 us (2 MB/s), compress ratio: 118.63 [ 2358.510604] lustre_kcompr_7642: compr lz4hc(15) in 1024kB chunks took 1302980 us (3 MB/s), compress ratio: 119.80 [ 2359.602269] lustre_kcompr_7642: compr lz4hc(15) in 2048kB chunks took 1086549 us (3 MB/s), compress ratio: 120.39 [ 2360.944921] lustre_kcompr_7642: compr lz4hc(15) in 4096kB chunks took 1325060 us (3 MB/s), compress ratio: 120.68 [ 2360.964361] lustre_kcompr_7642: decompr lz4hc(15) took 3387 us (9 MB/s) [ 2360.969961] lustre_kcompr_7642: test_comp_compress_decompress(lz4hc,15) ret 0 [ 2361.021254] lustre_kcompr_7642: acompr lz4hc(15) of 128kB chunks took 43005 us (2 MB/s), compress ratio: 115.48 [ 2361.027970] lustre_kcompr_7642: adecompr lz4hc(15) took 94 us (11 MB/s) [ 2361.042140] lustre_kcompr_7642: test_acomp_compress_decompress(lz4hc,15) ret 0 [ 2361.054902] lustre_kcompr_7642: compr lzo(-1) in 64kB chunks took 4107 us (973 MB/s), compress ratio: 81.40 [ 2361.065839] lustre_kcompr_7642: compr lzo(-1) in 128kB chunks took 1801 us (2220 MB/s), compress ratio: 86.49 [ 2361.080610] lustre_kcompr_7642: compr lzo(-1) in 256kB chunks took 6483 us (616 MB/s), compress ratio: 86.10 [ 2361.093833] lustre_kcompr_7642: compr lzo(-1) in 512kB chunks took 3934 us (1016 MB/s), compress ratio: 87.87 [ 2361.106345] lustre_kcompr_7642: compr lzo(-1) in 1024kB chunks took 3575 us (1118 MB/s), compress ratio: 87.90 [ 2361.121988] lustre_kcompr_7642: compr lzo(-1) in 2048kB chunks took 1793 us (2230 MB/s), compress ratio: 88.56 [ 2361.135845] lustre_kcompr_7642: compr lzo(-1) in 4096kB chunks took 4143 us (965 MB/s), compress ratio: 88.79 [ 2361.148852] lustre_kcompr_7642: decompr lzo(-1) took 1526 us (29 MB/s) [ 2361.152710] lustre_kcompr_7642: test_comp_compress_decompress(lzo,-1) ret 0 [ 2361.157112] lustre_kcompr_7642: acompr lzo(-1) of 128kB chunks took 138 us (905 MB/s), compress ratio: 88.56 [ 2361.162882] lustre_kcompr_7642: adecompr lzo(-1) took 92 us (15 MB/s) [ 2361.170872] lustre_kcompr_7642: test_acomp_compress_decompress(lzo,-1) ret 0 [ 2361.527812] lustre_kcompr_7642: compr deflate(-1) in 64kB chunks took 350390 us (11 MB/s), compress ratio: 97.58 [ 2361.993810] lustre_kcompr_7642: compr deflate(-1) in 128kB chunks took 447332 us (8 MB/s), compress ratio: 107.82 [ 2362.407961] lustre_kcompr_7642: compr deflate(-1) in 256kB chunks took 407379 us (9 MB/s), compress ratio: 114.20 [ 2362.877867] lustre_kcompr_7642: compr deflate(-1) in 512kB chunks took 459347 us (8 MB/s), compress ratio: 117.90 [ 2363.325922] lustre_kcompr_7642: compr deflate(-1) in 1024kB chunks took 440119 us (9 MB/s), compress ratio: 119.85 [ 2363.601420] lustre_kcompr_7642: compr deflate(-1) in 2048kB chunks took 269532 us (14 MB/s), compress ratio: 120.81 [ 2364.027678] lustre_kcompr_7642: compr deflate(-1) in 4096kB chunks took 420911 us (9 MB/s), compress ratio: 121.08 [ 2364.057743] lustre_kcompr_7642: decompr deflate(-1) took 12697 us (2 MB/s) [ 2364.065230] lustre_kcompr_7642: test_comp_compress_decompress(deflate,-1) ret 0 [ 2364.092695] lustre_kcompr_7642: acompr deflate(-1) of 128kB chunks took 21124 us (5 MB/s), compress ratio: 110.79 [ 2364.107871] lustre_kcompr_7642: adecompr deflate(-1) took 178 us (6 MB/s) [ 2364.123493] lustre_kcompr_7642: test_acomp_compress_decompress(deflate,-1) ret 0 [ 2364.127986] lustre_kcompr_7642: SUCCESS [ 2370.551742] lustre_kcompr_30202: ***** [ 2370.558906] lustre_kcompr_30202: (de)compression test on provided file /tmp/f84.sanity [ 2370.562373] lustre_kcompr_30202: ***** [ 2370.603612] lustre_kcompr_30202: compr lz4(1) in 64kB chunks took 28908 us (138 MB/s), compress ratio: 2.93 [ 2370.640121] lustre_kcompr_30202: compr lz4(1) in 128kB chunks took 29198 us (136 MB/s), compress ratio: 3.04 [ 2370.681149] lustre_kcompr_30202: compr lz4(1) in 256kB chunks took 35778 us (111 MB/s), compress ratio: 3.08 [ 2370.732250] lustre_kcompr_30202: compr lz4(1) in 512kB chunks took 41595 us (96 MB/s), compress ratio: 3.10 [ 2370.769546] lustre_kcompr_30202: compr lz4(1) in 1024kB chunks took 29020 us (137 MB/s), compress ratio: 3.11 [ 2370.811744] lustre_kcompr_30202: compr lz4(1) in 2048kB chunks took 39142 us (102 MB/s), compress ratio: 3.11 [ 2370.868423] lustre_kcompr_30202: compr lz4(1) in 4096kB chunks took 51377 us (77 MB/s), compress ratio: 3.12 [ 2370.902931] lustre_kcompr_30202: decompr lz4(1) took 14413 us (88 MB/s) [ 2370.910569] lustre_kcompr_30202: test_comp_compress_decompress(lz4,1) ret 0 [ 2370.920231] lustre_kcompr_30202: acompr lz4(1) of 128kB chunks took 4890 us (25 MB/s), compress ratio: 2.68 [ 2370.925253] lustre_kcompr_30202: adecompr lz4(1) took 346 us (134 MB/s) [ 2370.930119] lustre_kcompr_30202: test_acomp_compress_decompress(lz4,1) ret 0 [ 2370.977864] lustre_kcompr_30202: compr lz4(4) in 64kB chunks took 28917 us (138 MB/s), compress ratio: 2.67 [ 2371.027547] lustre_kcompr_30202: compr lz4(4) in 128kB chunks took 38743 us (103 MB/s), compress ratio: 2.63 [ 2371.056531] lustre_kcompr_30202: compr lz4(4) in 256kB chunks took 24012 us (166 MB/s), compress ratio: 2.68 [ 2371.125571] lustre_kcompr_30202: compr lz4(4) in 512kB chunks took 53910 us (74 MB/s), compress ratio: 2.71 [ 2371.207266] lustre_kcompr_30202: compr lz4(4) in 1024kB chunks took 71430 us (55 MB/s), compress ratio: 2.72 [ 2371.250403] lustre_kcompr_30202: compr lz4(4) in 2048kB chunks took 36896 us (108 MB/s), compress ratio: 2.72 [ 2371.301769] lustre_kcompr_30202: compr lz4(4) in 4096kB chunks took 40083 us (99 MB/s), compress ratio: 2.73 [ 2371.336812] lustre_kcompr_30202: decompr lz4(4) took 12090 us (121 MB/s) [ 2371.342103] lustre_kcompr_30202: test_comp_compress_decompress(lz4,4) ret 0 [ 2371.348668] lustre_kcompr_30202: acompr lz4(4) of 128kB chunks took 1460 us (85 MB/s), compress ratio: 2.30 [ 2371.365463] lustre_kcompr_30202: adecompr lz4(4) took 180 us (301 MB/s) [ 2371.406767] lustre_kcompr_30202: test_acomp_compress_decompress(lz4,4) ret 0 [ 2371.471811] lustre_kcompr_30202: compr lz4(9) in 64kB chunks took 40300 us (99 MB/s), compress ratio: 2.30 [ 2371.516698] lustre_kcompr_30202: compr lz4(9) in 128kB chunks took 25896 us (154 MB/s), compress ratio: 2.15 [ 2371.572744] lustre_kcompr_30202: compr lz4(9) in 256kB chunks took 40161 us (99 MB/s), compress ratio: 2.20 [ 2371.632061] lustre_kcompr_30202: compr lz4(9) in 512kB chunks took 49742 us (80 MB/s), compress ratio: 2.23 [ 2371.679678] lustre_kcompr_30202: compr lz4(9) in 1024kB chunks took 38953 us (102 MB/s), compress ratio: 2.24 [ 2371.736957] lustre_kcompr_30202: compr lz4(9) in 2048kB chunks took 49236 us (81 MB/s), compress ratio: 2.25 [ 2371.798270] lustre_kcompr_30202: compr lz4(9) in 4096kB chunks took 45506 us (87 MB/s), compress ratio: 2.26 [ 2371.843393] lustre_kcompr_30202: decompr lz4(9) took 12227 us (144 MB/s) [ 2371.851569] lustre_kcompr_30202: test_comp_compress_decompress(lz4,9) ret 0 [ 2371.863597] lustre_kcompr_30202: acompr lz4(9) of 128kB chunks took 538 us (232 MB/s), compress ratio: 1.87 [ 2371.870739] lustre_kcompr_30202: adecompr lz4(9) took 209 us (318 MB/s) [ 2371.887972] lustre_kcompr_30202: test_acomp_compress_decompress(lz4,9) ret 0 [ 2371.927764] lustre_kcompr_30202: compr lz4(15) in 64kB chunks took 23212 us (172 MB/s), compress ratio: 1.62 [ 2371.953157] lustre_kcompr_30202: compr lz4(15) in 128kB chunks took 13924 us (287 MB/s), compress ratio: 1.52 [ 2371.985632] lustre_kcompr_30202: compr lz4(15) in 256kB chunks took 27713 us (144 MB/s), compress ratio: 1.56 [ 2372.036194] lustre_kcompr_30202: compr lz4(15) in 512kB chunks took 43564 us (91 MB/s), compress ratio: 1.58 [ 2372.110067] lustre_kcompr_30202: compr lz4(15) in 1024kB chunks took 46830 us (85 MB/s), compress ratio: 1.60 [ 2372.138117] lustre_kcompr_30202: compr lz4(15) in 2048kB chunks took 21535 us (185 MB/s), compress ratio: 1.60 [ 2372.178884] lustre_kcompr_30202: compr lz4(15) in 4096kB chunks took 34777 us (115 MB/s), compress ratio: 1.60 [ 2372.200231] lustre_kcompr_30202: decompr lz4(15) took 6038 us (411 MB/s) [ 2372.208579] lustre_kcompr_30202: test_comp_compress_decompress(lz4,15) ret 0 [ 2372.216833] lustre_kcompr_30202: acompr lz4(15) of 128kB chunks took 385 us (324 MB/s), compress ratio: 1.33 [ 2372.226418] lustre_kcompr_30202: adecompr lz4(15) took 303 us (310 MB/s) [ 2372.258203] lustre_kcompr_30202: test_acomp_compress_decompress(lz4,15) ret 0 [ 2372.441204] lustre_kcompr_30202: compr lz4hc(1) in 64kB chunks took 155552 us (25 MB/s), compress ratio: 3.58 [ 2372.641079] lustre_kcompr_30202: compr lz4hc(1) in 128kB chunks took 196496 us (20 MB/s), compress ratio: 3.77 [ 2372.907497] lustre_kcompr_30202: compr lz4hc(1) in 256kB chunks took 257389 us (15 MB/s), compress ratio: 3.88 [ 2373.291647] lustre_kcompr_30202: compr lz4hc(1) in 512kB chunks took 371380 us (10 MB/s), compress ratio: 3.93 [ 2373.480404] lustre_kcompr_30202: compr lz4hc(1) in 1024kB chunks took 173919 us (22 MB/s), compress ratio: 3.96 [ 2373.719301] lustre_kcompr_30202: compr lz4hc(1) in 2048kB chunks took 227898 us (17 MB/s), compress ratio: 3.97 [ 2374.019896] lustre_kcompr_30202: compr lz4hc(1) in 4096kB chunks took 292985 us (13 MB/s), compress ratio: 3.98 [ 2374.045966] lustre_kcompr_30202: decompr lz4hc(1) took 10845 us (92 MB/s) [ 2374.051548] lustre_kcompr_30202: test_comp_compress_decompress(lz4hc,1) ret 0 [ 2374.064378] lustre_kcompr_30202: acompr lz4hc(1) of 128kB chunks took 7159 us (17 MB/s), compress ratio: 3.27 [ 2374.076509] lustre_kcompr_30202: adecompr lz4hc(1) took 300 us (127 MB/s) [ 2374.082186] lustre_kcompr_30202: test_acomp_compress_decompress(lz4hc,1) ret 0 [ 2374.394214] lustre_kcompr_30202: compr lz4hc(3) in 64kB chunks took 300728 us (13 MB/s), compress ratio: 3.68 [ 2374.769418] lustre_kcompr_30202: compr lz4hc(3) in 128kB chunks took 367324 us (10 MB/s), compress ratio: 3.91 [ 2375.181673] lustre_kcompr_30202: compr lz4hc(3) in 256kB chunks took 407268 us (9 MB/s), compress ratio: 4.04 [ 2375.650507] lustre_kcompr_30202: compr lz4hc(3) in 512kB chunks took 451074 us (8 MB/s), compress ratio: 4.10 [ 2376.105385] lustre_kcompr_30202: compr lz4hc(3) in 1024kB chunks took 440134 us (9 MB/s), compress ratio: 4.13 [ 2376.491751] lustre_kcompr_30202: compr lz4hc(3) in 2048kB chunks took 366374 us (10 MB/s), compress ratio: 4.15 [ 2376.868239] lustre_kcompr_30202: compr lz4hc(3) in 4096kB chunks took 364720 us (10 MB/s), compress ratio: 4.16 [ 2376.920272] lustre_kcompr_30202: decompr lz4hc(3) took 20913 us (45 MB/s) [ 2376.925447] lustre_kcompr_30202: test_comp_compress_decompress(lz4hc,3) ret 0 [ 2376.964786] lustre_kcompr_30202: acompr lz4hc(3) of 128kB chunks took 21366 us (5 MB/s), compress ratio: 3.38 [ 2376.975618] lustre_kcompr_30202: adecompr lz4hc(3) took 221 us (166 MB/s) [ 2376.990533] lustre_kcompr_30202: test_acomp_compress_decompress(lz4hc,3) ret 0 [ 2377.530153] lustre_kcompr_30202: compr lz4hc(8) in 64kB chunks took 514373 us (7 MB/s), compress ratio: 3.72 [ 2378.115807] lustre_kcompr_30202: compr lz4hc(8) in 128kB chunks took 569231 us (7 MB/s), compress ratio: 3.96 [ 2378.726638] lustre_kcompr_30202: compr lz4hc(8) in 256kB chunks took 602468 us (6 MB/s), compress ratio: 4.10 [ 2379.075836] lustre_kcompr_30202: compr lz4hc(8) in 512kB chunks took 336538 us (11 MB/s), compress ratio: 4.17 [ 2379.371811] lustre_kcompr_30202: compr lz4hc(8) in 1024kB chunks took 289969 us (13 MB/s), compress ratio: 4.21 [ 2379.909386] lustre_kcompr_30202: compr lz4hc(8) in 2048kB chunks took 533023 us (7 MB/s), compress ratio: 4.22 [ 2380.391398] lustre_kcompr_30202: compr lz4hc(8) in 4096kB chunks took 475648 us (8 MB/s), compress ratio: 4.23 [ 2380.425644] lustre_kcompr_30202: decompr lz4hc(8) took 17530 us (53 MB/s) [ 2380.431797] lustre_kcompr_30202: test_comp_compress_decompress(lz4hc,8) ret 0 [ 2380.472613] lustre_kcompr_30202: acompr lz4hc(8) of 128kB chunks took 31014 us (4 MB/s), compress ratio: 3.42 [ 2380.484111] lustre_kcompr_30202: adecompr lz4hc(8) took 175 us (208 MB/s) [ 2380.504643] lustre_kcompr_30202: test_acomp_compress_decompress(lz4hc,8) ret 0 [ 2380.916745] lustre_kcompr_30202: compr lz4hc(15) in 64kB chunks took 396203 us (10 MB/s), compress ratio: 3.72 [ 2381.538534] lustre_kcompr_30202: compr lz4hc(15) in 128kB chunks took 617017 us (6 MB/s), compress ratio: 3.96 [ 2382.140649] lustre_kcompr_30202: compr lz4hc(15) in 256kB chunks took 596812 us (6 MB/s), compress ratio: 4.10 [ 2382.974986] lustre_kcompr_30202: compr lz4hc(15) in 512kB chunks took 827509 us (4 MB/s), compress ratio: 4.17 [ 2383.567209] lustre_kcompr_30202: compr lz4hc(15) in 1024kB chunks took 586913 us (6 MB/s), compress ratio: 4.21 [ 2384.320598] lustre_kcompr_30202: compr lz4hc(15) in 2048kB chunks took 748043 us (5 MB/s), compress ratio: 4.22 [ 2384.991700] lustre_kcompr_30202: compr lz4hc(15) in 4096kB chunks took 663556 us (6 MB/s), compress ratio: 4.23 [ 2385.014833] lustre_kcompr_30202: decompr lz4hc(15) took 7253 us (130 MB/s) [ 2385.021329] lustre_kcompr_30202: test_comp_compress_decompress(lz4hc,15) ret 0 [ 2385.049709] lustre_kcompr_30202: acompr lz4hc(15) of 128kB chunks took 21829 us (5 MB/s), compress ratio: 3.42 [ 2385.059153] lustre_kcompr_30202: adecompr lz4hc(15) took 2253 us (16 MB/s) [ 2385.080984] lustre_kcompr_30202: test_acomp_compress_decompress(lz4hc,15) ret 0 [ 2385.141312] lustre_kcompr_30202: compr lzo(-1) in 64kB chunks took 52631 us (76 MB/s), compress ratio: 2.90 [ 2385.191908] lustre_kcompr_30202: compr lzo(-1) in 128kB chunks took 41273 us (96 MB/s), compress ratio: 2.95 [ 2385.236158] lustre_kcompr_30202: compr lzo(-1) in 256kB chunks took 39193 us (102 MB/s), compress ratio: 2.96 [ 2385.278748] lustre_kcompr_30202: compr lzo(-1) in 512kB chunks took 29931 us (133 MB/s), compress ratio: 2.98 [ 2385.313349] lustre_kcompr_30202: compr lzo(-1) in 1024kB chunks took 24657 us (162 MB/s), compress ratio: 2.97 [ 2385.371072] lustre_kcompr_30202: compr lzo(-1) in 2048kB chunks took 48039 us (83 MB/s), compress ratio: 2.97 [ 2385.428353] lustre_kcompr_30202: compr lzo(-1) in 4096kB chunks took 40522 us (98 MB/s), compress ratio: 2.96 [ 2385.481432] lustre_kcompr_30202: decompr lzo(-1) took 31573 us (42 MB/s) [ 2385.491647] lustre_kcompr_30202: test_comp_compress_decompress(lzo,-1) ret 0 [ 2385.507654] lustre_kcompr_30202: acompr lzo(-1) of 128kB chunks took 593 us (210 MB/s), compress ratio: 2.62 [ 2385.512659] lustre_kcompr_30202: adecompr lzo(-1) took 312 us (152 MB/s) [ 2385.555676] lustre_kcompr_30202: test_acomp_compress_decompress(lzo,-1) ret 0 [ 2386.252631] lustre_kcompr_30202: compr deflate(-1) in 64kB chunks took 691061 us (5 MB/s), compress ratio: 3.51 [ 2386.995676] lustre_kcompr_30202: compr deflate(-1) in 128kB chunks took 739355 us (5 MB/s), compress ratio: 3.53 [ 2387.616255] lustre_kcompr_30202: compr deflate(-1) in 256kB chunks took 612641 us (6 MB/s), compress ratio: 3.53 [ 2388.339779] lustre_kcompr_30202: compr deflate(-1) in 512kB chunks took 715669 us (5 MB/s), compress ratio: 3.54 [ 2389.060781] lustre_kcompr_30202: compr deflate(-1) in 1024kB chunks took 716415 us (5 MB/s), compress ratio: 3.54 [ 2389.723410] lustre_kcompr_30202: compr deflate(-1) in 2048kB chunks took 654858 us (6 MB/s), compress ratio: 3.54 [ 2390.438211] lustre_kcompr_30202: compr deflate(-1) in 4096kB chunks took 708482 us (5 MB/s), compress ratio: 3.54 [ 2390.537499] lustre_kcompr_30202: decompr deflate(-1) took 53580 us (21 MB/s) [ 2390.543702] lustre_kcompr_30202: test_comp_compress_decompress(deflate,-1) ret 0 [ 2390.581985] lustre_kcompr_30202: acompr deflate(-1) of 128kB chunks took 28269 us (4 MB/s), compress ratio: 3.09 [ 2390.590246] lustre_kcompr_30202: adecompr deflate(-1) took 2100 us (19 MB/s) [ 2390.599994] lustre_kcompr_30202: test_acomp_compress_decompress(deflate,-1) ret 0 [ 2390.604945] lustre_kcompr_30202: SUCCESS [ 2395.634606] lustre_kcompr_5481: ***** [ 2395.640572] lustre_kcompr_5481: (de)compression test on provided file /tmp/f84.sanity [ 2395.649448] lustre_kcompr_5481: ***** [ 2395.691680] lustre_kcompr_5481: compr lz4(1) in 64kB chunks took 27229 us (146 MB/s), compress ratio: 2.45 [ 2395.741880] lustre_kcompr_5481: compr lz4(1) in 128kB chunks took 40931 us (97 MB/s), compress ratio: 2.39 [ 2395.766162] lustre_kcompr_5481: compr lz4(1) in 256kB chunks took 18566 us (215 MB/s), compress ratio: 2.39 [ 2395.791588] lustre_kcompr_5481: compr lz4(1) in 512kB chunks took 19962 us (200 MB/s), compress ratio: 2.39 [ 2395.822778] lustre_kcompr_5481: compr lz4(1) in 1024kB chunks took 26905 us (148 MB/s), compress ratio: 2.39 [ 2395.875693] lustre_kcompr_5481: compr lz4(1) in 2048kB chunks took 44847 us (89 MB/s), compress ratio: 2.39 [ 2395.915195] lustre_kcompr_5481: compr lz4(1) in 4096kB chunks took 23614 us (169 MB/s), compress ratio: 2.39 [ 2395.945113] lustre_kcompr_5481: decompr lz4(1) took 9598 us (173 MB/s) [ 2395.954220] lustre_kcompr_5481: test_comp_compress_decompress(lz4,1) ret 0 [ 2395.966025] lustre_kcompr_5481: acompr lz4(1) of 128kB chunks took 140 us (892 MB/s), compress ratio: 15.67 [ 2395.976281] lustre_kcompr_5481: adecompr lz4(1) took 100 us (79 MB/s) [ 2395.992261] lustre_kcompr_5481: test_acomp_compress_decompress(lz4,1) ret 0 [ 2396.030426] lustre_kcompr_5481: compr lz4(4) in 64kB chunks took 9158 us (436 MB/s), compress ratio: 2.36 [ 2396.056508] lustre_kcompr_5481: compr lz4(4) in 128kB chunks took 20921 us (191 MB/s), compress ratio: 2.35 [ 2396.071304] lustre_kcompr_5481: compr lz4(4) in 256kB chunks took 10657 us (375 MB/s), compress ratio: 2.35 [ 2396.085343] lustre_kcompr_5481: compr lz4(4) in 512kB chunks took 10055 us (397 MB/s), compress ratio: 2.35 [ 2396.098564] lustre_kcompr_5481: compr lz4(4) in 1024kB chunks took 9151 us (437 MB/s), compress ratio: 2.35 [ 2396.126185] lustre_kcompr_5481: compr lz4(4) in 2048kB chunks took 20830 us (192 MB/s), compress ratio: 2.35 [ 2396.149524] lustre_kcompr_5481: compr lz4(4) in 4096kB chunks took 14450 us (276 MB/s), compress ratio: 2.35 [ 2396.164399] lustre_kcompr_5481: decompr lz4(4) took 3634 us (467 MB/s) [ 2396.169429] lustre_kcompr_5481: test_comp_compress_decompress(lz4,4) ret 0 [ 2396.174848] lustre_kcompr_5481: acompr lz4(4) of 128kB chunks took 278 us (449 MB/s), compress ratio: 15.30 [ 2396.180620] lustre_kcompr_5481: adecompr lz4(4) took 104 us (78 MB/s) [ 2396.187149] lustre_kcompr_5481: test_acomp_compress_decompress(lz4,4) ret 0 [ 2396.214549] lustre_kcompr_5481: compr lz4(9) in 64kB chunks took 12727 us (314 MB/s), compress ratio: 2.32 [ 2396.234893] lustre_kcompr_5481: compr lz4(9) in 128kB chunks took 12371 us (323 MB/s), compress ratio: 2.31 [ 2396.257619] lustre_kcompr_5481: compr lz4(9) in 256kB chunks took 13403 us (298 MB/s), compress ratio: 2.31 [ 2396.277512] lustre_kcompr_5481: compr lz4(9) in 512kB chunks took 12949 us (308 MB/s), compress ratio: 2.31 [ 2396.303832] lustre_kcompr_5481: compr lz4(9) in 1024kB chunks took 19287 us (207 MB/s), compress ratio: 2.31 [ 2396.332189] lustre_kcompr_5481: compr lz4(9) in 2048kB chunks took 18400 us (217 MB/s), compress ratio: 2.32 [ 2396.353566] lustre_kcompr_5481: compr lz4(9) in 4096kB chunks took 14308 us (279 MB/s), compress ratio: 2.32 [ 2396.368863] lustre_kcompr_5481: decompr lz4(9) took 2781 us (619 MB/s) [ 2396.372397] lustre_kcompr_5481: test_comp_compress_decompress(lz4,9) ret 0 [ 2396.375919] lustre_kcompr_5481: acompr lz4(9) of 128kB chunks took 100 us (1250 MB/s), compress ratio: 14.81 [ 2396.380195] lustre_kcompr_5481: adecompr lz4(9) took 301 us (28 MB/s) [ 2396.385584] lustre_kcompr_5481: test_acomp_compress_decompress(lz4,9) ret 0 [ 2396.396855] lustre_kcompr_5481: compr lz4(15) in 64kB chunks took 3244 us (1233 MB/s), compress ratio: 2.23 [ 2396.404285] lustre_kcompr_5481: compr lz4(15) in 128kB chunks took 3497 us (1143 MB/s), compress ratio: 2.23 [ 2396.415280] lustre_kcompr_5481: compr lz4(15) in 256kB chunks took 6739 us (593 MB/s), compress ratio: 2.23 [ 2396.431257] lustre_kcompr_5481: compr lz4(15) in 512kB chunks took 8149 us (490 MB/s), compress ratio: 2.23 [ 2396.449765] lustre_kcompr_5481: compr lz4(15) in 1024kB chunks took 12977 us (308 MB/s), compress ratio: 2.23 [ 2396.470602] lustre_kcompr_5481: compr lz4(15) in 2048kB chunks took 10711 us (373 MB/s), compress ratio: 2.23 [ 2396.484465] lustre_kcompr_5481: compr lz4(15) in 4096kB chunks took 8727 us (458 MB/s), compress ratio: 2.23 [ 2396.505480] lustre_kcompr_5481: decompr lz4(15) took 4046 us (442 MB/s) [ 2396.509881] lustre_kcompr_5481: test_comp_compress_decompress(lz4,15) ret 0 [ 2396.537809] lustre_kcompr_5481: acompr lz4(15) of 128kB chunks took 5177 us (24 MB/s), compress ratio: 14.18 [ 2396.552430] lustre_kcompr_5481: adecompr lz4(15) took 106 us (83 MB/s) [ 2396.558804] lustre_kcompr_5481: test_acomp_compress_decompress(lz4,15) ret 0 [ 2396.890816] lustre_kcompr_5481: compr lz4hc(1) in 64kB chunks took 317062 us (12 MB/s), compress ratio: 2.54 [ 2397.145269] lustre_kcompr_5481: compr lz4hc(1) in 128kB chunks took 246514 us (16 MB/s), compress ratio: 2.61 [ 2397.282613] lustre_kcompr_5481: compr lz4hc(1) in 256kB chunks took 133674 us (29 MB/s), compress ratio: 2.64 [ 2397.462959] lustre_kcompr_5481: compr lz4hc(1) in 512kB chunks took 175198 us (22 MB/s), compress ratio: 2.66 [ 2397.734165] lustre_kcompr_5481: compr lz4hc(1) in 1024kB chunks took 254609 us (15 MB/s), compress ratio: 2.67 [ 2397.979595] lustre_kcompr_5481: compr lz4hc(1) in 2048kB chunks took 239847 us (16 MB/s), compress ratio: 2.67 [ 2398.156169] lustre_kcompr_5481: compr lz4hc(1) in 4096kB chunks took 171993 us (23 MB/s), compress ratio: 2.67 [ 2398.172940] lustre_kcompr_5481: decompr lz4hc(1) took 4540 us (329 MB/s) [ 2398.177072] lustre_kcompr_5481: test_comp_compress_decompress(lz4hc,1) ret 0 [ 2398.182295] lustre_kcompr_5481: acompr lz4hc(1) of 128kB chunks took 795 us (157 MB/s), compress ratio: 15.97 [ 2398.200627] lustre_kcompr_5481: adecompr lz4hc(1) took 108 us (72 MB/s) [ 2398.216459] lustre_kcompr_5481: test_acomp_compress_decompress(lz4hc,1) ret 0 [ 2398.529991] lustre_kcompr_5481: compr lz4hc(3) in 64kB chunks took 301500 us (13 MB/s), compress ratio: 2.57 [ 2398.900381] lustre_kcompr_5481: compr lz4hc(3) in 128kB chunks took 352989 us (11 MB/s), compress ratio: 2.64 [ 2399.143531] lustre_kcompr_5481: compr lz4hc(3) in 256kB chunks took 236471 us (16 MB/s), compress ratio: 2.68 [ 2399.373572] lustre_kcompr_5481: compr lz4hc(3) in 512kB chunks took 225977 us (17 MB/s), compress ratio: 2.69 [ 2399.660593] lustre_kcompr_5481: compr lz4hc(3) in 1024kB chunks took 277668 us (14 MB/s), compress ratio: 2.70 [ 2399.948512] lustre_kcompr_5481: compr lz4hc(3) in 2048kB chunks took 282662 us (14 MB/s), compress ratio: 2.71 [ 2400.169481] lustre_kcompr_5481: compr lz4hc(3) in 4096kB chunks took 212149 us (18 MB/s), compress ratio: 2.71 [ 2400.207434] lustre_kcompr_5481: decompr lz4hc(3) took 6874 us (214 MB/s) [ 2400.215996] lustre_kcompr_5481: test_comp_compress_decompress(lz4hc,3) ret 0 [ 2400.230996] lustre_kcompr_5481: acompr lz4hc(3) of 128kB chunks took 4424 us (28 MB/s), compress ratio: 16.00 [ 2400.248977] lustre_kcompr_5481: adecompr lz4hc(3) took 122 us (64 MB/s) [ 2400.272463] lustre_kcompr_5481: test_acomp_compress_decompress(lz4hc,3) ret 0 [ 2400.811927] lustre_kcompr_5481: compr lz4hc(8) in 64kB chunks took 515498 us (7 MB/s), compress ratio: 2.60 [ 2401.291872] lustre_kcompr_5481: compr lz4hc(8) in 128kB chunks took 472923 us (8 MB/s), compress ratio: 2.66 [ 2401.746306] lustre_kcompr_5481: compr lz4hc(8) in 256kB chunks took 448923 us (8 MB/s), compress ratio: 2.70 [ 2402.367150] lustre_kcompr_5481: compr lz4hc(8) in 512kB chunks took 600978 us (6 MB/s), compress ratio: 2.71 [ 2403.040589] lustre_kcompr_5481: compr lz4hc(8) in 1024kB chunks took 669291 us (5 MB/s), compress ratio: 2.72 [ 2403.750083] lustre_kcompr_5481: compr lz4hc(8) in 2048kB chunks took 695405 us (5 MB/s), compress ratio: 2.73 [ 2404.622130] lustre_kcompr_5481: compr lz4hc(8) in 4096kB chunks took 867054 us (4 MB/s), compress ratio: 2.73 [ 2404.654900] lustre_kcompr_5481: decompr lz4hc(8) took 10470 us (139 MB/s) [ 2404.668203] lustre_kcompr_5481: test_comp_compress_decompress(lz4hc,8) ret 0 [ 2404.698026] lustre_kcompr_5481: acompr lz4hc(8) of 128kB chunks took 12121 us (10 MB/s), compress ratio: 16.17 [ 2404.705647] lustre_kcompr_5481: adecompr lz4hc(8) took 658 us (11 MB/s) [ 2404.750990] lustre_kcompr_5481: test_acomp_compress_decompress(lz4hc,8) ret 0 [ 2414.118364] lustre_kcompr_5481: compr lz4hc(15) in 64kB chunks took 9332929 us (0 MB/s), compress ratio: 2.61 [ 2426.883845] lustre_kcompr_5481: compr lz4hc(15) in 128kB chunks took 12758599 us (0 MB/s), compress ratio: 2.67 [ 2437.645946] lustre_kcompr_5481: compr lz4hc(15) in 256kB chunks took 10747623 us (0 MB/s), compress ratio: 2.71 [ 2454.842916] lustre_kcompr_5481: compr lz4hc(15) in 512kB chunks took 17192824 us (0 MB/s), compress ratio: 2.72 [ 2466.887595] lustre_kcompr_5481: compr lz4hc(15) in 1024kB chunks took 12038279 us (0 MB/s), compress ratio: 2.73 [ 2478.891662] lustre_kcompr_5481: compr lz4hc(15) in 2048kB chunks took 11999428 us (0 MB/s), compress ratio: 2.74 [ 2490.453768] lustre_kcompr_5481: compr lz4hc(15) in 4096kB chunks took 11549869 us (0 MB/s), compress ratio: 2.74 [ 2490.470405] lustre_kcompr_5481: decompr lz4hc(15) took 4241 us (343 MB/s) [ 2490.476676] lustre_kcompr_5481: test_comp_compress_decompress(lz4hc,15) ret 0 [ 2490.519178] lustre_kcompr_5481: acompr lz4hc(15) of 128kB chunks took 39416 us (3 MB/s), compress ratio: 16.30 [ 2490.524698] lustre_kcompr_5481: adecompr lz4hc(15) took 102 us (75 MB/s) [ 2490.530044] lustre_kcompr_5481: test_acomp_compress_decompress(lz4hc,15) ret 0 [ 2490.548579] lustre_kcompr_5481: compr lzo(-1) in 64kB chunks took 15594 us (256 MB/s), compress ratio: 2.35 [ 2490.588075] lustre_kcompr_5481: compr lzo(-1) in 128kB chunks took 35824 us (111 MB/s), compress ratio: 2.35 [ 2490.632863] lustre_kcompr_5481: compr lzo(-1) in 256kB chunks took 26092 us (153 MB/s), compress ratio: 2.35 [ 2490.671867] lustre_kcompr_5481: compr lzo(-1) in 512kB chunks took 31914 us (125 MB/s), compress ratio: 2.36 [ 2490.704445] lustre_kcompr_5481: compr lzo(-1) in 1024kB chunks took 26410 us (151 MB/s), compress ratio: 2.36 [ 2490.735655] lustre_kcompr_5481: compr lzo(-1) in 2048kB chunks took 27200 us (147 MB/s), compress ratio: 2.36 [ 2490.770544] lustre_kcompr_5481: compr lzo(-1) in 4096kB chunks took 26726 us (149 MB/s), compress ratio: 2.36 [ 2490.804821] lustre_kcompr_5481: decompr lzo(-1) took 14240 us (118 MB/s) [ 2490.811581] lustre_kcompr_5481: test_comp_compress_decompress(lzo,-1) ret 0 [ 2490.821062] lustre_kcompr_5481: acompr lzo(-1) of 128kB chunks took 1314 us (95 MB/s), compress ratio: 15.45 [ 2490.826126] lustre_kcompr_5481: adecompr lzo(-1) took 192 us (42 MB/s) [ 2490.831288] lustre_kcompr_5481: test_acomp_compress_decompress(lzo,-1) ret 0 [ 2491.732627] lustre_kcompr_5481: compr deflate(-1) in 64kB chunks took 895223 us (4 MB/s), compress ratio: 3.27 [ 2492.777406] lustre_kcompr_5481: compr deflate(-1) in 128kB chunks took 1040396 us (3 MB/s), compress ratio: 3.28 [ 2493.647533] lustre_kcompr_5481: compr deflate(-1) in 256kB chunks took 847962 us (4 MB/s), compress ratio: 3.28 [ 2494.421245] lustre_kcompr_5481: compr deflate(-1) in 512kB chunks took 755466 us (5 MB/s), compress ratio: 3.28 [ 2495.014421] lustre_kcompr_5481: compr deflate(-1) in 1024kB chunks took 576087 us (6 MB/s), compress ratio: 3.28 [ 2495.759289] lustre_kcompr_5481: compr deflate(-1) in 2048kB chunks took 739882 us (5 MB/s), compress ratio: 3.28 [ 2496.436200] lustre_kcompr_5481: compr deflate(-1) in 4096kB chunks took 671096 us (5 MB/s), compress ratio: 3.28 [ 2496.504705] lustre_kcompr_5481: decompr deflate(-1) took 55405 us (21 MB/s) [ 2496.512362] lustre_kcompr_5481: test_comp_compress_decompress(deflate,-1) ret 0 [ 2496.533891] lustre_kcompr_5481: acompr deflate(-1) of 128kB chunks took 13942 us (8 MB/s), compress ratio: 21.43 [ 2496.538777] lustre_kcompr_5481: adecompr deflate(-1) took 318 us (18 MB/s) [ 2496.550629] lustre_kcompr_5481: test_acomp_compress_decompress(deflate,-1) ret 0 [ 2496.561134] lustre_kcompr_5481: SUCCESS [ 2504.592336] Lustre: DEBUG MARKER: == sanity test 99: cvs strange file/directory operations ========================================================== 05:16:42 (1779095802) [ 2537.913586] Lustre: DEBUG MARKER: == sanity test 100: check local port using privileged port ========================================================== 05:17:16 (1779095836) [ 2547.363714] Lustre: DEBUG MARKER: == sanity test 101a: check read-ahead for random reads === 05:17:25 (1779095845) [ 2753.678068] Lustre: DEBUG MARKER: == sanity test 101b: check stride-io mode read-ahead =========================================================================== 05:20:51 (1779096051) [ 2788.140193] Lustre: DEBUG MARKER: == sanity test 101c: check stripe_size aligned read-ahead ========================================================== 05:21:25 (1779096085) [ 2876.029251] Lustre: DEBUG MARKER: == sanity test 101d: file read with and without read-ahead enabled ========================================================== 05:22:54 (1779096174) [ 3133.601932] Lustre: DEBUG MARKER: == sanity test 101e: check read-ahead for small read(1k) for small files(500k) ========================================================== 05:27:11 (1779096431) [ 3219.311950] Lustre: DEBUG MARKER: == sanity test 101f: check mmap read performance ========= 05:28:37 (1779096517) [ 3230.029430] Lustre: DEBUG MARKER: == sanity test 101g: Big bulk(4/16 MiB) readahead ======== 05:28:48 (1779096528) [ 3238.034519] LustreError: 78499:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9e354b58e000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 3238.042475] LustreError: 78499:0:(lov_obd.c:792:lov_cleanup()) Skipped 3 previous similar messages [ 3238.122503] Lustre: Unmounted lustre-client [ 3238.123794] Lustre: Skipped 1 previous similar message [ 3238.831435] Lustre: Mounted lustre-client [ 3238.832592] Lustre: Skipped 1 previous similar message [ 3277.384564] LustreError: 78641:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9e354a963000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 3277.402933] LustreError: 78641:0:(lov_obd.c:792:lov_cleanup()) Skipped 1 previous similar message [ 3277.488472] Lustre: Unmounted lustre-client [ 3278.286760] Lustre: Mounted lustre-client [ 3307.149909] Lustre: DEBUG MARKER: == sanity test 101h: Readahead should cover current read window ========================================================== 05:30:05 (1779096605) [ 3326.679209] Lustre: DEBUG MARKER: == sanity test 101i: allow current readahead to exceed reservation ========================================================== 05:30:25 (1779096625) [ 3337.135446] Lustre: DEBUG MARKER: == sanity test 101j: A complete read block should be submitted when no RA ========================================================== 05:30:35 (1779096635) [ 3388.865615] Lustre: DEBUG MARKER: == sanity test 101m: read ahead for small file and last stripe of the file ========================================================== 05:31:27 (1779096687) [ 3390.020453] Lustre: DEBUG MARKER: Test readahead: size=4096 ramax= iosz=1048576 [ 3390.467569] Lustre: DEBUG MARKER: Test readahead: size=16384 ramax= iosz=1048576 [ 3390.840593] Lustre: DEBUG MARKER: Test readahead: size=16385 ramax= iosz=1048576 [ 3391.175801] Lustre: DEBUG MARKER: Test readahead: size=16383 ramax= iosz=1048576 [ 3391.568481] Lustre: DEBUG MARKER: Test readahead: size=1048577 ramax= iosz=2097152 [ 3392.071759] Lustre: DEBUG MARKER: Test readahead: size=1064960 ramax= iosz=2097152 [ 3392.536743] Lustre: DEBUG MARKER: Test readahead: size=1064960 ramax= iosz=2097152 [ 3393.090501] Lustre: DEBUG MARKER: Test readahead: size=2113536 ramax= iosz=3145728 [ 3393.586794] Lustre: DEBUG MARKER: Test readahead: size=4210688 ramax= iosz=5242880 [ 3400.150545] Lustre: DEBUG MARKER: == sanity test 102a: user xattr test ============================================================================================ 05:31:38 (1779096698) [ 3407.841877] Lustre: DEBUG MARKER: == sanity test 102b: getfattr/setfattr for trusted.lov EAs ========================================================== 05:31:46 (1779096706) [ 3420.478083] Lustre: DEBUG MARKER: == sanity test 102c: non-root getfattr/setfattr for lustre.lov EAs ===================================================================== 05:31:58 (1779096718) [ 3428.351183] Lustre: DEBUG MARKER: == sanity test 102d: tar restore stripe info from tarfile,not keep osts ========================================================== 05:32:06 (1779096726) [ 3446.177911] Lustre: DEBUG MARKER: == sanity test 102f: tar copy files, not keep osts ======= 05:32:24 (1779096744) [ 3464.122774] Lustre: DEBUG MARKER: == sanity test 102h: grow xattr from inside inode to external block ========================================================== 05:32:42 (1779096762) [ 3466.316561] Lustre: DEBUG MARKER: save trusted.big on /mnt/lustre/f102h.sanity [ 3468.041685] Lustre: DEBUG MARKER: save trusted.sml on /mnt/lustre/f102h.sanity [ 3469.801434] Lustre: DEBUG MARKER: grow trusted.sml on /mnt/lustre/f102h.sanity [ 3471.526541] Lustre: DEBUG MARKER: trusted.big still valid after growing trusted.sml [ 3478.468672] Lustre: DEBUG MARKER: == sanity test 102ha: grow xattr from inside inode to external inode ========================================================== 05:32:56 (1779096776) [ 3481.540199] Lustre: DEBUG MARKER: save trusted.big on /mnt/lustre/f102ha.sanity [ 3483.088861] Lustre: DEBUG MARKER: save trusted.sml on /mnt/lustre/f102ha.sanity [ 3484.669797] Lustre: DEBUG MARKER: grow trusted.sml on /mnt/lustre/f102ha.sanity [ 3486.275640] Lustre: DEBUG MARKER: trusted.big still valid after growing trusted.sml [ 3488.431827] Lustre: DEBUG MARKER: save trusted.big on /mnt/lustre/f102ha.sanity [ 3495.003883] Lustre: DEBUG MARKER: == sanity test 102i: lgetxattr test on symbolic link ====================================================================== 05:33:13 (1779096793) [ 3501.969043] Lustre: DEBUG MARKER: == sanity test 102j: non-root tar restore stripe info from tarfile, not keep osts ============================================================= 05:33:20 (1779096800) [ 3520.614073] Lustre: DEBUG MARKER: == sanity test 102k: setfattr without parameter of value shouldn't cause a crash ========================================================== 05:33:38 (1779096818) [ 3528.849908] Lustre: DEBUG MARKER: == sanity test 102l: listxattr size test ============================================================================================ 05:33:47 (1779096827) [ 3535.954985] Lustre: DEBUG MARKER: == sanity test 102m: Ensure listxattr fails on small bufffer ================================================================== 05:33:54 (1779096834) [ 3543.491278] Lustre: DEBUG MARKER: == sanity test 102n: silently ignore setxattr on internal trusted xattrs ========================================================== 05:34:01 (1779096841) [ 3551.307837] Lustre: DEBUG MARKER: == sanity test 102p: check setxattr(2) correctly fails without permission ========================================================== 05:34:09 (1779096849) [ 3557.531813] Lustre: DEBUG MARKER: == sanity test 102q: flistxattr should not return trusted.link EAs for orphans ========================================================== 05:34:15 (1779096855) [ 3563.709787] Lustre: DEBUG MARKER: == sanity test 102r: set EAs with empty values =========== 05:34:22 (1779096862) [ 3571.462771] Lustre: DEBUG MARKER: == sanity test 102s: getting nonexistent xattrs should fail ========================================================== 05:34:29 (1779096869) [ 3572.009779] LustreError: lustre-MDT0000-mdc-ffff9e354894d800: operation mds_getxattr to node 192.168.202.131@tcp failed: rc = -95 [ 3578.855362] Lustre: DEBUG MARKER: == sanity test 102t: zero length xattr values handled correctly ========================================================== 05:34:37 (1779096877) [ 3586.319703] Lustre: DEBUG MARKER: == sanity test 103a: acl test ============================ 05:34:44 (1779096884) [ 3861.800266] Lustre: DEBUG MARKER: == sanity test 103b: umask lfs setstripe ================= 05:39:19 (1779097159) [ 4039.209551] Lustre: DEBUG MARKER: == sanity test 103c: 'cp -rp' won't set empty acl ======== 05:42:17 (1779097337) [ 4047.950252] Lustre: DEBUG MARKER: == sanity test 103e: inheritance of big amount of default ACLs ========================================================== 05:42:25 (1779097345) [ 4080.145726] Lustre: DEBUG MARKER: == sanity test 103f: changelog doesn't interfere with default ACLs buffers ========================================================== 05:42:57 (1779097377) [ 4105.660792] Lustre: DEBUG MARKER: == sanity test 103g: no MDS_GETXATTR storm for inodes without ACL_ACCESS (LU-17238) ========================================================== 05:43:23 (1779097403) [ 4114.769819] Lustre: DEBUG MARKER: == sanity test 104a: lfs df [-ih] [path] test =================================================================================== 05:43:32 (1779097412) [ 4115.550393] Lustre: setting import lustre-OST0000_UUID INACTIVE by administrator request [ 4115.605626] Lustre: lustre-OST0000-osc-ffff9e354894d800: Connection to lustre-OST0000 (at 192.168.202.131@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 4115.632819] LustreError: lustre-OST0000-osc-ffff9e354894d800: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 4115.653595] Lustre: lustre-OST0000-osc-ffff9e354894d800: Connection restored to 192.168.202.131@tcp (at 192.168.202.131@tcp) [ 4120.995711] Lustre: DEBUG MARKER: oleg231-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0000-osc-ffff9e354894d800.ost_server_uuid 50 [ 4122.759204] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9e354894d800.ost_server_uuid in FULL state after 0 sec [ 4131.857925] Lustre: DEBUG MARKER: == sanity test 104b: runas -u 500 -g 500 lfs check servers test ============================================================================== 05:43:49 (1779097429) [ 4140.301223] Lustre: DEBUG MARKER: == sanity test 104c: Verify df vs lfs_df stays same after recordsize change ========================================================== 05:43:58 (1779097438) [ 4142.358936] Lustre: DEBUG MARKER: SKIP: sanity test_104c zfs only test [ 4144.520258] Lustre: DEBUG MARKER: == sanity test 104d: runas -u 500 -g 500 lctl dl test ==== 05:44:02 (1779097442) [ 4153.571647] Lustre: DEBUG MARKER: == sanity test 105a: flock when mounted without -o flock test ================================================================== 05:44:11 (1779097451) [ 4163.830725] Lustre: DEBUG MARKER: == sanity test 105b: fcntl when mounted without -o flock test ================================================================== 05:44:21 (1779097461) [ 4173.701103] Lustre: DEBUG MARKER: == sanity test 105c: lockf when mounted without -o flock test ========================================================== 05:44:31 (1779097471) [ 4183.659442] Lustre: DEBUG MARKER: == sanity test 105d: flock race (should not freeze) ================================================================== 05:44:41 (1779097481) [ 4184.352124] LustreError: 113726:0:(ldlm_flock.c:851:ldlm_flock_completion_ast()) cfs_fail_timeout id 315 sleeping for 10000ms [ 4194.369955] LustreError: 113726:0:(ldlm_flock.c:851:ldlm_flock_completion_ast()) cfs_fail_timeout id 315 awake [ 4203.341897] Lustre: DEBUG MARKER: == sanity test 105e: Two conflicting flocks from same process ========================================================== 05:45:01 (1779097501) [ 4212.222968] Lustre: DEBUG MARKER: == sanity test 105f: Enqueue same range flocks =========== 05:45:09 (1779097509) [ 4224.033398] Lustre: DEBUG MARKER: == sanity test 105g: ldlm_lock_debug stack test ========== 05:45:21 (1779097521) [ 4224.645452] Lustre: *** cfs_fail_loc=32f, val=0*** [ 4224.647494] LustreError: 115582:0:(ldlm_flock.c:803:ldlm_flock_completion_ast()) ### Test ldlm error stack ns: lustre-MDT0000-mdc-ffff9e354894d800 lock: ffff9e3549650000/0xd6998ca8246cda26 lrc: 4/0,1 mode: PW/PW res: [0x20000040a:0xb42:0x0].0xc rrc: 2 type: FLK pid: 115581 [0->9223372036854775807] flags: 0x0 nid: local remote: 0x28879ca89fc705c8 expref: -99 pid: 115582 timeout: 0 [ 4224.674958] CPU: 1 PID: 115582 Comm: flocks_test Kdump: loaded Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 4224.684889] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.17.0-8.fc42 06/10/2025 [ 4224.695058] Call Trace: [ 4224.696718] ? dump_stack+0xbb/0x10e [ 4224.699156] ? ldlm_flock_completion_ast.cold.17+0xd/0x27 [ptlrpc] [ 4224.708702] ? _raw_spin_unlock+0x12/0x30 [ 4224.712191] ? unlock_res_and_lock+0x23/0x30 [ptlrpc] [ 4224.717471] ? ldlm_lock_enqueue+0x3a1/0xcd0 [ptlrpc] [ 4224.724059] ? ldlm_cli_enqueue_fini+0xadc/0x1500 [ptlrpc] [ 4224.737882] ? ldlm_cli_enqueue+0x47f/0xe40 [ptlrpc] [ 4224.741646] ? ldlm_flock_completion_ast_async+0xb30/0xb30 [ptlrpc] [ 4224.745162] ? mdc_changelog_cdev_finish+0x2c0/0x2c0 [mdc] [ 4224.750500] ? mdc_enqueue_base+0x458/0x1db0 [mdc] [ 4224.756612] ? mdc_enqueue+0x1c/0x30 [mdc] [ 4224.763426] ? lmv_enqueue+0x28a/0x530 [lmv] [ 4224.767815] ? ll_file_flock+0x962/0x1420 [lustre] [ 4224.769428] ? ldlm_flock_completion_ast_async+0xb30/0xb30 [ptlrpc] [ 4224.782656] ? mdc_changelog_cdev_finish+0x2c0/0x2c0 [mdc] [ 4224.791824] ? __mod_memcg_lruvec_state+0x5e/0x130 [ 4224.793198] ? __mod_lruvec_state+0x5a/0x80 [ 4224.796245] ? page_add_new_anon_rmap+0x77/0x1c0 [ 4224.798498] ? slab_post_alloc_hook+0x66/0x380 [ 4224.802549] ? locks_alloc_lock+0x1f/0x90 [ 4224.807149] ? kmem_cache_alloc+0x184/0x430 [ 4224.812534] ? vfs_lock_file+0x22/0x50 [ 4224.818124] ? fcntl_setlk+0xde/0x4e0 [ 4224.819431] ? __might_sleep+0x59/0xc0 [ 4224.820689] ? do_fcntl+0x7da/0xb80 [ 4224.824065] ? __x64_sys_fcntl+0xc4/0x110 [ 4224.826875] ? do_syscall_64+0xc1/0x440 [ 4224.828162] ? entry_SYSCALL_64_after_hwframe+0x49/0xae [ 4235.334723] Lustre: DEBUG MARKER: == sanity test 105h: Flock functional verify ============= 05:45:33 (1779097533) [ 4247.150413] Lustre: DEBUG MARKER: == sanity test 105i: Flock deadlock verify =============== 05:45:44 (1779097544) [ 4252.540546] LustreError: lustre-MDT0000-mdc-ffff9e354894d800: operation ldlm_enqueue to node 192.168.202.131@tcp failed: rc = -35 [ 4261.737791] Lustre: DEBUG MARKER: == sanity test 106: attempt exec of dir followed by chown of that dir ========================================================== 05:45:59 (1779097559) [ 4272.261070] Lustre: DEBUG MARKER: == sanity test 107: Coredump on SIG ====================== 05:46:09 (1779097569) [ 4284.925291] Lustre: DEBUG MARKER: == sanity test 110: filename length checking ============= 05:46:22 (1779097582) [ 4296.105046] Lustre: DEBUG MARKER: == sanity test 116a: stripe QOS: free space balance ============================================================================= 05:46:33 (1779097593) [ 4505.923564] Lustre: DEBUG MARKER: == sanity test 116b: QoS shouldn't LBUG if not enough OSTs found on the 2nd pass ========================================================== 05:50:04 (1779097804) [ 4522.729414] Lustre: DEBUG MARKER: == sanity test 117: verify osd extend ==================== 05:50:20 (1779097820) [ 4532.585334] Lustre: DEBUG MARKER: == sanity test 118a: verify O_SYNC works ================= 05:50:30 (1779097830) [ 4542.271940] Lustre: DEBUG MARKER: == sanity test 118b: Reclaim dirty pages on fatal error ==================================================================== 05:50:40 (1779097840) [ 4554.040895] Lustre: DEBUG MARKER: SKIP: sanity test_118c skipping ALWAYS excluded test 118c [ 4555.963849] Lustre: DEBUG MARKER: SKIP: sanity test_118d skipping ALWAYS excluded test 118d [ 4558.300819] Lustre: DEBUG MARKER: == sanity test 118f: Simulate unrecoverable OSC side error ==================================================================== 05:50:56 (1779097856) [ 4559.237264] Lustre: *** cfs_fail_loc=40a, val=0*** [ 4559.238953] Lustre: Skipped 41 previous similar messages [ 4559.244311] LustreError: 124312:0:(osc_request.c:2917:osc_build_rpc()) lustre-OST0001-osc-ffff9e354894d800: prep_req failed: rc = -22 [ 4559.259108] LustreError: 124312:0:(osc_cache.c:2367:osc_check_rpcs()) Write request failed with -22 [ 4568.104130] Lustre: DEBUG MARKER: == sanity test 118g: Don't stay in wait if we got local -ENOMEM ==================================================================== 05:51:05 (1779097865) [ 4568.984254] Lustre: *** cfs_fail_loc=406, val=0*** [ 4568.985543] LustreError: 124908:0:(osc_request.c:2917:osc_build_rpc()) lustre-OST0000-osc-ffff9e354894d800: prep_req failed: rc = -12 [ 4568.992372] LustreError: 124908:0:(osc_cache.c:2367:osc_check_rpcs()) Write request failed with -12 [ 4578.725882] Lustre: DEBUG MARKER: == sanity test 118h: Verify timeout in handling recoverables errors ==================================================================== 05:51:16 (1779097876) [ 4581.843196] LustreError: lustre-OST0001-osc-ffff9e354894d800: operation ost_write to node 192.168.202.131@tcp failed: rc = -5 [ 4581.850979] LustreError: 2409:0:(osc_request.c:2450:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff9e354bc72680 x1865514677443328/t0(0) o4->lustre-OST0001-osc-ffff9e354894d800@192.168.202.131@tcp:6/4 lens 4584/224 e 0 to 0 dl 1779097897 ref 2 fl Interpret:RMQU/600/0 rc -5/-5 job:'multiop.0' uid:0 gid:0 projid:0 [ 4581.868267] LustreError: 2409:0:(osc_request.c:2450:osc_brw_redo_request()) Skipped 1 previous similar message [ 4584.432074] LustreError: lustre-OST0001-osc-ffff9e354894d800: operation ost_write to node 192.168.202.131@tcp failed: rc = -5 [ 4584.443916] LustreError: Skipped 1 previous similar message [ 4587.545245] LustreError: lustre-OST0001-osc-ffff9e354894d800: operation ost_write to node 192.168.202.131@tcp failed: rc = -5 [ 4591.593785] LustreError: lustre-OST0001-osc-ffff9e354894d800: operation ost_write to node 192.168.202.131@tcp failed: rc = -5 [ 4591.598967] LustreError: 2408:0:(osc_request.c:2607:brw_interpret()) lustre-OST0001-osc-ffff9e354894d800: too many resent retries for object: 11811161089:6368: rc = -5 [ 4591.607324] LustreError: 2408:0:(osc_request.c:2607:brw_interpret()) Skipped 3 previous similar messages [ 4591.612231] Lustre: 2408:0:(llite_lib.c:4187:ll_dirty_page_discard_warn()) lustre: dirty page discard: 192.168.202.131@tcp:/lustre/fid: [0x20000040a:0xe74:0x0]// may get corrupted (rc -5) [ 4602.755882] Lustre: DEBUG MARKER: == sanity test 118i: Fix error before timeout in recoverable error ==================================================================== 05:51:40 (1779097900) [ 4607.088262] LustreError: lustre-OST0001-osc-ffff9e354894d800: operation ost_write to node 192.168.202.131@tcp failed: rc = -5 [ 4607.100971] LustreError: 2410:0:(osc_request.c:2450:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff9e35489bb100 x1865514677452672/t0(0) o4->lustre-OST0001-osc-ffff9e354894d800@192.168.202.131@tcp:6/4 lens 4584/224 e 0 to 0 dl 1779097922 ref 2 fl Interpret:RMQU/600/0 rc -5/-5 job:'multiop.0' uid:0 gid:0 projid:0 [ 4607.128464] LustreError: 2410:0:(osc_request.c:2450:osc_brw_redo_request()) Skipped 3 previous similar messages [ 4626.315168] Lustre: DEBUG MARKER: == sanity test 118j: Simulate unrecoverable OST side error ==================================================================== 05:52:04 (1779097924) [ 4629.155837] LustreError: lustre-OST0001-osc-ffff9e354894d800: operation ost_write to node 192.168.202.131@tcp failed: rc = -14 [ 4629.166034] LustreError: Skipped 3 previous similar messages [ 4641.195754] Lustre: DEBUG MARKER: == sanity test 118k: bio alloc -ENOMEM and IO TERM handling =================================================================== 05:52:18 (1779097938) [ 4644.682910] LustreError: 2410:0:(osc_request.c:2450:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff9e3549513800 x1865514677466752/t0(0) o4->lustre-OST0001-osc-ffff9e354894d800@192.168.202.131@tcp:6/4 lens 488/224 e 0 to 0 dl 1779097960 ref 2 fl Interpret:ReMQU/600/0 rc -5/-5 job:'dd.0' uid:0 gid:0 projid:0 [ 4644.740117] LustreError: 2410:0:(osc_request.c:2450:osc_brw_redo_request()) Skipped 3 previous similar messages [ 4669.113649] Lustre: DEBUG MARKER: == sanity test 118l: fsync dir =========================== 05:52:47 (1779097967) [ 4679.124218] Lustre: DEBUG MARKER: == sanity test 118m: fdatasync dir ======================= 05:52:56 (1779097976) [ 4688.921538] Lustre: DEBUG MARKER: == sanity test 118n: statfs() sends OST_STATFS requests in parallel ========================================================== 05:53:06 (1779097986) [ 4704.100805] Lustre: DEBUG MARKER: == sanity test 119a: Short directIO read must return actual read amount ========================================================== 05:53:21 (1779098001) [ 4715.172721] Lustre: DEBUG MARKER: == sanity test 119b: Sparse directIO read must return actual read amount ========================================================== 05:53:32 (1779098012) [ 4724.651843] Lustre: DEBUG MARKER: == sanity test 119c: Testing for direct read hitting hole ========================================================== 05:53:42 (1779098022) [ 4733.441887] Lustre: DEBUG MARKER: == sanity test 119e: Basic tests of dio read and write at various sizes ========================================================== 05:53:51 (1779098031) [ 4778.185575] Lustre: DEBUG MARKER: == sanity test 119f: dio vs dio race ===================== 05:54:35 (1779098075) [ 4838.395687] Lustre: DEBUG MARKER: == sanity test 119g: dio vs buffered I/O race ============ 05:55:35 (1779098135) [ 4895.089834] Lustre: DEBUG MARKER: == sanity test 119h: basic tests of memory unaligned dio ========================================================== 05:56:32 (1779098192) [ 4932.843784] Lustre: DEBUG MARKER: SKIP: sanity test_119i skipping ALWAYS excluded test 119i [ 4935.004147] Lustre: DEBUG MARKER: == sanity test 119j: basic tests of hybrid IO switching == 05:57:12 (1779098232) [ 4936.740677] sysctl (134805): drop_caches: 3 [ 4936.972071] Lustre: *** cfs_fail_loc=1429, val=0*** [ 4937.857705] Lustre: *** cfs_fail_loc=1429, val=0*** [ 4947.461740] Lustre: DEBUG MARKER: == sanity test 119k: hybrid IO counting with stats and disabling ========================================================== 05:57:25 (1779098245) [ 4972.809772] Lustre: DEBUG MARKER: == sanity test 119m: Test DIO readv/writev: exercise iter duplication ========================================================== 05:57:49 (1779098269) [ 4982.524393] Lustre: DEBUG MARKER: == sanity test 119n: Test Unaligned DIO readv() and writev() with unpatched ZFS ========================================================== 05:58:00 (1779098280) [ 4985.021811] Lustre: DEBUG MARKER: SKIP: sanity test_119n need ZFS server without unaligned_dio support [ 4987.261358] Lustre: DEBUG MARKER: == sanity test 119o: Test Unaligned DIO readv() and writev() with unpatched servers ========================================================== 05:58:05 (1779098285) [ 4989.136465] Lustre: DEBUG MARKER: SKIP: sanity test_119o need ldiskfs without unaligned_dio support. [ 4991.837125] Lustre: DEBUG MARKER: == sanity test 119p: Test Unaligned DIO readv() and writev() with patched servers ========================================================== 05:58:09 (1779098289) [ 5000.399515] Lustre: DEBUG MARKER: == sanity test 119q: Test patchded Unaligned DIO readv() and writev() ========================================================== 05:58:18 (1779098298) [ 5015.624309] Lustre: DEBUG MARKER: == sanity test 120a: Early Lock Cancel: mkdir test ======= 05:58:33 (1779098313) [ 5029.267900] Lustre: DEBUG MARKER: == sanity test 120b: Early Lock Cancel: create test ====== 05:58:46 (1779098326) [ 5042.196417] Lustre: DEBUG MARKER: == sanity test 120c: Early Lock Cancel: link test ======== 05:58:59 (1779098339) [ 5056.180051] Lustre: DEBUG MARKER: == sanity test 120d: Early Lock Cancel: setattr test ===== 05:59:13 (1779098353) [ 5070.972382] Lustre: DEBUG MARKER: == sanity test 120e: Early Lock Cancel: unlink test ====== 05:59:28 (1779098368) [ 5091.008449] Lustre: DEBUG MARKER: == sanity test 120f: Early Lock Cancel: rename test ====== 05:59:48 (1779098388) [ 5112.172170] Lustre: DEBUG MARKER: == sanity test 120g: Early Lock Cancel: performance test ========================================================== 06:00:10 (1779098410) [ 5572.447761] Lustre: DEBUG MARKER: == sanity test 121: read cancel race ===================== 06:07:49 (1779098869) [ 5573.199818] Lustre: *** cfs_fail_loc=310, val=0*** [ 5582.560160] Lustre: DEBUG MARKER: == sanity test 123aa: verify statahead work ============== 06:08:00 (1779098880) [ 5592.853982] Lustre: DEBUG MARKER: 'ls -l' 100 files without statahead: 2 sec [ 5595.773836] Lustre: DEBUG MARKER: 'ls -l' 100 files with statahead: 0 sec [ 5637.690902] Lustre: DEBUG MARKER: 'ls -l' 1000 files without statahead: 21 sec [ 5649.421927] Lustre: DEBUG MARKER: 'ls -l' 1000 files with statahead: 8 sec [ 5652.206809] Lustre: DEBUG MARKER: 'ls -l' done [ 5675.787107] Lustre: DEBUG MARKER: unlink + rm -r /mnt/lustre/d123aa.sanity: 22 seconds [ 5692.270883] Lustre: DEBUG MARKER: == sanity test 123ab: verify statahead work by using statx ========================================================== 06:09:49 (1779098989) [ 5705.577268] Lustre: DEBUG MARKER: 'statx -l' 100 files without statahead: 3 sec [ 5709.899125] Lustre: DEBUG MARKER: 'statx -l' 100 files with statahead: 2 sec [ 5754.959578] Lustre: DEBUG MARKER: 'statx -l' 1000 files without statahead: 22 sec [ 5766.159185] Lustre: DEBUG MARKER: 'statx -l' 1000 files with statahead: 6 sec [ 5768.209872] Lustre: DEBUG MARKER: 'statx -l' done [ 5792.667745] Lustre: DEBUG MARKER: unlink + rm -r /mnt/lustre/d123ab.sanity: 24 seconds [ 5807.986684] Lustre: DEBUG MARKER: == sanity test 123ac: verify statahead work by using statx without glimpse RPCs ========================================================== 06:11:45 (1779099105) [ 5821.437312] Lustre: DEBUG MARKER: 'statx -c 0 [ 5823.952849] Lustre: DEBUG MARKER: 'statx -c 0 [ 5856.495297] Lustre: DEBUG MARKER: 'statx -c 0 [ 5862.961845] Lustre: DEBUG MARKER: 'statx -c 0 [ 5864.710939] Lustre: DEBUG MARKER: 'statx -c 0 [ 5883.771679] Lustre: DEBUG MARKER: unlink + rm -r /mnt/lustre/d123ac.sanity: 18 seconds [ 5890.310811] Lustre: DEBUG MARKER: 'statx --cached=always -D' 100 files without statahead: 0 sec [ 5892.171929] Lustre: DEBUG MARKER: 'statx --cached=always -D' 100 files with statahead: 0 sec [ 5910.531635] Lustre: DEBUG MARKER: 'statx --cached=always -D' 1000 files without statahead: 0 sec [ 5912.681640] Lustre: DEBUG MARKER: 'statx --cached=always -D' 1000 files with statahead: 0 sec [ 6049.779806] Lustre: DEBUG MARKER: 'statx --cached=always -D' 10000 files without statahead: 0 sec [ 6052.780644] Lustre: DEBUG MARKER: 'statx --cached=always -D' 10000 files with statahead: 1 sec [ 6054.710398] Lustre: DEBUG MARKER: 'statx --cached=always -D' done [ 6398.861760] Lustre: DEBUG MARKER: unlink + rm -r /mnt/lustre/d123ac.sanity: 342 seconds [ 6420.123952] Lustre: DEBUG MARKER: == sanity test 123ad: Verify batching statahead works correctly ========================================================== 06:21:58 (1779099718) [ 6432.762895] Lustre: DEBUG MARKER: 'ls -l' 100 files without statahead: 3 sec [ 6435.797394] Lustre: DEBUG MARKER: 'ls -l' 100 files with statahead: 1 sec [ 6493.255096] Lustre: DEBUG MARKER: 'ls -l' 1000 files without statahead: 33 sec [ 6507.374255] Lustre: DEBUG MARKER: 'ls -l' 1000 files with statahead: 9 sec [ 6510.106585] Lustre: DEBUG MARKER: 'ls -l' done [ 6540.032611] Lustre: DEBUG MARKER: unlink + rm -r /mnt/lustre/d123ad.sanity: 27 seconds [ 7220.008741] Lustre: DEBUG MARKER: 'ls -l' 100 files without statahead: 4 sec [ 7224.436456] Lustre: DEBUG MARKER: 'ls -l' 100 files with statahead: 1 sec [ 7286.471681] Lustre: DEBUG MARKER: 'ls -l' 1000 files without statahead: 36 sec [ 7302.475484] Lustre: DEBUG MARKER: 'ls -l' 1000 files with statahead: 11 sec [ 7305.806887] Lustre: DEBUG MARKER: 'ls -l' done [ 7336.499575] Lustre: DEBUG MARKER: unlink + rm -r /mnt/lustre/d123ad.sanity: 29 seconds [ 7892.536229] Lustre: DEBUG MARKER: == sanity test 123b: not panic with network error in statahead enqueue (bug 15027) ========================================================== 06:46:30 (1779101190) [ 7918.621945] Lustre: DEBUG MARKER: ls done [ 7948.269099] Lustre: DEBUG MARKER: == sanity test 123c: Can not initialize inode warning on DNE statahead ========================================================== 06:47:26 (1779101246) [ 7952.355071] LustreError: 173059:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9e354894d800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 7952.366675] LustreError: 173059:0:(lov_obd.c:792:lov_cleanup()) Skipped 1 previous similar message [ 7952.446773] Lustre: Unmounted lustre-client [ 7953.109130] Lustre: Mounted lustre-client [ 7962.680206] Lustre: DEBUG MARKER: == sanity test 123d: Statahead on striped directories works correctly ========================================================== 06:47:40 (1779101260) [ 7971.961854] LustreError: 173736:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9e35442ab800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 7972.011031] LustreError: 173736:0:(lov_obd.c:792:lov_cleanup()) Skipped 1 previous similar message [ 7972.216926] Lustre: Unmounted lustre-client [ 7973.334350] Lustre: Mounted lustre-client [ 7998.984744] Lustre: DEBUG MARKER: == sanity test 123e: statahead with large wide striping == 06:48:16 (1779101296) [ 8401.560626] Lustre: DEBUG MARKER: == sanity test 123f: Retry mechanism with large wide striping files ========================================================== 06:54:57 (1779101697) [ 9862.590919] Lustre: DEBUG MARKER: == sanity test 123g: Test for stat-ahead advise ========== 07:19:20 (1779103160) [ 9996.750675] Lustre: DEBUG MARKER: == sanity test 123h: Verify statahead work with the fname pattern via du ========================================================== 07:21:34 (1779103294) [11960.574384] Lustre: DEBUG MARKER: == sanity test 123i: Verify statahead work with the fname indexing pattern ========================================================== 07:54:18 (1779105258) [12103.225717] Lustre: DEBUG MARKER: == sanity test 123j: -ENOENT error from batched statahead be handled correctly ========================================================== 07:56:40 (1779105400) [12113.896163] Lustre: DEBUG MARKER: == sanity test 123k: Verify statahead work with mdtest shared stat() mode ========================================================== 07:56:52 (1779105412) [12116.026615] Lustre: DEBUG MARKER: SKIP: sanity test_123k mdtest not found [12117.815569] Lustre: DEBUG MARKER: == sanity test 123l: Avoid panic when revalidate a local cached entry ========================================================== 07:56:56 (1779105416) [12122.921987] LustreError: 180384:0:(statahead.c:360:sa_put()) cfs_fail_timeout id 1433 sleeping for 35000ms [12157.935205] LustreError: 180384:0:(statahead.c:360:sa_put()) cfs_fail_timeout id 1433 awake [12198.412992] Lustre: DEBUG MARKER: == sanity test 124a: lru resize ================================================================================================= 07:58:16 (1779105496) [12200.267672] Lustre: DEBUG MARKER: create 2000 files at /mnt/lustre/d124a.sanity [12241.622230] Lustre: DEBUG MARKER: NSDIR=ldlm.namespaces.lustre-MDT0000-mdc-ffff9e3576ad9000 [12243.786835] Lustre: DEBUG MARKER: NS=ldlm.namespaces.lustre-MDT0000-mdc-ffff9e3576ad9000 [12245.367338] Lustre: DEBUG MARKER: LRU=1004 [12247.278874] Lustre: DEBUG MARKER: LIMIT=46162 [12249.048810] Lustre: DEBUG MARKER: LVF=5517300 [12250.889086] Lustre: DEBUG MARKER: OLD_LVF=100 [12252.694358] Lustre: DEBUG MARKER: Sleep 50 sec [12304.885709] Lustre: DEBUG MARKER: Dropped 541 locks in 50s [12306.739165] Lustre: DEBUG MARKER: unlink 2000 files at /mnt/lustre/d124a.sanity [12338.766254] Lustre: DEBUG MARKER: == sanity test 124b: lru resize (performance test) ================================================================================= 08:00:36 (1779105636) [12443.172649] Lustre: DEBUG MARKER: doing ls -la /mnt/lustre/d124b.sanity/disable_lru_resize 3 times [12609.256883] Lustre: DEBUG MARKER: ls -la time: 164 seconds [12612.017643] Lustre: DEBUG MARKER: lru_size = 400 [12841.749960] Lustre: DEBUG MARKER: doing ls -la /mnt/lustre/d124b.sanity/enable_lru_resize 3 times [12940.003542] Lustre: DEBUG MARKER: ls -la time: 92 seconds [12942.667794] Lustre: DEBUG MARKER: lru_size = 4006 [12945.016381] Lustre: DEBUG MARKER: ls -la is 43% faster with lru resize enabled [13020.333842] Lustre: DEBUG MARKER: == sanity test 124c: LRUR cancel very aged locks ========= 08:11:58 (1779106318) [13056.100574] Lustre: DEBUG MARKER: == sanity test 124d: cancel very aged locks if lru-resize disabled ========================================================== 08:12:34 (1779106354) [13088.927291] Lustre: DEBUG MARKER: == sanity test 124e: LFRU keep priv locks from eviction == 08:13:07 (1779106387) [13132.636712] Lustre: DEBUG MARKER: == sanity test 124f: LFRU priv threshold inc/dec adjustment ========================================================== 08:13:50 (1779106430) [13222.978633] Lustre: DEBUG MARKER: == sanity test 124g: LFRU performance test =============== 08:15:20 (1779106520) [13907.985840] Lustre: DEBUG MARKER: == sanity test 125: don't return EPROTO when a dir has a non-default striping and ACLs ========================================================== 08:26:45 (1779107205) [13919.250383] Lustre: DEBUG MARKER: == sanity test 126: check that the fsgid provided by the client is taken into account ========================================================== 08:26:56 (1779107216) [13928.590511] Lustre: DEBUG MARKER: == sanity test 127a: verify the client stats are sane ==== 08:27:06 (1779107226) [13937.739912] Lustre: DEBUG MARKER: == sanity test 127b: verify the llite client stats are sane ========================================================== 08:27:15 (1779107235) [13947.329584] Lustre: DEBUG MARKER: == sanity test 127c: test llite extent stats with regular [13984.839696] Lustre: DEBUG MARKER: == sanity test 127d: OSC RPC latency histograms for read and write latency ========================================================== 08:28:02 (1779107282) [13998.607775] Lustre: DEBUG MARKER: == sanity test 127e: client IO latency histograms by size ========================================================== 08:28:16 (1779107296) [14017.607434] Lustre: DEBUG MARKER: == sanity test 127f: OST IO latency histograms by size === 08:28:35 (1779107315) [14043.177902] Lustre: DEBUG MARKER: == sanity test 128: interactive lfs for 2 consecutive find's ========================================================== 08:29:01 (1779107341) [14053.264488] Lustre: DEBUG MARKER: == sanity test 129: test directory size limit ================================================================================== 08:29:10 (1779107350) [14145.321378] Lustre: DEBUG MARKER: == sanity test 130a: FIEMAP (1-stripe file) ============== 08:30:43 (1779107443) [14154.551150] Lustre: DEBUG MARKER: == sanity test 130b: FIEMAP (2-stripe file) ============== 08:30:52 (1779107452) [14163.994952] Lustre: DEBUG MARKER: == sanity test 130c: FIEMAP (2-stripe file with hole) ==== 08:31:01 (1779107461) [14173.826335] Lustre: DEBUG MARKER: == sanity test 130d: FIEMAP (N-stripe file) ============== 08:31:11 (1779107471) [14175.291823] Lustre: DEBUG MARKER: SKIP: sanity test_130d needs >= 3 OSTs [14177.790314] Lustre: DEBUG MARKER: == sanity test 130e: FIEMAP (test continuation FIEMAP calls) ========================================================== 08:31:15 (1779107475) [14251.645578] Lustre: DEBUG MARKER: == sanity test 130f: FIEMAP (unstriped file) ============= 08:32:29 (1779107549) [14260.556497] Lustre: DEBUG MARKER: == sanity test 130g: FIEMAP (overstripe file) ============ 08:32:38 (1779107558) [14308.116558] Lustre: DEBUG MARKER: == sanity test 130h: FIEMAP deadlock ===================== 08:33:26 (1779107606) [14310.140464] LustreError: 230414:0:(osc_object.c:271:osc_object_fiemap()) cfs_fail_timeout id 418 sleeping for 5000ms [14315.210895] LustreError: 230414:0:(osc_object.c:271:osc_object_fiemap()) cfs_fail_timeout id 418 awake [14324.002549] Lustre: DEBUG MARKER: == sanity test 130i: FIEMAP (DoM file) =================== 08:33:41 (1779107621) [14376.522782] Lustre: DEBUG MARKER: == sanity test 131a: test iov's crossing stripe boundary for writev/readv ========================================================== 08:34:33 (1779107673) [14385.565851] Lustre: DEBUG MARKER: == sanity test 131b: test append writev ================== 08:34:42 (1779107682) [14396.787113] Lustre: DEBUG MARKER: == sanity test 131c: test read/write on file w/o objects ========================================================== 08:34:54 (1779107694) [14406.917547] Lustre: DEBUG MARKER: == sanity test 131d: test short read ===================== 08:35:04 (1779107704) [14416.346623] Lustre: DEBUG MARKER: == sanity test 131e: test read hitting hole ============== 08:35:13 (1779107713) [14425.759648] Lustre: DEBUG MARKER: == sanity test 133a: Verifying MDT stats ================================================================================================== 08:35:23 (1779107723) [14452.337112] Lustre: DEBUG MARKER: == sanity test 133b: Verifying extra MDT stats ============================================================================================ 08:35:50 (1779107750) [14469.439527] Lustre: DEBUG MARKER: == sanity test 133c: Verifying OST stats ================================================================================================== 08:36:07 (1779107767) [14519.424988] Lustre: DEBUG MARKER: == sanity test 133d: Verifying rename_stats ================================================================================================== 08:36:56 (1779107816) [14570.357571] Lustre: DEBUG MARKER: == sanity test 133e: Verifying OST read_bytes write_bytes nid stats =========================================================================== 08:37:48 (1779107868) [14586.613640] Lustre: DEBUG MARKER: == sanity test 133f: Check reads/writes of client lustre proc files with bad area io ========================================================== 08:38:04 (1779107884) [14589.624897] LNet: 241772:0:(debug.c:376:cfs_str2mask()) unknown mask ''. [14589.624897] mask usage: [+|-] ... [14590.338344] LNet: 241815:0:(debug.c:376:cfs_str2mask()) unknown mask ''. [14590.338344] mask usage: [+|-] ... [14590.360127] LNet: 241815:0:(debug.c:376:cfs_str2mask()) Skipped 5 previous similar messages [14590.419659] Lustre: DEBUG MARKER:  [14590.421669] Lustre: DEBUG MARKER:  [14615.318586] LustreError: 242448:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9e3576ad9000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [14615.336444] LustreError: 242448:0:(lov_obd.c:792:lov_cleanup()) Skipped 1 previous similar message [14615.453378] Lustre: Unmounted lustre-client [14680.620830] Key type lgssc unregistered [14680.986374] LNet: 243100:0:(lib-ptl.c:967:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [14681.015539] LNetError: 243100:0:(acceptor.c:246:lnet_acceptor_remove_socket()) Interface ens2 not found [14681.030386] LNet: Removed LNI 192.168.202.31@tcp [14681.842185] Key type .llcrypt unregistered [14681.844691] Key type ._llcrypt unregistered [14698.309771] Key type ._llcrypt registered [14698.314619] Key type .llcrypt registered [14699.443236] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [14699.451252] alg: No test for adler32 (adler32-zlib) [14701.076974] Lustre: Lustre: Build Version: 2.17.53_24_g2ff46d7 [14702.010821] LNet: Added LNI 192.168.202.31@tcp [8/256/0/180] [14703.975220] Key type lgssc registered [14706.916815] Lustre: Echo OBD driver; http://www.lustre.org/ [14843.028975] Lustre: Mounted lustre-client [14849.840899] Lustre: DEBUG MARKER: Using TIMEOUT=20 [14867.837059] Lustre: DEBUG MARKER: == sanity test 133g: Check reads/writes of server lustre proc files with bad area io ========================================================== 08:42:45 (1779108165) [14868.450251] Lustre: lustre-OST0000-osc-ffff9e3545b1f000: disconnect after 23s idle [15047.612282] LustreError: 246827:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9e3545b1f000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [15047.757050] Lustre: Unmounted lustre-client [15120.222848] Key type lgssc unregistered [15120.584377] LNet: 247516:0:(lib-ptl.c:967:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [15120.589547] LNetError: 247516:0:(acceptor.c:246:lnet_acceptor_remove_socket()) Interface ens2 not found [15121.637851] LNet: Removed LNI 192.168.202.31@tcp [15122.634341] Key type .llcrypt unregistered [15122.637202] Key type ._llcrypt unregistered [15138.537107] Key type ._llcrypt registered [15138.542817] Key type .llcrypt registered [15139.413158] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [15139.436826] alg: No test for adler32 (adler32-zlib) [15140.738539] Lustre: Lustre: Build Version: 2.17.53_24_g2ff46d7 [15141.077549] LNet: Added LNI 192.168.202.31@tcp [8/256/0/180] [15142.799195] Key type lgssc registered [15145.032957] Lustre: Echo OBD driver; http://www.lustre.org/ [15290.594170] Lustre: Mounted lustre-client [15297.154102] Lustre: DEBUG MARKER: Using TIMEOUT=20 [15313.380224] Lustre: DEBUG MARKER: == sanity test 133h: Proc files should end with newlines ========================================================== 08:50:10 (1779108610) [15316.453467] Lustre: lustre-OST0000-osc-ffff9e35505d0000: disconnect after 23s idle [15362.534813] Lustre: lustre-OST0000-osc-ffff9e35505d0000: disconnect after 22s idle [15362.547727] Lustre: Skipped 1 previous similar message [15413.731682] Lustre: lustre-OST0000-osc-ffff9e35505d0000: disconnect after 23s idle [15413.753207] Lustre: Skipped 1 previous similar message [16768.668854] Lustre: DEBUG MARKER: == sanity test 134a: Server reclaims locks when reaching lock_reclaim_threshold ========================================================== 09:14:26 (1779110066) [16831.669853] Lustre: DEBUG MARKER: == sanity test 134b: Server rejects lock request when reaching lock_limit_mb ========================================================== 09:15:29 (1779110129) [16831.976397] Lustre: lustre-OST0000-osc-ffff9e35505d0000: disconnect after 20s idle [16831.982504] Lustre: Skipped 1 previous similar message [16879.865696] Lustre: DEBUG MARKER: SKIP: sanity test_135 skipping SLOW test 135 [16882.051973] Lustre: DEBUG MARKER: SKIP: sanity test_136 skipping SLOW test 136 [16884.054099] Lustre: DEBUG MARKER: == sanity test 140: Check reasonable stack depth (shouldn't LBUG) ============================================================== 09:16:22 (1779110182) [16941.896576] Lustre: DEBUG MARKER: == sanity test 150a: truncate/append tests =============== 09:17:19 (1779110239) [16957.660086] LustreError: 271886:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9e35505d0000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [16958.016688] Lustre: Unmounted lustre-client [16958.928820] Lustre: Mounted lustre-client [16987.732294] Lustre: DEBUG MARKER: == sanity test 150b: Verify fallocate (prealloc) functionality ========================================================== 09:18:06 (1779110286) [17020.577750] Lustre: DEBUG MARKER: == sanity test 150bb: Verify fallocate modes both zero space ========================================================== 09:18:38 (1779110318) [17061.284535] Lustre: DEBUG MARKER: == sanity test 150c: Verify fallocate Size and Blocks ==== 09:19:18 (1779110358) [17088.082391] Lustre: DEBUG MARKER: == sanity test 150d: Verify fallocate Size and Blocks - Non zero start ========================================================== 09:19:45 (1779110385) [17116.714958] Lustre: DEBUG MARKER: == sanity test 150e: Verify 60% of available OST space consumed by fallocate ========================================================== 09:20:13 (1779110413) [17148.682438] Lustre: DEBUG MARKER: == sanity test 150f: Verify fallocate punch functionality ========================================================== 09:20:46 (1779110446) [17175.237123] Lustre: DEBUG MARKER: == sanity test 150g: Verify fallocate punch on large range ========================================================== 09:21:13 (1779110473) [17210.705086] Lustre: DEBUG MARKER: == sanity test 150h: Verify extend fallocate updates the file size ========================================================== 09:21:48 (1779110508) [17221.153450] Lustre: DEBUG MARKER: == sanity test 150ia: Verify fallocate zero-range ZERO functionality ========================================================== 09:21:59 (1779110519) [17249.453456] Lustre: DEBUG MARKER: == sanity test 150ib: Verify fallocate zero-range PREALLOC functionality ========================================================== 09:22:25 (1779110545) [17276.326217] Lustre: DEBUG MARKER: == sanity test 150ic: Verify fallocate LARGE zero PREALLOC functionality ========================================================== 09:22:53 (1779110573) [17278.600542] Lustre: DEBUG MARKER: SKIP: sanity test_150ic only check on DoM component [17281.795848] Lustre: DEBUG MARKER: == sanity test 151: test cache on oss and controls ========================================================================================= 09:22:58 (1779110578) [17316.394439] Lustre: DEBUG MARKER: == sanity test 152: test read/write with enomem ====================================================================================== 09:23:34 (1779110614) [17324.659378] Lustre: DEBUG MARKER: == sanity test 153: test if fdatasync does not crash ================================================================================= 09:23:42 (1779110622) [17333.513811] Lustre: DEBUG MARKER: == sanity test 154A: lfs path2fid and fid2path basic checks ========================================================== 09:23:50 (1779110630) [17341.206937] Lustre: DEBUG MARKER: == sanity test 154B: verify the ll_decode_linkea tool ==== 09:23:59 (1779110639) [17349.890056] Lustre: DEBUG MARKER: == sanity test 154C: lfs fid2path on OST FID ============= 09:24:07 (1779110647) [17373.952868] Lustre: DEBUG MARKER: == sanity test 154a: Open-by-FID ========================= 09:24:32 (1779110672) [17376.145161] LustreError: 287202:0:(lmv_fld.c:51:lmv_fld_lookup()) lustre-clilmv-ffff9e3545d6c800: Error while looking for mds number. Seq 0xf00000400: rc = -2 [17378.310031] Lustre: dir [0x240000402:0x3e:0x0] stripe 0 readdir failed: -2, directory is partially accessed! [17386.875343] Lustre: DEBUG MARKER: == sanity test 154b: Open-by-FID for remote directory ==== 09:24:44 (1779110684) [17388.576854] LustreError: 287847:0:(lmv_fld.c:51:lmv_fld_lookup()) lustre-clilmv-ffff9e3545d6c800: Error while looking for mds number. Seq 0xf00000400: rc = -2 [17388.585281] LustreError: 287847:0:(lmv_fld.c:51:lmv_fld_lookup()) Skipped 1 previous similar message [17397.857888] Lustre: DEBUG MARKER: == sanity test 154c: lfs path2fid and fid2path multiple arguments ========================================================== 09:24:55 (1779110695) [17405.909338] Lustre: DEBUG MARKER: == sanity test 154d: Verify open file fid ================ 09:25:03 (1779110703) [17415.880520] Lustre: DEBUG MARKER: == sanity test 154e: .lustre is not returned by readdir == 09:25:13 (1779110713) [17423.289521] Lustre: DEBUG MARKER: == sanity test 154ea: .lustre is not returned by readdir (2) ========================================================== 09:25:21 (1779110721) [17497.351329] Lustre: DEBUG MARKER: == sanity test 154f: get parent fids by reading link ea == 09:26:35 (1779110795) [17509.233949] Lustre: DEBUG MARKER: == sanity test 154g: various llapi FID tests ============= 09:26:47 (1779110807) [19113.511068] Lustre: DEBUG MARKER: == sanity test 154h: Verify interactive path2fid ========= 09:53:31 (1779112411) [19124.936286] Lustre: DEBUG MARKER: == sanity test 154i: fid2path for path longer than PATH_MAX ========================================================== 09:53:42 (1779112422) [19172.965525] Lustre: DEBUG MARKER: == sanity test 154j: fid2path for long path crossing MDT boundary ========================================================== 09:54:31 (1779112471) [19200.354432] Lustre: DEBUG MARKER: == sanity test 155a: Verify small file correctness: read cache:on write_cache:on ========================================================== 09:54:58 (1779112498) [19218.856471] Lustre: DEBUG MARKER: == sanity test 155b: Verify small file correctness: read cache:on write_cache:off ========================================================== 09:55:16 (1779112516) [19236.851776] Lustre: DEBUG MARKER: == sanity test 155c: Verify small file correctness: read cache:off write_cache:on ========================================================== 09:55:34 (1779112534) [19254.628288] Lustre: DEBUG MARKER: == sanity test 155d: Verify small file correctness: read cache:off write_cache:off ========================================================== 09:55:51 (1779112551) [19275.504885] Lustre: DEBUG MARKER: == sanity test 155e: Verify big file correctness: read cache:on write_cache:on ========================================================== 09:56:12 (1779112572) [19329.457817] Lustre: DEBUG MARKER: == sanity test 155f: Verify big file correctness: read cache:on write_cache:off ========================================================== 09:57:06 (1779112626) [19389.431044] Lustre: DEBUG MARKER: == sanity test 155g: Verify big file correctness: read cache:off write_cache:on ========================================================== 09:58:06 (1779112686) [19451.958778] Lustre: DEBUG MARKER: == sanity test 155h: Verify big file correctness: read cache:off write_cache:off ========================================================== 09:59:09 (1779112749) [19504.129316] Lustre: DEBUG MARKER: == sanity test 156: Verification of tunables ============= 10:00:01 (1779112801) [19516.222438] Lustre: DEBUG MARKER: Turn on read and write cache [19521.833132] Lustre: DEBUG MARKER: Write data and read it back. [19523.358097] Lustre: DEBUG MARKER: Read should be satisfied from the cache. [19528.874937] Lustre: DEBUG MARKER: cache hits: before: 28718, after: 28721 [19531.754356] Lustre: DEBUG MARKER: Read again; it should be satisfied from the cache. [19536.271667] Lustre: DEBUG MARKER: cache hits:: before: 28721, after: 28724 [19539.151907] Lustre: DEBUG MARKER: Turn off the read cache and turn on the write cache [19545.458265] Lustre: DEBUG MARKER: Read again; it should be satisfied from the cache. [19551.172799] Lustre: DEBUG MARKER: cache hits:: before: 28724, after: 28727 [19553.441929] Lustre: DEBUG MARKER: Write data and read it back. [19555.659533] Lustre: DEBUG MARKER: Read should be satisfied from the cache. [19560.952459] Lustre: DEBUG MARKER: cache hits:: before: 28727, after: 28730 [19562.856561] Lustre: DEBUG MARKER: Turn off read and write cache [19568.035873] Lustre: DEBUG MARKER: Write data and read it back [19570.780820] Lustre: DEBUG MARKER: It should not be satisfied from the cache. [19577.016636] Lustre: DEBUG MARKER: cache hits:: before: 28730, after: 28730 [19579.196983] Lustre: DEBUG MARKER: Turn on the read cache and turn off the write cache [19584.664296] Lustre: DEBUG MARKER: Write data and read it back [19587.052660] Lustre: DEBUG MARKER: It should not be satisfied from the cache. [19592.509455] Lustre: DEBUG MARKER: cache hits:: before: 28730, after: 28730 [19594.482436] Lustre: DEBUG MARKER: Read again; it should be satisfied from the cache. [19599.608046] Lustre: DEBUG MARKER: cache hits:: before: 28730, after: 28733 [19610.676456] Lustre: DEBUG MARKER: == sanity test 157: llapi pool pinning API tests ========= 10:01:48 (1779112908) [19621.067282] Lustre: DEBUG MARKER: == sanity test 157a: lustre.pin inheritance on create ==== 10:01:58 (1779112918) [19631.427282] Lustre: DEBUG MARKER: == sanity test 160a: changelog sanity ==================== 10:02:09 (1779112929) [19662.329462] Lustre: lustre-MDT0000-mdc-ffff9e3545d6c800: Connection to lustre-MDT0000 (at 192.168.202.131@tcp) was lost; in progress operations using this service will wait for recovery to complete [19677.682769] LustreError: MGC192.168.202.131@tcp: Connection to MGS (at 192.168.202.131@tcp) was lost; in progress operations using this service will fail [19677.723794] Lustre: Evicted from MGS (at 192.168.202.131@tcp) after server handle changed from 0x4accb980e17b1fa4 to 0x4accb980e1854235 [19677.729909] Lustre: MGC192.168.202.131@tcp: Connection restored to 192.168.202.131@tcp (at 192.168.202.131@tcp) [19677.772933] LustreError: 247871:0:(client.c:3438:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9e356d769180 x1865530413925376/t12884907153(12884907153) o101->lustre-MDT0000-mdc-ffff9e3545d6c800@192.168.202.131@tcp:12/10 lens 912/608 e 0 to 0 dl 1779112993 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'bash.0' uid:0 gid:0 projid:0 [19678.289176] LustreError: 247871:0:(client.c:3438:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9e3546c4c380 x1865530421606272/t12884924556(12884924556) o101->lustre-MDT0000-mdc-ffff9e3545d6c800@192.168.202.131@tcp:12/10 lens 968/608 e 0 to 0 dl 1779112993 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'bash.0' uid:0 gid:0 projid:0 [19678.319806] LustreError: 247871:0:(client.c:3438:ptlrpc_replay_interpret()) Skipped 39 previous similar messages [19680.966530] Lustre: lustre-MDT0000-mdc-ffff9e3545d6c800: Connection restored to 192.168.202.131@tcp (at 192.168.202.131@tcp) [19705.270528] Lustre: DEBUG MARKER: == sanity test 160b: Verify that very long rename doesn't crash in changelog ========================================================== 10:03:22 (1779113002) [19734.839987] Lustre: DEBUG MARKER: == sanity test 160c: verify that changelog log catch the truncate event ========================================================== 10:03:52 (1779113032) [19763.078473] Lustre: DEBUG MARKER: == sanity test 160d: verify that changelog log catch the migrate event ========================================================== 10:04:20 (1779113060) [19791.127491] Lustre: DEBUG MARKER: == sanity test 160e: changelog negative testing (should return errors) ========================================================== 10:04:47 (1779113087) [19820.397817] Lustre: DEBUG MARKER: == sanity test 160f: changelog garbage collect (timestamped users) ========================================================== 10:05:17 (1779113117) [19837.573691] Lustre: DEBUG MARKER: 1779113134: creating first dirs [19902.815339] Lustre: DEBUG MARKER: == sanity test 160g: changelog garbage collect on idle records ========================================================== 10:06:40 (1779113200) [19972.093720] Lustre: DEBUG MARKER: == sanity test 160h: changelog gc thread stop upon umount, orphan records delete ========================================================== 10:07:50 (1779113270) [20025.837356] Lustre: lustre-MDT0000-mdc-ffff9e3545d6c800: Connection to lustre-MDT0000 (at 192.168.202.131@tcp) was lost; in progress operations using this service will wait for recovery to complete [20046.330489] LustreError: MGC192.168.202.131@tcp: Connection to MGS (at 192.168.202.131@tcp) was lost; in progress operations using this service will fail [20046.379905] Lustre: Evicted from MGS (at 192.168.202.131@tcp) after server handle changed from 0x4accb980e1854235 to 0x4accb980e185599d [20046.394734] Lustre: MGC192.168.202.131@tcp: Connection restored to 192.168.202.131@tcp (at 192.168.202.131@tcp) [20055.693832] LustreError: 247871:0:(client.c:3438:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9e3545754a80 x1865530421591424/t12884924517(12884924517) o101->lustre-MDT0000-mdc-ffff9e3545d6c800@192.168.202.131@tcp:12/10 lens 968/608 e 0 to 0 dl 1779113371 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'bash.0' uid:0 gid:0 projid:0 [20055.723160] LustreError: 247871:0:(client.c:3438:ptlrpc_replay_interpret()) Skipped 32 previous similar messages [20064.632149] Lustre: lustre-MDT0000-mdc-ffff9e3545d6c800: Connection restored to 192.168.202.131@tcp (at 192.168.202.131@tcp) [20102.105343] Lustre: DEBUG MARKER: == sanity test 160i: changelog user register/unregister race ========================================================== 10:09:59 (1779113399) [20149.204552] Lustre: DEBUG MARKER: == sanity test 160j: client can be umounted while its chanangelog is being used ========================================================== 10:10:46 (1779113446) [20149.932548] Lustre: Mounted lustre-client [20158.591090] LustreError: 323707:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9e3545d6c800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [20158.602173] LustreError: 323707:0:(lov_obd.c:792:lov_cleanup()) Skipped 1 previous similar message [20158.794712] Lustre: Unmounted lustre-client [20167.337512] Lustre: Mounted lustre-client [20180.497411] LustreError: 324287:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9e356b3bc800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [20180.518181] LustreError: 324287:0:(lov_obd.c:792:lov_cleanup()) Skipped 1 previous similar message [20180.664788] Lustre: Unmounted lustre-client [20182.890586] Lustre: DEBUG MARKER: == sanity test 160k: Verify that changelog records are not lost ========================================================== 10:11:20 (1779113480) [20219.273408] Lustre: DEBUG MARKER: == sanity test 160l: Verify that MTIME changelog records contain the parent FID ========================================================== 10:11:56 (1779113516) [20249.336339] Lustre: DEBUG MARKER: == sanity test 160m: Changelog clear race ================ 10:12:26 (1779113546) [20294.903562] Lustre: DEBUG MARKER: == sanity test 160n: Changelog destroy race ============== 10:13:12 (1779113592) [22467.707779] Lustre: DEBUG MARKER: == sanity test 160o: changelog user name and mask ======== 10:49:25 (1779115765) [22521.281848] Lustre: DEBUG MARKER: == sanity test 160p: Changelog orphan cleanup with no users ========================================================== 10:50:18 (1779115818) [22538.246379] Lustre: lustre-MDT0000-mdc-ffff9e3545dec800: Connection to lustre-MDT0000 (at 192.168.202.131@tcp) was lost; in progress operations using this service will wait for recovery to complete [22538.264174] Lustre: Skipped 1 previous similar message [22548.466584] LustreError: MGC192.168.202.131@tcp: Connection to MGS (at 192.168.202.131@tcp) was lost; in progress operations using this service will fail [22548.514840] Lustre: Evicted from MGS (at 192.168.202.131@tcp) after server handle changed from 0x4accb980e185599d to 0x4accb980e1c8d5b9 [22548.534879] Lustre: MGC192.168.202.131@tcp: Connection restored to 192.168.202.131@tcp (at 192.168.202.131@tcp) [22548.550181] Lustre: Skipped 1 previous similar message [22550.938219] Lustre: lustre-MDT0000-mdc-ffff9e3545dec800: Connection restored to 192.168.202.131@tcp (at 192.168.202.131@tcp) [22567.043626] Lustre: DEBUG MARKER: == sanity test 160q: changelog effective mask is DEFMASK if not set ========================================================== 10:51:05 (1779115865) [22581.037417] Lustre: DEBUG MARKER: == sanity test 160s: changelog garbage collect on idle records * time ========================================================== 10:51:19 (1779115879) [22624.682953] Lustre: DEBUG MARKER: == sanity test 160t: changelog garbage collect on lack of space ========================================================== 10:52:02 (1779115922) [22742.286358] Lustre: DEBUG MARKER: == sanity test 160u: changelog rename record type name and sname strings are correct ========================================================== 10:53:59 (1779116039) [22766.861725] Lustre: DEBUG MARKER: == sanity test 160v: setattr preserves mtime update despite inter-client clock skew ========================================================== 10:54:24 (1779116064) [22768.681581] Lustre: DEBUG MARKER: SKIP: sanity test_160v need >= 2 clients [22770.190971] Lustre: DEBUG MARKER: == sanity test 160w: lfs changelog --user --mask ========= 10:54:28 (1779116068) [22811.386937] Lustre: DEBUG MARKER: == sanity test 161a: link ea sanity ====================== 10:55:09 (1779116109) [22848.151230] Lustre: DEBUG MARKER: == sanity test 161b: link ea sanity under remote directory ========================================================== 10:55:46 (1779116146) [22895.504578] Lustre: DEBUG MARKER: == sanity test 161c: check CL_RENME[UNLINK] changelog record flags ========================================================== 10:56:33 (1779116193) [22930.588420] Lustre: DEBUG MARKER: == sanity test 161d: create with concurrent .lustre/fid access ========================================================== 10:57:08 (1779116228) [22938.421166] LustreError: 370314:0:(namei.c:1578:ll_create_node()) cfs_fail_timeout id 140c sleeping for 5000ms [22940.959277] LustreError: 370314:0:(namei.c:1578:ll_create_node()) cfs_fail_timeout interrupted [22955.410041] Lustre: DEBUG MARKER: == sanity test 162a: path lookup sanity ================== 10:57:33 (1779116253) [22965.668952] Lustre: DEBUG MARKER: == sanity test 162b: striped directory path lookup sanity ========================================================== 10:57:43 (1779116263) [22976.429507] Lustre: DEBUG MARKER: == sanity test 162c: fid2path works with paths 100 or more directories deep ========================================================== 10:57:54 (1779116274) [23107.567066] Lustre: DEBUG MARKER: == sanity test 165a: ofd access log discovery ============ 11:00:05 (1779116405) [23121.898204] Lustre: lustre-OST0000-osc-ffff9e3545dec800: Connection to lustre-OST0000 (at 192.168.202.131@tcp) was lost; in progress operations using this service will wait for recovery to complete [23150.962969] Lustre: DEBUG MARKER: == sanity test 165b: ofd access log entries are produced and consumed ========================================================== 11:00:48 (1779116448) [23188.481476] Lustre: lustre-OST0000-osc-ffff9e3545dec800: Connection to lustre-OST0000 (at 192.168.202.131@tcp) was lost; in progress operations using this service will wait for recovery to complete [23197.865540] Lustre: lustre-OST0000-osc-ffff9e3545dec800: Connection restored to 192.168.202.131@tcp (at 192.168.202.131@tcp) [23208.557953] Lustre: DEBUG MARKER: == sanity test 165c: full ofd access logs do not block IOs ========================================================== 11:01:46 (1779116506) [23244.783069] Lustre: lustre-OST0000-osc-ffff9e3545dec800: Connection to lustre-OST0000 (at 192.168.202.131@tcp) was lost; in progress operations using this service will wait for recovery to complete [23253.388963] Lustre: lustre-OST0000-osc-ffff9e3545dec800: Connection restored to 192.168.202.131@tcp (at 192.168.202.131@tcp) [23263.231397] Lustre: DEBUG MARKER: == sanity test 165d: ofd_access_log mask works =========== 11:02:41 (1779116561) [23316.481503] Lustre: lustre-OST0000-osc-ffff9e3545dec800: Connection to lustre-OST0000 (at 192.168.202.131@tcp) was lost; in progress operations using this service will wait for recovery to complete [23329.490764] Lustre: lustre-OST0000-osc-ffff9e3545dec800: Connection restored to 192.168.202.131@tcp (at 192.168.202.131@tcp) [23343.743541] Lustre: DEBUG MARKER: == sanity test 165e: ofd_access_log MDT index filter works ========================================================== 11:04:00 (1779116640) [23372.799576] Lustre: lustre-OST0000-osc-ffff9e3545dec800: Connection to lustre-OST0000 (at 192.168.202.131@tcp) was lost; in progress operations using this service will wait for recovery to complete [23380.498107] Lustre: lustre-OST0000-osc-ffff9e3545dec800: Connection restored to 192.168.202.131@tcp (at 192.168.202.131@tcp) [23389.936325] Lustre: DEBUG MARKER: == sanity test 165f: ofd_access_log_reader --exit-on-close works ========================================================== 11:04:47 (1779116687) [23403.495688] Lustre: lustre-OST0000-osc-ffff9e3545dec800: Connection to lustre-OST0000 (at 192.168.202.131@tcp) was lost; in progress operations using this service will wait for recovery to complete [23420.698864] Lustre: lustre-OST0000-osc-ffff9e3545dec800: Connection restored to 192.168.202.131@tcp (at 192.168.202.131@tcp) [23429.983357] Lustre: DEBUG MARKER: == sanity test 165g: ofd_access_log_reader --keepalive works ========================================================== 11:05:27 (1779116727) [23475.201384] Lustre: lustre-OST0000-osc-ffff9e3545dec800: Connection to lustre-OST0000 (at 192.168.202.131@tcp) was lost; in progress operations using this service will wait for recovery to complete [23499.111769] Lustre: lustre-OST0000-osc-ffff9e3545dec800: Connection restored to 192.168.202.131@tcp (at 192.168.202.131@tcp) [23509.215663] Lustre: DEBUG MARKER: == sanity test 169: parallel read and truncate should not deadlock ========================================================== 11:06:47 (1779116807) [23511.474571] Lustre: DEBUG MARKER: creating a 10 Mb file [23597.292980] Lustre: DEBUG MARKER: starting reads [23601.003555] Lustre: DEBUG MARKER: truncating the file [23602.875729] Lustre: DEBUG MARKER: killing dd [23604.689663] Lustre: DEBUG MARKER: removing the temporary file [23612.992118] Lustre: DEBUG MARKER: == sanity test 170a: test lctl df to handle corrupted log ========================================================== 11:08:30 (1779116910) [23613.254756] Lustre: debug daemon will attempt to start writing to /tmp/f170a.sanity_log_good (512000kB max) [23613.407728] Lustre: shutting down debug daemon thread... [23613.483040] Lustre: debug daemon will attempt to start writing to /tmp/f170a.sanity_log_good (512000kB max) [23613.559889] Lustre: shutting down debug daemon thread... [23622.157637] Lustre: DEBUG MARKER: == sanity test 170b: check filename encoding ============= 11:08:40 (1779116920) [23656.152580] Lustre: DEBUG MARKER: == sanity test 171: test libcfs_debug_dumplog_thread stuck in do_exit() ================================================================ 11:09:13 (1779116953) [23656.365687] LustreError: 385450:0:(file.c:482:ll_file_release()) cfs_fail_timeout id 50e sleeping for 3000ms [23659.392552] LustreError: 385450:0:(file.c:482:ll_file_release()) cfs_fail_timeout id 50e awake [23659.412916] LustreError: dumping log to /tmp/lustre-log.1779116959.385450 [23667.875607] Lustre: DEBUG MARKER: == sanity test 172: manual device removal with lctl cleanup/detach ================================================================ 11:09:25 (1779116965) [23670.950032] LustreError: 386035:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9e3545dec800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [23670.967604] LustreError: 386035:0:(lov_obd.c:792:lov_cleanup()) Skipped 1 previous similar message [23671.115029] Lustre: *** cfs_fail_loc=60e, val=0*** [23671.125262] Lustre: Unmounted lustre-client [23677.178777] Lustre: Mounted lustre-client [23678.882142] Lustre: DEBUG MARKER: == sanity test 180a: test obdecho on osc ================= 11:09:37 (1779116977) [23680.415859] Lustre: DEBUG MARKER: SKIP: sanity test_180a obdecho on osc is no longer supported [23682.268821] Lustre: DEBUG MARKER: == sanity test 180b: test obdecho directly on obdfilter == 11:09:40 (1779116980) [23708.839862] Lustre: DEBUG MARKER: == sanity test 180c: test huge bulk I/O size on obdfilter, don't LASSERT ========================================================== 11:10:06 (1779117006) [23740.761858] Lustre: DEBUG MARKER: == sanity test 181: Test open-unlinked dir ================================================================================== 11:10:38 (1779117038) [23843.532218] Lustre: DEBUG MARKER: == sanity test 182a: Test parallel modify metadata operations from mdc ========================================================== 11:12:21 (1779117141) [23959.677255] Lustre: DEBUG MARKER: == sanity test 182b: Test parallel modify metadata operations from osp ========================================================== 11:14:17 (1779117257) [24852.119755] Lustre: DEBUG MARKER: == sanity test 183: No crash or request leak in case of strange dispositions ================================================================== 11:29:09 (1779118149) [24863.726056] Lustre: DEBUG MARKER: == sanity test 184a: Basic layout swap =================== 11:29:21 (1779118161) [24879.746688] Lustre: DEBUG MARKER: == sanity test 184b: Forbidden layout swap (will generate errors) ========================================================== 11:29:37 (1779118177) [24888.742943] Lustre: DEBUG MARKER: == sanity test 184c: Concurrent write and layout swap ==== 11:29:47 (1779118187) [24949.735754] Lustre: DEBUG MARKER: == sanity test 184d: allow stripeless layouts swap ======= 11:30:47 (1779118247) [24960.808612] Lustre: DEBUG MARKER: == sanity test 184e: Recreate layout after stripeless layout swaps ========================================================== 11:30:58 (1779118258) [24971.802188] Lustre: DEBUG MARKER: == sanity test 184f: IOC_MDC_GETFILEINFO for files with long names but no striping ========================================================== 11:31:09 (1779118269) [24979.779764] Lustre: DEBUG MARKER: == sanity test 185: Volatile file support ================ 11:31:17 (1779118277) [24989.478031] Lustre: DEBUG MARKER: == sanity test 185a: Volatile file creation in .lustre/fid/ ========================================================== 11:31:27 (1779118287) [25002.989991] Lustre: DEBUG MARKER: == sanity test 187a: Test data version change ============ 11:31:40 (1779118300) [25015.630988] Lustre: DEBUG MARKER: == sanity test 187b: Test data version change on volatile file ========================================================== 11:31:53 (1779118313) [25025.199610] Lustre: DEBUG MARKER: == sanity test 190a: check lfs project -p works with project name ========================================================== 11:32:03 (1779118323) [25034.532912] Lustre: DEBUG MARKER: == sanity test 190b: check lfs find --project works with project name ========================================================== 11:32:12 (1779118332) [25075.459343] Lustre: DEBUG MARKER: == sanity test 190c: check lfs project -p works with u:USERNAME ========================================================== 11:32:53 (1779118373) [25095.435640] Lustre: DEBUG MARKER: == sanity test complete, duration 24717 sec ============== 11:33:13 (1779118393) [25097.500039] Lustre: DEBUG MARKER: === sanity: start cleanup 11:33:15 (1779118395) === [25152.972521] Lustre: DEBUG MARKER: === sanity: finish cleanup 11:34:11 (1779118451) === [25155.302156] LustreError: 416729:0:(lov_obd.c:792:lov_cleanup()) lustre-clilov-ffff9e356d4ac800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [25155.320168] LustreError: 416729:0:(lov_obd.c:792:lov_cleanup()) Skipped 1 previous similar message [25155.467911] Lustre: Unmounted lustre-client [25210.333449] Key type lgssc unregistered [25210.872133] LNet: 417414:0:(lib-ptl.c:967:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [25210.883294] LNetError: 417414:0:(acceptor.c:246:lnet_acceptor_remove_socket()) Interface ens2 not found [25210.924475] LNet: Removed LNI 192.168.202.31@tcp [25212.100163] Key type .llcrypt unregistered [25212.103248] Key type ._llcrypt unregistered