[ 0.000000] Linux version 4.18.0rh8.10-debug (green@maintenance) (gcc version 8.5.0 20210514 (Red Hat 8.5.0-26) (GCC)) #2 SMP Mon Jul 14 01:24:22 EDT 2025 [ 0.000000] Command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers' [ 0.000000] x86/fpu: xstate_offset[2]: 576, xstate_sizes[2]: 256 [ 0.000000] x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'standard' format. [ 0.000000] signal: max sigframe size: 1776 [ 0.000000] BIOS-provided physical RAM map: [ 0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable [ 0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000000100000-0x00000000bffd9fff] usable [ 0.000000] BIOS-e820: [mem 0x00000000bffda000-0x00000000bfffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000100000000-0x0000000146dfffff] usable [ 0.000000] NX (Execute Disable) protection: active [ 0.000000] SMBIOS 2.8 present. [ 0.000000] DMI: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.17.0-10.fc44 06/10/2025 [ 0.000000] Hypervisor detected: KVM [ 0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00 [ 0.000000] kvm-clock: using sched offset of 437459111 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2399.998 MHz processor [ 0.000000] last_pfn = 0x146e00 max_arch_pfn = 0x400000000 [ 0.000000] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT [ 0.000000] last_pfn = 0xbffda max_arch_pfn = 0x400000000 [ 0.000000] found SMP MP-table at [mem 0x000f54d0-0x000f54df] [ 0.000000] RAMDISK: [mem 0xbcc64000-0xbffcffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F52F0 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE2464 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE2300 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 0022C0 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE2374 000090 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE2404 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE243C 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe2300-0xbffe2373] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe22ff] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe2374-0xbffe2403] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe2404-0xbffe243b] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe243c-0xbffe2463] [ 0.000000] No NUMA configuration found [ 0.000000] Faking a node at [mem 0x0000000000000000-0x0000000146dfffff] [ 0.000000] NODE_DATA(0) allocated [mem 0x1465a3000-0x1465cdfff] [ 0.000000] Reserving 256MB of memory at 2624MB for crashkernel (System RAM: 4205MB) [ 0.000000] Zone ranges: [ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.000000] DMA32 [mem 0x0000000001000000-0x00000000ffffffff] [ 0.000000] Normal [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Device empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff] [ 0.000000] node 0: [mem 0x0000000000100000-0x00000000bffd9fff] [ 0.000000] node 0: [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Zeroed struct page in unavailable ranges: 4744 pages [ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x0000000146dfffff] [ 0.000000] ACPI: PM-Timer IO Port: 0x608 [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) [ 0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) [ 0.000000] Using ACPI (MADT) for SMP configuration information [ 0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000] TSC deadline timer available [ 0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs [ 0.000000] kvm-guest: KVM setup pv remote TLB flush [ 0.000000] kvm-guest: setup PV sched yield [ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff] [ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff] [ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff] [ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff] [ 0.000000] PM: Registered nosave memory: [mem 0xbffda000-0xbfffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xc0000000-0xfeffbfff] [ 0.000000] PM: Registered nosave memory: [mem 0xfeffc000-0xfeffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xff000000-0xfffbffff] [ 0.000000] PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff] [ 0.000000] [mem 0xc0000000-0xfeffbfff] available for PCI devices [ 0.000000] Booting paravirtualized kernel on KVM [ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns [ 0.000000] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1 [ 0.000000] percpu: Embedded 63 pages/cpu s221184 r8192 d28672 u524288 [ 0.000000] kvm-guest: PV spinlocks enabled [ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1059618 [ 0.000000] Policy zone: Normal [ 0.000000] Kernel command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] Specific versions of hardware are certified with Red Hat Enterprise Linux 8. Please see the list of hardware certified with Red Hat Enterprise Linux 8 at https://catalog.redhat.com. [ 0.000000] audit: disabled (until reboot) [ 0.000000] software IO TLB: area num 4. [ 0.000000] Memory: 2829700K/4306400K available (18435K kernel code, 11221K rwdata, 7248K rodata, 2908K init, 18040K bss, 524584K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] ftrace: allocating 41240 entries in 162 pages [ 0.000000] ftrace: allocated 162 pages with 3 groups [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] rcu: RCU event tracing is enabled. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ 0.000000] rcu: RCU callback double-/use-after-free debug enabled. [ 0.000000] Rude variant of Tasks RCU enabled. [ 0.000000] Tracing variant of Tasks RCU enabled. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 0.000000] NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16 [ 0.000000] random: get_random_bytes called from start_kernel+0x622/0x9a8 with crng_init=0 [ 0.001000] Console: colour *CGA 80x25 [ 0.001000] printk: console [ttyS1] enabled [ 0.001000] ACPI: Core revision 20220331 [ 0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.001016] APIC: Switch to symmetric I/O mode setup [ 0.002465] x2apic enabled [ 0.003014] Switched APIC routing to physical x2apic. [ 0.004021] kvm-guest: setup PV IPIs [ 0.006987] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.007000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.007021] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.008017] pid_max: default: 32768 minimum: 301 [ 0.010168] LSM: Security Framework initializing [ 0.011057] Yama: becoming mindful. [ 0.012042] SELinux: Initializing. [ 0.013085] *** VALIDATE selinux *** [ 0.021445] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.026459] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.027166] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.028113] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.029098] *** VALIDATE tmpfs *** [ 0.031073] *** VALIDATE proc *** [ 0.032260] *** VALIDATE cgroup *** [ 0.033009] *** VALIDATE cgroup2 *** [ 0.035095] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.036153] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.037010] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.038032] Spectre V2 : User space: Vulnerable [ 0.039007] Speculative Store Bypass: Vulnerable [ 0.042364] debug: unmapping init [mem 0xffffffffada59000-0xffffffffada60fff] [ 0.045000] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.045711] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.046026] ... version: 2 [ 0.047013] ... bit width: 48 [ 0.048014] ... generic registers: 4 [ 0.049010] ... value mask: 0000ffffffffffff [ 0.050015] ... max period: 00007fffffffffff [ 0.051018] ... fixed-purpose events: 3 [ 0.052010] ... event mask: 000000070000000f [ 0.053309] rcu: Hierarchical SRCU implementation. [ 0.055490] smp: Bringing up secondary CPUs ... [ 0.056593] x86: Booting SMP configuration: [ 0.057030] .... node #0, CPUs: #1 #2 #3 [ 0.060780] smp: Brought up 1 node, 4 CPUs [ 0.062013] smpboot: Max logical packages: 1 [ 0.063020] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.130382] node 0 deferred pages initialised in 63ms [ 0.134016] devtmpfs: initialized [ 0.135326] x86/mm: Memory block size: 128MB [ 0.138995] gcov: version magic: 0x41383552 [ 0.142195] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.145145] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.148325] pinctrl core: initialized pinctrl subsystem [ 0.150164] [ 0.150779] ************************************************************* [ 0.153016] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.156013] ** ** [ 0.158013] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.160015] ** ** [ 0.163014] ** This means that this kernel is built to expose internal ** [ 0.165014] ** IOMMU data structures, which may compromise security on ** [ 0.168014] ** your system. ** [ 0.170012] ** ** [ 0.173021] ** If you see this message and you are not debugging the ** [ 0.175014] ** kernel, report this immediately to your vendor! ** [ 0.177012] ** ** [ 0.180015] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.182015] ************************************************************* [ 0.185845] NET: Registered protocol family 16 [ 0.186509] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.189065] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.192068] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.196099] cpuidle: using governor menu [ 0.198815] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.201496] PCI: Using configuration type 1 for base access [ 0.204124] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.214055] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.216033] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.219078] cryptd: max_cpu_qlen set to 1000 [ 0.222168] ACPI: Added _OSI(Module Device) [ 0.224014] ACPI: Added _OSI(Processor Device) [ 0.225015] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.227016] ACPI: Added _OSI(Processor Aggregator Device) [ 0.231651] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.237364] ACPI: Interpreter enabled [ 0.238000] ACPI: PM: (supports S0 S3 S4 S5) [ 0.240013] ACPI: Using IOAPIC for interrupt routing [ 0.242128] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.246616] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.258784] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.261076] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.264031] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.266114] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.271797] acpiphp: Slot [2] registered [ 0.274177] acpiphp: Slot [5] registered [ 0.275194] acpiphp: Slot [6] registered [ 0.277138] acpiphp: Slot [3] registered [ 0.278113] acpiphp: Slot [4] registered [ 0.280194] acpiphp: Slot [7] registered [ 0.282206] acpiphp: Slot [8] registered [ 0.284188] acpiphp: Slot [9] registered [ 0.285145] acpiphp: Slot [10] registered [ 0.287104] acpiphp: Slot [11] registered [ 0.289111] acpiphp: Slot [12] registered [ 0.290173] acpiphp: Slot [13] registered [ 0.292126] acpiphp: Slot [14] registered [ 0.293105] acpiphp: Slot [15] registered [ 0.295132] acpiphp: Slot [16] registered [ 0.296118] acpiphp: Slot [17] registered [ 0.298101] acpiphp: Slot [18] registered [ 0.300101] acpiphp: Slot [19] registered [ 0.301148] acpiphp: Slot [20] registered [ 0.303206] acpiphp: Slot [21] registered [ 0.305105] acpiphp: Slot [22] registered [ 0.307120] acpiphp: Slot [23] registered [ 0.309134] acpiphp: Slot [24] registered [ 0.310146] acpiphp: Slot [25] registered [ 0.312086] acpiphp: Slot [26] registered [ 0.314114] acpiphp: Slot [27] registered [ 0.315208] acpiphp: Slot [28] registered [ 0.317130] acpiphp: Slot [29] registered [ 0.318112] acpiphp: Slot [30] registered [ 0.320114] acpiphp: Slot [31] registered [ 0.321070] PCI host bridge to bus 0000:00 [ 0.323022] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.325023] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.328023] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.330025] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.332023] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.335033] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.337212] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.340106] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.343295] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.351587] pci 0000:00:01.1: reg 0x20: [io 0xc120-0xc12f] [ 0.356074] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.360043] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.362036] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.364017] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.367598] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.370791] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.373041] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.376847] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.380016] pci 0000:00:02.0: reg 0x10: [io 0xc100-0xc11f] [ 0.391014] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.394061] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.400449] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.406013] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.411014] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.422018] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.431396] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.439015] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.445014] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.458013] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.468412] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.471404] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.473353] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.475393] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.477186] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.482093] iommu: Default domain type: Passthrough [ 0.484454] SCSI subsystem initialized [ 0.485146] ACPI: bus type USB registered [ 0.487107] usbcore: registered new interface driver usbfs [ 0.489101] usbcore: registered new interface driver hub [ 0.491080] usbcore: registered new device driver usb [ 0.493124] pps_core: LinuxPPS API ver. 1 registered [ 0.495016] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.498066] PTP clock support registered [ 0.500145] EDAC MC: Ver: 3.0.0 [ 0.502115] PCI: Using ACPI for IRQ routing [ 0.504776] NetLabel: Initializing [ 0.506011] NetLabel: domain hash size = 128 [ 0.507011] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.509106] NetLabel: unlabeled traffic allowed by default [ 0.510120] vgaarb: loaded [ 0.512255] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.514013] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.522730] clocksource: Switched to clocksource kvm-clock [ 0.632430] VFS: Disk quotas dquot_6.6.0 [ 0.634353] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.637227] *** VALIDATE ramfs *** [ 0.638608] *** VALIDATE hugetlbfs *** [ 0.640601] pnp: PnP ACPI init [ 0.643988] pnp: PnP ACPI: found 6 devices [ 0.677223] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.680575] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.682793] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.684654] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.687000] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.689666] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.691837] NET: Registered protocol family 2 [ 0.694636] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.698575] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.702434] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.708030] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.711214] TCP: Hash tables configured (established 65536 bind 65536) [ 0.714268] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.717565] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.720540] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.723607] NET: Registered protocol family 1 [ 0.730027] RPC: Registered named UNIX socket transport module. [ 0.732254] RPC: Registered udp transport module. [ 0.733873] RPC: Registered tcp transport module. [ 0.735800] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.737504] NET: Registered protocol family 44 [ 0.739819] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.742243] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.744556] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.746935] PCI: CLS 0 bytes, default 64 [ 0.748797] Unpacking initramfs... [ 2.167395] debug: unmapping init [mem 0xffff9627fcc64000-0xffff9627fffcffff] [ 2.171535] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.173541] software IO TLB: mapped [mem 0x00000000b8c64000-0x00000000bcc64000] (64MB) [ 2.176187] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 2.674327] Initialise system trusted keyrings [ 2.676129] Key type blacklist registered [ 2.678143] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.689176] zbud: loaded [ 2.692236] *** VALIDATE nfs *** [ 2.693691] *** VALIDATE nfs4 *** [ 2.695658] pstore: using deflate compression [ 2.699526] Platform Keyring initialized [ 2.803817] NET: Registered protocol family 38 [ 2.805655] Key type asymmetric registered [ 2.806858] Asymmetric key parser 'x509' registered [ 2.808780] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 2.811790] io scheduler mq-deadline registered [ 2.814051] io scheduler kyber registered [ 2.815974] io scheduler bfq registered [ 2.818576] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 2.822195] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 2.825350] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 2.828972] ACPI: Power Button [PWRF] [ 2.835429] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 2.842831] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 2.859510] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 2.888464] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 2.919174] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 2.924781] Non-volatile memory driver v1.3 [ 2.926528] Linux agpgart interface v0.103 [ 2.960713] virtio_blk virtio1: [vda] 146712 512-byte logical blocks (75.1 MB/71.6 MiB) [ 2.963507] vda: detected capacity change from 0 to 75116544 [ 2.977538] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 2.980179] vdb: detected capacity change from 0 to 1073741824 [ 2.986688] libphy: Fixed MDIO Bus: probed [ 2.994110] usbcore: registered new interface driver usbserial_generic [ 2.996536] usbserial: USB Serial support registered for generic [ 2.999572] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.003186] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.004630] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.007193] mousedev: PS/2 mouse device common for all mice [ 3.009539] rtc_cmos 00:05: RTC can wake from S4 [ 3.012289] rtc_cmos 00:05: registered as rtc0 [ 3.014436] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.014633] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.020109] intel_pstate: CPU model not supported [ 3.023657] hid: raw HID events driver (C) Jiri Kosina [ 3.024502] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.025872] usbcore: registered new interface driver usbhid [ 3.030682] usbhid: USB HID core driver [ 3.032249] drop_monitor: Initializing network drop monitor service [ 3.033736] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.036359] Initializing XFRM netlink socket [ 3.041887] NET: Registered protocol family 10 [ 3.044824] Segment Routing with IPv6 [ 3.046202] NET: Registered protocol family 17 [ 3.048605] mpls_gso: MPLS GSO support [ 3.054466] RAS: Correctable Errors collector initialized. [ 3.056288] AVX version of gcm_enc/dec engaged. [ 3.057807] AES CTR mode by8 optimization enabled [ 3.131232] sched_clock: Marking stable (3131031582, 0)->(4072465181, -941433599) [ 3.133799] registered taskstats version 1 [ 3.135301] Loading compiled-in X.509 certificates [ 3.136805] zswap: loaded using pool lzo/zbud [ 3.161550] Key type big_key registered [ 3.174096] Key type encrypted registered [ 3.175989] ima: No TPM chip found, activating TPM-bypass! [ 3.178254] ima: Allocated hash algorithm: sha1 [ 3.180101] ima: No architecture policies found [ 3.181807] evm: Initialising EVM extended attributes: [ 3.183929] evm: security.selinux [ 3.185319] evm: security.ima [ 3.186490] evm: security.capability [ 3.187907] evm: HMAC attrs: 0x1 [ 3.190358] rtc_cmos 00:05: setting system clock to 2026-09-08 05:08:10 UTC (1788844090) [ 3.196918] debug: unmapping init [mem 0xffffffffaea03000-0xffffffffaebfffff] [ 3.200469] debug: unmapping init [mem 0xffffffffad782000-0xffffffffada58fff] [ 3.209162] Write protecting the kernel read-only data: 28672k [ 3.212370] debug: unmapping init [mem 0xffffffffabe03000-0xffffffffabffffff] [ 3.215051] debug: unmapping init [mem 0xffffffffac714000-0xffffffffac7fffff] [ 3.247960] 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.256088] systemd[1]: Detected virtualization kvm. [ 3.257921] systemd[1]: Detected architecture x86-64. [ 3.259462] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.280772] systemd[1]: No hostname configured. [ 3.282721] systemd[1]: Set hostname to . [ 3.284733] random: systemd: uninitialized urandom read (16 bytes read) [ 3.287471] systemd[1]: Initializing machine ID from random generator. [ 3.339649] random: ln: uninitialized urandom read (6 bytes read) [ 3.427211] random: systemd: uninitialized urandom read (16 bytes read) [ 3.430076] systemd[1]: Started Dispatch Password Requests to Console Directory Watch. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ 3.437259] systemd[1]: Listening on udev Kernel Socket. [ OK ] Listening on udev Kernel Socket. [ 3.442473] systemd[1]: Listening on Journal Socket (/dev/log). [ OK ] Listening on Journal Socket (/dev/log). [ OK ] Reached target Slices. [ OK ] Reached target Paths. [ OK ] Listening on Journal Socket. Starting Journal Service... Starting Create list of required st…ce nodes for the current kernel... [ OK ] Reached target Initrd Root Device. [ OK ] Reached target Swap. [ OK ] Started Memstrack Anylazing Service. [ OK ] Listening on udev Control Socket. [ OK ] Reached target Sockets. Starting Apply Kernel Variables... [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Timers. [ OK ] Reached target Local File Systems. Starting Create Volatile Files and Directories... Starting Setup Virtual Console... [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Apply Kernel Variables. Starting Create Static Device Nodes in /dev... [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Journal Service. [ OK ] Started Setup Virtual Console. Starting dracut cmdline hook... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 4.069856] device-mapper: uevent: version 1.0.3 [ 4.072363] device-mapper: ioctl: 4.46.0-ioctl (2022-02-22) initialised: dm-devel@redhat.com [ OK ] Started dracut pre-udev hook. Starting udev Kernel Device Manager... [ OK ] Started udev Kernel Device Manager. Starting dracut pre-trigger hook... [ OK ] Started dracut pre-trigger hook. Starting udev Coldplug all Devices... Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting dracut initqueue hook... [ 4.831892] virtio_net virtio0 ens2: renamed from eth0 [ 4.888883] scsi host0: ata_piix [ 4.897692] scsi host1: ata_piix [ 4.919279] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc120 irq 14 [ 4.922710] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc128 irq 15 [ 9.296885] dracut-initqueue[589]: RTNETLINK answers: File exists [ 9.695717] random: crng init done [ 9.697256] random: 7 urandom warning(s) missed due to ratelimiting Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. Mounting /sysroot... [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. [ 10.178141] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Remote File Systems. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped target Timers. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Paths. [ OK ] Stopped target Slices. [ OK ] Stopped target Sockets. [ OK ] Stopped target System Initialization. [ OK ] Stopped target Swap. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. [ OK ] Stopped target Local File Systems. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. Stopping udev Kernel Device Manager... [ OK ] Stopped Apply Kernel Variables. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Closed udev Kernel Socket. [ OK ] Closed udev Control Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 11.434665] printk: systemd: 22 output lines suppressed due to ratelimiting [ 11.729607] SELinux: Disabled at runtime. [ 11.792497] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 11.801861] systemd[1]: Detected virtualization kvm. [ 11.803972] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 12.395749] systemd[1]: initrd-switch-root.service: Succeeded. [ 12.399412] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 12.404852] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 12.409494] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 12.413456] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 12.422239] systemd[1]: Starting Journal Service... Starting Journal Service... [ 12.430442] systemd[1]: Mounting Kernel Debug File System... Mounting Kernel Debug File System... Mounting Huge Pages File System... [ OK ] Stopped target Switch Root. [ OK ] Listening on udev Kernel Socket. [ OK ] Stopped target Initrd File Systems. [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Reached target RPC Port Mapper. [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Listening on Process Core Dump Socket. [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Created slice User and Session Slice. [ OK ] Reached target Slices. [ OK ] Reached target rpc_pipefs.target. [ OK ] Listening on udev Control Socket. Starting Create list of required st…ce nodes for the current kernel... [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. Starting Remount Root and Kernel File Systems... Starting Apply Kernel Variables... Activating swap /dev/disk/by-label/SWAP... [ OK ] Created slice system-getty.slice. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. [ OK ] Stopped target Initrd Root File System. [ 12.611941] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS Mounting POSIX Message Queue File System... Starting udev Coldplug all Devices... [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Started Journal Service. [ OK ] Mounted Kernel Debug File System. [ OK ] Mounted Huge Pages File System. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Started Apply Kernel Variables. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Reached target Swap. Starting Configure read-only root support... Starting Create Static Device Nodes in /dev... Starting Flush Journal to Persistent Storage... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. Starting udev Kernel Device Manager... [ OK ] Reached target Local File Systems (Pre). Mounting /mnt... Mounting /home/green/git/lustre-release... [ OK ] Started udev Coldplug all Devices. [ OK ] Mounted /mnt. [ 12.927554] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 13.237112] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 13.254702] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 13.390236] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 13.420643] EDAC sbridge: Ver: 1.1.2 [ 14.409714] Key type dns_resolver registered [ 14.752535] NFS: Registering the id_resolver key type [ 14.756336] Key type id_resolver registered [ 14.758136] Key type id_legacy registered [ OK ] Started Configure read-only root support. [ 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... Starting Load/Save Random Seed... [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Load/Save Random Seed. [ OK ] Started Create Volatile Files and Directories. Starting RPC Bind... Starting Update UTMP about System Boot/Shutdown... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Started dnf makecache --timer. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. [ OK ] Started irqbalance daemon. Starting Restore /run/initramfs on shutdown... Starting Login Service... [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Started D-Bus System Message Bus. Starting Network Manager... [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Reached target sshd-keygen.target. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Reached target Timers. [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Login Service. [ OK ] Started Network Manager. Starting Network Manager Wait Online... [ OK ] Reached target Network. Starting Dynamic System Tuning Daemon... Starting OpenSSH server daemon... Starting GSSAPI Proxy Daemon... Starting Hostname Service... [ OK ] Started OpenSSH server daemon. [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... [ 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 Notify NFS peers of a restart... Starting Crash recovery kernel arming... Starting System Logging Service... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Starting Authorization Manager... [ OK ] Started Authorization Manager. [ OK ] Started Dynamic System Tuning Daemon. [ OK ] Reached target Multi-User System. [ OK ] Reached target Graphical Interface. Starting Update UTMP about System Runlevel Changes... [ OK ] Started Update UTMP about System Runlevel Changes. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg408-client login: [ 44.552218] libcfs: loading out-of-tree module taints kernel. [ 44.585096] Key type ._llcrypt registered [ 44.586830] Key type .llcrypt registered [ 44.870093] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [ 44.877933] alg: No test for adler32 (adler32-zlib) [ 45.906560] Lustre: Lustre: Build Version: 2.17.57_111_g33f3974 [ 46.272182] LNet: Added LNI 192.168.204.8@tcp [8/256/0/180] [ 47.920228] Key type lgssc registered [ 48.720360] Lustre: Echo OBD driver; http://www.lustre.org/ [ 187.334554] Lustre: Mounted lustre-client - version 2.17.57_111_g33f3974 [ 193.179408] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 193.319065] hrtimer: interrupt took 3487672 ns [ 208.355938] Lustre: DEBUG MARKER: oleg408-client.virtnet: executing check_logdir /tmp/testlogs/ [ 212.963663] Lustre: lustre-OST0000-osc-ffff962850633000: disconnect after 23s idle [ 214.182839] Lustre: DEBUG MARKER: oleg408-client.virtnet: executing yml_node [ 219.588629] Lustre: DEBUG MARKER: Client: 2.17.57.111 [ 222.830610] Lustre: DEBUG MARKER: MDS: 2.17.57.111 [ 225.981289] Lustre: DEBUG MARKER: OSS: 2.17.57.111 [ 228.036734] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity ============----- Tue Sep 8 01:11:53 EDT 2026 [ 247.932771] Lustre: DEBUG MARKER: - need MDS1_VERSION <= 2.16.61-1-g89cf292a8c2 (34683247 <= 34618625) for LU-18938, skip 360 [ 249.784231] Lustre: DEBUG MARKER: - need MDS1_VERSION < v2_14_55-100-g8a84c7f9c7 (34683247 < 34486116) for LU-14927, skip 0f [ 251.806423] Lustre: DEBUG MARKER: - need OST1_VERSION < v2_17_50-410-gbd8e7b9555 (34683247 < 34681754) for LU-12550, skip 216 [ 253.662338] Lustre: DEBUG MARKER: excepting tests: 42a 42c 42b 118c 118d 407 119i 216 817 411a 130b 130c 130d 130e 130f 130g [ 255.389780] Lustre: DEBUG MARKER: skipping tests SLOW=no: 27m 60i 64b 68 71 135 136 230d 300o 842 51b 51c 51e 834 [ 256.993758] Lustre: DEBUG MARKER: === sanity: start setup 01:12:22 (1788844342) === [ 263.742954] Lustre: DEBUG MARKER: oleg408-client.virtnet: executing check_config_client /mnt/lustre [ 284.821601] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 297.742931] Lustre: DEBUG MARKER: === sanity: finish setup 01:13:03 (1788844383) === [ 306.973731] Lustre: DEBUG MARKER: == sanity test 60a: llog_test run from kernel module and test llog_reader ========================================================== 01:13:12 (1788844392) [ 311.673763] Lustre: DEBUG MARKER: SKIP: sanity test_60a missing subtest run-llog.sh [ 313.706933] Lustre: DEBUG MARKER: == sanity test 60b: limit repeated messages from CERROR/CWARN ========================================================== 01:13:19 (1788844399) [ 320.480718] Lustre: lustre-OST0001-osc-ffff962850633000: disconnect after 22s idle [ 320.489935] Lustre: Skipped 1 previous similar message [ 324.491616] Lustre: DEBUG MARKER: == sanity test 60c: unlink file when mds full ============ 01:13:30 (1788844410) [ 565.681466] Lustre: DEBUG MARKER: == sanity test 60d: test printk console message masking == 01:17:30 (1788844650) [ 565.886767] Lustre: DEBUG MARKER: test message ID 22643 7619 [ 574.835699] Lustre: DEBUG MARKER: == sanity test 60e: no space while new llog is being created ========================================================== 01:17:40 (1788844660) [ 586.200776] Lustre: DEBUG MARKER: == sanity test 60f: change debug_path works ============== 01:17:51 (1788844671) [ 586.689730] LustreError: dumping log to /tmp/f60f.sanity.1788844673.13898 [ 594.834116] Lustre: DEBUG MARKER: == sanity test 60g: transaction abort won't cause MDT hung ========================================================== 01:18:00 (1788844680) [ 728.627101] Lustre: DEBUG MARKER: == sanity test 60h: striped directory with missing stripes can be accessed ========================================================== 01:20:14 (1788844814) [ 730.861402] Lustre: DEBUG MARKER: SKIP: sanity test_60h Need at least 2 MDTs [ 733.047877] Lustre: DEBUG MARKER: SKIP: sanity test_60i skipping SLOW test 60i [ 735.708975] Lustre: DEBUG MARKER: == sanity test 60j: llog_reader reports corruptions ====== 01:20:21 (1788844821) [ 738.526737] Lustre: DEBUG MARKER: SKIP: sanity test_60j ldiskfs only test [ 740.687428] Lustre: DEBUG MARKER: == sanity test 61a: mmap() writes don't make sync hang ========================================================================== 01:20:26 (1788844826) [ 752.983208] Lustre: DEBUG MARKER: == sanity test 61b: mmap() of unstriped file is successful ========================================================== 01:20:37 (1788844837) [ 760.807778] Lustre: lustre-OST0001-osc-ffff962850633000: disconnect after 20s idle [ 762.229465] Lustre: DEBUG MARKER: == sanity test 63a: Verify oig_wait interruption does not crash ================================================================= 01:20:47 (1788844847) [ 833.199526] Lustre: DEBUG MARKER: == sanity test 63b: async write errors should be returned to fsync ============================================================= 01:21:59 (1788844919) [ 834.787197] Lustre: *** cfs_fail_loc=406, val=0*** [ 834.793868] LustreError: 20762:0:(osc_request.c:2918:osc_build_rpc()) lustre-OST0001-osc-ffff962850633000: prep_req failed: rc = -12 [ 834.806276] LustreError: 20762:0:(osc_cache.c:2365:osc_check_rpcs()) Write request failed with -12 [ 848.627926] Lustre: DEBUG MARKER: == sanity test 63c: test sync_on_close=1 ================= 01:22:14 (1788844934) [ 861.938378] LNet: 21578:0:(debug.c:375:cfs_str2mask()) unknown mask 'entry'. [ 861.938378] mask usage: [+|-] ... [ 874.767470] Lustre: DEBUG MARKER: == sanity test 64a: verify filter grant calculations (in kernel) =============================================================== 01:22:40 (1788844960) [ 885.376362] Lustre: DEBUG MARKER: SKIP: sanity test_64b skipping SLOW test 64b [ 887.347907] Lustre: DEBUG MARKER: == sanity test 64c: verify grant shrink ================== 01:22:52 (1788844972) [ 897.615710] Lustre: DEBUG MARKER: == sanity test 64d: check grant limit exceed ============= 01:23:03 (1788844983) [ 962.851375] Lustre: DEBUG MARKER: == sanity test 64e: check grant consumption (no grant allocation) ========================================================== 01:24:08 (1788845048) [ 966.203241] Lustre: Unmounted lustre-client [ 966.781835] Lustre: Mounted lustre-client - version 2.17.57_111_g33f3974 [ 972.219192] Lustre: Unmounted lustre-client [ 972.749078] Lustre: Mounted lustre-client - version 2.17.57_111_g33f3974 [ 983.627555] Lustre: DEBUG MARKER: == sanity test 64f: check grant consumption (with grant allocation) ========================================================== 01:24:29 (1788845069) [ 986.358278] Lustre: Unmounted lustre-client [ 986.988121] Lustre: Mounted lustre-client - version 2.17.57_111_g33f3974 [ 990.763718] Lustre: Unmounted lustre-client [ 991.170969] Lustre: Mounted lustre-client - version 2.17.57_111_g33f3974 [ 999.563409] Lustre: DEBUG MARKER: == sanity test 64g: grant shrink on MDT ================== 01:24:45 (1788845085) [ 1028.970308] Lustre: DEBUG MARKER: == sanity test 64h: grant shrink on read ================= 01:25:14 (1788845114) [ 1054.257685] Lustre: DEBUG MARKER: == sanity test 64i: shrink on reconnect ================== 01:25:39 (1788845139) [ 1073.126501] Lustre: lustre-OST0000-osc-ffff962852e0c000: Connection to lustre-OST0000 (at 192.168.204.108@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1083.360157] Lustre: 2350:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788845154/real 1788845154] req@ffff96276fda4e00 x1875739032084224/t0(0) o17->lustre-OST0000-osc-ffff962852e0c000@192.168.204.108@tcp:28/4 lens 456/432 e 0 to 1 dl 1788845170 ref 1 fl Rpc:XQr/200/ffffffff rc 0/-1 job:'lctl.0' uid:0 gid:0 projid:4294967295 [ 1107.641094] Lustre: DEBUG MARKER: oleg408-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 1109.510529] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 1124.452417] Lustre: DEBUG MARKER: == sanity test 64j: check grants on re-done rpc ========== 01:26:50 (1788845210) [ 1125.997855] LustreError: 2351:0:(osc_request.c:2451:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff96276fda7100 x1875739032096640/t0(0) o4->lustre-OST0000-osc-ffff962852e0c000@192.168.204.108@tcp:6/4 lens 4584/448 e 0 to 0 dl 1788845229 ref 2 fl Interpret:RMQU/600/0 rc -5/-5 job:'multiop.0' uid:0 gid:0 projid:0 [ 1136.748627] Lustre: DEBUG MARKER: == sanity test 65a: directory with no stripe info ======== 01:27:02 (1788845222) [ 1144.193733] Lustre: DEBUG MARKER: == sanity test 65b: directory setstripe -S stripe_size*2 -i 0 -c 1 ========================================================== 01:27:09 (1788845229) [ 1151.495812] Lustre: DEBUG MARKER: == sanity test 65c: directory setstripe -S stripe_size*4 -i 1 -c 1 ========================================================== 01:27:17 (1788845237) [ 1159.133546] Lustre: DEBUG MARKER: == sanity test 65d: directory setstripe -S stripe_size -c stripe_count ========================================================== 01:27:24 (1788845244) [ 1166.590498] Lustre: DEBUG MARKER: == sanity test 65e: directory setstripe defaults ========= 01:27:32 (1788845252) [ 1173.763797] Lustre: DEBUG MARKER: == sanity test 65f: dir setstripe permission (should return error) ============================================================= 01:27:39 (1788845259) [ 1181.233885] Lustre: DEBUG MARKER: == sanity test 65g: directory setstripe -d =============== 01:27:46 (1788845266) [ 1189.120774] Lustre: DEBUG MARKER: == sanity test 65h: directory stripe info inherit ============================================================================== 01:27:54 (1788845274) [ 1197.141815] Lustre: DEBUG MARKER: == sanity test 65i: various tests to set root directory striping ========================================================== 01:28:02 (1788845282) [ 1206.273196] Lustre: DEBUG MARKER: == sanity test 65j: set default striping on root directory (bug 6367)=========================================================== 01:28:12 (1788845292) [ 1215.225770] Lustre: DEBUG MARKER: == sanity test 65k: validate manual striping works properly with deactivated OSCs ========================================================== 01:28:20 (1788845300) [ 1329.931260] Lustre: DEBUG MARKER: == sanity test 65l: lfs find on -1 stripe dir ================================================================================== 01:30:15 (1788845415) [ 1337.676682] Lustre: DEBUG MARKER: == sanity test 65m: normal user can't set filesystem default stripe ========================================================== 01:30:23 (1788845423) [ 1344.779622] Lustre: DEBUG MARKER: == sanity test 65n: don't inherit default layout from root for new subdirectories ========================================================== 01:30:30 (1788845430) [ 1356.712484] Lustre: DEBUG MARKER: SKIP: sanity test_65n needs >= 2 MDTs [ 1370.865291] Lustre: DEBUG MARKER: == sanity test 65o: pool inheritance for mdt component === 01:30:56 (1788845456) [ 1399.478622] Lustre: DEBUG MARKER: == sanity test 65p: setstripe with yaml file and huge number ========================================================== 01:31:25 (1788845485) [ 1408.030157] Lustre: DEBUG MARKER: == sanity test 65q: setstripe with >=8E offset should fail ========================================================== 01:31:33 (1788845493) [ 1416.325105] Lustre: DEBUG MARKER: == sanity test 65r: prevent all-zero offsets ============= 01:31:42 (1788845502) [ 1425.818814] Lustre: DEBUG MARKER: == sanity test 66: update inode blocks count on client ========================================================================= 01:31:51 (1788845511) [ 1440.030415] Lustre: DEBUG MARKER: == sanity test 69: verify oa2dentry return -ENOENT doesn't LBUG ================================================================ 01:32:05 (1788845525) [ 1452.225774] Lustre: DEBUG MARKER: == sanity test 70a: verify health_check, health_write don't explode (on OST) ========================================================== 01:32:18 (1788845538) [ 1465.194512] Lustre: DEBUG MARKER: SKIP: sanity test_71 skipping SLOW test 71 [ 1466.771645] Lustre: DEBUG MARKER: == sanity test 72a: Test that remove suid works properly (bug5695) ============================================================== 01:32:32 (1788845552) [ 1474.172224] Lustre: DEBUG MARKER: == sanity test 72b: Test that we keep mode setting if without file data changed (bug 24226) ========================================================== 01:32:40 (1788845560) [ 1483.033498] Lustre: DEBUG MARKER: == sanity test 73: multiple MDC requests (should not deadlock) ========================================================== 01:32:48 (1788845568) [ 1519.051701] Lustre: DEBUG MARKER: == sanity test 74a: ldlm_enqueue freed-export error path, ls (shouldn't LBUG) ========================================================== 01:33:24 (1788845604) [ 1527.903038] Lustre: DEBUG MARKER: == sanity test 74b: ldlm_enqueue freed-export error path, touch (shouldn't LBUG) ========================================================== 01:33:33 (1788845613) [ 1535.611190] Lustre: DEBUG MARKER: == sanity test 74c: ldlm_lock_create error path, (shouldn't LBUG) ========================================================== 01:33:41 (1788845621) [ 1535.868857] Lustre: *** cfs_fail_loc=319, val=0*** [ 1543.488210] Lustre: DEBUG MARKER: == sanity test 76a: confirm clients recycle inodes properly ============================================================== 01:33:49 (1788845629) [ 1636.064983] Lustre: DEBUG MARKER: == sanity test 76b: confirm clients recycle directory inodes properly ============================================================== 01:35:21 (1788845721) [ 1702.219782] Lustre: DEBUG MARKER: == sanity test 77a: normal checksum read/write operation ========================================================== 01:36:27 (1788845787) [ 1711.075983] Lustre: DEBUG MARKER: == sanity test 77b: checksum error on client write, read ========================================================== 01:36:36 (1788845796) [ 1711.698479] Lustre: *** cfs_fail_loc=409, val=0*** [ 1711.855167] LustreError: lustre-OST0001-osc-ffff962852e0c000: BAD WRITE CHECKSUM: changed on the client after we checksummed it - likely false positive due to mmap IO (bug 11742): from 192.168.204.108@tcp inode [0x200000406:0xc34:0x0] object 0x280000400:3787 extent [0-1048575], original client csum e2d00085 (type 4), server csum e2d00084 (type 4), client csum now e2d00084 [ 1711.878839] LustreError: 2348:0:(osc_request.c:2451:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff962858f9fb80 x1875739035292160/t4294971589(4294971589) o4->lustre-OST0001-osc-ffff962852e0c000@192.168.204.108@tcp:6/4 lens 488/448 e 0 to 0 dl 1788845815 ref 3 fl Interpret:RQU/604/0 rc 0/0 job:'dd.0' uid:0 gid:0 projid:0 [ 1714.955940] Lustre: DEBUG MARKER: set checksum type to crc32, rc = 0 [ 1715.499259] Lustre: *** cfs_fail_loc=408, val=0*** [ 1715.522855] LustreError: lustre-OST0001-osc-ffff962852e0c000: BAD READ CHECKSUM: from 192.168.204.108@tcp inode [0x200000406:0xc34:0x0] object 0x280000400:3787 extent [0-1048575], client b214f2f6/b214f2f6, server fa123271, cksum_type 1 [ 1715.535501] LustreError: 2351:0:(osc_request.c:2451:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff9628718c3b80 x1875739035294848/t0(0) o3->lustre-OST0001-osc-ffff962852e0c000@192.168.204.108@tcp:6/4 lens 488/440 e 0 to 0 dl 1788845818 ref 2 fl Interpret:RMQU/600/0 rc 1048576/1048576 job:'cmp.0' uid:0 gid:0 projid:0 [ 1719.436447] Lustre: DEBUG MARKER: set checksum type to adler, rc = 0 [ 1720.294620] Lustre: *** cfs_fail_loc=408, val=0*** [ 1720.311843] LustreError: lustre-OST0001-osc-ffff962852e0c000: BAD READ CHECKSUM: from 192.168.204.108@tcp inode [0x200000406:0xc34:0x0] object 0x280000400:3787 extent [1048576-2097151], client 83fb465d/83fb465d, server 26bb45f9, cksum_type 2 [ 1720.327608] LustreError: 2350:0:(osc_request.c:2451:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff9628718c2d80 x1875739035297536/t0(0) o3->lustre-OST0001-osc-ffff962852e0c000@192.168.204.108@tcp:6/4 lens 488/440 e 0 to 0 dl 1788845823 ref 2 fl Interpret:RMQU/600/0 rc 1048576/1048576 job:'cmp.0' uid:0 gid:0 projid:0 [ 1724.762591] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 1725.117590] Lustre: *** cfs_fail_loc=408, val=0*** [ 1725.129499] LustreError: lustre-OST0001-osc-ffff962852e0c000: BAD READ CHECKSUM: from 192.168.204.108@tcp inode [0x200000406:0xc34:0x0] object 0x280000400:3787 extent [1048576-2097151], client 158b8fe2/158b8fe2, server fffd035e, cksum_type 4 [ 1725.147262] LustreError: 2348:0:(osc_request.c:2451:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff962858f9c700 x1875739035299968/t0(0) o3->lustre-OST0001-osc-ffff962852e0c000@192.168.204.108@tcp:6/4 lens 488/440 e 0 to 0 dl 1788845828 ref 2 fl Interpret:RMQU/600/0 rc 1048576/1048576 job:'cmp.0' uid:0 gid:0 projid:0 [ 1729.561748] Lustre: DEBUG MARKER: set checksum type to t10ip512, rc = 0 [ 1730.273824] Lustre: *** cfs_fail_loc=408, val=0*** [ 1730.287889] LustreError: lustre-OST0001-osc-ffff962852e0c000: BAD READ CHECKSUM: from 192.168.204.108@tcp inode [0x200000406:0xc34:0x0] object 0x280000400:3787 extent [0-1048575], client 656fc20/656fc20, server a65afcaa, cksum_type 10 [ 1734.868523] Lustre: DEBUG MARKER: set checksum type to t10ip4K, rc = 0 [ 1735.975468] LustreError: lustre-OST0001-osc-ffff962852e0c000: BAD READ CHECKSUM: from 192.168.204.108@tcp inode [0x200000406:0xc34:0x0] object 0x280000400:3787 extent [0-1048575], client 809801c7/809801c7, server 94330251, cksum_type 20 [ 1736.009424] LustreError: 2351:0:(osc_request.c:2451:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff962877428380 x1875739035304064/t0(0) o3->lustre-OST0001-osc-ffff962852e0c000@192.168.204.108@tcp:6/4 lens 488/440 e 0 to 0 dl 1788845839 ref 2 fl Interpret:RMQU/600/0 rc 1048576/1048576 job:'cmp.0' uid:0 gid:0 projid:0 [ 1736.080113] LustreError: 2351:0:(osc_request.c:2451:osc_brw_redo_request()) Skipped 1 previous similar message [ 1740.738240] Lustre: DEBUG MARKER: set checksum type to t10crc4K, rc = 0 [ 1741.468576] Lustre: *** cfs_fail_loc=408, val=0*** [ 1741.475692] Lustre: Skipped 1 previous similar message [ 1745.491798] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 1753.777940] Lustre: DEBUG MARKER: == sanity test 77c: checksum error on client read with debug ========================================================== 01:37:19 (1788845839) [ 1760.358898] Lustre: *** cfs_fail_loc=408, val=0*** [ 1760.376893] Lustre: 2350:0:(osc_request.c:2035:dump_all_bulk_pages()) /tmp/lustre-log-checksum_dump-osc-[0x200000406:0xc35:0x0]:[0-1048575]-dc0df22b-e2d00084: dumping checksum data [ 1760.404431] LustreError: dumping log to /tmp/lustre-log.1788845847.2350 [ 1764.459035] LustreError: lustre-OST0000-osc-ffff962852e0c000: BAD READ CHECKSUM: from 192.168.204.108@tcp inode [0x200000406:0xc35:0x0] object 0x240000400:3799 extent [0-1048575], client dc0df22b/dc0df22b, server e2d00084, cksum_type 4 [ 1764.492782] LustreError: Skipped 1 previous similar message [ 1764.498425] LustreError: 2350:0:(osc_request.c:2451:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff962877428700 x1875739035313664/t0(0) o3->lustre-OST0000-osc-ffff962852e0c000@192.168.204.108@tcp:6/4 lens 488/440 e 0 to 0 dl 1788845863 ref 2 fl Interpret:RMQU/600/0 rc 1048576/1048576 job:'dd.0' uid:0 gid:0 projid:0 [ 1764.522575] LustreError: 2350:0:(osc_request.c:2451:osc_brw_redo_request()) Skipped 1 previous similar message [ 1799.828757] Lustre: DEBUG MARKER: == sanity test 77d: checksum error on OST direct write, read ========================================================== 01:38:05 (1788845885) [ 1800.460781] Lustre: *** cfs_fail_loc=409, val=0*** [ 1800.467775] LustreError: 2347:0:(osc_request.c:1024:osc_init_grant()) lustre-OST0000-osc-ffff962852e0c000: granted 3407872 but already consumed 13631488 [ 1800.878296] LustreError: lustre-OST0000-osc-ffff962852e0c000: BAD WRITE CHECKSUM: changed on the client after we checksummed it - likely false positive due to mmap IO (bug 11742): from 192.168.204.108@tcp inode [0x200000406:0xc37:0x0] object 0x240000400:3800 extent [0-1048575], original client csum b5ea7f3c (type 4), server csum b5ea7f3b (type 4), client csum now b5ea7f3b [ 1800.906613] LustreError: 2350:0:(osc_request.c:2451:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff9628718c1f80 x1875739035319040/t8589936190(8589936190) o4->lustre-OST0000-osc-ffff962852e0c000@192.168.204.108@tcp:6/4 lens 488/448 e 0 to 0 dl 1788845903 ref 2 fl Interpret:RMQU/600/0 rc 0/0 job:'directio.0' uid:0 gid:0 projid:0 [ 1802.528213] LustreError: lustre-OST0000-osc-ffff962852e0c000: BAD READ CHECKSUM: from 192.168.204.108@tcp inode [0x200000406:0xc37:0x0] object 0x240000400:3800 extent [0-1048575], client fe0f685f/fe0f685f, server b5ea7f3b, cksum_type 4 [ 1813.310215] Lustre: DEBUG MARKER: == sanity test 77f: repeat checksum error on write (expect error) ========================================================== 01:38:18 (1788845898) [ 1815.559826] Lustre: DEBUG MARKER: set checksum type to crc32, rc = 0 [ 1816.236433] LustreError: 2347:0:(osc_request.c:1024:osc_init_grant()) lustre-OST0001-osc-ffff962852e0c000: granted 3407872 but already consumed 13631488 [ 1816.519412] LustreError: lustre-OST0001-osc-ffff962852e0c000: BAD WRITE CHECKSUM: changed in transit before arrival at OST: from 192.168.204.108@tcp inode [0x200000406:0xc38:0x0] object 0x280000400:3788 extent [4194304-5242879], original client csum b2f1b12 (type 1), server csum b2f1b11 (type 1), client csum now b2f1b12 [ 1816.558115] LustreError: Skipped 2 previous similar messages [ 1817.905821] LustreError: 2351:0:(osc_request.c:2608:brw_interpret()) lustre-OST0001-osc-ffff962852e0c000: too many resent retries for object: 10737419264:3788: rc = -11 [ 1819.757400] Lustre: DEBUG MARKER: set checksum type to adler, rc = 0 [ 1820.525072] LustreError: lustre-OST0000-osc-ffff962852e0c000: BAD WRITE CHECKSUM: changed in transit before arrival at OST: from 192.168.204.108@tcp inode [0x200000406:0xc39:0x0] object 0x240000400:3801 extent [2097152-3145727], original client csum 19eeae62 (type 2), server csum 19eeae61 (type 2), client csum now 19eeae62 [ 1820.546091] LustreError: Skipped 13 previous similar messages [ 1821.814202] LustreError: 2351:0:(osc_request.c:2608:brw_interpret()) lustre-OST0000-osc-ffff962852e0c000: too many resent retries for object: 9663677440:3801: rc = -11 [ 1821.831988] LustreError: 2351:0:(osc_request.c:2608:brw_interpret()) Skipped 7 previous similar messages [ 1823.893207] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 1824.530384] LustreError: lustre-OST0001-osc-ffff962852e0c000: BAD WRITE CHECKSUM: changed in transit before arrival at OST: from 192.168.204.108@tcp inode [0x200000406:0xc3a:0x0] object 0x280000400:3789 extent [3145728-4194303], original client csum b5ea7f3c (type 4), server csum b5ea7f3b (type 4), client csum now b5ea7f3c [ 1824.563665] LustreError: Skipped 16 previous similar messages [ 1825.788182] LustreError: 2348:0:(osc_request.c:2608:brw_interpret()) lustre-OST0001-osc-ffff962852e0c000: too many resent retries for object: 10737419264:3789: rc = -11 [ 1825.795925] LustreError: 2348:0:(osc_request.c:2608:brw_interpret()) Skipped 7 previous similar messages [ 1828.179180] Lustre: DEBUG MARKER: set checksum type to t10ip512, rc = 0 [ 1830.161777] LustreError: 2349:0:(osc_request.c:2608:brw_interpret()) lustre-OST0000-osc-ffff962852e0c000: too many resent retries for object: 9663677440:3802: rc = -11 [ 1830.174150] LustreError: 2349:0:(osc_request.c:2608:brw_interpret()) Skipped 7 previous similar messages [ 1832.582203] Lustre: DEBUG MARKER: set checksum type to t10ip4K, rc = 0 [ 1833.300128] LustreError: lustre-OST0001-osc-ffff962852e0c000: BAD WRITE CHECKSUM: changed in transit before arrival at OST: from 192.168.204.108@tcp inode [0x200000406:0xc3c:0x0] object 0x280000400:3790 extent [1048576-2097151], original client csum 30ec5402 (type 20), server csum 30ec5401 (type 20), client csum now 30ec5402 [ 1833.340741] LustreError: Skipped 30 previous similar messages [ 1834.620076] LustreError: 2350:0:(osc_request.c:2608:brw_interpret()) lustre-OST0001-osc-ffff962852e0c000: too many resent retries for object: 10737419264:3790: rc = -11 [ 1834.632258] LustreError: 2350:0:(osc_request.c:2608:brw_interpret()) Skipped 7 previous similar messages [ 1837.169994] Lustre: DEBUG MARKER: set checksum type to t10crc4K, rc = 0 [ 1848.723658] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 1851.002748] Lustre: DEBUG MARKER: == sanity test 77g: checksum error on OST write, read ==== 01:38:56 (1788845936) [ 1853.689853] LustreError: lustre-OST0000-osc-ffff962852e0c000: BAD WRITE CHECKSUM: changed in transit before arrival at OST: from 192.168.204.108@tcp inode [0x200000406:0xc3e:0x0] object 0x240000400:3804 extent [0-1048575], original client csum e2d00084 (type 4), server csum 4bd77643 (type 4), client csum now e2d00084 [ 1853.734785] LustreError: Skipped 31 previous similar messages [ 1859.692927] LustreError: lustre-OST0000-osc-ffff962852e0c000: BAD READ CHECKSUM: from 192.168.204.108@tcp inode [0x200000406:0xc3e:0x0] object 0x240000400:3804 extent [0-1048575], client e2d00084/e2d00084, server ceba49c9, cksum_type 4 [ 1871.927358] Lustre: DEBUG MARKER: == sanity test 77k: enable/disable checksum correctly ==== 01:39:17 (1788845957) [ 1878.270601] Lustre: Unmounted lustre-client [ 1878.893119] Lustre: Mounted lustre-client - version 2.17.57_111_g33f3974 [ 1885.920031] Lustre: Unmounted lustre-client [ 1886.422138] Lustre: Mounted lustre-client - version 2.17.57_111_g33f3974 [ 1890.728693] Lustre: Unmounted lustre-client [ 1891.314926] Lustre: Mounted lustre-client - version 2.17.57_111_g33f3974 [ 1893.392458] Lustre: Unmounted lustre-client [ 1893.869241] Lustre: Mounted lustre-client - version 2.17.57_111_g33f3974 [ 1906.911517] Lustre: DEBUG MARKER: == sanity test 77l: preferred checksum type is remembered after reconnected ========================================================== 01:39:52 (1788845992) [ 1908.819440] Lustre: DEBUG MARKER: set checksum type to invalid, rc = 22 [ 1911.349524] Lustre: DEBUG MARKER: set checksum type to crc32, rc = 0 [ 1917.914369] Lustre: DEBUG MARKER: oleg408-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff962846c8e800.ost_server_uuid 50 [ 1919.354934] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff962846c8e800.ost_server_uuid in IDLE state after 0 sec [ 1925.073493] Lustre: DEBUG MARKER: oleg408-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff962846c8e800.ost_server_uuid 50 [ 1926.400138] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff962846c8e800.ost_server_uuid in FULL state after 0 sec [ 1927.951351] Lustre: DEBUG MARKER: set checksum type to adler, rc = 0 [ 1934.537246] Lustre: DEBUG MARKER: oleg408-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff962846c8e800.ost_server_uuid 50 [ 1944.809966] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff962846c8e800.ost_server_uuid in IDLE state after 8 sec [ 1951.444363] Lustre: DEBUG MARKER: oleg408-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff962846c8e800.ost_server_uuid 50 [ 1953.638917] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff962846c8e800.ost_server_uuid in FULL state after 0 sec [ 1956.021875] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 1963.822498] Lustre: DEBUG MARKER: oleg408-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff962846c8e800.ost_server_uuid 50 [ 1970.397786] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff962846c8e800.ost_server_uuid in IDLE state after 4 sec [ 1976.581165] Lustre: DEBUG MARKER: oleg408-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff962846c8e800.ost_server_uuid 50 [ 1978.588711] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff962846c8e800.ost_server_uuid in FULL state after 0 sec [ 1980.724852] Lustre: DEBUG MARKER: set checksum type to t10ip512, rc = 0 [ 1987.693154] Lustre: DEBUG MARKER: oleg408-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff962846c8e800.ost_server_uuid 50 [ 1995.644748] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff962846c8e800.ost_server_uuid in IDLE state after 6 sec [ 2001.772201] Lustre: DEBUG MARKER: oleg408-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff962846c8e800.ost_server_uuid 50 [ 2003.616504] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff962846c8e800.ost_server_uuid in FULL state after 0 sec [ 2005.145910] Lustre: DEBUG MARKER: set checksum type to t10ip4K, rc = 0 [ 2011.832499] Lustre: DEBUG MARKER: oleg408-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff962846c8e800.ost_server_uuid 50 [ 2021.296351] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff962846c8e800.ost_server_uuid in IDLE state after 7 sec [ 2027.252323] Lustre: DEBUG MARKER: oleg408-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff962846c8e800.ost_server_uuid 50 [ 2029.181652] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff962846c8e800.ost_server_uuid in FULL state after 0 sec [ 2031.581837] Lustre: DEBUG MARKER: set checksum type to t10crc4K, rc = 0 [ 2038.759573] Lustre: DEBUG MARKER: oleg408-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff962846c8e800.ost_server_uuid 50 [ 2046.762632] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff962846c8e800.ost_server_uuid in IDLE state after 6 sec [ 2053.106741] Lustre: DEBUG MARKER: oleg408-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff962846c8e800.ost_server_uuid 50 [ 2054.416078] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff962846c8e800.ost_server_uuid in FULL state after 0 sec [ 2062.174455] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 2064.005969] Lustre: DEBUG MARKER: == sanity test 77m: Verify checksum_speed is correctly read ========================================================== 01:42:29 (1788846149) [ 2071.961212] Lustre: DEBUG MARKER: == sanity test 77n: Verify read from a hole inside contiguous blocks with T10PI ========================================================== 01:42:37 (1788846157) [ 2074.460258] Lustre: DEBUG MARKER: SKIP: sanity test_77n f77n.sanity blocks not contiguous around hole [ 2076.796527] Lustre: DEBUG MARKER: == sanity test 77o: Verify checksum_type for server (mdt and ofd(obdfilter)) ========================================================== 01:42:42 (1788846162) [ 2088.561654] Lustre: DEBUG MARKER: == sanity test 78: handle large O_DIRECT writes correctly ====================================================================== 01:42:54 (1788846174) [ 2100.036872] Lustre: DEBUG MARKER: == sanity test 79: df report consistency check =========== 01:43:05 (1788846185) [ 2120.928380] Lustre: DEBUG MARKER: == sanity test 80: Page eviction is equally fast at high offsets too ========================================================== 01:43:26 (1788846206) [ 2133.930186] Lustre: DEBUG MARKER: == sanity test 81a: OST should retry write when get -ENOSPC ========================================================================= 01:43:38 (1788846218) [ 2143.657049] Lustre: DEBUG MARKER: == sanity test 81b: OST should return -ENOSPC when retry still fails ================================================================= 01:43:49 (1788846229) [ 2153.401879] Lustre: DEBUG MARKER: == sanity test 99: cvs strange file/directory operations ========================================================== 01:43:58 (1788846238) [ 2190.109575] Lustre: DEBUG MARKER: == sanity test 100: check local port using privileged port ========================================================== 01:44:35 (1788846275) [ 2200.671976] Lustre: DEBUG MARKER: == sanity test 101a: check read-ahead for random reads === 01:44:46 (1788846286) [ 2407.832677] Lustre: DEBUG MARKER: == sanity test 101b: check stride-io mode read-ahead =========================================================================== 01:48:13 (1788846493) [ 2442.951609] Lustre: DEBUG MARKER: == sanity test 101c: check stripe_size aligned read-ahead ========================================================== 01:48:48 (1788846528) [ 2541.992175] Lustre: DEBUG MARKER: == sanity test 101d: file read with and without read-ahead enabled ========================================================== 01:50:27 (1788846627) [ 2877.901581] Lustre: DEBUG MARKER: == sanity test 101e: check read-ahead for small read(1k) for small files(500k) ========================================================== 01:56:03 (1788846963) [ 2983.114042] Lustre: DEBUG MARKER: == sanity test 101f: check mmap read performance ========= 01:57:48 (1788847068) [ 2996.505566] Lustre: DEBUG MARKER: == sanity test 101g: Big bulk(4/16 MiB) readahead ======== 01:58:01 (1788847081) [ 3007.081813] Lustre: Unmounted lustre-client [ 3007.087578] Lustre: Skipped 1 previous similar message [ 3007.587663] Lustre: Mounted lustre-client - version 2.17.57_111_g33f3974 [ 3007.592526] Lustre: Skipped 1 previous similar message [ 3053.382668] Lustre: Unmounted lustre-client [ 3053.988667] Lustre: Mounted lustre-client - version 2.17.57_111_g33f3974 [ 3103.546904] Lustre: DEBUG MARKER: == sanity test 101h: Readahead should cover current read window ========================================================== 01:59:49 (1788847189) [ 3127.363824] Lustre: DEBUG MARKER: == sanity test 101i: allow current readahead to exceed reservation ========================================================== 02:00:12 (1788847212) [ 3139.460618] Lustre: DEBUG MARKER: == sanity test 101j: A complete read block should be submitted when no RA ========================================================== 02:00:24 (1788847224) [ 3213.636209] Lustre: DEBUG MARKER: == sanity test 101m: read ahead for small file and last stripe of the file ========================================================== 02:01:39 (1788847299) [ 3216.174806] Lustre: DEBUG MARKER: SKIP: sanity test_101m fallocate not supported [ 3218.378658] Lustre: DEBUG MARKER: == sanity test 102a: user xattr test ============================================================================================ 02:01:43 (1788847303) [ 3227.288630] Lustre: DEBUG MARKER: == sanity test 102b: getfattr/setfattr for trusted.lov EAs ========================================================== 02:01:52 (1788847312) [ 3242.511974] Lustre: DEBUG MARKER: == sanity test 102c: non-root getfattr/setfattr for lustre.lov EAs ===================================================================== 02:02:08 (1788847328) [ 3251.156974] Lustre: DEBUG MARKER: == sanity test 102d: tar restore stripe info from tarfile,not keep osts ========================================================== 02:02:16 (1788847336) [ 3272.774973] Lustre: DEBUG MARKER: == sanity test 102f: tar copy files, not keep osts ======= 02:02:38 (1788847358) [ 3296.854656] Lustre: DEBUG MARKER: == sanity test 102h: grow xattr from inside inode to external block ========================================================== 02:03:02 (1788847382) [ 3300.021989] Lustre: DEBUG MARKER: save trusted.big on /mnt/lustre/f102h.sanity [ 3302.363666] Lustre: DEBUG MARKER: save trusted.sml on /mnt/lustre/f102h.sanity [ 3304.225295] Lustre: DEBUG MARKER: grow trusted.sml on /mnt/lustre/f102h.sanity [ 3305.885770] Lustre: DEBUG MARKER: trusted.big still valid after growing trusted.sml [ 3314.095425] Lustre: DEBUG MARKER: == sanity test 102ha: grow xattr from inside inode to external inode ========================================================== 02:03:19 (1788847399) [ 3316.527376] Lustre: DEBUG MARKER: save trusted.big on /mnt/lustre/f102ha.sanity [ 3319.077584] Lustre: DEBUG MARKER: save trusted.sml on /mnt/lustre/f102ha.sanity [ 3321.050451] Lustre: DEBUG MARKER: grow trusted.sml on /mnt/lustre/f102ha.sanity [ 3323.107490] Lustre: DEBUG MARKER: trusted.big still valid after growing trusted.sml [ 3326.595728] Lustre: DEBUG MARKER: save trusted.big on /mnt/lustre/f102ha.sanity [ 3335.773756] Lustre: DEBUG MARKER: == sanity test 102i: lgetxattr test on symbolic link ====================================================================== 02:03:40 (1788847420) [ 3344.780614] Lustre: DEBUG MARKER: == sanity test 102j: non-root tar restore stripe info from tarfile, not keep osts ============================================================= 02:03:50 (1788847430) [ 3367.734450] Lustre: DEBUG MARKER: == sanity test 102k: setfattr without parameter of value shouldn't cause a crash ========================================================== 02:04:13 (1788847453) [ 3375.452040] Lustre: DEBUG MARKER: == sanity test 102l: listxattr size test ============================================================================================ 02:04:21 (1788847461) [ 3383.886751] Lustre: DEBUG MARKER: == sanity test 102m: Ensure listxattr fails on small bufffer ================================================================== 02:04:29 (1788847469) [ 3391.081387] Lustre: DEBUG MARKER: == sanity test 102n: silently ignore setxattr on internal trusted xattrs ========================================================== 02:04:36 (1788847476) [ 3400.358383] Lustre: DEBUG MARKER: == sanity test 102p: check setxattr(2) correctly fails without permission ========================================================== 02:04:46 (1788847486) [ 3407.157343] Lustre: DEBUG MARKER: == sanity test 102q: flistxattr should not return trusted.link EAs for orphans ========================================================== 02:04:53 (1788847493) [ 3414.464496] Lustre: DEBUG MARKER: == sanity test 102r: set EAs with empty values =========== 02:04:59 (1788847499) [ 3422.884360] Lustre: DEBUG MARKER: == sanity test 102s: getting nonexistent xattrs should fail ========================================================== 02:05:08 (1788847508) [ 3430.988204] Lustre: DEBUG MARKER: == sanity test 102t: zero length xattr values handled correctly ========================================================== 02:05:16 (1788847516) [ 3443.305652] Lustre: DEBUG MARKER: == sanity test 103a: acl test ============================ 02:05:28 (1788847528) [ 3790.507995] Lustre: DEBUG MARKER: == sanity test 103b: umask lfs setstripe ================= 02:11:16 (1788847876) [ 4000.109615] Lustre: DEBUG MARKER: == sanity test 103c: 'cp -rp' won't set empty acl ======== 02:14:45 (1788848085) [ 4009.742325] Lustre: DEBUG MARKER: == sanity test 103e: inheritance of big amount of default ACLs ========================================================== 02:14:55 (1788848095) [ 4044.514970] Lustre: DEBUG MARKER: == sanity test 103f: changelog doesn't interfere with default ACLs buffers ========================================================== 02:15:29 (1788848129) [ 4058.942389] Lustre: DEBUG MARKER: == sanity test 103g: no MDS_GETXATTR storm for inodes without ACL_ACCESS (LU-17238) ========================================================== 02:15:44 (1788848144) [ 4066.950183] Lustre: DEBUG MARKER: == sanity test 104a: lfs df [-ih] [path] test =================================================================================== 02:15:52 (1788848152) [ 4067.600592] Lustre: setting import lustre-OST0000_UUID INACTIVE by administrator request [ 4067.642298] Lustre: lustre-OST0000-osc-ffff96274f06a000: Connection to lustre-OST0000 (at 192.168.204.108@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 4067.660200] LustreError: lustre-OST0000-osc-ffff96274f06a000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 4073.344932] Lustre: DEBUG MARKER: oleg408-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0000-osc-ffff96274f06a000.ost_server_uuid 50 [ 4075.244429] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff96274f06a000.ost_server_uuid in FULL state after 0 sec [ 4081.934975] Lustre: DEBUG MARKER: == sanity test 104b: runas -u 500 -g 500 lfs check servers test ============================================================================== 02:16:07 (1788848167) [ 4090.603645] Lustre: DEBUG MARKER: == sanity test 104c: Verify df vs lfs_df stays same after recordsize change ========================================================== 02:16:16 (1788848176) [ 4120.373173] Lustre: DEBUG MARKER: == sanity test 104d: runas -u 500 -g 500 lctl dl test ==== 02:16:45 (1788848205) [ 4128.198981] Lustre: DEBUG MARKER: == sanity test 105a: flock when mounted without -o flock test ================================================================== 02:16:53 (1788848213) [ 4136.482893] Lustre: DEBUG MARKER: == sanity test 105b: fcntl when mounted without -o flock test ================================================================== 02:17:02 (1788848222) [ 4145.201123] Lustre: DEBUG MARKER: == sanity test 105c: lockf when mounted without -o flock test ========================================================== 02:17:11 (1788848231) [ 4153.651547] Lustre: DEBUG MARKER: == sanity test 105d: flock race (should not freeze) ================================================================== 02:17:19 (1788848239) [ 4154.406637] LustreError: 110512:0:(ldlm_flock.c:850:ldlm_flock_completion_ast()) cfs_fail_timeout id 315 sleeping for 10000ms [ 4164.432136] LustreError: 110512:0:(ldlm_flock.c:850:ldlm_flock_completion_ast()) cfs_fail_timeout id 315 awake [ 4173.911967] Lustre: DEBUG MARKER: == sanity test 105e: Two conflicting flocks from same process ========================================================== 02:17:39 (1788848259) [ 4181.070864] Lustre: DEBUG MARKER: == sanity test 105f: Enqueue same range flocks =========== 02:17:47 (1788848267) [ 4191.528146] Lustre: DEBUG MARKER: == sanity test 105g: ldlm_lock_debug stack test ========== 02:17:57 (1788848277) [ 4192.134342] Lustre: *** cfs_fail_loc=32f, val=0*** [ 4192.136970] LustreError: 112341:0:(ldlm_flock.c:802:ldlm_flock_completion_ast()) ### Test ldlm error stack ns: lustre-MDT0000-mdc-ffff96274f06a000 lock: ffff96274f320e00/0xfb408b5cf44e0d66 lrc: 4/0,1 mode: PW/PW res: [0x200000409:0xb6a:0x0].0xc rrc: 2 type: FLK pid: 112340 [0->9223372036854775807] flags: 0x0 nid: local remote: 0x4ae8acec9d2b2a1c expref: -99 pid: 112341 timeout: 0 [ 4192.159772] CPU: 0 PID: 112341 Comm: flocks_test Kdump: loaded Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 4192.165331] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.17.0-10.fc44 06/10/2025 [ 4192.170730] Call Trace: [ 4192.174541] ? dump_stack+0xbb/0x10e [ 4192.179328] ? ldlm_flock_completion_ast.cold.17+0xd/0x27 [ptlrpc] [ 4192.184733] ? _raw_spin_unlock+0x12/0x30 [ 4192.186389] ? unlock_res_and_lock+0x23/0x30 [ptlrpc] [ 4192.191744] ? ldlm_lock_enqueue+0x3a1/0xcd0 [ptlrpc] [ 4192.198214] ? ldlm_cli_enqueue_fini+0xadc/0x1500 [ptlrpc] [ 4192.202295] ? ldlm_cli_enqueue+0x47f/0xe40 [ptlrpc] [ 4192.210428] ? ldlm_flock_completion_ast_async+0xb30/0xb30 [ptlrpc] [ 4192.221829] ? mdc_changelog_cdev_finish+0x2c0/0x2c0 [mdc] [ 4192.234620] ? mdc_enqueue_base+0x456/0x1dd0 [mdc] [ 4192.245610] ? mdc_enqueue+0x1c/0x30 [mdc] [ 4192.247420] ? lmv_enqueue+0x28a/0x530 [lmv] [ 4192.252654] ? ll_file_flock+0x962/0x1420 [lustre] [ 4192.254569] ? ldlm_flock_completion_ast_async+0xb30/0xb30 [ptlrpc] [ 4192.264791] ? mdc_changelog_cdev_finish+0x2c0/0x2c0 [mdc] [ 4192.271029] ? __mod_memcg_lruvec_state+0x5e/0x130 [ 4192.278626] ? __mod_lruvec_state+0x5a/0x80 [ 4192.286636] ? page_add_new_anon_rmap+0x77/0x1c0 [ 4192.288383] ? slab_post_alloc_hook+0x66/0x380 [ 4192.294819] ? locks_alloc_lock+0x1f/0x90 [ 4192.296970] ? kmem_cache_alloc+0x184/0x430 [ 4192.299808] ? vfs_lock_file+0x22/0x50 [ 4192.302615] ? fcntl_setlk+0xde/0x4e0 [ 4192.304816] ? __might_sleep+0x59/0xc0 [ 4192.306885] ? do_fcntl+0x7da/0xb80 [ 4192.309628] ? __x64_sys_fcntl+0xc4/0x110 [ 4192.313225] ? do_syscall_64+0xc1/0x440 [ 4192.315029] ? entry_SYSCALL_64_after_hwframe+0x49/0xae [ 4203.352996] Lustre: DEBUG MARKER: == sanity test 105h: Flock functional verify ============= 02:18:08 (1788848288) [ 4212.839548] Lustre: DEBUG MARKER: == sanity test 105i: Flock deadlock verify =============== 02:18:18 (1788848298) [ 4218.468024] LustreError: lustre-MDT0000-mdc-ffff96274f06a000: operation ldlm_enqueue to node 192.168.204.108@tcp failed: rc = -35 [ 4226.740683] Lustre: DEBUG MARKER: == sanity test 106: attempt exec of dir followed by chown of that dir ========================================================== 02:18:32 (1788848312) [ 4234.156085] Lustre: DEBUG MARKER: == sanity test 107: Coredump on SIG ====================== 02:18:39 (1788848319) [ 4243.512825] Lustre: DEBUG MARKER: == sanity test 110: filename length checking ============= 02:18:49 (1788848329) [ 4251.700041] Lustre: DEBUG MARKER: == sanity test 116a: stripe QOS: free space balance ============================================================================= 02:18:57 (1788848337) [ 4568.793709] Lustre: DEBUG MARKER: == sanity test 116b: QoS shouldn't LBUG if not enough OSTs found on the 2nd pass ========================================================== 02:24:14 (1788848654) [ 4584.118028] Lustre: DEBUG MARKER: == sanity test 117: verify osd extend ==================== 02:24:29 (1788848669) [ 4593.395587] Lustre: DEBUG MARKER: == sanity test 118a: verify O_SYNC works ================= 02:24:38 (1788848678) [ 4601.677281] Lustre: DEBUG MARKER: == sanity test 118b: Reclaim dirty pages on fatal error ==================================================================== 02:24:47 (1788848687) [ 4611.419641] Lustre: DEBUG MARKER: SKIP: sanity test_118c skipping ALWAYS excluded test 118c [ 4613.079277] Lustre: DEBUG MARKER: SKIP: sanity test_118d skipping ALWAYS excluded test 118d [ 4614.693551] Lustre: DEBUG MARKER: == sanity test 118f: Simulate unrecoverable OSC side error ==================================================================== 02:25:00 (1788848700) [ 4615.419880] Lustre: *** cfs_fail_loc=40a, val=0*** [ 4615.421560] Lustre: Skipped 193 previous similar messages [ 4615.424288] LustreError: 122028:0:(osc_request.c:2918:osc_build_rpc()) lustre-OST0001-osc-ffff96274f06a000: prep_req failed: rc = -22 [ 4615.432293] LustreError: 122028:0:(osc_cache.c:2365:osc_check_rpcs()) Write request failed with -22 [ 4622.769481] Lustre: DEBUG MARKER: == sanity test 118g: Don't stay in wait if we got local -ENOMEM ==================================================================== 02:25:08 (1788848708) [ 4623.204702] LustreError: 122618:0:(osc_request.c:2918:osc_build_rpc()) lustre-OST0000-osc-ffff96274f06a000: prep_req failed: rc = -12 [ 4623.211955] LustreError: 122618:0:(osc_cache.c:2365:osc_check_rpcs()) Write request failed with -12 [ 4631.502069] Lustre: DEBUG MARKER: == sanity test 118h: Verify timeout in handling recoverables errors ==================================================================== 02:25:17 (1788848717) [ 4633.785863] LustreError: lustre-OST0001-osc-ffff96274f06a000: operation ost_write to node 192.168.204.108@tcp failed: rc = -5 [ 4633.793990] LustreError: 2350:0:(osc_request.c:2451:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff96276663c700 x1875739050719616/t0(0) o4->lustre-OST0001-osc-ffff96274f06a000@192.168.204.108@tcp:6/4 lens 4584/224 e 0 to 0 dl 1788848737 ref 2 fl Interpret:RMQU/600/0 rc -5/-5 job:'multiop.0' uid:0 gid:0 projid:0 [ 4633.809958] LustreError: 2350:0:(osc_request.c:2451:osc_brw_redo_request()) Skipped 51 previous similar messages [ 4634.857621] LustreError: lustre-OST0001-osc-ffff96274f06a000: operation ost_write to node 192.168.204.108@tcp failed: rc = -5 [ 4636.912974] LustreError: lustre-OST0001-osc-ffff96274f06a000: operation ost_write to node 192.168.204.108@tcp failed: rc = -5 [ 4644.020085] LustreError: lustre-OST0001-osc-ffff96274f06a000: operation ost_write to node 192.168.204.108@tcp failed: rc = -5 [ 4644.029821] LustreError: Skipped 1 previous similar message [ 4644.033751] LustreError: 2351:0:(osc_request.c:2608:brw_interpret()) lustre-OST0001-osc-ffff96274f06a000: too many resent retries for object: 10737419264:6346: rc = -5 [ 4644.044424] LustreError: 2351:0:(osc_request.c:2608:brw_interpret()) Skipped 15 previous similar messages [ 4644.053305] Lustre: 2351:0:(llite_lib.c:4342:ll_dirty_page_discard_warn()) lustre: dirty page discard: 192.168.204.108@tcp:/lustre/fid: [0x200000409:0xf51:0x0]// may get corrupted (rc -5) [ 4653.224564] Lustre: DEBUG MARKER: == sanity test 118i: Fix error before timeout in recoverable error ==================================================================== 02:25:39 (1788848739) [ 4655.599446] LustreError: lustre-OST0001-osc-ffff96274f06a000: operation ost_write to node 192.168.204.108@tcp failed: rc = -5 [ 4655.605844] LustreError: 2350:0:(osc_request.c:2451:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff962871807b80 x1875739050727552/t0(0) o4->lustre-OST0001-osc-ffff96274f06a000@192.168.204.108@tcp:6/4 lens 4584/224 e 0 to 0 dl 1788848758 ref 2 fl Interpret:RMQU/600/0 rc -5/-5 job:'multiop.0' uid:0 gid:0 projid:0 [ 4655.620741] LustreError: 2350:0:(osc_request.c:2451:osc_brw_redo_request()) Skipped 3 previous similar messages [ 4672.746151] Lustre: DEBUG MARKER: == sanity test 118j: Simulate unrecoverable OST side error ==================================================================== 02:25:58 (1788848758) [ 4675.072283] LustreError: lustre-OST0001-osc-ffff96274f06a000: operation ost_write to node 192.168.204.108@tcp failed: rc = -14 [ 4675.081492] LustreError: Skipped 3 previous similar messages [ 4683.133899] Lustre: DEBUG MARKER: == sanity test 118k: bio alloc -ENOMEM and IO TERM handling =================================================================== 02:26:08 (1788848768) [ 4685.435158] LustreError: 2351:0:(osc_request.c:2451:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff962871805f80 x1875739050738944/t0(0) o4->lustre-OST0000-osc-ffff96274f06a000@192.168.204.108@tcp:6/4 lens 488/224 e 0 to 0 dl 1788848788 ref 2 fl Interpret:ReMQU/600/0 rc -5/-5 job:'dd.0' uid:0 gid:0 projid:0 [ 4685.457617] LustreError: 2351:0:(osc_request.c:2451:osc_brw_redo_request()) Skipped 3 previous similar messages [ 4704.800382] Lustre: DEBUG MARKER: == sanity test 118l: fsync dir =========================== 02:26:30 (1788848790) [ 4712.114120] Lustre: DEBUG MARKER: == sanity test 118m: fdatasync dir ======================= 02:26:37 (1788848797) [ 4719.603308] Lustre: DEBUG MARKER: == sanity test 118n: statfs() sends OST_STATFS requests in parallel ========================================================== 02:26:45 (1788848805) [ 4731.326444] Lustre: DEBUG MARKER: == sanity test 119a: Short directIO read must return actual read amount ========================================================== 02:26:57 (1788848817) [ 4739.455923] Lustre: DEBUG MARKER: == sanity test 119b: Sparse directIO read must return actual read amount ========================================================== 02:27:04 (1788848824) [ 4747.978776] Lustre: DEBUG MARKER: == sanity test 119c: Testing for direct read hitting hole ========================================================== 02:27:13 (1788848833) [ 4757.087227] Lustre: DEBUG MARKER: == sanity test 119e: Basic tests of dio read and write at various sizes ========================================================== 02:27:22 (1788848842) [ 4806.267369] Lustre: DEBUG MARKER: == sanity test 119f: dio vs dio race ===================== 02:28:12 (1788848892) [ 4851.146130] Lustre: DEBUG MARKER: == sanity test 119g: dio vs buffered I/O race ============ 02:28:57 (1788848937) [ 4896.208700] Lustre: DEBUG MARKER: == sanity test 119h: basic tests of memory unaligned dio ========================================================== 02:29:41 (1788848981) [ 4927.577295] Lustre: DEBUG MARKER: SKIP: sanity test_119i skipping ALWAYS excluded test 119i [ 4929.737838] Lustre: DEBUG MARKER: == sanity test 119j: basic tests of hybrid IO switching == 02:30:15 (1788849015) [ 4930.490603] Lustre: *** cfs_fail_loc=1429, val=0*** [ 4938.795629] Lustre: DEBUG MARKER: == sanity test 119k: hybrid IO counting with stats and disabling ========================================================== 02:30:24 (1788849024) [ 4958.235346] Lustre: DEBUG MARKER: == sanity test 119m: Test DIO readv/writev: exercise iter duplication ========================================================== 02:30:44 (1788849044) [ 4964.551568] Lustre: DEBUG MARKER: == sanity test 119n: Test Unaligned DIO readv() and writev() with unpatched ZFS ========================================================== 02:30:50 (1788849050) [ 4965.956735] Lustre: DEBUG MARKER: SKIP: sanity test_119n zfs server without 'unaligned_dio' support [ 4967.537972] Lustre: DEBUG MARKER: == sanity test 119o: Test Unaligned DIO readv() and writev() with unpatched servers ========================================================== 02:30:53 (1788849053) [ 4968.993539] Lustre: DEBUG MARKER: SKIP: sanity test_119o need ldiskfs without 'unaligned_dio' support [ 4970.869446] Lustre: DEBUG MARKER: == sanity test 119p: Test Unaligned DIO readv() and writev() with patched servers ========================================================== 02:30:56 (1788849056) [ 4978.918987] Lustre: DEBUG MARKER: == sanity test 119q: Test patchded Unaligned DIO readv() and writev() ========================================================== 02:31:04 (1788849064) [ 4996.189381] Lustre: DEBUG MARKER: == sanity test 119r: Test error handling in unaligned DIO user copy ========================================================== 02:31:21 (1788849081) [ 4997.033505] Lustre: *** cfs_fail_loc=1437, val=0*** [ 4997.037421] LustreError: 109490:0:(osc_cache.c:2365:osc_check_rpcs()) Write request failed with -14 [ 5004.197208] Lustre: DEBUG MARKER: == sanity test 119s: full-size unaligned DIO packs matching bulk MDs ========================================================== 02:31:30 (1788849090) [ 5006.262488] Lustre: DEBUG MARKER: SKIP: sanity test_119s need client page size larger than the server's [ 5008.746259] Lustre: DEBUG MARKER: == sanity test 120a: Early Lock Cancel: mkdir test ======= 02:31:34 (1788849094) [ 5018.620785] Lustre: DEBUG MARKER: == sanity test 120b: Early Lock Cancel: create test ====== 02:31:44 (1788849104) [ 5028.203983] Lustre: DEBUG MARKER: == sanity test 120c: Early Lock Cancel: link test ======== 02:31:54 (1788849114) [ 5036.842478] Lustre: DEBUG MARKER: == sanity test 120d: Early Lock Cancel: setattr test ===== 02:32:03 (1788849123) [ 5045.157976] Lustre: DEBUG MARKER: == sanity test 120e: Early Lock Cancel: unlink test ====== 02:32:11 (1788849131) [ 5063.645884] Lustre: DEBUG MARKER: == sanity test 120f: Early Lock Cancel: rename test ====== 02:32:29 (1788849149) [ 5081.033636] Lustre: DEBUG MARKER: == sanity test 120g: Early Lock Cancel: performance test ========================================================== 02:32:46 (1788849166) [ 5557.930889] Lustre: DEBUG MARKER: == sanity test 121: read cancel race ===================== 02:40:44 (1788849644) [ 5558.187087] Lustre: *** cfs_fail_loc=310, val=0*** [ 5564.035330] Lustre: DEBUG MARKER: == sanity test 123aa: verify statahead work ============== 02:40:50 (1788849650) [ 5573.549987] Lustre: DEBUG MARKER: 'ls -l' 100 files without statahead: 2 sec [ 5575.960426] Lustre: DEBUG MARKER: 'ls -l' 100 files with statahead: 0 sec [ 5617.631826] Lustre: DEBUG MARKER: 'ls -l' 1000 files without statahead: 22 sec [ 5625.902954] Lustre: DEBUG MARKER: 'ls -l' 1000 files with statahead: 5 sec [ 5627.328329] Lustre: DEBUG MARKER: 'ls -l' done [ 5645.118502] Lustre: DEBUG MARKER: unlink + rm -r /mnt/lustre/d123aa.sanity: 17 seconds [ 5654.336287] Lustre: DEBUG MARKER: == sanity test 123ab: verify statahead work by using statx ========================================================== 02:42:20 (1788849740) [ 5662.600361] Lustre: DEBUG MARKER: 'statx -l' 100 files without statahead: 2 sec [ 5664.871984] Lustre: DEBUG MARKER: 'statx -l' 100 files with statahead: 0 sec [ 5702.359867] Lustre: DEBUG MARKER: 'statx -l' 1000 files without statahead: 20 sec [ 5709.171801] Lustre: DEBUG MARKER: 'statx -l' 1000 files with statahead: 5 sec [ 5710.670306] Lustre: DEBUG MARKER: 'statx -l' done [ 5727.944484] Lustre: DEBUG MARKER: unlink + rm -r /mnt/lustre/d123ab.sanity: 16 seconds [ 5737.183572] Lustre: DEBUG MARKER: == sanity test 123ac: verify statahead work by using statx without glimpse RPCs ========================================================== 02:43:43 (1788849823) [ 5744.310288] Lustre: DEBUG MARKER: 'statx -c 0 [ 5746.111399] Lustre: DEBUG MARKER: 'statx -c 0 [ 5772.506651] Lustre: DEBUG MARKER: 'statx -c 0 [ 5779.425118] Lustre: DEBUG MARKER: 'statx -c 0 [ 5780.839666] Lustre: DEBUG MARKER: 'statx -c 0 [ 5798.097491] Lustre: DEBUG MARKER: unlink + rm -r /mnt/lustre/d123ac.sanity: 16 seconds [ 5803.916440] Lustre: DEBUG MARKER: 'statx --cached=always -D' 100 files without statahead: 0 sec [ 5805.491748] Lustre: DEBUG MARKER: 'statx --cached=always -D' 100 files with statahead: 0 sec [ 5823.141676] Lustre: DEBUG MARKER: 'statx --cached=always -D' 1000 files without statahead: 0 sec [ 5824.769760] Lustre: DEBUG MARKER: 'statx --cached=always -D' 1000 files with statahead: 0 sec [ 5946.571741] Lustre: DEBUG MARKER: 'statx --cached=always -D' 10000 files without statahead: 0 sec [ 5948.136796] Lustre: DEBUG MARKER: 'statx --cached=always -D' 10000 files with statahead: 0 sec [ 5949.387528] Lustre: DEBUG MARKER: 'statx --cached=always -D' done [ 6156.986666] Lustre: DEBUG MARKER: unlink + rm -r /mnt/lustre/d123ac.sanity: 207 seconds [ 6165.856925] Lustre: DEBUG MARKER: == sanity test 123ad: Verify batching statahead works correctly ========================================================== 02:50:52 (1788850252) [ 6171.814337] Lustre: DEBUG MARKER: 'ls -l' 100 files without statahead: 2 sec [ 6173.549396] Lustre: DEBUG MARKER: 'ls -l' 100 files with statahead: 0 sec [ 6200.343084] Lustre: DEBUG MARKER: 'ls -l' 1000 files without statahead: 14 sec [ 6207.462519] Lustre: DEBUG MARKER: 'ls -l' 1000 files with statahead: 5 sec [ 6208.369386] Lustre: DEBUG MARKER: 'ls -l' done [ 6220.786331] Lustre: DEBUG MARKER: unlink + rm -r /mnt/lustre/d123ad.sanity: 12 seconds [ 6595.644599] Lustre: DEBUG MARKER: 'ls -l' 100 files without statahead: 3 sec [ 6602.101074] Lustre: DEBUG MARKER: 'ls -l' 100 files with statahead: 2 sec [ 6664.661335] Lustre: DEBUG MARKER: 'ls -l' 1000 files without statahead: 23 sec [ 6673.578087] Lustre: DEBUG MARKER: 'ls -l' 1000 files with statahead: 6 sec [ 6675.085671] Lustre: DEBUG MARKER: 'ls -l' done [ 6698.592791] Lustre: DEBUG MARKER: unlink + rm -r /mnt/lustre/d123ad.sanity: 22 seconds [ 7216.082859] Lustre: DEBUG MARKER: == sanity test 123b: not panic with network error in statahead enqueue (bug 15027) ========================================================== 03:08:22 (1788851302) [ 7242.989286] Lustre: DEBUG MARKER: ls done [ 7272.591704] Lustre: DEBUG MARKER: == sanity test 123c: Can not initialize inode warning on DNE statahead ========================================================== 03:09:18 (1788851358) [ 7274.280442] Lustre: DEBUG MARKER: SKIP: sanity test_123c needs >= 2 MDTs [ 7276.243372] Lustre: DEBUG MARKER: == sanity test 123d: Statahead on striped directories works correctly ========================================================== 03:09:22 (1788851362) [ 7280.804598] Lustre: Unmounted lustre-client [ 7281.276432] Lustre: Mounted lustre-client - version 2.17.57_111_g33f3974 [ 7293.001233] Lustre: DEBUG MARKER: == sanity test 123e: statahead with large wide striping == 03:09:38 (1788851378) [ 7613.586955] Lustre: DEBUG MARKER: == sanity test 123f: Retry mechanism with large wide striping files ========================================================== 03:14:59 (1788851699) [ 9008.434543] Lustre: DEBUG MARKER: == sanity test 123g: Test for stat-ahead advise ========== 03:38:13 (1788853093) [ 9096.484317] Lustre: DEBUG MARKER: == sanity test 123h: Verify statahead work with the fname pattern via du ========================================================== 03:39:41 (1788853181) [10936.632944] Lustre: DEBUG MARKER: == sanity test 123i: Verify statahead work with the fname indexing pattern ========================================================== 04:10:22 (1788855022) [11075.000516] Lustre: DEBUG MARKER: == sanity test 123j: -ENOENT error from batched statahead be handled correctly ========================================================== 04:12:40 (1788855160) [11076.710153] Lustre: DEBUG MARKER: SKIP: sanity test_123j needs >= 2 MDTs [11078.567107] Lustre: DEBUG MARKER: == sanity test 123k: Verify statahead work with mdtest shared stat() mode ========================================================== 04:12:44 (1788855164) [11080.627502] Lustre: DEBUG MARKER: SKIP: sanity test_123k mdtest not found [11082.748802] Lustre: DEBUG MARKER: == sanity test 123l: Avoid panic when revalidate a local cached entry ========================================================== 04:12:48 (1788855168) [11088.904408] LustreError: 177517:0:(statahead.c:360:sa_put()) cfs_fail_timeout id 1433 sleeping for 35000ms [11123.920126] LustreError: 177517:0:(statahead.c:360:sa_put()) cfs_fail_timeout id 1433 awake [11165.364486] Lustre: DEBUG MARKER: == sanity test 124a: lru resize ================================================================================================= 04:14:11 (1788855251) [11167.261995] Lustre: DEBUG MARKER: create 2000 files at /mnt/lustre/d124a.sanity [11215.288252] Lustre: DEBUG MARKER: NSDIR=ldlm.namespaces.lustre-MDT0000-mdc-ffff9627488d0000 [11217.314193] Lustre: DEBUG MARKER: NS=ldlm.namespaces.lustre-MDT0000-mdc-ffff9627488d0000 [11218.824519] Lustre: DEBUG MARKER: LRU=2003 [11220.296321] Lustre: DEBUG MARKER: LIMIT=61549 [11221.807373] Lustre: DEBUG MARKER: LVF=3687400 [11223.560760] Lustre: DEBUG MARKER: OLD_LVF=100 [11225.382590] Lustre: DEBUG MARKER: Sleep 50 sec [11277.398279] Lustre: DEBUG MARKER: Dropped 1065 locks in 50s [11279.853807] Lustre: DEBUG MARKER: unlink 2000 files at /mnt/lustre/d124a.sanity [11320.522790] Lustre: DEBUG MARKER: == sanity test 124b: lru resize (performance test) ================================================================================= 04:16:46 (1788855406) [11445.768257] Lustre: DEBUG MARKER: doing ls -la /mnt/lustre/d124b.sanity/disable_lru_resize 3 times [11620.951583] Lustre: DEBUG MARKER: ls -la time: 173 seconds [11623.159551] Lustre: DEBUG MARKER: lru_size = 400 [11886.846828] Lustre: DEBUG MARKER: doing ls -la /mnt/lustre/d124b.sanity/enable_lru_resize 3 times [11983.249859] Lustre: DEBUG MARKER: ls -la time: 89 seconds [11985.858893] Lustre: DEBUG MARKER: lru_size = 8008 [11987.627197] Lustre: DEBUG MARKER: ls -la is 48% faster with lru resize enabled [12077.629946] Lustre: DEBUG MARKER: == sanity test 124c: LRUR cancel very aged locks ========= 04:29:22 (1788856162) [12113.188110] Lustre: DEBUG MARKER: == sanity test 124d: cancel very aged locks if lru-resize disabled ========================================================== 04:29:58 (1788856198) [12148.401714] Lustre: DEBUG MARKER: == sanity test 124e: LFRU keep priv locks from eviction == 04:30:34 (1788856234) [12204.196682] Lustre: DEBUG MARKER: == sanity test 124f: LFRU priv threshold inc/dec adjustment ========================================================== 04:31:29 (1788856289) [12300.280585] Lustre: DEBUG MARKER: == sanity test 124g: LFRU performance test =============== 04:33:05 (1788856385) [13291.261819] Lustre: DEBUG MARKER: == sanity test 125: don't return EPROTO when a dir has a non-default striping and ACLs ========================================================== 04:49:37 (1788857377) [13298.077756] Lustre: DEBUG MARKER: == sanity test 126: check that the fsgid provided by the client is taken into account ========================================================== 04:49:44 (1788857384) [13305.131735] Lustre: DEBUG MARKER: == sanity test 127a: verify the client stats are sane ==== 04:49:50 (1788857390) [13313.974158] Lustre: DEBUG MARKER: == sanity test 127b: verify the llite client stats are sane ========================================================== 04:49:59 (1788857399) [13320.887636] Lustre: DEBUG MARKER: == sanity test 127c: test llite extent stats with regular [13363.430244] Lustre: DEBUG MARKER: == sanity test 127d: OSC RPC latency histograms for read and write latency ========================================================== 04:50:48 (1788857448) [13375.610585] Lustre: DEBUG MARKER: == sanity test 127e: client IO latency histograms by size ========================================================== 04:51:01 (1788857461) [13395.186551] Lustre: DEBUG MARKER: == sanity test 127f: OST IO latency histograms by size === 04:51:20 (1788857480) [13396.725545] Lustre: DEBUG MARKER: SKIP: sanity test_127f ldiskfs only [13398.702970] Lustre: DEBUG MARKER: == sanity test 127g: cached_read_bytes tracks page cache hits ========================================================== 04:51:24 (1788857484) [13400.977529] bash (221164): drop_caches: 3 [13402.117862] bash (221164): drop_caches: 3 [13403.879607] bash (221164): drop_caches: 3 [13412.642412] Lustre: DEBUG MARKER: == sanity test 128: interactive lfs for 2 consecutive find's ========================================================== 04:51:38 (1788857498) [13420.032407] Lustre: DEBUG MARKER: == sanity test 129: test directory size limit ================================================================================== 04:51:45 (1788857505) [13421.736037] Lustre: DEBUG MARKER: SKIP: sanity test_129 ldiskfs only test [13423.689373] Lustre: DEBUG MARKER: == sanity test 130a: FIEMAP (1-stripe file) ============== 04:51:49 (1788857509) [13425.424299] Lustre: DEBUG MARKER: SKIP: sanity test_130a LU-1941: FIEMAP unimplemented on ZFS [13427.577180] Lustre: DEBUG MARKER: SKIP: sanity test_130b skipping ALWAYS excluded test 130b [13429.217309] Lustre: DEBUG MARKER: SKIP: sanity test_130c skipping ALWAYS excluded test 130c [13431.038402] Lustre: DEBUG MARKER: SKIP: sanity test_130d skipping ALWAYS excluded test 130d [13432.659238] Lustre: DEBUG MARKER: SKIP: sanity test_130e skipping ALWAYS excluded test 130e [13434.030481] Lustre: DEBUG MARKER: SKIP: sanity test_130f skipping ALWAYS excluded test 130f [13435.607583] Lustre: DEBUG MARKER: SKIP: sanity test_130g skipping ALWAYS excluded test 130g [13437.494801] Lustre: DEBUG MARKER: == sanity test 130h: FIEMAP deadlock ===================== 04:52:03 (1788857523) [13439.701839] LustreError: 223959:0:(osc_object.c:271:osc_object_fiemap()) cfs_fail_timeout id 418 sleeping for 5000ms [13444.722414] LustreError: 223959:0:(osc_object.c:271:osc_object_fiemap()) cfs_fail_timeout id 418 awake [13452.743500] Lustre: DEBUG MARKER: == sanity test 130i: FIEMAP (DoM file) =================== 04:52:18 (1788857538) [13454.518557] Lustre: DEBUG MARKER: SKIP: sanity test_130i LU-1941: FIEMAP unimplemented on ZFS [13456.828353] Lustre: DEBUG MARKER: == sanity test 131a: test iov's crossing stripe boundary for writev/readv ========================================================== 04:52:22 (1788857542) [13465.829449] Lustre: DEBUG MARKER: == sanity test 131b: test append writev ================== 04:52:31 (1788857551) [13473.860566] Lustre: DEBUG MARKER: == sanity test 131c: test read/write on file w/o objects ========================================================== 04:52:39 (1788857559) [13481.478852] Lustre: DEBUG MARKER: == sanity test 131d: test short read ===================== 04:52:47 (1788857567) [13488.952476] Lustre: DEBUG MARKER: == sanity test 131e: test read hitting hole ============== 04:52:54 (1788857574) [13496.122575] Lustre: DEBUG MARKER: == sanity test 133a: Verifying MDT stats ================================================================================================== 04:53:01 (1788857581) [13521.371441] Lustre: DEBUG MARKER: == sanity test 133b: Verifying extra MDT stats ============================================================================================ 04:53:27 (1788857607) [13545.196896] Lustre: DEBUG MARKER: == sanity test 133c: Verifying OST stats ================================================================================================== 04:53:50 (1788857630) [13592.072511] Lustre: DEBUG MARKER: == sanity test 133d: Verifying rename_stats ================================================================================================== 04:54:38 (1788857678) [13630.210337] Lustre: DEBUG MARKER: == sanity test 133e: Verifying OST read_bytes write_bytes nid stats =========================================================================== 04:55:15 (1788857715) [13642.312719] Lustre: DEBUG MARKER: == sanity test 133f: Check reads/writes of client lustre proc files with bad area io ========================================================== 04:55:28 (1788857728) [13644.602618] LNet: 232253:0:(debug.c:375:cfs_str2mask()) unknown mask ''. [13644.602618] mask usage: [+|-] ... [13645.031524] Lustre: DEBUG MARKER:  [13645.033294] Lustre: DEBUG MARKER:  [13645.210792] LNet: 232320:0:(debug.c:375:cfs_str2mask()) unknown mask ''. [13645.210792] mask usage: [+|-] ... [13645.237462] LNet: 232320:0:(debug.c:375:cfs_str2mask()) Skipped 6 previous similar messages [13660.728161] Lustre: Unmounted lustre-client [13696.858939] Key type lgssc unregistered [13697.100854] LNet: 233284:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [13697.110970] LNetError: 233284:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [13697.130761] LNet: Removed LNI 192.168.204.8@tcp [13698.440189] Key type .llcrypt unregistered [13698.442252] Key type ._llcrypt unregistered [13706.891199] Key type ._llcrypt registered [13706.895193] Key type .llcrypt registered [13707.478831] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [13707.497528] alg: No test for adler32 (adler32-zlib) [13708.928140] Lustre: Lustre: Build Version: 2.17.57_111_g33f3974 [13709.841811] LNet: Added LNI 192.168.204.8@tcp [8/256/0/180] [13711.600440] Key type lgssc registered [13713.243113] Lustre: Echo OBD driver; http://www.lustre.org/ [13791.987928] Lustre: Mounted lustre-client - version 2.17.57_111_g33f3974 [13797.532334] Lustre: DEBUG MARKER: Using TIMEOUT=20 [13810.154670] Lustre: DEBUG MARKER: == sanity test 133g: Check reads/writes of server lustre proc files with bad area io ========================================================== 04:58:15 (1788857895) [13817.825624] Lustre: lustre-OST0000-osc-ffff96276955a800: disconnect after 24s idle [13892.675382] Lustre: Unmounted lustre-client [13912.448416] Key type lgssc unregistered [13912.720934] LNet: 237051:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [13912.730243] LNetError: 237051:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [13912.767676] LNet: Removed LNI 192.168.204.8@tcp [13913.741156] Key type .llcrypt unregistered [13913.749285] Key type ._llcrypt unregistered [13927.569335] Key type ._llcrypt registered [13927.571028] Key type .llcrypt registered [13928.027992] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [13928.053313] alg: No test for adler32 (adler32-zlib) [13929.383840] Lustre: Lustre: Build Version: 2.17.57_111_g33f3974 [13929.916873] LNet: Added LNI 192.168.204.8@tcp [8/256/0/180] [13931.688374] Key type lgssc registered [13933.624161] Lustre: Echo OBD driver; http://www.lustre.org/ [14019.272553] Lustre: Mounted lustre-client - version 2.17.57_111_g33f3974 [14024.896024] Lustre: DEBUG MARKER: Using TIMEOUT=20 [14035.956754] Lustre: DEBUG MARKER: == sanity test 133h: Proc files should end with newlines ========================================================== 05:02:01 (1788858121) [14045.154241] Lustre: lustre-OST0000-osc-ffff9628548a4800: disconnect after 23s idle [14075.873439] Lustre: lustre-OST0000-osc-ffff9628548a4800: disconnect after 24s idle [14075.878576] Lustre: Skipped 1 previous similar message [14101.474781] Lustre: lustre-OST0000-osc-ffff9628548a4800: disconnect after 21s idle [14101.492337] Lustre: Skipped 1 previous similar message [14106.592581] Lustre: lustre-OST0001-osc-ffff9628548a4800: disconnect after 23s idle [15001.087537] Lustre: DEBUG MARKER: == sanity test 134a: Server reclaims locks when reaching lock_reclaim_threshold ========================================================== 05:18:07 (1788859087) [15058.915147] Lustre: lustre-OST0000-osc-ffff9628548a4800: disconnect after 22s idle [15059.544355] Lustre: DEBUG MARKER: == sanity test 134b: Server rejects lock request when reaching lock_limit_mb ========================================================== 05:19:05 (1788859145) [15104.117136] Lustre: DEBUG MARKER: == sanity test 134c: Lock memory accounting includes associated structures ========================================================== 05:19:49 (1788859189) [15119.818716] Lustre: DEBUG MARKER: SKIP: sanity test_135 skipping SLOW test 135 [15121.629654] Lustre: DEBUG MARKER: SKIP: sanity test_136 skipping SLOW test 136 [15123.873811] Lustre: DEBUG MARKER: == sanity test 140: Check reasonable stack depth (shouldn't LBUG) ============================================================== 05:20:09 (1788859209) [15165.416609] Lustre: DEBUG MARKER: == sanity test 150a: truncate/append tests =============== 05:20:51 (1788859251) [15186.912404] Lustre: lustre-OST0001-osc-ffff9628548a4800: disconnect after 21s idle [15188.179673] Lustre: Unmounted lustre-client [15188.656759] Lustre: Mounted lustre-client - version 2.17.57_111_g33f3974 [15218.614966] Lustre: DEBUG MARKER: == sanity test 150b: Verify fallocate (prealloc) functionality ========================================================== 05:21:44 (1788859304) [15225.184803] Lustre: DEBUG MARKER: SKIP: sanity test_150b fallocate failed, error Operation not supported, mode 0, offset 41943040, len 4194304|check_fallocate failed [15248.817340] Lustre: DEBUG MARKER: == sanity test 150bb: Verify fallocate modes both zero space ========================================================== 05:22:14 (1788859334) [15251.168365] Lustre: DEBUG MARKER: SKIP: sanity test_150bb fallocate not supported [15253.190191] Lustre: DEBUG MARKER: == sanity test 150c: Verify fallocate Size and Blocks ==== 05:22:18 (1788859338) [15255.665235] Lustre: DEBUG MARKER: SKIP: sanity test_150c fallocate not supported [15257.457036] Lustre: DEBUG MARKER: == sanity test 150d: Verify fallocate Size and Blocks - Non zero start ========================================================== 05:22:23 (1788859343) [15260.276240] Lustre: DEBUG MARKER: SKIP: sanity test_150d fallocate not supported [15262.148450] Lustre: DEBUG MARKER: == sanity test 150e: Verify 60% of available OST space consumed by fallocate ========================================================== 05:22:27 (1788859347) [15264.573154] Lustre: DEBUG MARKER: SKIP: sanity test_150e fallocate not supported [15266.370393] Lustre: DEBUG MARKER: == sanity test 150f: Verify fallocate punch functionality ========================================================== 05:22:32 (1788859352) [15326.639106] Lustre: DEBUG MARKER: == sanity test 150g: Verify fallocate punch on large range ========================================================== 05:23:32 (1788859412) [15331.306897] Lustre: DEBUG MARKER: SKIP: sanity test_150g fallocate not supported [15333.887823] Lustre: DEBUG MARKER: == sanity test 150h: Verify extend fallocate updates the file size ========================================================== 05:23:39 (1788859419) [15337.300748] Lustre: DEBUG MARKER: SKIP: sanity test_150h fallocate not supported [15338.953137] Lustre: DEBUG MARKER: == sanity test 150ia: Verify fallocate zero-range ZERO functionality ========================================================== 05:23:44 (1788859424) [15340.536921] Lustre: DEBUG MARKER: SKIP: sanity test_150ia zero-range mode is not implemented on OSD ZFS [15342.436702] Lustre: DEBUG MARKER: == sanity test 150ib: Verify fallocate zero-range PREALLOC functionality ========================================================== 05:23:48 (1788859428) [15344.450210] Lustre: DEBUG MARKER: SKIP: sanity test_150ib zero-range mode is not implemented on OSD ZFS [15346.304182] Lustre: DEBUG MARKER: == sanity test 150ic: Verify fallocate LARGE zero PREALLOC functionality ========================================================== 05:23:52 (1788859432) [15347.715162] Lustre: DEBUG MARKER: SKIP: sanity test_150ic zero-range mode is not implemented on OSD ZFS [15349.573683] Lustre: DEBUG MARKER: == sanity test 150id: fallocate that fails must not leave a dirty page behind ========================================================== 05:23:55 (1788859435) [15351.542442] Lustre: DEBUG MARKER: SKIP: sanity test_150id fallocate zero-range is ldiskfs only [15353.173461] Lustre: DEBUG MARKER: == sanity test 151: test cache on oss and controls ========================================================================================= 05:23:59 (1788859439) [15356.451697] Lustre: DEBUG MARKER: SKIP: sanity test_151 not cache-capable obdfilter [15358.225949] Lustre: DEBUG MARKER: == sanity test 152: test read/write with enomem ====================================================================================== 05:24:04 (1788859444) [15364.796476] Lustre: DEBUG MARKER: == sanity test 153: test if fdatasync does not crash ================================================================================= 05:24:10 (1788859450) [15371.562518] Lustre: DEBUG MARKER: == sanity test 154A: lfs path2fid and fid2path basic checks ========================================================== 05:24:17 (1788859457) [15378.487211] Lustre: DEBUG MARKER: == sanity test 154B: verify the ll_decode_linkea tool ==== 05:24:24 (1788859464) [15385.423938] Lustre: DEBUG MARKER: == sanity test 154C: lfs fid2path on OST FID ============= 05:24:31 (1788859471) [15419.758464] Lustre: DEBUG MARKER: == sanity test 154a: Open-by-FID ========================= 05:25:05 (1788859505) [15431.792715] Lustre: DEBUG MARKER: == sanity test 154b: Open-by-FID for remote directory ==== 05:25:17 (1788859517) [15433.364108] Lustre: DEBUG MARKER: SKIP: sanity test_154b needs >= 2 MDTs [15435.747199] Lustre: DEBUG MARKER: == sanity test 154c: lfs path2fid and fid2path multiple arguments ========================================================== 05:25:21 (1788859521) [15443.441242] Lustre: DEBUG MARKER: == sanity test 154d: Verify open file fid ================ 05:25:29 (1788859529) [15453.217330] Lustre: DEBUG MARKER: == sanity test 154db: fid is stored in dir entries ======= 05:25:38 (1788859538) [15454.991531] Lustre: DEBUG MARKER: SKIP: sanity test_154db ldiskfs only test [15457.201660] Lustre: DEBUG MARKER: == sanity test 154e: .lustre is not returned by readdir == 05:25:42 (1788859542) [15464.173623] Lustre: DEBUG MARKER: == sanity test 154ea: .lustre is not returned by readdir (2) ========================================================== 05:25:49 (1788859549) [15520.689566] Lustre: DEBUG MARKER: == sanity test 154f: get parent fids by reading link ea == 05:26:46 (1788859606) [15530.688962] Lustre: DEBUG MARKER: == sanity test 154g: various llapi FID tests ============= 05:26:56 (1788859616) [16795.647806] Lustre: DEBUG MARKER: == sanity test 154h: Verify interactive path2fid ========= 05:48:01 (1788860881) [16803.362820] Lustre: DEBUG MARKER: == sanity test 154i: fid2path for path longer than PATH_MAX ========================================================== 05:48:09 (1788860889) [16842.787856] Lustre: DEBUG MARKER: == sanity test 154j: fid2path for long path crossing MDT boundary ========================================================== 05:48:48 (1788860928) [16844.678956] Lustre: DEBUG MARKER: SKIP: sanity test_154j needs >= 2 MDTs [16847.121840] Lustre: DEBUG MARKER: == sanity test 155a: Verify small file correctness: read cache:on write_cache:on ========================================================== 05:48:52 (1788860932) [16862.085793] Lustre: DEBUG MARKER: == sanity test 155b: Verify small file correctness: read cache:on write_cache:off ========================================================== 05:49:07 (1788860947) [16875.443291] Lustre: DEBUG MARKER: == sanity test 155c: Verify small file correctness: read cache:off write_cache:on ========================================================== 05:49:21 (1788860961) [16887.404128] Lustre: DEBUG MARKER: == sanity test 155d: Verify small file correctness: read cache:off write_cache:off ========================================================== 05:49:33 (1788860973) [16901.191799] Lustre: DEBUG MARKER: == sanity test 155e: Verify big file correctness: read cache:on write_cache:on ========================================================== 05:49:47 (1788860987) [16956.247415] Lustre: DEBUG MARKER: == sanity test 155f: Verify big file correctness: read cache:on write_cache:off ========================================================== 05:50:42 (1788861042) [17010.608373] Lustre: DEBUG MARKER: == sanity test 155g: Verify big file correctness: read cache:off write_cache:on ========================================================== 05:51:36 (1788861096) [17073.206811] Lustre: DEBUG MARKER: == sanity test 155h: Verify big file correctness: read cache:off write_cache:off ========================================================== 05:52:39 (1788861159) [17125.949652] Lustre: DEBUG MARKER: == sanity test 156: Verification of tunables ============= 05:53:31 (1788861211) [17127.821285] Lustre: DEBUG MARKER: SKIP: sanity test_156 LU-1956/LU-2261: stats not implemented on OSD ZFS [17129.618188] Lustre: DEBUG MARKER: == sanity test 157a: llapi pool pinning API tests ======== 05:53:35 (1788861215) [17137.237936] Lustre: DEBUG MARKER: == sanity test 157b: lustre.pin inheritance on create ==== 05:53:43 (1788861223) [17145.144476] Lustre: DEBUG MARKER: == sanity test 160a: changelog sanity ==================== 05:53:51 (1788861231) [17164.275329] Lustre: lustre-MDT0000-mdc-ffff9627678d0800: Connection to lustre-MDT0000 (at 192.168.204.108@tcp) was lost; in progress operations using this service will wait for recovery to complete [17174.512496] LustreError: MGC192.168.204.108@tcp: Connection to MGS (at 192.168.204.108@tcp) was lost; in progress operations using this service will fail [17174.560104] Lustre: Evicted from MGS (at 192.168.204.108@tcp) after server handle changed from 0x23583c4770ff883a to 0x23583c477108a8f1 [17174.578328] Lustre: MGC192.168.204.108@tcp: Connection restored to 192.168.204.108@tcp (at 192.168.204.108@tcp) [17183.861588] LustreError: 237381:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff96287ef4c380 x1875753586831744/t12884908728(12884908728) o101->lustre-MDT0000-mdc-ffff9627678d0800@192.168.204.108@tcp:12/10 lens 968/608 e 0 to 0 dl 1788861287 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'lfs.0' uid:0 gid:0 projid:0 [17184.365432] LustreError: 237381:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff96287e3e9500 x1875753593614336/t12884924448(12884924448) o101->lustre-MDT0000-mdc-ffff9627678d0800@192.168.204.108@tcp:12/10 lens 968/608 e 0 to 0 dl 1788861287 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'bash.0' uid:0 gid:0 projid:0 [17184.398463] LustreError: 237381:0:(client.c:3448:ptlrpc_replay_interpret()) Skipped 65 previous similar messages [17184.883924] Lustre: lustre-MDT0000-mdc-ffff9627678d0800: Connection restored to 192.168.204.108@tcp (at 192.168.204.108@tcp) [17199.601790] Lustre: DEBUG MARKER: == sanity test 160b: Verify that very long rename doesn't crash in changelog ========================================================== 05:54:44 (1788861284) [17214.806420] Lustre: DEBUG MARKER: == sanity test 160c: verify that changelog log catch the truncate event ========================================================== 05:55:00 (1788861300) [17232.358461] Lustre: DEBUG MARKER: == sanity test 160d: verify that changelog log catch the migrate event ========================================================== 05:55:18 (1788861318) [17234.311828] Lustre: DEBUG MARKER: SKIP: sanity test_160d needs >= 2 MDTs [17236.147733] Lustre: DEBUG MARKER: == sanity test 160e: changelog negative testing (should return errors) ========================================================== 05:55:21 (1788861321) [17252.415753] Lustre: DEBUG MARKER: == sanity test 160f: changelog garbage collect (timestamped users) ========================================================== 05:55:38 (1788861338) [17260.774039] Lustre: DEBUG MARKER: 1788861346: creating first dirs [17303.208051] Lustre: DEBUG MARKER: == sanity test 160g: changelog garbage collect on idle records ========================================================== 05:56:28 (1788861388) [17343.077925] Lustre: DEBUG MARKER: == sanity test 160h: changelog gc thread stop upon umount, orphan records delete ========================================================== 05:57:09 (1788861429) [17378.297079] Lustre: lustre-MDT0000-mdc-ffff9627678d0800: Connection to lustre-MDT0000 (at 192.168.204.108@tcp) was lost; in progress operations using this service will wait for recovery to complete [17393.648171] LustreError: MGC192.168.204.108@tcp: Connection to MGS (at 192.168.204.108@tcp) was lost; in progress operations using this service will fail [17393.672539] Lustre: Evicted from MGS (at 192.168.204.108@tcp) after server handle changed from 0x23583c477108a8f1 to 0x23583c477108bd3b [17393.684736] Lustre: MGC192.168.204.108@tcp: Connection restored to 192.168.204.108@tcp (at 192.168.204.108@tcp) [17397.896165] LustreError: 237381:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff96287da1c380 x1875753593589120/t12884924382(12884924382) o101->lustre-MDT0000-mdc-ffff9627678d0800@192.168.204.108@tcp:12/10 lens 968/608 e 0 to 0 dl 1788861501 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'bash.0' uid:0 gid:0 projid:0 [17397.941527] LustreError: 237381:0:(client.c:3448:ptlrpc_replay_interpret()) Skipped 6 previous similar messages [17399.203001] Lustre: lustre-MDT0000-mdc-ffff9627678d0800: Connection restored to 192.168.204.108@tcp (at 192.168.204.108@tcp) [17414.581574] Lustre: DEBUG MARKER: == sanity test 160i: changelog user register/unregister race ========================================================== 05:58:20 (1788861500) [17439.080838] Lustre: DEBUG MARKER: == sanity test 160j: client can be umounted while its chanangelog is being used ========================================================== 05:58:45 (1788861525) [17439.726881] Lustre: Mounted lustre-client - version 2.17.57_111_g33f3974 [17443.377174] Lustre: Unmounted lustre-client [17449.216147] Lustre: Mounted lustre-client - version 2.17.57_111_g33f3974 [17453.061427] Lustre: Unmounted lustre-client [17454.445199] Lustre: DEBUG MARKER: == sanity test 160k: Verify that changelog records are not lost ========================================================== 05:59:00 (1788861540) [17477.962427] Lustre: DEBUG MARKER: == sanity test 160l: Verify that MTIME changelog records contain the parent FID ========================================================== 05:59:23 (1788861563) [17499.145548] Lustre: DEBUG MARKER: == sanity test 160m: Changelog clear race ================ 05:59:44 (1788861584) [17524.869975] Lustre: DEBUG MARKER: == sanity test 160n: Changelog destroy race ============== 06:00:10 (1788861610) [19839.619872] Lustre: DEBUG MARKER: == sanity test 160o: changelog user name and mask ======== 06:38:44 (1788863924) [19881.981932] Lustre: DEBUG MARKER: == sanity test 160p: Changelog orphan cleanup with no users ========================================================== 06:39:27 (1788863967) [19884.572766] Lustre: DEBUG MARKER: SKIP: sanity test_160p ldiskfs only test [19886.802509] Lustre: DEBUG MARKER: == sanity test 160q: changelog effective mask is DEFMASK if not set ========================================================== 06:39:32 (1788863972) [19900.380905] Lustre: DEBUG MARKER: == sanity test 160s: changelog garbage collect on idle records * time ========================================================== 06:39:45 (1788863985) [19941.222242] Lustre: DEBUG MARKER: == sanity test 160t: changelog garbage collect on lack of space ========================================================== 06:40:26 (1788864026) [20069.191865] Lustre: DEBUG MARKER: == sanity test 160u: changelog rename record type name and sname strings are correct ========================================================== 06:42:34 (1788864154) [20089.381589] Lustre: DEBUG MARKER: == sanity test 160v: setattr preserves mtime update despite inter-client clock skew ========================================================== 06:42:54 (1788864174) [20091.236875] Lustre: DEBUG MARKER: SKIP: sanity test_160v need >= 2 clients [20093.485639] Lustre: DEBUG MARKER: == sanity test 160w: lfs changelog --user --mask ========= 06:42:58 (1788864178) [20119.221721] Lustre: DEBUG MARKER: == sanity test 160x: changelog users do not disappear ==== 06:43:24 (1788864204) [20178.715423] Lustre: DEBUG MARKER: == sanity test 161a: link ea sanity ====================== 06:44:24 (1788864264) [20218.921315] Lustre: DEBUG MARKER: == sanity test 161b: link ea sanity under remote directory ========================================================== 06:45:04 (1788864304) [20220.360606] Lustre: DEBUG MARKER: SKIP: sanity test_161b skipping remote directory test [20222.340602] Lustre: DEBUG MARKER: == sanity test 161c: check CL_RENME[UNLINK] changelog record flags ========================================================== 06:45:07 (1788864307) [20238.093853] Lustre: DEBUG MARKER: == sanity test 161d: create with concurrent .lustre/fid access ========================================================== 06:45:24 (1788864324) [20241.686718] LustreError: 342961:0:(namei.c:1587:ll_create_node()) cfs_fail_timeout id 140c sleeping for 5000ms [20244.202275] LustreError: 342961:0:(namei.c:1587:ll_create_node()) cfs_fail_timeout interrupted [20253.272890] Lustre: DEBUG MARKER: == sanity test 162a: path lookup sanity ================== 06:45:39 (1788864339) [20261.976624] Lustre: DEBUG MARKER: == sanity test 162b: striped directory path lookup sanity ========================================================== 06:45:47 (1788864347) [20263.292297] Lustre: DEBUG MARKER: SKIP: sanity test_162b needs >= 2 MDTs [20265.029630] Lustre: DEBUG MARKER: == sanity test 162c: fid2path works with paths 100 or more directories deep ========================================================== 06:45:50 (1788864350) [20321.251944] Lustre: DEBUG MARKER: == sanity test 165a: ofd access log discovery ============ 06:46:47 (1788864407) [20335.090951] Lustre: lustre-OST0000-osc-ffff96287f718800: Connection to lustre-OST0000 (at 192.168.204.108@tcp) was lost; in progress operations using this service will wait for recovery to complete [20363.190418] Lustre: DEBUG MARKER: == sanity test 165b: ofd access log entries are produced and consumed ========================================================== 06:47:28 (1788864448) [20401.654606] Lustre: lustre-OST0000-osc-ffff96287f718800: Connection to lustre-OST0000 (at 192.168.204.108@tcp) was lost; in progress operations using this service will wait for recovery to complete [20411.696178] Lustre: lustre-OST0000-osc-ffff96287f718800: Connection restored to 192.168.204.108@tcp (at 192.168.204.108@tcp) [20419.773519] Lustre: DEBUG MARKER: == sanity test 165c: full ofd access logs do not block IOs ========================================================== 06:48:25 (1788864505) [20447.722867] Lustre: lustre-OST0000-osc-ffff96287f718800: Connection to lustre-OST0000 (at 192.168.204.108@tcp) was lost; in progress operations using this service will wait for recovery to complete [20459.056598] Lustre: lustre-OST0000-osc-ffff96287f718800: Connection restored to 192.168.204.108@tcp (at 192.168.204.108@tcp) [20468.279418] Lustre: DEBUG MARKER: == sanity test 165d: ofd_access_log mask works =========== 06:49:13 (1788864553) [20519.402828] Lustre: lustre-OST0000-osc-ffff96287f718800: Connection to lustre-OST0000 (at 192.168.204.108@tcp) was lost; in progress operations using this service will wait for recovery to complete [20529.344764] Lustre: lustre-OST0000-osc-ffff96287f718800: Connection restored to 192.168.204.108@tcp (at 192.168.204.108@tcp) [20539.966306] Lustre: DEBUG MARKER: == sanity test 165e: ofd_access_log MDT index filter works ========================================================== 06:50:24 (1788864624) [20542.069830] Lustre: DEBUG MARKER: SKIP: sanity test_165e needs >= 2 MDTs [20543.920827] Lustre: DEBUG MARKER: == sanity test 165f: ofd_access_log_reader --exit-on-close works ========================================================== 06:50:29 (1788864629) [20555.250990] Lustre: lustre-OST0000-osc-ffff96287f718800: Connection to lustre-OST0000 (at 192.168.204.108@tcp) was lost; in progress operations using this service will wait for recovery to complete [20573.595403] Lustre: lustre-OST0000-osc-ffff96287f718800: Connection restored to 192.168.204.108@tcp (at 192.168.204.108@tcp) [20583.324101] Lustre: DEBUG MARKER: == sanity test 165g: ofd_access_log_reader --keepalive works ========================================================== 06:51:09 (1788864669) [20632.056953] Lustre: lustre-OST0000-osc-ffff96287f718800: Connection to lustre-OST0000 (at 192.168.204.108@tcp) was lost; in progress operations using this service will wait for recovery to complete [20650.313700] Lustre: lustre-OST0000-osc-ffff96287f718800: Connection restored to 192.168.204.108@tcp (at 192.168.204.108@tcp) [20659.952808] Lustre: DEBUG MARKER: == sanity test 169: parallel read and truncate should not deadlock ========================================================== 06:52:25 (1788864745) [20661.703830] Lustre: DEBUG MARKER: creating a 10 Mb file [20738.190257] Lustre: DEBUG MARKER: starting reads [20741.306516] Lustre: DEBUG MARKER: truncating the file [20743.595832] Lustre: DEBUG MARKER: killing dd [20745.779757] Lustre: DEBUG MARKER: removing the temporary file [20754.240546] Lustre: DEBUG MARKER: == sanity test 170a: test lctl df to handle corrupted log ========================================================== 06:53:59 (1788864839) [20754.416209] Lustre: debug daemon will attempt to start writing to /tmp/f170a.sanity_log_good (512000kB max) [20754.971147] Lustre: shutting down debug daemon thread... [20755.155646] Lustre: debug daemon will attempt to start writing to /tmp/f170a.sanity_log_good (512000kB max) [20755.350215] Lustre: shutting down debug daemon thread... [20775.351509] Lustre: DEBUG MARKER: == sanity test 170b: check filename encoding ============= 06:54:20 (1788864860) [20811.052512] Lustre: DEBUG MARKER: == sanity test 171: test libcfs_debug_dumplog_thread stuck in do_exit() ================================================================ 06:54:56 (1788864896) [20811.457881] LustreError: 356584:0:(file.c:513:ll_file_release()) cfs_fail_timeout id 50e sleeping for 3000ms [20814.496093] LustreError: 356584:0:(file.c:513:ll_file_release()) cfs_fail_timeout id 50e awake [20814.505431] LustreError: dumping log to /tmp/lustre-log.1788864901.356584 [20821.666484] Lustre: DEBUG MARKER: == sanity test 172: manual device removal with lctl cleanup/detach ================================================================ 06:55:07 (1788864907) [20823.805750] Lustre: *** cfs_fail_loc=60e, val=0*** [20823.814425] Lustre: Unmounted lustre-client [20830.293457] Lustre: Mounted lustre-client - version 2.17.57_111_g33f3974 [20832.251858] Lustre: DEBUG MARKER: == sanity test 180a: test obdecho on osc ================= 06:55:17 (1788864917) [20833.983753] Lustre: DEBUG MARKER: SKIP: sanity test_180a obdecho on osc is no longer supported [20836.166643] Lustre: DEBUG MARKER: == sanity test 180b: test obdecho directly on obdfilter == 06:55:21 (1788864921) [20860.823572] Lustre: DEBUG MARKER: == sanity test 180c: test huge bulk I/O size on obdfilter, don't LASSERT ========================================================== 06:55:46 (1788864946) [20891.447386] Lustre: DEBUG MARKER: == sanity test 181: Test open-unlinked dir ================================================================================== 06:56:16 (1788864976) [21007.505621] Lustre: DEBUG MARKER: == sanity test 182a: Test parallel modify metadata operations from mdc ========================================================== 06:58:12 (1788865092) [21137.465225] Lustre: DEBUG MARKER: == sanity test 182b: Test parallel modify metadata operations from osp ========================================================== 07:00:23 (1788865223) [21139.346593] Lustre: DEBUG MARKER: SKIP: sanity test_182b needs >= 2 MDTs [21141.630284] Lustre: DEBUG MARKER: == sanity test 183: No crash or request leak in case of strange dispositions ================================================================== 07:00:27 (1788865227) [21152.642193] Lustre: DEBUG MARKER: == sanity test 184a: Basic layout swap =================== 07:00:38 (1788865238) [21164.776664] Lustre: DEBUG MARKER: == sanity test 184b: Forbidden layout swap (will generate errors) ========================================================== 07:00:50 (1788865250) [21175.415673] Lustre: DEBUG MARKER: == sanity test 184c: Concurrent write and layout swap ==== 07:01:00 (1788865260) [21233.161643] Lustre: DEBUG MARKER: == sanity test 184d: allow stripeless layouts swap ======= 07:01:58 (1788865318) [21255.649949] Lustre: DEBUG MARKER: == sanity test 184e: Recreate layout after stripeless layout swaps ========================================================== 07:02:21 (1788865341) [21277.909272] Lustre: DEBUG MARKER: == sanity test 184f: IOC_MDC_GETFILEINFO for files with long names but no striping ========================================================== 07:02:43 (1788865363) [21285.256854] Lustre: DEBUG MARKER: == sanity test 185: Volatile file support ================ 07:02:51 (1788865371) [21293.084264] Lustre: DEBUG MARKER: == sanity test 185a: Volatile file creation in .lustre/fid/ ========================================================== 07:02:59 (1788865379) [21303.930622] Lustre: DEBUG MARKER: == sanity test 187a: Test data version change ============ 07:03:08 (1788865388) [21316.532466] Lustre: DEBUG MARKER: == sanity test 187b: Test data version change on volatile file ========================================================== 07:03:21 (1788865401) [21325.678925] Lustre: DEBUG MARKER: == sanity test 190a: check lfs project -p works with project name ========================================================== 07:03:31 (1788865411) [21333.912726] Lustre: DEBUG MARKER: == sanity test 190b: check lfs find --project works with project name ========================================================== 07:03:39 (1788865419) [21434.111857] Lustre: DEBUG MARKER: == sanity test 190c: check lfs project -p works with u:USERNAME ========================================================== 07:05:19 (1788865519) [21452.174195] Lustre: DEBUG MARKER: == sanity test complete, duration 21222 sec ============== 07:05:38 (1788865538) [21454.205555] Lustre: DEBUG MARKER: === sanity: start cleanup 07:05:39 (1788865539) === [21503.938812] Lustre: DEBUG MARKER: === sanity: finish cleanup 07:06:29 (1788865589) === [21507.549823] Lustre: Unmounted lustre-client [21530.644710] Key type lgssc unregistered [21530.968114] LNet: 375669:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [21530.976039] LNetError: 375669:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [21531.002044] LNet: Removed LNI 192.168.204.8@tcp [21532.285270] Key type .llcrypt unregistered [21532.288751] Key type ._llcrypt unregistered