[ 0.000000] Linux version 5.14.0rocky95-debug (green@maintenance) (gcc (GCC) 11.5.0 20240719 (Red Hat 11.5.0-2), GNU ld version 2.35.2-54.el9) #3 SMP PREEMPT_DYNAMIC Sun Jan 19 16:53:39 EST 2025 [ 0.000000] The list of certified hardware and cloud instances for Red Hat Enterprise Linux 9 can be viewed at the Red Hat Ecosystem Catalog, https://catalog.redhat.com. [ 0.000000] Command line: rd.shell root=nbd:192.168.200.253:rocky9.5: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] 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] APIC: Static calls initialized [ 0.000000] SMBIOS 3.0.0 present. [ 0.000000] DMI: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.16.3-1.fc39 04/01/2014 [ 0.000000] Hypervisor detected: KVM [ 0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00 [ 0.000006] kvm-clock: using sched offset of 948510485 cycles [ 0.000013] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000029] tsc: Detected 2399.998 MHz processor [ 0.001115] last_pfn = 0x146e00 max_arch_pfn = 0x400000000 [ 0.001165] MTRR map: 4 entries (3 fixed + 1 variable; max 19), built from 8 variable MTRRs [ 0.001174] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT [ 0.001236] last_pfn = 0xbffda max_arch_pfn = 0x400000000 [ 0.008012] found SMP MP-table at [mem 0x000f5410-0x000f541f] [ 0.069932] RAMDISK: [mem 0xb9406000-0xbffcffff] [ 0.069966] ACPI: Early table checksum verification disabled [ 0.069979] ACPI: RSDP 0x00000000000F5220 000014 (v00 BOCHS ) [ 0.069994] ACPI: RSDT 0x00000000BFFE1D6F 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.070010] ACPI: FACP 0x00000000BFFE1C0B 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.070027] ACPI: DSDT 0x00000000BFFE0040 001BCB (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.070038] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.070047] ACPI: APIC 0x00000000BFFE1C7F 000090 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.070058] ACPI: HPET 0x00000000BFFE1D0F 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.070068] ACPI: WAET 0x00000000BFFE1D47 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.070078] ACPI: Reserving FACP table memory at [mem 0xbffe1c0b-0xbffe1c7e] [ 0.070083] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe1c0a] [ 0.070087] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.070090] ACPI: Reserving APIC table memory at [mem 0xbffe1c7f-0xbffe1d0e] [ 0.070094] ACPI: Reserving HPET table memory at [mem 0xbffe1d0f-0xbffe1d46] [ 0.070098] ACPI: Reserving WAET table memory at [mem 0xbffe1d47-0xbffe1d6e] [ 0.070685] No NUMA configuration found [ 0.070690] Faking a node at [mem 0x0000000000000000-0x0000000146dfffff] [ 0.070727] NODE_DATA(0) allocated [mem 0x1465a7000-0x1465d2fff] [ 0.071376] Reserving 256MB of memory at 2704MB for crashkernel (System RAM: 4205MB) [ 0.099575] Zone ranges: [ 0.099588] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.099599] DMA32 [mem 0x0000000001000000-0x00000000ffffffff] [ 0.099605] Normal [mem 0x0000000100000000-0x0000000146dfffff] [ 0.099609] Device empty [ 0.099613] Movable zone start for each node [ 0.099618] Early memory node ranges [ 0.099620] node 0: [mem 0x0000000000001000-0x000000000009efff] [ 0.099625] node 0: [mem 0x0000000000100000-0x00000000bffd9fff] [ 0.099629] node 0: [mem 0x0000000100000000-0x0000000146dfffff] [ 0.099635] Initmem setup node 0 [mem 0x0000000000001000-0x0000000146dfffff] [ 0.099672] On node 0, zone DMA: 1 pages in unavailable ranges [ 0.099969] On node 0, zone DMA: 97 pages in unavailable ranges [ 0.166060] On node 0, zone Normal: 38 pages in unavailable ranges [ 0.168340] On node 0, zone Normal: 4608 pages in unavailable ranges [ 0.418154] kasan: KernelAddressSanitizer initialized [ 0.418836] ACPI: PM-Timer IO Port: 0x608 [ 0.418866] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) [ 0.418949] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 [ 0.418960] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.418966] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) [ 0.418971] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.418975] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) [ 0.418980] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) [ 0.418992] ACPI: Using ACPI (MADT) for SMP configuration information [ 0.418996] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.419010] TSC deadline timer available [ 0.419013] smpboot: Allowing 4 CPUs, 0 hotplug CPUs [ 0.419106] kvm-guest: APIC: eoi() replaced with kvm_guest_apic_eoi_write() [ 0.419141] kvm-guest: KVM setup pv remote TLB flush [ 0.419148] kvm-guest: setup PV sched yield [ 0.419205] PM: hibernation: Registered nosave memory: [mem 0x00000000-0x00000fff] [ 0.419213] PM: hibernation: Registered nosave memory: [mem 0x0009f000-0x0009ffff] [ 0.419217] PM: hibernation: Registered nosave memory: [mem 0x000a0000-0x000effff] [ 0.419221] PM: hibernation: Registered nosave memory: [mem 0x000f0000-0x000fffff] [ 0.419228] PM: hibernation: Registered nosave memory: [mem 0xbffda000-0xbfffffff] [ 0.419231] PM: hibernation: Registered nosave memory: [mem 0xc0000000-0xfeffbfff] [ 0.419235] PM: hibernation: Registered nosave memory: [mem 0xfeffc000-0xfeffffff] [ 0.419238] PM: hibernation: Registered nosave memory: [mem 0xff000000-0xfffbffff] [ 0.419241] PM: hibernation: Registered nosave memory: [mem 0xfffc0000-0xffffffff] [ 0.419252] [mem 0xc0000000-0xfeffbfff] available for PCI devices [ 0.419256] Booting paravirtualized kernel on KVM [ 0.419267] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns [ 0.419278] Warning: Deprecated Hardware is detected: x86_64-v2:GenuineIntel:Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz will not be maintained in a future major release and may be disabled [ 0.444444] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1 [ 0.452955] percpu: Embedded 531 pages/cpu s2138112 r8192 d28672 u4194304 [ 0.453150] kvm-guest: PV spinlocks enabled [ 0.453161] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.453188] Kernel command line: rd.shell root=nbd:192.168.200.253:rocky9.5: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.453338] Booted with the nomodeset parameter. Only the system framebuffer will be available [ 0.453505] audit: disabled (until reboot) [ 0.453518] Unknown kernel command line parameters "ipmtu=9000 ip=dhcp", will be passed to user space. [ 0.453615] random: crng init done [ 0.457009] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, linear) [ 0.458688] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, linear) [ 0.459173] Fallback order for Node 0: 0 [ 0.459190] Built 1 zonelists, mobility grouping on. Total pages: 1059618 [ 0.459195] Policy zone: Normal [ 0.459241] mem auto-init: stack:off, heap alloc:off, heap free:off [ 0.459246] stackdepot: allocating hash table via alloc_large_system_hash [ 0.459257] stackdepot hash table entries: 1048576 (order: 12, 16777216 bytes, linear) [ 0.465908] software IO TLB: area num 4. [ 1.771361] Memory: 2837312K/4306400K available (43008K kernel code, 14200K rwdata, 17804K rodata, 5284K init, 25448K bss, 1220592K reserved, 0K cma-reserved) [ 1.771380] ********************************************************** [ 1.771383] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 1.771385] ** ** [ 1.771387] ** This system shows unhashed kernel memory addresses ** [ 1.771389] ** via the console, logs, and other interfaces. This ** [ 1.771391] ** might reduce the security of your system. ** [ 1.771393] ** ** [ 1.771396] ** If you see this message and you are not debugging ** [ 1.771398] ** the kernel, report this immediately to your system ** [ 1.771400] ** administrator! ** [ 1.771402] ** ** [ 1.771404] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 1.771407] ********************************************************** [ 1.774096] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 1.774110] kmemleak: Kernel memory leak detector disabled [ 1.780291] ftrace: allocating 51191 entries in 200 pages [ 1.799679] ftrace: allocated 200 pages with 3 groups [ 1.806726] Dynamic Preempt: voluntary [ 1.809636] rcu: Preemptible hierarchical RCU implementation. [ 1.809645] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ 1.809652] rcu: RCU callback double-/use-after-free debug is enabled. [ 1.809655] Trampoline variant of Tasks RCU enabled. [ 1.809657] Rude variant of Tasks RCU enabled. [ 1.809659] Tracing variant of Tasks RCU enabled. [ 1.809662] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 1.809665] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 1.878002] NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16 [ 1.879365] rcu: srcu_init: Setting srcu_struct sizes based on contention. [ 1.880248] Console: colour *CGA 80x25 [ 1.880477] printk: console [ttyS1] enabled [ 2.189231] Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo Molnar [ 2.191653] ... MAX_LOCKDEP_SUBCLASSES: 8 [ 2.192858] ... MAX_LOCK_DEPTH: 48 [ 2.194225] ... MAX_LOCKDEP_KEYS: 8192 [ 2.195373] ... CLASSHASH_SIZE: 4096 [ 2.200969] ... MAX_LOCKDEP_ENTRIES: 65536 [ 2.202359] ... MAX_LOCKDEP_CHAINS: 262144 [ 2.203695] ... CHAINHASH_SIZE: 131072 [ 2.206501] memory used by lock dependency info: 6889 kB [ 2.208075] per task-struct memory footprint: 2688 bytes [ 2.213200] ACPI: Core revision 20230331 [ 2.215470] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 2.219683] APIC: Switch to symmetric I/O mode setup [ 2.221389] x2apic enabled [ 2.222878] APIC: Switched APIC routing to: physical x2apic [ 2.224851] kvm-guest: APIC: send_IPI_mask() replaced with kvm_send_ipi_mask() [ 2.227048] kvm-guest: APIC: send_IPI_mask_allbutself() replaced with kvm_send_ipi_mask_allbutself() [ 2.229486] kvm-guest: setup PV IPIs [ 2.233687] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 2.236432] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 2.240030] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 2.241207] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 2.242324] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 2.243022] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 2.244069] Spectre V2 : User space: Vulnerable [ 2.245021] Speculative Store Bypass: Vulnerable [ 2.246065] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers' [ 2.247027] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers' [ 2.248026] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers' [ 2.249022] x86/fpu: xstate_offset[2]: 576, xstate_sizes[2]: 256 [ 2.250021] x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'standard' format. [ 2.253711] debug: unmapping init [mem 0xffffffffa191b000-0xffffffffa1924fff] [ 2.254063] pid_max: default: 32768 minimum: 301 [ 2.256331] LSM: initializing lsm=lockdown,capability,yama,integrity,selinux,bpf [ 2.257228] Yama: becoming mindful. [ 2.258006] SELinux: Initializing. [ 2.259665] LSM support for eBPF active [ 2.260805] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, linear) [ 2.261066] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, linear) [ 2.273241] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 2.278526] RCU Tasks: Setting shift to 2 and lim to 1 rcu_task_cb_adjust=1. [ 2.279573] RCU Tasks Rude: Setting shift to 2 and lim to 1 rcu_task_cb_adjust=1. [ 2.280615] RCU Tasks Trace: Setting shift to 2 and lim to 1 rcu_task_cb_adjust=1. [ 2.281650] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 2.282050] ... version: 2 [ 2.283025] ... bit width: 48 [ 2.284023] ... generic registers: 4 [ 2.285024] ... value mask: 0000ffffffffffff [ 2.286023] ... max period: 00007fffffffffff [ 2.287027] ... fixed-purpose events: 3 [ 2.288022] ... event mask: 000000070000000f [ 2.289949] signal: max sigframe size: 1776 [ 2.291020] rcu: Hierarchical SRCU implementation. [ 2.291027] rcu: Max phase no-delay instances is 400. [ 2.306326] smp: Bringing up secondary CPUs ... [ 2.310426] smpboot: x86: Booting SMP configuration: [ 2.310454] .... node #0, CPUs: #2 [ 2.321366] #1 #3 [ 2.342203] smp: Brought up 1 node, 4 CPUs [ 2.342247] smpboot: Max logical packages: 1 [ 2.342258] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 2.419335] node 0 deferred pages initialised in 64ms [ 2.421200] pgdatinit0 (40) used greatest stack depth: 29944 bytes left [ 2.430059] devtmpfs: initialized [ 2.433259] x86/mm: Memory block size: 128MB [ 2.493232] DMA-API: preallocated 65536 debug entries [ 2.494020] DMA-API: debugging enabled by kernel config [ 2.494055] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 2.494107] futex hash table entries: 1024 (order: 5, 131072 bytes, linear) [ 2.496611] prandom: seed boundary self test passed [ 2.499173] prandom: 100 self tests passed [ 2.499190] pinctrl core: initialized pinctrl subsystem [ 2.501195] [ 2.501206] ************************************************************* [ 2.501209] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 2.501213] ** ** [ 2.501216] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 2.501219] ** ** [ 2.501222] ** This means that this kernel is built to expose internal ** [ 2.501226] ** IOMMU data structures, which may compromise security on ** [ 2.501229] ** your system. ** [ 2.501233] ** ** [ 2.501236] ** If you see this message and you are not debugging the ** [ 2.501239] ** kernel, report this immediately to your vendor! ** [ 2.501243] ** ** [ 2.501246] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 2.501250] ************************************************************* [ 2.502020] PM: RTC time: 07:33:07, date: 2025-04-01 [ 2.509213] NET: Registered PF_NETLINK/PF_ROUTE protocol family [ 2.515609] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 2.515759] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 2.515959] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 2.522612] thermal_sys: Registered thermal governor 'fair_share' [ 2.522625] thermal_sys: Registered thermal governor 'step_wise' [ 2.522633] thermal_sys: Registered thermal governor 'user_space' [ 2.523901] cpuidle: using governor menu [ 2.531439] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 2.536216] PCI: Using configuration type 1 for base access [ 2.536431] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 2.725204] kprobes: kprobe jump-optimization is enabled. All kprobes are optimized if possible. [ 2.732006] HugeTLB: registered 1.00 GiB page size, pre-allocated 0 pages [ 2.732006] HugeTLB: 16380 KiB vmemmap can be freed for a 1.00 GiB page [ 2.732006] HugeTLB: registered 2.00 MiB page size, pre-allocated 0 pages [ 2.732006] HugeTLB: 28 KiB vmemmap can be freed for a 2.00 MiB page [ 2.760006] cryptd: max_cpu_qlen set to 1000 [ 2.772006] ACPI: Added _OSI(Module Device) [ 2.772006] ACPI: Added _OSI(Processor Device) [ 2.772006] ACPI: Added _OSI(3.0 _SCP Extensions) [ 2.772006] ACPI: Added _OSI(Processor Aggregator Device) [ 2.774077] ACPI: Added _OSI(Linux-Dell-Video) [ 2.774133] ACPI: Added _OSI(Linux-Lenovo-NV-HDMI-Audio) [ 2.774172] ACPI: Added _OSI(Linux-HPI-Hybrid-Graphics) [ 2.888006] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 3.382581] ACPI: _OSC evaluation for CPUs failed, trying _PDC [ 3.393586] ACPI: Interpreter enabled [ 3.395052] ACPI: PM: (supports S0 S3 S4 S5) [ 3.395149] ACPI: Using IOAPIC for interrupt routing [ 3.400006] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 3.400006] PCI: Using E820 reservations for host bridge windows [ 3.405006] ACPI: Enabled 2 GPEs in block 00 to 0F [ 3.730657] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 3.735153] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI EDR HPX-Type3] [ 3.735202] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 3.735989] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended configuration space under this bridge [ 3.822006] acpiphp: Slot [2] registered [ 3.827231] acpiphp: Slot [5] registered [ 3.828004] acpiphp: Slot [6] registered [ 3.828651] acpiphp: Slot [3] registered [ 3.829328] acpiphp: Slot [4] registered [ 3.829971] acpiphp: Slot [7] registered [ 3.830555] acpiphp: Slot [8] registered [ 3.856422] acpiphp: Slot [9] registered [ 3.857006] acpiphp: Slot [10] registered [ 3.857006] acpiphp: Slot [11] registered [ 3.857006] acpiphp: Slot [12] registered [ 3.873162] acpiphp: Slot [13] registered [ 3.873792] acpiphp: Slot [14] registered [ 3.874341] acpiphp: Slot [15] registered [ 3.874873] acpiphp: Slot [16] registered [ 3.875006] acpiphp: Slot [17] registered [ 3.875006] acpiphp: Slot [18] registered [ 3.875006] acpiphp: Slot [19] registered [ 3.894711] acpiphp: Slot [20] registered [ 3.895452] acpiphp: Slot [21] registered [ 3.896028] acpiphp: Slot [22] registered [ 3.896655] acpiphp: Slot [23] registered [ 3.897006] acpiphp: Slot [24] registered [ 3.911787] acpiphp: Slot [25] registered [ 3.912415] acpiphp: Slot [26] registered [ 3.913045] acpiphp: Slot [27] registered [ 3.913686] acpiphp: Slot [28] registered [ 3.935282] acpiphp: Slot [29] registered [ 3.936777] acpiphp: Slot [30] registered [ 3.937006] acpiphp: Slot [31] registered [ 3.937006] PCI host bridge to bus 0000:00 [ 3.937006] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 3.937006] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 3.937006] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 3.937006] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 3.937006] pci_bus 0000:00: root bus resource [mem 0x380000000000-0x38007fffffff window] [ 3.937006] pci_bus 0000:00: root bus resource [bus 00-ff] [ 3.937006] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 conventional PCI endpoint [ 3.950303] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 conventional PCI endpoint [ 3.963285] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 conventional PCI endpoint [ 3.973594] pci 0000:00:01.1: BAR 4 [io 0xc120-0xc12f] [ 3.978725] pci 0000:00:01.1: BAR 0 [io 0x01f0-0x01f7]: legacy IDE quirk [ 3.978744] pci 0000:00:01.1: BAR 1 [io 0x03f6]: legacy IDE quirk [ 3.978751] pci 0000:00:01.1: BAR 2 [io 0x0170-0x0177]: legacy IDE quirk [ 3.978758] pci 0000:00:01.1: BAR 3 [io 0x0376]: legacy IDE quirk [ 3.984006] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 conventional PCI endpoint [ 3.985599] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 3.985633] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 3.996006] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 conventional PCI endpoint [ 3.996006] pci 0000:00:02.0: BAR 0 [io 0xc100-0xc11f] [ 4.022006] pci 0000:00:02.0: BAR 4 [mem 0x380000000000-0x380000003fff 64bit pref] [ 4.026026] pci 0000:00:02.0: ROM [mem 0xfeb80000-0xfebbffff pref] [ 4.195297] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 conventional PCI endpoint [ 4.207034] pci 0000:00:05.0: BAR 0 [io 0xc000-0xc07f] [ 4.218039] pci 0000:00:05.0: BAR 1 [mem 0xfebc0000-0xfebc0fff] [ 4.259048] pci 0000:00:05.0: BAR 4 [mem 0x380000004000-0x380000007fff 64bit pref] [ 4.372795] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 conventional PCI endpoint [ 4.380029] pci 0000:00:06.0: BAR 0 [io 0xc080-0xc0ff] [ 4.394032] pci 0000:00:06.0: BAR 1 [mem 0xfebc1000-0xfebc1fff] [ 4.411031] pci 0000:00:06.0: BAR 4 [mem 0x380000008000-0x38000000bfff 64bit pref] [ 4.519716] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 4.530884] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 4.537649] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 4.546494] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 4.550761] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 4.582720] iommu: Default domain type: Translated [ 4.583006] iommu: DMA domain TLB invalidation policy: lazy mode [ 4.586340] SCSI subsystem initialized [ 4.588006] ACPI: bus type USB registered [ 4.590139] usbcore: registered new interface driver usbfs [ 4.592370] usbcore: registered new interface driver hub [ 4.592709] usbcore: registered new device driver usb [ 4.598282] pps_core: LinuxPPS API ver. 1 registered [ 4.598299] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 4.598460] PTP clock support registered [ 4.616088] NetLabel: Initializing [ 4.616140] NetLabel: domain hash size = 128 [ 4.616152] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 4.617103] NetLabel: unlabeled traffic allowed by default [ 4.617145] PCI: Using ACPI for IRQ routing [ 4.624006] vgaarb: loaded [ 4.628891] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 4.628920] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 4.649448] clocksource: Switched to clocksource kvm-clock [ 4.694863] VFS: Disk quotas dquot_6.6.0 [ 4.701260] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 4.730444] pnp: PnP ACPI init [ 4.871427] pnp: PnP ACPI: found 6 devices [ 5.640007] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 5.667750] NET: Registered PF_INET protocol family [ 5.690271] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, linear) [ 5.763914] tcp_listen_portaddr_hash hash table entries: 4096 (order: 6, 327680 bytes, linear) [ 5.777537] Table-perturb hash table entries: 65536 (order: 6, 262144 bytes, linear) [ 5.786083] TCP established hash table entries: 65536 (order: 7, 524288 bytes, linear) [ 5.803184] TCP bind hash table entries: 65536 (order: 10, 5242880 bytes, vmalloc hugepage) [ 5.895265] TCP: Hash tables configured (established 65536 bind 65536) [ 5.910815] MPTCP token hash table entries: 8192 (order: 7, 786432 bytes, linear) [ 5.937375] UDP hash table entries: 4096 (order: 7, 786432 bytes, linear) [ 5.970201] UDP-Lite hash table entries: 4096 (order: 7, 786432 bytes, linear) [ 6.001781] NET: Registered PF_UNIX/PF_LOCAL protocol family [ 6.083750] RPC: Registered named UNIX socket transport module. [ 6.093913] RPC: Registered udp transport module. [ 6.094605] RPC: Registered tcp transport module. [ 6.094644] RPC: Registered tcp-with-tls transport module. [ 6.094655] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 6.094680] NET: Registered PF_XDP protocol family [ 6.094726] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 6.094744] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 6.094755] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 6.094766] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 6.094776] pci_bus 0000:00: resource 8 [mem 0x380000000000-0x38007fffffff window] [ 6.096384] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 6.096433] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 6.096668] PCI: CLS 0 bytes, default 64 [ 6.096847] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 6.096857] software IO TLB: mapped [mem 0x00000000a5000000-0x00000000a9000000] (64MB) [ 6.096976] ACPI: bus type thunderbolt registered [ 6.116353] Trying to unpack rootfs image as initramfs... [ 6.131305] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 10.291560] Initialise system trusted keyrings [ 10.316671] Key type blacklist registered [ 10.338425] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 10.590408] zbud: loaded [ 10.640371] NFS: Registering the id_resolver key type [ 10.645698] Key type id_resolver registered [ 10.645735] Key type id_legacy registered [ 10.645925] nfs4filelayout_init: NFSv4 File Layout Driver Registering... [ 10.646000] nfs4flexfilelayout_init: NFSv4 Flexfile Layout Driver Registering... [ 10.817466] integrity: Platform Keyring initialized [ 10.824198] integrity: Machine keyring initialized [ 10.923114] NET: Registered PF_ALG protocol family [ 10.923248] xor: automatically using best checksumming function avx [ 10.923267] Key type asymmetric registered [ 10.923291] Asymmetric key parser 'x509' registered [ 10.923301] Running certificate verification selftests [ 10.955324] cryptomgr_test (68) used greatest stack depth: 29872 bytes left [ 10.988402] cryptomgr_test (70) used greatest stack depth: 29424 bytes left [ 11.007875] cryptomgr_probe (69) used greatest stack depth: 28600 bytes left [ 11.045134] Loaded X.509 cert 'Certificate verification self-testing key: f58703bb33ce1b73ee02eccdee5b8817518fe3db' [ 11.070212] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 246) [ 11.087889] io scheduler mq-deadline registered [ 11.087905] io scheduler kyber registered [ 11.088128] io scheduler bfq registered [ 11.375658] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 11.396859] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 11.440144] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 11.481782] ACPI: button: Power Button [PWRF] [ 31.247420] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 36.919657] debug: unmapping init [mem 0xffff8880b9406000-0xffff8880bffcffff] [ 42.883423] hrtimer: interrupt took 14758445 ns [ 52.213270] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 73.288943] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 73.343161] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 73.363882] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 73.499082] Non-volatile memory driver v1.3 [ 75.314968] virtio_blk virtio1: 4/0/0 default/read/poll queues [ 75.328904] virtio_blk virtio1: [vda] 131792 512-byte logical blocks (67.5 MB/64.4 MiB) [ 75.599394] virtio_blk virtio2: 4/0/0 default/read/poll queues [ 75.730368] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 75.892209] rdac: device handler registered [ 75.895106] hp_sw: device handler registered [ 75.895164] emc: device handler registered [ 75.899447] alua: device handler registered [ 76.033522] usbcore: registered new interface driver usbserial_generic [ 76.043682] usbserial: USB Serial support registered for generic [ 76.055044] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 76.084305] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 76.084522] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 76.112828] mousedev: PS/2 mouse device common for all mice [ 76.144712] rtc_cmos 00:05: RTC can wake from S4 [ 76.190351] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 76.193480] rtc_cmos 00:05: registered as rtc0 [ 76.195422] rtc_cmos 00:05: setting system clock to 2025-04-01T07:34:23 UTC (1743492863) [ 76.205129] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 76.207590] intel_pstate: CPU model not supported [ 76.322023] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 76.332732] hid: raw HID events driver (C) Jiri Kosina [ 76.334298] usbcore: registered new interface driver usbhid [ 76.334308] usbhid: USB HID core driver [ 76.334720] drop_monitor: Initializing network drop monitor service [ 76.374799] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 76.697849] Initializing XFRM netlink socket [ 76.728895] NET: Registered PF_INET6 protocol family [ 77.472505] modprobe (101) used greatest stack depth: 26512 bytes left [ 78.141521] modprobe (102) used greatest stack depth: 26360 bytes left [ 79.488849] Segment Routing with IPv6 [ 79.489132] NET: Registered PF_PACKET protocol family [ 79.495113] Key type dns_resolver registered [ 79.495139] mpls_gso: MPLS GSO support [ 79.550018] IPI shorthand broadcast: enabled [ 79.550348] AVX version of gcm_enc/dec engaged. [ 79.584038] AES CTR mode by8 optimization enabled [ 79.612776] sched_clock: Marking stable (79260014204, 352614757)->(81640001136, -2027372175) [ 79.670385] registered taskstats version 1 [ 79.703875] Loading compiled-in X.509 certificates [ 79.745305] Loaded X.509 cert 'Build time autogenerated kernel key: e7dd487b25da3070ab21d0f388d69a833b127865' [ 81.280783] debug_vm_pgtable: [debug_vm_pgtable ]: Validating architecture page table helpers [ 92.133235] page_owner is disabled [ 92.135860] Key type big_key registered [ 93.058733] Key type encrypted registered [ 93.058963] ima: No TPM chip found, activating TPM-bypass! [ 93.059071] Loading compiled-in module X.509 certificates [ 93.061794] Loaded X.509 cert 'Build time autogenerated kernel key: e7dd487b25da3070ab21d0f388d69a833b127865' [ 93.061857] ima: Allocated hash algorithm: sha256 [ 93.062093] ima: No architecture policies found [ 93.075172] evm: Initialising EVM extended attributes: [ 93.075184] evm: security.selinux [ 93.075190] evm: security.SMACK64 (disabled) [ 93.075194] evm: security.SMACK64EXEC (disabled) [ 93.075198] evm: security.SMACK64TRANSMUTE (disabled) [ 93.075201] evm: security.SMACK64MMAP (disabled) [ 93.075205] evm: security.apparmor (disabled) [ 93.075208] evm: security.ima [ 93.075212] evm: security.capability [ 93.075216] evm: HMAC attrs: 0x1 [ 104.726194] PM: Magic number: 5:830:570 [ 105.008574] clk: Disabling unused clocks [ 105.334428] debug: unmapping init [mem 0xffffffffa3003000-0xffffffffa31fffff] [ 105.358448] debug: unmapping init [mem 0xffffffffa13f2000-0xffffffffa191afff] [ 105.396102] Write protecting the kernel read-only data: 61440k [ 105.431432] debug: unmapping init [mem 0xffffffff9fd63000-0xffffffff9fdfffff] [ 106.340288] x86/mm: Checked W+X mappings: passed, no W+X pages found. [ 106.340589] Run /init as init process [ 109.061843] systemd[1]: systemd 252-46.el9_5.2.0.1 running in system mode (+PAM +AUDIT +SELINUX -APPARMOR +IMA +SMACK +SECCOMP +GCRYPT +GNUTLS +OPENSSL +ACL +BLKID +CURL +ELFUTILS +FIDO2 +IDN2 -IDN -IPTC +KMOD +LIBCRYPTSETUP +LIBFDISK +PCRE2 -PWQUALITY +P11KIT -QRENCODE +TPM2 +BZIP2 +LZ4 +XZ +ZLIB +ZSTD -BPF_FRAMEWORK +XKBCOMMON +UTMP +SYSVINIT default-hierarchy=unified) [ 109.064039] systemd[1]: Detected virtualization kvm. [ 109.064121] systemd[1]: Detected architecture x86-64. [ 109.064163] systemd[1]: Running in initrd. Welcome to Rocky Linux 9.5 (Blue Onyx) dracut-057-70.git20240819.el9 (Initramfs)! [ 109.168112] systemd[1]: No hostname configured, using default hostname. [ 109.169421] systemd[1]: Hostname set to . [ 109.195753] systemd[1]: Initializing machine ID from random generator. [ 112.319830] systemd-cryptse (222) used greatest stack depth: 26248 bytes left [ 112.596139] systemd-hiberna (226) used greatest stack depth: 26224 bytes left [ 118.565054] systemd[1]: Queued start job for default target Initrd Default Target. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ 118.577819] systemd[1]: Started Dispatch Password Requests to Console Directory Watch. [ 118.640516] systemd[1]: Reached target Local Encrypted Volumes. [ OK ] Reached target Local Encrypted Volumes. [ 118.723170] systemd[1]: Reached target Initrd Root Device. [ OK ] Reached target Initrd Root Device. [ OK ] Reached target Initrd /usr File System. [ 118.747154] systemd[1]: Reached target Initrd /usr File System. [ 118.781777] systemd[1]: Reached target Local File Systems. [ OK ] Reached target Local File Systems. [ 118.815430] systemd[1]: Reached target Path Units. [ OK ] Reached target Path Units. [ 118.858898] systemd[1]: Reached target Slice Units. [ OK ] Reached target Slice Units. [ 118.872966] systemd[1]: Reached target Swaps. [ OK ] Reached target Swaps. [ 118.900861] systemd[1]: Reached target Timer Units. [ OK ] Reached target Timer Units. [ 118.940527] systemd[1]: Listening on Journal Socket (/dev/log). [ OK ] Listening on Journal Socket (/dev/log). [ OK ] Listening on Journal Socket. [ 119.013385] systemd[1]: Listening on Journal Socket. [ OK ] Listening on udev Control Socket. [ 119.057071] systemd[1]: Listening on udev Control Socket. [ 119.094360] systemd[1]: Listening on udev Kernel Socket. [ OK ] Listening on udev Kernel Socket. [ 119.138106] systemd[1]: Reached target Socket Units. [ OK ] Reached target Socket Units. [ 119.400583] systemd[1]: Starting Create List of Static Device Nodes... Starting Create List of Static Device Nodes... [ 119.428197] systemd[1]: Memstrack Anylazing Service was skipped because no trigger condition checks were met. [ 120.323087] systemd[1]: Starting Journal Service... Starting Journal Service... [ 120.373424] systemd[1]: Load Kernel Modules was skipped because no trigger condition checks were met. [ 120.586435] systemd[1]: Starting Apply Kernel Variables... Starting Apply Kernel Variables... [ 120.774426] systemd[1]: Starting Setup Virtual Console... Starting Setup Virtual Console... [ 121.027160] systemd[1]: Finished Create List of Static Device Nodes. [ OK ] Finished Create List of Static Device Nodes. [ 122.147324] systemd[1]: Starting Create Static Device Nodes in /dev... Starting Create Static Device Nodes in /dev... [ 122.786607] systemd[1]: Finished Apply Kernel Variables. [ OK ] Finished Apply Kernel Variables. [ OK ] Finished Setup Virtual Console. [ 123.256918] systemd[1]: Finished Setup Virtual Console. [ 123.379193] systemd[1]: dracut ask for additional cmdline parameters was skipped because no trigger condition checks were met. [ 123.783597] systemd[1]: Starting dracut cmdline hook... Starting dracut cmdline hook... [ 124.979675] systemd[1]: Finished Create Static Device Nodes in /dev. [ OK ] Finished Create Static Device Nodes in /dev. [ 125.047055] workqueue: delayed_vfree_work hogged CPU for >10000us 4 times, consider switching to WQ_UNBOUND [ 126.276933] systemd[1]: Started Journal Service. [ OK ] Started Journal Service. Starting Create Volatile Files and Directories... [ OK ] Finished Create Volatile Files and Directories. [ OK ] Finished dracut cmdline hook. Starting dracut pre-udev hook... [ 140.148724] device-mapper: core: CONFIG_IMA_DISABLE_HTABLE is disabled. Duplicate IMA measurements will not be recorded in the IMA log. [ 140.150592] device-mapper: uevent: version 1.0.3 [ 140.192453] device-mapper: ioctl: 4.48.0-ioctl (2023-03-01) initialised: dm-devel@redhat.com [ 147.532646] workqueue: delayed_vfree_work hogged CPU for >10000us 5 times, consider switching to WQ_UNBOUND [ OK ] Finished dracut pre-udev hook. Starting Rule-based Manager for Device Events and Files... [ *** ] A start job is running for Rule-bas… Events and Files (32s / no limit) M [ OK ] Started Rule-based Manager for Device Events and Files.  Starting dracut pre-trigger hook... [ OK ] Finished dracut pre-trigger hook. Starting Coldplug All udev Devices... [ ***] A start job is running for Coldplug All udev Devices (37s / no limit) M [ **] A start job is running for Coldplug All udev Devices (37s / no limit) M [ *] A start job is running for Coldplug All udev Devices (38s / no limit) M [ **] A start job is running for Coldplug All udev Devices (38s / no limit) M [ ***] A start job is running for Coldplug All udev Devices (39s / no limit) M [ *** ] A start job is running for Coldplug All udev Devices (39s / no limit) M [ *** ] A start job is running for Coldplug All udev Devices (40s / no limit) M [*** ] A start job is running for Coldplug All udev Devices (40s / no limit) M [** ] A start job is running for Coldplug All udev Devices (41s / no limit) M [* ] A start job is running for Coldplug All udev Devices (41s / no limit) M [** ] A start job is running for Coldplug All udev Devices (42s / no limit) M [*** ] A start job is running for Coldplug All udev Devices (42s / no limit) M [ *** ] A start job is running for Coldplug All udev Devices (43s / no limit) M [ *** ] A start job is running for Coldplug All udev Devices (43s / no limit) M [ ***] A start job is running for Coldplug All udev Devices (44s / no limit) M [ **] A start job is running for Coldplug All udev Devices (45s / no limit) M [ *] A start job is running for Coldplug All udev Devices (45s / no limit) M [ **] A start job is running for Coldplug All udev Devices (46s / no limit) M [ ***] A start job is running for Coldplug All udev Devices (46s / no limit) M [ *** ] A start job is running for Coldplug All udev Devices (46s / no limit) M [ *** ] A start job is running for Coldplug All udev Devices (47s / no limit) M [*** ] A start job is running for Coldplug All udev Devices (47s / no limit) M [ OK ] Finished Coldplug All udev Devices. [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. Starting dracut initqueue hook... [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ 171.045564] nbd-client (471) used greatest stack depth: 25672 bytes left [ 172.732557] virtio_net virtio0 ens2: renamed from eth0 [ 178.371219] systemd-udevd (474) used greatest stack depth: 25552 bytes left [ 178.374499] workqueue: delayed_vfree_work hogged CPU for >10000us 7 times, consider switching to WQ_UNBOUND [ 187.095455] ip (607) used greatest stack depth: 24424 bytes left [ 187.287635] workqueue: delayed_vfree_work hogged CPU for >10000us 11 times, consider switching to WQ_UNBOUND [ 189.321926] scsi host0: ata_piix [ 189.465641] workqueue: do_free_init hogged CPU for >10000us 4 times, consider switching to WQ_UNBOUND [ 189.543002] scsi host1: ata_piix [ 189.557583] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc120 irq 14 lpm-pol 0 [ 189.557654] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc128 irq 15 lpm-pol 0 [ 189.608637] workqueue: do_free_init hogged CPU for >10000us 5 times, consider switching to WQ_UNBOUND [ 196.062317] dracut-initqueue[694]: Error: ipv4: Address already assigned. [ 214.147384] nbd0: detected capacity change from 0 to 62914560 [ OK ] Finished dracut initqueue hook. [ OK ] Reached target Preparation for Remote File Systems. [ OK ] Reached target Remote Encrypted Volumes. [ OK ] Reached target Remote File Systems. Starting dracut pre-mount hook... [ OK ] Finished dracut pre-mount hook. Mounting /sysroot... [ 218.848593] systemd-udevd (783) used greatest stack depth: 22232 bytes left [ 219.001502] workqueue: do_free_init hogged CPU for >10000us 7 times, consider switching to WQ_UNBOUND [ *** ] A start job is running for /sysroot (1min 42s / no limit) M [ *** ] A start job is running for /sysroot (1min 43s / no limit) [ 221.704520] EXT4-fs (nbd0): mounted filesystem 78814501-6d48-4019-818e-1b1fdcf55d3f ro with ordered data mode. Quota mode: none. [ 221.736584] mount (798) used greatest stack depth: 21808 bytes left M [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Mountpoints Configured in the Real Root... [ 222.694967] systemd-fstab-g (804) used greatest stack depth: 21424 bytes left [ OK ] Finished Mountpoints Configured in the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Finished dracut pre-pivot and cleanup hook. [ 229.597708] dracut-pre-pivo (806) used greatest stack depth: 21056 bytes left Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped target Remote Encrypted Volumes. [ OK ] Stopped target Timer Units. [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped target Initrd /usr File System. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Preparation for Remote File Systems. [ OK ] Stopped dracut pre-mount hook. [ OK ] Stopped dracut initqueue hook. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped Setup Virtual Console. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Finished Cleaning Up and Shutting Down Daemons. [ OK ] Stopped target Basic System. [ OK ] Stopped target Path Units. [ OK ] Stopped target Slice Units. [ OK ] Stopped target Socket Units. [ OK ] Stopped target System Initialization. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped target Swaps. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. [ OK ] Stopped Coldplug All udev Devices. [ OK ] Stopped dracut pre-trigger hook. Stopping Rule-based Manager for Device Events and Files... [ OK ] Stopped Rule-based Manager for Device Events and Files. [ OK ] Closed udev Control Socket. [ OK ] Closed udev Kernel Socket. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. Starting Cleanup udev Database... [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create List of Static Device Nodes. [ OK ] Finished Cleanup udev Database. [ OK ] Reached target Switch Root. Starting Switch Root... [ 233.555675] systemd-journald[263]: Received SIGTERM from PID 1 (systemd). [ 240.856072] systemd[1]: systemd 252-46.el9_5.2.0.1 running in system mode (+PAM +AUDIT +SELINUX -APPARMOR +IMA +SMACK +SECCOMP +GCRYPT +GNUTLS +OPENSSL +ACL +BLKID +CURL +ELFUTILS +FIDO2 +IDN2 -IDN -IPTC +KMOD +LIBCRYPTSETUP +LIBFDISK +PCRE2 -PWQUALITY +P11KIT -QRENCODE +TPM2 +BZIP2 +LZ4 +XZ +ZLIB +ZSTD -BPF_FRAMEWORK +XKBCOMMON +UTMP +SYSVINIT default-hierarchy=unified) [ 240.893953] systemd[1]: Detected virtualization kvm. [ 240.894022] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 9.5 (Blue Onyx)! [ 244.015315] kdump-dep-gener (855) used greatest stack depth: 20872 bytes left [ 244.331192] systemd-rc-local-generator[867]: /etc/rc.d/rc.local is not marked executable, skipping. [ 248.602958] systemd[1]: initrd-switch-root.service: Deactivated successfully. [ 248.611428] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 248.637258] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ OK ] Created slice Slice /system/getty. [ 248.659162] systemd[1]: Created slice Slice /system/getty. [ 248.685294] systemd[1]: Created slice Slice /system/modprobe. [ OK ] Created slice Slice /system/modprobe. [ 248.717053] systemd[1]: Created slice Slice /system/serial-getty. [ OK ] Created slice Slice /system/serial-getty. [ 248.778477] systemd[1]: Created slice Slice /system/sshd-keygen. [ OK ] Created slice Slice /system/sshd-keygen. [ 248.801873] systemd[1]: Created slice User and Session Slice. [ OK ] Created slice User and Session Slice. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ 248.825698] systemd[1]: Started Dispatch Password Requests to Console Directory Watch. [ 248.835182] systemd[1]: Started Forward Password Requests to Wall Directory Watch. [ OK ] Started Forward Password Requests to Wall Directory Watch. [ 248.867268] systemd[1]: proc-sys-fs-binfmt_misc.automount: Refusing to start, unit proc-sys-fs-binfmt_misc.mount to trigger not loaded. [ 248.869345] systemd[1]: Failed to set up automount Arbitrary Executable File Formats File System Automount Point. [FAILED] Failed to set up automount Arbitra…ormats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ 248.915334] systemd[1]: Reached target Local Encrypted Volumes. [ OK ] Reached target Local Encrypted Volumes. [ 248.954180] systemd[1]: Stopped target Switch Root. [ OK ] Stopped target Switch Root. [ 248.972292] systemd[1]: Stopped target Initrd File Systems. [ OK ] Stopped target Initrd File Systems. [ 248.986603] systemd[1]: Stopped target Initrd Root File System. [ OK ] Stopped target Initrd Root File System. [ 249.036034] systemd[1]: Reached target Local Integrity Protected Volumes. [ OK ] Reached target Local Integrity Protected Volumes. [ 249.045775] systemd[1]: Reached target Path Units. [ OK ] Reached target Path Units. [ 249.053809] systemd[1]: Reached target rpc_pipefs.target. [ OK ] Reached target rpc_pipefs.target. [ OK ] Reached target Slice Units. [ 249.071508] systemd[1]: Reached target Slice Units. [ OK ] Reached target Local Verity Protected Volumes. [ 249.095241] systemd[1]: Reached target Local Verity Protected Volumes. [ 249.507809] systemd[1]: Listening on RPCbind Server Activation Socket. [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Reached target RPC Port Mapper. [ 249.534991] systemd[1]: Reached target RPC Port Mapper. [ OK ] Listening on Process Core Dump Socket. [ 249.592670] systemd[1]: Listening on Process Core Dump Socket. [ 249.612018] systemd[1]: Listening on initctl Compatibility Named Pipe. [ OK ] Listening on initctl Compatibility Named Pipe. [ 249.639202] systemd[1]: Listening on udev Control Socket. [ OK ] Listening on udev Control Socket. [ 249.669200] systemd[1]: Listening on udev Kernel Socket. [ OK ] Listening on udev Kernel Socket. Mounting Huge Pages File System... [ 249.756245] systemd[1]: Mounting Huge Pages File System... Mounting POSIX Message Queue File System...[ 249.919807] systemd[1]: Mounting POSIX Message Queue File System... [ 250.094318] systemd[1]: Mounting Kernel Debug File System... Mounting Kernel Debug File System... [ 250.229752] systemd[1]: Mounting Kernel Trace File System... Mounting Kernel Trace File System... [ 250.262895] systemd[1]: Kernel Module supporting RPCSEC_GSS was skipped because of an unmet condition check (ConditionPathExists=/etc/krb5.keytab). [ 250.375011] systemd[1]: Starting Create List of Static Device Nodes... Starting Create List of Static Device Nodes... [ 250.435059] systemd[1]: Load legacy module configuration was skipped because no trigger condition checks were met. Starting Load Kernel Module configfs... [ 250.534370] systemd[1]: Starting Load Kernel Module configfs... [ 250.664061] systemd[1]: Starting Load Kernel Module drm... Starting Load Kernel Module drm... Starting Load Kernel Module fuse... [ 250.740364] systemd[1]: Starting Load Kernel Module fuse... [ 250.774522] systemd[1]: Read and set NIS domainname from /etc/sysconfig/network was skipped because of an unmet condition check (ConditionPathExists=/etc/sysconfig/network). [ OK ] Stopped Journal Service. [ 250.775662] systemd[1]: Stopped Journal Service. [ 250.814381] systemd[1]: systemd-journald.service: Consumed 1.463s CPU time. Starting Journal Service..[ 251.111847] systemd[1]: Starting Journal Service... . [ 251.179834] systemd[1]: Load Kernel Modules was skipped because no trigger condition checks were met. [ 251.180238] systemd[1]: TPM2 PCR Machine ID Measurement was skipped because of an unmet condition check (ConditionPathExists=/sys/firmware/efi/efivars/StubPcrKernelImage-4a67b082-0a4c-41cf-b6c7-440b29bb8c4f). Starting Remount Root and Kernel File Systems... [ 251.489675] systemd[1]: Starting Remount Root and Kernel File Systems... [ 251.543866] systemd[1]: Repartition Root Disk was skipped because no trigger condition checks were met. Startin[ 251.742104] systemd[1]: Starting Apply Kernel Variables... g Apply Kernel Variables... Starting Coldplug All udev Devices... [ 251.884097] systemd[1]: Starting Coldplug All udev Devices... [ 251.956182] fuse: init (API version 7.36) [ 252.051359] ACPI: bus type drm_connector registered [ 252.099816] systemd[1]: Mounted Huge Pages File System. [ OK ] Mounted Huge Pages File System. [ 252.121769] systemd[1]: Mounted POSIX Message Queue File System. [ OK ] Mounted POSIX Message Queue File System. [ 252.173703] systemd[1]: Mounted Kernel Debug File System. [ OK ] Mounted Kernel Debug File System. [ OK ] Mounted Kernel Trace File System. [ 252.232749] systemd[1]: Mounted Kernel Trace File System. [ OK [[ 252.259147] systemd[1]: Started Journal Service. 0m] Started Journal Service. [ OK ] Finished Create List of Static Device Nodes. [ OK ] Finished Load Kernel Module configfs. [ OK ] Finished Load Kernel Module drm. [ OK ] Finished Load Kernel Module fuse. Mounting FUSE Control File System... Mounting Kernel Configuration File System... [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Finished Apply Kernel Variables. [ OK ] Mounted FUSE Control File System. [ OK ] Mounted Kernel Configuration File System. Starting Configure read-only root support... Starting Flush Journal to Persistent Storage... Starting Create Static Device Nodes in /dev... [ 254.357039] systemd-journald[889]: Received client request to flush runtime journal. [ OK ] Finished Flush Journal to Persistent Storage. [ OK ] Finished Create Static Device Nodes in /dev. [ OK ] Reached target Preparation for Local File Systems. Mounting /mnt... Starting Rule-based Manager for Device Events and Files... [ OK ] Mounted /mnt. [* ] (1 of 7) A start job is running for /dev/vda (9s / no limit) M [ OK ] Started Rule-based Manager for Device Events and Files. [** ] (1 of 6) A start job is running for /dev/vda (12s / no limit) M [*** ] (1 of 6) A start job is running for /dev/vda (12s / no limit) M [ *** ] (2 of 6) A start job is running for…only root support (13s / no limit) M [ *** ] (2 of 6) A start job is running for…only root support (13s / no limit) M  Starting Load Kernel Module configfs... [ OK ] Finished Load Kernel Module configfs. [ OK ] Finished Coldplug All udev Devices. Mounting /home/green/git/lustre-release... [ 266.688862] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. Activating swap /dev/disk/by-label/SWAP... [ 268.335580] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Reached target Swaps. [ 269.173886] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 269.236804] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ ***] A start job is running for Configur…only root support (22s / no limit) M [ **] A start job is running for Configur…only root support (23s / no limit) M [ *] A start job is running for Configur…only root support (23s / no limit) M [ **] A start job is running for Configur…only root support (24s / no limit) M [ ***] A start job is running for Configur…only root support (24s / no limit) M [ *** ] A start job is running for Configur…only root support (25s / no limit) M [ *** ] A start job is running for Configur…only root support (25s / no limit) M [*** ] A start job is running for Configur…only root support (26s / no limit) M [** ] A start job is running for Configur…only root support (26s / no limit) [ 274.845503] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer M [* ] A start job is running for Configur…only root support (27s / no limit) M [** ] A start job is running for Configur…only root support (27s / no limit) M [*** ] A start job is running for Configur…only root support (28s / no limit) M [ *** ] A start job is running for Configur…only root support (28s / no limit) M [ *** ] A start job is running for Configur…only root support (29s / no limit) M [ ***] A start job is running for Configur…only root support (29s / no limit) M [ **] A start job is running for Configur…only root support (30s / no limit) M [ *] A start job is running for Configur…only root support (30s / no limit) M [ **] A start job is running for Configur…only root support (31s / no limit) M [ ***] A start job is running for Configur…only root support (31s / no limit) M [ *** ] A start job is running for Configur…only root support (32s / no limit) M [ *** ] A start job is running for Configur…only root support (32s / no limit) M [*** ] A start job is running for Configur…only root support (33s / no limit) M [** ] A start job is running for Configur…only root support (33s / no limit) M [* ] A start job is running for Configur…only root support (34s / no limit) M [** ] A start job is running for Configur…only root support (34s / no limit) M [*** ] A start job is running for Configur…only root support (35s / no limit) M [ *** ] A start job is running for Configur…only root support (35s / no limit) M [ *** ] A start job is running for Configur…only root support (35s / no limit) M [ ***] A start job is running for Configur…only root support (36s / no limit) M [ **] A start job is running for Configur…only root support (36s / no limit) M [ *] A start job is running for Configur…only root support (37s / no limit) M [ **] A start job is running for Configur…only root support (37s / no limit) M [ ***] A start job is running for Configur…only root support (38s / no limit) M [ OK ] Finished Configure read-only root support. [ OK ] Reached target Local File Systems. Starting Rebuild Dynamic Linker Cache... Starting Mark the need to relabel after reboot... Starting Load/Save OS Random Seed... Starting Create Volatile Files and Directories... [ OK ] Finished Mark the need to relabel after reboot. [ OK ] Finished Load/Save OS Random Seed. [ OK ] Finished Create Volatile Files and Directories. Starting RPC Bind... Starting Record System Boot/Shutdown in UTMP... [ OK ] Started RPC Bind. [ OK ] Finished Record System Boot/Shutdown in UTMP. [ *** ] A start job is running for Rebuild …amic Linker Cache (43s / no limit) M [ *** ] A start job is running for Rebuild …amic Linker Cache (43s / no limit) M [*** ] A start job is running for Rebuild …amic Linker Cache (44s / no limit) M [** ] A start job is running for Rebuild …amic Linker Cache (44s / no limit) M [* ] A start job is running for Rebuild …amic Linker Cache (45s / no limit) M [** ] A start job is running for Rebuild …amic Linker Cache (45s / no limit) M [*** ] A start job is running for Rebuild …amic Linker Cache (46s / no limit) M [ *** ] A start job is running for Rebuild …amic Linker Cache (46s / no limit) M [ *** ] A start job is running for Rebuild …amic Linker Cache (47s / no limit) M [ OK ] Finished Rebuild Dynamic Linker Cache.  Starting Update is Completed... [ OK ] Finished Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Started dnf makecache --timer. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Reached target Timer Units. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Socket Units. Starting D-Bus System Message Bus... [ OK ] Started D-Bus System Message Bus. [ OK ] Reached target Basic System. Starting Network Manager... Starting Restore /run/initramfs on shutdown... [ OK ] Started irqbalance daemon. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting RealtimeKit Scheduling Policy Service... [ OK ] Reached target sshd-keygen.target. Starting User Login Management... Starting Daemon for power management... [ OK ] Finished Restore /run/initramfs on shutdown. [FAILED] Failed to start User Login Management. See 'systemctl status systemd-logind.service' for details. [FAILED] Failed to start Daemon for power management. See 'systemctl status upower.service' for details. [ OK ] Stopped User Login Management. Starting Load Kernel Module drm... [ OK ] Stopped Daemon for power management. Starting Daemon for power management... [ OK ] Finished Load Kernel Module drm. [FAILED] Failed to start Daemon for power management. See 'systemctl status upower.service' for details. [ OK ] Started RealtimeKit Scheduling Policy Service. Starting User Login Management... [ OK ] Stopped Daemon for power management. Starting Daemon for power management... [FAILED] Failed to start User Login Management. See 'systemctl status systemd-logind.service' for details. [FAILED] Failed to start Daemon for power management. See 'systemctl status upower.service' for details. Starting Hostname Service... [ OK ] Stopped User Login Management. Starting Load Kernel Module drm... [ OK ] Stopped Daemon for power management. Starting Daemon for power management... [FAILED] Failed to start Daemon for power management. See 'systemctl status upower.service' for details. [ OK ] Finished Load Kernel Module drm. Starting User Login Management... [ OK ] Stopped Daemon for power management. Starting Daemon for power management... [FAILED] Failed to start User Login Management. See 'systemctl status systemd-logind.service' for details. [FAILED] Failed to start Daemon for power management. See 'systemctl status upower.service' for details. [ OK ] Stopped User Login Management. Starting Load Kernel Module drm... [ OK ] Stopped Daemon for power management. [FAILED] Failed to start Daemon for power management. See 'systemctl status upower.service' for details. [ OK ] Finished Load Kernel Module drm. Starting User Login Management... [FAILED] Failed to start User Login Management. See 'systemctl status systemd-logind.service' for details. [ OK ] Stopped User Login Management. Starting Load Kernel Module drm... [ OK ] Started Hostname Service. [ OK ] Finished Load Kernel Module drm. Starting User Login Management... [FAILED] Failed to start User Login Management. See 'systemctl status systemd-logind.service' for details. [ OK ] Listening on Load/Save RF Kill Switch Status /dev/rfkill Watch. Starting Network Manager Script Dispatcher Service... [ OK ] Stopped User Login Management. Starting Load Kernel Module drm... [ OK ] Started Network Manager. [ OK ] Reached target Network. Starting Network Manager Wait Online... Starting GSSAPI Proxy Daemon... Starting OpenSSH server daemon... Starting Dynamic System Tuning Daemon... [ OK ] Finished Load Kernel Module drm. [ OK ] Started Network Manager Script Dispatcher Service. [FAILED] Failed to start User Login Management. See 'systemctl status systemd-logind.service' for details. [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Reached target NFS client services. [ OK ] Reached target Preparation for Remote File Systems. [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... [ OK ] Started OpenSSH server daemon. [ OK ] Finished Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting Crash recovery kernel arming... Starting Notify NFS peers of a restart... Starting System Logging Service... [ OK ] Finished Permit User Sessions. [ OK ] Started Notify NFS peers of a restart. [ OK ] Started Command Scheduler. [ OK ] Started Getty on tty1. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Serial Getty on ttyS1. [ OK ] Reached target Login Prompts. [ OK ] Started System Logging Service. Rocky Linux 9.5 (Blue Onyx) Kernel 5.14.0rocky95-debug on an x86_64 oleg646-client login: [ 322.393294] workqueue: delayed_vfree_work hogged CPU for >10000us 19 times, consider switching to WQ_UNBOUND [ 341.563076] kexec (1591) used greatest stack depth: 20752 bytes left [ 481.775181] libcfs: loading out-of-tree module taints kernel. [ 481.775241] libcfs: module verification failed: signature and/or required key missing - tainting kernel [ 484.610235] Key type ._llcrypt registered [ 484.610283] Key type .llcrypt registered [ 487.859185] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [ 487.993762] alg: No test for adler32 (adler32-zlib) [ 493.517996] Lustre: Lustre: Build Version: 2.16.52_73_g6bb624e [ 498.825802] LNet: Added LNI 192.168.206.46@tcp [8/256/0/180] [ 498.839225] LNet: Accept secure, port 988 [ 502.336186] Key type lgssc registered [ 514.209761] Lustre: Echo OBD driver; http://www.lustre.org/ [ 535.070717] workqueue: do_free_init hogged CPU for >10000us 11 times, consider switching to WQ_UNBOUND [ 793.537664] workqueue: delayed_vfree_work hogged CPU for >10000us 35 times, consider switching to WQ_UNBOUND [ 958.038861] ------------[ cut here ]------------ [ 958.038894] refcount_t: decrement hit 0; leaking memory. [ 958.039051] WARNING: CPU: 1 PID: 2467 at lib/refcount.c:31 refcount_warn_saturate+0x7d/0x140 [ 958.039090] Modules linked in: lustre(OE) osp(OE) ofd(OE) lod(OE) mdt(OE) mdd(OE) mgs(OE) lquota(OE) lfsck(OE) obdecho(OE) mgc(OE) mdc(OE) lov(OE) osc(OE) lmv(OE) fid(OE) fld(OE) ptlrpc_gss(OE) ptlrpc(OE) obdclass(OE) ksocklnd(OE) lnet(OE) libcfs(OE) rfkill rpcsec_gss_krb5 auth_rpcgss intel_rapl_msr intel_rapl_common kvm_intel kvm rapl pcspkr i2c_piix4 joydev squashfs fuse drm ext4 mbcache jbd2 ata_generic crct10dif_pclmul crc32_pclmul crc32c_intel ata_piix ghash_clmulni_intel libata serio_raw dm_mirror dm_region_hash dm_log dm_mod [ 958.039499] CPU: 1 PID: 2467 Comm: socknal_cd00 Kdump: loaded Tainted: G OE ------- --- 5.14.0rocky95-debug #3 [ 958.039513] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.16.3-1.fc39 04/01/2014 [ 958.039522] RIP: 0010:refcount_warn_saturate+0x7d/0x140 [ 958.039536] Code: 1f 3b 6e 03 00 0f 84 ba 00 00 00 5b 5d c3 80 3d 0e 3b 6e 03 00 75 f4 48 c7 c7 00 0b fa 9e c6 05 fe 3a 6e 03 01 e8 03 ed f5 fe <0f> 0b eb dd 80 3d f2 3a 6e 03 00 75 d4 48 c7 c7 a0 09 fa 9e c6 05 [ 958.039548] RSP: 0018:ffffc900016dfa40 EFLAGS: 00010282 [ 958.039563] RAX: 0000000000000000 RBX: ffffffffa2fcd574 RCX: 0000000000000000 [ 958.039574] RDX: 0000000000000002 RSI: ffffffff9efa8ae0 RDI: 0000000000000001 [ 958.039584] RBP: 0000000000000004 R08: 0000000000000001 R09: ffffed102317fd88 [ 958.039593] R10: ffff888118bfec47 R11: 1ffff11021cff936 R12: 1ffff920002dbf4c [ 958.039603] R13: 00000000ffffffef R14: ffffffffa2fcd574 R15: 0000000000000002 [ 958.039642] FS: 0000000000000000(0000) GS:ffff888118a00000(0000) knlGS:0000000000000000 [ 958.039656] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [ 958.039667] CR2: 000000000096ebc8 CR3: 000000010ae34004 CR4: 0000000000170ef0 [ 958.039678] Call Trace: [ 958.039688] [ 958.039703] ? show_trace_log_lvl+0x1c4/0x2db [ 958.039724] ? show_trace_log_lvl+0x1c4/0x2db [ 958.039752] ? ref_tracker_free+0x481/0x600 [ 958.039773] ? refcount_warn_saturate+0x7d/0x140 [ 958.039787] ? __warn+0xce/0x180 [ 958.039803] ? refcount_warn_saturate+0x7d/0x140 [ 958.039816] ? report_bug+0x1eb/0x360 [ 958.039841] ? handle_bug+0x3c/0x70 [ 958.039857] ? exc_invalid_op+0x14/0x40 [ 958.039871] ? asm_exc_invalid_op+0x16/0x20 [ 958.039902] ? refcount_warn_saturate+0x7d/0x140 [ 958.039920] ref_tracker_free+0x481/0x600 [ 958.039947] ? local_clock_noinstr+0x9/0xb0 [ 958.039966] ? ref_tracker_dir_exit+0x690/0x690 [ 958.039979] ? __lock_release+0x4bb/0x9f0 [ 958.040003] ? lock_downgrade+0x130/0x130 [ 958.040025] ? lock_acquire+0x164/0x3c0 [ 958.040045] ? bpf_sk_storage_free+0x75/0x90 [ 958.040069] __sk_destruct+0x2c1/0x510 [ 958.040091] inet_release+0xf4/0x220 [ 958.040113] sock_release+0x82/0x190 [ 958.040138] lnet_sock_connect+0xce/0x350 [lnet] [ 958.040285] lnet_connect.part.0+0x98/0x430 [lnet] [ 958.040412] ? lnet_connect_console_error+0x500/0x500 [lnet] [ 958.040539] ? do_raw_write_trylock+0xb5/0x180 [ 958.040558] ? do_raw_write_lock+0x280/0x280 [ 958.040580] ? ksocknal_connect+0x303/0x11d0 [ksocklnd] [ 958.040675] ? ksocknal_connect+0x303/0x11d0 [ksocklnd] [ 958.040726] ksocknal_connect+0x399/0x11d0 [ksocklnd] [ 958.040776] ? do_raw_spin_trylock+0xb5/0x180 [ 958.040796] ? ksocknal_txlist_done+0x620/0x620 [ksocklnd] [ 958.040838] ? ksocknal_connd+0xa40/0xfc0 [ksocklnd] [ 958.040890] ksocknal_connd+0xa48/0xfc0 [ksocklnd] [ 958.040945] ? ksocknal_thread_fini+0x30/0x30 [ksocklnd] [ 958.040991] ? __kthread_parkme+0xba/0x200 [ 958.041011] ? prepare_to_swait_exclusive+0x240/0x240 [ 958.041035] ? __kthread_parkme+0xc7/0x200 [ 958.041055] ? ksocknal_thread_fini+0x30/0x30 [ksocklnd] [ 958.041099] kthread+0x2ab/0x350 [ 958.041115] ? kthread_insert_work_sanity_check+0xd0/0xd0 [ 958.041133] ret_from_fork+0x1f/0x30 [ 958.041173] [ 958.041183] ---[ end trace 0000000000000000 ]--- [ 960.709868] Lustre: Mounted lustre-client [ 996.138713] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1063.370726] Lustre: DEBUG MARKER: oleg646-client.virtnet: executing check_logdir /tmp/testlogs/ [ 1092.395865] Lustre: DEBUG MARKER: oleg646-client.virtnet: executing yml_node [ 1125.724197] Lustre: DEBUG MARKER: Client: 2.16.52.73 [ 1140.007498] Lustre: DEBUG MARKER: MDS: 2.16.52.73 [ 1153.077054] workqueue: bpf_prog_free_deferred hogged CPU for >10000us 4 times, consider switching to WQ_UNBOUND [ 1154.655762] Lustre: DEBUG MARKER: OSS: 2.16.52.73 [ 1165.462830] workqueue: bpf_prog_free_deferred hogged CPU for >10000us 5 times, consider switching to WQ_UNBOUND [ 1169.272512] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity ============----- Tue Apr 1 03:52:22 AM EDT 2025 [ 1241.880514] Lustre: DEBUG MARKER: - need mds1 <= 2.14.55-100-g8a84c7f9c7 for LU-14927, skip 0f [ 1254.828364] Lustre: DEBUG MARKER: - need mds1 < v2_14_55-100-g8a84c7f9c7 for LU-14927, skip 0f [ 1269.803999] Lustre: DEBUG MARKER: excepting tests: 56oc 42a 42c 42b 118c 118d 407 119i 851 817 130b 130c 130d 130e 130f 130g 312 906 [ 1282.613225] Lustre: DEBUG MARKER: skipping tests SLOW=no: 27m 60i 64b 68 71 135 136 230d 300o 842 51b [ 1297.822750] Lustre: DEBUG MARKER: === sanity: start setup 03:54:30 (1743494070) === [ 1321.891906] Lustre: DEBUG MARKER: oleg646-client.virtnet: executing check_config_client /mnt/lustre [ 1401.931204] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1415.279661] workqueue: delayed_vfree_work hogged CPU for >10000us 67 times, consider switching to WQ_UNBOUND [ 1449.048651] workqueue: bpf_prog_free_deferred hogged CPU for >10000us 7 times, consider switching to WQ_UNBOUND [ 1463.580903] Lustre: DEBUG MARKER: === sanity: finish setup 03:57:17 (1743494237) === [ 1482.116575] Lustre: DEBUG MARKER: == sanity test 0a: touch; rm ============================= 03:57:36 (1743494256) [ 1488.082458] Lustre: lustre-OST0001-osc-ffff888102f2c000: disconnect after 21s idle [ 1508.540209] Lustre: lustre-OST0000-osc-ffff888102f2c000: disconnect after 21s idle [ 1541.400205] Lustre: DEBUG MARKER: == sanity test 0b: chmod 0755 /mnt/lustre ======================================================================================= 03:58:35 (1743494315) [ 1574.260638] workqueue: bpf_prog_free_deferred hogged CPU for >10000us 11 times, consider switching to WQ_UNBOUND [ 1594.408309] Lustre: DEBUG MARKER: == sanity test 0c: check import proc ===================== 03:59:28 (1743494368) [ 1649.620587] Lustre: DEBUG MARKER: == sanity test 0d: check export proc ======================================================================================= 04:00:24 (1743494424) [ 1655.960158] ------------[ cut here ]------------ [ 1655.960218] WARNING: CPU: 1 PID: 4242 at include/linux/backing-dev.h:271 ll_writepages+0x7ef/0x9f0 [lustre] [ 1655.960444] Modules linked in: lustre(OE) osp(OE) ofd(OE) lod(OE) mdt(OE) mdd(OE) mgs(OE) lquota(OE) lfsck(OE) obdecho(OE) mgc(OE) mdc(OE) lov(OE) osc(OE) lmv(OE) fid(OE) fld(OE) ptlrpc_gss(OE) ptlrpc(OE) obdclass(OE) ksocklnd(OE) lnet(OE) libcfs(OE) rfkill rpcsec_gss_krb5 auth_rpcgss intel_rapl_msr intel_rapl_common kvm_intel kvm rapl pcspkr i2c_piix4 joydev squashfs fuse drm ext4 mbcache jbd2 ata_generic crct10dif_pclmul crc32_pclmul crc32c_intel ata_piix ghash_clmulni_intel libata serio_raw dm_mirror dm_region_hash dm_log dm_mod [ 1655.960931] CPU: 1 PID: 4242 Comm: kworker/u16:3 Kdump: loaded Tainted: G W OE ------- --- 5.14.0rocky95-debug #3 [ 1655.960947] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.16.3-1.fc39 04/01/2014 [ 1655.960959] Workqueue: writeback wb_workfn (flush-lustre-ffff888102) [ 1655.965272] RIP: 0010:ll_writepages+0x7ef/0x9f0 [lustre] [ 1655.965432] Code: f2 83 e2 07 38 d0 0f 8f db fd ff ff 84 c0 0f 84 d3 fd ff ff 4c 89 f7 e8 df b4 e3 d9 44 8b 4c 24 08 4c 8b 14 24 e9 bd fd ff ff <0f> 0b 48 b8 00 00 00 00 00 fc ff df 4c 89 f2 48 c1 ea 03 0f b6 04 [ 1655.965440] RSP: 0000:ffffc90003bd75d8 EFLAGS: 00010246 [ 1655.965448] RAX: 0000000000000000 RBX: ffffc90003bd7838 RCX: 0000000000000001 [ 1655.965454] RDX: 0000000000000002 RSI: ffffffff9ece9ea0 RDI: ffffffff9efa8b60 [ 1655.965460] RBP: ffffffffc0dbda40 R08: 0000000000000000 R09: 0000000000000000 [ 1655.965465] R10: 0000000000000000 R11: 1ffff1102289894b R12: ffff88807c0623d0 [ 1655.965470] R13: ffff88807c062190 R14: ffffc90003bd785c R15: ffffffffffffffff [ 1655.965475] FS: 0000000000000000(0000) GS:ffff888118a00000(0000) knlGS:0000000000000000 [ 1655.965485] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033 [ 1655.965491] CR2: 00007f3d2bcee008 CR3: 000000013a22c005 CR4: 0000000000170ef0 [ 1655.965496] Call Trace: [ 1655.965506] [ 1655.965515] ? show_trace_log_lvl+0x1c4/0x2db [ 1655.965531] ? show_trace_log_lvl+0x1c4/0x2db [ 1655.965561] ? do_writepages+0x16e/0x590 [ 1655.965584] ? ll_writepages+0x7ef/0x9f0 [lustre] [ 1655.965736] ? __warn+0xce/0x180 [ 1655.965751] ? ll_writepages+0x7ef/0x9f0 [lustre] [ 1655.965872] ? report_bug+0x1eb/0x360 [ 1655.965898] ? handle_bug+0x3c/0x70 [ 1655.965910] ? exc_invalid_op+0x14/0x40 [ 1655.965918] ? asm_exc_invalid_op+0x16/0x20 [ 1655.965948] ? ll_writepages+0x7ef/0x9f0 [lustre] [ 1655.966079] ? ll_writepages+0x7a1/0x9f0 [lustre] [ 1655.966198] do_writepages+0x16e/0x590 [ 1655.966219] ? writeback_set_ratelimit+0x120/0x120 [ 1655.966228] ? lock_downgrade+0x130/0x130 [ 1655.966255] ? wbc_attach_and_unlock_inode+0x388/0x6d0 [ 1655.966275] __writeback_single_inode+0x110/0x8d0 [ 1655.966296] writeback_sb_inodes+0x47e/0xcc0 [ 1655.966326] ? sync_inode_metadata+0xd0/0xd0 [ 1655.966358] ? down_read_trylock+0x43/0x50 [ 1655.966373] __writeback_inodes_wb+0xb7/0x200 [ 1655.966397] wb_writeback+0x686/0x930 [ 1655.966431] ? __writeback_inodes_wb+0x200/0x200 [ 1655.966458] ? get_nr_dirty_inodes+0x116/0x1d0 [ 1655.966480] wb_do_writeback+0x59e/0x860 [ 1655.966497] ? set_worker_desc+0x157/0x170 [ 1655.966509] ? wb_writeback+0x930/0x930 [ 1655.966527] ? lock_contended+0x340/0x340 [ 1655.966547] wb_workfn+0x12c/0x610 [ 1655.966565] ? inode_wait_for_writeback+0x30/0x30 [ 1655.966574] ? local_clock_noinstr+0x9/0xb0 [ 1655.966587] ? __lock_acquire.constprop.0+0x558/0xfb0 [ 1655.966602] ? sha256_transform+0x1027/0x2150 [ 1655.966657] ? lock_acquire+0x164/0x3c0 [ 1655.966681] process_one_work+0x89c/0x1540 [ 1655.966706] ? __lock_acquired+0x203/0x800 [ 1655.966716] ? pwq_dec_nr_in_flight+0x550/0x550 [ 1655.966740] ? assign_work+0x168/0x240 [ 1655.966755] worker_thread+0x586/0xd20 [ 1655.966781] ? process_one_work+0x1540/0x1540 [ 1655.966794] kthread+0x2ab/0x350 [ 1655.966804] ? kthread_insert_work_sanity_check+0xd0/0xd0 [ 1655.966816] ret_from_fork+0x1f/0x30 [ 1655.966854] [ 1655.966859] ---[ end trace 0000000000000000 ]--- [ 1675.166519] workqueue: css_killed_work_fn hogged CPU for >10000us 4 times, consider switching to WQ_UNBOUND [ 1721.003846] Lustre: DEBUG MARKER: == sanity test 0e: Enable DNE MDT balancing for mkdir in the ROOT ========================================================== 04:01:36 (1743494496) [ 1734.862136] Lustre: DEBUG MARKER: SKIP: sanity test_0e We need at least 2 MDTs for this test [ 1749.400386] Lustre: DEBUG MARKER: == sanity test 1: mkdir; remkdir; rmdir ================== 04:02:03 (1743494523) [ 1782.252792] workqueue: bpf_prog_free_deferred hogged CPU for >10000us 19 times, consider switching to WQ_UNBOUND [ 1799.609794] Lustre: DEBUG MARKER: == sanity test 2: mkdir; touch; rmdir; check file ======== 04:02:55 (1743494575) [ 1851.381538] Lustre: DEBUG MARKER: == sanity test 3: mkdir; touch; rmdir; check dir ========= 04:03:46 (1743494626) [ 1866.699784] workqueue: delayed_vfree_work hogged CPU for >10000us 131 times, consider switching to WQ_UNBOUND [ 1893.677979] workqueue: kernfs_notify_workfn hogged CPU for >10000us 4 times, consider switching to WQ_UNBOUND [ 1907.973182] Lustre: DEBUG MARKER: == sanity test 4: mkdir; touch dir/file; rmdir; checkdir (expect error) ========================================================== 04:04:43 (1743494683) [ 1968.077484] Lustre: DEBUG MARKER: == sanity test 5: mkdir .../d5 .../d5/d2; chmod .../d5/d2 ========================================================== 04:05:41 (1743494741) [ 2022.195426] Lustre: DEBUG MARKER: == sanity test 6a: touch f6a; chmod f6a; runas -u 500 -g 500 chmod f6a (should return error) ============================================================ 04:06:36 (1743494796) [ 2058.179714] workqueue: css_killed_work_fn hogged CPU for >10000us 5 times, consider switching to WQ_UNBOUND [ 2076.025877] Lustre: DEBUG MARKER: == sanity test 6c: touch f6c; chown f6c; runas -u 500 -g 500 chown f6c (should return error) ============================================================ 04:07:31 (1743494851) [ 2128.514757] Lustre: DEBUG MARKER: == sanity test 6e: touch+chgrp ; runas -u 500 -g 500 chgrp (should return error) ========================================================== 04:08:23 (1743494903) [ 2180.836594] Lustre: DEBUG MARKER: == sanity test 6g: verify new dir in sgid dir inherits group ========================================================== 04:09:14 (1743494954) [ 2234.296116] Lustre: DEBUG MARKER: == sanity test 6h: runas -u 500 -g 500 chown RUNAS_ID.0 .../ (should return error) ========================================================== 04:10:08 (1743495008) [ 2284.246282] Lustre: DEBUG MARKER: == sanity test 6i: touch+chmod+chgrp ; chgrp read-only file should succeed ========================================================== 04:10:59 (1743495059) [ 2307.229145] Lustre: lustre-OST0001-osc-ffff888102f2c000: disconnect after 21s idle [ 2317.471923] Lustre: lustre-OST0000-osc-ffff888102f2c000: disconnect after 22s idle [ 2317.584649] workqueue: bpf_prog_free_deferred hogged CPU for >10000us 35 times, consider switching to WQ_UNBOUND [ 2336.121198] Lustre: DEBUG MARKER: == sanity test 7a: mkdir .../d7; mcreate .../d7/f; chmod .../d7/f ============================================================== 04:11:51 (1743495111) [ 2386.708460] Lustre: DEBUG MARKER: == sanity test 7b: mkdir .../d7; mcreate d7/f2; echo foo > d7/f2 =============================================================== 04:12:42 (1743495162) [ 2437.386377] Lustre: DEBUG MARKER: == sanity test 8: mkdir .../d8; touch .../d8/f; chmod .../d8/f ================================================================= 04:13:31 (1743495211) [ 2473.597196] workqueue: kernfs_notify_workfn hogged CPU for >10000us 5 times, consider switching to WQ_UNBOUND [ 2490.004091] Lustre: DEBUG MARKER: == sanity test 9: mkdir .../d9 .../d9/d2 .../d9/d2/d3 ========================================================================== 04:14:25 (1743495265) [ 2541.556125] Lustre: DEBUG MARKER: == sanity test 10: mkdir .../d10 .../d10/d2; touch .../d10/d2/f ================================================================ 04:15:17 (1743495317) [ 2589.597191] Lustre: DEBUG MARKER: == sanity test 11: mkdir .../d11 d11/d2; chmod .../d11/d2 ====================================================================== 04:16:06 (1743495366) [ 2637.848858] Lustre: DEBUG MARKER: == sanity test 12: touch .../d12/f; chmod .../d12/f .../d12/f ================================================================== 04:16:53 (1743495413) [ 2649.535744] workqueue: drain_vmap_area_work hogged CPU for >10000us 4 times, consider switching to WQ_UNBOUND [ 2689.909928] Lustre: DEBUG MARKER: == sanity test 13: creat .../d13/f; dd .../d13/f; > .../d13/f ================================================================== 04:17:44 (1743495464) [ 2740.994075] Lustre: DEBUG MARKER: == sanity test 14: touch .../d14/f; rm .../d14/f; rm .../d14/f ================================================================= 04:18:37 (1743495517) [ 2786.234095] Lustre: DEBUG MARKER: == sanity test 15: touch .../d15/f; mv .../d15/f .../d15/f2 ==================================================================== 04:19:22 (1743495562) [ 2838.525130] Lustre: DEBUG MARKER: == sanity test 16: touch .../d16/f; rm -rf .../d16/f ===== 04:20:12 (1743495612) [ 2888.392089] workqueue: process_srcu hogged CPU for >10000us 4 times, consider switching to WQ_UNBOUND [ 2891.101863] Lustre: DEBUG MARKER: == sanity test 17a: symlinks: create, remove (real) ====== 04:21:06 (1743495666) [ 2900.655705] workqueue: css_killed_work_fn hogged CPU for >10000us 7 times, consider switching to WQ_UNBOUND [ 2946.651166] workqueue: delayed_vfree_work hogged CPU for >10000us 259 times, consider switching to WQ_UNBOUND [ 2947.353802] Lustre: DEBUG MARKER: == sanity test 17b: symlinks: create, remove (dangling) == 04:22:02 (1743495722) [ 2998.626206] Lustre: DEBUG MARKER: == sanity test 17c: symlinks: open dangling (should return error) ========================================================== 04:22:53 (1743495773) [ 3044.507314] Lustre: lustre-OST0001-osc-ffff888102f2c000: disconnect after 21s idle [ 3050.690314] Lustre: DEBUG MARKER: == sanity test 17d: symlinks: create dangling ============ 04:23:45 (1743495825) [ 3075.227951] Lustre: lustre-OST0000-osc-ffff888102f2c000: disconnect after 23s idle [ 3106.260130] Lustre: DEBUG MARKER: == sanity test 17e: symlinks: create recursive symlink (should return error) ========================================================== 04:24:40 (1743495880) [ 3161.472713] Lustre: DEBUG MARKER: == sanity test 17f: symlinks: long and very long symlink name ========================================================== 04:25:34 (1743495934) [ 3188.277316] workqueue: kernfs_notify_workfn hogged CPU for >10000us 7 times, consider switching to WQ_UNBOUND [ 3206.753725] workqueue: drain_vmap_area_work hogged CPU for >10000us 5 times, consider switching to WQ_UNBOUND [ 3218.520870] Lustre: DEBUG MARKER: == sanity test 17g: symlinks: really long symlink name and inode boundaries ========================================================== 04:26:32 (1743495992) [ 3256.507828] workqueue: kfree_rcu_monitor hogged CPU for >10000us 4 times, consider switching to WQ_UNBOUND [ 3269.335265] Lustre: DEBUG MARKER: == sanity test 17h: create objects: lov_free_memmd() doesn't lbug ========================================================== 04:27:25 (1743496045) [ 3300.505183] Lustre: lustre-OST0000-osc-ffff888102f2c000: disconnect after 24s idle [ 3323.344002] Lustre: DEBUG MARKER: == sanity test 17i: don't panic on short symlink (should return error) ========================================================== 04:28:18 (1743496098) [ 3328.622009] LustreError: 33727:0:(symlink.c:86:ll_readlink_internal()) lustre: inode [0x200000401:0x50:0x0]: symlink length 33 not expected 35 [ 3347.977701] workqueue: bpf_prog_free_deferred hogged CPU for >10000us 67 times, consider switching to WQ_UNBOUND [ 3375.864034] Lustre: DEBUG MARKER: == sanity test 17k: symlinks: rsync with xattrs enabled == 04:29:11 (1743496151) [ 3427.670337] Lustre: DEBUG MARKER: == sanity test 17l: Ensure lgetxattr's returned xattr size is consistent ========================================================== 04:30:01 (1743496201) [ 3482.022746] Lustre: DEBUG MARKER: == sanity test 17m: run e2fsck against MDT which contains short/long symlink ========================================================== 04:30:58 (1743496258) [ 3495.308532] Lustre: DEBUG MARKER: SKIP: sanity test_17m ldiskfs only test [ 3510.327390] Lustre: DEBUG MARKER: == sanity test 17n: run e2fsck against master/slave MDT which contains remote dir ========================================================== 04:31:24 (1743496284) [ 3522.312841] Lustre: DEBUG MARKER: SKIP: sanity test_17n needs >= 2 MDTs [ 3536.280043] Lustre: DEBUG MARKER: == sanity test 17o: stat file with incompat LMA feature == 04:31:51 (1743496311) [ 3564.708803] Lustre: 2481:0:(client.c:2340:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1743496336/real 1743496336] req@ffff88810cff9e40 x1828185215138688/t0(0) o400->MGC192.168.206.146@tcp@192.168.206.146@tcp:26/25 lens 224/224 e 0 to 1 dl 1743496352 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 [ 3564.709012] LustreError: MGC192.168.206.146@tcp: Connection to MGS (at 192.168.206.146@tcp) was lost; in progress operations using this service will fail [ 3564.709387] Lustre: lustre-MDT0000-mdc-ffff888102f2c000: Connection to lustre-MDT0000 (at 192.168.206.146@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 3569.817401] Lustre: 2481:0:(client.c:2340:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1743496341/real 1743496341] req@ffff88810cffad40 x1828185215139328/t0(0) o400->lustre-MDT0000-mdc-ffff888102f2c000@192.168.206.146@tcp:12/10 lens 224/224 e 0 to 1 dl 1743496357 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 [ 3569.817452] Lustre: 2481:0:(client.c:2340:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 3574.938958] Lustre: 2482:0:(client.c:2340:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1743496346/real 1743496346] req@ffff88810cffdf40 x1828185215139840/t0(0) o400->lustre-MDT0000-mdc-ffff888102f2c000@192.168.206.146@tcp:12/10 lens 224/224 e 0 to 1 dl 1743496362 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 [ 3590.335926] Lustre: Evicted from MGS (at 192.168.206.146@tcp) after server handle changed from 0xba31104fd0ece24a to 0xba31104fd0ed03c9 [ 3590.343480] Lustre: MGC192.168.206.146@tcp: Connection restored to 192.168.206.146@tcp (at 192.168.206.146@tcp) [ 3610.058379] Lustre: lustre-MDT0000-mdc-ffff888102f2c000: Connection restored to 192.168.206.146@tcp (at 192.168.206.146@tcp) [ 3641.717427] Lustre: DEBUG MARKER: oleg646-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3655.390166] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3717.850457] Lustre: DEBUG MARKER: == sanity test 17p: symlink overwrite directory error message ========================================================== 04:34:53 (1743496493) [ 3719.987486] strace (37956) used greatest stack depth: 20400 bytes left [ 3740.663194] workqueue: kernfs_notify_workfn hogged CPU for >10000us 11 times, consider switching to WQ_UNBOUND [ 3768.488509] Lustre: DEBUG MARKER: == sanity test 18: touch .../f ; ls ... ======================================================================================== 04:35:43 (1743496543) [ 3816.104058] Lustre: DEBUG MARKER: == sanity test 19a: touch .../f19 ; ls -l ... ; rm .../f19 ===================================================================== 04:36:32 (1743496592) [ 3866.133072] workqueue: process_srcu hogged CPU for >10000us 5 times, consider switching to WQ_UNBOUND [ 3869.316858] Lustre: DEBUG MARKER: == sanity test 19b: ls -l .../f19 (should return error) ======================================================================== 04:37:24 (1743496644) [ 3919.733704] Lustre: DEBUG MARKER: == sanity test 19c: runas -u 500 -g 500 touch .../f19 (should return error) ============================================================ 04:38:14 (1743496694) [ 3972.931665] Lustre: DEBUG MARKER: == sanity test 19d: cat .../f19 (should return error) ======================================================================== 04:39:08 (1743496748) [ 4001.945902] Lustre: lustre-OST0000-osc-ffff888102f2c000: disconnect after 21s idle [ 4001.945951] Lustre: Skipped 1 previous similar message [ 4026.768236] Lustre: DEBUG MARKER: == sanity test 20: touch .../f ; ls -l ... =============== 04:40:01 (1743496801) [ 4048.369952] workqueue: css_killed_work_fn hogged CPU for >10000us 11 times, consider switching to WQ_UNBOUND [ 4053.145821] Lustre: lustre-OST0000-osc-ffff888102f2c000: disconnect after 23s idle [ 4053.145867] Lustre: Skipped 1 previous similar message [ 4080.496835] Lustre: DEBUG MARKER: == sanity test 21: write to dangling link ================ 04:40:55 (1743496855) [ 4131.905780] Lustre: DEBUG MARKER: == sanity test 22: unpack tar archive as non-root user === 04:41:46 (1743496906) [ 4167.418799] workqueue: css_release_work_fn hogged CPU for >10000us 4 times, consider switching to WQ_UNBOUND [ 4185.086791] Lustre: DEBUG MARKER: == sanity test 23a: O_CREAT|O_EXCL in subdir ============= 04:42:40 (1743496960) [ 4233.417738] workqueue: kernfs_notify_workfn hogged CPU for >10000us 19 times, consider switching to WQ_UNBOUND [ 4234.832409] Lustre: DEBUG MARKER: == sanity test 23b: O_APPEND check ======================= 04:43:30 (1743497010) [ 4286.933054] Lustre: DEBUG MARKER: == sanity test 23c: O_APPEND size checks for tiny writes ========================================================== 04:44:20 (1743497060) [ 4351.069250] Lustre: DEBUG MARKER: == sanity test 23d: file offset is correct after appending writes ========================================================== 04:45:28 (1743497128) [ 4375.555644] workqueue: drain_vmap_area_work hogged CPU for >10000us 7 times, consider switching to WQ_UNBOUND [ 4395.271129] Lustre: DEBUG MARKER: == sanity test 24a: rename file to non-existent target === 04:46:12 (1743497172) [ 4406.296651] workqueue: css_free_rwork_fn hogged CPU for >10000us 4 times, consider switching to WQ_UNBOUND [ 4445.052343] Lustre: DEBUG MARKER: == sanity test 24b: rename file to existing target ======= 04:47:00 (1743497220) [ 4491.676464] Lustre: DEBUG MARKER: == sanity test 24c: rename directory to non-existent target ========================================================== 04:47:47 (1743497267) [ 4538.148574] Lustre: DEBUG MARKER: == sanity test 24d: rename directory to existing target == 04:48:35 (1743497315) [ 4585.412284] Lustre: DEBUG MARKER: == sanity test 24e: touch .../R5a/f; rename .../R5a/f .../R5b/g ================================================================ 04:49:22 (1743497362) [ 4628.570505] Lustre: DEBUG MARKER: == sanity test 24f: touch .../R6a/f R6b/g; mv .../R6a/f .../R6b/g ============================================================== 04:50:05 (1743497405) [ 4676.243658] Lustre: DEBUG MARKER: == sanity test 24g: mkdir .../R7a/d; .../R7b/d; mv .../R7a/d .../R7b/e ================================================================ 04:50:53 (1743497453) [ 4682.666755] workqueue: ldlm_pools_recalc_task [ptlrpc] hogged CPU for >10000us 4 times, consider switching to WQ_UNBOUND [ 4720.554866] Lustre: DEBUG MARKER: == sanity test 24h: mkdir .../R8a/d; .../R8a/e; .../R8b/d; .../R8b/e; rename .../R8a/d .../R8b/e ========================================================== 04:51:38 (1743497498) [ 4742.298244] Lustre: lustre-OST0001-osc-ffff888102f2c000: disconnect after 22s idle [ 4742.298281] Lustre: Skipped 1 previous similar message [ 4760.579149] Lustre: DEBUG MARKER: == sanity test 24i: rename file to dir error: touch f ; mkdir a ; rename f a ========================================================== 04:52:18 (1743497538) [ 4793.502069] Lustre: lustre-OST0000-osc-ffff888102f2c000: disconnect after 22s idle [ 4805.082086] Lustre: DEBUG MARKER: == sanity test 24j: source does not exist ====================================================================================== 04:53:01 (1743497581) [ 4844.763176] Lustre: DEBUG MARKER: == sanity test 24k: touch .../R11a/f; mv .../R11a/f .../R11a/d ================================================================= 04:53:42 (1743497622) [ 4886.977600] Lustre: DEBUG MARKER: == sanity test 24l: Renaming a file to itself ================================================================================== 04:54:24 (1743497664) [ 4926.426892] Lustre: DEBUG MARKER: == sanity test 24m: Renaming a file to a hard link to itself =================================================================== 04:55:03 (1743497703) [ 4962.265765] Lustre: DEBUG MARKER: == sanity test 24n: Statting the old file after renaming (Posix rename 2) ========================================================== 04:55:42 (1743497742) [ 4995.069153] Lustre: DEBUG MARKER: == sanity test 24o: rename of files during htree split === 04:56:14 (1743497774) [ 5387.419047] Lustre: lustre-OST0001-osc-ffff888102f2c000: disconnect after 24s idle [ 5469.338376] Lustre: lustre-OST0000-osc-ffff888102f2c000: disconnect after 21s idle [ 6203.710530] Lustre: DEBUG MARKER: == sanity test 24p: mkdir .../R12a; .../R12b; rename .../R12a .../R12b ========================================================== 05:16:25 (1743498985) [ 6229.056047] Lustre: DEBUG MARKER: == sanity test 24q: mkdir .../R13a; .../R13b; open R13b rename R13a R13b ============================================================= 05:16:50 (1743499010) [ 6257.807834] Lustre: DEBUG MARKER: == sanity test 24r: mkdir .../R14a/b; rename .../R14a .../R14a/b =============================================================== 05:17:19 (1743499039) [ 6285.422216] Lustre: DEBUG MARKER: == sanity test 24s: mkdir .../R15a/b/c; rename .../R15a .../R15a/b/c =========================================================== 05:17:46 (1743499066) [ 6314.306943] Lustre: DEBUG MARKER: == sanity test 24t: mkdir .../R16a/b/c; rename .../R16a/b/c .../R16a =========================================================== 05:18:15 (1743499095) [ 6341.424777] Lustre: DEBUG MARKER: == sanity test 24u: create stripe file =================== 05:18:42 (1743499122) [ 6366.282638] workqueue: delayed_vfree_work hogged CPU for >10000us 515 times, consider switching to WQ_UNBOUND [ 6370.299993] Lustre: DEBUG MARKER: == sanity test 24v: list large directory (test hash collision, b=17560) ========================================================== 05:19:11 (1743499151) [ 6739.414785] Lustre: DEBUG MARKER: == sanity test 24w: Reading a file larger than 4Gb ======= 05:25:21 (1743499521) [ 6761.210944] Lustre: DEBUG MARKER: == sanity test 24x: cross MDT rename/link ================ 05:25:43 (1743499543) [ 6766.254172] Lustre: DEBUG MARKER: SKIP: sanity test_24x needs >= 2 MDTs [ 6771.711546] Lustre: DEBUG MARKER: == sanity test 24y: rename/link on the same dir should succeed ========================================================== 05:25:54 (1743499554) [ 6776.384297] Lustre: DEBUG MARKER: SKIP: sanity test_24y needs >= 2 MDTs [ 6782.303268] Lustre: DEBUG MARKER: == sanity test 24z: cross-MDT rename is done as cp ======= 05:26:04 (1743499564) [ 6787.177745] Lustre: DEBUG MARKER: SKIP: sanity test_24z needs >= 2 MDTs [ 6792.866414] Lustre: DEBUG MARKER: == sanity test 24A: readdir() returns correct number of entries. ========================================================== 05:26:15 (1743499575) [ 6821.539635] workqueue: nfs4_renew_state hogged CPU for >10000us 4 times, consider switching to WQ_UNBOUND [ 6974.616393] Lustre: lustre-OST0000-osc-ffff888102f2c000: disconnect after 23s idle [ 6974.706105] Lustre: DEBUG MARKER: == sanity test 24B: readdir for striped dir return correct number of entries ========================================================== 05:29:16 (1743499756) [ 6980.089894] Lustre: DEBUG MARKER: SKIP: sanity test_24B needs >= 2 MDTs [ 6986.251779] Lustre: DEBUG MARKER: == sanity test 24C: check .. in striped dir ============== 05:29:28 (1743499768) [ 6991.594557] Lustre: DEBUG MARKER: SKIP: sanity test_24C needs >= 2 MDTs [ 6997.315011] Lustre: DEBUG MARKER: == sanity test 24E: cross MDT rename/link ================ 05:29:39 (1743499779) [ 7002.202144] Lustre: DEBUG MARKER: SKIP: sanity test_24E needs >= 4 MDTs [ 7008.531011] Lustre: DEBUG MARKER: == sanity test 24F: hash order vs readdir (LU-11330) ===== 05:29:50 (1743499790) [ 7013.508951] Lustre: DEBUG MARKER: SKIP: sanity test_24F needs >= 2 MDTs [ 7018.891333] Lustre: DEBUG MARKER: == sanity test 24G: migrate symlink in rename ============ 05:30:01 (1743499801) [ 7023.799085] Lustre: DEBUG MARKER: SKIP: sanity test_24G needs >= 2 MDTs [ 7029.130845] Lustre: DEBUG MARKER: == sanity test 24H: repeat FLD_QUERY rpc ================= 05:30:11 (1743499811) [ 7034.578283] Lustre: DEBUG MARKER: SKIP: sanity test_24H needs >= 2 MDTs [ 7040.669668] Lustre: DEBUG MARKER: == sanity test 25a: create file in symlinked directory ========================================================================= 05:30:22 (1743499822) [ 7061.656386] Lustre: lustre-OST0000-osc-ffff888102f2c000: disconnect after 20s idle [ 7061.656428] Lustre: Skipped 1 previous similar message [ 7064.370916] Lustre: DEBUG MARKER: == sanity test 25b: lookup file in symlinked directory ========================================================================= 05:30:46 (1743499846) [ 7086.198343] Lustre: DEBUG MARKER: == sanity test 26a: multiple component symlink ================================================================================= 05:31:08 (1743499868) [ 7107.740140] Lustre: lustre-OST0001-osc-ffff888102f2c000: disconnect after 21s idle [ 7109.627207] Lustre: DEBUG MARKER: == sanity test 26b: multiple component symlink at end of lookup ================================================================ 05:31:31 (1743499891) [ 7132.789123] Lustre: DEBUG MARKER: == sanity test 26c: chain of symlinks ==================== 05:31:54 (1743499914) [ 7156.373841] Lustre: DEBUG MARKER: == sanity test 26d: create multiple component recursive symlink ========================================================== 05:32:17 (1743499937) [ 7181.866849] Lustre: DEBUG MARKER: == sanity test 26e: unlink multiple component recursive symlink ========================================================== 05:32:43 (1743499963) [ 7202.715988] Lustre: DEBUG MARKER: == sanity test 26f: rm -r of a directory which has recursive symlink ========================================================== 05:33:04 (1743499984) [ 7226.673549] Lustre: DEBUG MARKER: == sanity test 27a: one stripe file ====================== 05:33:28 (1743500008) [ 7250.948208] Lustre: DEBUG MARKER: == sanity test 27b: create and write to two stripe file == 05:33:52 (1743500032) [ 7272.754483] Lustre: DEBUG MARKER: == sanity test 27ca: one stripe on specified OST ========= 05:34:15 (1743500055) [ 7295.999068] Lustre: DEBUG MARKER: == sanity test 27cb: two stripes on specified OSTs ======= 05:34:37 (1743500077) [ 7321.351946] Lustre: DEBUG MARKER: == sanity test 27cc: two stripes on the same OST ========= 05:35:02 (1743500102) [ 7343.800275] Lustre: DEBUG MARKER: == sanity test 27cd: four stripes on two OSTs ============ 05:35:25 (1743500125) [ 7365.898803] Lustre: DEBUG MARKER: == sanity test 27ce: more stripes than OSTs with -o ====== 05:35:47 (1743500147) [ 7389.840353] Lustre: DEBUG MARKER: == sanity test 27cf: 'setstripe -o' on inactive OSTs should return error ========================================================== 05:36:11 (1743500171) [ 7419.522796] Lustre: DEBUG MARKER: == sanity test 27cg: 1000 shouldn't cause too many credits ========================================================== 05:36:41 (1743500201) [ 7424.842122] Lustre: DEBUG MARKER: SKIP: sanity test_27cg ldiskfs only test [ 7430.166391] Lustre: DEBUG MARKER: == sanity test 27d: create file with default settings ==== 05:36:52 (1743500212) [ 7439.395703] workqueue: drain_vmap_area_work hogged CPU for >10000us 11 times, consider switching to WQ_UNBOUND [ 7451.451773] Lustre: DEBUG MARKER: == sanity test 27e: setstripe existing file (should return error) ========================================================== 05:37:13 (1743500233) [ 7473.750086] Lustre: DEBUG MARKER: == sanity test 27f: setstripe with bad stripe size (should return error) ========================================================== 05:37:35 (1743500255) [ 7494.967345] Lustre: DEBUG MARKER: == sanity test 27g: /home/green/git/lustre-release/lustre/utils/lfs getstripe with no objects ========================================================== 05:37:57 (1743500277) [ 7516.006555] Lustre: DEBUG MARKER: == sanity test 27ga: /home/green/git/lustre-release/lustre/utils/lfs getstripe with missing file (should return error) ========================================================== 05:38:18 (1743500298) [ 7537.868168] Lustre: DEBUG MARKER: == sanity test 27i: /home/green/git/lustre-release/lustre/utils/lfs getstripe with some objects ========================================================== 05:38:40 (1743500320) [ 7561.261560] Lustre: DEBUG MARKER: == sanity test 27j: setstripe with bad stripe offset (should return error) ========================================================== 05:39:02 (1743500342) [ 7582.940164] Lustre: DEBUG MARKER: == sanity test 27k: limit i_blksize for broken user apps ========================================================== 05:39:25 (1743500365) [ 7604.962143] Lustre: DEBUG MARKER: == sanity test 27l: check setstripe permissions (should return error) ========================================================== 05:39:47 (1743500387) [ 7624.449453] Lustre: DEBUG MARKER: SKIP: sanity test_27m skipping SLOW test 27m [ 7629.785126] Lustre: DEBUG MARKER: == sanity test 27n: create file with some full OSTs ====== 05:40:12 (1743500412) [ 7696.536525] Lustre: lustre-OST0000-osc-ffff888102f2c000: disconnect after 21s idle [ 7700.943209] Lustre: DEBUG MARKER: == sanity test 27o: create file with all full OSTs (should error) ========================================================== 05:41:23 (1743500483) [ 7768.217320] Lustre: lustre-OST0001-osc-ffff888102f2c000: disconnect after 24s idle [ 7780.207725] Lustre: DEBUG MARKER: == sanity test 27oo: don't let few threads to reserve too many objects ========================================================== 05:42:43 (1743500563) [ 7856.334194] Lustre: DEBUG MARKER: == sanity test 27p: append to a truncated file with some full OSTs ========================================================== 05:43:58 (1743500638) [ 7927.037436] Lustre: DEBUG MARKER: == sanity test 27q: append to truncated file with all OSTs full (should error) ========================================================== 05:45:09 (1743500709) [ 8004.189856] Lustre: DEBUG MARKER: == sanity test 27r: stripe file with some full OSTs (shouldn't LBUG) =========================================================== 05:46:26 (1743500786) [ 8075.447242] Lustre: DEBUG MARKER: == sanity test 27s: lsm_xfersize overflow (should error) (bug 10725) ========================================================== 05:47:37 (1743500857) [ 8095.271501] Lustre: DEBUG MARKER: == sanity test 27t: check that utils parse path correctly ========================================================== 05:47:58 (1743500878) [ 8115.925899] Lustre: DEBUG MARKER: == sanity test 27u: skip object creation on OSC w/o objects ========================================================== 05:48:18 (1743500898) [ 8226.654221] Lustre: DEBUG MARKER: == sanity test 27v: skip object creation on slow OST ===== 05:50:08 (1743501008) [ 8318.000301] Lustre: DEBUG MARKER: == sanity test 27w: check /home/green/git/lustre-release/lustre/utils/lfs setstripe -S and getstrip -d options ========================================================== 05:51:40 (1743501100) [ 8339.156599] Lustre: DEBUG MARKER: == sanity test 27wa: check /home/green/git/lustre-release/lustre/utils/lfs setstripe -c -i options ========================================================== 05:52:01 (1743501121) [ 8359.164064] Lustre: DEBUG MARKER: == sanity test 27x: create files while OST0 is degraded == 05:52:21 (1743501141) [ 8392.767467] Lustre: DEBUG MARKER: == sanity test 27y: create files while OST0 is degraded and the rest inactive ========================================================== 05:52:56 (1743501176) [ 8443.961201] Lustre: DEBUG MARKER: == sanity test 27z: check SEQ/OID on the MDT and OST filesystems ========================================================== 05:53:47 (1743501227) [ 8454.508484] Lustre: DEBUG MARKER: check file /mnt/lustre/d27z.sanity/f27z.sanity-1 [ 8458.911064] Lustre: DEBUG MARKER: FID seq 0x200000401, oid 0x6776 ver 0x0 [ 8462.905180] Lustre: DEBUG MARKER: LOV seq 0x200000401, oid 0x6776, count: 1 [ 8466.913954] Lustre: DEBUG MARKER: want: stripe:0 ost:0 oid:109/0x6d seq:0x240000400 [ 8469.677145] Lustre: lustre-OST0000-osc-ffff888102f2c000: Connection to lustre-OST0000 (at 192.168.206.146@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 8496.529394] Lustre: lustre-OST0000-osc-ffff888102f2c000: Connection restored to 192.168.206.146@tcp (at 192.168.206.146@tcp) [ 8511.532272] Lustre: DEBUG MARKER: check file /mnt/lustre/d27z.sanity/f27z.sanity-2 [ 8515.966377] Lustre: DEBUG MARKER: FID seq 0x200000401, oid 0x6778 ver 0x0 [ 8520.305299] Lustre: DEBUG MARKER: LOV seq 0x200000401, oid 0x6778, count: 2 [ 8524.654461] Lustre: DEBUG MARKER: want: stripe:0 ost:1 oid:1199/0x4af seq:0x280000400 [ 8531.098363] Lustre: lustre-OST0000-osc-ffff888102f2c000: disconnect after 24s idle [ 8531.113071] Lustre: lustre-OST0001-osc-ffff888102f2c000: Connection to lustre-OST0001 (at 192.168.206.146@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 8557.679089] Lustre: lustre-OST0001-osc-ffff888102f2c000: Connection restored to 192.168.206.146@tcp (at 192.168.206.146@tcp) [ 8572.951479] Lustre: DEBUG MARKER: want: stripe:1 ost:0 oid:110/0x6e seq:0x240000400 [ 8577.196245] Lustre: lustre-OST0000-osc-ffff888102f2c000: Connection to lustre-OST0000 (at 192.168.206.146@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 8592.538170] Lustre: lustre-OST0001-osc-ffff888102f2c000: disconnect after 24s idle [ 8602.611019] Lustre: lustre-OST0000-osc-ffff888102f2c000: Connection restored to 192.168.206.146@tcp (at 192.168.206.146@tcp) [ 8633.210284] Lustre: DEBUG MARKER: == sanity test 27A: check filesystem-wide default LOV EA values ========================================================== 05:56:56 (1743501416) [ 8638.616329] Lustre: lustre-OST0000-osc-ffff888102f2c000: disconnect after 24s idle [ 8644.066635] workqueue: ldlm_pools_recalc_task [ptlrpc] hogged CPU for >10000us 5 times, consider switching to WQ_UNBOUND [ 8652.828044] Lustre: DEBUG MARKER: == sanity test 27B: call setstripe on open unlinked file/rename victim ========================================================== 05:57:15 (1743501435) [ 8671.295471] Lustre: DEBUG MARKER: == sanity test 27Ca: check full striping across all OSTs ========================================================== 05:57:34 (1743501454) [ 8679.576347] Lustre: lustre-OST0001-osc-ffff888102f2c000: disconnect after 22s idle [ 8679.579200] Lustre: Skipped 1 previous similar message [ 8688.990098] Lustre: DEBUG MARKER: == sanity test 27Cb: more stripes than OSTs with -C ====== 05:57:52 (1743501472) [ 8707.471322] Lustre: DEBUG MARKER: == sanity test 27Cc: fewer stripes than OSTs does not set overstriping ========================================================== 05:58:10 (1743501490) [ 8723.708452] Lustre: DEBUG MARKER: == sanity test 27Cd: test maximum stripe count =========== 05:58:27 (1743501507) [ 8759.970630] workqueue: nfs4_renew_state hogged CPU for >10000us 5 times, consider switching to WQ_UNBOUND [ 8777.277732] Lustre: DEBUG MARKER: == sanity test 27Ce: test pool with overstriping ========= 05:59:21 (1743501561) [ 8807.894191] Lustre: DEBUG MARKER: == sanity test 27Cf: test default inheritance with overstriping ========================================================== 05:59:51 (1743501591) [ 8823.148681] Lustre: DEBUG MARKER: == sanity test 27Cg: test setstripe with wrong OST idx === 06:00:06 (1743501606) [ 8837.671391] Lustre: DEBUG MARKER: == sanity test 27Ci: add an overstriping component ======= 06:00:21 (1743501621) [ 8838.296174] Lustre: lustre-OST0000-osc-ffff888102f2c000: disconnect after 22s idle [ 8854.606903] Lustre: DEBUG MARKER: == sanity test 27Cj: overstriping with -C for max values in multiple of targets ========================================================== 06:00:38 (1743501638) [ 8868.416690] Lustre: DEBUG MARKER: == sanity test 27D: validate llapi_layout API ============ 06:00:52 (1743501652) [ 8904.125432] Lustre: DEBUG MARKER: == sanity test 27E: check that default extended attribute size properly increases ========================================================== 06:01:27 (1743501687) [ 8918.744357] Lustre: DEBUG MARKER: == sanity test 27F: Client resend delayed layout creation with non-zero size ========================================================== 06:01:42 (1743501702) [ 8925.343567] Lustre: lustre-OST0000-osc-ffff888102f2c000: Connection to lustre-OST0000 (at 192.168.206.146@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 8935.584838] Lustre: lustre-OST0001-osc-ffff888102f2c000: Connection to lustre-OST0001 (at 192.168.206.146@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 8944.848800] Lustre: lustre-OST0000-osc-ffff888102f2c000: Connection restored to 192.168.206.146@tcp (at 192.168.206.146@tcp) [ 8945.815970] Lustre: 2483:0:(client.c:2340:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1743501717/real 1743501717] req@ffff88807d7ac640 x1828185238125184/t0(0) o400->lustre-OST0001-osc-ffff888102f2c000@192.168.206.146@tcp:28/4 lens 224/224 e 0 to 1 dl 1743501733 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 [ 8951.036590] Lustre: lustre-OST0001-osc-ffff888102f2c000: Connection restored to 192.168.206.146@tcp (at 192.168.206.146@tcp) [ 8970.970987] Lustre: DEBUG MARKER: == sanity test 27G: Clear OST pool from stripe =========== 06:02:34 (1743501754) [ 9001.814032] Lustre: DEBUG MARKER: == sanity test 27H: Set specific OSTs stripe ============= 06:03:05 (1743501785) [ 9005.171509] Lustre: DEBUG MARKER: SKIP: sanity test_27H needs >= 3 OSTs [ 9008.966044] Lustre: DEBUG MARKER: == sanity test 27I: check that root dir striping does not break parent dir one ========================================================== 06:03:12 (1743501792) [ 9039.653923] Lustre: DEBUG MARKER: == sanity test 27Ia: check that root dir pool is dropped with conflict parent dir settings ========================================================== 06:03:43 (1743501823) [ 9072.362165] Lustre: DEBUG MARKER: == sanity test 27J: basic ops on file with foreign LOV === 06:04:16 (1743501856) [ 9089.106826] Lustre: DEBUG MARKER: == sanity test 27K: basic ops on dir with foreign LMV ==== 06:04:32 (1743501872) [ 9105.970384] Lustre: DEBUG MARKER: == sanity test 27L: lfs pool_list gives correct pool name ========================================================== 06:04:49 (1743501889) [ 9128.855798] Lustre: DEBUG MARKER: == sanity test 27M: test O_APPEND striping =============== 06:05:12 (1743501912) [ 9190.010759] Lustre: DEBUG MARKER: == sanity test 27N: lctl pool_list on separate MGS gives correct pool name ========================================================== 06:06:13 (1743501973) [ 9193.687421] Lustre: DEBUG MARKER: SKIP: sanity test_27N needs separate MGS/MDT [ 9197.654001] Lustre: DEBUG MARKER: == sanity test 27O: basic ops on foreign file of symlink type ========================================================== 06:06:21 (1743501981) [ 9214.485011] Lustre: DEBUG MARKER: == sanity test 27P: basic ops on foreign dir of foreign_symlink type ========================================================== 06:06:38 (1743501998) [ 9231.836652] Lustre: DEBUG MARKER: == sanity test 27Q: llapi_file_get_stripe() works on symlinks ========================================================== 06:06:55 (1743502015) [ 9247.434995] Lustre: DEBUG MARKER: == sanity test 27R: test max_stripecount limitation when stripe count is set to -1 ========================================================== 06:07:11 (1743502031) [ 9266.083395] Lustre: DEBUG MARKER: == sanity test 27T: no eio on close on partial write due to enosp ========================================================== 06:07:29 (1743502049) [ 9267.872553] Lustre: *** cfs_fail_loc=411, val=1*** [ 9282.792359] Lustre: DEBUG MARKER: == sanity test 27U: append pool and stripe count work with composite default layout ========================================================== 06:07:46 (1743502066) [ 9338.875492] Lustre: DEBUG MARKER: == sanity test 27V: creating widely striped file races with deactivating OST ========================================================== 06:08:42 (1743502122) [ 9342.095122] Lustre: DEBUG MARKER: SKIP: sanity test_27V needs >= 4 OSTs [ 9345.901061] Lustre: DEBUG MARKER: == sanity test 27W: test enable_setstripe_gid ============ 06:08:49 (1743502129) [ 9361.903226] Lustre: DEBUG MARKER: == sanity test 28: create/mknod/mkdir with bad file types ====================================================================== 06:09:05 (1743502145) [ 9377.658137] Lustre: DEBUG MARKER: == sanity test 29: IT_GETATTR regression ====================================================================================== 06:09:21 (1743502161) [ 9382.778325] Lustre: DEBUG MARKER: first d29 [ 9386.815659] Lustre: DEBUG MARKER: second d29 [ 9390.156646] Lustre: DEBUG MARKER: done [ 9399.384459] Lustre: lustre-OST0001-osc-ffff888102f2c000: disconnect after 20s idle [ 9404.699727] Lustre: DEBUG MARKER: == sanity test 30a: execute binary from Lustre (execve) ======================================================================== 06:09:48 (1743502188) [ 9419.282929] Lustre: DEBUG MARKER: == sanity test 30b: execute binary from Lustre as non-root ===================================================================== 06:10:03 (1743502203) [ 9434.164289] Lustre: DEBUG MARKER: == sanity test 30c: execute binary from Lustre without read perms ============================================================== 06:10:18 (1743502218) [ 9449.695172] Lustre: DEBUG MARKER: == sanity test 30d: execute binary from Lustre while clear locks ========================================================== 06:10:33 (1743502233) [ 9495.202631] workqueue: nfs4_renew_state hogged CPU for >10000us 7 times, consider switching to WQ_UNBOUND [ 9614.488170] Lustre: lustre-OST0001-osc-ffff888102f2c000: disconnect after 24s idle [ 9614.488206] Lustre: Skipped 1 previous similar message [ 9618.486914] Lustre: DEBUG MARKER: == sanity test 31a: open-unlink file ============================================================================================ 06:13:22 (1743502402) [ 9632.391678] Lustre: DEBUG MARKER: == sanity test 31b: unlink file with multiple links while open ================================================================= 06:13:36 (1743502416) [ 9647.254592] Lustre: DEBUG MARKER: == sanity test 31c: open-unlink file with multiple links ======================================================================= 06:13:51 (1743502431) [ 9661.715722] Lustre: DEBUG MARKER: == sanity test 31d: remove of open directory =================================================================================== 06:14:05 (1743502445) [ 9675.926735] Lustre: DEBUG MARKER: == sanity test 31e: remove of open non-empty directory ========================================================================= 06:14:19 (1743502459) [ 9689.742043] Lustre: DEBUG MARKER: == sanity test 31f: remove of open directory with open-unlink file ============================================================= 06:14:33 (1743502473) [ 9710.548632] workqueue: css_release_work_fn hogged CPU for >10000us 5 times, consider switching to WQ_UNBOUND [ 9711.394110] Lustre: DEBUG MARKER: == sanity test 31g: cross directory link================== 06:14:55 (1743502495) [ 9725.654957] Lustre: DEBUG MARKER: == sanity test 31h: cross directory link under child========================================================================= 06:15:09 (1743502509) [ 9739.150961] Lustre: DEBUG MARKER: == sanity test 31i: cross directory link under parent========================================================================= 06:15:23 (1743502523) [ 9753.240658] Lustre: DEBUG MARKER: == sanity test 31j: link for directory =================== 06:15:36 (1743502536) [ 9767.703864] Lustre: DEBUG MARKER: == sanity test 31k: link to file: the same, non-existing, dir ========================================================== 06:15:51 (1743502551) [ 9782.131103] Lustre: DEBUG MARKER: == sanity test 31l: link to file: target dir has trailing slash ========================================================== 06:16:06 (1743502566) [ 9785.691777] Lustre: DEBUG MARKER: SKIP: sanity test_31l need coreutils < 8.31 or kernel >= 5.18 for ln [ 9789.224258] Lustre: DEBUG MARKER: == sanity test 31m: link to file: the same, non-existing, dir ========================================================== 06:16:13 (1743502573) [ 9802.119491] Lustre: DEBUG MARKER: == sanity test 31n: check link count of unlinked file ==== 06:16:26 (1743502586) [ 9815.522483] Lustre: DEBUG MARKER: == sanity test 31o: duplicate hard links with same filename ========================================================== 06:16:39 (1743502599) [ 9885.936535] Lustre: DEBUG MARKER: == sanity test 31p: remove of open striped directory ===== 06:17:49 (1743502669) [ 9889.095247] Lustre: DEBUG MARKER: SKIP: sanity test_31p needs >= 2 MDTs [ 9892.770982] Lustre: DEBUG MARKER: == sanity test 31q: create striped directory on specific MDTs ========================================================== 06:17:56 (1743502676) [ 9895.978422] Lustre: DEBUG MARKER: SKIP: sanity test_31q needs >= 3 MDTs [ 9899.371197] Lustre: DEBUG MARKER: == sanity test 31r: open-rename(replace) race ============ 06:18:03 (1743502683) [ 9911.517632] workqueue: drain_vmap_area_work hogged CPU for >10000us 19 times, consider switching to WQ_UNBOUND [ 9913.432255] Lustre: DEBUG MARKER: == sanity test 32a: stat d32a/ext2-mountpoint/.. =============================================================================== 06:18:17 (1743502697) [ 9913.787778] loop: module loaded [ 9913.809841] loop0: detected capacity change from 0 to 16000 [ 9913.813671] EXT4-fs (loop0): mounting ext2 file system using the ext4 subsystem [ 9913.828246] EXT4-fs (loop0): mounted filesystem 635ea07b-2fba-4f0e-ab74-6a4cf94c3d89 r/w with ordered data mode. Quota mode: none. [ 9913.991389] EXT4-fs (loop0): unmounting filesystem 635ea07b-2fba-4f0e-ab74-6a4cf94c3d89. [ 9926.435078] Lustre: DEBUG MARKER: == sanity test 32b: open d32b/ext2-mountpoint/.. =============================================================================== 06:18:30 (1743502710) [ 9926.695709] loop0: detected capacity change from 0 to 16000 [ 9926.698056] EXT4-fs (loop0): mounting ext2 file system using the ext4 subsystem [ 9926.707321] EXT4-fs (loop0): mounted filesystem 635ea07b-2fba-4f0e-ab74-6a4cf94c3d89 r/w with ordered data mode. Quota mode: none. [ 9926.935134] EXT4-fs (loop0): unmounting filesystem 635ea07b-2fba-4f0e-ab74-6a4cf94c3d89. [ 9940.566145] Lustre: DEBUG MARKER: == sanity test 32c: stat d32c/ext2-mountpoint/../d2/test_dir =================================================================== 06:18:44 (1743502724) [ 9940.835083] loop0: detected capacity change from 0 to 16000 [ 9940.837447] EXT4-fs (loop0): mounting ext2 file system using the ext4 subsystem [ 9940.848331] EXT4-fs (loop0): mounted filesystem 635ea07b-2fba-4f0e-ab74-6a4cf94c3d89 r/w with ordered data mode. Quota mode: none. [ 9941.207098] EXT4-fs (loop0): unmounting filesystem 635ea07b-2fba-4f0e-ab74-6a4cf94c3d89. [ 9954.215082] Lustre: DEBUG MARKER: == sanity test 32d: open d32d/ext2-mountpoint/../d2/test_dir ========================================================== 06:18:58 (1743502738) [ 9954.483299] loop0: detected capacity change from 0 to 16000 [ 9954.486486] EXT4-fs (loop0): mounting ext2 file system using the ext4 subsystem [ 9954.497603] EXT4-fs (loop0): mounted filesystem 635ea07b-2fba-4f0e-ab74-6a4cf94c3d89 r/w with ordered data mode. Quota mode: none. [ 9954.941454] EXT4-fs (loop0): unmounting filesystem 635ea07b-2fba-4f0e-ab74-6a4cf94c3d89. [ 9967.773907] Lustre: DEBUG MARKER: == sanity test 32e: stat d32e/symlink->tmp/symlink->lustre-subdir ========================================================== 06:19:11 (1743502751) [ 9980.970417] Lustre: DEBUG MARKER: == sanity test 32f: open d32f/symlink->tmp/symlink->lustre-subdir ========================================================== 06:19:25 (1743502765) [ 9994.430443] Lustre: DEBUG MARKER: == sanity test 32g: stat d32g/symlink->tmp/symlink->lustre-subdir/2 ========================================================== 06:19:38 (1743502778) [10007.493135] Lustre: DEBUG MARKER: == sanity test 32h: open d32h/symlink->tmp/symlink->lustre-subdir/2 ========================================================== 06:19:51 (1743502791) [10020.127684] Lustre: DEBUG MARKER: == sanity test 32i: stat d32i/ext2-mountpoint/../test_file ===================================================================== 06:20:04 (1743502804) [10020.395845] loop0: detected capacity change from 0 to 16000 [10020.399750] EXT4-fs (loop0): mounting ext2 file system using the ext4 subsystem [10020.424262] EXT4-fs (loop0): mounted filesystem 635ea07b-2fba-4f0e-ab74-6a4cf94c3d89 r/w with ordered data mode. Quota mode: none. [10020.643741] EXT4-fs (loop0): unmounting filesystem 635ea07b-2fba-4f0e-ab74-6a4cf94c3d89. [10033.059014] Lustre: DEBUG MARKER: == sanity test 32j: open d32j/ext2-mountpoint/../test_file ===================================================================== 06:20:17 (1743502817) [10033.370729] loop0: detected capacity change from 0 to 16000 [10033.374152] EXT4-fs (loop0): mounting ext2 file system using the ext4 subsystem [10033.385400] EXT4-fs (loop0): mounted filesystem 635ea07b-2fba-4f0e-ab74-6a4cf94c3d89 r/w with ordered data mode. Quota mode: none. [10033.593312] EXT4-fs (loop0): unmounting filesystem 635ea07b-2fba-4f0e-ab74-6a4cf94c3d89. [10046.029757] Lustre: DEBUG MARKER: == sanity test 32k: stat d32k/ext2-mountpoint/../d2/test_file ================================================================== 06:20:30 (1743502830) [10046.341123] loop0: detected capacity change from 0 to 16000 [10046.344658] EXT4-fs (loop0): mounting ext2 file system using the ext4 subsystem [10046.353981] EXT4-fs (loop0): mounted filesystem 635ea07b-2fba-4f0e-ab74-6a4cf94c3d89 r/w with ordered data mode. Quota mode: none. [10046.696201] EXT4-fs (loop0): unmounting filesystem 635ea07b-2fba-4f0e-ab74-6a4cf94c3d89. [10059.873738] Lustre: DEBUG MARKER: == sanity test 32l: open d32l/ext2-mountpoint/../d2/test_file ================================================================== 06:20:44 (1743502844) [10060.201188] loop0: detected capacity change from 0 to 16000 [10060.204599] EXT4-fs (loop0): mounting ext2 file system using the ext4 subsystem [10060.217468] EXT4-fs (loop0): mounted filesystem 635ea07b-2fba-4f0e-ab74-6a4cf94c3d89 r/w with ordered data mode. Quota mode: none. [10060.594192] EXT4-fs (loop0): unmounting filesystem 635ea07b-2fba-4f0e-ab74-6a4cf94c3d89. [10073.051743] Lustre: DEBUG MARKER: == sanity test 32m: stat d32m/symlink->tmp/symlink->lustre-root ================================================================ 06:20:57 (1743502857) [10085.717098] Lustre: DEBUG MARKER: == sanity test 32n: open d32n/symlink->tmp/symlink->lustre-root ================================================================ 06:21:10 (1743502870) [10098.481133] Lustre: DEBUG MARKER: == sanity test 32o: stat d32o/symlink->tmp/symlink->lustre-root/ ========================================================== 06:21:22 (1743502882) [10112.505265] Lustre: DEBUG MARKER: == sanity test 32p: open d32p/symlink->tmp/symlink->lustre-root/ ========================================================== 06:21:36 (1743502896) [10115.601797] Lustre: DEBUG MARKER: 32p_1 [10118.735001] Lustre: DEBUG MARKER: 32p_2 [10121.840325] Lustre: DEBUG MARKER: 32p_3 [10125.229365] Lustre: DEBUG MARKER: 32p_4 [10128.472809] Lustre: DEBUG MARKER: 32p_5 [10131.367346] Lustre: DEBUG MARKER: 32p_6 [10134.405063] Lustre: DEBUG MARKER: 32p_7 [10137.646916] Lustre: DEBUG MARKER: 32p_8 [10140.506999] Lustre: DEBUG MARKER: 32p_9 [10143.632259] Lustre: DEBUG MARKER: 32p_10 [10156.663799] Lustre: DEBUG MARKER: == sanity test 32q: stat follows mountpoints in Lustre (should return error) ========================================================== 06:22:21 (1743502941) [10156.941498] loop0: detected capacity change from 0 to 16000 [10156.943574] EXT4-fs (loop0): mounting ext2 file system using the ext4 subsystem [10156.953036] EXT4-fs (loop0): mounted filesystem 635ea07b-2fba-4f0e-ab74-6a4cf94c3d89 r/w with ordered data mode. Quota mode: none. [10157.127267] EXT4-fs (loop0): unmounting filesystem 635ea07b-2fba-4f0e-ab74-6a4cf94c3d89. [10169.672930] Lustre: DEBUG MARKER: == sanity test 32r: opendir follows mountpoints in Lustre (should return error) ========================================================== 06:22:33 (1743502953) [10170.063226] loop0: detected capacity change from 0 to 16000 [10170.066233] EXT4-fs (loop0): mounting ext2 file system using the ext4 subsystem [10170.078705] EXT4-fs (loop0): mounted filesystem 635ea07b-2fba-4f0e-ab74-6a4cf94c3d89 r/w with ordered data mode. Quota mode: none. [10170.278084] EXT4-fs (loop0): unmounting filesystem 635ea07b-2fba-4f0e-ab74-6a4cf94c3d89. [10182.781867] Lustre: DEBUG MARKER: == sanity test 33aa: write file with mode 444 (should return error) ========================================================== 06:22:47 (1743502967) [10186.096870] Lustre: DEBUG MARKER: 33_1 [10189.290948] Lustre: DEBUG MARKER: 33_2 [10201.206590] Lustre: DEBUG MARKER: == sanity test 33a: test open file(mode=0444) with O_RDWR (should return error) ========================================================== 06:23:05 (1743502985) [10214.463099] Lustre: DEBUG MARKER: == sanity test 33b: test open file with malformed flags (No panic) ========================================================== 06:23:18 (1743502998) [10227.897518] Lustre: DEBUG MARKER: == sanity test 33c: test write_bytes stats =============== 06:23:32 (1743503012) [10243.321908] Lustre: DEBUG MARKER: == sanity test 33d: openfile with 444 modes and malformed flags under remote dir ========================================================== 06:23:47 (1743503027) [10246.521344] Lustre: DEBUG MARKER: SKIP: sanity test_33d needs >= 2 MDTs [10250.035289] Lustre: DEBUG MARKER: == sanity test 33e: mkdir and striped directory should have same mode ========================================================== 06:23:54 (1743503034) [10253.397601] Lustre: DEBUG MARKER: SKIP: sanity test_33e needs >= 2 MDTs [10257.081166] Lustre: DEBUG MARKER: == sanity test 33f: nonroot user can create, access, and remove a striped directory ========================================================== 06:24:01 (1743503041) [10260.221104] Lustre: DEBUG MARKER: SKIP: sanity test_33f needs >= 2 MDTs [10263.902436] Lustre: DEBUG MARKER: == sanity test 33g: nonroot user create already existing root created file ========================================================== 06:24:07 (1743503047) [10277.158902] Lustre: DEBUG MARKER: == sanity test 33h: temp file is located on the same MDT as target (crush) ========================================================== 06:24:21 (1743503061) [10280.504355] Lustre: DEBUG MARKER: SKIP: sanity test_33h needs >= 2 MDTs [10284.103124] Lustre: DEBUG MARKER: == sanity test 33hh: temp file is located on the same MDT as target (crush2) ========================================================== 06:24:28 (1743503068) [10287.417942] Lustre: DEBUG MARKER: SKIP: sanity test_33hh needs >= 2 MDTs [10290.861660] Lustre: DEBUG MARKER: == sanity test 33i: striped directory can be accessed when one MDT is down ========================================================== 06:24:35 (1743503075) [10293.992026] Lustre: DEBUG MARKER: SKIP: sanity test_33i needs >= 2 MDTs [10297.416362] Lustre: DEBUG MARKER: == sanity test 33j: lfs setdirstripe -D -i x,y,x should fail ========================================================== 06:24:41 (1743503081) [10300.351015] Lustre: DEBUG MARKER: SKIP: sanity test_33j needs >= 2 MDTs [10303.768693] Lustre: DEBUG MARKER: == sanity test 34a: truncate file that has not been opened ===================================================================== 06:24:47 (1743503087) [10317.768164] Lustre: DEBUG MARKER: == sanity test 34b: O_RDONLY opening file doesn't create objects =============================================================== 06:25:01 (1743503101) [10331.450455] Lustre: DEBUG MARKER: == sanity test 34c: O_RDWR opening file-with-size works ======================================================================== 06:25:15 (1743503115) [10343.919027] Lustre: DEBUG MARKER: == sanity test 34d: write to sparse file ======================================================================================= 06:25:28 (1743503128) [10351.768729] Lustre: lustre-OST0001-osc-ffff888102f2c000: disconnect after 21s idle [10351.768797] Lustre: Skipped 3 previous similar messages [10357.768225] Lustre: DEBUG MARKER: == sanity test 34e: create objects, some with size and some without ============================================================ 06:25:41 (1743503141) [10370.662042] Lustre: DEBUG MARKER: == sanity test 34f: read from a file with no objects until EOF ================================================================= 06:25:54 (1743503154) [10372.248330] Lustre: lustre-OST0000-osc-ffff888102f2c000: disconnect after 24s idle [10384.750544] Lustre: DEBUG MARKER: == sanity test 34g: truncate long file ========================================================================================= 06:26:08 (1743503168) [10398.713541] Lustre: DEBUG MARKER: == sanity test 34h: ftruncate file under grouplock should not block ========================================================== 06:26:23 (1743503183) [10415.151476] Lustre: DEBUG MARKER: == sanity test 35a: exec file with mode 444 (should return and not leak) ========================================================== 06:26:39 (1743503199) [10428.259763] Lustre: DEBUG MARKER: == sanity test 36a: MDS utime check (mknod, utime) ======= 06:26:52 (1743503212) [10440.722155] Lustre: DEBUG MARKER: == sanity test 36b: OST utime check (open, utime) ======== 06:27:04 (1743503224) [10453.232202] Lustre: DEBUG MARKER: == sanity test 36c: non-root MDS utime check (mknod, utime) ========================================================== 06:27:17 (1743503237) [10465.710752] Lustre: DEBUG MARKER: == sanity test 36d: non-root OST utime check (open, utime) ========================================================== 06:27:30 (1743503250) [10477.770076] Lustre: DEBUG MARKER: == sanity test 36e: utime on non-owned file (should return error) ========================================================== 06:27:42 (1743503262) [10490.650328] Lustre: DEBUG MARKER: == sanity test 36f: utime on file racing with OST BRW write ==================================================================== 06:27:54 (1743503274) [10504.539032] Lustre: DEBUG MARKER: == sanity test 36g: FMD cache expiry =============================================================================== 06:28:09 (1743503289) [10525.849221] Lustre: lustre-OST0000-osc-ffff888102f2c000: disconnect after 20s idle [10562.744937] Lustre: DEBUG MARKER: == sanity test 36h: utime on file racing with OST BRW write ==================================================================== 06:29:07 (1743503347) [10576.372578] Lustre: DEBUG MARKER: == sanity test 36i: change mtime on striped directory ==== 06:29:20 (1743503360) [10579.529678] Lustre: DEBUG MARKER: SKIP: sanity test_36i needs >= 2 MDTs [10582.872302] Lustre: DEBUG MARKER: == sanity test 38: open a regular file with O_DIRECTORY should return -ENOTDIR ============================================================= 06:29:27 (1743503367) [10595.148166] Lustre: DEBUG MARKER: == sanity test 39a: mtime changed on create ============== 06:29:39 (1743503379) [10610.207281] Lustre: DEBUG MARKER: == sanity test 39b: mtime change on open, link, unlink, rename ================================================================ 06:29:54 (1743503394) [10625.280440] Lustre: DEBUG MARKER: == sanity test 39c: mtime change on rename ===================================================================================== 06:30:09 (1743503409) [10633.368199] Lustre: lustre-OST0000-osc-ffff888102f2c000: disconnect after 20s idle [10640.707522] Lustre: DEBUG MARKER: == sanity test 39d: create, utime, stat ======================================================================================== 06:30:24 (1743503424) [10654.130163] Lustre: DEBUG MARKER: == sanity test 39e: create, stat, utime, stat ================================================================================== 06:30:38 (1743503438) [10666.664886] Lustre: DEBUG MARKER: == sanity test 39f: create, stat, sleep, utime, stat =========================================================================== 06:30:51 (1743503451) [10681.303173] Lustre: DEBUG MARKER: == sanity test 39g: write, chmod, stat ========================================================================================= 06:31:05 (1743503465) [10696.130894] Lustre: DEBUG MARKER: == sanity test 39h: write, utime within one second, stat ======================================================================= 06:31:20 (1743503480) [10705.048217] Lustre: lustre-OST0001-osc-ffff888102f2c000: disconnect after 21s idle [10705.048254] Lustre: Skipped 4 previous similar messages [10709.390225] Lustre: DEBUG MARKER: == sanity test 39i: write, rename, stat ======================================================================================== 06:31:34 (1743503494) [10724.605954] Lustre: DEBUG MARKER: == sanity test 39j: write, rename, close, stat ================================================================================= 06:31:48 (1743503508) [10731.083716] LustreError: 172466:0:(osc_io.c:902:osc_io_write_start()) cfs_fail_timeout id 412 sleeping for 1000ms [10732.128076] LustreError: 172466:0:(osc_io.c:902:osc_io_write_start()) cfs_fail_timeout id 412 awake [10751.736150] Lustre: DEBUG MARKER: == sanity test 39k: write, utime, close, stat ================================================================================== 06:32:16 (1743503536) [10766.110045] Lustre: DEBUG MARKER: == sanity test 39l: directory atime update ===================================================================================== 06:32:30 (1743503550) [10788.607534] Lustre: DEBUG MARKER: == sanity test 39m: test atime and mtime before 1970 ===== 06:32:52 (1743503572) [10803.605679] Lustre: DEBUG MARKER: == sanity test 39n: check that O_NOATIME is honored ====== 06:33:08 (1743503588) [10830.217130] Lustre: DEBUG MARKER: == sanity test 39o: directory cached attributes updated after create ========================================================== 06:33:34 (1743503614) [10843.367202] Lustre: DEBUG MARKER: == sanity test 39p: remote directory cached attributes updated after create ================================================================== 06:33:47 (1743503627) [10846.556062] Lustre: DEBUG MARKER: SKIP: sanity test_39p needs >= 2 MDTs [10849.917220] Lustre: DEBUG MARKER: == sanity test 39r: lazy atime update on OST ============= 06:33:54 (1743503634) [10853.109324] Lustre: DEBUG MARKER: SKIP: sanity test_39r ldiskfs only test [10856.484944] Lustre: DEBUG MARKER: == sanity test 39q: close won't zero out atime =========== 06:34:00 (1743503640) [10869.491894] Lustre: DEBUG MARKER: == sanity test 39s: relatime is supported ================ 06:34:13 (1743503653) [10871.375826] Lustre: Unmounted lustre-client [10872.084290] Lustre: Mounted lustre-client [10879.488860] Lustre: Unmounted lustre-client [10880.083216] Lustre: Mounted lustre-client [10892.578656] Lustre: DEBUG MARKER: == sanity test 39u: stat race ============================ 06:34:37 (1743503677) [10894.929589] Lustre: *** cfs_fail_loc=1434, val=5173*** [10894.929671] LustreError: 178406:0:(file.c:6246:ll_getattr_dentry()) cfs_race id 1435 sleeping [10895.939014] LustreError: 178409:0:(file.c:1531:ll_merge_attr_nolock()) cfs_race id 1435 sleeping [10900.119888] LustreError: 178406:0:(file.c:6246:ll_getattr_dentry()) cfs_fail_race id 1435 awake: rc=0 [10901.143884] LustreError: 178409:0:(file.c:1531:ll_merge_attr_nolock()) cfs_fail_race id 1435 awake: rc=0 [10901.143933] LustreError: 178409:0:(file.c:1536:ll_merge_attr_nolock()) cfs_fail_timeout id 1435 sleeping for 1000ms [10902.185599] LustreError: 178409:0:(file.c:1536:ll_merge_attr_nolock()) cfs_fail_timeout id 1435 awake [10902.186035] LustreError: 178409:0:(file.c:6246:ll_getattr_dentry()) cfs_race id 1435 sleeping [10907.287896] LustreError: 178409:0:(file.c:6246:ll_getattr_dentry()) cfs_fail_race id 1435 awake: rc=0 [10919.376572] Lustre: DEBUG MARKER: == sanity test 40: failed open(O_TRUNC) doesn't truncate ======================================================================= 06:35:03 (1743503703) [10932.114008] Lustre: DEBUG MARKER: == sanity test 41: test small file write + fstat =============================================================================== 06:35:16 (1743503716) [10945.261143] Lustre: DEBUG MARKER: SKIP: sanity test_42a skipping ALWAYS excluded test 42a [10948.555389] Lustre: DEBUG MARKER: SKIP: sanity test_42b skipping ALWAYS excluded test 42b [10951.400056] Lustre: DEBUG MARKER: SKIP: sanity test_42c skipping ALWAYS excluded test 42c [10954.493153] Lustre: DEBUG MARKER: == sanity test 42d: test complete truncate of file with cached dirty data ========================================================== 06:35:38 (1743503738) [10970.061111] Lustre: DEBUG MARKER: == sanity test 42e: verify sub-RPC writes are not done synchronously ========================================================== 06:35:54 (1743503754) [11218.594924] Lustre: DEBUG MARKER: == sanity test 43A: execution of file opened for write should return -ETXTBSY ========================================================== 06:40:02 (1743504002) [11232.209599] Lustre: DEBUG MARKER: == sanity test 43a: open(RDWR) of file being executed should return -ETXTBSY ========================================================== 06:40:16 (1743504016) [11245.826437] Lustre: DEBUG MARKER: == sanity test 43b: truncate of file being executed should return -ETXTBSY ========================================================== 06:40:30 (1743504030) [11261.349685] Lustre: DEBUG MARKER: == sanity test 43c: md5sum of copy into lustre =========== 06:40:45 (1743504045) [11274.290286] Lustre: DEBUG MARKER: == sanity test 44A: zero length read from a sparse stripe ========================================================== 06:40:58 (1743504058) [11286.822098] Lustre: DEBUG MARKER: == sanity test 44a: test sparse pwrite ========================================================================================= 06:41:11 (1743504071) [11303.484285] Lustre: DEBUG MARKER: == sanity test 44b: write one byte at offset 0xfffffffe000 ========================================================== 06:41:27 (1743504087) [11318.010993] Lustre: DEBUG MARKER: == sanity test 44c: write 1 byte at max_object_bytes - 1 offset ========================================================== 06:41:42 (1743504102) [11331.677610] Lustre: DEBUG MARKER: == sanity test 44d: if write at position fails (EFBIG), so should do append ========================================================== 06:41:56 (1743504116) [11343.881366] Lustre: DEBUG MARKER: == sanity test 44e: write and read maximal stripes ======= 06:42:08 (1743504128) [11390.805398] Lustre: DEBUG MARKER: == sanity test 44f: Check fiemap for sparse files ======== 06:42:54 (1743504174) [11394.161892] Lustre: DEBUG MARKER: SKIP: sanity test_44f ORI-366/LU-1941: FIEMAP unimplemented on ZFS [11397.431864] Lustre: DEBUG MARKER: == sanity test 45: osc io page accounting ================ 06:43:01 (1743504181) [11411.171801] Lustre: DEBUG MARKER: == sanity test 46: dirtying a previously written page ========================================================================== 06:43:15 (1743504195) [11423.266548] Lustre: DEBUG MARKER: == sanity test 48a: Access renamed working dir (should return errors)=========================================================== 06:43:27 (1743504207) [11436.330285] Lustre: DEBUG MARKER: == sanity test 48b: Access removed working dir (should return errors)=========================================================== 06:43:40 (1743504220) [11448.908427] Lustre: DEBUG MARKER: == sanity test 48c: Access removed working subdir (should return errors) ========================================================== 06:43:53 (1743504233) [11461.776452] Lustre: DEBUG MARKER: == sanity test 48d: Access removed parent subdir (should return errors) ========================================================== 06:44:06 (1743504246) [11474.885468] Lustre: DEBUG MARKER: == sanity test 48e: Access to recreated parent subdir (should return errors) ========================================================== 06:44:18 (1743504258) [11477.888629] workqueue: css_release_work_fn hogged CPU for >10000us 7 times, consider switching to WQ_UNBOUND [11489.054419] Lustre: DEBUG MARKER: == sanity test 48f: non-zero nlink dir unlink won't LBUG() ========================================================== 06:44:33 (1743504273) [11492.243594] Lustre: DEBUG MARKER: SKIP: sanity test_48f needs >= 2 MDTs [11495.934497] Lustre: DEBUG MARKER: == sanity test 49: Change max_pages_per_rpc won't break osc extent ========================================================== 06:44:39 (1743504279) [11511.933902] Lustre: DEBUG MARKER: == sanity test 50: special situations: /proc symlinks ========================================================================= 06:44:55 (1743504295) [11525.766569] Lustre: DEBUG MARKER: == sanity test 51a: special situations: split htree with empty entry ============================================================ 06:45:09 (1743504309) [11546.698101] Lustre: DEBUG MARKER: SKIP: sanity test_51b skipping SLOW test 51b [11550.435089] Lustre: DEBUG MARKER: == sanity test 51d: check LOV round-robin OST object distribution ========================================================== 06:45:34 (1743504334) [11553.699108] Lustre: DEBUG MARKER: SKIP: sanity test_51d needs >= 3 OSTs [11557.246694] Lustre: DEBUG MARKER: == sanity test 51e: check file nlink limit =============== 06:45:41 (1743504341) [11559.958338] Lustre: DEBUG MARKER: SKIP: sanity test_51e ldiskfs only test [11563.103064] Lustre: DEBUG MARKER: == sanity test 51f: check many open files limit ========== 06:45:47 (1743504347) [11640.804643] workqueue: rht_deferred_worker hogged CPU for >10000us 4 times, consider switching to WQ_UNBOUND [11784.354628] workqueue: nfs4_renew_state hogged CPU for >10000us 11 times, consider switching to WQ_UNBOUND [11804.081639] workqueue: rht_deferred_worker hogged CPU for >10000us 5 times, consider switching to WQ_UNBOUND [11833.492634] workqueue: rht_deferred_worker hogged CPU for >10000us 7 times, consider switching to WQ_UNBOUND [11882.637416] Lustre: DEBUG MARKER: == sanity test 52a: append-only flag test (should return errors) ========================================================== 06:51:06 (1743504666) [11883.029077] LustreError: 200289:0:(file.c:246:ll_close_inode_openhandle()) lustre-clilmv-ffff888102ee1000: inode [0x200000bd2:0x55d8:0x0] mdc close failed: rc = -1 [11895.562049] Lustre: DEBUG MARKER: == sanity test 52b: immutable flag test (should return errors) ================================================================= 06:51:19 (1743504679) [11907.808407] Lustre: DEBUG MARKER: == sanity test 53: verify that MDS and OSTs agree on pre-creation ============================================================== 06:51:32 (1743504692) [11926.680499] Lustre: DEBUG MARKER: == sanity test 54a: unix domain socket test ============== 06:51:51 (1743504711) [11939.251964] Lustre: DEBUG MARKER: == sanity test 54b: char device works in lustre ================================================================================ 06:52:03 (1743504723) [11951.485638] Lustre: DEBUG MARKER: == sanity test 54c: block device works in lustre =============================================================================== 06:52:15 (1743504735) [11951.803981] block device autoloading is deprecated and will be removed. [11951.810218] loop3: detected capacity change from 0 to 8200 [11952.002040] operation not supported error, dev loop3, sector 0 op 0x3:(DISCARD) flags 0x800 phys_seg 1 prio class 2 [11952.012883] operation not supported error, dev loop3, sector 2 op 0x3:(DISCARD) flags 0x0 phys_seg 1 prio class 2 [11952.018644] operation not supported error, dev loop3, sector 8 op 0x3:(DISCARD) flags 0x800 phys_seg 1 prio class 2 [11952.024684] operation not supported error, dev loop3, sector 8064 op 0x9:(WRITE_ZEROES) flags 0x8000800 phys_seg 0 prio class 2 [11952.064882] operation not supported error, dev loop3, sector 42 op 0x9:(WRITE_ZEROES) flags 0x8000800 phys_seg 0 prio class 2 [11952.349994] operation not supported error, dev loop3, sector 580 op 0x9:(WRITE_ZEROES) flags 0x8000800 phys_seg 0 prio class 2 [11952.679519] EXT4-fs (loop3): mounting ext2 file system using the ext4 subsystem [11952.738033] EXT4-fs (loop3): mounted filesystem 87580e5d-91ff-4d1c-920c-eba21aa50ebf r/w without journal. Quota mode: none. [11953.068417] EXT4-fs (loop3): unmounting filesystem 87580e5d-91ff-4d1c-920c-eba21aa50ebf. [11965.471933] Lustre: DEBUG MARKER: == sanity test 54d: fifo device works in lustre ================================================================================ 06:52:29 (1743504749) [11977.464112] Lustre: DEBUG MARKER: == sanity test 54e: console/tty device works in lustre ================================================================================ 06:52:41 (1743504761) aaaaaa [11989.765006] Lustre: DEBUG MARKER: == sanity test 55a: OBD device life cycle unit tests ===== 06:52:54 (1743504774) [11990.155250] Lustre: OBD: obd_test_setup [11990.155286] Lustre: OBD: obd_name: obd_name, obd_num: 6, obd_uuid: obd_uuid [11990.155320] Lustre: OBD: class_name2dev(): 6, PASS [11990.155334] Lustre: OBD: class_uuid2dev(): 6, PASS [11990.155342] Lustre: OBD: class_name2obd(): 6, PASS [11990.155351] Lustre: OBD: class_uuid2obd(): 6, PASS [11990.262051] Lustre: OBD: obd_test_cleanup [12002.522258] Lustre: DEBUG MARKER: == sanity test 55b: Load and unload max OBD devices ====== 06:53:06 (1743504786) [12880.610490] Lustre: DEBUG MARKER: == sanity test 56a: check /home/green/git/lustre-release/lustre/utils/lfs getstripe ========================================================== 07:07:44 (1743505664) [12897.094354] Lustre: DEBUG MARKER: == sanity test 56b: check /home/green/git/lustre-release/lustre/utils/lfs getdirstripe ========================================================== 07:08:01 (1743505681) [12911.925035] Lustre: DEBUG MARKER: == sanity test 56bb: check /home/green/git/lustre-release/lustre/utils/lfs getdirstripe layout is YAML ========================================================== 07:08:15 (1743505695) [12926.776809] Lustre: DEBUG MARKER: == sanity test 56bc: check '/home/green/git/lustre-release/lustre/utils/lfs getdirstripe --yaml' params are valid ========================================================== 07:08:30 (1743505710) [12929.973839] Lustre: DEBUG MARKER: SKIP: sanity test_56bc need >= 2 MDTs [12933.649292] Lustre: DEBUG MARKER: == sanity test 56c: check 'lfs df' showing device status ========================================================== 07:08:37 (1743505717) [12971.757763] Lustre: DEBUG MARKER: == sanity test 56d: 'lfs df -v' prints only configured devices ========================================================== 07:09:15 (1743505755) [12986.392048] Lustre: DEBUG MARKER: == sanity test 56e: 'lfs df' Handle non LustreFS [13000.166248] Lustre: DEBUG MARKER: == sanity test 56g: check lfs find -name ================= 07:09:44 (1743505784) [13016.257693] Lustre: DEBUG MARKER: == sanity test 56h: check lfs find ! -name =============== 07:09:59 (1743505799) [13029.765254] Lustre: DEBUG MARKER: == sanity test 56i: check 'lfs find -ost UUID' skips directories ========================================================== 07:10:14 (1743505814) [13041.856929] Lustre: DEBUG MARKER: == sanity test 56ib: check 'lfs find -ost INDEX_RANGE' command ========================================================== 07:10:26 (1743505826) [13054.248031] Lustre: DEBUG MARKER: == sanity test 56j: check lfs find -type d =============== 07:10:38 (1743505838) [13066.618863] Lustre: DEBUG MARKER: == sanity test 56k: check lfs find -type f =============== 07:10:51 (1743505851) [13078.572028] Lustre: DEBUG MARKER: == sanity test 56l: check lfs find -type b =============== 07:11:03 (1743505863) [13090.350080] Lustre: DEBUG MARKER: == sanity test 56m: check lfs find -type c =============== 07:11:14 (1743505874) [13101.718460] Lustre: DEBUG MARKER: == sanity test 56n: check lfs find -type l =============== 07:11:26 (1743505886) [13114.714393] Lustre: DEBUG MARKER: == sanity test 56o: check lfs find -mtime for old files == 07:11:38 (1743505898) [13130.100848] Lustre: DEBUG MARKER: == sanity test 56ob: check lfs find -atime -mtime -ctime with units ========================================================== 07:11:54 (1743505914) [13147.060418] Lustre: DEBUG MARKER: SKIP: sanity test_56oc skipping excluded test 56oc [13150.440049] Lustre: DEBUG MARKER: == sanity test 56od: check lfs find -btime with units ==== 07:12:14 (1743505934) [13163.331256] Lustre: DEBUG MARKER: sanity test_56od: @@@@@@ FAIL: '/home/green/git/lustre-release/lustre/utils/lfs find /mnt/lustre/d56od.sanity -btime -5s -type d' wrong: found 1, expected 4 [13184.513476] Lustre: DEBUG MARKER: == sanity test 56oe: check lfs find with time range ====== 07:12:48 (1743505968) [13222.838276] Lustre: DEBUG MARKER: == sanity test 56p: check lfs find -uid and ! -uid ======= 07:13:27 (1743506007) [13237.703219] Lustre: DEBUG MARKER: == sanity test 56q: check lfs find -gid and ! -gid ======= 07:13:41 (1743506021) [13251.580213] Lustre: DEBUG MARKER: == sanity test 56r: check lfs find -size works =========== 07:13:56 (1743506036) [13269.724408] Lustre: DEBUG MARKER: == sanity test 56ra: check lfs find -size -lazy works for data on OSTs ========================================================== 07:14:13 (1743506053) [13293.041330] Lustre: DEBUG MARKER: == sanity test 56rb: check lfs find --size --ost/--mdt works ========================================================== 07:14:36 (1743506076) [13307.776669] Lustre: DEBUG MARKER: == sanity test 56rc: check lfs find --mdt-count/--mdt-hash works ========================================================== 07:14:51 (1743506091) [13311.212523] Lustre: DEBUG MARKER: SKIP: sanity test_56rc needs at least 2 MDTs [13314.997435] Lustre: DEBUG MARKER: == sanity test 56rd: check lfs find --printf special files ========================================================== 07:14:58 (1743506098) [13330.256554] Lustre: DEBUG MARKER: == sanity test 56re: check lfs find -printf width format specifiers are consistant with regular find ========================================================== 07:15:14 (1743506114) [13351.063421] Lustre: DEBUG MARKER: == sanity test 56rf: check lfs find -printf width format specifiers for lustre specific formats ========================================================== 07:15:34 (1743506134) [13377.255845] Lustre: DEBUG MARKER: == sanity test 56s: check lfs find -stripe-count works === 07:16:01 (1743506161) [13395.106023] Lustre: DEBUG MARKER: == sanity test 56t: check lfs find -stripe-size works ==== 07:16:18 (1743506178) [13414.192867] Lustre: DEBUG MARKER: == sanity test 56u: check lfs find -stripe-index works === 07:16:37 (1743506197) [13430.805010] Lustre: DEBUG MARKER: == sanity test 56v: check 'lfs find -m match with lfs getstripe -m' ========================================================== 07:16:54 (1743506214) [13447.095719] Lustre: DEBUG MARKER: == sanity test 56wa: check lfs_migrate -c stripe_count works ========================================================== 07:17:11 (1743506231) [13557.347937] Lustre: DEBUG MARKER: == sanity test 56wb: check lfs_migrate pool support ====== 07:19:01 (1743506341) [13588.585576] Lustre: DEBUG MARKER: == sanity test 56wc: check unrecognized options for lfs_migrate are passed through ========================================================== 07:19:32 (1743506372) [13635.032538] Lustre: DEBUG MARKER: == sanity test 56wd: check lfs_migrate --rsync and --no-rsync work ========================================================== 07:20:19 (1743506419) [13650.314465] Lustre: DEBUG MARKER: == sanity test 56we: check lfs_migrate --non-direct|-D support ========================================================== 07:20:34 (1743506434) [13665.829932] Lustre: DEBUG MARKER: == sanity test 56x: lfs migration support ================ 07:20:50 (1743506450) [13680.698898] Lustre: DEBUG MARKER: == sanity test 56xa: lfs migration --block support ======= 07:21:04 (1743506464) [13695.118308] Lustre: DEBUG MARKER: == sanity test 56xb: lfs migration hard link support ===== 07:21:19 (1743506479) [14048.742010] Lustre: DEBUG MARKER: == sanity test 56xc: lfs migration autostripe ============ 07:27:12 (1743506832) [14170.137858] Lustre: DEBUG MARKER: == sanity test 56xd: check lfs_migrate --yaml and --copy support ========================================================== 07:29:14 (1743506954) [14200.064732] Lustre: DEBUG MARKER: == sanity test 56xe: migrate a composite layout file ===== 07:29:44 (1743506984) [14249.953025] Lustre: DEBUG MARKER: == sanity test 56xf: FID is not lost during migration of a composite layout file ========================================================== 07:30:34 (1743507034) [14268.997880] Lustre: DEBUG MARKER: == sanity test 56xg: lfs migrate pool support ============ 07:30:52 (1743507052) [14334.863860] Lustre: DEBUG MARKER: == sanity test 56xh: lfs migrate bandwidth limitation support ========================================================== 07:31:59 (1743507119) [14380.094828] Lustre: DEBUG MARKER: == sanity test 56xi: lfs migrate stats support =========== 07:32:44 (1743507164) [14399.628497] Lustre: DEBUG MARKER: == sanity test 56xj: lfs migrate -b should not cause starvation of threads on OSS ========================================================== 07:33:03 (1743507183) [14438.335922] Lustre: DEBUG MARKER: == sanity test 56xk: lfs mirror resync bandwidth limitation support ========================================================== 07:33:42 (1743507222) [14460.040479] Lustre: DEBUG MARKER: == sanity test 56xl: lfs mirror resync stats support ===== 07:34:03 (1743507243) [14477.547313] Lustre: DEBUG MARKER: == sanity test 56y: lfs find -L raid0|released =========== 07:34:21 (1743507261) [14491.590164] Lustre: DEBUG MARKER: == sanity test 56z: lfs find should continue after an error ========================================================== 07:34:35 (1743507275) [14508.524473] Lustre: DEBUG MARKER: == sanity test 56aa: lfs find --size under striped dir === 07:34:52 (1743507292) [14511.654458] Lustre: DEBUG MARKER: SKIP: sanity test_56aa needs >= 2 MDTs [14515.404907] Lustre: DEBUG MARKER: == sanity test 56ab: lfs find --blocks =================== 07:34:59 (1743507299) [14535.960010] Lustre: DEBUG MARKER: == sanity test 56aca: check lfs find -perm with octal representation ========================================================== 07:35:19 (1743507319) [14551.862635] workqueue: drain_vmap_area_work hogged CPU for >10000us 35 times, consider switching to WQ_UNBOUND [14574.026029] Lustre: DEBUG MARKER: == sanity test 56acb: check lfs find -perm with symbolic representation ========================================================== 07:35:57 (1743507357) [14593.912720] Lustre: DEBUG MARKER: == sanity test 56acc: check parsing error for lfs find -perm ========================================================== 07:36:18 (1743507378) [14607.437573] Lustre: DEBUG MARKER: == sanity test 56ba: test lfs find --component-end, -start, -count, and -flags ========================================================== 07:36:31 (1743507391) [14627.947481] Lustre: DEBUG MARKER: == sanity test 56ca: check lfs find --mirror-count|-N and --mirror-state ========================================================== 07:36:52 (1743507412) [14646.094843] Lustre: DEBUG MARKER: == sanity test 56da: test lfs find with long paths ======= 07:37:10 (1743507430) [14664.581866] Lustre: DEBUG MARKER: == sanity test 56db: test 'lfs df -m' only shows MDT devices ========================================================== 07:37:28 (1743507448) [14678.215880] Lustre: DEBUG MARKER: == sanity test 56dc: test 'lfs df -o' only shows OST devices ========================================================== 07:37:42 (1743507462) [14691.480562] Lustre: DEBUG MARKER: == sanity test 56dd: test lfs find with mindepth argument ========================================================== 07:37:55 (1743507475) [14704.622546] Lustre: DEBUG MARKER: == sanity test 56ea: test lfs find -printf option ======== 07:38:08 (1743507488) [14734.888799] Lustre: DEBUG MARKER: == sanity test 56eaa: test lfs find -printf added functions ========================================================== 07:38:38 (1743507518) [14799.104971] Lustre: DEBUG MARKER: == sanity test 56eab: test lfs find -ls function ========= 07:39:43 (1743507583) [14819.649921] Lustre: DEBUG MARKER: == sanity test 56eb: check lfs getstripe on symlink ====== 07:40:04 (1743507604) [14832.969088] Lustre: DEBUG MARKER: == sanity test 56ebb: check /home/green/git/lustre-release/lustre/utils/lfs getdirstripe for FIFO file ========================================================== 07:40:17 (1743507617) [14845.473184] Lustre: DEBUG MARKER: == sanity test 56ec: check lfs getstripe,setstripe --hex --yaml ========================================================== 07:40:29 (1743507629) [14858.321395] Lustre: DEBUG MARKER: == sanity test 56ed: verify new YAML format is valid and back-compatible ========================================================== 07:40:42 (1743507642) [14904.722893] Lustre: DEBUG MARKER: == sanity test 56eda: check lfs find --links ============= 07:41:28 (1743507688) [14917.928919] Lustre: DEBUG MARKER: == sanity test 56edb: check lfs find --links for directory striped on multiple MDTs ========================================================== 07:41:42 (1743507702) [14921.281569] Lustre: DEBUG MARKER: SKIP: sanity test_56edb needs >= 2 MDTs [14924.602153] Lustre: DEBUG MARKER: == sanity test 56ef: lfs find with multiple paths ======== 07:41:48 (1743507708) [14938.821298] Lustre: DEBUG MARKER: == sanity test 56eg: lfs find -xattr ===================== 07:42:02 (1743507722) [14953.727208] Lustre: DEBUG MARKER: == sanity test 56eh: check lfs find --skip =============== 07:42:17 (1743507737) [14973.932260] Lustre: DEBUG MARKER: == sanity test 56ei: test lfs find --printf prints correct projid for special files ========================================================== 07:42:38 (1743507758) [14987.694546] Lustre: DEBUG MARKER: == sanity test 56ej: lfs migration --non-block copy ====== 07:42:51 (1743507771) [15001.021565] Lustre: DEBUG MARKER: == sanity test 57a: verify MDS filesystem created with large inodes ============================================================ 07:43:05 (1743507785) [15003.980971] Lustre: DEBUG MARKER: SKIP: sanity test_57a ldiskfs only test [15007.212910] Lustre: DEBUG MARKER: == sanity test 57b: default LOV EAs are stored inside large inodes ============================================================= 07:43:11 (1743507791) [15010.075400] Lustre: DEBUG MARKER: SKIP: sanity test_57b ldiskfs only test [15013.476059] Lustre: DEBUG MARKER: == sanity test 58: verify cross-platform wire constants ======================================================================== 07:43:17 (1743507797) [15025.705177] Lustre: DEBUG MARKER: == sanity test 59: verify cancellation of llog records async =================================================================== 07:43:30 (1743507810) [15084.882474] Lustre: DEBUG MARKER: == sanity test complete, duration 13911 sec ============== 07:44:28 (1743507868) [15088.109582] Lustre: DEBUG MARKER: === sanity: start cleanup 07:44:32 (1743507872) === [15118.783517] Lustre: DEBUG MARKER: === sanity: finish cleanup 07:45:03 (1743507903) === [15139.991921] Lustre: 2482:0:(client.c:2340:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1743507911/real 1743507911] req@ffff888113d1b240 x1828185267026048/t0(0) o400->MGC192.168.206.146@tcp@192.168.206.146@tcp:26/25 lens 224/224 e 0 to 1 dl 1743507927 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 [15139.991921] Lustre: 2483:0:(client.c:2340:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1743507911/real 1743507911] req@ffff888113d1e940 x1828185267026176/t0(0) o400->lustre-MDT0000-mdc-ffff888102ee1000@192.168.206.146@tcp:12/10 lens 224/224 e 0 to 1 dl 1743507927 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 [15139.992049] Lustre: lustre-MDT0000-mdc-ffff888102ee1000: Connection to lustre-MDT0000 (at 192.168.206.146@tcp) was lost; in progress operations using this service will wait for recovery to complete [15139.992074] LustreError: MGC192.168.206.146@tcp: Connection to MGS (at 192.168.206.146@tcp) was lost; in progress operations using this service will fail [15146.135933] Lustre: 2482:0:(client.c:2340:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1743507917/real 1743507917] req@ffff888005d00f40 x1828185267026688/t0(0) o400->lustre-MDT0000-mdc-ffff888102ee1000@192.168.206.146@tcp:12/10 lens 224/224 e 0 to 1 dl 1743507933 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 [15150.237093] Lustre: Evicted from MGS (at 192.168.206.146@tcp) after server handle changed from 0xba31104fd1187572 to 0xba31104fd13a3f42 [15150.238321] Lustre: MGC192.168.206.146@tcp: Connection restored to 192.168.206.146@tcp (at 192.168.206.146@tcp) [15151.255796] Lustre: 2481:0:(client.c:2340:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1743507922/real 1743507922] req@ffff888005d05040 x1828185267027200/t0(0) o400->lustre-MDT0000-mdc-ffff888102ee1000@192.168.206.146@tcp:12/10 lens 224/224 e 0 to 1 dl 1743507938 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 [15162.955050] Lustre: DEBUG MARKER: oleg646-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [15166.111721] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [15170.279829] Lustre: Unmounted lustre-client [15201.713402] Key type lgssc unregistered [15202.481095] LNet: 277146:0:(lib-ptl.c:966:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [15203.550880] LNet: Removed LNI 192.168.206.46@tcp [15205.779430] Key type .llcrypt unregistered [15205.779511] Key type ._llcrypt unregistered