[ 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.16.2-1.fc38 04/01/2014 [ 0.000000] Hypervisor detected: KVM [ 0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00 [ 0.000000] kvm-clock: using sched offset of 373139491 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 0x000f5b50-0x000f5b5f] [ 0.000000] RAMDISK: [mem 0xbcc64000-0xbffcffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F5970 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE1BB7 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE1A53 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 001A13 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE1AC7 000090 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE1B57 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE1B8F 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe1a53-0xbffe1ac6] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe1a52] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe1ac7-0xbffe1b56] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe1b57-0xbffe1b8e] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe1b8f-0xbffe1bb6] [ 0.000000] No NUMA configuration found [ 0.000000] Faking a node at [mem 0x0000000000000000-0x0000000146dfffff] [ 0.000000] NODE_DATA(0) allocated [mem 0x1465a3000-0x1465cdfff] [ 0.000000] Reserving 256MB of memory at 2752MB for crashkernel (System RAM: 4205MB) [ 0.000000] Zone ranges: [ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.000000] DMA32 [mem 0x0000000001000000-0x00000000ffffffff] [ 0.000000] Normal [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Device empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff] [ 0.000000] node 0: [mem 0x0000000000100000-0x00000000bffd9fff] [ 0.000000] node 0: [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Zeroed struct page in unavailable ranges: 4744 pages [ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x0000000146dfffff] [ 0.000000] ACPI: PM-Timer IO Port: 0x608 [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) [ 0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) [ 0.000000] Using ACPI (MADT) for SMP configuration information [ 0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000] TSC deadline timer available [ 0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs [ 0.000000] kvm-guest: KVM setup pv remote TLB flush [ 0.000000] kvm-guest: setup PV sched yield [ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff] [ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff] [ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff] [ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff] [ 0.000000] PM: Registered nosave memory: [mem 0xbffda000-0xbfffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xc0000000-0xfeffbfff] [ 0.000000] PM: Registered nosave memory: [mem 0xfeffc000-0xfeffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xff000000-0xfffbffff] [ 0.000000] PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff] [ 0.000000] [mem 0xc0000000-0xfeffbfff] available for PCI devices [ 0.000000] Booting paravirtualized kernel on KVM [ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns [ 0.000000] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1 [ 0.000000] percpu: Embedded 63 pages/cpu s221184 r8192 d28672 u524288 [ 0.000000] kvm-guest: PV spinlocks enabled [ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1059618 [ 0.000000] Policy zone: Normal [ 0.000000] Kernel command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] Specific versions of hardware are certified with Red Hat Enterprise Linux 8. Please see the list of hardware certified with Red Hat Enterprise Linux 8 at https://catalog.redhat.com. [ 0.000000] audit: disabled (until reboot) [ 0.000000] software IO TLB: area num 4. [ 0.000000] Memory: 2895288K/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.001010] APIC: Switch to symmetric I/O mode setup [ 0.002000] x2apic enabled [ 0.002005] Switched APIC routing to physical x2apic. [ 0.003006] kvm-guest: setup PV IPIs [ 0.005347] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.006000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.006013] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.007004] pid_max: default: 32768 minimum: 301 [ 0.008106] LSM: Security Framework initializing [ 0.009027] Yama: becoming mindful. [ 0.009618] SELinux: Initializing. [ 0.011035] *** VALIDATE selinux *** [ 0.017183] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.021331] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.022137] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.023063] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.024061] *** VALIDATE tmpfs *** [ 0.025295] *** VALIDATE proc *** [ 0.026132] *** VALIDATE cgroup *** [ 0.026676] *** VALIDATE cgroup2 *** [ 0.027161] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.028095] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.029002] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.030017] Spectre V2 : User space: Vulnerable [ 0.031004] Speculative Store Bypass: Vulnerable [ 0.034265] debug: unmapping init [mem 0xffffffffb4a59000-0xffffffffb4a60fff] [ 0.036728] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.037449] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.038011] ... version: 2 [ 0.038589] ... bit width: 48 [ 0.039007] ... generic registers: 4 [ 0.040006] ... value mask: 0000ffffffffffff [ 0.041007] ... max period: 00007fffffffffff [ 0.042005] ... fixed-purpose events: 3 [ 0.042786] ... event mask: 000000070000000f [ 0.043283] rcu: Hierarchical SRCU implementation. [ 0.045383] smp: Bringing up secondary CPUs ... [ 0.046383] x86: Booting SMP configuration: [ 0.047012] .... node #0, CPUs: #1 #2 #3 [ 0.049775] smp: Brought up 1 node, 4 CPUs [ 0.050846] smpboot: Max logical packages: 1 [ 0.051008] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.127852] node 0 deferred pages initialised in 76ms [ 0.131014] devtmpfs: initialized [ 0.132086] x86/mm: Memory block size: 128MB [ 0.134335] gcov: version magic: 0x41383552 [ 0.136307] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.137073] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.138300] pinctrl core: initialized pinctrl subsystem [ 0.139167] [ 0.139528] ************************************************************* [ 0.140006] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.141005] ** ** [ 0.142006] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.143005] ** ** [ 0.144007] ** This means that this kernel is built to expose internal ** [ 0.145012] ** IOMMU data structures, which may compromise security on ** [ 0.146008] ** your system. ** [ 0.147007] ** ** [ 0.148010] ** If you see this message and you are not debugging the ** [ 0.149007] ** kernel, report this immediately to your vendor! ** [ 0.150008] ** ** [ 0.151008] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.152007] ************************************************************* [ 0.153774] NET: Registered protocol family 16 [ 0.154297] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.155044] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.156043] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.157486] cpuidle: using governor menu [ 0.158000] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.160338] PCI: Using configuration type 1 for base access [ 0.162104] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.169201] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.171011] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.172191] cryptd: max_cpu_qlen set to 1000 [ 0.175426] ACPI: Added _OSI(Module Device) [ 0.177015] ACPI: Added _OSI(Processor Device) [ 0.178011] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.180015] ACPI: Added _OSI(Processor Aggregator Device) [ 0.183506] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.190734] ACPI: Interpreter enabled [ 0.191051] ACPI: PM: (supports S0 S3 S4 S5) [ 0.192013] ACPI: Using IOAPIC for interrupt routing [ 0.194090] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.197422] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.207272] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.209038] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.211029] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.214077] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.216928] acpiphp: Slot [2] registered [ 0.218061] acpiphp: Slot [3] registered [ 0.218739] acpiphp: Slot [4] registered [ 0.219037] acpiphp: Slot [5] registered [ 0.219792] acpiphp: Slot [6] registered [ 0.221080] acpiphp: Slot [7] registered [ 0.222043] acpiphp: Slot [8] registered [ 0.222801] acpiphp: Slot [9] registered [ 0.224060] acpiphp: Slot [10] registered [ 0.225108] acpiphp: Slot [11] registered [ 0.226070] acpiphp: Slot [12] registered [ 0.228079] acpiphp: Slot [13] registered [ 0.229116] acpiphp: Slot [14] registered [ 0.231064] acpiphp: Slot [15] registered [ 0.232072] acpiphp: Slot [16] registered [ 0.233062] acpiphp: Slot [17] registered [ 0.234068] acpiphp: Slot [18] registered [ 0.236086] acpiphp: Slot [19] registered [ 0.237063] acpiphp: Slot [20] registered [ 0.239097] acpiphp: Slot [21] registered [ 0.240057] acpiphp: Slot [22] registered [ 0.241058] acpiphp: Slot [23] registered [ 0.243062] acpiphp: Slot [24] registered [ 0.244100] acpiphp: Slot [25] registered [ 0.245059] acpiphp: Slot [26] registered [ 0.246071] acpiphp: Slot [27] registered [ 0.247056] acpiphp: Slot [28] registered [ 0.249056] acpiphp: Slot [29] registered [ 0.250054] acpiphp: Slot [30] registered [ 0.251055] acpiphp: Slot [31] registered [ 0.252071] PCI host bridge to bus 0000:00 [ 0.253012] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.255012] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.257012] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.259012] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.261011] pci_bus 0000:00: root bus resource [mem 0x180000000-0x1ffffffff window] [ 0.263014] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.264210] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.268216] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.272143] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.278872] pci 0000:00:01.1: reg 0x20: [io 0xc120-0xc12f] [ 0.282538] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.284010] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.287017] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.289011] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.291678] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.293791] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.297026] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.299645] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.303975] pci 0000:00:02.0: reg 0x10: [io 0xc100-0xc11f] [ 0.312927] pci 0000:00:02.0: reg 0x20: [mem 0xfebf4000-0xfebf7fff 64bit pref] [ 0.315783] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.320695] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.327015] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.332012] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.341019] pci 0000:00:05.0: reg 0x20: [mem 0xfebf8000-0xfebfbfff 64bit pref] [ 0.351155] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.357014] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.363016] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.374015] pci 0000:00:06.0: reg 0x20: [mem 0xfebfc000-0xfebfffff 64bit pref] [ 0.382510] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.384328] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.386187] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.387172] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.389104] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.392239] iommu: Default domain type: Passthrough [ 0.394403] SCSI subsystem initialized [ 0.396106] ACPI: bus type USB registered [ 0.397109] usbcore: registered new interface driver usbfs [ 0.398035] usbcore: registered new interface driver hub [ 0.399039] usbcore: registered new device driver usb [ 0.401096] pps_core: LinuxPPS API ver. 1 registered [ 0.402006] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.403021] PTP clock support registered [ 0.404141] EDAC MC: Ver: 3.0.0 [ 0.406146] PCI: Using ACPI for IRQ routing [ 0.407743] NetLabel: Initializing [ 0.409012] NetLabel: domain hash size = 128 [ 0.410006] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.412061] NetLabel: unlabeled traffic allowed by default [ 0.414102] vgaarb: loaded [ 0.415172] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.416008] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.421289] clocksource: Switched to clocksource kvm-clock [ 0.529021] VFS: Disk quotas dquot_6.6.0 [ 0.530461] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.532754] *** VALIDATE ramfs *** [ 0.533807] *** VALIDATE hugetlbfs *** [ 0.535302] pnp: PnP ACPI init [ 0.537476] pnp: PnP ACPI: found 6 devices [ 0.551772] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.554833] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.556883] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.558814] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.561103] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.563337] pci_bus 0000:00: resource 8 [mem 0x180000000-0x1ffffffff window] [ 0.565928] NET: Registered protocol family 2 [ 0.568126] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.572444] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.575654] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.580375] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.583423] TCP: Hash tables configured (established 65536 bind 65536) [ 0.586136] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.588857] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.591056] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.593732] NET: Registered protocol family 1 [ 0.596163] RPC: Registered named UNIX socket transport module. [ 0.597549] RPC: Registered udp transport module. [ 0.598982] RPC: Registered tcp transport module. [ 0.600759] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.601885] NET: Registered protocol family 44 [ 0.602985] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.604469] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.605597] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.606923] PCI: CLS 0 bytes, default 64 [ 0.608075] Unpacking initramfs... [ 1.921077] debug: unmapping init [mem 0xffff9b15bcc64000-0xffff9b15bffcffff] [ 1.924877] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 1.927292] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 1.929670] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 2.499634] Initialise system trusted keyrings [ 2.501130] Key type blacklist registered [ 2.503925] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.512770] zbud: loaded [ 2.516033] *** VALIDATE nfs *** [ 2.517352] *** VALIDATE nfs4 *** [ 2.519115] pstore: using deflate compression [ 2.522157] Platform Keyring initialized [ 2.674636] NET: Registered protocol family 38 [ 2.676079] Key type asymmetric registered [ 2.677681] Asymmetric key parser 'x509' registered [ 2.679342] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 2.682610] io scheduler mq-deadline registered [ 2.684093] io scheduler kyber registered [ 2.685533] io scheduler bfq registered [ 2.687702] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 2.695601] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 2.697982] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 2.700504] ACPI: Power Button [PWRF] [ 2.799683] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 2.895439] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 2.999087] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 3.037097] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.067744] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.073845] Non-volatile memory driver v1.3 [ 3.075364] Linux agpgart interface v0.103 [ 3.102138] virtio_blk virtio1: [vda] 132968 512-byte logical blocks (68.1 MB/64.9 MiB) [ 3.106296] vda: detected capacity change from 0 to 68079616 [ 3.126028] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.128452] vdb: detected capacity change from 0 to 1073741824 [ 3.134169] libphy: Fixed MDIO Bus: probed [ 3.142191] usbcore: registered new interface driver usbserial_generic [ 3.144324] usbserial: USB Serial support registered for generic [ 3.146274] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.150547] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.152958] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.155289] mousedev: PS/2 mouse device common for all mice [ 3.158725] rtc_cmos 00:05: RTC can wake from S4 [ 3.162275] rtc_cmos 00:05: registered as rtc0 [ 3.164377] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.168248] intel_pstate: CPU model not supported [ 3.170466] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.173579] hid: raw HID events driver (C) Jiri Kosina [ 3.179865] usbcore: registered new interface driver usbhid [ 3.181544] usbhid: USB HID core driver [ 3.185524] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.189011] drop_monitor: Initializing network drop monitor service [ 3.198760] Initializing XFRM netlink socket [ 3.202884] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.204485] NET: Registered protocol family 10 [ 3.218332] Segment Routing with IPv6 [ 3.223084] NET: Registered protocol family 17 [ 3.227203] mpls_gso: MPLS GSO support [ 3.235582] RAS: Correctable Errors collector initialized. [ 3.238484] AVX version of gcm_enc/dec engaged. [ 3.240196] AES CTR mode by8 optimization enabled [ 3.381986] sched_clock: Marking stable (3381964914, 0)->(4047889543, -665924629) [ 3.385992] registered taskstats version 1 [ 3.388566] Loading compiled-in X.509 certificates [ 3.394975] zswap: loaded using pool lzo/zbud [ 3.438897] Key type big_key registered [ 3.470470] Key type encrypted registered [ 3.472537] ima: No TPM chip found, activating TPM-bypass! [ 3.474886] ima: Allocated hash algorithm: sha1 [ 3.477189] ima: No architecture policies found [ 3.479348] evm: Initialising EVM extended attributes: [ 3.481554] evm: security.selinux [ 3.482616] evm: security.ima [ 3.483727] evm: security.capability [ 3.484993] evm: HMAC attrs: 0x1 [ 3.490492] rtc_cmos 00:05: setting system clock to 2025-08-13 14:37:08 UTC (1755095828) [ 3.504324] debug: unmapping init [mem 0xffffffffb5a03000-0xffffffffb5bfffff] [ 3.512156] debug: unmapping init [mem 0xffffffffb4782000-0xffffffffb4a58fff] [ 3.530111] Write protecting the kernel read-only data: 28672k [ 3.536084] debug: unmapping init [mem 0xffffffffb2e03000-0xffffffffb2ffffff] [ 3.539055] debug: unmapping init [mem 0xffffffffb3714000-0xffffffffb37fffff] [ 3.582217] 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.598516] systemd[1]: Detected virtualization kvm. [ 3.600476] systemd[1]: Detected architecture x86-64. [ 3.602479] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.669339] systemd[1]: No hostname configured. [ 3.678917] systemd[1]: Set hostname to . [ 3.683921] random: systemd: uninitialized urandom read (16 bytes read) [ 3.686056] systemd[1]: Initializing machine ID from random generator. [ 3.953503] random: systemd: uninitialized urandom read (16 bytes read) [ 3.956749] systemd[1]: Listening on udev Control Socket. [ OK ] Listening on udev Control Socket. [ 3.964385] random: systemd: uninitialized urandom read (16 bytes read) [ 3.967031] systemd[1]: Reached target Swap. [ OK ] Reached target Swap. [ 3.977761] systemd[1]: Reached target Timers. [ OK ] Reached target Timers. [ OK ] Reached target Initrd Root Device. [ OK ] Listening on udev Kernel Socket. [ OK ] Reached target Slices. [ OK ] Listening on Journal Socket (/dev/log). [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Paths. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Listening on Journal Socket. Starting Journal Service... Starting Apply Kernel Variables... [ OK ] Reached target Sockets. Starting Setup Virtual Console... [ OK ] Started Memstrack Anylazing Service. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Reached target Local File Systems. Starting Create Volatile Files and Directories... [ OK ] Started Apply Kernel Variables. [ OK ] Started Setup Virtual Console. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Journal Service. [ OK ] Started Create Volatile Files and Directories. Starting Create Static Device Nodes in /dev... Starting dracut cmdline hook... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 5.446593] device-mapper: uevent: version 1.0.3 [ 5.450783] 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... [ 7.858095] virtio_net virtio0 ens2: renamed from eth0 [ 8.358128] scsi host0: ata_piix [ 8.439112] scsi host1: ata_piix [ 8.440580] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc120 irq 14 [ 8.446648] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc128 irq 15 [ 14.022391] random: crng init done [ 14.038268] random: 7 urandom warning(s) missed due to ratelimiting [ 16.517424] dracut-initqueue[585]: RTNETLINK answers: File exists Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Mounting /sysroot... [ 18.558413] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped target Timers. [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Paths. [ OK ] Stopped target Slices. [ OK ] Stopped target Sockets. [ OK ] Stopped target System Initialization. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. Stopping udev Kernel Device Manager... [ OK ] Stopped target Swap. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ 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... [ 20.659452] printk: systemd: 22 output lines suppressed due to ratelimiting [ 21.318978] SELinux: Disabled at runtime. [ 21.421732] 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) [ 21.440393] systemd[1]: Detected virtualization kvm. [ 21.442019] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 22.797379] systemd[1]: initrd-switch-root.service: Succeeded. [ 22.803316] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 22.813348] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 22.825950] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 22.838701] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 22.856812] systemd[1]: Starting Journal Service... Starting Journal Service... [ 22.888218] systemd[1]: Mounting Huge Pages File System... Mounting Huge Pages File System... [ OK ] Started Dispatch Password Requests to Console Directory Watch. Mounting POSIX Message Queue File System... [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Created slice User and Session Slice. Starting Create list of required st…ce nodes for the current kernel... Mounting Kernel Debug File System... Starting Apply Kernel Variables... [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Reached target Paths. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Reached target RPC Port Mapper. [ OK ] Reached target Slices. [ OK ] Listening on udev Control Socket. Activating swap /dev/disk/by-label/SWAP... [ OK ] Created slice system-serial\x2dgetty.slice. Starting Remount Root and Kernel File Systems... [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd File Systems. [ OK ] Stopped target Initrd Root File System. [ OK ] Listening on udev Kernel Socket. [ 23.387424] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS Starting udev Coldplug all Devices... [ OK ] Created slice system-getty.slice. [ OK ] Reached target rpc_pipefs.target. [ OK ] Listening on Process Core Dump Socket. [ OK ] Started Journal Service. [ OK ] Mounted Huge Pages File System. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Mounted Kernel Debug File System. [ OK ] Started Apply Kernel Variables. [ OK ] Activated swap /dev/disk/by-label/SWAP. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. Starting Configure read-only root support... [ OK ] Reached target Swap. Starting Create Static Device Nodes in /dev... Starting Flush Journal to Persistent Storage... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started udev Coldplug all Devices. [ OK ] Reached target Local File Systems (Pre). Mounting /mnt... Mounting /home/green/git/lustre-release... Starting udev Kernel Device Manager... [ OK ] Mounted /mnt. [ 24.274516] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 25.257081] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 25.291704] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 26.593984] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 26.649910] EDAC sbridge: Ver: 1.1.2 [ 28.723202] Key type dns_resolver registered [ 29.313974] NFS: Registering the id_resolver key type [ 29.315745] Key type id_resolver registered [ 29.317119] Key type id_legacy registered [ OK ] Started Configure read-only root support. Starting Load/Save Random Seed... [ OK ] Reached target Local File Systems. Starting Rebuild Dynamic Linker Cache... Starting Mark the need to relabel after reboot... Starting Create Volatile Files and Directories... [ OK ] Started Load/Save Random Seed. [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Create Volatile Files and Directories. Starting RPC Bind... Starting Update UTMP about System Boot/Shutdown... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Started dnf makecache --timer. [ OK ] Reached target Timers. [ OK ] Reached target Basic System. 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 irqbalance daemon. [ OK ] Reached target sshd-keygen.target. [ OK ] Started Restore /run/initramfs on shutdown. [ 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 Serial Getty on ttyS1. [ OK ] Started Getty on tty1. [ OK ] Started Serial Getty on ttyS0. [ OK ] Reached target Login Prompts. [ OK ] Started Command Scheduler. [ OK ] Started Login Service. [ 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 System Logging Service... Starting Notify NFS peers of a restart... Starting Crash recovery kernel arming... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg234-client login: [ 83.062167] libcfs: loading out-of-tree module taints kernel. [ 83.098081] Key type ._llcrypt registered [ 83.099865] Key type .llcrypt registered [ 83.465715] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [ 83.478259] alg: No test for adler32 (adler32-zlib) [ 84.478260] Lustre: Lustre: Build Version: 2.16.56_9_g5b8a063 [ 84.796050] LNet: Added LNI 192.168.202.34@tcp [8/256/0/180] [ 84.798299] LNet: Accept secure, port 988 [ 86.416197] Key type lgssc registered [ 87.009223] Lustre: Echo OBD driver; http://www.lustre.org/ [ 143.451265] Lustre: Mounted lustre-client [ 146.073471] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 159.443934] Lustre: DEBUG MARKER: oleg234-client.virtnet: executing check_logdir /tmp/testlogs/ [ 161.372479] Lustre: DEBUG MARKER: oleg234-client.virtnet: executing yml_node [ 163.849644] Lustre: DEBUG MARKER: Client: 2.16.56.9 [ 164.862852] Lustre: DEBUG MARKER: MDS: 2.16.56.9 [ 165.749349] Lustre: DEBUG MARKER: OSS: 2.16.56.9 [ 166.313728] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity ============----- Wed Aug 13 10:39:50 EDT 2025 [ 168.928202] Lustre: lustre-OST0000-osc-ffff9b1618963000: disconnect after 23s idle [ 173.022988] Lustre: DEBUG MARKER: - need mds1 <= 2.14.55-100-g8a84c7f9c7 for LU-14927, skip 0f [ 173.734423] Lustre: DEBUG MARKER: - need mds1 < v2_14_55-100-g8a84c7f9c7 for LU-14927, skip 0f [ 174.550859] Lustre: DEBUG MARKER: excepting tests: 225 255 256 400a 42a 42c 42b 118c 118d 407 119i 817 411a 130b 130c 130d 130e 130f 130g 312 [ 175.351389] Lustre: DEBUG MARKER: skipping tests SLOW=no: 27m 60i 64b 68 71 135 136 230d 300o 842 51b [ 176.237717] Lustre: DEBUG MARKER: === sanity: start setup 10:40:00 (1755096000) === [ 178.286803] Lustre: DEBUG MARKER: oleg234-client.virtnet: executing check_config_client /mnt/lustre [ 185.972405] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 190.424172] Lustre: DEBUG MARKER: === sanity: finish setup 10:40:14 (1755096014) === [ 195.386318] Lustre: DEBUG MARKER: == sanity test 200: OST pools ============================ 10:40:19 (1755096019) [ 213.847506] Lustre: DEBUG MARKER: == sanity test 204a: Print default stripe attributes ===== 10:40:38 (1755096038) [ 217.229644] Lustre: DEBUG MARKER: == sanity test 204b: Print default stripe size and offset ========================================================== 10:40:41 (1755096041) [ 220.570843] Lustre: DEBUG MARKER: == sanity test 204c: Print default stripe count and offset ========================================================== 10:40:44 (1755096044) [ 223.826326] Lustre: DEBUG MARKER: == sanity test 204d: Print default stripe count and size ========================================================== 10:40:48 (1755096048) [ 227.048489] Lustre: DEBUG MARKER: == sanity test 204e: Print raw stripe attributes ========= 10:40:51 (1755096051) [ 230.322950] Lustre: DEBUG MARKER: == sanity test 204f: Print raw stripe size and offset ==== 10:40:54 (1755096054) [ 230.369576] Lustre: lustre-OST0000-osc-ffff9b1618963000: disconnect after 20s idle [ 230.372747] Lustre: Skipped 1 previous similar message [ 233.782464] Lustre: DEBUG MARKER: == sanity test 204g: Print raw stripe count and offset === 10:40:58 (1755096058) [ 237.208301] Lustre: DEBUG MARKER: == sanity test 204h: Print raw stripe count and size ===== 10:41:01 (1755096061) [ 241.112550] Lustre: DEBUG MARKER: == sanity test 205a: Verify job stats ==================== 10:41:05 (1755096065) [ 247.600288] Lustre: DEBUG MARKER: Test: /home/green/git/lustre-release/lustre/utils/lfs mkdir -i 0 -c 1 /mnt/lustre/d205a.sanity [ 248.497201] Lustre: DEBUG MARKER: Using JobID environment nodelocal=id.205a.lfs.22888 [ 249.987279] Lustre: DEBUG MARKER: Test: rmdir /mnt/lustre/d205a.sanity [ 250.802548] Lustre: DEBUG MARKER: Using JobID environment nodelocal=id.205a.rmdir.23575 [ 252.174929] Lustre: DEBUG MARKER: Test: mknod /mnt/lustre/f205a.sanity c 1 3 [ 253.065136] Lustre: DEBUG MARKER: Using JobID environment nodelocal=id.205a.mknod.9544 [ 254.456185] Lustre: DEBUG MARKER: Test: rm -f /mnt/lustre/f205a.sanity [ 255.261452] Lustre: DEBUG MARKER: Using JobID environment nodelocal=id.205a.rm.12778 [ 256.462199] Lustre: DEBUG MARKER: Test: /home/green/git/lustre-release/lustre/utils/lfs setstripe -i 0 -c 1 /mnt/lustre/f205a.sanity [ 257.240785] Lustre: DEBUG MARKER: Using JobID environment nodelocal=id.205a.lfs.152 [ 258.541128] Lustre: DEBUG MARKER: Test: touch /mnt/lustre/f205a.sanity [ 259.373726] Lustre: DEBUG MARKER: Using JobID environment nodelocal=id.205a.touch.13351 [ 261.107180] Lustre: DEBUG MARKER: Test: dd if=/dev/zero of=/mnt/lustre/f205a.sanity bs=1M count=1 oflag=sync [ 261.886762] Lustre: DEBUG MARKER: Using JobID environment nodelocal=id.205a.dd.7556 [ 263.246796] Lustre: DEBUG MARKER: Test: dd if=/mnt/lustre/f205a.sanity of=/dev/null bs=1M count=1 iflag=direct [ 263.975165] Lustre: DEBUG MARKER: Using JobID environment nodelocal=id.205a.dd.22666 [ 265.118187] Lustre: DEBUG MARKER: Test: /home/green/git/lustre-release/lustre/tests/truncate /mnt/lustre/f205a.sanity 0 [ 265.867913] Lustre: DEBUG MARKER: Using JobID environment nodelocal=id.205a.truncate.23663 [ 267.659720] Lustre: DEBUG MARKER: Test: mv -f /mnt/lustre/f205a.sanity /mnt/lustre/d205a.sanity.rename [ 268.464371] Lustre: DEBUG MARKER: Using JobID environment nodelocal=id.205a.mv.10101 [ 269.775531] Lustre: DEBUG MARKER: Test: /home/green/git/lustre-release/lustre/utils/lfs mkdir -i 0 -c 1 /mnt/lustre/d205a.sanity.expire [ 270.620208] Lustre: DEBUG MARKER: Using JobID environment nodelocal=id.205a.lfs.4703 [ 275.632651] Lustre: DEBUG MARKER: Test: touch /mnt/lustre/f205a.sanity [ 276.381690] Lustre: DEBUG MARKER: Using JobID environment USER=S.root.touch.0.oleg234-client.v [ 277.687330] Lustre: DEBUG MARKER: Test: touch /mnt/lustre/f205a.sanity [ 278.485424] Lustre: DEBUG MARKER: Using JobID environment USER=S.root.touch.0.oleg234-client.E [ 279.788552] Lustre: DEBUG MARKER: Test: touch /mnt/lustre/f205a.sanity [ 280.650473] Lustre: DEBUG MARKER: Using JobID environment session=S.root.touch.0.oleg234-client.v [ 288.525183] Lustre: DEBUG MARKER: == sanity test 205b: Verify job stats jobid and output format ========================================================== 10:41:52 (1755096112) [ 294.694778] Lustre: DEBUG MARKER: == sanity test 205c: Verify client stats format ========== 10:41:59 (1755096119) [ 297.809790] Lustre: DEBUG MARKER: == sanity test 205d: verify the format of some stats files ========================================================== 10:42:02 (1755096122) [ 304.485768] Lustre: DEBUG MARKER: == sanity test 205e: verify the output of lljobstat ====== 10:42:08 (1755096128) [ 311.989342] Lustre: DEBUG MARKER: == sanity test 205f: verify qos_ost_weights YAML format == 10:42:16 (1755096136) [ 316.001916] Lustre: DEBUG MARKER: == sanity test 205g: stress test for job_stats procfile == 10:42:20 (1755096140) [ 412.608833] Lustre: DEBUG MARKER: == sanity test 205h: check jobid xattr is stored correctly ========================================================== 10:43:56 (1755096236) [ 418.586598] Lustre: DEBUG MARKER: == sanity test 205i: check job_xattr parameter accepts and rejects values correctly ========================================================== 10:44:02 (1755096242) [ 425.416943] Lustre: DEBUG MARKER: == sanity test 205k: Verify '?' operator on job stats ==== 10:44:09 (1755096249) [ 430.555591] Lustre: DEBUG MARKER: == sanity test 205l: Verify job stats can scale ========== 10:44:14 (1755096254) [ 487.093630] Lustre: DEBUG MARKER: == sanity test 206: fail lov_init_raid0() doesn't lbug === 10:45:11 (1755096311) [ 487.178322] Lustre: *** cfs_fail_loc=1403, val=1*** [ 487.179687] LustreError: 43598:0:(lcommon_cl.c:188:cl_file_inode_init()) lustre: failed to initialize cl_object [0x200000401:0x896:0x0]: rc = -5 [ 487.183051] LustreError: 43598:0:(llite_lib.c:3769:ll_prep_inode()) lustre: new_inode - fatal error: rc = -5 [ 489.693495] Lustre: DEBUG MARKER: == sanity test 207a: can refresh layout at glimpse ======= 10:45:14 (1755096314) [ 492.454571] Lustre: DEBUG MARKER: == sanity test 207b: can refresh layout at open ========== 10:45:16 (1755096316) [ 495.450604] Lustre: DEBUG MARKER: == sanity test 208: Exclusive open ======================= 10:45:19 (1755096319) [ 517.088757] Lustre: lustre-OST0000-osc-ffff9b1618963000: disconnect after 25s idle [ 517.091742] Lustre: Skipped 1 previous similar message [ 517.098064] Lustre: lustre-MDT0000-mdc-ffff9b1618963000: Connection to lustre-MDT0000 (at 192.168.202.134@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 517.103547] LustreError: MGC192.168.202.134@tcp: Connection to MGS (at 192.168.202.134@tcp) was lost; in progress operations using this service will fail [ 517.112435] Lustre: Evicted from MGS (at 192.168.202.134@tcp) after server handle changed from 0xf9d39a36c0a2c987 to 0xf9d39a36c0a6437c [ 517.117618] Lustre: MGC192.168.202.134@tcp: Connection restored to (at 192.168.202.134@tcp) [ 517.128594] LustreError: 2377:0:(mdc_request.c:662:mdc_replay_open()) @@@ cannot properly replay without open data req@ffff9b160673ad80 x1840351450929152/t4294974989(4294974989) o101->lustre-MDT0000-mdc-ffff9b1618963000@192.168.202.134@tcp:12/10 lens 608/608 e 0 to 0 dl 1755096358 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'touch.0' uid:0 gid:0 projid:0 [ 517.138021] LustreError: 2377:0:(client.c:3395:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9b160673ad80 x1840351450929152/t4294974989(4294974989) o101->lustre-MDT0000-mdc-ffff9b1618963000@192.168.202.134@tcp:12/10 lens 608/608 e 0 to 0 dl 1755096358 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'touch.0' uid:0 gid:0 projid:0 [ 521.424981] Lustre: DEBUG MARKER: oleg234-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 522.099255] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 522.208350] Lustre: 2380:0:(client.c:2453:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1755096331/real 1755096331] req@ffff9b161079b480 x1840351450942848/t0(0) o400->lustre-MDT0000-mdc-ffff9b1618963000@192.168.202.134@tcp:12/10 lens 224/224 e 0 to 1 dl 1755096347 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 527.328279] Lustre: 2381:0:(client.c:2453:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1755096336/real 1755096336] req@ffff9b1606739f80 x1840351450943360/t0(0) o400->lustre-MDT0000-mdc-ffff9b1618963000@192.168.202.134@tcp:12/10 lens 224/224 e 0 to 1 dl 1755096352 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 542.692206] Lustre: lustre-MDT0000-mdc-ffff9b1618963000: Connection to lustre-MDT0000 (at 192.168.202.134@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 542.698928] LustreError: MGC192.168.202.134@tcp: Connection to MGS (at 192.168.202.134@tcp) was lost; in progress operations using this service will fail [ 542.705869] Lustre: Evicted from MGS (at 192.168.202.134@tcp) after server handle changed from 0xf9d39a36c0a6437c to 0xf9d39a36c0a6480d [ 542.710663] Lustre: MGC192.168.202.134@tcp: Connection restored to (at 192.168.202.134@tcp) [ 542.714153] Lustre: Skipped 1 previous similar message [ 542.716845] LustreError: 2377:0:(mdc_request.c:662:mdc_replay_open()) @@@ cannot properly replay without open data req@ffff9b160673ad80 x1840351450929152/t4294974989(4294974989) o101->lustre-MDT0000-mdc-ffff9b1618963000@192.168.202.134@tcp:12/10 lens 608/608 e 0 to 0 dl 1755096383 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'touch.0' uid:0 gid:0 projid:0 [ 542.732170] LustreError: 2377:0:(client.c:3395:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9b1606739180 x1840351450948608/t8589934595(8589934595) o101->lustre-MDT0000-mdc-ffff9b1618963000@192.168.202.134@tcp:12/10 lens 584/608 e 0 to 0 dl 1755096383 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'multiop.0' uid:0 gid:0 projid:0 [ 542.743324] LustreError: 2377:0:(client.c:3395:ptlrpc_replay_interpret()) Skipped 2 previous similar messages [ 543.712185] Lustre: 2379:0:(client.c:2453:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1755096352/real 1755096352] req@ffff9b16106b9500 x1840351450949504/t0(0) o400->lustre-MDT0000-mdc-ffff9b1618963000@192.168.202.134@tcp:12/10 lens 224/224 e 0 to 1 dl 1755096368 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 545.247627] Lustre: DEBUG MARKER: oleg234-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 545.938766] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 548.833399] Lustre: 2379:0:(client.c:2453:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1755096357/real 1755096357] req@ffff9b16106b9f80 x1840351450950016/t0(0) o400->lustre-MDT0000-mdc-ffff9b1618963000@192.168.202.134@tcp:12/10 lens 224/224 e 0 to 1 dl 1755096373 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 550.367810] Lustre: DEBUG MARKER: == sanity test 209: read-only open/close requests should be freed promptly ========================================================== 10:46:14 (1755096374) [ 553.952268] Lustre: 2379:0:(client.c:2453:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1755096362/real 1755096362] req@ffff9b16106ba300 x1840351450950528/t0(0) o400->lustre-MDT0000-mdc-ffff9b1618963000@192.168.202.134@tcp:12/10 lens 224/224 e 0 to 1 dl 1755096378 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 555.762137] bash (47308): drop_caches: 3 [ 559.423583] bash (47308): drop_caches: 3 [ 562.520174] Lustre: DEBUG MARKER: == sanity test 210: lfs getstripe does not break leases == 10:46:26 (1755096386) [ 567.198142] Lustre: DEBUG MARKER: == sanity test 212: Sendfile test ====================================================================================================== 10:46:31 (1755096391) [ 570.718294] Lustre: DEBUG MARKER: == sanity test 213: OSC lock completion and cancel race don't crash - bug 18829 ========================================================== 10:46:35 (1755096395) [ 570.824512] LustreError: 2380:0:(osc_request.c:3105:osc_enqueue_interpret()) cfs_fail_timeout id 40f sleeping for 10000ms [ 580.840130] LustreError: 2380:0:(osc_request.c:3105:osc_enqueue_interpret()) cfs_fail_timeout id 40f awake [ 583.933584] Lustre: DEBUG MARKER: == sanity test 214: hash-indexed directory test - bug 20133 ========================================================== 10:46:48 (1755096408) [ 600.048128] Lustre: DEBUG MARKER: == sanity test 215: lnet exists and has proper content - bugs 18102, 21079, 21517 ========================================================== 10:47:04 (1755096424) [ 603.146992] Lustre: DEBUG MARKER: == sanity test 216: check lockless direct write updates file size and kms correctly ========================================================== 10:47:07 (1755096427) [ 612.328061] Lustre: DEBUG MARKER: == sanity test 217: check lctl ping for hostnames with embedded hyphen ('-') ========================================================== 10:47:16 (1755096436) [ 616.542269] Lustre: DEBUG MARKER: == sanity test 218: parallel read and truncate should not deadlock ========================================================== 10:47:20 (1755096440) [ 617.226291] Lustre: DEBUG MARKER: creating a 10 Mb file [ 629.728502] Lustre: lustre-OST0000-osc-ffff9b1618963000: disconnect after 20s idle [ 629.732517] Lustre: Skipped 1 previous similar message [ 645.746366] Lustre: DEBUG MARKER: starting reads [ 646.851147] Lustre: DEBUG MARKER: truncating the file [ 647.782707] Lustre: DEBUG MARKER: killing dd [ 648.474990] Lustre: DEBUG MARKER: removing the temporary file [ 651.624894] Lustre: DEBUG MARKER: == sanity test 219: LU-394: Write partial won't cause uncontiguous pages vec at LND ========================================================== 10:47:55 (1755096475) [ 651.735874] Lustre: *** cfs_fail_loc=411, val=0*** [ 654.824947] Lustre: DEBUG MARKER: == sanity test 220: preallocated MDS objects still used if ENOSPC from OST ========================================================== 10:47:59 (1755096479) [ 671.237364] Lustre: DEBUG MARKER: == sanity test 221: make sure fault and truncate race to not cause OOM ========================================================== 10:48:15 (1755096495) [ 680.440914] Lustre: DEBUG MARKER: == sanity test 222a: AGL for ls should not trigger CLIO lock failure ========================================================== 10:48:24 (1755096504) [ 683.929962] Lustre: DEBUG MARKER: == sanity test 222b: AGL for rmdir should not trigger CLIO lock failure ========================================================== 10:48:28 (1755096508) [ 687.502974] Lustre: DEBUG MARKER: == sanity test 223: osc reenqueue if without AGL lock granted ================================================================================= 10:48:31 (1755096511) [ 691.117130] Lustre: DEBUG MARKER: == sanity test 224a: Don't panic on bulk IO failure ====== 10:48:35 (1755096515) [ 691.243230] Lustre: *** cfs_fail_loc=508, val=2147483648*** [ 691.246889] LustreError: 2371:0:(events.c:193:client_bulk_callback()) event type 1, status -5, desc ffff9b16125dd400 [ 691.251814] Lustre: 2380:0:(client.c:2453:ptlrpc_expire_one_request()) @@@ Request sent has failed due to network error: [sent 1755096516/real 1755096516] req@ffff9b16187cfb80 x1840351451599744/t0(0) o4->lustre-OST0001-osc-ffff9b1618963000@192.168.202.134@tcp:6/4 lens 488/448 e 0 to 1 dl 1755096532 ref 2 fl Rpc:eXQr/600/ffffffff rc 0/-1 job:'dd.0' uid:0 gid:0 projid:0 [ 691.264390] Lustre: lustre-OST0001-osc-ffff9b1618963000: Connection to lustre-OST0001 (at 192.168.202.134@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 691.278289] Lustre: lustre-OST0001-osc-ffff9b1618963000: Connection restored to (at 192.168.202.134@tcp) [ 691.281325] Lustre: Skipped 1 previous similar message [ 695.202856] Lustre: DEBUG MARKER: == sanity test 224b: Don't panic on bulk IO failure ====== 10:48:39 (1755096519) [ 704.921161] Lustre: DEBUG MARKER: == sanity test 224c: Don't hang if one of md lost during large bulk RPC ========================================================== 10:48:49 (1755096529) [ 715.744980] Lustre: lustre-OST0001-osc-ffff9b1618963000: disconnect after 20s idle [ 717.792403] Lustre: 2380:0:(client.c:2453:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1755096537/real 1755096537] req@ffff9b16187ce680 x1840351451613184/t0(0) o4->lustre-OST0000-osc-ffff9b1618963000@192.168.202.134@tcp:6/4 lens 488/448 e 0 to 1 dl 1755096542 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'dd.0' uid:0 gid:0 projid:0 [ 717.805239] Lustre: lustre-OST0000-osc-ffff9b1618963000: Connection to lustre-OST0000 (at 192.168.202.134@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 717.824195] Lustre: lustre-OST0000-osc-ffff9b1618963000: Connection restored to (at 192.168.202.134@tcp) [ 727.952449] Lustre: DEBUG MARKER: == sanity test 224d: Don't corrupt data on bulk IO timeout ========================================================== 10:49:12 (1755096552) [ 750.560315] Lustre: 2380:0:(client.c:2453:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1755096555/real 1755096555] req@ffff9b16187cd880 x1840351451627136/t0(0) o3->lustre-OST0000-osc-ffff9b1618963000@192.168.202.134@tcp:6/4 lens 488/440 e 0 to 1 dl 1755096575 ref 2 fl Bulk:RXMQU/600/0 rc 0/0 job:'dd.0' uid:0 gid:0 projid:0 [ 750.571071] Lustre: lustre-OST0000-osc-ffff9b1618963000: Connection to lustre-OST0000 (at 192.168.202.134@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 750.577925] LustreError: 2380:0:(client.c:2322:ptlrpc_check_set()) @@@ bulk transfer failed 0/1048576/0 req@ffff9b16187cd880 x1840351451627136/t0(0) o3->lustre-OST0000-osc-ffff9b1618963000@192.168.202.134@tcp:6/4 lens 488/440 e 0 to 1 dl 1755096575 ref 2 fl Bulk:ReXMQU/600/0 rc 0/0 job:'dd.0' uid:0 gid:0 projid:0 [ 750.591612] LustreError: 2380:0:(osc_request.c:2444:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff9b16187cd880 x1840351451627136/t0(0) o3->lustre-OST0000-osc-ffff9b1618963000@192.168.202.134@tcp:6/4 lens 488/440 e 0 to 1 dl 1755096575 ref 2 fl Interpret:ReXMQU/600/0 rc -5/0 job:'dd.0' uid:0 gid:0 projid:0 [ 750.605519] Lustre: lustre-OST0000-osc-ffff9b1618963000: Connection restored to (at 192.168.202.134@tcp) [ 756.232131] Lustre: DEBUG MARKER: SKIP: sanity test_225a skipping excluded test 225a (base 225) [ 757.010281] Lustre: DEBUG MARKER: SKIP: sanity test_225b skipping excluded test 225b (base 225) [ 757.873260] Lustre: DEBUG MARKER: == sanity test 226a: call path2fid and fid2path on files of all type ========================================================== 10:49:42 (1755096582) [ 761.345739] Lustre: DEBUG MARKER: == sanity test 226b: call path2fid and fid2path on files of all type under remote dir ========================================================== 10:49:45 (1755096585) [ 762.143871] Lustre: DEBUG MARKER: SKIP: sanity test_226b needs >= 2 MDTs [ 763.019887] Lustre: DEBUG MARKER: == sanity test 226c: call path2fid and fid2path under remote dir with subdir mount ========================================================== 10:49:47 (1755096587) [ 763.791309] Lustre: DEBUG MARKER: SKIP: sanity test_226c needs >= 2 MDTs [ 764.695394] Lustre: DEBUG MARKER: == sanity test 226d: verify fid2path with -n and -fn option ========================================================== 10:49:48 (1755096588) [ 768.262350] Lustre: DEBUG MARKER: == sanity test 226e: Verify path2fid -0 option with newline and space ========================================================== 10:49:52 (1755096592) [ 771.340333] Lustre: DEBUG MARKER: == sanity test 227: running truncated executable does not cause OOM ========================================================== 10:49:55 (1755096595) [ 774.766764] Lustre: DEBUG MARKER: == sanity test 228a: try to reuse idle OI blocks ========= 10:49:59 (1755096599) [ 775.575501] Lustre: DEBUG MARKER: SKIP: sanity test_228a ldiskfs only test [ 776.419760] Lustre: DEBUG MARKER: == sanity test 228b: idle OI blocks can be reused after MDT restart ========================================================== 10:50:00 (1755096600) [ 777.265407] Lustre: DEBUG MARKER: SKIP: sanity test_228b ldiskfs only test [ 778.110405] Lustre: DEBUG MARKER: == sanity test 228c: NOT shrink the last entry in OI index node to recycle idle leaf ========================================================== 10:50:02 (1755096602) [ 778.936232] Lustre: DEBUG MARKER: SKIP: sanity test_228c ldiskfs only test [ 779.797739] Lustre: DEBUG MARKER: == sanity test 229: getstripe/stat/rm/attr changes work on released files ========================================================== 10:50:04 (1755096604) [ 783.030885] Lustre: DEBUG MARKER: == sanity test 230a: Create remote directory and files under the remote directory ========================================================== 10:50:07 (1755096607) [ 783.727689] Lustre: DEBUG MARKER: SKIP: sanity test_230a needs >= 2 MDTs [ 784.515394] Lustre: DEBUG MARKER: == sanity test 230b: migrate directory =================== 10:50:08 (1755096608) [ 785.190798] Lustre: DEBUG MARKER: SKIP: sanity test_230b needs >= 2 MDTs [ 785.967778] Lustre: DEBUG MARKER: == sanity test 230c: check directory accessiblity if migration failed ========================================================== 10:50:10 (1755096610) [ 786.641660] Lustre: DEBUG MARKER: SKIP: sanity test_230c needs >= 2 MDTs [ 787.323497] Lustre: DEBUG MARKER: SKIP: sanity test_230d skipping SLOW test 230d [ 788.075508] Lustre: DEBUG MARKER: == sanity test 230e: migrate mulitple local link files === 10:50:12 (1755096612) [ 788.761648] Lustre: DEBUG MARKER: SKIP: sanity test_230e needs >= 2 MDTs [ 789.515771] Lustre: DEBUG MARKER: == sanity test 230f: migrate mulitple remote link files == 10:50:13 (1755096613) [ 790.126273] Lustre: DEBUG MARKER: SKIP: sanity test_230f needs >= 2 MDTs [ 790.854319] Lustre: DEBUG MARKER: == sanity test 230g: migrate dir to non-exist MDT ======== 10:50:15 (1755096615) [ 791.491419] Lustre: DEBUG MARKER: SKIP: sanity test_230g needs >= 2 MDTs [ 792.259503] Lustre: DEBUG MARKER: == sanity test 230h: migrate .. and root ================= 10:50:16 (1755096616) [ 792.874741] Lustre: DEBUG MARKER: SKIP: sanity test_230h needs >= 2 MDTs [ 793.585492] Lustre: DEBUG MARKER: == sanity test 230i: lfs migrate -m tolerates trailing slashes ========================================================== 10:50:17 (1755096617) [ 794.244644] Lustre: DEBUG MARKER: SKIP: sanity test_230i needs >= 2 MDTs [ 794.999376] Lustre: DEBUG MARKER: == sanity test 230j: DoM file data not changed after dir migration ========================================================== 10:50:19 (1755096619) [ 795.662669] Lustre: DEBUG MARKER: SKIP: sanity test_230j needs >= 2 MDTs [ 796.419946] Lustre: DEBUG MARKER: == sanity test 230k: file data not changed after dir migration ========================================================== 10:50:20 (1755096620) [ 796.641682] Lustre: lustre-OST0000-osc-ffff9b1618963000: disconnect after 23s idle [ 797.086798] Lustre: DEBUG MARKER: SKIP: sanity test_230k needs >= 4 MDTs [ 797.906394] Lustre: DEBUG MARKER: == sanity test 230l: readdir between MDTs won't crash ==== 10:50:22 (1755096622) [ 798.610424] Lustre: DEBUG MARKER: SKIP: sanity test_230l needs >= 2 MDTs [ 799.415601] Lustre: DEBUG MARKER: == sanity test 230m: xattrs not changed after dir migration ========================================================== 10:50:23 (1755096623) [ 800.172928] Lustre: DEBUG MARKER: SKIP: sanity test_230m needs >= 2 MDTs [ 801.167536] Lustre: DEBUG MARKER: == sanity test 230n: Dir migration with mirrored file ==== 10:50:25 (1755096625) [ 801.918947] Lustre: DEBUG MARKER: SKIP: sanity test_230n needs >= 2 MDTs [ 802.800691] Lustre: DEBUG MARKER: == sanity test 230o: dir split =========================== 10:50:27 (1755096627) [ 803.653754] Lustre: DEBUG MARKER: SKIP: sanity test_230o needs >= 2 MDTs [ 804.506450] Lustre: DEBUG MARKER: == sanity test 230p: dir merge =========================== 10:50:28 (1755096628) [ 805.227347] Lustre: DEBUG MARKER: SKIP: sanity test_230p needs >= 2 MDTs [ 806.042881] Lustre: DEBUG MARKER: == sanity test 230q: dir auto split ====================== 10:50:30 (1755096630) [ 806.753161] Lustre: DEBUG MARKER: SKIP: sanity test_230q needs >= 2 MDTs [ 807.546690] Lustre: DEBUG MARKER: == sanity test 230r: migrate with too many local locks === 10:50:31 (1755096631) [ 808.264332] Lustre: DEBUG MARKER: SKIP: sanity test_230r needs >= 2 MDTs [ 809.068933] Lustre: DEBUG MARKER: == sanity test 230s: lfs mkdir should return -EEXIST if target exists ========================================================== 10:50:33 (1755096633) [ 813.872513] Lustre: DEBUG MARKER: == sanity test 230t: migrate directory with project ID set ========================================================== 10:50:38 (1755096638) [ 814.548764] Lustre: DEBUG MARKER: SKIP: sanity test_230t needs >= 2 MDTs [ 815.316768] Lustre: DEBUG MARKER: == sanity test 230u: migrate directory by QOS ============ 10:50:39 (1755096639) [ 815.977427] Lustre: DEBUG MARKER: SKIP: sanity test_230u needs >= 4 MDTs [ 816.711474] Lustre: DEBUG MARKER: == sanity test 230v: subdir migrated to the MDT where its parent is located ========================================================== 10:50:41 (1755096641) [ 817.356033] Lustre: DEBUG MARKER: SKIP: sanity test_230v needs >= 4 MDTs [ 818.140729] Lustre: DEBUG MARKER: == sanity test 230w: non-recursive mode dir migration ==== 10:50:42 (1755096642) [ 818.811027] Lustre: DEBUG MARKER: SKIP: sanity test_230w needs >= 2 MDTs [ 819.603777] Lustre: DEBUG MARKER: == sanity test 230x: dir migration check space =========== 10:50:43 (1755096643) [ 820.316474] Lustre: DEBUG MARKER: SKIP: sanity test_230x needs >= 2 MDTs [ 821.076636] Lustre: DEBUG MARKER: == sanity test 230y: unlink dir with bad hash type ======= 10:50:45 (1755096645) [ 821.766291] Lustre: DEBUG MARKER: SKIP: sanity test_230y needs >= 2 MDTs [ 822.560546] Lustre: DEBUG MARKER: == sanity test 230z: resume dir migration with bad hash type ========================================================== 10:50:46 (1755096646) [ 823.212845] Lustre: DEBUG MARKER: SKIP: sanity test_230z needs >= 2 MDTs [ 823.968527] Lustre: DEBUG MARKER: == sanity test 231a: checking that reading/writing of BRW RPC size results in one RPC ========================================================== 10:50:48 (1755096648) [ 828.809612] Lustre: DEBUG MARKER: == sanity test 231b: must not assert on fully utilized OST request buffer ========================================================== 10:50:53 (1755096653) [ 852.349399] Lustre: DEBUG MARKER: == sanity test 232a: failed lock should not block umount ========================================================== 10:51:16 (1755096676) [ 852.845183] LustreError: lustre-OST0000-osc-ffff9b1618963000: operation ldlm_enqueue to node 192.168.202.134@tcp failed: rc = -12 [ 853.677075] LustreError: 76337:0:(lov_obd.c:784:lov_cleanup()) lustre-clilov-ffff9b1618963000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 853.688694] LustreError: 76337:0:(obd_class.h:479:obd_check_dev()) Device 5 not setup [ 853.716867] Lustre: Unmounted lustre-client [ 854.037655] Lustre: Mounted lustre-client [ 859.108207] Lustre: lustre-OST0000-osc-ffff9b16105be800: Connection to lustre-OST0000 (at 192.168.202.134@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 859.363258] Lustre: lustre-OST0000-osc-ffff9b16105be800: Connection restored to 192.168.202.134@tcp (at 192.168.202.134@tcp) [ 864.054087] Lustre: DEBUG MARKER: == sanity test 232b: failed data version lock should not block umount ========================================================== 10:51:28 (1755096688) [ 865.493731] LustreError: 77232:0:(lov_obd.c:784:lov_cleanup()) lustre-clilov-ffff9b16105be800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 865.499937] LustreError: 77232:0:(lov_obd.c:784:lov_cleanup()) Skipped 1 previous similar message [ 865.506678] LustreError: 77232:0:(obd_class.h:479:obd_check_dev()) Device 5 not setup [ 865.509262] LustreError: 77232:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 865.533115] Lustre: Unmounted lustre-client [ 865.742767] Lustre: Mounted lustre-client [ 875.461678] Lustre: DEBUG MARKER: == sanity test 233a: checking that OBF of the FS root succeeds ========================================================== 10:51:39 (1755096699) [ 878.586127] Lustre: DEBUG MARKER: == sanity test 233b: checking that OBF of the FS .lustre succeeds ========================================================== 10:51:42 (1755096702) [ 881.791801] Lustre: DEBUG MARKER: == sanity test 234: xattr cache should not crash on ENOMEM ========================================================== 10:51:46 (1755096706) [ 881.984756] Lustre: *** cfs_fail_loc=1405, val=0*** [ 885.055209] Lustre: DEBUG MARKER: == sanity test 235: LU-1715: flock deadlock detection does not work properly ========================================================== 10:51:49 (1755096709) [ 889.981956] Lustre: DEBUG MARKER: == sanity test 236: Layout swap on open unlinked file ==== 10:51:54 (1755096714) [ 893.447225] Lustre: DEBUG MARKER: == sanity test 238: Verify linkea consistency ============ 10:51:57 (1755096717) [ 896.538664] Lustre: DEBUG MARKER: == sanity test 239A: osp_sync test ======================= 10:52:00 (1755096720) [ 946.692673] Lustre: DEBUG MARKER: == sanity test 239a: process invalid osp sync record correctly ========================================================== 10:52:51 (1755096771) [ 964.216465] Lustre: DEBUG MARKER: == sanity test 239b: process osp sync record with ENOMEM error correctly ========================================================== 10:53:08 (1755096788) [ 980.069339] Lustre: DEBUG MARKER: == sanity test 240: race between ldlm enqueue and the connection RPC (no ASSERT) ========================================================== 10:53:24 (1755096804) [ 980.754104] Lustre: DEBUG MARKER: SKIP: sanity test_240 needs >= 2 MDTs [ 981.540941] Lustre: DEBUG MARKER: == sanity test 241a: bio vs dio ========================== 10:53:25 (1755096805) [ 1025.296967] Lustre: DEBUG MARKER: == sanity test 241b: dio vs dio ========================== 10:54:09 (1755096849) [ 1044.155649] Lustre: DEBUG MARKER: == sanity test 242: mdt_readpage failure should not cause directory unreadable ========================================================== 10:54:28 (1755096868) [ 1044.735476] LustreError: lustre-MDT0000-mdc-ffff9b161085c000: operation mds_readpage to node 192.168.202.134@tcp failed: rc = -12 [ 1047.822761] Lustre: DEBUG MARKER: == sanity test 243: various group lock tests ============= 10:54:32 (1755096872) [ 1051.939972] Lustre: 95336:0:(file.c:3143:ll_get_grouplock()) lustre: group lock already exists with gid 97486 on [0x2000013a2:0x1399:0x0]: rc = -22 [ 1051.944124] Lustre: 95336:0:(file.c:3218:ll_put_grouplock()) lustre: no group lock held on [0x2000013a2:0x1399:0x0]: rc = -22 [ 1051.948137] Lustre: 95336:0:(file.c:3125:ll_get_grouplock()) lustre: group id for group lock on [0x2000013a2:0x1399:0x0] is 0: rc = -22 [ 1051.954157] Lustre: 95336:0:(file.c:3228:ll_put_grouplock()) lustre: group lock 4294967286 doesn't match current id 3543 on [0x2000013a2:0x1399:0x0]: rc = -22 [ 1182.968180] Lustre: 95336:0:(file.c:3218:ll_put_grouplock()) lustre: no group lock held on [0x2000013a2:0x13a0:0x0]: rc = -22 [ 1182.986968] Lustre: 95336:0:(file.c:3125:ll_get_grouplock()) lustre: group id for group lock on [0x2000013a2:0x13a0:0x0] is 0: rc = -22 [ 1186.171294] Lustre: DEBUG MARKER: == sanity test 244a: sendfile with group lock tests ====== 10:56:50 (1755097010) [ 1229.903594] Lustre: DEBUG MARKER: == sanity test 244b: multi-threaded write with group lock ========================================================== 10:57:34 (1755097054) [ 1232.863872] Lustre: DEBUG MARKER: == sanity test 245a: check mdc connection flag/data: multiple modify RPCs ========================================================== 10:57:37 (1755097057) [ 1235.408400] Lustre: DEBUG MARKER: == sanity test 245b: check osp connection flag/data: multiple modify RPCs ========================================================== 10:57:39 (1755097059) [ 1236.078181] Lustre: DEBUG MARKER: SKIP: sanity test_245b needs >= 2 MDTs [ 1236.746068] Lustre: DEBUG MARKER: == sanity test 247a: mount subdir as fileset ============= 10:57:41 (1755097061) [ 1236.922056] Lustre: Mounted lustre-client [ 1236.987339] LustreError: 98104:0:(lov_obd.c:784:lov_cleanup()) lustre-clilov-ffff9b16129a3000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 1236.991822] LustreError: 98104:0:(lov_obd.c:784:lov_cleanup()) Skipped 1 previous similar message [ 1236.998176] LustreError: 98104:0:(obd_class.h:479:obd_check_dev()) Device 10 not setup [ 1237.000651] LustreError: 98104:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 1237.015141] Lustre: Unmounted lustre-client [ 1240.039335] Lustre: DEBUG MARKER: == sanity test 247b: mount subdir that dose not exist ==== 10:57:44 (1755097064) [ 1240.183070] LustreError: 98740:0:(llite_lib.c:690:client_common_fill_super()) cannot mds_connect: rc = -2 [ 1240.187893] LustreError: 98740:0:(obd_class.h:479:obd_check_dev()) Device 10 not setup [ 1240.189453] LustreError: 98740:0:(obd_class.h:479:obd_check_dev()) Skipped 11 previous similar messages [ 1240.204222] Lustre: Unmounted lustre-client [ 1240.205746] Lustre: Skipped 1 previous similar message [ 1240.208099] LustreError: 98740:0:(super25.c:181:lustre_fill_super()) llite: Unable to mount : rc = -2 [ 1242.658815] Lustre: DEBUG MARKER: == sanity test 247c: running fid2path outside subdirectory root ========================================================== 10:57:47 (1755097067) [ 1242.846760] Lustre: Mounted lustre-client [ 1242.848419] Lustre: Skipped 1 previous similar message [ 1242.917756] LustreError: 99359:0:(lov_obd.c:784:lov_cleanup()) lustre-clilov-ffff9b1607cf9000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 1242.922166] LustreError: 99359:0:(lov_obd.c:784:lov_cleanup()) Skipped 3 previous similar messages [ 1245.764547] Lustre: DEBUG MARKER: == sanity test 247d: running fid2path inside subdirectory root ========================================================== 10:57:50 (1755097070) [ 1245.999461] LustreError: 100022:0:(obd_class.h:479:obd_check_dev()) Device 10 not setup [ 1246.001345] LustreError: 100022:0:(obd_class.h:479:obd_check_dev()) Skipped 17 previous similar messages [ 1246.014112] Lustre: Unmounted lustre-client [ 1246.015193] Lustre: Skipped 2 previous similar messages [ 1248.810548] Lustre: DEBUG MARKER: == sanity test 247e: mount .. as fileset ================= 10:57:53 (1755097073) [ 1248.957702] Lustre: Mounted lustre-client [ 1248.958715] Lustre: Skipped 3 previous similar messages [ 1249.026526] LustreError: 100684:0:(lov_obd.c:784:lov_cleanup()) lustre-clilov-ffff9b16127aa800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 1249.029602] LustreError: 100684:0:(lov_obd.c:784:lov_cleanup()) Skipped 7 previous similar messages [ 1249.130479] LustreError: lustre-MDT0000-mdc-ffff9b1618963000: operation mds_get_root to node 192.168.202.134@tcp failed: rc = -22 [ 1249.133700] LustreError: 100691:0:(llite_lib.c:690:client_common_fill_super()) cannot mds_connect: rc = -22 [ 1249.153365] LustreError: 100691:0:(super25.c:181:lustre_fill_super()) llite: Unable to mount : rc = -22 [ 1251.462193] Lustre: DEBUG MARKER: == sanity test 247f: mount striped or remote directory as fileset ========================================================== 10:57:55 (1755097075) [ 1252.005891] Lustre: DEBUG MARKER: SKIP: sanity test_247f needs >= 2 MDTs [ 1252.624995] Lustre: DEBUG MARKER: == sanity test 247g: striped directory submount revalidate ROOT from cache ========================================================== 10:57:57 (1755097077) [ 1253.219304] Lustre: DEBUG MARKER: SKIP: sanity test_247g needs > 1 MDTs [ 1253.842190] Lustre: DEBUG MARKER: == sanity test 247h: remote directory submount revalidate ROOT from cache ========================================================== 10:57:58 (1755097078) [ 1254.389878] Lustre: DEBUG MARKER: SKIP: sanity test_247h needs > 1 MDTs [ 1255.039659] Lustre: DEBUG MARKER: == sanity test 248a: fast read verification ============== 10:57:59 (1755097079) [ 1322.003758] Lustre: DEBUG MARKER: == sanity test 248b: test short_io read and write for both small and large sizes ========================================================== 10:59:06 (1755097146) [ 1349.064438] Lustre: DEBUG MARKER: == sanity test 248c: verify whole file read behavior ===== 10:59:33 (1755097173) [ 1361.624553] Lustre: DEBUG MARKER: == sanity test 249: Write above 2T file size ============= 10:59:46 (1755097186) [ 1364.240570] Lustre: DEBUG MARKER: == sanity test 250: Write above 16T limit ================ 10:59:48 (1755097188) [ 1364.855427] Lustre: DEBUG MARKER: SKIP: sanity test_250 no 16TB file size limit on ZFS [ 1365.594271] Lustre: DEBUG MARKER: == sanity test 251a: Handling short read and write correctly ========================================================== 10:59:49 (1755097189) [ 1366.226614] Lustre: *** cfs_fail_loc=1407, val=0*** [ 1368.992544] Lustre: DEBUG MARKER: == sanity test 251b: short read restore offset correctly ========================================================== 10:59:53 (1755097193) [ 1369.072944] LustreError: 105414:0:(file.c:2464:do_file_read_iter()) cfs_fail_timeout id 1431 sleeping for 5000ms [ 1374.176155] LustreError: 105414:0:(file.c:2464:do_file_read_iter()) cfs_fail_timeout id 1431 awake [ 1376.672637] Lustre: DEBUG MARKER: == sanity test 252: check lr_reader tool ================= 11:00:01 (1755097201) [ 1377.491086] Lustre: DEBUG MARKER: SKIP: sanity test_252 ldiskfs only test [ 1378.178077] Lustre: DEBUG MARKER: == sanity test 253: Check object allocation limit ======== 11:00:02 (1755097202) [ 1378.969611] Lustre: DEBUG MARKER: SKIP: sanity test_253 need >= 2.13.57 and ldiskfs for fallocate [ 1379.670910] Lustre: DEBUG MARKER: == sanity test 254: Check changelog size ================= 11:00:04 (1755097204) [ 1385.064265] Lustre: DEBUG MARKER: SKIP: sanity test_255a skipping excluded test 255a (base 255) [ 1385.668555] Lustre: DEBUG MARKER: SKIP: sanity test_255b skipping excluded test 255b (base 255) [ 1386.236358] Lustre: DEBUG MARKER: SKIP: sanity test_255c skipping excluded test 255c (base 255) [ 1386.821129] Lustre: DEBUG MARKER: SKIP: sanity test_256 skipping excluded test 256 [ 1387.443747] Lustre: DEBUG MARKER: == sanity test 257: xattr locks are not lost ============= 11:00:11 (1755097211) [ 1388.111883] LustreError: lustre-MDT0000-mdc-ffff9b161085c000: operation ldlm_enqueue to node 192.168.202.134@tcp failed: rc = -14 [ 1392.610528] LustreError: MGC192.168.202.134@tcp: Connection to MGS (at 192.168.202.134@tcp) was lost; in progress operations using this service will fail [ 1392.616535] Lustre: lustre-MDT0000-mdc-ffff9b161085c000: Connection to lustre-MDT0000 (at 192.168.202.134@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1392.618822] Lustre: Evicted from MGS (at 192.168.202.134@tcp) after server handle changed from 0xf9d39a36c0a79afa to 0xf9d39a36c0b44145 [ 1392.620752] Lustre: Skipped 1 previous similar message [ 1392.626938] Lustre: MGC192.168.202.134@tcp: Connection restored to 192.168.202.134@tcp (at 192.168.202.134@tcp) [ 1392.629386] Lustre: Skipped 1 previous similar message [ 1392.639263] LustreError: 2377:0:(client.c:3395:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9b1621e4b100 x1840351452352768/t12884905703(12884905703) o101->lustre-MDT0000-mdc-ffff9b161085c000@192.168.202.134@tcp:12/10 lens 648/608 e 0 to 0 dl 1755097233 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'bash.0' uid:0 gid:0 projid:0 [ 1392.653701] LustreError: 2377:0:(client.c:3395:ptlrpc_replay_interpret()) Skipped 2 previous similar messages [ 1397.366271] Lustre: DEBUG MARKER: == sanity test 258a: verify i_mutex security behavior when suid attributes is set ========================================================== 11:00:21 (1755097221) [ 1399.967891] Lustre: DEBUG MARKER: == sanity test 258b: verify i_mutex security behavior ==== 11:00:24 (1755097224) [ 1402.428753] Lustre: DEBUG MARKER: == sanity test 259: crash at delayed truncate ============ 11:00:26 (1755097226) [ 1403.020117] Lustre: DEBUG MARKER: SKIP: sanity test_259 ldiskfs only test [ 1403.643971] Lustre: DEBUG MARKER: == sanity test 260: Check mdc_close fail ================= 11:00:28 (1755097228) [ 1403.685427] Lustre: *** cfs_fail_loc=806, val=0*** [ 1403.687363] Lustre: 110253:0:(mdc_request.c:913:mdc_close()) lustre-MDT0000-mdc-ffff9b161085c000: close of FID [0x2000013a2:0x13da:0x0] failed, file reference will be dropped when this client unmounts or is evicted [ 1403.692111] LustreError: 110253:0:(file.c:247:ll_close_inode_openhandle()) lustre-clilmv-ffff9b161085c000: inode [0x2000013a2:0x13da:0x0] mdc close failed: rc = -12 [ 1406.111320] Lustre: DEBUG MARKER: == sanity test 270a: DoM: basic functionality tests ====== 11:00:30 (1755097230) [ 1410.725102] Lustre: DEBUG MARKER: == sanity test 270b: DoM: maximum size overflow checks for DoM-only file ========================================================== 11:00:35 (1755097235) [ 1413.514691] Lustre: DEBUG MARKER: == sanity test 270c: DoM: DoM EA inheritance tests ======= 11:00:37 (1755097237) [ 1416.225087] Lustre: DEBUG MARKER: == sanity test 270d: DoM: change striping from DoM to RAID0 ========================================================== 11:00:40 (1755097240) [ 1418.993588] Lustre: DEBUG MARKER: == sanity test 270e: DoM: lfs find with DoM files test === 11:00:43 (1755097243) [ 1422.239273] Lustre: DEBUG MARKER: == sanity test 270f: DoM: maximum DoM stripe size checks ========================================================== 11:00:46 (1755097246) [ 1429.087260] Lustre: DEBUG MARKER: == sanity test 270g: DoM: default DoM stripe size depends on free space ========================================================== 11:00:53 (1755097253) [ 1438.487848] Lustre: DEBUG MARKER: == sanity test 270h: DoM: DoM stripe removal when disabled on server ========================================================== 11:01:02 (1755097262) [ 1442.121968] Lustre: DEBUG MARKER: == sanity test 270i: DoM: setting invalid DoM striping should fail ========================================================== 11:01:06 (1755097266) [ 1444.930453] Lustre: DEBUG MARKER: == sanity test 270j: DoM migration: DOM file to the OST-striped file (plain) ========================================================== 11:01:09 (1755097269) [ 1448.089044] Lustre: DEBUG MARKER: == sanity test 271a: DoM: data is cached for read after write ========================================================== 11:01:12 (1755097272) [ 1451.122325] Lustre: DEBUG MARKER: == sanity test 271b: DoM: no glimpse RPC for stat (DoM only file) ========================================================== 11:01:15 (1755097275) [ 1453.891448] Lustre: DEBUG MARKER: == sanity test 271ba: DoM: no glimpse RPC for stat (combined file) ========================================================== 11:01:18 (1755097278) [ 1456.817946] Lustre: DEBUG MARKER: == sanity test 271c: DoM: IO lock at open saves enqueue RPCs ========================================================== 11:01:21 (1755097281) [ 1490.343198] Lustre: DEBUG MARKER: == sanity test 271d: DoM: read on open (1K file in reply buffer) ========================================================== 11:01:54 (1755097314) [ 1493.326968] Lustre: DEBUG MARKER: == sanity test 271f: DoM: read on open (200K file and read tail) ========================================================== 11:01:57 (1755097317) [ 1496.079919] Lustre: DEBUG MARKER: == sanity test 271g: Discard DoM data vs client flush race ========================================================== 11:02:00 (1755097320) [ 1497.164459] Lustre: *** cfs_fail_loc=314, val=0*** [ 1499.531854] Lustre: DEBUG MARKER: == sanity test 272a: DoM migration: new layout with the same DOM component ========================================================== 11:02:03 (1755097323) [ 1502.232410] Lustre: DEBUG MARKER: == sanity test 272b: DoM migration: DOM file to the OST-striped file (plain) ========================================================== 11:02:06 (1755097326) [ 1505.982449] Lustre: DEBUG MARKER: == sanity test 272c: DoM migration: DOM file to the OST-striped file (composite) ========================================================== 11:02:10 (1755097330) [ 1509.392175] Lustre: DEBUG MARKER: == sanity test 272d: DoM mirroring: OST-striped mirror to DOM file ========================================================== 11:02:13 (1755097333) [ 1510.463594] LustreError: 123733:0:(file.c:247:ll_close_inode_openhandle()) lustre-clilmv-ffff9b161085c000: inode [0x2000013a2:0x1c12:0x0] mdc close failed: rc = -22 [ 1513.068573] Lustre: DEBUG MARKER: == sanity test 272e: DoM mirroring: DOM mirror to the OST-striped file ========================================================== 11:02:17 (1755097337) [ 1514.775019] LustreError: 124326:0:(file.c:247:ll_close_inode_openhandle()) lustre-clilmv-ffff9b161085c000: inode [0x2000013a2:0x1c16:0x0] mdc close failed: rc = -22 [ 1517.337258] Lustre: DEBUG MARKER: == sanity test 272f: DoM migration: OST-striped file to DOM file ========================================================== 11:02:21 (1755097341) [ 1517.972671] LustreError: 124920:0:(file.c:247:ll_close_inode_openhandle()) lustre-clilmv-ffff9b161085c000: inode [0x2000013a2:0x1c1b:0x0] mdc close failed: rc = -22 [ 1520.512516] Lustre: DEBUG MARKER: == sanity test 273a: DoM: layout swapping should fail with DOM ========================================================== 11:02:24 (1755097344) [ 1523.255943] Lustre: DEBUG MARKER: == sanity test 273b: DoM: race writeback and object destroy ========================================================== 11:02:27 (1755097347) [ 1528.692118] Lustre: DEBUG MARKER: == sanity test 273c: race writeback and object destroy === 11:02:33 (1755097353) [ 1534.217740] Lustre: DEBUG MARKER: == sanity test 275: Read on a canceled duplicate lock ==== 11:02:38 (1755097358) [ 1534.712808] LustreError: 125504:0:(ldlm_lockd.c:2902:ldlm_bl_thread_blwi()) cfs_fail_timeout id 31f sleeping for 4000ms [ 1536.696069] LustreError: 125504:0:(ldlm_lockd.c:2902:ldlm_bl_thread_blwi()) cfs_fail_timeout interrupted [ 1538.551519] Lustre: DEBUG MARKER: == sanity test 276: Race between mount and obd_statfs ==== 11:02:43 (1755097363) [ 1541.091716] Lustre: lustre-OST0000-osc-ffff9b161085c000: Connection to lustre-OST0000 (at 192.168.202.134@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1550.606396] Lustre: lustre-OST0000-osc-ffff9b161085c000: Connection restored to 192.168.202.134@tcp (at 192.168.202.134@tcp) [ 1550.609979] Lustre: Skipped 1 previous similar message [ 1607.651785] Lustre: lustre-OST0000-osc-ffff9b161085c000: Connection to lustre-OST0000 (at 192.168.202.134@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1607.657524] Lustre: Skipped 9 previous similar messages [ 1619.992970] Lustre: lustre-OST0000-osc-ffff9b161085c000: Connection restored to 192.168.202.134@tcp (at 192.168.202.134@tcp) [ 1619.995683] Lustre: Skipped 9 previous similar messages [ 1680.076460] Lustre: DEBUG MARKER: == sanity test 277: Direct IO shall drop page cache ====== 11:05:04 (1755097504) [ 1682.599837] Lustre: DEBUG MARKER: == sanity test 278: Race starting MDS between MDTs stop/start ========================================================== 11:05:07 (1755097507) [ 1683.181650] Lustre: DEBUG MARKER: SKIP: sanity test_278 needs >= 2 MDTs [ 1683.881953] Lustre: DEBUG MARKER: == sanity test 280: Race between MGS umount and client llog processing ========================================================== 11:05:08 (1755097508) [ 1684.345621] LustreError: 133934:0:(lov_obd.c:784:lov_cleanup()) lustre-clilov-ffff9b161085c000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 1684.350277] LustreError: 133934:0:(lov_obd.c:784:lov_cleanup()) Skipped 1 previous similar message [ 1684.354197] LustreError: 133934:0:(obd_class.h:479:obd_check_dev()) Device 5 not setup [ 1684.357296] LustreError: 133934:0:(obd_class.h:479:obd_check_dev()) Skipped 23 previous similar messages [ 1684.376660] Lustre: Unmounted lustre-client [ 1684.377577] Lustre: Skipped 3 previous similar messages [ 1695.202278] LustreError: MGC192.168.202.134@tcp: Connection to MGS (at 192.168.202.134@tcp) was lost; in progress operations using this service will fail [ 1695.208174] LustreError: MGC192.168.202.134@tcp: Confguration from log lustre-client failed from MGS -5. Communication error between node & MGS, a bad configuration, or other errors. See syslog for more info [ 1695.210385] Lustre: Evicted from MGS (at 192.168.202.134@tcp) after server handle changed from 0xf9d39a36c0b74694 to 0xf9d39a36c0b747f9 [ 1695.226983] LustreError: 133956:0:(super25.c:181:lustre_fill_super()) llite: Unable to mount : rc = -5 [ 1706.190952] Lustre: Mounted lustre-client [ 1708.884667] Lustre: DEBUG MARKER: == sanity test 300a: basic striped dir sanity test ======= 11:05:33 (1755097533) [ 1709.542797] Lustre: DEBUG MARKER: SKIP: sanity test_300a needs >= 2 MDTs [ 1710.172796] Lustre: DEBUG MARKER: == sanity test 300b: check ctime/mtime for striped dir === 11:05:34 (1755097534) [ 1710.720556] Lustre: DEBUG MARKER: SKIP: sanity test_300b needs >= 2 MDTs [ 1711.328007] Lustre: DEBUG MARKER: == sanity test 300c: chown [ 1711.884471] Lustre: DEBUG MARKER: SKIP: sanity test_300c needs >= 2 MDTs [ 1712.552537] Lustre: DEBUG MARKER: == sanity test 300d: check default stripe under striped directory ========================================================== 11:05:36 (1755097536) [ 1713.180763] Lustre: DEBUG MARKER: SKIP: sanity test_300d needs >= 2 MDTs [ 1713.900632] Lustre: DEBUG MARKER: == sanity test 300e: check rename under striped directory ========================================================== 11:05:38 (1755097538) [ 1714.515881] Lustre: DEBUG MARKER: SKIP: sanity test_300e needs >= 2 MDTs [ 1715.213263] Lustre: DEBUG MARKER: == sanity test 300f: check rename cross striped directory ========================================================== 11:05:39 (1755097539) [ 1715.846746] Lustre: DEBUG MARKER: SKIP: sanity test_300f needs >= 2 MDTs [ 1716.575763] Lustre: DEBUG MARKER: == sanity test 300g: check default striped directory for normal directory ========================================================== 11:05:40 (1755097540) [ 1717.156670] Lustre: DEBUG MARKER: SKIP: sanity test_300g needs >= 2 MDTs [ 1717.794929] Lustre: DEBUG MARKER: == sanity test 300h: check default striped directory for striped directory ========================================================== 11:05:42 (1755097542) [ 1718.371390] Lustre: DEBUG MARKER: SKIP: sanity test_300h needs >= 2 MDTs [ 1719.096082] Lustre: DEBUG MARKER: == sanity test 300i: client handle unknown hash type striped directory ========================================================== 11:05:43 (1755097543) [ 1719.732870] Lustre: DEBUG MARKER: SKIP: sanity test_300i needs >= 2 MDTs [ 1720.387218] Lustre: DEBUG MARKER: == sanity test 300j: test large update record ============ 11:05:44 (1755097544) [ 1721.018738] Lustre: DEBUG MARKER: SKIP: sanity test_300j needs >= 2 MDTs [ 1721.708661] Lustre: DEBUG MARKER: == sanity test 300k: test large striped directory ======== 11:05:46 (1755097546) [ 1722.339769] Lustre: DEBUG MARKER: SKIP: sanity test_300k needs >= 2 MDTs [ 1723.010350] Lustre: DEBUG MARKER: == sanity test 300l: non-root user to create dir under striped dir with stale layout ========================================================== 11:05:47 (1755097547) [ 1723.670693] Lustre: DEBUG MARKER: SKIP: sanity test_300l needs >= 2 MDTs [ 1724.410676] Lustre: DEBUG MARKER: == sanity test 300m: setstriped directory on single MDT FS ========================================================== 11:05:48 (1755097548) [ 1727.273964] Lustre: DEBUG MARKER: == sanity test 300n: non-root user to create dir under striped dir with default EA ========================================================== 11:05:51 (1755097551) [ 1727.827625] Lustre: DEBUG MARKER: SKIP: sanity test_300n needs >= 2 MDTs [ 1728.469343] Lustre: DEBUG MARKER: SKIP: sanity test_300o skipping SLOW test 300o [ 1729.131219] Lustre: DEBUG MARKER: == sanity test 300p: create striped directory without space ========================================================== 11:05:53 (1755097553) [ 1729.803170] Lustre: DEBUG MARKER: SKIP: sanity test_300p needs >= 2 MDTs [ 1730.508959] Lustre: DEBUG MARKER: == sanity test 300q: create remote directory under orphan directory ========================================================== 11:05:54 (1755097554) [ 1731.102352] Lustre: DEBUG MARKER: SKIP: sanity test_300q needs >= 2 MDTs [ 1731.835296] Lustre: DEBUG MARKER: == sanity test 300r: test -1 striped directory =========== 11:05:56 (1755097556) [ 1732.421416] Lustre: DEBUG MARKER: SKIP: sanity test_300r needs >= 2 MDTs [ 1733.138707] Lustre: DEBUG MARKER: == sanity test 300s: test lfs mkdir -c without -i ======== 11:05:57 (1755097557) [ 1733.783472] Lustre: DEBUG MARKER: SKIP: sanity test_300s needs >= 2 MDTs [ 1734.440719] Lustre: DEBUG MARKER: == sanity test 300t: test max_mdt_stripecount ============ 11:05:58 (1755097558) [ 1735.050787] Lustre: DEBUG MARKER: SKIP: sanity test_300t needs at least 2 MDTs [ 1736.518682] Lustre: DEBUG MARKER: == sanity test 300ua: basic overstriped dir sanity test == 11:06:00 (1755097560) [ 1737.163617] Lustre: DEBUG MARKER: SKIP: sanity test_300ua needs >= 2 MDTs [ 1737.842759] Lustre: DEBUG MARKER: == sanity test 300ub: test MDT overstriping interface [ 1738.478163] Lustre: DEBUG MARKER: SKIP: sanity test_300ub needs >= 2 MDTs [ 1739.181449] Lustre: DEBUG MARKER: == sanity test 300uc: test MDT overstriping as default [ 1739.739940] Lustre: DEBUG MARKER: SKIP: sanity test_300uc needs >= 2 MDTs [ 1740.453700] Lustre: DEBUG MARKER: == sanity test 300ud: dir split ========================== 11:06:04 (1755097564) [ 1741.113423] Lustre: DEBUG MARKER: SKIP: sanity test_300ud needs >= 2 MDTs [ 1741.867995] Lustre: DEBUG MARKER: == sanity test 300ue: dir merge ========================== 11:06:06 (1755097566) [ 1742.494252] Lustre: DEBUG MARKER: SKIP: sanity test_300ue needs >= 2 MDTs [ 1743.186738] Lustre: DEBUG MARKER: == sanity test 300uf: migrate with too many local locks == 11:06:07 (1755097567) [ 1743.809190] Lustre: DEBUG MARKER: SKIP: sanity test_300uf needs >= 2 MDTs [ 1744.476931] Lustre: DEBUG MARKER: == sanity test 300ug: migrate overstriped dirs =========== 11:06:08 (1755097568) [ 1745.105675] Lustre: DEBUG MARKER: SKIP: sanity test_300ug needs >= 2 MDTs [ 1745.808963] Lustre: DEBUG MARKER: == sanity test 300uh: overstripe tunable max_stripes_per_mdt ========================================================== 11:06:10 (1755097570) [ 1746.503120] Lustre: DEBUG MARKER: SKIP: sanity test_300uh needs >= 2 MDTs [ 1747.219827] Lustre: DEBUG MARKER: == sanity test 300ui: overstripe is not supported on one MDT system ========================================================== 11:06:11 (1755097571) [ 1749.887167] Lustre: DEBUG MARKER: == sanity test 300uj: overstriped dir with -C -N sanity test ========================================================== 11:06:14 (1755097574) [ 1750.502684] Lustre: DEBUG MARKER: SKIP: sanity test_300uj needs >= 2 MDTs [ 1751.589615] Lustre: DEBUG MARKER: == sanity test 310a: open unlink remote file ============= 11:06:16 (1755097576) [ 1752.144099] Lustre: DEBUG MARKER: SKIP: sanity test_310a needs >= 4 MDTs [ 1752.797991] Lustre: DEBUG MARKER: == sanity test 310b: unlink remote file with multiple links while open ========================================================== 11:06:17 (1755097577) [ 1753.443031] Lustre: DEBUG MARKER: SKIP: sanity test_310b needs >= 4 MDTs [ 1754.175264] Lustre: DEBUG MARKER: == sanity test 310c: open-unlink remote file with multiple links ========================================================== 11:06:18 (1755097578) [ 1754.760667] Lustre: DEBUG MARKER: SKIP: sanity test_310c needs >= 4 MDTs [ 1755.477753] Lustre: DEBUG MARKER: == sanity test 311: disable OSP precreate, and unlink should destroy objs ========================================================== 11:06:19 (1755097579) [ 1793.286438] Lustre: DEBUG MARKER: SKIP: sanity test_312 skipping ALWAYS excluded test 312 [ 1793.934130] Lustre: DEBUG MARKER: == sanity test 313: io should fail after last_rcvd update fail ========================================================== 11:06:58 (1755097618) [ 1797.197075] Lustre: DEBUG MARKER: == sanity test 314: OSP shouldn't fail after last_rcvd update failure ========================================================== 11:07:01 (1755097621) [ 1819.565897] Lustre: DEBUG MARKER: == sanity test 315: read should be accounted ============= 11:07:24 (1755097644) [ 1826.403801] Lustre: DEBUG MARKER: == sanity test 316: lfs migrate of file with large_xattr enabled ========================================================== 11:07:30 (1755097650) [ 1827.043089] Lustre: DEBUG MARKER: SKIP: sanity test_316 needs >= 2 MDTs [ 1827.739371] Lustre: DEBUG MARKER: == sanity test 317: Verify blocks get correctly update after truncate ========================================================== 11:07:32 (1755097652) [ 1828.334251] Lustre: DEBUG MARKER: SKIP: sanity test_317 LU-10370: no implementation for ZFS [ 1829.052865] Lustre: DEBUG MARKER: == sanity test 318: Verify async readahead tunables ====== 11:07:33 (1755097653) [ 1829.170106] LustreError: 149342:0:(lproc_llite.c:1814:read_ahead_async_file_threshold_mb_store()) lustre: can't set read_ahead_async_file_threshold_mb=65 > max_read_readahead_per_file_mb=64 [ 1831.698085] Lustre: DEBUG MARKER: == sanity test 319: lost lease lock on migrate error ===== 11:07:36 (1755097656) [ 1832.277178] Lustre: DEBUG MARKER: SKIP: sanity test_319 needs >= 2 MDTs [ 1832.913254] Lustre: DEBUG MARKER: == sanity test 350: force NID mismatch path to be exercised ========================================================== 11:07:37 (1755097657) [ 1884.463297] Lustre: DEBUG MARKER: == sanity test 360: ldiskfs unlink in a separate thread == 11:08:28 (1755097708) [ 1885.075138] Lustre: DEBUG MARKER: SKIP: sanity test_360 ldiskfs only test [ 1885.673190] Lustre: DEBUG MARKER: == sanity test 398a: direct IO should cancel lock otherwise lockless ========================================================== 11:08:30 (1755097710) [ 1888.330142] Lustre: DEBUG MARKER: == sanity test 398b: DIO and buffer IO race ============== 11:08:32 (1755097712) [ 2038.103194] Lustre: DEBUG MARKER: == sanity test 398c: run fio to test AIO ================= 11:11:02 (1755097862) [ 2108.356313] Lustre: DEBUG MARKER: == sanity test 398d: run aiocp to verify block size > stripe size ========================================================== 11:12:12 (1755097932) [ 2127.162898] Lustre: DEBUG MARKER: == sanity test 398e: O_Direct open cleared by fcntl doesn't cause hang ========================================================== 11:12:31 (1755097951) [ 2129.619433] Lustre: DEBUG MARKER: == sanity test 398f: verify aio handles ll_direct_rw_pages errors correctly ========================================================== 11:12:34 (1755097954) [ 2136.211917] Lustre: DEBUG MARKER: == sanity test 398g: verify parallel dio async RPC submission ========================================================== 11:12:40 (1755097960) [ 2159.249574] Lustre: DEBUG MARKER: == sanity test 398h: verify correctness of read [ 2173.188356] Lustre: DEBUG MARKER: == sanity test 398i: verify parallel dio handles ll_direct_rw_pages errors correctly ========================================================== 11:13:17 (1755097997) [ 2175.145962] Lustre: *** cfs_fail_loc=1418, val=0*** [ 2177.437729] Lustre: DEBUG MARKER: == sanity test 398j: test parallel dio where stripe size > rpc_size ========================================================== 11:13:21 (1755098001) [ 2191.478631] Lustre: DEBUG MARKER: == sanity test 398k: test enospc on first stripe ========= 11:13:36 (1755098016) [ 2211.020909] Lustre: DEBUG MARKER: SKIP: sanity test_398k 7527424 > 600000 skipping out-of-space test on OST0 [ 2211.647957] Lustre: DEBUG MARKER: == sanity test 398l: test enospc on intermediate stripe/RPC ========================================================== 11:13:56 (1755098036) [ 2221.579064] Lustre: DEBUG MARKER: SKIP: sanity test_398l 7504896 > 600000 skipping out-of-space test on OST0 [ 2241.532694] Lustre: DEBUG MARKER: == sanity test 398m: test RPC failures with parallel dio ========================================================== 11:14:25 (1755098065) [ 2242.123500] LustreError: lustre-OST0000-osc-ffff9b1606470800: operation ost_write to node 192.168.202.134@tcp failed: rc = -5 [ 2242.126065] LustreError: 2379:0:(osc_request.c:2444:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff9b1610752300 x1840351486871680/t0(0) o4->lustre-OST0000-osc-ffff9b1606470800@192.168.202.134@tcp:6/4 lens 488/224 e 0 to 0 dl 1755098083 ref 2 fl Interpret:ReMQU/600/0 rc -5/-5 job:'dd.0' uid:0 gid:0 projid:0 [ 2243.236147] LustreError: lustre-OST0000-osc-ffff9b1606470800: operation ost_write to node 192.168.202.134@tcp failed: rc = -5 [ 2243.236374] LustreError: 2378:0:(osc_request.c:2444:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff9b1610750700 x1840351486872448/t0(0) o4->lustre-OST0000-osc-ffff9b1606470800@192.168.202.134@tcp:6/4 lens 488/224 e 0 to 0 dl 1755098084 ref 2 fl Interpret:ReMQU/600/0 rc -5/-5 job:'ptlrpcd_00_00.0' uid:0 gid:0 projid:0 [ 2243.240444] LustreError: Skipped 4 previous similar messages [ 2243.247466] LustreError: 2378:0:(osc_request.c:2444:osc_brw_redo_request()) Skipped 3 previous similar messages [ 2245.091761] LustreError: lustre-OST0000-osc-ffff9b1606470800: operation ost_write to node 192.168.202.134@tcp failed: rc = -5 [ 2245.094064] LustreError: 2379:0:(osc_request.c:2444:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff9b1608866300 x1840351486874368/t0(0) o4->lustre-OST0000-osc-ffff9b1606470800@192.168.202.134@tcp:6/4 lens 488/224 e 0 to 0 dl 1755098086 ref 2 fl Interpret:ReMQU/600/0 rc -5/-5 job:'ptlrpcd_00_01.0' uid:0 gid:0 projid:0 [ 2245.094364] LustreError: Skipped 3 previous similar messages [ 2245.101051] LustreError: 2379:0:(osc_request.c:2444:osc_brw_redo_request()) Skipped 1 previous similar message [ 2248.163072] LustreError: lustre-OST0000-osc-ffff9b1606470800: operation ost_write to node 192.168.202.134@tcp failed: rc = -5 [ 2248.163208] LustreError: 2378:0:(osc_request.c:2444:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff9b1610751880 x1840351486875520/t0(0) o4->lustre-OST0000-osc-ffff9b1606470800@192.168.202.134@tcp:6/4 lens 488/224 e 0 to 0 dl 1755098089 ref 2 fl Interpret:ReMQU/600/0 rc -5/-5 job:'ptlrpcd_00_00.0' uid:0 gid:0 projid:0 [ 2248.167391] LustreError: Skipped 3 previous similar messages [ 2252.195715] LustreError: lustre-OST0000-osc-ffff9b1606470800: operation ost_write to node 192.168.202.134@tcp failed: rc = -5 [ 2252.198594] LustreError: Skipped 2 previous similar messages [ 2252.200088] LustreError: 2378:0:(osc_request.c:2444:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff9b1610751500 x1840351486876160/t0(0) o4->lustre-OST0000-osc-ffff9b1606470800@192.168.202.134@tcp:6/4 lens 488/224 e 0 to 0 dl 1755098093 ref 2 fl Interpret:ReMQU/600/0 rc -5/-5 job:'ptlrpcd_00_01.0' uid:0 gid:0 projid:0 [ 2252.208261] LustreError: 2378:0:(osc_request.c:2444:osc_brw_redo_request()) Skipped 3 previous similar messages [ 2263.460521] LustreError: lustre-OST0000-osc-ffff9b1606470800: operation ost_write to node 192.168.202.134@tcp failed: rc = -5 [ 2263.463930] LustreError: Skipped 7 previous similar messages [ 2263.465263] LustreError: 2378:0:(osc_request.c:2444:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff9b1608867480 x1840351486878208/t0(0) o4->lustre-OST0000-osc-ffff9b1606470800@192.168.202.134@tcp:6/4 lens 488/224 e 0 to 0 dl 1755098104 ref 2 fl Interpret:ReMQU/600/0 rc -5/-5 job:'ptlrpcd_00_01.0' uid:0 gid:0 projid:0 [ 2263.470542] LustreError: 2378:0:(osc_request.c:2444:osc_brw_redo_request()) Skipped 7 previous similar messages [ 2287.078928] LustreError: lustre-OST0000-osc-ffff9b1606470800: operation ost_write to node 192.168.202.134@tcp failed: rc = -5 [ 2287.083812] LustreError: 2378:0:(osc_request.c:2444:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff9b1608867b80 x1840351486881920/t0(0) o4->lustre-OST0000-osc-ffff9b1606470800@192.168.202.134@tcp:6/4 lens 488/224 e 0 to 0 dl 1755098128 ref 2 fl Interpret:ReMQU/600/0 rc -5/-5 job:'ptlrpcd_00_00.0' uid:0 gid:0 projid:0 [ 2287.085268] LustreError: Skipped 12 previous similar messages [ 2287.101496] LustreError: 2378:0:(osc_request.c:2444:osc_brw_redo_request()) Skipped 11 previous similar messages [ 2297.317501] LustreError: 2379:0:(osc_request.c:2599:brw_interpret()) lustre-OST0000-osc-ffff9b1606470800: too many resent retries for object: 9663677440:4212: rc = -5 [ 2321.893889] LustreError: lustre-OST0000-osc-ffff9b1606470800: operation ost_read to node 192.168.202.134@tcp failed: rc = -5 [ 2321.899360] LustreError: Skipped 30 previous similar messages [ 2321.902180] LustreError: 2379:0:(osc_request.c:2444:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff9b1610751c00 x1840351486910848/t0(0) o3->lustre-OST0000-osc-ffff9b1606470800@192.168.202.134@tcp:6/4 lens 488/440 e 0 to 0 dl 1755098162 ref 2 fl Interpret:ReMQU/600/0 rc -5/-5 job:'ptlrpcd_00_00.0' uid:0 gid:0 projid:0 [ 2321.916208] LustreError: 2379:0:(osc_request.c:2444:osc_brw_redo_request()) Skipped 24 previous similar messages [ 2356.714836] LustreError: 2379:0:(osc_request.c:2599:brw_interpret()) lustre-OST0000-osc-ffff9b1606470800: too many resent retries for object: 9663677440:4211: rc = -5 [ 2356.722988] LustreError: 2379:0:(osc_request.c:2599:brw_interpret()) Skipped 3 previous similar messages [ 2387.431522] LustreError: lustre-OST0001-osc-ffff9b1606470800: operation ost_write to node 192.168.202.134@tcp failed: rc = -5 [ 2387.436774] LustreError: Skipped 47 previous similar messages [ 2387.439676] LustreError: 2378:0:(osc_request.c:2444:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff9b1608865880 x1840351486929792/t0(0) o4->lustre-OST0001-osc-ffff9b1606470800@192.168.202.134@tcp:6/4 lens 488/224 e 0 to 0 dl 1755098228 ref 2 fl Interpret:ReMQU/600/0 rc -5/-5 job:'ptlrpcd_00_01.0' uid:0 gid:0 projid:0 [ 2387.452873] LustreError: 2378:0:(osc_request.c:2444:osc_brw_redo_request()) Skipped 43 previous similar messages [ 2415.075441] LustreError: 2379:0:(osc_request.c:2599:brw_interpret()) lustre-OST0001-osc-ffff9b1606470800: too many resent retries for object: 10737419264:3107: rc = -5 [ 2415.080320] LustreError: 2379:0:(osc_request.c:2599:brw_interpret()) Skipped 3 previous similar messages [ 2473.379587] LustreError: 2381:0:(osc_request.c:2599:brw_interpret()) lustre-OST0001-osc-ffff9b1606470800: too many resent retries for object: 10737419264:3106: rc = -5 [ 2473.385019] LustreError: 2381:0:(osc_request.c:2599:brw_interpret()) Skipped 3 previous similar messages [ 2476.940753] Lustre: DEBUG MARKER: == sanity test 398n: test append with parallel DIO ======= 11:18:21 (1755098301) [ 2489.859756] Lustre: DEBUG MARKER: == sanity test 398o: right kms with DIO ================== 11:18:34 (1755098314) [ 2492.891572] Lustre: DEBUG MARKER: == sanity test 398p: race aio with buffered i/o ========== 11:18:37 (1755098317) [ 2546.800291] Lustre: DEBUG MARKER: == sanity test 398q: race dio with buffered i/o ========== 11:19:30 (1755098370) [ 2675.992741] Lustre: DEBUG MARKER: == sanity test 398r: i/o error on file read ============== 11:21:40 (1755098500) [ 2676.634955] LustreError: lustre-OST0000-osc-ffff9b1606470800: operation ost_read to node 192.168.202.134@tcp failed: rc = -5 [ 2676.640113] LustreError: Skipped 59 previous similar messages [ 2676.642802] LustreError: 2380:0:(osc_request.c:2444:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff9b1602a25c00 x1840351492923776/t0(0) o3->lustre-OST0000-osc-ffff9b1606470800@192.168.202.134@tcp:6/4 lens 488/4536 e 0 to 0 dl 1755098517 ref 2 fl Interpret:RMQU/600/0 rc -5/-5 job:'cat.0' uid:0 gid:0 projid:0 [ 2676.656081] LustreError: 2380:0:(osc_request.c:2444:osc_brw_redo_request()) Skipped 51 previous similar messages [ 2732.514515] LustreError: 2380:0:(osc_request.c:2599:brw_interpret()) lustre-OST0000-osc-ffff9b1606470800: too many resent retries for object: 9663677440:4223: rc = -5 [ 2732.519506] LustreError: 2380:0:(osc_request.c:2599:brw_interpret()) Skipped 3 previous similar messages [ 2735.222695] Lustre: DEBUG MARKER: == sanity test 398s: i/o error on mirror file read ======= 11:22:39 (1755098559) [ 2738.642473] Lustre: DEBUG MARKER: == sanity test 399a: fake write should not be slower than normal write ========================================================== 11:22:43 (1755098563) [ 2797.116815] Lustre: DEBUG MARKER: sanity test_399a: @@@@@@ IGNORE (env=kvm): fake write is slower [ 2800.686616] Lustre: DEBUG MARKER: == sanity test 399b: fake read should not be slower than normal read ========================================================== 11:23:44 (1755098624) [ 2801.646782] Lustre: DEBUG MARKER: SKIP: sanity test_399b ldiskfs only test [ 2802.595178] Lustre: DEBUG MARKER: SKIP: sanity test_400a skipping excluded test 400a [ 2803.504842] Lustre: DEBUG MARKER: == sanity test 400b: packaged headers can be compiled ==== 11:23:47 (1755098627) [ 2806.836533] Lustre: DEBUG MARKER: == sanity test 401a: Verify if 'lctl list_param -R' can list parameters recursively ========================================================== 11:23:51 (1755098631) [ 2810.465446] Lustre: DEBUG MARKER: == sanity test 401aa: Verify that 'lctl list_param -p' lists the correct path names ========================================================== 11:23:54 (1755098634) [ 2814.192603] Lustre: DEBUG MARKER: == sanity test 401ab: Check that 'lctl list_param -r' lists only readable params ========================================================== 11:23:58 (1755098638) [ 2818.001626] Lustre: DEBUG MARKER: == sanity test 401ac: Check that 'lctl list_param -w' lists only writable params ========================================================== 11:24:02 (1755098642) [ 2821.494345] Lustre: DEBUG MARKER: == sanity test 401ad: Check that 'lctl list_param -wr' is conjunctive ========================================================== 11:24:05 (1755098645) [ 2824.648152] Lustre: DEBUG MARKER: == sanity test 401b: Verify 'lctl get_param' set_param' continue after error ========================================================== 11:24:08 (1755098648) [ 2828.045156] Lustre: DEBUG MARKER: == sanity test 401c: Verify 'lctl set_param' without value fails in either format. ========================================================== 11:24:12 (1755098652) [ 2830.995375] Lustre: DEBUG MARKER: == sanity test 401d: Verify 'lctl set_param' accepts values containing '=' ========================================================== 11:24:15 (1755098655) [ 2833.832778] Lustre: DEBUG MARKER: == sanity test 401db: Verify 'lctl set_param' does not add trailing '=' ========================================================== 11:24:18 (1755098658) [ 2933.514563] Lustre: DEBUG MARKER: == sanity test 401e: verify 'lctl get_param' works with NID in parameter ========================================================== 11:25:57 (1755098757) [ 2936.734512] Lustre: DEBUG MARKER: == sanity test 401f: check 'lctl list_param' doesn't follow symlinks with --no-links ========================================================== 11:26:00 (1755098760) [ 2939.843419] Lustre: DEBUG MARKER: == sanity test 401ga: check 'set_param -C' sets params upon mount ========================================================== 11:26:04 (1755098764) [ 2940.184530] LustreError: 173084:0:(lov_obd.c:784:lov_cleanup()) lustre-clilov-ffff9b1606470800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 2940.187397] LustreError: 173084:0:(lov_obd.c:784:lov_cleanup()) Skipped 1 previous similar message [ 2940.189753] LustreError: 173084:0:(obd_class.h:479:obd_check_dev()) Device 5 not setup [ 2940.191311] LustreError: 173084:0:(obd_class.h:479:obd_check_dev()) Skipped 15 previous similar messages [ 2940.203084] Lustre: Unmounted lustre-client [ 2940.203977] Lustre: Skipped 1 previous similar message [ 2940.319759] Lustre: Mounted lustre-client [ 2943.473460] Lustre: DEBUG MARKER: == sanity test 401gb: check 'set_param -d -C' removes client params ========================================================== 11:26:07 (1755098767) [ 2943.890573] LustreError: 173742:0:(lov_obd.c:784:lov_cleanup()) lustre-clilov-ffff9b16127ac800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 2943.893844] LustreError: 173742:0:(lov_obd.c:784:lov_cleanup()) Skipped 1 previous similar message [ 2943.898282] LustreError: 173742:0:(obd_class.h:479:obd_check_dev()) Device 5 not setup [ 2943.900143] LustreError: 173742:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 2943.914630] Lustre: Unmounted lustre-client [ 2944.083612] Lustre: Mounted lustre-client [ 2947.484782] Lustre: DEBUG MARKER: == sanity test 402: Return ENOENT to lod_generate_and_set_lovea ========================================================== 11:26:11 (1755098771) [ 2951.394254] Lustre: DEBUG MARKER: == sanity test 403: i_nlink should not drop to zero due to aliasing ========================================================== 11:26:15 (1755098775) [ 2951.745220] sysctl (174990): drop_caches: 2 [ 2954.763308] Lustre: DEBUG MARKER: == sanity test 404: validate manual {de}activated works properly for OSPs ========================================================== 11:26:19 (1755098779) [ 2959.530305] Lustre: DEBUG MARKER: == sanity test 405: Various layout swap lock tests ======= 11:26:24 (1755098784) [ 2961.405750] Lustre: DEBUG MARKER: SKIP: sanity test_405 layout swap does not support DOM files so far [ 2962.219630] Lustre: DEBUG MARKER: == sanity test 406: DNE support fs default striping ====== 11:26:26 (1755098786) [ 2962.991780] Lustre: DEBUG MARKER: SKIP: sanity test_406 needs >= 2 MDTs [ 2963.842411] Lustre: DEBUG MARKER: SKIP: sanity test_407 skipping ALWAYS excluded test 407 [ 2964.802322] Lustre: DEBUG MARKER: == sanity test 408: drop_caches should not hang due to page leaks ========================================================== 11:26:28 (1755098788) [ 2964.917348] Lustre: *** cfs_fail_loc=40a, val=0*** [ 2964.919442] LustreError: 2380:0:(osc_request.c:2866:osc_build_rpc()) lustre-OST0001-osc-ffff9b1610746800: prep_req failed: rc = -22 [ 2964.924287] LustreError: 2380:0:(osc_cache.c:2197:osc_check_rpcs()) Read request failed with -22 [ 2968.505213] bash (176833): drop_caches: 2 [ 2972.229815] Lustre: DEBUG MARKER: == sanity test 409: Large amount of cross-MDTs hard links on the same file ========================================================== 11:26:36 (1755098796) [ 2973.005644] Lustre: DEBUG MARKER: SKIP: sanity test_409 needs >= 2 MDTs [ 2973.938269] Lustre: DEBUG MARKER: == sanity test 410: Test inode number returned from kernel thread ========================================================== 11:26:38 (1755098798) [ 2974.114270] lustre_kinode_20058: CONFIG_X86_X32 is not set [ 2974.121625] lustre_kinode_20058: inode is 144115339507007594 [ 2974.124782] lustre_kinode_20058: inode is 144115339507007594 [ 2974.127322] lustre_kinode_20058: inode numbers are identical: 144115339507007594 [ 2977.439637] Lustre: DEBUG MARKER: SKIP: sanity test_411a skipping ALWAYS excluded test 411a [ 2978.350239] Lustre: DEBUG MARKER: == sanity test 411b: confirm Lustre can avoid OOM with reasonable cgroups limits ========================================================== 11:26:42 (1755098802) [ 3386.102107] Lustre: DEBUG MARKER: SKIP: sanity test_411b OST space are too small: 3762176K [ 3387.109425] Lustre: DEBUG MARKER: == sanity test 412: mkdir on specific MDTs =============== 11:33:31 (1755099211) [ 3387.923431] Lustre: DEBUG MARKER: SKIP: sanity test_412 needs >= 2 MDTs [ 3388.857610] Lustre: DEBUG MARKER: == sanity test 413a: QoS mkdir with 'lfs mkdir -i -1' ==== 11:33:33 (1755099213) [ 3389.654898] Lustre: DEBUG MARKER: SKIP: sanity test_413a We need at least 2 MDTs for this test [ 3390.595480] Lustre: DEBUG MARKER: == sanity test 413b: QoS mkdir under dir whose default LMV starting MDT offset is -1 ========================================================== 11:33:34 (1755099214) [ 3391.341116] Lustre: DEBUG MARKER: SKIP: sanity test_413b We need at least 2 MDTs for this test [ 3392.262318] Lustre: DEBUG MARKER: == sanity test 413c: mkdir with default LMV max inherit rr ========================================================== 11:33:36 (1755099216) [ 3393.084925] Lustre: DEBUG MARKER: SKIP: sanity test_413c We need at least 2 MDTs for this test [ 3394.014997] Lustre: DEBUG MARKER: == sanity test 413d: inherit ROOT default LMV ============ 11:33:38 (1755099218) [ 3394.825990] Lustre: DEBUG MARKER: SKIP: sanity test_413d We need at least 2 MDTs for this test [ 3395.763265] Lustre: DEBUG MARKER: == sanity test 413e: check default max-inherit value ===== 11:33:39 (1755099219) [ 3396.580063] Lustre: DEBUG MARKER: SKIP: sanity test_413e We need at least 2 MDTs for this test [ 3397.506414] Lustre: DEBUG MARKER: == sanity test 413f: lfs getdirstripe -D list ROOT default LMV if it's not set on dir ========================================================== 11:33:41 (1755099221) [ 3398.294992] Lustre: DEBUG MARKER: SKIP: sanity test_413f We need at least 2 MDTs for this test [ 3399.217286] Lustre: DEBUG MARKER: == sanity test 413g: enforce ROOT default LMV on subdir mount ========================================================== 11:33:43 (1755099223) [ 3400.063284] Lustre: DEBUG MARKER: SKIP: sanity test_413g We need at least 2 MDTs for this test [ 3401.025906] Lustre: DEBUG MARKER: == sanity test 413h: don't stick to parent for round-robin dirs ========================================================== 11:33:45 (1755099225) [ 3401.820363] Lustre: DEBUG MARKER: SKIP: sanity test_413h We need at least 2 MDTs for this test [ 3402.793374] Lustre: DEBUG MARKER: == sanity test 413i: check default layout inheritance ==== 11:33:46 (1755099226) [ 3403.574220] Lustre: DEBUG MARKER: SKIP: sanity test_413i needs >= 2 MDTs [ 3404.499916] Lustre: DEBUG MARKER: == sanity test 413j: set default LMV by setxattr ========= 11:33:48 (1755099228) [ 3405.336490] Lustre: DEBUG MARKER: SKIP: sanity test_413j needs >= 2 MDTs [ 3406.194594] Lustre: DEBUG MARKER: == sanity test 413k: QoS mkdir exclude prefixes ========== 11:33:50 (1755099230) [ 3410.182386] Lustre: DEBUG MARKER: == sanity test 413z: 413 test cleanup ==================== 11:33:54 (1755099234) [ 3413.470639] Lustre: DEBUG MARKER: == sanity test 414: simulate ENOMEM in ptlrpc_register_bulk() ========================================================== 11:33:57 (1755099237) [ 3414.149277] LustreError: 183358:0:(lov_obd.c:784:lov_cleanup()) lustre-clilov-ffff9b1610746800: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 3414.153827] LustreError: 183358:0:(lov_obd.c:784:lov_cleanup()) Skipped 1 previous similar message [ 3414.160884] LustreError: 183358:0:(obd_class.h:479:obd_check_dev()) Device 5 not setup [ 3414.163827] LustreError: 183358:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 3414.195185] Lustre: Unmounted lustre-client [ 3414.438251] Lustre: Mounted lustre-client [ 3417.858800] Lustre: DEBUG MARKER: == sanity test 415: lock revoke is not missing =========== 11:34:02 (1755099242) [ 3444.785399] Lustre: DEBUG MARKER: == sanity test 416: transaction start failure won't cause system hung ========================================================== 11:34:28 (1755099268) [ 3448.509595] Lustre: DEBUG MARKER: == sanity test 417: disable remote dir, striped dir and dir migration ========================================================== 11:34:32 (1755099272) [ 3449.317161] Lustre: DEBUG MARKER: SKIP: sanity test_417 needs >= 2 MDTs [ 3450.273196] Lustre: DEBUG MARKER: == sanity test 418: df and lfs df outputs match ========== 11:34:34 (1755099274) [ 3484.811258] Lustre: DEBUG MARKER: == sanity test 419: Verify open file by name doesn't crash kernel ========================================================== 11:35:09 (1755099309) [ 3488.464773] Lustre: DEBUG MARKER: == sanity test 420: clear SGID bit on non-directories for non-members ========================================================== 11:35:12 (1755099312) [ 3492.039344] Lustre: DEBUG MARKER: == sanity test 421a: simple rm by fid ==================== 11:35:16 (1755099316) [ 3495.655371] Lustre: DEBUG MARKER: == sanity test 421b: rm by fid on open file ============== 11:35:19 (1755099319) [ 3499.173316] Lustre: DEBUG MARKER: == sanity test 421c: rm by fid against hardlinked files == 11:35:23 (1755099323) [ 3504.502349] Lustre: DEBUG MARKER: == sanity test 421d: rmfid en masse ====================== 11:35:28 (1755099328) [ 3553.810346] Lustre: DEBUG MARKER: == sanity test 421e: rmfid in DNE ======================== 11:36:18 (1755099378) [ 3554.825857] Lustre: DEBUG MARKER: SKIP: sanity test_421e needs >= 2 MDTs [ 3555.745776] Lustre: DEBUG MARKER: == sanity test 421f: rmfid checks permissions ============ 11:36:19 (1755099379) [ 3556.517498] Lustre: Mounted lustre-client [ 3559.536215] LustreError: 192094:0:(lov_obd.c:784:lov_cleanup()) lustre-clilov-ffff9b1607e68000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 3559.540252] LustreError: 192094:0:(lov_obd.c:784:lov_cleanup()) Skipped 1 previous similar message [ 3559.546369] LustreError: 192094:0:(obd_class.h:479:obd_check_dev()) Device 10 not setup [ 3559.548369] LustreError: 192094:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 3559.565135] Lustre: Unmounted lustre-client [ 3560.188133] Lustre: DEBUG MARKER: == sanity test 421g: rmfid to return errors properly ===== 11:36:24 (1755099384) [ 3560.979492] Lustre: DEBUG MARKER: SKIP: sanity test_421g needs >= 2 MDTs [ 3561.892740] Lustre: DEBUG MARKER: == sanity test 421h: rmfid with fileset mount ============ 11:36:26 (1755099386) [ 3566.019678] Lustre: DEBUG MARKER: == sanity test 422: kill a process with RPC in progress == 11:36:30 (1755099390) [ 3588.064083] Lustre: 193352:0:(client.c:2453:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1755099392/real 1755099392] req@ffff9b1634ec2300 x1840351499373056/t0(0) o101->lustre-MDT0000-mdc-ffff9b16105bf000@192.168.202.134@tcp:12/10 lens 576/1376 e 0 to 1 dl 1755099412 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'touch.0' uid:0 gid:0 projid:0 [ 3588.071468] Lustre: lustre-MDT0000-mdc-ffff9b16105bf000: Connection to lustre-MDT0000 (at 192.168.202.134@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 3588.075105] Lustre: Skipped 9 previous similar messages [ 3588.087580] Lustre: lustre-MDT0000-mdc-ffff9b16105bf000: Connection restored to 192.168.202.134@tcp (at 192.168.202.134@tcp) [ 3588.090182] Lustre: Skipped 9 previous similar messages [ 3608.544274] Lustre: 193352:0:(client.c:2453:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1755099413/real 1755099413] req@ffff9b1634ec2300 x1840351499373056/t0(0) o101->lustre-MDT0000-mdc-ffff9b16105bf000@192.168.202.134@tcp:12/10 lens 576/1376 e 0 to 1 dl 1755099433 ref 2 fl Rpc:XQr/602/ffffffff rc 0/-1 job:'touch.0' uid:0 gid:0 projid:0 [ 3608.544501] Lustre: lustre-MDT0000-mdc-ffff9b16105bf000: Connection to lustre-MDT0000 (at 192.168.202.134@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 3608.558393] Lustre: 193352:0:(client.c:2453:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 3608.577476] Lustre: lustre-MDT0000-mdc-ffff9b16105bf000: Connection restored to 192.168.202.134@tcp (at 192.168.202.134@tcp) [ 3611.040743] Lustre: DEBUG MARKER: touch [ 3629.024194] Lustre: 193352:0:(client.c:2453:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1755099433/real 1755099433] req@ffff9b1634ec2300 x1840351499373056/t0(0) o101->lustre-MDT0000-mdc-ffff9b16105bf000@192.168.202.134@tcp:12/10 lens 576/1376 e 0 to 1 dl 1755099453 ref 2 fl Rpc:XQr/602/ffffffff rc 0/-1 job:'touch.0' uid:0 gid:0 projid:0 [ 3633.881812] Lustre: DEBUG MARKER: == sanity test 423: statfs should return a right data ==== 11:37:38 (1755099458) [ 3639.284851] Lustre: DEBUG MARKER: == sanity test 424: simulate ENOMEM in ptl_send_rpc bulk reply ME attach ========================================================== 11:37:43 (1755099463) [ 3639.420884] Lustre: *** cfs_fail_loc=522, val=0*** [ 3639.422078] LustreError: 2380:0:(niobuf.c:996:ptl_send_rpc()) LNetMEAttach failed: -12 [ 3642.745440] Lustre: DEBUG MARKER: == sanity test 425: lock count should not exceed lru size ========================================================== 11:37:46 (1755099466) [ 3654.725529] Lustre: DEBUG MARKER: == sanity test 426: splice test on Lustre ================ 11:37:58 (1755099478) [ 3658.877650] Lustre: DEBUG MARKER: == sanity test 427: Failed DNE2 update request shouldn't corrupt updatelog ========================================================== 11:38:03 (1755099483) [ 3659.662386] Lustre: DEBUG MARKER: SKIP: sanity test_427 needs >= 2 MDTs [ 3660.611375] Lustre: DEBUG MARKER: == sanity test 428: large block size IO should not hang == 11:38:04 (1755099484) [ 3736.799415] Lustre: DEBUG MARKER: == sanity test 429: verify if opencache flag on client side does work ========================================================== 11:39:20 (1755099560) [ 3740.403731] Lustre: DEBUG MARKER: == sanity test 430a: lseek: SEEK_DATA/SEEK_HOLE basic functionality ========================================================== 11:39:24 (1755099564) [ 3741.117858] Lustre: DEBUG MARKER: SKIP: sanity test_430a MDT does not support SEEK_HOLE [ 3741.865163] Lustre: DEBUG MARKER: == sanity test 430b: lseek: SEEK_DATA/SEEK_HOLE special cases ========================================================== 11:39:26 (1755099566) [ 3742.687357] Lustre: DEBUG MARKER: SKIP: sanity test_430b OST does not support SEEK_HOLE [ 3743.604971] Lustre: DEBUG MARKER: == sanity test 430c: lseek: external tools check ========= 11:39:27 (1755099567) [ 3744.430215] Lustre: DEBUG MARKER: SKIP: sanity test_430c OST does not support SEEK_HOLE [ 3745.399883] Lustre: DEBUG MARKER: == sanity test 431: Restart transaction for IO =========== 11:39:29 (1755099569) [ 3748.417994] bash (198716): drop_caches: 3 [ 3752.276982] Lustre: DEBUG MARKER: == sanity test 432: mv dir from outside Lustre =========== 11:39:36 (1755099576) [ 3803.535282] Lustre: DEBUG MARKER: == sanity test 433: ldlm lock cancel releases dentries and inodes ========================================================== 11:40:27 (1755099627) [ 3821.955514] Lustre: DEBUG MARKER: == sanity test 434: Client should not send RPCs for security.selinux with SElinux disabled ========================================================== 11:40:46 (1755099646) [ 3829.525654] Lustre: DEBUG MARKER: == sanity test 440: bash completion for lfs, lctl ======== 11:40:53 (1755099653) [ 3832.914234] Lustre: DEBUG MARKER: == sanity test 442: truncate vs read/write should not panic ========================================================== 11:40:57 (1755099657) [ 3834.067672] LustreError: 202833:0:(llite_lib.c:3149:ll_truncate_inode_pages_final()) cfs_fail_timeout id 1430 sleeping for 5000ms [ 3839.168143] LustreError: 202833:0:(llite_lib.c:3149:ll_truncate_inode_pages_final()) cfs_fail_timeout id 1430 awake [ 3842.489350] Lustre: DEBUG MARKER: == sanity test 460d: Check encrypt pools output ========== 11:41:06 (1755099666) [ 3846.246233] Lustre: DEBUG MARKER: == sanity test 600a: basic test for mlock()ed file ======= 11:41:10 (1755099670) [ 3847.130072] Lustre: DEBUG MARKER: SKIP: sanity test_600a This test needs vmtouch utility [ 3848.067289] Lustre: DEBUG MARKER: == sanity test 600b: mlock a file (via vmtouch) larger than max_cached_mb ========================================================== 11:41:12 (1755099672) [ 3848.944646] Lustre: DEBUG MARKER: SKIP: sanity test_600b This test needs vmtouch utility [ 3849.835962] Lustre: DEBUG MARKER: == sanity test 600c: Test I/O when mlocked page count > @max_cached_mb ========================================================== 11:41:14 (1755099674) [ 3850.711565] Lustre: DEBUG MARKER: SKIP: sanity test_600c This test needs vmtouch utility [ 3851.661905] Lustre: DEBUG MARKER: == sanity test 600d: Test I/O with limited LRU page slots (some was mlocked) ========================================================== 11:41:15 (1755099675) [ 3852.552404] Lustre: DEBUG MARKER: SKIP: sanity test_600d This test needs vmtouch utility [ 3853.505250] Lustre: DEBUG MARKER: == sanity test 801a: write barrier user interfaces and stat machine ========================================================== 11:41:17 (1755099677) [ 3889.843419] Lustre: DEBUG MARKER: == sanity test 801b: modification will be blocked by write barrier ========================================================== 11:41:54 (1755099714) [ 3893.928793] Lustre: 206535:0:(client.c:1611:after_reply()) @@@ resending request on EINPROGRESS req@ffff9b163696fb80 x1840351503475200/t0(0) o36->lustre-MDT0000-mdc-ffff9b16105bf000@192.168.202.134@tcp:12/10 lens 488/456 e 0 to 0 dl 1755099774 ref 2 fl Rpc:RQU/202/0 rc 0/-115 job:'rm.0' uid:0 gid:0 projid:4294967295 [ 3893.934621] Lustre: 206535:0:(client.c:1611:after_reply()) Skipped 2 previous similar messages [ 3901.697796] Lustre: DEBUG MARKER: == sanity test 801c: rescan barrier bitmap =============== 11:42:06 (1755099726) [ 3902.215181] Lustre: DEBUG MARKER: SKIP: sanity test_801c needs >= 2 MDTs [ 3902.798267] Lustre: DEBUG MARKER: == sanity test 802b: be able to set MDTs to readonly ===== 11:42:07 (1755099727) [ 3907.316954] Lustre: DEBUG MARKER: == sanity test 802c: be able to set OFDs to readonly ===== 11:42:11 (1755099731) [ 3913.285294] Lustre: DEBUG MARKER: == sanity test 803a: verify agent object for remote object ========================================================== 11:42:17 (1755099737) [ 3913.956333] Lustre: DEBUG MARKER: SKIP: sanity test_803a needs >= 2 MDTs [ 3914.808311] Lustre: DEBUG MARKER: == sanity test 803b: remote object can getattr from cache ========================================================== 11:42:19 (1755099739) [ 3915.641111] Lustre: DEBUG MARKER: SKIP: sanity test_803b needs >= 2 MDTs [ 3916.595975] Lustre: DEBUG MARKER: == sanity test 804: verify agent entry for remote entry == 11:42:20 (1755099740) [ 3917.408732] Lustre: DEBUG MARKER: SKIP: sanity test_804 needs >= 2 MDTs [ 3918.216601] Lustre: DEBUG MARKER: == sanity test 805: ZFS can remove from full fs ========== 11:42:22 (1755099742) [ 3986.444927] LustreError: 210205:0:(file.c:247:ll_close_inode_openhandle()) lustre-clilmv-ffff9b16105bf000: inode [0x200002343:0x1720:0x0] mdc close failed: rc = -122 [ 4028.596563] Lustre: DEBUG MARKER: == sanity test 806: Verify Lazy Size on MDS ============== 11:44:12 (1755099852) [ 4040.892080] Lustre: DEBUG MARKER: == sanity test 807a: verify LSOM syncing tool ============ 11:44:25 (1755099865) [ 4044.773703] Lustre: DEBUG MARKER: oleg234-client.virtnet: executing cancel_lru_locks osc [ 4053.762607] Lustre: DEBUG MARKER: == sanity test 807b: verify lfs somsync utility ========== 11:44:38 (1755099878) [ 4055.289697] Lustre: DEBUG MARKER: oleg234-client.virtnet: executing cancel_lru_locks osc [ 4063.635618] Lustre: DEBUG MARKER: == sanity test 808: Check trusted.som xattr not logged in Changelogs ========================================================== 11:44:47 (1755099887) [ 4070.497061] Lustre: DEBUG MARKER: == sanity test 809: Verify no SOM xattr store for DoM-only files ========================================================== 11:44:54 (1755099894) [ 4074.059626] Lustre: DEBUG MARKER: == sanity test 810: partial page writes on ZFS (LU-11663) ========================================================== 11:44:58 (1755099898) [ 4074.184979] Lustre: *** cfs_fail_loc=411, val=0*** [ 4074.186670] Lustre: Skipped 1 previous similar message [ 4074.789483] Lustre: *** cfs_fail_loc=411, val=0*** [ 4074.791782] Lustre: Skipped 7 previous similar messages [ 4075.877862] Lustre: *** cfs_fail_loc=411, val=0*** [ 4075.880175] Lustre: Skipped 13 previous similar messages [ 4077.882348] Lustre: *** cfs_fail_loc=411, val=0*** [ 4077.884604] Lustre: Skipped 25 previous similar messages [ 4081.691218] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 4082.664094] Lustre: DEBUG MARKER: == sanity test 812a: do not drop reqs generated when imp is going to idle (LU-11951) ========================================================== 11:45:06 (1755099906) [ 4084.477164] Lustre: DEBUG MARKER: oleg234-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9b16105bf000.ost_server_uuid 50 [ 4085.170893] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9b16105bf000.ost_server_uuid in FULL state after 0 sec [ 4087.293491] Lustre: DEBUG MARKER: oleg234-client.virtnet: executing wait_import_state CONNECTING osc.lustre-OST0000-osc-ffff9b16105bf000.ost_server_uuid 50 [ 4101.397137] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9b16105bf000.ost_server_uuid in CONNECTING state after 13 sec [ 4105.391673] Lustre: DEBUG MARKER: == sanity test 812b: do not drop no resend request for idle connect ========================================================== 11:45:29 (1755099929) [ 4107.228668] Lustre: DEBUG MARKER: oleg234-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9b16105bf000.ost_server_uuid 50 [ 4107.931740] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9b16105bf000.ost_server_uuid in FULL state after 0 sec [ 4109.426203] Lustre: DEBUG MARKER: oleg234-client.virtnet: executing wait_import_state CONNECTING osc.lustre-OST0000-osc-ffff9b16105bf000.ost_server_uuid 50 [ 4121.026845] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9b16105bf000.ost_server_uuid in CONNECTING state after 11 sec [ 4122.904737] Lustre: DEBUG MARKER: oleg234-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff9b16105bf000.ost_server_uuid 50 [ 4136.953606] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9b16105bf000.ost_server_uuid in IDLE state after 13 sec [ 4140.762675] Lustre: DEBUG MARKER: == sanity test 812c: idle import vs lock enqueue race ==== 11:46:05 (1755099965) [ 4142.736519] Lustre: DEBUG MARKER: oleg234-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9b16105bf000.ost_server_uuid 50 [ 4143.494583] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9b16105bf000.ost_server_uuid in FULL state after 0 sec [ 4156.384886] LustreError: 186582:0:(import.c:2037:ptlrpc_disconnect_and_idle_import()) cfs_race id 533 sleeping [ 4158.595801] LustreError: 219261:0:(osc_lock.c:1027:osc_lock_enqueue()) cfs_fail_race id 533 waking [ 4158.600308] LustreError: 186582:0:(import.c:2037:ptlrpc_disconnect_and_idle_import()) cfs_fail_race id 533 awake: rc=2789 [ 4159.107988] LustreError: 219261:0:(osc_lock.c:1027:osc_lock_enqueue()) cfs_fail_race id 533 waking [ 4163.676955] Lustre: DEBUG MARKER: == sanity test 813: File heat verfication ================ 11:46:27 (1755099987) [ 4295.417805] Lustre: DEBUG MARKER: == sanity test 814: sparse cp works as expected (LU-12361) ========================================================== 11:48:39 (1755100119) [ 4299.134959] Lustre: DEBUG MARKER: == sanity test 815: zero byte tiny write doesn't hang (LU-12382) ========================================================== 11:48:43 (1755100123) [ 4302.675713] Lustre: DEBUG MARKER: == sanity test 816: do not reset lru_resize on idle reconnect ========================================================== 11:48:46 (1755100126) [ 4304.523219] Lustre: DEBUG MARKER: oleg234-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9b16105bf000.ost_server_uuid 50 [ 4305.266813] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9b16105bf000.ost_server_uuid in FULL state after 0 sec [ 4307.147863] Lustre: DEBUG MARKER: oleg234-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff9b16105bf000.ost_server_uuid 50 [ 4320.319835] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9b16105bf000.ost_server_uuid in IDLE state after 12 sec [ 4323.985933] Lustre: DEBUG MARKER: SKIP: sanity test_817 skipping ALWAYS excluded test 817 [ 4324.937702] Lustre: DEBUG MARKER: == sanity test 818: unlink with failed llog ============== 11:49:09 (1755100149) [ 4334.051998] LustreError: MGC192.168.202.134@tcp: Connection to MGS (at 192.168.202.134@tcp) was lost; in progress operations using this service will fail [ 4334.052144] Lustre: lustre-MDT0000-mdc-ffff9b16105bf000: Connection to lustre-MDT0000 (at 192.168.202.134@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 4334.062341] Lustre: Evicted from MGS (at 192.168.202.134@tcp) after server handle changed from 0xf9d39a36c0c143a1 to 0xf9d39a36c0cc78e4 [ 4334.067348] Lustre: Skipped 1 previous similar message [ 4334.077790] Lustre: MGC192.168.202.134@tcp: Connection restored to 192.168.202.134@tcp (at 192.168.202.134@tcp) [ 4334.082620] Lustre: Skipped 1 previous similar message [ 4334.161861] LustreError: 2377:0:(client.c:3395:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9b163696d880 x1840351505976832/t21474873512(21474873512) o101->lustre-MDT0000-mdc-ffff9b16105bf000@192.168.202.134@tcp:12/10 lens 576/608 e 0 to 0 dl 1755100175 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'md5sum.0' uid:0 gid:0 projid:0 [ 4334.172783] LustreError: 2377:0:(client.c:3395:ptlrpc_replay_interpret()) Skipped 7 previous similar messages [ 4344.288195] Lustre: 2379:0:(client.c:2453:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1755100153/real 1755100153] req@ffff9b1604100a80 x1840351506157312/t0(0) o400->lustre-MDT0000-mdc-ffff9b16105bf000@192.168.202.134@tcp:12/10 lens 224/224 e 0 to 1 dl 1755100169 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4354.531221] Lustre: lustre-MDT0000-mdc-ffff9b16105bf000: Connection to lustre-MDT0000 (at 192.168.202.134@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 4354.531258] LustreError: MGC192.168.202.134@tcp: Connection to MGS (at 192.168.202.134@tcp) was lost; in progress operations using this service will fail [ 4354.544225] Lustre: Evicted from MGS (at 192.168.202.134@tcp) after server handle changed from 0xf9d39a36c0cc78e4 to 0xf9d39a36c0cc7ccd [ 4354.549556] Lustre: MGC192.168.202.134@tcp: Connection restored to 192.168.202.134@tcp (at 192.168.202.134@tcp) [ 4354.552977] Lustre: Skipped 1 previous similar message [ 4354.603122] LustreError: 2377:0:(client.c:3395:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9b163696d880 x1840351505976832/t21474873512(21474873512) o101->lustre-MDT0000-mdc-ffff9b16105bf000@192.168.202.134@tcp:12/10 lens 576/608 e 0 to 0 dl 1755100195 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'md5sum.0' uid:0 gid:0 projid:0 [ 4354.610163] LustreError: 2377:0:(client.c:3395:ptlrpc_replay_interpret()) Skipped 4 previous similar messages [ 4355.552220] Lustre: 2378:0:(client.c:2453:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1755100164/real 1755100164] req@ffff9b1634f87b80 x1840351506162688/t0(0) o400->lustre-MDT0000-mdc-ffff9b16105bf000@192.168.202.134@tcp:12/10 lens 224/224 e 0 to 1 dl 1755100180 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4358.666140] Lustre: DEBUG MARKER: oleg234-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4359.431135] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4361.820197] Lustre: DEBUG MARKER: == sanity test 819a: too big niobuf in read ============== 11:49:46 (1755100186) [ 4365.792246] Lustre: 2379:0:(client.c:2453:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1755100174/real 1755100174] req@ffff9b1604100000 x1840351506163456/t0(0) o400->lustre-MDT0000-mdc-ffff9b16105bf000@192.168.202.134@tcp:12/10 lens 224/224 e 0 to 1 dl 1755100190 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4365.808211] Lustre: 2379:0:(client.c:2453:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 4366.023935] Lustre: DEBUG MARKER: == sanity test 819b: too big niobuf in write ============= 11:49:50 (1755100190) [ 4366.536165] LustreError: 2380:0:(osc_request.c:2444:osc_brw_redo_request()) @@@ redo for recoverable error -12 req@ffff9b1605f74380 x1840351506171648/t0(0) o4->lustre-OST0000-osc-ffff9b16105bf000@192.168.202.134@tcp:6/4 lens 488/448 e 0 to 0 dl 1755100207 ref 2 fl Interpret:ReMQU/600/0 rc -12/-12 job:'dd.0' uid:0 gid:0 projid:0 [ 4366.548421] LustreError: 2380:0:(osc_request.c:2444:osc_brw_redo_request()) Skipped 9 previous similar messages [ 4371.869951] Lustre: DEBUG MARKER: == sanity test 820: update max EA from open intent ======= 11:49:56 (1755100196) [ 4372.687421] Lustre: DEBUG MARKER: SKIP: sanity test_820 needs >= 2 MDTs [ 4373.652175] Lustre: DEBUG MARKER: == sanity test 823: Setting create_count > OST_MAX_PRECREATE is lowered to maximum ========================================================== 11:49:57 (1755100197) [ 4376.689527] Lustre: DEBUG MARKER: setting create_count to 100200: [ 4377.261595] Lustre: DEBUG MARKER: -result- count: 9984 with max: 20000, expecting: 9984 [ 4380.644378] Lustre: DEBUG MARKER: == sanity test 831: throttling unlink/setattr queuing on OSP ========================================================== 11:50:05 (1755100205) [ 4389.669550] Lustre: 227644:0:(client.c:1611:after_reply()) @@@ resending request on EINPROGRESS req@ffff9b16376bbb80 x1840351506714752/t0(0) o36->lustre-MDT0000-mdc-ffff9b16105bf000@192.168.202.134@tcp:12/10 lens 488/456 e 0 to 0 dl 1755100230 ref 2 fl Rpc:RQU/202/0 rc 0/-115 job:'unlinkmany.0' uid:0 gid:0 projid:4294967295 [ 4392.738688] Lustre: 227644:0:(client.c:1611:after_reply()) @@@ resending request on EINPROGRESS req@ffff9b16376b9f80 x1840351506716032/t0(0) o36->lustre-MDT0000-mdc-ffff9b16105bf000@192.168.202.134@tcp:12/10 lens 488/456 e 0 to 0 dl 1755100233 ref 2 fl Rpc:RQU/202/0 rc 0/-115 job:'unlinkmany.0' uid:0 gid:0 projid:4294967295 [ 4399.149486] Lustre: 227644:0:(client.c:1611:after_reply()) @@@ resending request on EINPROGRESS req@ffff9b16107a0380 x1840351506743040/t0(0) o36->lustre-MDT0000-mdc-ffff9b16105bf000@192.168.202.134@tcp:12/10 lens 488/456 e 0 to 0 dl 1755100240 ref 2 fl Rpc:RQU/202/0 rc 0/-115 job:'unlinkmany.0' uid:0 gid:0 projid:4294967295 [ 4408.867166] Lustre: 227644:0:(client.c:1611:after_reply()) @@@ resending request on EINPROGRESS req@ffff9b1634c8d180 x1840351506796544/t0(0) o36->lustre-MDT0000-mdc-ffff9b16105bf000@192.168.202.134@tcp:12/10 lens 488/456 e 0 to 0 dl 1755100249 ref 2 fl Rpc:RQU/202/0 rc 0/-115 job:'unlinkmany.0' uid:0 gid:0 projid:4294967295 [ 4408.880339] Lustre: 227644:0:(client.c:1611:after_reply()) Skipped 1 previous similar message [ 4418.274948] Lustre: 227644:0:(client.c:1611:after_reply()) @@@ resending request on EINPROGRESS req@ffff9b161075ca80 x1840351506824320/t0(0) o36->lustre-MDT0000-mdc-ffff9b16105bf000@192.168.202.134@tcp:12/10 lens 488/456 e 0 to 0 dl 1755100259 ref 2 fl Rpc:RQU/202/0 rc 0/-115 job:'unlinkmany.0' uid:0 gid:0 projid:4294967295 [ 4418.289697] Lustre: 227644:0:(client.c:1611:after_reply()) Skipped 1 previous similar message [ 4440.546827] Lustre: 227644:0:(client.c:1611:after_reply()) @@@ resending request on EINPROGRESS req@ffff9b1604100380 x1840351506931456/t0(0) o36->lustre-MDT0000-mdc-ffff9b16105bf000@192.168.202.134@tcp:12/10 lens 488/456 e 0 to 0 dl 1755100281 ref 2 fl Rpc:RQU/202/0 rc 0/-115 job:'unlinkmany.0' uid:0 gid:0 projid:4294967295 [ 4440.559969] Lustre: 227644:0:(client.c:1611:after_reply()) Skipped 3 previous similar messages [ 4449.999139] Lustre: DEBUG MARKER: == sanity test 832: lfs rm_entry ========================= 11:51:14 (1755100274) [ 4450.910120] Lustre: DEBUG MARKER: SKIP: sanity test_832 needs >= 2 MDTs [ 4452.004314] Lustre: DEBUG MARKER: == sanity test 833: Mixed buffered/direct read and write should not return -EIO ========================================================== 11:51:16 (1755100276) [ 4492.458118] Lustre: DEBUG MARKER: SKIP: sanity test_842 skipping SLOW test 842 [ 4493.000327] Lustre: DEBUG MARKER: == sanity test 850: lljobstat can parse living and aggregated job_stats ========================================================== 11:51:57 (1755100317) [ 4495.363068] Lustre: DEBUG MARKER: == sanity test 851: fanotify can monitor open/read/write/close events for lustre fs ========================================================== 11:51:59 (1755100319) [ 4498.001823] Lustre: DEBUG MARKER: == sanity test 852: mkdir using intent lock for striped directory ========================================================== 11:52:02 (1755100322) [ 4498.496728] Lustre: DEBUG MARKER: SKIP: sanity test_852 needs >= 2 MDTs [ 4499.036534] Lustre: DEBUG MARKER: == sanity test 853: Verify that random fadvise works as expected ========================================================== 11:52:03 (1755100323) [ 4507.659109] Lustre: DEBUG MARKER: == sanity test 900: umount should not race with any mgc requeue thread ========================================================== 11:52:12 (1755100332) [ 4523.491490] LustreError: MGC192.168.202.134@tcp: Connection to MGS (at 192.168.202.134@tcp) was lost; in progress operations using this service will fail [ 4523.491639] Lustre: lustre-MDT0000-mdc-ffff9b16105bf000: Connection to lustre-MDT0000 (at 192.168.202.134@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 4523.497097] Lustre: Evicted from MGS (at 192.168.202.134@tcp) after server handle changed from 0xf9d39a36c0cc7ccd to 0xf9d39a36c0cda360 [ 4523.502108] Lustre: MGC192.168.202.134@tcp: Connection restored to 192.168.202.134@tcp (at 192.168.202.134@tcp) [ 4523.504006] Lustre: Skipped 1 previous similar message [ 4523.535765] LustreError: 2377:0:(client.c:3395:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9b163696d880 x1840351505976832/t21474873512(21474873512) o101->lustre-MDT0000-mdc-ffff9b16105bf000@192.168.202.134@tcp:12/10 lens 576/608 e 0 to 0 dl 1755100364 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'md5sum.0' uid:0 gid:0 projid:0 [ 4523.545747] LustreError: 2377:0:(client.c:3395:ptlrpc_replay_interpret()) Skipped 4 previous similar messages [ 4524.641081] LustreError: 183384:0:(mgc_request.c:1758:mgc_process_log()) cfs_fail_timeout id 903 sleeping for 20000ms [ 4525.000328] Lustre: DEBUG MARKER: oleg234-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4525.469188] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4529.632141] Lustre: 2379:0:(client.c:2453:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1755100338/real 1755100338] req@ffff9b1605f76d80 x1840351507198080/t0(0) o400->lustre-MDT0000-mdc-ffff9b16105bf000@192.168.202.134@tcp:12/10 lens 224/224 e 0 to 1 dl 1755100354 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4544.712117] LustreError: 183384:0:(mgc_request.c:1758:mgc_process_log()) cfs_fail_timeout id 903 awake [ 4544.724708] LustreError: 183384:0:(mgc_request.c:1758:mgc_process_log()) cfs_fail_timeout id 903 sleeping for 20000ms [ 4564.800058] LustreError: 183384:0:(mgc_request.c:1758:mgc_process_log()) cfs_fail_timeout id 903 awake [ 4564.809444] LustreError: 183384:0:(mgc_request.c:1758:mgc_process_log()) cfs_fail_timeout id 903 sleeping for 20000ms [ 4564.810297] LustreError: 232691:0:(lov_obd.c:784:lov_cleanup()) lustre-clilov-ffff9b16105bf000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 4564.814964] LustreError: 232691:0:(lov_obd.c:784:lov_cleanup()) Skipped 5 previous similar messages [ 4564.817449] LustreError: 232691:0:(obd_class.h:479:obd_check_dev()) Device 5 not setup [ 4564.819282] LustreError: 232691:0:(obd_class.h:479:obd_check_dev()) Skipped 17 previous similar messages [ 4564.834911] Lustre: Unmounted lustre-client [ 4564.835936] Lustre: Skipped 2 previous similar messages [ 4584.880115] LustreError: 183384:0:(mgc_request.c:1758:mgc_process_log()) cfs_fail_timeout id 903 awake [ 4584.885409] LustreError: 183384:0:(mgc_request.c:614:do_requeue()) failed processing log: -5 [ 4584.893988] LustreError: 232691:0:(obd_class.h:479:obd_check_dev()) Device 0 not setup [ 4584.897653] LustreError: 232691:0:(obd_class.h:479:obd_check_dev()) Skipped 5 previous similar messages [ 4612.601046] Key type lgssc unregistered [ 4612.722669] LNet: 233150:0:(lib-ptl.c:966:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 4613.735537] LNet: Removed LNI 192.168.202.34@tcp [ 4614.070611] Key type .llcrypt unregistered [ 4614.071889] Key type ._llcrypt unregistered [ 4618.628606] Key type ._llcrypt registered [ 4618.630991] Key type .llcrypt registered [ 4618.782461] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [ 4618.786612] alg: No test for adler32 (adler32-zlib) [ 4619.738562] Lustre: Lustre: Build Version: 2.16.56_9_g5b8a063 [ 4619.982381] LNet: Added LNI 192.168.202.34@tcp [8/256/0/180] [ 4619.983829] LNet: Accept secure, port 988 [ 4621.584083] Key type lgssc registered [ 4622.053485] Lustre: Echo OBD driver; http://www.lustre.org/ [ 4655.738826] Lustre: Mounted lustre-client [ 4658.864653] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4670.206970] Lustre: DEBUG MARKER: == sanity test 901: don't leak a mgc lock on client umount ========================================================== 11:54:54 (1755100494) [ 4671.657236] LustreError: 236227:0:(lov_obd.c:784:lov_cleanup()) lustre-clilov-ffff9b16180b9000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 4671.667732] LustreError: 236227:0:(obd_class.h:479:obd_check_dev()) Device 5 not setup [ 4671.694200] Lustre: Unmounted lustre-client [ 4671.920691] Lustre: Mounted lustre-client [ 4675.257954] Lustre: DEBUG MARKER: == sanity test 902: test short write doesn't hang lustre ========================================================== 11:54:59 (1755100499) [ 4675.408691] Lustre: *** cfs_fail_loc=2001415, val=0*** [ 4678.984463] Lustre: DEBUG MARKER: == sanity test 903: Test long page discard does not cause evictions ========================================================== 11:55:03 (1755100503) [ 4685.093072] LustreError: 236252:0:(osc_cache.c:3310:osc_page_gang_lookup()) cfs_fail_timeout id 417 sleeping for 20000ms [ 4705.168133] LustreError: 236252:0:(osc_cache.c:3310:osc_page_gang_lookup()) cfs_fail_timeout id 417 awake [ 4705.196844] LustreError: 236252:0:(osc_cache.c:3310:osc_page_gang_lookup()) cfs_fail_timeout id 417 sleeping for 20000ms [ 4725.272125] LustreError: 236252:0:(osc_cache.c:3310:osc_page_gang_lookup()) cfs_fail_timeout id 417 awake [ 4725.304033] LustreError: 236252:0:(osc_cache.c:3310:osc_page_gang_lookup()) cfs_fail_timeout id 417 sleeping for 20000ms [ 4745.384132] LustreError: 236252:0:(osc_cache.c:3310:osc_page_gang_lookup()) cfs_fail_timeout id 417 awake [ 4745.412602] LustreError: 236252:0:(osc_cache.c:3310:osc_page_gang_lookup()) cfs_fail_timeout id 417 sleeping for 20000ms [ 4765.488129] LustreError: 236252:0:(osc_cache.c:3310:osc_page_gang_lookup()) cfs_fail_timeout id 417 awake [ 4765.516881] LustreError: 236252:0:(osc_cache.c:3310:osc_page_gang_lookup()) cfs_fail_timeout id 417 sleeping for 20000ms [ 4785.592125] LustreError: 236252:0:(osc_cache.c:3310:osc_page_gang_lookup()) cfs_fail_timeout id 417 awake [ 4785.620952] LustreError: 236252:0:(osc_cache.c:3310:osc_page_gang_lookup()) cfs_fail_timeout id 417 sleeping for 20000ms [ 4805.697091] LustreError: 236252:0:(osc_cache.c:3310:osc_page_gang_lookup()) cfs_fail_timeout id 417 awake [ 4813.048146] Lustre: DEBUG MARKER: == sanity test 904: virtual project ID xattr ============= 11:57:17 (1755100637) [ 4813.987781] Lustre: DEBUG MARKER: SKIP: sanity test_904 ldiskfs only test [ 4815.094451] Lustre: DEBUG MARKER: == sanity test 905: bad or new opcode should not stuck client ========================================================== 11:57:19 (1755100639) [ 4815.810191] LustreError: lustre-OST0000-osc-ffff9b16127ae000: operation ost_ladvise to node 192.168.202.134@tcp failed: rc = -95 [ 4819.510966] Lustre: DEBUG MARKER: == sanity test 906: Simple test for io_uring I/O engine via fio ========================================================== 11:57:23 (1755100643) [ 4820.368460] Lustre: DEBUG MARKER: SKIP: sanity test_906 kernel does not support io_uring fully [ 4821.378781] Lustre: DEBUG MARKER: == sanity test 907: write rpc error during unlink ======== 11:57:25 (1755100645) [ 4823.064451] LustreError: lustre-OST0000-osc-ffff9b16127ae000: operation ost_write to node 192.168.202.134@tcp failed: rc = -3 [ 4823.069778] LustreError: Skipped 3 previous similar messages [ 4826.431388] Lustre: DEBUG MARKER: == sanity test 908a: llog created with valid ctime ======= 11:57:30 (1755100650) [ 4827.290272] Lustre: DEBUG MARKER: SKIP: sanity test_908a ldiskfs only test [ 4828.246124] Lustre: DEBUG MARKER: == sanity test 908b: changelog stores valid mtime ======== 11:57:32 (1755100652) [ 4829.087282] Lustre: DEBUG MARKER: SKIP: sanity test_908b ldiskfs only test [ 4829.999616] Lustre: DEBUG MARKER: == sanity test complete, duration 4663 sec =============== 11:57:34 (1755100654) [ 4830.896093] Lustre: DEBUG MARKER: === sanity: start cleanup 11:57:35 (1755100655) === [ 4841.442477] Lustre: DEBUG MARKER: === sanity: finish cleanup 11:57:45 (1755100665) === [ 4841.885669] LustreError: 243929:0:(lov_obd.c:784:lov_cleanup()) lustre-clilov-ffff9b16127ae000: lov tgt 0 not cleaned! deathrow=0, lovrc=1 [ 4841.889476] LustreError: 243929:0:(lov_obd.c:784:lov_cleanup()) Skipped 1 previous similar message [ 4841.896378] LustreError: 243929:0:(obd_class.h:479:obd_check_dev()) Device 5 not setup [ 4841.898376] LustreError: 243929:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 4841.915233] Lustre: Unmounted lustre-client [ 4871.034528] Key type lgssc unregistered [ 4871.210282] LNet: 244408:0:(lib-ptl.c:966:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 4872.231445] LNet: Removed LNI 192.168.202.34@tcp [ 4872.657489] Key type .llcrypt unregistered [ 4872.659488] Key type ._llcrypt unregistered