[ 0.000000] Linux version 4.18.0rh8.10-debug (green@maintenance) (gcc version 8.5.0 20210514 (Red Hat 8.5.0-26) (GCC)) #2 SMP Mon Jul 14 01:24:22 EDT 2025 [ 0.000000] Command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers' [ 0.000000] x86/fpu: xstate_offset[2]: 576, xstate_sizes[2]: 256 [ 0.000000] x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'standard' format. [ 0.000000] signal: max sigframe size: 1776 [ 0.000000] BIOS-provided physical RAM map: [ 0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable [ 0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000000100000-0x00000000bffcdfff] usable [ 0.000000] BIOS-e820: [mem 0x00000000bffce000-0x00000000bfffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000100000000-0x0000000146dfffff] usable [ 0.000000] NX (Execute Disable) protection: active [ 0.000000] SMBIOS 2.8 present. [ 0.000000] DMI: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.17.0-10.fc44 06/10/2025 [ 0.000000] Hypervisor detected: KVM [ 0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00 [ 0.000000] kvm-clock: using sched offset of 573483108 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2399.998 MHz processor [ 0.000000] last_pfn = 0x146e00 max_arch_pfn = 0x400000000 [ 0.000000] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT [ 0.000000] last_pfn = 0xbffce max_arch_pfn = 0x400000000 [ 0.000000] found SMP MP-table at [mem 0x000f54b0-0x000f54bf] [ 0.000000] RAMDISK: [mem 0xbcc54000-0xbffbffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F52D0 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE247C 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE2318 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 0022D8 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE238C 000090 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE241C 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE2454 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe2318-0xbffe238b] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe2317] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe238c-0xbffe241b] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe241c-0xbffe2453] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe2454-0xbffe247b] [ 0.000000] No NUMA configuration found [ 0.000000] Faking a node at [mem 0x0000000000000000-0x0000000146dfffff] [ 0.000000] NODE_DATA(0) allocated [mem 0x1465a3000-0x1465cdfff] [ 0.000000] Reserving 256MB of memory at 2752MB for crashkernel (System RAM: 4205MB) [ 0.000000] Zone ranges: [ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.000000] DMA32 [mem 0x0000000001000000-0x00000000ffffffff] [ 0.000000] Normal [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Device empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff] [ 0.000000] node 0: [mem 0x0000000000100000-0x00000000bffcdfff] [ 0.000000] node 0: [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Zeroed struct page in unavailable ranges: 4756 pages [ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x0000000146dfffff] [ 0.000000] ACPI: PM-Timer IO Port: 0x608 [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) [ 0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) [ 0.000000] Using ACPI (MADT) for SMP configuration information [ 0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000] TSC deadline timer available [ 0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs [ 0.000000] kvm-guest: KVM setup pv remote TLB flush [ 0.000000] kvm-guest: setup PV sched yield [ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff] [ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff] [ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff] [ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff] [ 0.000000] PM: Registered nosave memory: [mem 0xbffce000-0xbfffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xc0000000-0xfeffbfff] [ 0.000000] PM: Registered nosave memory: [mem 0xfeffc000-0xfeffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xff000000-0xfffbffff] [ 0.000000] PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff] [ 0.000000] [mem 0xc0000000-0xfeffbfff] available for PCI devices [ 0.000000] Booting paravirtualized kernel on KVM [ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns [ 0.000000] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1 [ 0.000000] percpu: Embedded 63 pages/cpu s221184 r8192 d28672 u524288 [ 0.000000] kvm-guest: PV spinlocks enabled [ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1059606 [ 0.000000] Policy zone: Normal [ 0.000000] Kernel command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] Specific versions of hardware are certified with Red Hat Enterprise Linux 8. Please see the list of hardware certified with Red Hat Enterprise Linux 8 at https://catalog.redhat.com. [ 0.000000] audit: disabled (until reboot) [ 0.000000] software IO TLB: area num 4. [ 0.000000] Memory: 2895240K/4306352K available (18435K kernel code, 11221K rwdata, 7248K rodata, 2908K init, 18040K bss, 524580K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] ftrace: allocating 41240 entries in 162 pages [ 0.000000] ftrace: allocated 162 pages with 3 groups [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] rcu: RCU event tracing is enabled. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ 0.000000] rcu: RCU callback double-/use-after-free debug enabled. [ 0.000000] Rude variant of Tasks RCU enabled. [ 0.000000] Tracing variant of Tasks RCU enabled. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 0.000000] NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16 [ 0.000000] random: get_random_bytes called from start_kernel+0x622/0x9a8 with crng_init=0 [ 0.001000] Console: colour *CGA 80x25 [ 0.001000] printk: console [ttyS1] enabled [ 0.001000] ACPI: Core revision 20220331 [ 0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.001009] APIC: Switch to symmetric I/O mode setup [ 0.002321] x2apic enabled [ 0.003006] Switched APIC routing to physical x2apic. [ 0.004010] kvm-guest: setup PV IPIs [ 0.007492] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.008000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.008018] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.009010] pid_max: default: 32768 minimum: 301 [ 0.010121] LSM: Security Framework initializing [ 0.011037] Yama: becoming mindful. [ 0.012032] SELinux: Initializing. [ 0.013061] *** VALIDATE selinux *** [ 0.020750] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.025110] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.026148] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.027108] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.029013] *** VALIDATE tmpfs *** [ 0.031167] *** VALIDATE proc *** [ 0.032213] *** VALIDATE cgroup *** [ 0.033008] *** VALIDATE cgroup2 *** [ 0.034257] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.035146] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.036007] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.037049] Spectre V2 : User space: Vulnerable [ 0.038007] Speculative Store Bypass: Vulnerable [ 0.041218] debug: unmapping init [mem 0xffffffff97859000-0xffffffff97860fff] [ 0.044000] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.044641] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.045029] ... version: 2 [ 0.046010] ... bit width: 48 [ 0.047008] ... generic registers: 4 [ 0.048009] ... value mask: 0000ffffffffffff [ 0.049012] ... max period: 00007fffffffffff [ 0.050011] ... fixed-purpose events: 3 [ 0.051012] ... event mask: 000000070000000f [ 0.052294] rcu: Hierarchical SRCU implementation. [ 0.054318] smp: Bringing up secondary CPUs ... [ 0.055537] x86: Booting SMP configuration: [ 0.056023] .... node #0, CPUs: #1 #2 #3 [ 0.059776] smp: Brought up 1 node, 4 CPUs [ 0.061014] smpboot: Max logical packages: 1 [ 0.062016] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.145020] node 0 deferred pages initialised in 78ms [ 0.148100] devtmpfs: initialized [ 0.150240] x86/mm: Memory block size: 128MB [ 0.153854] gcov: version magic: 0x41383552 [ 0.157326] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.160086] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.163246] pinctrl core: initialized pinctrl subsystem [ 0.165157] [ 0.165807] ************************************************************* [ 0.168011] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.170009] ** ** [ 0.173012] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.175008] ** ** [ 0.178011] ** This means that this kernel is built to expose internal ** [ 0.180009] ** IOMMU data structures, which may compromise security on ** [ 0.183009] ** your system. ** [ 0.185010] ** ** [ 0.188010] ** If you see this message and you are not debugging the ** [ 0.190009] ** kernel, report this immediately to your vendor! ** [ 0.192008] ** ** [ 0.194008] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.196012] ************************************************************* [ 0.199712] NET: Registered protocol family 16 [ 0.201489] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.204046] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.206114] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.210085] cpuidle: using governor menu [ 0.212000] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.213463] PCI: Using configuration type 1 for base access [ 0.216160] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.226058] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.229017] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.233056] cryptd: max_cpu_qlen set to 1000 [ 0.236251] ACPI: Added _OSI(Module Device) [ 0.237010] ACPI: Added _OSI(Processor Device) [ 0.238013] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.239024] ACPI: Added _OSI(Processor Aggregator Device) [ 0.244081] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.250492] ACPI: Interpreter enabled [ 0.251043] ACPI: PM: (supports S0 S3 S4 S5) [ 0.252008] ACPI: Using IOAPIC for interrupt routing [ 0.254069] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.256323] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.265587] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.267022] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.269012] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.272061] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.276895] acpiphp: Slot [2] registered [ 0.278137] acpiphp: Slot [5] registered [ 0.280126] acpiphp: Slot [6] registered [ 0.281082] acpiphp: Slot [7] registered [ 0.282069] acpiphp: Slot [8] registered [ 0.284075] acpiphp: Slot [9] registered [ 0.285099] acpiphp: Slot [10] registered [ 0.287082] acpiphp: Slot [3] registered [ 0.288089] acpiphp: Slot [4] registered [ 0.289080] acpiphp: Slot [11] registered [ 0.291079] acpiphp: Slot [12] registered [ 0.292067] acpiphp: Slot [13] registered [ 0.294101] acpiphp: Slot [14] registered [ 0.295067] acpiphp: Slot [15] registered [ 0.297082] acpiphp: Slot [16] registered [ 0.299074] acpiphp: Slot [17] registered [ 0.300068] acpiphp: Slot [18] registered [ 0.302068] acpiphp: Slot [19] registered [ 0.303094] acpiphp: Slot [20] registered [ 0.305101] acpiphp: Slot [21] registered [ 0.306075] acpiphp: Slot [22] registered [ 0.308075] acpiphp: Slot [23] registered [ 0.309081] acpiphp: Slot [24] registered [ 0.311068] acpiphp: Slot [25] registered [ 0.312068] acpiphp: Slot [26] registered [ 0.314094] acpiphp: Slot [27] registered [ 0.315079] acpiphp: Slot [28] registered [ 0.317072] acpiphp: Slot [29] registered [ 0.318071] acpiphp: Slot [30] registered [ 0.320074] acpiphp: Slot [31] registered [ 0.321062] PCI host bridge to bus 0000:00 [ 0.323013] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.325016] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.327015] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.330015] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.333017] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.336011] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.338190] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.340975] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.344136] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.353756] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.358010] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.360014] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.362011] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.365013] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.368127] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.370835] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.374045] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.376944] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.383014] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.396012] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.402009] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.407263] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.425012] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.438013] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.483013] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.502454] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.523011] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.550013] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.606022] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.624077] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.640014] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.655012] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.690014] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.708024] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.728012] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.747012] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.792019] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.806100] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.823014] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.836014] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.882013] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 0.899612] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.909016] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.920021] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.950026] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 0.963081] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.966364] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.970357] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.973319] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.975168] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.980099] iommu: Default domain type: Passthrough [ 0.983465] SCSI subsystem initialized [ 0.984110] ACPI: bus type USB registered [ 0.986088] usbcore: registered new interface driver usbfs [ 0.987056] usbcore: registered new interface driver hub [ 0.990083] usbcore: registered new device driver usb [ 0.991143] pps_core: LinuxPPS API ver. 1 registered [ 0.993008] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.996050] PTP clock support registered [ 0.999169] EDAC MC: Ver: 3.0.0 [ 1.001111] PCI: Using ACPI for IRQ routing [ 1.002813] NetLabel: Initializing [ 1.004008] NetLabel: domain hash size = 128 [ 1.006009] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 1.007066] NetLabel: unlabeled traffic allowed by default [ 1.010037] vgaarb: loaded [ 1.011230] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 1.013016] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 1.019110] clocksource: Switched to clocksource kvm-clock [ 1.126875] VFS: Disk quotas dquot_6.6.0 [ 1.128479] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 1.131687] *** VALIDATE ramfs *** [ 1.133089] *** VALIDATE hugetlbfs *** [ 1.134770] pnp: PnP ACPI init [ 1.137306] pnp: PnP ACPI: found 6 devices [ 1.155329] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 1.158719] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 1.160922] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 1.163317] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 1.165544] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 1.168191] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 1.171243] NET: Registered protocol family 2 [ 1.173920] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 1.178760] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 1.182380] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 1.187856] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 1.191726] TCP: Hash tables configured (established 65536 bind 65536) [ 1.194808] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 1.198484] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 1.201521] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 1.204910] NET: Registered protocol family 1 [ 1.208930] RPC: Registered named UNIX socket transport module. [ 1.211270] RPC: Registered udp transport module. [ 1.213269] RPC: Registered tcp transport module. [ 1.215328] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 1.217888] NET: Registered protocol family 44 [ 1.219581] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 1.221930] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 1.225513] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 1.228115] PCI: CLS 0 bytes, default 64 [ 1.229918] Unpacking initramfs... [ 2.591040] debug: unmapping init [mem 0xffff9d417cc54000-0xffff9d417ffbffff] [ 2.595292] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.597812] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.600556] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 3.092309] Initialise system trusted keyrings [ 3.094169] Key type blacklist registered [ 3.096111] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 3.105364] zbud: loaded [ 3.108467] *** VALIDATE nfs *** [ 3.109842] *** VALIDATE nfs4 *** [ 3.111507] pstore: using deflate compression [ 3.115039] Platform Keyring initialized [ 3.215588] NET: Registered protocol family 38 [ 3.217456] Key type asymmetric registered [ 3.219082] Asymmetric key parser 'x509' registered [ 3.220896] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 3.223758] io scheduler mq-deadline registered [ 3.225369] io scheduler kyber registered [ 3.227119] io scheduler bfq registered [ 3.229242] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 3.232380] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 3.235250] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 3.240047] ACPI: Power Button [PWRF] [ 3.249414] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 3.258276] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 3.304424] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 3.314864] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 3.363123] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 3.396463] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.426747] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.434289] Non-volatile memory driver v1.3 [ 3.435723] Linux agpgart interface v0.103 [ 3.470608] virtio_blk virtio1: [vda] 145904 512-byte logical blocks (74.7 MB/71.2 MiB) [ 3.473289] vda: detected capacity change from 0 to 74702848 [ 3.501628] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.504839] vdb: detected capacity change from 0 to 1073741824 [ 3.520712] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.523762] vdc: detected capacity change from 0 to 2621440000 [ 3.539818] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.542901] vdd: detected capacity change from 0 to 2621440000 [ 3.567952] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.571112] vde: detected capacity change from 0 to 4294967296 [ 3.598404] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.601233] vdf: detected capacity change from 0 to 4294967296 [ 3.610697] libphy: Fixed MDIO Bus: probed [ 3.621291] usbcore: registered new interface driver usbserial_generic [ 3.623609] usbserial: USB Serial support registered for generic [ 3.625832] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.629810] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.631285] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.634131] mousedev: PS/2 mouse device common for all mice [ 3.637364] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.637379] rtc_cmos 00:05: RTC can wake from S4 [ 3.643292] rtc_cmos 00:05: registered as rtc0 [ 3.645558] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.646460] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.649508] intel_pstate: CPU model not supported [ 3.655115] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.659463] hid: raw HID events driver (C) Jiri Kosina [ 3.661896] usbcore: registered new interface driver usbhid [ 3.664022] usbhid: USB HID core driver [ 3.665988] drop_monitor: Initializing network drop monitor service [ 3.668438] Initializing XFRM netlink socket [ 3.670801] NET: Registered protocol family 10 [ 3.673374] Segment Routing with IPv6 [ 3.674980] NET: Registered protocol family 17 [ 3.676980] mpls_gso: MPLS GSO support [ 3.683164] RAS: Correctable Errors collector initialized. [ 3.685207] AVX version of gcm_enc/dec engaged. [ 3.686757] AES CTR mode by8 optimization enabled [ 3.775512] sched_clock: Marking stable (3775491732, 0)->(4643665132, -868173400) [ 3.779715] registered taskstats version 1 [ 3.783069] Loading compiled-in X.509 certificates [ 3.786159] zswap: loaded using pool lzo/zbud [ 3.813282] Key type big_key registered [ 3.826715] Key type encrypted registered [ 3.828305] ima: No TPM chip found, activating TPM-bypass! [ 3.830148] ima: Allocated hash algorithm: sha1 [ 3.831575] ima: No architecture policies found [ 3.833123] evm: Initialising EVM extended attributes: [ 3.834956] evm: security.selinux [ 3.836116] evm: security.ima [ 3.837246] evm: security.capability [ 3.838434] evm: HMAC attrs: 0x1 [ 3.840569] rtc_cmos 00:05: setting system clock to 2026-07-30 06:25:30 UTC (1785392730) [ 3.846830] debug: unmapping init [mem 0xffffffff98803000-0xffffffff989fffff] [ 3.849734] debug: unmapping init [mem 0xffffffff97582000-0xffffffff97858fff] [ 3.858210] Write protecting the kernel read-only data: 28672k [ 3.861704] debug: unmapping init [mem 0xffffffff95c03000-0xffffffff95dfffff] [ 3.864512] debug: unmapping init [mem 0xffffffff96514000-0xffffffff965fffff] [ 3.901423] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 3.912084] systemd[1]: Detected virtualization kvm. [ 3.913974] systemd[1]: Detected architecture x86-64. [ 3.915748] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.942414] systemd[1]: No hostname configured. [ 3.944415] systemd[1]: Set hostname to . [ 3.946779] random: systemd: uninitialized urandom read (16 bytes read) [ 3.949536] systemd[1]: Initializing machine ID from random generator. [ 3.998629] random: ln: uninitialized urandom read (6 bytes read) [ 4.095913] random: systemd: uninitialized urandom read (16 bytes read) [ 4.099498] systemd[1]: Listening on udev Control Socket. [ OK ] Listening on udev Control Socket. [ 4.104759] systemd[1]: Reached target Slices. [ OK ] Reached target Slices. [ 4.108765] systemd[1]: Reached target Timers. [ OK ] Reached target Timers. [ OK ] Reached target Initrd Root Device. [ OK ] Listening on Journal Socket (/dev/log). [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Paths. [ OK ] Listening on udev Kernel Socket. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Listening on Journal Socket. [ OK ] Reached target Sockets. Starting Create list of required st…ce nodes for the current kernel... Starting Setup Virtual Console... Starting Apply Kernel Variables... Starting Journal Service... [ OK ] Started Memstrack Anylazing Service. [ OK ] Reached target Local File Systems. Starting Create Volatile Files and Directories... [ OK ] Reached target Swap. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Setup Virtual Console. [ OK ] Started Apply Kernel Variables. [ OK ] Started Create Volatile Files and Directories. Starting dracut cmdline hook... Starting Create Static Device Nodes in /dev... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started Journal Service. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 4.894195] device-mapper: uevent: version 1.0.3 [ 4.896327] device-mapper: ioctl: 4.46.0-ioctl (2022-02-22) initialised: dm-devel@redhat.com [ OK ] Started dracut pre-udev hook. Starting udev Kernel Device Manager... [ OK ] Started udev Kernel Device Manager. Starting dracut pre-trigger hook... [ OK ] Started dracut pre-trigger hook. Starting udev Coldplug all Devices... Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. Starting dracut initqueue hook... [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ 5.750642] virtio_net virtio0 ens2: renamed from eth0 [ 5.765501] random: fast init done [ 5.831994] scsi host0: ata_piix [ 5.854750] scsi host1: ata_piix [ 5.856833] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 5.861494] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 10.243650] dracut-initqueue[589]: RTNETLINK answers: File exists [ 10.344162] random: crng init done [ 10.346290] random: 7 urandom warning(s) missed due to ratelimiting Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. Mounting /sysroot... [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. [ 10.901061] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped target Timers. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target System Initialization. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. Stopping udev Kernel Device Manager... [ OK ] Stopped target Swap. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped target Slices. [ OK ] Stopped target Sockets. [ OK ] Stopped target Paths. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Closed udev Control Socket. [ OK ] Closed udev Kernel Socket. Starting Cleanup udevd DB... [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 12.064889] printk: systemd: 26 output lines suppressed due to ratelimiting [ 12.363781] SELinux: Disabled at runtime. [ 12.430623] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 12.441757] systemd[1]: Detected virtualization kvm. [ 12.443969] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 12.974273] systemd[1]: initrd-switch-root.service: Succeeded. [ 12.978091] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 12.984227] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 12.989533] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 12.993343] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 13.000607] systemd[1]: Starting Journal Service... Starting Journal Service... [ 13.011128] systemd[1]: Mounting Kernel Debug File System... Mounting Kernel Debug File System... [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd File Systems. [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Started Dispatch Password Requests to Console Directory Watch. Starting Remount Root and Kernel File Systems... [ OK ] Created slice system-getty.slice. Mounting POSIX Message Queue File System... [ OK ] Created slice User and Session Slice. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Reached target Local Encrypted Volumes. Activating swap /dev/disk/by-label/SWAP... [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Reached target Paths. [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Listening on udev Control Socket. [ OK ] Stopped targ[ 13.147182] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS et Initrd Root File System. [ OK ] Listening on udev Kernel Socket. Starting udev Coldplug all Devices... [ OK ] Reached target Slices. [ OK ] Listening on Process Core Dump Socket. [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Reached target RPC Port Mapper. [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Reached target rpc_pipefs.target. Starting Apply Kernel Variables... Mounting Huge Pages File System... [ OK ] Started Journal Service. [ OK ] Mounted Kernel Debug File System. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Started Apply Kernel Variables. [ OK ] Mounted Huge Pages File System. [ OK ] Reached target Swap. Starting Configure read-only root support... Starting Create Static Device Nodes in /dev... Starting Flush Journal to Persistent Storage... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Reached target Local File Systems (Pre). Mounting /mnt... Mounting /home/green/git/lustre-release... Starting udev Kernel Device Manager... [ OK ] Mounted /mnt. [ OK ] Started udev Coldplug all Devices. [ 13.498245] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 13.803777] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 13.894819] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 13.977785] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 13.990096] EDAC sbridge: Ver: 1.1.2 [ 15.962657] Key type dns_resolver registered [ 16.290587] NFS: Registering the id_resolver key type [ 16.292344] Key type id_resolver registered [ 16.294382] Key type id_legacy registered [ OK ] Started Configure read-only root support. Starting Load/Save Random Seed... [ OK ] Reached target Local File Systems. Starting Mark the need to relabel after reboot... Starting Rebuild Dynamic Linker Cache... Starting Create Volatile Files and Directories... [ OK ] Started Load/Save Random Seed. [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Create Volatile Files and Directories. Starting RPC Bind... Starting Update UTMP about System Boot/Shutdown... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting Restore /run/initramfs on shutdown... [ OK ] Started daily update of the root trust anchor for DNSSEC. Starting Login Service... [ OK ] Started irqbalance daemon. [ OK ] Reached target sshd-keygen.target. [ OK ] Started D-Bus System Message Bus. Starting Network Manager... [ OK ] Started dnf makecache --timer. [ OK ] Reached target Timers. [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Network Manager. [ OK ] Reached target Network. Starting Dynamic System Tuning Daemon... Starting OpenSSH server daemon... Starting GSSAPI Proxy Daemon... Starting Network Manager Wait Online... [ OK ] Started Login Service. Starting Hostname Service... [ OK ] Started OpenSSH server daemon. [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... [ OK ] Started Permit User Sessions. [ OK ] Started Command Scheduler. [ OK ] Started Getty on tty1. [ OK ] Started Serial Getty on ttyS1. [ OK ] Started Serial Getty on ttyS0. [ OK ] Reached target Login Prompts. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting Crash recovery kernel arming... Starting System Logging Service... Starting Notify NFS peers of a restart... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Starting Authorization Manager... [ OK ] Started Authorization Manager. [ OK ] Started Dynamic System Tuning Daemon. [ OK ] Reached target Multi-User System. [ OK ] Reached target Graphical Interface. Starting Update UTMP about System Runlevel Changes... [ OK ] Started Update UTMP about System Runlevel Changes. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg302-server login: [ 35.289455] spl: loading out-of-tree module taints kernel. [ 38.008371] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 42.742297] Key type ._llcrypt registered [ 42.743799] Key type .llcrypt registered [ 42.794372] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing set_hostid [ 54.285302] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing load_modules_local [ 56.752922] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 56.779953] alg: No test for adler32 (adler32-zlib) [ 58.956483] Lustre: Lustre: Build Version: 2.17.56_2_geb69296 [ 61.101330] LNet: Added LNI 192.168.203.102@tcp [8/256/0/180] [ 63.336784] Key type lgssc registered [ 65.424689] Lustre: Echo OBD driver; http://www.lustre.org/ [ 66.877011] hrtimer: interrupt took 1968874 ns [ 80.613991] vdc: vdc1 vdc9 [ 96.057257] vde: vde1 vde9 [ 96.089668] vde: vde1 vde9 [ 111.540641] vdf: vdf1 vdf9 [ 137.418702] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing load_modules_local [ 150.118090] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 151.676262] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 152.150669] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 152.299519] Lustre: lustre-MDT0000: new disk, initializing [ 152.997661] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 153.132851] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 158.143292] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 164.693977] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 174.816765] Lustre: lustre-OST0000: new disk, initializing [ 174.831618] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 174.841340] Lustre: Skipped 1 previous similar message [ 175.056679] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 180.493107] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:0:ost [ 180.504834] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:0:ost] [ 180.856575] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x240000400 [ 186.432656] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 203.928094] Lustre: lustre-OST0001: new disk, initializing [ 203.940759] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 204.134099] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 212.996882] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:1:ost [ 213.049086] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:1:ost] [ 213.393205] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x280000400 [ 215.152403] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 235.562020] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 244.330418] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 253.222345] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing check_logdir /tmp/testlogs/ [ 259.236241] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing yml_node [ 264.037259] Lustre: DEBUG MARKER: Client: 2.17.56.2 [ 266.766110] Lustre: DEBUG MARKER: MDS: 2.17.56.2 [ 269.395315] Lustre: DEBUG MARKER: OSS: 2.17.56.2 [ 271.491087] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity-quota ============----- Thu Jul 30 02:29:55 EDT 2026 [ 293.673965] Lustre: DEBUG MARKER: excepting tests: 2 4a 63 65 [ 295.610306] Lustre: DEBUG MARKER: skipping tests SLOW=no: 61 12a 9 [ 298.917540] Lustre: DEBUG MARKER: === sanity-quota: start setup 02:30:22 (1785393022) === [ 306.876738] Lustre: DEBUG MARKER: oleg302-client.virtnet: executing check_config_client /mnt/lustre [ 330.769106] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 335.972424] Lustre: 11189:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 342.613911] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 348.989831] Lustre: DEBUG MARKER: === sanity-quota: finish setup 02:31:12 (1785393072) === [ 427.112931] Lustre: DEBUG MARKER: == sanity-quota test 0: Test basic quota performance ===== 02:32:31 (1785393151) [ 492.429460] Lustre: DEBUG MARKER: == sanity-quota test 1a: Block hard limit (normal use and out of quota) ========================================================== 02:33:36 (1785393216) [ 511.745570] Lustre: DEBUG MARKER: User quota (block hardlimit:10 MB) [ 520.209421] Lustre: DEBUG MARKER: Write... [ 523.601264] Lustre: DEBUG MARKER: Write out of block quota ... [ 573.953547] Lustre: DEBUG MARKER: -------------------------------------- [ 576.043942] Lustre: DEBUG MARKER: Group quota (block hardlimit:10 MB) [ 583.411830] Lustre: DEBUG MARKER: Write... [ 586.525303] Lustre: DEBUG MARKER: Write out of block quota ... [ 641.829078] Lustre: DEBUG MARKER: -------------------------------------- [ 643.637247] Lustre: DEBUG MARKER: Project quota (block hardlimit:10 mb) [ 647.377277] Lustre: DEBUG MARKER: Write... [ 650.716549] Lustre: DEBUG MARKER: Write out of block quota ... [ 725.733178] Lustre: DEBUG MARKER: == sanity-quota test 1b: Quota pools: Block hard limit (normal use and out of quota) ========================================================== 02:37:29 (1785393449) [ 754.773913] Lustre: DEBUG MARKER: User quota (block hardlimit:20 MB) [ 780.817288] Lustre: DEBUG MARKER: Write... [ 784.278323] Lustre: DEBUG MARKER: Write out of block quota ... [ 834.508724] Lustre: DEBUG MARKER: -------------------------------------- [ 836.469556] Lustre: DEBUG MARKER: Group quota (block hardlimit:20 MB) [ 844.201736] Lustre: DEBUG MARKER: Write... [ 847.940640] Lustre: DEBUG MARKER: Write out of block quota ... [ 905.264491] Lustre: DEBUG MARKER: -------------------------------------- [ 907.809430] Lustre: DEBUG MARKER: Project quota (block hardlimit:20 mb) [ 912.496353] Lustre: DEBUG MARKER: Write... [ 917.171671] Lustre: DEBUG MARKER: Write out of block quota ... [ 1007.417487] Lustre: DEBUG MARKER: == sanity-quota test 1c: Quota pools: check 3 pools with hardlimit only for global ========================================================== 02:42:11 (1785393731) [ 1028.048690] Lustre: DEBUG MARKER: User quota (block hardlimit:20 MB) [ 1058.112399] Lustre: DEBUG MARKER: Write... [ 1061.877909] Lustre: DEBUG MARKER: Write out of block quota ... [ 1179.106745] Lustre: DEBUG MARKER: == sanity-quota test 1d: Quota pools: check block hardlimit on different pools ========================================================== 02:45:02 (1785393902) [ 1202.324325] Lustre: DEBUG MARKER: User quota (block hardlimit:20 MB) [ 1233.629680] Lustre: DEBUG MARKER: Write... [ 1238.238583] Lustre: DEBUG MARKER: Write out of block quota ... [ 1358.186712] Lustre: DEBUG MARKER: == sanity-quota test 1e: Quota pools: global pool high block limit vs quota pool with small ========================================================== 02:48:02 (1785394082) [ 1380.135477] Lustre: DEBUG MARKER: User quota (block hardlimit:53000000 MB) [ 1399.052995] Lustre: DEBUG MARKER: Write... [ 1401.684898] Lustre: DEBUG MARKER: Write out of block quota ... [ 1420.015747] Lustre: DEBUG MARKER: Write... [ 1493.230307] Lustre: DEBUG MARKER: == sanity-quota test 1f: Quota pools: correct qunit after removing/adding OST ========================================================== 02:50:17 (1785394217) [ 1512.824864] Lustre: DEBUG MARKER: User quota (block hardlimit:200 MB) [ 1530.130525] Lustre: DEBUG MARKER: Write... [ 1533.045336] Lustre: DEBUG MARKER: Write out of block quota ... [ 1586.029459] Lustre: DEBUG MARKER: Write... [ 1590.227156] Lustre: DEBUG MARKER: Write out of block quota ... [ 1666.766056] Lustre: DEBUG MARKER: == sanity-quota test 1g: Quota pools: Block hard limit with wide striping ========================================================== 02:53:10 (1785394390) [ 1688.235883] Lustre: DEBUG MARKER: User quota (block hardlimit:40 MB) [ 1703.621324] Lustre: DEBUG MARKER: Write... [ 1723.487046] Lustre: DEBUG MARKER: Write out of block quota ... [ 1847.220644] Lustre: DEBUG MARKER: == sanity-quota test 1h: Block hard limit test using fallocate ========================================================== 02:56:10 (1785394570) [ 1849.271831] Lustre: DEBUG MARKER: SKIP: sanity-quota test_1h need >= 2.13.57 and ldiskfs for fallocate [ 1851.388445] Lustre: DEBUG MARKER: == sanity-quota test 1i: Quota pools: different limit and usage relations ========================================================== 02:56:15 (1785394575) [ 1873.243119] Lustre: DEBUG MARKER: User quota (block hardlimit:200 MB) [ 1887.831992] Lustre: DEBUG MARKER: Write... [ 1891.462244] Lustre: DEBUG MARKER: Write out of block quota ... [ 1934.923038] Lustre: DEBUG MARKER: Write... [ 1939.514689] Lustre: DEBUG MARKER: Write out of block quota ... [ 1953.151177] LustreError: 5770:0:(qmt_entry.c:558:qmt_adjust_edquot()) $$$ set revoke_time explicitly qmt:lustre-QMT0000 pool:dt-qpool1 id:60000 enforced:1 hard:10240 soft:0 granted:15366 time:0 qunit: 1024 edquot:0 may_rel:0 revoke:0 default:no [ 2017.325031] Lustre: DEBUG MARKER: == sanity-quota test 1j: Enable project quota enforcement for root ========================================================== 02:59:01 (1785394741) [ 2045.680798] Lustre: DEBUG MARKER: -------------------------------------- [ 2048.072470] Lustre: DEBUG MARKER: Project quota (hardlimit: 40 mb, 2048 files) [ 2468.189484] Lustre: DEBUG MARKER: == sanity-quota test 1k: LQA: Block hard limit (normal use and out of quota) ========================================================== 03:06:32 (1785395192) [ 2496.099085] Lustre: DEBUG MARKER: Write... [ 2499.808515] Lustre: DEBUG MARKER: Write out of block quota ... [ 2544.880759] Lustre: DEBUG MARKER: Write... [ 2550.745282] Lustre: DEBUG MARKER: Write out of block quota ... [ 2595.134932] Lustre: DEBUG MARKER: Write... [ 2600.213445] Lustre: DEBUG MARKER: Write out of block quota ... [ 2656.727169] Lustre: DEBUG MARKER: == sanity-quota test 1l: Async writes should not be rejected by quota with root_prj_enable ========================================================== 03:09:40 (1785395380) [ 2732.342138] Lustre: DEBUG MARKER: SKIP: sanity-quota test_2 skipping excluded test 2 [ 2734.575859] Lustre: DEBUG MARKER: == sanity-quota test 3a: Block soft limit (start timer, timer goes off, stop timer) ========================================================== 03:10:58 (1785395458) [ 2832.282256] Lustre: DEBUG MARKER: Write after timer goes off [ 2834.818790] Lustre: DEBUG MARKER: Write after cancel lru locks [ 2898.917029] LustreError: 3285:0:(qsd_reint.c:633:qqi_reint_delayed()) lustre-OST0001: Delaying reintegration for qtype:0 until pending updates are flushed. [ 2993.213321] Lustre: DEBUG MARKER: Write after timer goes off [ 2995.274897] Lustre: DEBUG MARKER: Write after cancel lru locks [ 3141.497623] Lustre: DEBUG MARKER: Write after timer goes off [ 3143.823673] Lustre: DEBUG MARKER: Write after cancel lru locks [ 3264.333708] Lustre: DEBUG MARKER: == sanity-quota test 3b: Quota pools: Block soft limit (start timer, expires, stop timer) ========================================================== 03:19:48 (1785395988) [ 3373.836329] Lustre: DEBUG MARKER: Write after timer goes off [ 3376.384481] Lustre: DEBUG MARKER: Write after cancel lru locks [ 3529.065971] Lustre: DEBUG MARKER: Write after timer goes off [ 3532.231838] Lustre: DEBUG MARKER: Write after cancel lru locks [ 3689.016609] Lustre: DEBUG MARKER: Write after timer goes off [ 3691.338590] Lustre: DEBUG MARKER: Write after cancel lru locks [ 3835.103544] Lustre: DEBUG MARKER: == sanity-quota test 3c: Quota pools: check block soft limit on different pools ========================================================== 03:29:19 (1785396559) [ 3948.791808] Lustre: DEBUG MARKER: Write after timer goes off [ 3952.006825] Lustre: DEBUG MARKER: Write after cancel lru locks [ 4071.329399] Lustre: DEBUG MARKER: SKIP: sanity-quota test_4a skipping excluded test 4a [ 4073.856965] Lustre: DEBUG MARKER: == sanity-quota test 4b: Grace time strings handling ===== 03:33:17 (1785396797) [ 4095.799749] Lustre: DEBUG MARKER: == sanity-quota test 5: Chown [ 4256.958155] Lustre: DEBUG MARKER: == sanity-quota test 6: Test dropping acquire request on master ========================================================== 03:36:20 (1785396980) [ 4320.229068] Lustre: *** cfs_fail_loc=513, val=601*** [ 4321.428516] Lustre: *** cfs_fail_loc=513, val=601*** [ 4321.430676] Lustre: Skipped 5 previous similar messages [ 4322.456812] Lustre: *** cfs_fail_loc=513, val=601*** [ 4322.462103] Lustre: Skipped 9 previous similar messages [ 4322.560713] LustreError: 14206:0:(service.c:2341:ptlrpc_server_handle_req_in()) drop incoming rpc opc 601, x1872120028886528 [ 4325.344769] Lustre: *** cfs_fail_loc=513, val=601*** [ 4325.348366] Lustre: Skipped 6 previous similar messages [ 4329.440736] Lustre: *** cfs_fail_loc=513, val=601*** [ 4329.447794] Lustre: Skipped 4 previous similar messages [ 4338.144358] Lustre: 38560:0:(service.c:1612:ptlrpc_at_send_early_reply()) @@@ Could not add any time (5/5), not sending early reply req@ffff9d41fd3e6a00 x1872120016762112/t0(0) o4->a014fdf7-784a-44ee-95fc-8e4596396f54@192.168.203.2@tcp:249/0 lens 488/448 e 1 to 0 dl 1785397069 ref 2 fl Interpret:/600/0 rc 0/0 job:'dd.60000' uid:60000 gid:60000 projid:0 [ 4338.145298] Lustre: *** cfs_fail_loc=513, val=601*** [ 4338.184989] Lustre: Skipped 20 previous similar messages [ 4339.168281] Lustre: 38717:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1785397049/real 1785397049] req@ffff9d41fd3bd880 x1872120028886528/t0(0) o601->lustre-MDT0000-lwp-OST0000@0@lo:23/10 lens 336/336 e 0 to 1 dl 1785397065 ref 2 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'ll_ost_io00_009.0' uid:0 gid:0 projid:4294967295 [ 4339.205310] Lustre: lustre-MDT0000-lwp-OST0000: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 4339.234364] Lustre: lustre-MDT0000: Client lustre-MDT0000-lwp-OST0000_UUID (at 0@lo) reconnecting [ 4339.240945] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 4340.339804] LustreError: 14208:0:(service.c:2341:ptlrpc_server_handle_req_in()) drop incoming rpc opc 601, x1872120028890752 [ 4346.848836] LustreError: 14209:0:(service.c:2341:ptlrpc_server_handle_req_in()) drop incoming rpc opc 601, x1872120028892160 [ 4346.860261] LustreError: 14209:0:(service.c:2341:ptlrpc_server_handle_req_in()) Skipped 2 previous similar messages [ 4354.528735] Lustre: *** cfs_fail_loc=513, val=601*** [ 4354.535270] Lustre: Skipped 43 previous similar messages [ 4355.552145] Lustre: 6569:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1785397066/real 1785397066] req@ffff9d40cf1c8700 x1872120028890752/t0(0) o601->lustre-MDT0000-lwp-OST0000@0@lo:23/10 lens 336/336 e 0 to 1 dl 1785397082 ref 2 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'ll_ost_io00_001.0' uid:0 gid:0 projid:4294967295 [ 4355.588762] Lustre: lustre-MDT0000-lwp-OST0000: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 4355.625622] Lustre: lustre-MDT0000: Client lustre-MDT0000-lwp-OST0000_UUID (at 0@lo) reconnecting [ 4355.640997] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 4357.311565] LustreError: 14206:0:(service.c:2341:ptlrpc_server_handle_req_in()) drop incoming rpc opc 601, x1872120028894976 [ 4362.720159] Lustre: 3284:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1785397073/real 1785397073] req@ffff9d40c6f19f80 x1872120028892032/t0(0) o601->lustre-MDT0000-lwp-OST0001@0@lo:23/10 lens 336/336 e 0 to 1 dl 1785397089 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'lquota_wb_lustr.0' uid:0 gid:0 projid:4294967295 [ 4362.722174] Lustre: lustre-MDT0000-lwp-OST0001: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 4362.759362] Lustre: 3284:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 4362.818684] Lustre: lustre-MDT0000: Client lustre-MDT0000-lwp-OST0001_UUID (at 0@lo) reconnecting [ 4362.830458] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 4372.448131] Lustre: 38559:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1785397083/real 1785397083] req@ffff9d40c7771880 x1872120028894976/t0(0) o601->lustre-MDT0000-lwp-OST0000@0@lo:23/10 lens 336/336 e 0 to 1 dl 1785397099 ref 2 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'ll_ost_io00_006.0' uid:0 gid:0 projid:4294967295 [ 4372.485153] Lustre: 38559:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 4372.502961] Lustre: lustre-MDT0000-lwp-OST0000: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 4372.523215] Lustre: lustre-MDT0000: Client lustre-MDT0000-lwp-OST0000_UUID (at 0@lo) reconnecting [ 4372.531660] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 4415.513824] Lustre: DEBUG MARKER: == sanity-quota test 7a: Quota reintegration (global index) ========================================================== 03:38:59 (1785397139) [ 4463.984241] Lustre: Failing over lustre-OST0000 [ 4464.239715] Lustre: server umount lustre-OST0000 complete [ 4464.616297] Lustre: lustre-OST0000-osc-MDT0000: Connection to lustre-OST0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 4469.737868] LustreError: 38810:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4469.771252] LustreError: 38810:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 3 previous similar messages [ 4474.854735] LustreError: 6565:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4474.910828] LustreError: 6565:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 1 previous similar message [ 4479.979805] LustreError: 38816:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4480.012247] LustreError: 38816:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 1 previous similar message [ 4484.240859] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [ 4484.297408] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 4485.281828] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4485.946686] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 4485.950143] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 4497.029281] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4511.465912] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 4523.701549] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 4531.901560] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 4540.292685] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 4549.203793] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 4557.028712] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 4593.788798] Lustre: Failing over lustre-OST0000 [ 4593.904034] Lustre: server umount lustre-OST0000 complete [ 4596.706088] Lustre: lustre-OST0000-osc-MDT0000: Connection to lustre-OST0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 4596.737043] LustreError: 38480:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4596.759770] LustreError: 38480:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 1 previous similar message [ 4601.831607] LustreError: 38430:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4605.394359] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [ 4605.407884] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 4606.882642] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4607.006632] Lustre: lustre-OST0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4607.006970] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 4612.885280] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4624.922779] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 4631.676177] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 4640.158903] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 4648.191768] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 4656.582196] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 4663.854720] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 4707.672463] Lustre: DEBUG MARKER: == sanity-quota test 7b: Quota reintegration (slave index) ========================================================== 03:43:52 (1785397432) [ 4757.008898] Lustre: *** cfs_fail_loc=a02, val=0*** [ 4766.418836] LustreError: 3285:0:(qsd_handler.c:298:qsd_req_completion()) $$$ DQACQ failed with -5, flags:0x8 qsd:lustre-OST0000 qtype:usr lqe: ffff9d41ff6d2d80 id:60000 enforced:1 granted: 1026 pending:0 waiting:0 req:1 usage: 2052 qunit:0 qtune:0 edquot:0 default:no revoke:0 [ 4766.442561] Lustre: Failing over lustre-OST0000 [ 4766.671045] Lustre: server umount lustre-OST0000 complete [ 4766.901077] LustreError: 38809:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.203.2@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4769.250799] Lustre: lustre-OST0000-osc-MDT0000: Connection to lustre-OST0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 4775.370987] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [ 4775.407818] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 4777.029908] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4777.391356] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 4777.391541] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 4783.203769] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4794.726559] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 4802.535333] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 4813.420305] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 4824.532632] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 4832.752595] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 4839.809874] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 4902.023447] Lustre: DEBUG MARKER: == sanity-quota test 7c: Quota reintegration (restart mds during reintegration) ========================================================== 03:47:05 (1785397625) [ 4941.698773] LustreError: 89483:0:(qsd_reint.c:488:qsd_reint_main()) cfs_fail_timeout id a03 sleeping for 10000ms [ 4941.713820] LustreError: 89483:0:(qsd_reint.c:488:qsd_reint_main()) Skipped 5 previous similar messages [ 4944.602519] Lustre: Failing over lustre-MDT0000 [ 4945.489245] Lustre: server umount lustre-MDT0000 complete [ 4950.474283] LustreError: 89486:0:(qsd_reint.c:488:qsd_reint_main()) cfs_fail_timeout interrupted [ 4958.853409] LustreError: MGC192.168.203.102@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4959.509816] Lustre: lustre-MDT0000-lwp-OST0001: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 4959.870524] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4960.097599] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4961.504579] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4961.849186] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4961.969563] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:145 to 0x240000400:161) [ 4961.978307] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:116 to 0x280000400:161) [ 4964.000992] Lustre: 3286:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1785397674/real 1785397674] req@ffff9d41fc725500 x1872120029290112/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1785397690 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4964.843648] LustreError: 3283:0:(ldlm_resource.c:1207:ldlm_resource_complain()) lustre-MDT0000-lwp-OST0001: namespace resource [0x200000006:0x2020000:0x0].0x0 (ffff9d41e02e7600) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 4964.879238] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 4967.903125] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4974.050570] Lustre: 3285:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1785397684/real 1785397684] req@ffff9d41c5dd9500 x1872120029291520/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1785397700 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4974.086545] Lustre: 3285:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 4978.597902] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 5057.523582] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 5065.720876] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 5073.574243] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 5082.076917] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 5093.264156] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 5143.361091] Lustre: DEBUG MARKER: == sanity-quota test 7d: Quota reintegration (Transfer index in multiple bulks) ========================================================== 03:51:07 (1785397867) [ 5177.697622] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 5186.609063] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 5252.884036] Lustre: DEBUG MARKER: == sanity-quota test 7e: Quota reintegration (inode limits) ========================================================== 03:52:56 (1785397976) [ 5254.890609] Lustre: DEBUG MARKER: SKIP: sanity-quota test_7e needs >= 2 MDTs [ 5257.285588] Lustre: DEBUG MARKER: == sanity-quota test 7f: Quota reintegration automatically ========================================================== 03:53:01 (1785397981) [ 5277.525258] Lustre: *** cfs_fail_loc=a11, val=0*** [ 5284.184440] Lustre: *** cfs_fail_loc=a11, val=0*** [ 5338.100403] Lustre: *** cfs_fail_loc=a11, val=0*** [ 5562.312181] Lustre: DEBUG MARKER: == sanity-quota test 8: Run dbench with quota enabled ==== 03:58:06 (1785398286) [ 5771.222736] Lustre: DEBUG MARKER: SKIP: sanity-quota test_9 skipping SLOW test 9 [ 5773.889568] Lustre: DEBUG MARKER: == sanity-quota test 10: Test quota for root user ======== 04:01:37 (1785398497) [ 5844.300351] Lustre: DEBUG MARKER: == sanity-quota test 11: Chown/chgrp ignores quota ======= 04:02:46 (1785398566) [ 5904.952289] Lustre: DEBUG MARKER: SKIP: sanity-quota test_12a skipping SLOW test 12a [ 5907.102991] Lustre: DEBUG MARKER: == sanity-quota test 12b: Inode quota rebalancing ======== 04:03:51 (1785398631) [ 5909.417401] Lustre: DEBUG MARKER: SKIP: sanity-quota test_12b needs >= 2 MDTs [ 5911.881881] Lustre: DEBUG MARKER: == sanity-quota test 13: Cancel per-ID lock in the LRU list ========================================================== 04:03:55 (1785398635) [ 5994.290706] Lustre: DEBUG MARKER: == sanity-quota test 14: check panic in qmt_site_recalc_cb ========================================================== 04:05:18 (1785398718) [ 6035.605217] Lustre: Failing over lustre-OST0000 [ 6035.786160] Lustre: server umount lustre-OST0000 complete [ 6036.674039] LustreError: 38480:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.203.2@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 6036.709515] LustreError: 38480:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 3 previous similar messages [ 6038.508538] Lustre: lustre-OST0000-osc-MDT0000: Connection to lustre-OST0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 6038.527086] Lustre: Skipped 1 previous similar message [ 6041.751184] LustreError: 38812:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.203.2@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 6041.775352] LustreError: 38812:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 1 previous similar message [ 6046.869843] LustreError: 8456:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.203.2@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 6046.906847] LustreError: 8456:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 1 previous similar message [ 6051.775574] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [ 6051.837392] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 6052.002942] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 6052.933957] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 6052.936482] Lustre: Skipped 1 previous similar message [ 6052.938148] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 6060.762331] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6113.096351] Lustre: DEBUG MARKER: == sanity-quota test 15: Set over 4T block quota ========= 04:07:16 (1785398836) [ 6155.685879] Lustre: DEBUG MARKER: == sanity-quota test 16a: lfs quota should skip the inactive MDT/OST ========================================================== 04:07:58 (1785398878) [ 6188.005356] Lustre: lustre-OST0000: Client a014fdf7-784a-44ee-95fc-8e4596396f54 (at 192.168.203.2@tcp) reconnecting [ 6223.661701] Lustre: DEBUG MARKER: == sanity-quota test 16b: lfs quota should skip the nonexistent MDT/OST ========================================================== 04:09:07 (1785398947) [ 6226.088055] Lustre: DEBUG MARKER: SKIP: sanity-quota test_16b needs >= 3 MDTs [ 6228.187284] Lustre: DEBUG MARKER: == sanity-quota test 17: DQACQ return recoverable error == 04:09:12 (1785398952) [ 6264.679595] Lustre: *** cfs_fail_loc=a04, val=37*** [ 6264.691068] LustreError: 6570:0:(qsd_handler.c:298:qsd_req_completion()) $$$ DQACQ failed with -37, flags:0x1 qsd:lustre-OST0000 qtype:usr lqe: ffff9d41ff6b9380 id:60000 enforced:1 granted: 0 pending:0 waiting:1 req:1 usage: 0 qunit:0 qtune:0 edquot:0 default:no revoke:0 [ 6265.866189] Lustre: *** cfs_fail_loc=a04, val=37*** [ 6265.872271] LustreError: 6569:0:(qsd_handler.c:298:qsd_req_completion()) $$$ DQACQ failed with -37, flags:0x1 qsd:lustre-OST0000 qtype:usr lqe: ffff9d41ff6b9380 id:60000 enforced:1 granted: 0 pending:0 waiting:1024 req:1 usage: 0 qunit:0 qtune:0 edquot:0 default:no revoke:0 [ 6266.979847] Lustre: *** cfs_fail_loc=a04, val=37*** [ 6267.006161] LustreError: 3285:0:(qsd_handler.c:298:qsd_req_completion()) $$$ DQACQ failed with -37, flags:0x8 qsd:lustre-OST0000 qtype:usr lqe: ffff9d41ff6b9380 id:60000 enforced:1 granted: 0 pending:0 waiting:0 req:1 usage: 1 qunit:0 qtune:0 edquot:0 default:no revoke:0 [ 6346.821934] Lustre: *** cfs_fail_loc=a04, val=11*** [ 6346.828920] Lustre: Skipped 2 previous similar messages [ 6433.267324] Lustre: *** cfs_fail_loc=a04, val=110*** [ 6433.281141] Lustre: Skipped 2 previous similar messages [ 6512.543941] Lustre: *** cfs_fail_loc=a04, val=107*** [ 6512.545607] Lustre: Skipped 4 previous similar messages [ 6642.334389] Lustre: DEBUG MARKER: == sanity-quota test 18: MDS failover while writing, no watchdog triggered (b14840) ========================================================== 04:16:06 (1785399366) [ 6662.266302] Lustre: DEBUG MARKER: User quota (limit: 200) [ 6669.460206] Lustre: DEBUG MARKER: Write 100M (buffered) ... [ 6673.100308] LustreError: 118516:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 6674.256147] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 6676.135910] Lustre: DEBUG MARKER: Fail mds for 40 seconds [ 6678.314950] Lustre: Failing over lustre-MDT0000 [ 6678.869054] Lustre: server umount lustre-MDT0000 complete [ 6694.752785] Lustre: 3286:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1785399405/real 1785399405] req@ffff9d410cc96a00 x1872120030359552/t0(0) o601->lustre-MDT0000-lwp-OST0000@0@lo:23/10 lens 336/336 e 0 to 1 dl 1785399421 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'lquota_wb_lustr.0' uid:0 gid:0 projid:4294967295 [ 6694.794429] Lustre: 3286:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 6694.797501] Lustre: lustre-MDT0000-lwp-OST0000: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 6697.888315] Lustre: 3286:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1785399408/real 1785399408] req@ffff9d410cc97800 x1872120030359680/t0(0) o400->MGC192.168.203.102@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1785399424 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6697.888496] Lustre: lustre-MDT0000-lwp-OST0001: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 6697.916918] Lustre: 3286:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 6697.916981] LustreError: MGC192.168.203.102@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 6703.008142] Lustre: 3287:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1785399413/real 1785399413] req@ffff9d40d8868380 x1872120030360192/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1785399429 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6709.217667] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 6709.426267] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 6711.138205] Lustre: 3284:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1785399421/real 1785399421] req@ffff9d40d886ad80 x1872120030360960/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1785399437 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6711.176319] Lustre: 3284:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 6715.438943] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6720.370301] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 6722.476061] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 6722.713957] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 6722.916806] LustreError: 119134:0:(tgt_handler.c:534:tgt_filter_recovery_request()) @@@ not permitted during recovery req@ffff9d40c7325f80 x1872120030376320/t0(0) o601->lustre-MDT0000-lwp-OST0000_UUID@0@lo:375/0 lens 336/0 e 0 to 0 dl 1785399460 ref 1 fl Interpret:/200/ffffffff rc 0/-1 job:'qsd_reint_0.lus.0' uid:0 gid:0 projid:4294967295 [ 6722.942635] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 6722.994471] LustreError: lustre-MDT0000-lwp-OST0000: operation quota_acquire to node 0@lo failed: rc = -11 [ 6723.086805] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:496 to 0x240000400:513) [ 6723.092816] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:492 to 0x280000400:513) [ 6733.466077] Lustre: DEBUG MARKER: oleg302-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6735.975533] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6747.425629] Lustre: DEBUG MARKER: (dd_pid=113265, time=0, timeout=600) [ 6811.219419] Lustre: DEBUG MARKER: User quota (limit: 200) [ 6819.278278] Lustre: DEBUG MARKER: Write 100M (directio) ... [ 6824.087634] LustreError: 121354:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 6825.278615] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 6827.601348] Lustre: DEBUG MARKER: Fail mds for 40 seconds [ 6830.209083] Lustre: Failing over lustre-MDT0000 [ 6830.258958] Lustre: lustre-MDT0000: Not available for connect from 192.168.203.2@tcp (stopping) [ 6830.902527] Lustre: server umount lustre-MDT0000 complete [ 6848.480326] Lustre: 3285:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1785399559/real 1785399559] req@ffff9d4110296a00 x1872120030408576/t0(0) o601->lustre-MDT0000-lwp-OST0000@0@lo:23/10 lens 336/336 e 0 to 1 dl 1785399575 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'lquota_wb_lustr.0' uid:0 gid:0 projid:4294967295 [ 6848.545297] Lustre: lustre-MDT0000-lwp-OST0000: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 6850.640103] LustreError: MGC192.168.203.102@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 6860.896498] LustreError: 3283:0:(client.c:1391:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9d41ff6e8700 x1872120030411776/t0(0) o250->MGC192.168.203.102@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 0 ref 1 fl Rpc:NQU/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6862.071445] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 6862.249012] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 6869.254983] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6870.230830] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 6870.527677] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 6870.705378] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:515 to 0x240000400:545) [ 6870.719764] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:492 to 0x280000400:545) [ 6874.153725] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 6882.907158] Lustre: DEBUG MARKER: oleg302-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6884.689458] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6893.536097] Lustre: DEBUG MARKER: (dd_pid=115657, time=2, timeout=600) [ 6974.708540] Lustre: DEBUG MARKER: == sanity-quota test 19: Updating admin limits doesn't zero operational limits(b14790) ========================================================== 04:21:38 (1785399698) [ 7005.781293] Lustre: DEBUG MARKER: Files for user (quota_usr), count=1: [ 7007.817271] Lustre: DEBUG MARKER: Block quota isn't 0 (u:quota_usr:2). [ 7016.113882] Lustre: DEBUG MARKER: Files for user (quota_usr), count=1: [ 7018.479236] Lustre: DEBUG MARKER: Block quota isn't 0 (u:quota_usr:2). [ 7065.425873] Lustre: DEBUG MARKER: == sanity-quota test 20: Test if setquota specifiers work properly (b15754) ========================================================== 04:23:09 (1785399789) [ 7095.875681] Lustre: DEBUG MARKER: == sanity-quota test 21: Setquota while writing [ 7114.373687] Lustre: DEBUG MARKER: Set limit(block:10G; file:1000000) for user: quota_usr [ 7117.257956] Lustre: DEBUG MARKER: Set limit(block:10G; file:1000000) for group: quota_usr [ 7119.409788] Lustre: DEBUG MARKER: Set limit(block:10G; file:) for project: 1000 [ 7122.326080] Lustre: DEBUG MARKER: Set quota for 1 times [ 7126.925294] Lustre: DEBUG MARKER: Set quota for 2 times [ 7130.883638] Lustre: DEBUG MARKER: Set quota for 3 times [ 7135.030667] Lustre: DEBUG MARKER: Set quota for 4 times [ 7139.884976] Lustre: DEBUG MARKER: Set quota for 5 times [ 7145.425252] Lustre: DEBUG MARKER: Set quota for 6 times [ 7150.864457] Lustre: DEBUG MARKER: Set quota for 7 times [ 7207.507073] Lustre: DEBUG MARKER: == sanity-quota test 22: enable/disable quota by 'lctl conf_param/set_param -P' ========================================================== 04:25:31 (1785399931) [ 7223.680150] Lustre: server umount lustre-MDT0000 complete [ 7230.086478] LustreError: 5755:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1785399956 with bad export cookie 12267358205363920501 [ 7230.097051] LustreError: MGC192.168.203.102@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 7239.773460] Lustre: server umount lustre-OST0000 complete [ 7240.674116] Lustre: 3284:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1785399951/real 1785399951] req@ffff9d40c522aa00 x1872120030535680/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1785399967 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 7240.709141] Lustre: 3284:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 8 previous similar messages [ 7240.734984] Lustre: lustre-MDT0000-lwp-OST0001: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 7240.757199] Lustre: Skipped 1 previous similar message [ 7246.496564] Lustre: server umount lustre-OST0001 complete [ 7267.589423] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing load_modules_local [ 7280.965927] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 7288.893325] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7293.287869] Lustre: 131046:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 7301.362860] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 7306.417286] LustreError: 131359:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 7306.451354] LustreError: 131359:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 1 previous similar message [ 7306.479410] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:548 to 0x240000400:577) [ 7310.968345] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7311.853663] LustreError: 131359:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 7316.974127] LustreError: 131556:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 7322.274211] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 7327.228066] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:547 to 0x280000400:577) [ 7331.713446] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7340.465283] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 7345.290623] Lustre: 132867:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 7368.165234] Lustre: lustre-MDT0000-lwp-OST0001: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 7368.185901] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 7368.191202] Lustre: Skipped 1 previous similar message [ 7368.212083] Lustre: Skipped 1 previous similar message [ 7368.484525] Lustre: server umount lustre-MDT0000 complete [ 7373.649837] LustreError: 130593:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1785400100 with bad export cookie 12267358205363926591 [ 7373.669173] LustreError: MGC192.168.203.102@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 7373.673481] LustreError: 130593:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 7373.834612] Lustre: server umount lustre-OST0000 complete [ 7379.468455] Lustre: server umount lustre-OST0001 complete [ 7403.539883] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing load_modules_local [ 7418.871223] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 7426.398490] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7430.823294] Lustre: 135473:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 7437.519344] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 7443.628846] LustreError: 135799:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 7443.676809] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:548 to 0x240000400:609) [ 7445.422875] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7454.185000] LustreError: 136083:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 7454.224969] LustreError: 136083:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 1 previous similar message [ 7460.874150] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:547 to 0x280000400:609) [ 7463.368470] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7472.985890] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 7478.103963] Lustre: 137294:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 7492.312849] Lustre: DEBUG MARKER: == sanity-quota test 23: Quota should be honored with directIO (b16125) ========================================================== 04:30:16 (1785400216) [ 7494.349174] Lustre: DEBUG MARKER: SKIP: sanity-quota test_23 Overwrite in place is not guaranteed to be space neutral on ZFS [ 7496.601765] Lustre: DEBUG MARKER: == sanity-quota test 24: lfs draws an asterix when limit is reached (b16646) ========================================================== 04:30:20 (1785400220) [ 7573.384606] Lustre: DEBUG MARKER: == sanity-quota test 25: check indexes versions ========== 04:31:36 (1785400296) [ 7643.457858] Lustre: DEBUG MARKER: Write... [ 7646.808543] Lustre: DEBUG MARKER: Write out of block quota ... [ 7719.830642] Lustre: DEBUG MARKER: == sanity-quota test 27a: lfs quota/setquota should handle wrong arguments (b19612) ========================================================== 04:34:03 (1785400443) [ 7731.450299] Lustre: DEBUG MARKER: == sanity-quota test 27b: lfs quota/setquota should handle user/group/project ID (b20200) ========================================================== 04:34:15 (1785400455) [ 7744.646553] Lustre: DEBUG MARKER: == sanity-quota test 27c: lfs quota should support human-readable output ========================================================== 04:34:28 (1785400468) [ 7756.759549] Lustre: DEBUG MARKER: == sanity-quota test 27d: lfs setquota should support fraction block limit ========================================================== 04:34:40 (1785400480) [ 7766.302350] Lustre: DEBUG MARKER: == sanity-quota test 30: Hard limit updates should not reset grace times ========================================================== 04:34:50 (1785400490) [ 7841.811201] Lustre: DEBUG MARKER: == sanity-quota test 33: Basic usage tracking for user [ 8029.362023] Lustre: DEBUG MARKER: == sanity-quota test 34: Usage transfer for user [ 8250.089944] Lustre: DEBUG MARKER: == sanity-quota test 35: Usage is still accessible across reboot ========================================================== 04:42:52 (1785400972) [ 8335.156795] Lustre: DEBUG MARKER: Restart... [ 8341.478442] Lustre: lustre-MDT0000-lwp-OST0001: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 8341.482502] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 8341.504626] Lustre: Skipped 1 previous similar message [ 8341.529807] Lustre: Skipped 1 previous similar message [ 8342.770129] Lustre: server umount lustre-MDT0000 complete [ 8348.565209] LustreError: 135025:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1785401075 with bad export cookie 12267358205363928124 [ 8348.572845] LustreError: MGC192.168.203.102@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 8348.591677] LustreError: 135025:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 8348.804368] Lustre: server umount lustre-OST0000 complete [ 8355.764435] Lustre: server umount lustre-OST0001 complete [ 8379.902750] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing load_modules_local [ 8393.261391] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 8393.268695] Lustre: Skipped 1 previous similar message [ 8399.724856] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 8403.591324] Lustre: 155680:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 8411.461644] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 8417.443023] LustreError: 155998:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 8417.463912] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:618 to 0x240000400:641) [ 8419.288613] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 8422.882404] LustreError: 156277:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 8428.001067] LustreError: 155998:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 8430.102665] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 8433.103411] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:618 to 0x280000400:641) [ 8438.668294] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 8448.600882] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 8454.852942] Lustre: 157496:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 8552.118722] Lustre: DEBUG MARKER: == sanity-quota test 37: Quota accounted properly for file created by 'lfs setstripe' ========================================================== 04:47:56 (1785401276) [ 8647.919942] Lustre: DEBUG MARKER: == sanity-quota test 38: Quota accounting iterator doesn't skip id entries ========================================================== 04:49:31 (1785401371) [11017.351188] Lustre: DEBUG MARKER: == sanity-quota test 39: Project ID interface works correctly ========================================================== 05:29:01 (1785403741) [11037.677352] Lustre: server umount lustre-MDT0000 complete [11043.453899] LustreError: 155231:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1785403770 with bad export cookie 12267358205363934620 [11043.473463] LustreError: MGC192.168.203.102@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [11053.664145] Lustre: 3286:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1785403764/real 1785403764] req@ffff9d410f6bca80 x1872120033998592/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1785403780 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [11053.690293] Lustre: 3286:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 1 previous similar message [11053.702846] Lustre: lustre-MDT0000-lwp-OST0001: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [11054.924533] Lustre: server umount lustre-OST0000 complete [11060.630176] Lustre: server umount lustre-OST0001 complete [11083.275445] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing load_modules_local [11096.663891] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [11103.786452] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [11108.221461] Lustre: 165693:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [11116.587178] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [11120.571554] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5644 to 0x240000400:5665) [11121.588416] LustreError: 166014:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [11125.011919] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [11126.758612] LustreError: 166014:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [11131.884865] LustreError: 166014:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [11134.356936] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [11139.629591] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5642 to 0x280000400:5665) [11146.442820] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [11157.763672] Lustre: DEBUG MARKER: Using TIMEOUT=20 [11163.429836] Lustre: 167515:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [11205.755778] Lustre: DEBUG MARKER: == sanity-quota test 40a: Hard link across different project ID ========================================================== 05:32:09 (1785403929) [11261.598281] Lustre: DEBUG MARKER: == sanity-quota test 40b: Mv across different project ID ========================================================== 05:33:05 (1785403985) [11325.085655] Lustre: DEBUG MARKER: == sanity-quota test 40c: Remote child Dir inherit project quota properly ========================================================== 05:34:08 (1785404048) [11328.564133] Lustre: DEBUG MARKER: SKIP: sanity-quota test_40c needs >= 2 MDTs [11332.287689] Lustre: DEBUG MARKER: == sanity-quota test 40d: Stripe Directory inherit project quota properly ========================================================== 05:34:15 (1785404055) [11335.547124] Lustre: DEBUG MARKER: SKIP: sanity-quota test_40d needs >= 2 MDTs [11338.285983] Lustre: DEBUG MARKER: == sanity-quota test 41: df should return projid-specific values ========================================================== 05:34:22 (1785404062) [11448.595934] Lustre: DEBUG MARKER: == sanity-quota test 42: lfs quota should include default quota info ========================================================== 05:36:11 (1785404171) [11511.359590] Lustre: DEBUG MARKER: == sanity-quota test 48: lfs quota --delete should delete quota project ID ========================================================== 05:37:15 (1785404235) [11621.425422] Lustre: DEBUG MARKER: == sanity-quota test 49a: lfs quota -a prints the quota usage for all quota IDs ========================================================== 05:39:05 (1785404345) [11635.478806] Lustre: *** cfs_fail_loc=a09, val=0*** [11635.488987] Lustre: Skipped 2 previous similar messages [11637.518924] Lustre: *** cfs_fail_loc=a09, val=0*** [11637.525251] Lustre: Skipped 63 previous similar messages [11641.567911] Lustre: *** cfs_fail_loc=a09, val=0*** [11641.569426] Lustre: Skipped 119 previous similar messages [11649.576059] Lustre: *** cfs_fail_loc=a09, val=0*** [11649.577824] Lustre: Skipped 267 previous similar messages [11665.656200] Lustre: *** cfs_fail_loc=a09, val=0*** [11665.659296] Lustre: Skipped 615 previous similar messages [11698.435261] Lustre: *** cfs_fail_loc=a09, val=0*** [11698.438051] Lustre: Skipped 1099 previous similar messages [11762.488199] Lustre: *** cfs_fail_loc=a09, val=0*** [11762.493510] Lustre: Skipped 2051 previous similar messages [12516.012355] Lustre: *** cfs_fail_loc=a08, val=0*** [12516.024549] Lustre: Skipped 3783 previous similar messages [12516.026695] Lustre: *** cfs_fail_loc=a08, val=0*** [12516.047912] Lustre: Skipped 1 previous similar message [12516.546031] Lustre: *** cfs_fail_loc=a08, val=0*** [12516.549859] Lustre: Skipped 67 previous similar messages [12525.361683] Lustre: *** cfs_fail_loc=a08, val=0*** [12525.363326] Lustre: Skipped 158 previous similar messages [12535.501613] Lustre: *** cfs_fail_loc=a08, val=0*** [12535.517348] Lustre: Skipped 841 previous similar messages [12535.766861] Lustre: *** cfs_fail_loc=a08, val=0*** [12535.772696] Lustre: Skipped 617 previous similar messages [12545.730215] Lustre: *** cfs_fail_loc=a08, val=0*** [12545.736172] Lustre: Skipped 361 previous similar messages [12555.984973] Lustre: *** cfs_fail_loc=a08, val=0*** [12555.998012] Lustre: Skipped 503 previous similar messages [12575.476210] Lustre: *** cfs_fail_loc=a08, val=0*** [12575.483989] Lustre: Skipped 1929 previous similar messages [12575.505556] Lustre: *** cfs_fail_loc=a08, val=0*** [12575.513065] Lustre: Skipped 1059 previous similar messages [12666.731389] Lustre: *** cfs_fail_loc=a08, val=0*** [12666.741118] Lustre: Skipped 1167 previous similar messages [12666.845770] Lustre: *** cfs_fail_loc=a08, val=0*** [12666.863671] Lustre: Skipped 1168 previous similar messages [12736.621215] Lustre: *** cfs_fail_loc=a08, val=0*** [12736.631427] Lustre: Skipped 1401 previous similar messages [12768.741814] Lustre: lustre-MDT0000-lwp-OST0000: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [12768.759415] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [12768.760012] Lustre: Skipped 1 previous similar message [12773.860256] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [12773.862996] Lustre: Skipped 1 previous similar message [12775.481633] Lustre: server umount lustre-MDT0000 complete [12786.147463] LustreError: 178633:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1785405512 with bad export cookie 12267358205365718745 [12786.156282] LustreError: MGC192.168.203.102@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [12786.176926] LustreError: 178633:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [12786.485940] Lustre: server umount lustre-OST0000 complete [12793.034554] Lustre: server umount lustre-OST0001 complete [12806.210994] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing set_hostid [12817.016776] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing load_modules_local [12839.587603] vdc: vdc1 vdc9 [12839.629461] vdc: vdc1 vdc9 [12839.661877] vdc: vdc1 vdc9 [12863.091976] vde: vde1 vde9 [12863.109565] vde: vde1 vde9 [12882.464352] vdf: vdf1 vdf9 [12882.506722] vdf: vdf1 vdf9 [12882.536102] vdf: vdf1 vdf9 [12909.284992] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing load_modules_local [12921.695435] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [12921.958449] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [12922.036441] Lustre: lustre-MDT0000: new disk, initializing [12922.601656] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [12922.666263] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [12928.916283] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [12935.446664] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [12943.359701] Lustre: lustre-OST0000: new disk, initializing [12943.365663] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [12943.372129] Lustre: Skipped 1 previous similar message [12943.536537] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [12944.753091] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:0:ost [12944.767047] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:0:ost] [12944.929292] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x240000400 [12952.562425] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [12965.178295] Lustre: lustre-OST0001: new disk, initializing [12965.185041] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [12965.326292] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [12966.845482] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:1:ost [12966.862887] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:1:ost] [12967.042280] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x280000400 [12974.272697] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [12983.954340] Lustre: DEBUG MARKER: Using TIMEOUT=20 [12988.845481] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [13040.639070] Lustre: DEBUG MARKER: == sanity-quota test 49b: lfs quota -a --blocks has a delimiter ========================================================== 06:02:44 (1785405764) [13051.553603] Lustre: DEBUG MARKER: == sanity-quota test 50: Test if lfs find --projid works ========================================================== 06:02:55 (1785405775) [13110.254237] Lustre: DEBUG MARKER: == sanity-quota test 51: Test project accounting with mv/cp ========================================================== 06:03:54 (1785405834) [13186.843969] Lustre: DEBUG MARKER: == sanity-quota test 52: Rename normal file across project ID ========================================================== 06:05:11 (1785405911) [13228.978927] Lustre: DEBUG MARKER: rename directory return 255 [13284.838440] Lustre: DEBUG MARKER: == sanity-quota test 53: Project inherit attribute could be cleared ========================================================== 06:06:48 (1785406008) [13322.159588] Lustre: DEBUG MARKER: == sanity-quota test 54: basic lfs project interface test ========================================================== 06:07:26 (1785406046) [13385.804771] Lustre: DEBUG MARKER: == sanity-quota test 55: Chgrp should be affected by group quota ========================================================== 06:08:27 (1785406107) [13589.174569] Lustre: DEBUG MARKER: == sanity-quota test 56: lfs quota -t should work well === 06:11:52 (1785406312) [13638.539939] Lustre: DEBUG MARKER: == sanity-quota test 57: lfs project could tolerate errors ========================================================== 06:12:42 (1785406362) [13690.963697] Lustre: DEBUG MARKER: == sanity-quota test 58: project ID should be kept for new mirrors created by FID ========================================================== 06:13:35 (1785406415) [13939.272982] Lustre: DEBUG MARKER: == sanity-quota test 59: lfs project dosen't crash kernel with project disabled ========================================================== 06:17:43 (1785406663) [13942.002938] Lustre: DEBUG MARKER: SKIP: sanity-quota test_59 ldiskfs only test [13945.379735] Lustre: DEBUG MARKER: == sanity-quota test 60: Test quota for root with setgid ========================================================== 06:17:48 (1785406668) [14020.059901] Lustre: DEBUG MARKER: SKIP: sanity-quota test_61 skipping SLOW test 61 [14022.135148] Lustre: DEBUG MARKER: == sanity-quota test 62: Project inherit should be only changed by root ========================================================== 06:19:06 (1785406746) [14065.327889] Lustre: DEBUG MARKER: SKIP: sanity-quota test_63 skipping excluded test 63 [14068.900561] Lustre: DEBUG MARKER: == sanity-quota test 64: lfs project on non-dir/files should succeed ========================================================== 06:19:51 (1785406791) [14136.366064] Lustre: DEBUG MARKER: SKIP: sanity-quota test_65 skipping excluded test 65 [14140.288682] Lustre: DEBUG MARKER: == sanity-quota test 66: nonroot user can not change project state in default ========================================================== 06:21:02 (1785406862) [14197.089892] Lustre: DEBUG MARKER: == sanity-quota test 67: quota pools recalculation ======= 06:22:01 (1785406921) [14198.921322] Lustre: DEBUG MARKER: SKIP: sanity-quota test_67 ZFS grants some block space together with inode [14201.149591] Lustre: DEBUG MARKER: == sanity-quota test 68: slave number in quota pool changed after each add/remove OST ========================================================== 06:22:05 (1785406925) [14232.347650] LustreError: 205181:0:(mgs_handler.c:1144:mgs_iocontrol_pool()) OBD_IOC_POOL err -17, cmd CE021 for pool lustre.qpool1 [14289.884179] Lustre: DEBUG MARKER: == sanity-quota test 69: EDQUOT at one of pools shouldn't affect DOM ========================================================== 06:23:34 (1785407014) [14323.802209] Lustre: DEBUG MARKER: User quota (block hardlimit:200 MB) [14325.867768] Lustre: DEBUG MARKER: User quota (block hardlimit:10 MB) [14616.570378] Lustre: DEBUG MARKER: == sanity-quota test 70a: check lfs setquota/quota with a pool option ========================================================== 06:29:00 (1785407340) [14690.143171] Lustre: DEBUG MARKER: == sanity-quota test 70b: lfs setquota pool works properly ========================================================== 06:30:13 (1785407413) [14738.454406] Lustre: DEBUG MARKER: == sanity-quota test 71a: Check PFL with quota pools ===== 06:31:01 (1785407461) [14740.820792] Lustre: DEBUG MARKER: SKIP: sanity-quota test_71a ZFS grants some block space together with inode [14743.727397] Lustre: DEBUG MARKER: == sanity-quota test 71b: Check SEL with quota pools ===== 06:31:07 (1785407467) [14745.607619] Lustre: DEBUG MARKER: SKIP: sanity-quota test_71b ZFS grants some block space together with inode [14748.028701] Lustre: DEBUG MARKER: == sanity-quota test 72: lfs quota --pool prints only pool's OSTs ========================================================== 06:31:12 (1785407472) [14768.788946] Lustre: DEBUG MARKER: User quota (block hardlimit:50 MB) [14794.460388] Lustre: DEBUG MARKER: Write... [14798.311499] Lustre: DEBUG MARKER: Write out of block quota ... [14865.463589] Lustre: DEBUG MARKER: == sanity-quota test 73a: default limits at OST Pool Quotas ========================================================== 06:33:08 (1785407588) [14899.976338] Lustre: DEBUG MARKER: set to use default quota [14902.498570] Lustre: DEBUG MARKER: set default quota [14906.114018] Lustre: DEBUG MARKER: get default quota [14918.703710] Lustre: DEBUG MARKER: Test not out of quota [14924.957311] Lustre: DEBUG MARKER: Test out of quota [14945.051678] Lustre: DEBUG MARKER: Increase default quota [14989.842201] Lustre: DEBUG MARKER: Set quota to override default quota [14989.912914] LustreError: 182329:0:(qmt_entry.c:558:qmt_adjust_edquot()) $$$ set revoke_time explicitly qmt:lustre-QMT0000 pool:dt-qpool1 id:60000 enforced:1 hard:20480 soft:20480 granted:45063 time:1786012516 qunit: 1024 edquot:0 may_rel:0 revoke:0 default:no [15010.319320] Lustre: DEBUG MARKER: Set to use default quota again [15048.196805] Lustre: DEBUG MARKER: Cleanup [15135.862814] Lustre: DEBUG MARKER: == sanity-quota test 73b: default OST Pool Quotas limit for new user ========================================================== 06:37:40 (1785407860) [15171.078569] Lustre: DEBUG MARKER: set default quota for qpool1 [15173.261297] Lustre: DEBUG MARKER: Write from user that hasn't lqe [15237.725695] Lustre: DEBUG MARKER: == sanity-quota test 74: check quota pools per user ====== 06:39:21 (1785407961) [15360.200283] Lustre: DEBUG MARKER: == sanity-quota test 75: nodemap squashed root respects quota enforcement ========================================================== 06:41:23 (1785408083) [15466.948539] Lustre: DEBUG MARKER: Write... [15472.207968] Lustre: DEBUG MARKER: Write out of block quota ... [15646.929883] Lustre: DEBUG MARKER: == sanity-quota test 76: project ID 4294967295 should be not allowed ========================================================== 06:46:10 (1785408370) [15714.946491] Lustre: DEBUG MARKER: == sanity-quota test 77: lfs setquota should fail in Lustre mount with 'ro' ========================================================== 06:47:18 (1785408438) [15725.524826] Lustre: DEBUG MARKER: == sanity-quota test 78A: Check fallocate increase quota usage ========================================================== 06:47:29 (1785408449) [15727.794109] Lustre: DEBUG MARKER: SKIP: sanity-quota test_78A need >= 2.13.57 and ldiskfs for fallocate [15730.566781] Lustre: DEBUG MARKER: == sanity-quota test 78a: Check fallocate increase projectid usage ========================================================== 06:47:34 (1785408454) [15734.298446] Lustre: DEBUG MARKER: SKIP: sanity-quota test_78a need >= 2.13.57 and ldiskfs for fallocate [15738.073635] Lustre: DEBUG MARKER: == sanity-quota test 79: access to non-existed dt-pool/info doesn't cause a panic ========================================================== 06:47:41 (1785408461) [15777.355468] Lustre: DEBUG MARKER: == sanity-quota test 80: check for EDQUOT after OST failover ========================================================== 06:48:21 (1785408501) [15779.199359] Lustre: DEBUG MARKER: SKIP: sanity-quota test_80 ZFS grants some block space together with inode [15781.185567] Lustre: DEBUG MARKER: == sanity-quota test 81: Race qmt_start_pool_recalc with qmt_pool_free ========================================================== 06:48:25 (1785408505) [15806.088722] Lustre: DEBUG MARKER: User quota (block hardlimit:20 MB) [15815.063635] LustreError: 230034:0:(qmt_pool.c:1413:qmt_pool_recalc()) cfs_fail_timeout id a07 sleeping for 10000ms [15820.768884] Lustre: lustre-MDT0000-lwp-OST0000: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [15820.781863] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [15820.796971] Lustre: Skipped 1 previous similar message [15820.854687] Lustre: Skipped 1 previous similar message [15823.047623] Lustre: lustre-MDT0000: Not available for connect from 192.168.203.2@tcp (stopping) [15825.154393] LustreError: 230034:0:(qmt_pool.c:1413:qmt_pool_recalc()) cfs_fail_timeout id a07 awake [15825.865304] Lustre: server umount lustre-MDT0000 complete [15839.038904] LustreError: MGC192.168.203.102@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [15839.483751] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [15839.770890] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:27 to 0x240000400:65) [15839.775304] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:27 to 0x280000400:65) [15840.449725] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [15840.465826] Lustre: Skipped 1 previous similar message [15846.254435] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [15895.884088] Lustre: DEBUG MARKER: == sanity-quota test 82: verify more than 8 qids for single operation ========================================================== 06:50:19 (1785408619) [15951.256914] Lustre: DEBUG MARKER: == sanity-quota test 83: Setting default quota shouldn't affect grace time ========================================================== 06:51:14 (1785408674) [15992.599456] Lustre: DEBUG MARKER: == sanity-quota test 84: Reset quota should fix the insane granted quota ========================================================== 06:51:56 (1785408716) [16067.047916] Lustre: *** cfs_fail_loc=a08, val=0*** [16067.050291] Lustre: Skipped 1975 previous similar messages [16067.079058] Lustre: *** cfs_fail_loc=a08, val=0*** [16067.085800] Lustre: Skipped 579 previous similar messages [16245.392335] Lustre: DEBUG MARKER: == sanity-quota test 85: do not hung at write with the least_qunit ========================================================== 06:56:08 (1785408968) [16342.205567] Lustre: DEBUG MARKER: == sanity-quota test 86: Pre-acquired quota should be released if quota is over limit ========================================================== 06:57:46 (1785409066) [16450.948284] LustreError: 239000:0:(qmt_entry.c:558:qmt_adjust_edquot()) $$$ set revoke_time explicitly qmt:lustre-QMT0000 pool:md-0x0 id:60000 enforced:1 hard:2048 soft:2048 granted:65536 time:1786013977 qunit: 1024 edquot:0 may_rel:0 revoke:0 default:no [16641.248518] LustreError: 230976:0:(qmt_entry.c:558:qmt_adjust_edquot()) $$$ set revoke_time explicitly qmt:lustre-QMT0000 pool:md-0x0 id:60000 enforced:1 hard:2048 soft:2048 granted:65536 time:1786014167 qunit: 1024 edquot:0 may_rel:0 revoke:0 default:no [16874.945515] LustreError: 230562:0:(qmt_entry.c:558:qmt_adjust_edquot()) $$$ set revoke_time explicitly qmt:lustre-QMT0000 pool:md-0x0 id:1000 enforced:1 hard:2048 soft:2048 granted:65536 time:1786014401 qunit: 1024 edquot:0 may_rel:0 revoke:0 default:no [17012.298022] Lustre: DEBUG MARKER: == sanity-quota test 87: lfs quota -a should print default quota setting ========================================================== 07:08:56 (1785409736) [17026.008251] Lustre: *** cfs_fail_loc=a09, val=0*** [17028.038116] Lustre: *** cfs_fail_loc=a09, val=0*** [17028.040624] Lustre: Skipped 57 previous similar messages [17032.094418] Lustre: *** cfs_fail_loc=a09, val=0*** [17032.098788] Lustre: Skipped 127 previous similar messages [17040.162874] Lustre: *** cfs_fail_loc=a09, val=0*** [17040.174158] Lustre: Skipped 301 previous similar messages [17155.765283] Lustre: lustre-MDT0000: Not available for connect from 192.168.203.2@tcp (stopping) [17156.577775] Lustre: lustre-MDT0000-lwp-OST0000: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [17156.604209] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [17160.853122] Lustre: lustre-MDT0000: Not available for connect from 192.168.203.2@tcp (stopping) [17160.862707] Lustre: Skipped 1 previous similar message [17161.519893] Lustre: server umount lustre-MDT0000 complete [17172.402606] LustreError: MGC192.168.203.102@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [17173.270777] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [17173.567949] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:27 to 0x280000400:97) [17173.589120] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:68 to 0x240000400:97) [17177.292090] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [17177.308944] Lustre: Skipped 1 previous similar message [17180.503572] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [17207.563977] Lustre: DEBUG MARKER: == sanity-quota test 88: Writing over quota should not hang ========================================================== 07:12:11 (1785409931) [17209.828873] Lustre: DEBUG MARKER: SKIP: sanity-quota test_88 require client with >4k pages [17212.422450] Lustre: DEBUG MARKER: == sanity-quota test 89: Show default quota with squash_uid ========================================================== 07:12:16 (1785409936) [17239.421809] Lustre: DEBUG MARKER: == sanity-quota test 90a: lfs quota should work without mount point ========================================================== 07:12:43 (1785409963) [17267.572566] Lustre: DEBUG MARKER: == sanity-quota test 90b: lfs quota should work with multiple mount points ========================================================== 07:13:11 (1785409991) [17296.951371] Lustre: DEBUG MARKER: == sanity-quota test 91: new quota index files in quota_master ========================================================== 07:13:41 (1785410021) [17315.821309] Lustre: lustre-MDT0000-lwp-OST0001: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [17315.829954] Lustre: Skipped 1 previous similar message [17315.837502] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [17320.930295] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [17320.934638] Lustre: Skipped 2 previous similar messages [17321.475099] Lustre: server umount lustre-MDT0000 complete [17327.338521] LustreError: 182314:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1785410053 with bad export cookie 12267358205367221897 [17327.344117] LustreError: MGC192.168.203.102@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [17327.371080] LustreError: 182314:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [17329.501806] Lustre: server umount lustre-OST0000 complete [17342.726749] Lustre: server umount lustre-OST0001 complete [17354.131470] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing set_hostid [17367.189945] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing load_modules_local [17385.379297] vdc: vdc1 vdc9 [17403.056330] vde: vde1 vde9 [17417.311285] vdf: vdf1 vdf9 [17417.360107] vdf: vdf1 vdf9 [17417.384027] vdf: vdf1 vdf9 [17432.893953] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [17433.312941] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [17433.526991] Lustre: lustre-MDT0000: new disk, initializing [17434.450835] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [17434.656470] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [17441.789324] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [17457.247398] Lustre: DEBUG MARKER: oleg302-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [17467.259622] Lustre: lustre-OST0000: new disk, initializing [17467.273690] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [17467.276431] Lustre: Skipped 1 previous similar message [17467.500904] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [17469.421548] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:0:ost [17469.434205] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:0:ost] [17469.606744] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x240000400 [17477.707057] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [17493.009769] Lustre: DEBUG MARKER: oleg302-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [17505.309618] Lustre: lustre-OST0001: new disk, initializing [17505.319182] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [17505.513923] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [17507.212074] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:1:ost [17507.216625] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:1:ost] [17507.445979] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x280000400 [17516.906676] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [17530.404207] Lustre: DEBUG MARKER: oleg302-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0001-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [17546.954054] Lustre: lustre-MDT0000: Not available for connect from 192.168.203.2@tcp (stopping) [17548.257706] Lustre: lustre-MDT0000-lwp-OST0001: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [17548.268100] Lustre: Skipped 1 previous similar message [17551.577216] Lustre: server umount lustre-MDT0000 complete [17567.407645] LustreError: MGC192.168.203.102@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [17567.938315] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [17568.955274] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [17568.969695] Lustre: Skipped 1 previous similar message [17573.589166] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [17588.043570] Lustre: DEBUG MARKER: oleg302-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [17590.120429] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [17605.096056] Lustre: lustre-MDT0000-lwp-OST0000: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [17605.102793] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [17605.118957] Lustre: Skipped 1 previous similar message [17605.143884] Lustre: Skipped 3 previous similar messages [17607.894766] Lustre: server umount lustre-MDT0000 complete [17616.828562] LustreError: 249804:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1785410343 with bad export cookie 12267358205367224347 [17616.836386] LustreError: MGC192.168.203.102@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [17616.902236] Lustre: server umount lustre-OST0000 complete [17623.981063] Lustre: server umount lustre-OST0001 complete [17651.364733] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing set_hostid [17662.850462] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing load_modules_local [17682.771802] vdc: vdc1 vdc9 [17702.359580] vde: vde1 vde9 [17717.657254] vdf: vdf1 vdf9 [17741.758815] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing load_modules_local [17755.632937] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [17756.000992] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [17756.112163] Lustre: lustre-MDT0000: new disk, initializing [17757.068052] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [17757.282629] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [17764.478041] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [17770.906143] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [17778.758735] Lustre: lustre-OST0000: new disk, initializing [17778.767369] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [17778.778616] Lustre: Skipped 1 previous similar message [17779.056087] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [17780.518229] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:0:ost [17780.531907] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:0:ost] [17780.793138] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x240000400 [17789.167633] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [17803.236378] Lustre: lustre-OST0001: new disk, initializing [17803.239431] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [17804.554113] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:1:ost [17804.565216] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:1:ost] [17804.685479] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x280000400 [17812.893562] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [17825.837676] Lustre: DEBUG MARKER: Using TIMEOUT=20 [17830.238741] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [17840.502905] Lustre: DEBUG MARKER: == sanity-quota test 92: Cannot set inode limit with Quota Pools ========================================================== 07:22:43 (1785410563) [17865.879525] Lustre: DEBUG MARKER: == sanity-quota test 93: update projid while client write to OST ========================================================== 07:23:09 (1785410589) [17900.310940] Lustre: *** cfs_fail_loc=170c, val=0*** [17975.141843] Lustre: DEBUG MARKER: == sanity-quota test 94: lfs quota all respects nodemap offset ========================================================== 07:24:59 (1785410699) [18034.367949] Lustre: lustre-MDT0000: Not available for connect from 192.168.203.2@tcp (stopping) [18034.658349] Lustre: lustre-MDT0000-lwp-OST0001: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [18036.934778] Lustre: server umount lustre-MDT0000 complete [18048.249981] LustreError: MGC192.168.203.102@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [18049.044987] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [18049.059262] Lustre: Skipped 1 previous similar message [18049.387762] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3 to 0x240000400:33) [18055.146775] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [18055.171663] Lustre: Skipped 1 previous similar message [18056.992569] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [18075.620679] Lustre: lustre-MDT0000-lwp-OST0000: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [18075.644653] Lustre: Skipped 2 previous similar messages [18077.851944] Lustre: server umount lustre-MDT0000 complete [18088.142424] LustreError: MGC192.168.203.102@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [18089.013769] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3 to 0x240000400:65) [18095.062488] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [18096.124282] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [18096.137795] Lustre: Skipped 1 previous similar message [18104.291853] Lustre: DEBUG MARKER: == sanity-quota test 95a: Correct limits for squashed root ========================================================== 07:27:08 (1785410828) [18144.923129] Lustre: DEBUG MARKER: == sanity-quota test 95b: df respects squashed project id ========================================================== 07:27:48 (1785410868) [18212.010744] Lustre: DEBUG MARKER: == sanity-quota test 96: quota grant should be released when big files are deleted ========================================================== 07:28:55 (1785410935) [18213.855446] Lustre: DEBUG MARKER: SKIP: sanity-quota test_96 the test in only needed to run on LDiskFS [18215.952930] Lustre: DEBUG MARKER: == sanity-quota test 97a: LQA control commands =========== 07:29:00 (1785410940) [18255.337696] LustreError: 267671:0:(qmt_lqa.c:79:qmt_lqa_destroy()) lustre-QMT0000: cannot destroy lqa-dt-lqa1: rc = -2 [18255.346502] LustreError: 267671:0:(qmt_lqa.c:84:qmt_lqa_destroy()) lustre-QMT0000: cannot destroy lqa-md-lqa1: rc = -2 [18257.315590] Lustre: DEBUG MARKER: == sanity-quota test 97b: Check LQA internals ============ 07:29:41 (1785410981) [18280.385938] LustreError: 268469:0:(qmt_lqa.c:250:qmt_lqa_insert_range()) lustre-QMT0000: LQA range 15-31 partially overlaps with existing range 10-19: rc = -34 [18280.402210] LustreError: 268469:0:(qmt_lqa.c:669:qmt_lqa_add()) lustre-QMT0000: lqa:lqa1 can't add range 15:31: rc = -17 [18284.256610] LustreError: 268667:0:(qmt_lqa.c:825:qmt_lqa_remove()) lustre-QMT0000: lqa-md-lqa1 cannot remove range 10:19: rc = -2 [18299.122398] Lustre: DEBUG MARKER: adding 50 LQA ranges took 3s [18306.198411] Lustre: DEBUG MARKER: Removing 50 LQA ranges took 2s [18318.496629] Lustre: DEBUG MARKER: == sanity-quota test 97c: LQA lfs quota commands and MDS restart consistency ========================================================== 07:30:42 (1785411042) [18324.339966] Lustre: Failing over lustre-MDT0000 [18324.848935] Lustre: server umount lustre-MDT0000 complete [18334.582886] LustreError: MGC192.168.203.102@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [18335.135654] Lustre: 270484:0:(scrub.c:694:lustre_index_register()) lustre-MDT0000: the index [0x200000003:0x74:0x0] has registered with 8/8, may be invalid, replace with 4/8 [18335.227800] Lustre: lustre-MDT0000-lwp-OST0001: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [18335.256693] Lustre: Skipped 1 previous similar message [18335.633632] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [18335.638617] Lustre: Skipped 1 previous similar message [18335.820271] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [18336.476787] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [18336.646183] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [18336.730810] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3 to 0x240000400:97) [18340.848133] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [18340.868468] Lustre: Skipped 1 previous similar message [18342.368596] Lustre: 3286:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1785411053/real 1785411053] req@ffff9d41d8411f80 x1872120042781056/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1785411069 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [18342.412494] Lustre: 3286:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 1 previous similar message [18342.984446] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [18348.000313] Lustre: 3284:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1785411058/real 1785411058] req@ffff9d41d0562680 x1872120042781440/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1785411074 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [18348.037203] Lustre: 3284:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 1 previous similar message [18351.440212] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [18362.275747] Lustre: DEBUG MARKER: == sanity-quota test 97d: LQA disk persistence using standard commands ========================================================== 07:31:26 (1785411086) [18387.518610] Lustre: Failing over lustre-MDT0000 [18387.636476] Lustre: lustre-MDT0000: Not available for connect from 192.168.203.2@tcp (stopping) [18387.651273] Lustre: Skipped 5 previous similar messages [18388.045899] Lustre: server umount lustre-MDT0000 complete [18398.418477] LustreError: MGC192.168.203.102@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [18398.871617] Lustre: 272504:0:(scrub.c:694:lustre_index_register()) lustre-MDT0000: the index [0x200000003:0x87:0x0] has registered with 8/8, may be invalid, replace with 4/8 [18398.895459] LustreError: 272504:0:(qmt_lqa.c:522:qmt_lqa_load_ranges_from_disk()) lustre-QMT0000: Failed to get record from IAM iterator: rc = -2 [18398.978047] Lustre: lustre-MDT0000-lwp-OST0001: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [18399.501971] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [18404.330468] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [18404.338564] Lustre: Skipped 1 previous similar message [18406.153058] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [18407.127534] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [18407.284056] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [18407.373462] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3 to 0x240000400:129) [18408.168216] Lustre: 3285:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1785411118/real 1785411118] req@ffff9d41c63f6680 x1872120042799616/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1785411134 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [18408.202148] Lustre: 3285:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 1 previous similar message [18412.513171] Lustre: 3284:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1785411123/real 1785411123] req@ffff9d41c63f7800 x1872120042800128/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1785411139 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [18412.558117] Lustre: 3284:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 1 previous similar message [18414.391518] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [18476.080967] Lustre: DEBUG MARKER: == sanity-quota test 98: Verify MDT retry on -EDQUOT during mkdir ========================================================== 07:33:19 (1785411199) [18480.701521] Lustre: DEBUG MARKER: SKIP: sanity-quota test_98 needs >= 2 MDTs [18484.576576] Lustre: DEBUG MARKER: == sanity-quota test 300: inode quota with MDT directory migration at 80% limit ========================================================== 07:33:27 (1785411207) [18487.675290] Lustre: DEBUG MARKER: SKIP: sanity-quota test_300 needs >= 2 MDTs [18495.407944] Lustre: DEBUG MARKER: == sanity-quota test complete, duration 18222 sec ======== 07:33:39 (1785411219) [18498.047196] Lustre: DEBUG MARKER: === sanity-quota: start cleanup 07:33:41 (1785411221) === [18502.754592] Lustre: DEBUG MARKER: === sanity-quota: finish cleanup 07:33:46 (1785411226) === [18510.804309] Lustre: server umount lustre-MDT0000 complete [18517.070130] LustreError: 268215:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1785411243 with bad export cookie 12267358205367229968 [18517.101652] LustreError: 268215:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [18517.110599] LustreError: MGC192.168.203.102@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [18526.839935] Lustre: server umount lustre-OST0000 complete [18528.227428] Lustre: 3287:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1785411238/real 1785411238] req@ffff9d41c7fc0a80 x1872120042831616/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1785411254 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [18528.274863] Lustre: 3287:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 1 previous similar message [18528.291153] Lustre: lustre-MDT0000-lwp-OST0001: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [18528.310424] Lustre: Skipped 1 previous similar message [18534.261281] Lustre: server umount lustre-OST0001 complete [18552.668091] Lustre: DEBUG MARKER: oleg302-server.virtnet: executing unload_modules_local [18557.140632] Key type lgssc unregistered [18557.499208] LNet: 275751:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [18557.505505] LNetError: 275751:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [18557.525722] LNet: Removed LNI 192.168.203.102@tcp [18559.031176] Key type .llcrypt unregistered [18559.032846] Key type ._llcrypt unregistered