[ 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 612320510 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: 2829652K/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.001013] APIC: Switch to symmetric I/O mode setup [ 0.002338] x2apic enabled [ 0.003008] Switched APIC routing to physical x2apic. [ 0.004011] kvm-guest: setup PV IPIs [ 0.007366] ..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.008032] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.009014] pid_max: default: 32768 minimum: 301 [ 0.010142] LSM: Security Framework initializing [ 0.011059] Yama: becoming mindful. [ 0.012039] SELinux: Initializing. [ 0.013065] *** VALIDATE selinux *** [ 0.021715] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.025610] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.026155] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.027111] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.028125] *** VALIDATE tmpfs *** [ 0.029457] *** VALIDATE proc *** [ 0.031039] *** VALIDATE cgroup *** [ 0.032008] *** VALIDATE cgroup2 *** [ 0.033261] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.034171] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.036003] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.037030] Spectre V2 : User space: Vulnerable [ 0.038011] Speculative Store Bypass: Vulnerable [ 0.041095] debug: unmapping init [mem 0xffffffffa7859000-0xffffffffa7860fff] [ 0.043262] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.044725] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.045029] ... version: 2 [ 0.046013] ... bit width: 48 [ 0.047012] ... generic registers: 4 [ 0.048008] ... value mask: 0000ffffffffffff [ 0.049014] ... max period: 00007fffffffffff [ 0.050012] ... fixed-purpose events: 3 [ 0.051012] ... event mask: 000000070000000f [ 0.053238] rcu: Hierarchical SRCU implementation. [ 0.055536] smp: Bringing up secondary CPUs ... [ 0.056583] x86: Booting SMP configuration: [ 0.057030] .... node #0, CPUs: #1 #2 #3 [ 0.064205] smp: Brought up 1 node, 4 CPUs [ 0.066033] smpboot: Max logical packages: 1 [ 0.067012] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.103589] node 0 deferred pages initialised in 34ms [ 0.104149] devtmpfs: initialized [ 0.105000] x86/mm: Memory block size: 128MB [ 0.106000] gcov: version magic: 0x41383552 [ 0.109346] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.111080] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.112000] pinctrl core: initialized pinctrl subsystem [ 0.113159] [ 0.113643] ************************************************************* [ 0.116010] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.118011] ** ** [ 0.120010] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.122011] ** ** [ 0.124010] ** This means that this kernel is built to expose internal ** [ 0.126013] ** IOMMU data structures, which may compromise security on ** [ 0.128055] ** your system. ** [ 0.131011] ** ** [ 0.133009] ** If you see this message and you are not debugging the ** [ 0.135011] ** kernel, report this immediately to your vendor! ** [ 0.137011] ** ** [ 0.139011] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.141011] ************************************************************* [ 0.144489] NET: Registered protocol family 16 [ 0.146549] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.149069] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.151088] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.155045] cpuidle: using governor menu [ 0.157000] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.159874] PCI: Using configuration type 1 for base access [ 0.162151] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.170081] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.171018] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.176291] cryptd: max_cpu_qlen set to 1000 [ 0.178301] ACPI: Added _OSI(Module Device) [ 0.179000] ACPI: Added _OSI(Processor Device) [ 0.180009] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.182018] ACPI: Added _OSI(Processor Aggregator Device) [ 0.187807] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.195790] ACPI: Interpreter enabled [ 0.197092] ACPI: PM: (supports S0 S3 S4 S5) [ 0.199016] ACPI: Using IOAPIC for interrupt routing [ 0.201114] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.204503] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.220212] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.222044] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.225019] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.228151] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.233551] acpiphp: Slot [2] registered [ 0.235175] acpiphp: Slot [5] registered [ 0.237201] acpiphp: Slot [6] registered [ 0.238148] acpiphp: Slot [7] registered [ 0.240188] acpiphp: Slot [8] registered [ 0.241140] acpiphp: Slot [9] registered [ 0.243158] acpiphp: Slot [10] registered [ 0.244133] acpiphp: Slot [3] registered [ 0.246098] acpiphp: Slot [4] registered [ 0.247098] acpiphp: Slot [11] registered [ 0.248088] acpiphp: Slot [12] registered [ 0.250103] acpiphp: Slot [13] registered [ 0.251230] acpiphp: Slot [14] registered [ 0.253136] acpiphp: Slot [15] registered [ 0.254225] acpiphp: Slot [16] registered [ 0.256101] acpiphp: Slot [17] registered [ 0.258124] acpiphp: Slot [18] registered [ 0.259140] acpiphp: Slot [19] registered [ 0.261102] acpiphp: Slot [20] registered [ 0.262110] acpiphp: Slot [21] registered [ 0.264153] acpiphp: Slot [22] registered [ 0.265093] acpiphp: Slot [23] registered [ 0.266090] acpiphp: Slot [24] registered [ 0.268142] acpiphp: Slot [25] registered [ 0.269135] acpiphp: Slot [26] registered [ 0.271103] acpiphp: Slot [27] registered [ 0.273125] acpiphp: Slot [28] registered [ 0.274106] acpiphp: Slot [29] registered [ 0.276111] acpiphp: Slot [30] registered [ 0.277112] acpiphp: Slot [31] registered [ 0.279059] PCI host bridge to bus 0000:00 [ 0.280018] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.282022] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.285013] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.286000] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.287028] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.290031] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.292215] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.295199] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.298419] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.309018] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.313606] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.314021] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.316022] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.318020] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.321656] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.323894] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.326042] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.329817] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.335017] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.348014] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.353014] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.361252] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.368016] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.377031] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.411019] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.425447] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.432019] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.457045] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.490023] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.504713] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.517018] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.532018] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.570018] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.588064] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.598022] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.609019] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.644019] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.661066] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.672023] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.684028] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.714019] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 0.731515] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.969033] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.976018] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.995034] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 1.007691] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 1.010418] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 1.012477] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 1.015389] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 1.017215] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 1.023028] iommu: Default domain type: Passthrough [ 1.025412] SCSI subsystem initialized [ 1.026199] ACPI: bus type USB registered [ 1.028169] usbcore: registered new interface driver usbfs [ 1.030077] usbcore: registered new interface driver hub [ 1.032128] usbcore: registered new device driver usb [ 1.034248] pps_core: LinuxPPS API ver. 1 registered [ 1.036014] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 1.039126] PTP clock support registered [ 1.042032] EDAC MC: Ver: 3.0.0 [ 1.044048] PCI: Using ACPI for IRQ routing [ 1.046069] NetLabel: Initializing [ 1.048010] NetLabel: domain hash size = 128 [ 1.049009] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 1.051085] NetLabel: unlabeled traffic allowed by default [ 1.053409] vgaarb: loaded [ 1.055372] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 1.057016] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 1.065277] clocksource: Switched to clocksource kvm-clock [ 1.177963] VFS: Disk quotas dquot_6.6.0 [ 1.179257] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 1.181418] *** VALIDATE ramfs *** [ 1.182492] *** VALIDATE hugetlbfs *** [ 1.184584] pnp: PnP ACPI init [ 1.186771] pnp: PnP ACPI: found 6 devices [ 1.201907] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 1.204824] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 1.206766] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 1.208617] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 1.210650] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 1.212726] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 1.215336] NET: Registered protocol family 2 [ 1.217506] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 1.222160] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 1.225226] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 1.229811] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 1.232726] TCP: Hash tables configured (established 65536 bind 65536) [ 1.235159] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 1.237679] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 1.240026] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 1.242546] NET: Registered protocol family 1 [ 1.245455] RPC: Registered named UNIX socket transport module. [ 1.247457] RPC: Registered udp transport module. [ 1.250958] RPC: Registered tcp transport module. [ 1.252556] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 1.254619] NET: Registered protocol family 44 [ 1.256130] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 1.257927] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 1.259691] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 1.261633] PCI: CLS 0 bytes, default 64 [ 1.263155] Unpacking initramfs... [ 2.800957] debug: unmapping init [mem 0xffff926fbcc54000-0xffff926fbffbffff] [ 2.805249] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.807746] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.812404] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 3.342548] Initialise system trusted keyrings [ 3.344320] Key type blacklist registered [ 3.346419] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 3.356061] zbud: loaded [ 3.359165] *** VALIDATE nfs *** [ 3.360389] *** VALIDATE nfs4 *** [ 3.362254] pstore: using deflate compression [ 3.366307] Platform Keyring initialized [ 3.480364] NET: Registered protocol family 38 [ 3.482365] Key type asymmetric registered [ 3.484156] Asymmetric key parser 'x509' registered [ 3.485985] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 3.489407] io scheduler mq-deadline registered [ 3.491027] io scheduler kyber registered [ 3.493187] io scheduler bfq registered [ 3.495126] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 3.498402] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 3.501915] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 3.505515] ACPI: Power Button [PWRF] [ 3.511693] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 3.519763] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 3.532762] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 3.539497] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 3.565553] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 3.592858] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.655788] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.662698] Non-volatile memory driver v1.3 [ 3.664430] Linux agpgart interface v0.103 [ 3.695030] virtio_blk virtio1: [vda] 146536 512-byte logical blocks (75.0 MB/71.6 MiB) [ 3.697885] vda: detected capacity change from 0 to 75026432 [ 3.714267] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.717155] vdb: detected capacity change from 0 to 1073741824 [ 3.735068] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.738299] vdc: detected capacity change from 0 to 2621440000 [ 3.758581] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.761548] vdd: detected capacity change from 0 to 2621440000 [ 3.784363] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.787490] vde: detected capacity change from 0 to 4294967296 [ 3.811378] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.814734] vdf: detected capacity change from 0 to 4294967296 [ 3.834728] libphy: Fixed MDIO Bus: probed [ 3.850944] usbcore: registered new interface driver usbserial_generic [ 3.853567] usbserial: USB Serial support registered for generic [ 3.856209] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.861912] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.863900] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.867032] mousedev: PS/2 mouse device common for all mice [ 3.869676] rtc_cmos 00:05: RTC can wake from S4 [ 3.873695] rtc_cmos 00:05: registered as rtc0 [ 3.875231] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.875939] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.875997] intel_pstate: CPU model not supported [ 3.878454] hid: raw HID events driver (C) Jiri Kosina [ 3.884054] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.884550] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.899308] usbcore: registered new interface driver usbhid [ 3.901388] usbhid: USB HID core driver [ 3.902943] drop_monitor: Initializing network drop monitor service [ 3.905205] Initializing XFRM netlink socket [ 3.907208] NET: Registered protocol family 10 [ 3.909968] Segment Routing with IPv6 [ 3.911406] NET: Registered protocol family 17 [ 3.921751] mpls_gso: MPLS GSO support [ 3.927178] RAS: Correctable Errors collector initialized. [ 3.929384] AVX version of gcm_enc/dec engaged. [ 3.930934] AES CTR mode by8 optimization enabled [ 4.012849] sched_clock: Marking stable (4012589299, 0)->(4992321019, -979731720) [ 4.018409] registered taskstats version 1 [ 4.020606] Loading compiled-in X.509 certificates [ 4.022941] zswap: loaded using pool lzo/zbud [ 4.053770] Key type big_key registered [ 4.071911] Key type encrypted registered [ 4.073721] ima: No TPM chip found, activating TPM-bypass! [ 4.076255] ima: Allocated hash algorithm: sha1 [ 4.078275] ima: No architecture policies found [ 4.079990] evm: Initialising EVM extended attributes: [ 4.082389] evm: security.selinux [ 4.083697] evm: security.ima [ 4.085276] evm: security.capability [ 4.086636] evm: HMAC attrs: 0x1 [ 4.089275] rtc_cmos 00:05: setting system clock to 2026-08-22 04:27:52 UTC (1787372872) [ 4.097853] debug: unmapping init [mem 0xffffffffa8803000-0xffffffffa89fffff] [ 4.101690] debug: unmapping init [mem 0xffffffffa7582000-0xffffffffa7858fff] [ 4.110241] Write protecting the kernel read-only data: 28672k [ 4.113618] debug: unmapping init [mem 0xffffffffa5c03000-0xffffffffa5dfffff] [ 4.116895] debug: unmapping init [mem 0xffffffffa6514000-0xffffffffa65fffff] [ 4.161362] 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) [ 4.170573] systemd[1]: Detected virtualization kvm. [ 4.172577] systemd[1]: Detected architecture x86-64. [ 4.175447] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 4.203749] systemd[1]: No hostname configured. [ 4.205672] systemd[1]: Set hostname to . [ 4.208099] random: systemd: uninitialized urandom read (16 bytes read) [ 4.210364] systemd[1]: Initializing machine ID from random generator. [ 4.307528] random: ln: uninitialized urandom read (6 bytes read) [ 4.546467] random: systemd: uninitialized urandom read (16 bytes read) [ 4.549416] systemd[1]: Reached target Initrd Root Device. [ OK ] Reached target Initrd Root Device. [ 4.557340] systemd[1]: Reached target Local File Systems. [ OK ] Reached target Local File Systems. [ 4.567593] systemd[1]: Listening on Journal Socket (/dev/log). [ OK ] Listening on Journal Socket (/dev/log). [ OK ] Listening on udev Control Socket. [ OK ] Listening on udev Kernel Socket. [ OK ] Reached target Timers. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. [ OK ] Reached target Slices. [ OK ] Reached target Swap. [ OK ] Listening on Journal Socket. [ OK ] Started Memstrack Anylazing Service. Starting Create Volatile Files and Directories... Starting Create list of required st…ce nodes for the current kernel... Starting Apply Kernel Variables... [ OK ] Reached target Sockets. Starting Journal Service... Starting Setup Virtual Console... [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Apply Kernel Variables. [ OK ] Started Setup Virtual Console. 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... [ 5.444346] device-mapper: uevent: version 1.0.3 [ 5.446403] 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 ] [ 6.612584] random: fast init done Started Hardware RNG Entropy Gatherer Daemon. [ 6.828614] virtio_net virtio0 ens2: renamed from eth0 [ 8.808311] scsi host0: ata_piix [ 8.836405] scsi host1: ata_piix [ 8.837822] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 8.841784] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 11.603464] random: crng init done [ 11.605131] random: 7 urandom warning(s) missed due to ratelimiting [ 12.695941] dracut-initqueue[582]: RTNETLINK answers: File exists Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. Mounting /sysroot... [ OK ] Reached target Remote File Systems (Pre). [ OK ] [ 15.700950] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) Reached target Remote File Systems. [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... 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 Initrd Root Device. [ OK ] Stopped target Timers. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Slices. [ OK ] Stopped target System Initialization. [ OK ] Stopped target Local Encrypted Volumes. [ 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 Apply Kernel Variables. [ OK ] Stopped target Sockets. [ OK ] Stopped target Paths. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Closed udev Kernel Socket. [ OK ] Closed udev Control Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 20.785228] printk: systemd: 26 output lines suppressed due to ratelimiting [ 22.389202] SELinux: Disabled at runtime. [ 22.840374] 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) [ 22.884359] systemd[1]: Detected virtualization kvm. [ 22.895741] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 26.527405] systemd[1]: initrd-switch-root.service: Succeeded. [ 26.550583] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 26.597671] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 26.609620] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 26.619355] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 26.631570] systemd[1]: Starting Journal Service... Starting Journal Service... [ 26.670902] systemd[1]: Mounting POSIX Message Queue File System... Mounting POSIX Message Queue File System... Starting Remount Root and Kernel File Systems... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. Activating swap /dev/disk/by-label/SWAP... [ OK ] Reached target rpc_pipefs.target. [ 27.382138] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS Starting Create list of required st…ce nodes for the current kernel... [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Created slice system-sshd\x2dkeygen.slice. [ 29.715321] systemd[1]: Created slice system-serial\x2dgetty.slice. [ OK ] Created slice system-serial\x2dgetty.slice. [ 29.856489] systemd[1]: Started Forward Password Requests to Wall Directory Watch. [ OK ] Started Forward Password Requests to Wall Directory Watch. [ 29.936950] systemd[1]: Created slice User and Session Slice. [ OK ] Created slice User and Session Slice. [ 29.984329] systemd[1]: Reached target Slices. [ OK ] Reached target Slices. [ 30.038734] systemd[1]: Reached target Paths. [ OK ] Reached target Paths. [ 30.100318] systemd[1]: Listening on RPCbind Server Activation Socket. [ OK ] Listening on RPCbind Server Activation Socket. [ 30.136727] systemd[1]: Reached target RPC Port Mapper. [ OK ] Reached target RPC Port Mapper. [ 30.198275] systemd[1]: Mounting Kernel Debug File System... Mounting Kernel Debug File System... [ 30.342286] systemd[1]: Listening on Process Core Dump Socket. [ OK ] Listening on Process Core Dump Socket. [ 30.410360] systemd[1]: Listening on udev Kernel Socket. [ OK ] Listening on udev Kernel Socket. [ OK ] Created slice system-getty.slice. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Listening on udev Control Socket. Starting udev Coldplug all Devices... Mounting Huge Pages File System... Starting Apply Kernel Variables... [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd File Systems. [ OK ] Stopped target Initrd Root File System. [ OK ] Mounted POSIX Message Queue File System. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Started Journal Service. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Mounted Kernel Debug File System. [ OK ] Mounted Huge Pages File System. [ OK ] Started Apply Kernel Variables. [ OK ] Reached target Swap. Starting Flush Journal to Persistent Storage... Starting Configure read-only root support... Starting Create Static Device Nodes in /dev... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started udev Coldplug all Devices. [ OK ] Started Create Static Device Nodes in /dev. Starting udev Kernel Device Manager... [ OK ] Reached target Local File Systems (Pre). Mounting /mnt... Mounting /home/green/git/lustre-release... [ OK ] Mounted /mnt. [ 33.368101] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 35.703823] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 36.897639] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 37.450191] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 37.710042] EDAC sbridge: Ver: 1.1.2 [* ] A start job is running for Configur…only root support (14s / no limit) [** ] A start job is running for Configur…only root support (14s / no limit) [*** ] A start job is running for Configur…only root support (15s / no limit) [ *** ] A start job is running for Configur…only root support (15s / no limit) [ *** ] A start job is running for Configur…only root support (16s / no limit) [ ***] A start job is running for Configur…only root support (16s / no limit) [ **] A start job is running for Configur…only root support (17s / no limit) [ *] A start job is running for Configur…only root support (17s / no limit) [ **] A start job is running for Configur…only root support (17s / no limit)[ 44.515839] Key type dns_resolver registered [ ***] A start job is running for Configur…only root support (18s / no limit) [ *** ] A start job is running for Configur…only root support (18s / no limit) [ *** ] A start job is running for Configur…only root support (19s / no limit)[ 45.972916] NFS: Registering the id_resolver key type [ 45.981520] Key type id_resolver registered [ 45.993873] Key type id_legacy registered [*** ] A start job is running for Configur…only root support (19s / no limit) [** ] A start job is running for Configur…only root support (20s / no limit) [ OK ] Started Configure read-only root support. Starting Load/Save Random Seed... [ OK ] Reached target Local File Systems. Starting Rebuild Dynamic Linker Cache... Starting Mark the need to relabel after reboot... Starting Create Volatile Files and Directories... [ OK ] Started Load/Save Random Seed. [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Create Volatile Files and Directories. Starting RPC Bind... Starting Update UTMP about System Boot/Shutdown... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Started dnf makecache --timer. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Reached target Timers. [ OK ] Reached target Basic System. [ OK ] Started irqbalance daemon. Starting Login Service... [ OK ] Started D-Bus System Message Bus. Starting Restore /run/initramfs on shutdown... [ OK ] Reached target sshd-keygen.target. Starting Network Manager... [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Network Manager. Starting Network Manager Wait Online... [ OK ] Reached target Network. Starting GSSAPI Proxy Daemon... Starting OpenSSH server daemon... Starting Dynamic System Tuning Daemon... [ OK ] Started OpenSSH server daemon. [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Started Login Service. Starting Hostname Service... [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... [ OK ] Started Permit User Sessions. [ OK ] Started Serial Getty on ttyS1. [ OK ] Started Command Scheduler. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Getty on tty1. [ 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. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg141-server login: [ 91.031436] spl: loading out-of-tree module taints kernel. [ 97.228377] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 108.476123] Key type ._llcrypt registered [ 108.477846] Key type .llcrypt registered [ 108.559541] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing set_hostid [ 126.371787] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing load_modules_local [ 128.348816] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 128.377182] alg: No test for adler32 (adler32-zlib) [ 129.732530] Lustre: Lustre: Build Version: 2.17.57_45_gb800aec [ 130.364066] LNet: Added LNI 192.168.201.141@tcp [8/256/0/180] [ 132.119154] Key type lgssc registered [ 133.776919] Lustre: Echo OBD driver; http://www.lustre.org/ [ 144.017737] vdc: vdc1 vdc9 [ 145.263019] hrtimer: interrupt took 3902828 ns [ 154.263790] vde: vde1 vde9 [ 164.922495] vdf: vdf1 vdf9 [ 183.605381] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing load_modules_local [ 193.845702] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 195.181263] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 195.443292] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 195.517308] Lustre: lustre-MDT0000: new disk, initializing [ 195.834191] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 195.894608] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 200.399516] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 205.308615] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 211.522762] Lustre: lustre-OST0000: new disk, initializing [ 211.527838] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 211.534471] Lustre: Skipped 1 previous similar message [ 211.637365] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 214.975323] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:0:ost [ 214.981689] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:0:ost] [ 215.191291] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x240000400 [ 218.291222] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 229.882966] Lustre: lustre-OST0001: new disk, initializing [ 229.886643] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 229.958309] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 236.259636] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:1:ost [ 236.264921] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:1:ost] [ 236.393515] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x280000400 [ 236.660623] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 249.853464] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 261.420534] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 268.951934] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing check_logdir /tmp/testlogs/ [ 274.535798] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing yml_node [ 279.811464] Lustre: DEBUG MARKER: Client: 2.17.57.45 [ 282.750940] Lustre: DEBUG MARKER: MDS: 2.17.57.45 [ 286.483095] Lustre: DEBUG MARKER: OSS: 2.17.57.45 [ 288.941740] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity-quota ============----- Sat Aug 22 00:32:36 EDT 2026 [ 310.295735] Lustre: DEBUG MARKER: excepting tests: 2 4a 63 65 [ 312.448062] Lustre: DEBUG MARKER: skipping tests SLOW=no: 61 12a 9 [ 315.335222] Lustre: DEBUG MARKER: === sanity-quota: start setup 00:33:03 (1787373183) === [ 321.426367] Lustre: DEBUG MARKER: oleg141-client.virtnet: executing check_config_client /mnt/lustre [ 338.546391] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 342.102598] Lustre: 11338:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 345.904618] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 349.746752] Lustre: DEBUG MARKER: === sanity-quota: finish setup 00:33:37 (1787373217) === [ 419.500444] Lustre: DEBUG MARKER: == sanity-quota test 0: Test basic quota performance ===== 00:34:47 (1787373287) [ 478.856304] Lustre: DEBUG MARKER: == sanity-quota test 1a: Block hard limit (normal use and out of quota) ========================================================== 00:35:46 (1787373346) [ 495.964725] Lustre: DEBUG MARKER: User quota (block hardlimit:10 MB) [ 504.313947] Lustre: DEBUG MARKER: Write... [ 507.187897] Lustre: DEBUG MARKER: Write out of block quota ... [ 555.058304] Lustre: DEBUG MARKER: -------------------------------------- [ 556.642800] Lustre: DEBUG MARKER: Group quota (block hardlimit:10 MB) [ 564.761412] Lustre: DEBUG MARKER: Write... [ 567.406936] Lustre: DEBUG MARKER: Write out of block quota ... [ 612.211803] Lustre: DEBUG MARKER: -------------------------------------- [ 613.784166] Lustre: DEBUG MARKER: Project quota (block hardlimit:10 mb) [ 616.194952] Lustre: DEBUG MARKER: Write... [ 618.836718] Lustre: DEBUG MARKER: Write out of block quota ... [ 686.563657] Lustre: DEBUG MARKER: == sanity-quota test 1b: Quota pools: Block hard limit (normal use and out of quota) ========================================================== 00:39:14 (1787373554) [ 704.025659] Lustre: DEBUG MARKER: User quota (block hardlimit:20 MB) [ 723.300416] Lustre: DEBUG MARKER: Write... [ 726.097439] Lustre: DEBUG MARKER: Write out of block quota ... [ 773.764427] Lustre: DEBUG MARKER: -------------------------------------- [ 775.297333] Lustre: DEBUG MARKER: Group quota (block hardlimit:20 MB) [ 781.813403] Lustre: DEBUG MARKER: Write... [ 784.241878] Lustre: DEBUG MARKER: Write out of block quota ... [ 835.667899] Lustre: DEBUG MARKER: -------------------------------------- [ 837.324747] Lustre: DEBUG MARKER: Project quota (block hardlimit:20 mb) [ 840.436818] Lustre: DEBUG MARKER: Write... [ 843.176265] Lustre: DEBUG MARKER: Write out of block quota ... [ 917.149944] Lustre: DEBUG MARKER: == sanity-quota test 1c: Quota pools: check 3 pools with hardlimit only for global ========================================================== 00:43:04 (1787373784) [ 933.520365] Lustre: DEBUG MARKER: User quota (block hardlimit:20 MB) [ 956.646929] Lustre: DEBUG MARKER: Write... [ 960.988157] Lustre: DEBUG MARKER: Write out of block quota ... [ 1054.228438] Lustre: DEBUG MARKER: == sanity-quota test 1d: Quota pools: check block hardlimit on different pools ========================================================== 00:45:21 (1787373921) [ 1072.008321] Lustre: DEBUG MARKER: User quota (block hardlimit:20 MB) [ 1094.755817] Lustre: DEBUG MARKER: Write... [ 1097.351789] Lustre: DEBUG MARKER: Write out of block quota ... [ 1186.587688] Lustre: DEBUG MARKER: == sanity-quota test 1e: Quota pools: global pool high block limit vs quota pool with small ========================================================== 00:47:34 (1787374054) [ 1204.677338] Lustre: DEBUG MARKER: User quota (block hardlimit:53000000 MB) [ 1218.965302] Lustre: DEBUG MARKER: Write... [ 1222.354963] Lustre: DEBUG MARKER: Write out of block quota ... [ 1235.529093] Lustre: DEBUG MARKER: Write... [ 1297.493321] Lustre: DEBUG MARKER: == sanity-quota test 1f: Quota pools: correct qunit after removing/adding OST ========================================================== 00:49:25 (1787374165) [ 1313.323638] Lustre: DEBUG MARKER: User quota (block hardlimit:200 MB) [ 1324.138565] Lustre: DEBUG MARKER: Write... [ 1326.465882] Lustre: DEBUG MARKER: Write out of block quota ... [ 1373.939954] Lustre: DEBUG MARKER: Write... [ 1375.885817] Lustre: DEBUG MARKER: Write out of block quota ... [ 1424.299469] Lustre: DEBUG MARKER: == sanity-quota test 1g: Quota pools: Block hard limit with wide striping ========================================================== 00:51:32 (1787374292) [ 1438.158854] Lustre: DEBUG MARKER: User quota (block hardlimit:40 MB) [ 1449.348517] Lustre: DEBUG MARKER: Write... [ 1459.101880] Lustre: DEBUG MARKER: Write out of block quota ... [ 1540.003914] Lustre: DEBUG MARKER: == sanity-quota test 1h: Block hard limit test using fallocate ========================================================== 00:53:28 (1787374408) [ 1541.626361] Lustre: DEBUG MARKER: SKIP: sanity-quota test_1h need >= 2.13.57 and ldiskfs for fallocate [ 1543.302640] Lustre: DEBUG MARKER: == sanity-quota test 1i: Quota pools: different limit and usage relations ========================================================== 00:53:31 (1787374411) [ 1558.553795] Lustre: DEBUG MARKER: User quota (block hardlimit:200 MB) [ 1570.471745] Lustre: DEBUG MARKER: Write... [ 1573.066412] Lustre: DEBUG MARKER: Write out of block quota ... [ 1611.748986] Lustre: DEBUG MARKER: Write... [ 1615.028729] Lustre: DEBUG MARKER: Write out of block quota ... [ 1625.889671] LustreError: 5830: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 [ 1669.840603] Lustre: DEBUG MARKER: == sanity-quota test 1j: Enable project quota enforcement for root ========================================================== 00:55:37 (1787374537) [ 1687.472322] Lustre: DEBUG MARKER: -------------------------------------- [ 1688.771904] Lustre: DEBUG MARKER: Project quota (hardlimit: 40 mb, 2048 files) [ 2035.778598] Lustre: DEBUG MARKER: == sanity-quota test 1k: LQA: Block hard limit (normal use and out of quota) ========================================================== 01:01:43 (1787374903) [ 2058.032533] Lustre: DEBUG MARKER: Write... [ 2061.761959] Lustre: DEBUG MARKER: Write out of block quota ... [ 2105.470137] Lustre: DEBUG MARKER: Write... [ 2108.513710] Lustre: DEBUG MARKER: Write out of block quota ... [ 2148.062568] Lustre: DEBUG MARKER: Write... [ 2153.088994] Lustre: DEBUG MARKER: Write out of block quota ... [ 2199.641742] Lustre: DEBUG MARKER: == sanity-quota test 1l: Async writes should not be rejected by quota with root_prj_enable ========================================================== 01:04:27 (1787375067) [ 2260.200069] Lustre: DEBUG MARKER: SKIP: sanity-quota test_2 skipping excluded test 2 [ 2261.753482] Lustre: DEBUG MARKER: == sanity-quota test 3a: Block soft limit (start timer, timer goes off, stop timer) ========================================================== 01:05:29 (1787375129) [ 2351.974111] Lustre: DEBUG MARKER: Write after timer goes off [ 2353.732341] Lustre: DEBUG MARKER: Write after cancel lru locks [ 2495.642638] Lustre: DEBUG MARKER: Write after timer goes off [ 2497.502667] Lustre: DEBUG MARKER: Write after cancel lru locks [ 2638.668714] Lustre: DEBUG MARKER: Write after timer goes off [ 2640.273377] Lustre: DEBUG MARKER: Write after cancel lru locks [ 2745.693604] Lustre: DEBUG MARKER: == sanity-quota test 3b: Quota pools: Block soft limit (start timer, expires, stop timer) ========================================================== 01:13:33 (1787375613) [ 2838.834049] Lustre: DEBUG MARKER: Write after timer goes off [ 2840.843614] Lustre: DEBUG MARKER: Write after cancel lru locks [ 2977.543771] Lustre: DEBUG MARKER: Write after timer goes off [ 2979.653977] Lustre: DEBUG MARKER: Write after cancel lru locks [ 3120.386620] Lustre: DEBUG MARKER: Write after timer goes off [ 3122.437557] Lustre: DEBUG MARKER: Write after cancel lru locks [ 3246.715357] Lustre: DEBUG MARKER: == sanity-quota test 3c: Quota pools: check block soft limit on different pools ========================================================== 01:21:54 (1787376114) [ 3354.351963] Lustre: DEBUG MARKER: Write after timer goes off [ 3356.876880] Lustre: DEBUG MARKER: Write after cancel lru locks [ 3468.659733] Lustre: DEBUG MARKER: SKIP: sanity-quota test_4a skipping excluded test 4a [ 3470.595614] Lustre: DEBUG MARKER: == sanity-quota test 4b: Grace time strings handling ===== 01:25:38 (1787376338) [ 3488.850141] Lustre: DEBUG MARKER: == sanity-quota test 5: Chown [ 3634.351120] Lustre: DEBUG MARKER: == sanity-quota test 6: Test dropping acquire request on master ========================================================== 01:28:21 (1787376501) [ 3692.003893] Lustre: *** cfs_fail_loc=513, val=601*** [ 3692.513643] Lustre: *** cfs_fail_loc=513, val=601*** [ 3692.515573] Lustre: Skipped 4 previous similar messages [ 3694.128830] Lustre: *** cfs_fail_loc=513, val=601*** [ 3695.002200] LustreError: 5834:0:(service.c:2341:ptlrpc_server_handle_req_in()) drop incoming rpc opc 601, x1874196430524160 [ 3696.608565] Lustre: *** cfs_fail_loc=513, val=601*** [ 3696.613542] Lustre: Skipped 16 previous similar messages [ 3701.727659] Lustre: *** cfs_fail_loc=513, val=601*** [ 3701.729733] Lustre: Skipped 10 previous similar messages [ 3710.431172] Lustre: 39473:0:(service.c:1612:ptlrpc_at_send_early_reply()) @@@ Could not add any time (5/5), not sending early reply req@ffff92703c449c00 x1874196418445568/t0(0) o4->da56c13d-15fb-473d-a613-5e4f4c502836@192.168.201.41@tcp:153/0 lens 488/448 e 1 to 0 dl 1787376583 ref 2 fl Interpret:/600/0 rc 0/0 job:'dd.60000' uid:60000 gid:60000 projid:0 [ 3711.455248] Lustre: 39314:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787376563/real 1787376563] req@ffff926f03fa9880 x1874196430524160/t0(0) o601->lustre-MDT0000-lwp-OST0000@0@lo:23/10 lens 336/336 e 0 to 1 dl 1787376579 ref 2 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'ll_ost_io00_007.0' uid:0 gid:0 projid:4294967295 [ 3711.486790] 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 [ 3711.504415] Lustre: *** cfs_fail_loc=513, val=601*** [ 3711.505791] Lustre: lustre-MDT0000: Client lustre-MDT0000-lwp-OST0000_UUID (at 0@lo) reconnecting [ 3711.511049] Lustre: Skipped 24 previous similar messages [ 3711.537835] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 3712.580285] LustreError: 5833:0:(service.c:2341:ptlrpc_server_handle_req_in()) drop incoming rpc opc 601, x1874196430528512 [ 3720.166423] LustreError: 14344:0:(service.c:2341:ptlrpc_server_handle_req_in()) drop incoming rpc opc 601, x1874196430529920 [ 3727.839204] Lustre: 39313:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787376580/real 1787376580] req@ffff926f0ed35880 x1874196430528512/t0(0) o601->lustre-MDT0000-lwp-OST0000@0@lo:23/10 lens 336/336 e 0 to 1 dl 1787376596 ref 2 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'ll_ost_io00_006.0' uid:0 gid:0 projid:4294967295 [ 3727.876480] 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 [ 3727.886471] Lustre: *** cfs_fail_loc=513, val=601*** [ 3727.888280] Lustre: Skipped 41 previous similar messages [ 3727.905660] Lustre: lustre-MDT0000: Client lustre-MDT0000-lwp-OST0000_UUID (at 0@lo) reconnecting [ 3727.928541] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 3729.990390] LustreError: 5834:0:(service.c:2341:ptlrpc_server_handle_req_in()) drop incoming rpc opc 601, x1874196430532864 [ 3729.997824] LustreError: 5834:0:(service.c:2341:ptlrpc_server_handle_req_in()) Skipped 2 previous similar messages [ 3736.031547] Lustre: 3308:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787376588/real 1787376588] req@ffff926f03fa9180 x1874196430529920/t0(0) o601->lustre-MDT0000-lwp-OST0001@0@lo:23/10 lens 336/336 e 0 to 1 dl 1787376604 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'lquota_wb_lustr.0' uid:0 gid:0 projid:4294967295 [ 3736.092114] 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 [ 3736.112585] Lustre: lustre-MDT0000: Client lustre-MDT0000-lwp-OST0001_UUID (at 0@lo) reconnecting [ 3736.119652] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 3746.271207] Lustre: 6681:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787376598/real 1787376598] req@ffff926f0727d180 x1874196430532864/t0(0) o601->lustre-MDT0000-lwp-OST0000@0@lo:23/10 lens 336/336 e 0 to 1 dl 1787376614 ref 2 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'ll_ost_io00_002.0' uid:0 gid:0 projid:4294967295 [ 3746.295429] Lustre: 6681:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 3746.317876] 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 [ 3746.333226] Lustre: lustre-MDT0000: Client lustre-MDT0000-lwp-OST0000_UUID (at 0@lo) reconnecting [ 3746.348324] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 3790.482495] Lustre: DEBUG MARKER: == sanity-quota test 7a: Quota reintegration (global index) ========================================================== 01:30:57 (1787376657) [ 3824.284828] Lustre: Failing over lustre-OST0000 [ 3824.609137] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 3824.622210] 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 [ 3824.639098] Lustre: lustre-OST0000: Not available for connect from 0@lo (stopping) [ 3826.571648] Lustre: server umount lustre-OST0000 complete [ 3832.380718] LustreError: 6675:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.201.41@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3832.397189] LustreError: 6675:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 3 previous similar messages [ 3833.313647] LustreError: 39207:0:(ldlm_lib.c:1190: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. [ 3837.478865] LustreError: 39562:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.201.41@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3840.269748] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [ 3840.303592] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 3841.553903] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 3842.316451] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 3842.319198] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 3847.663867] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3858.011984] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3864.937544] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3870.711850] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3877.397740] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3884.061734] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3889.698843] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3922.160431] Lustre: Failing over lustre-OST0000 [ 3922.257242] Lustre: server umount lustre-OST0000 complete [ 3922.409695] 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 [ 3922.426712] LustreError: 8442:0:(ldlm_lib.c:1190: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. [ 3922.442589] LustreError: 8442:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 1 previous similar message [ 3927.522190] LustreError: 6675:0:(ldlm_lib.c:1190: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. [ 3932.190889] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [ 3932.217569] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 3933.667031] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 3933.749631] Lustre: lustre-OST0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 3933.753584] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 3938.293663] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3946.030477] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3951.435797] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3957.290644] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3963.249912] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3968.297980] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3973.971452] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 4009.610677] Lustre: DEBUG MARKER: == sanity-quota test 7b: Quota reintegration (slave index) ========================================================== 01:34:37 (1787376877) [ 4046.441651] Lustre: *** cfs_fail_loc=a02, val=0*** [ 4053.025310] LustreError: 3307:0:(qsd_handler.c:298:qsd_req_completion()) $$$ DQACQ failed with -5, flags:0x8 qsd:lustre-OST0000 qtype:usr lqe: ffff927037b43200 id:60000 enforced:1 granted: 1026 pending:0 waiting:0 req:1 usage: 2052 qunit:0 qtune:0 edquot:0 default:no revoke:0 [ 4053.069693] Lustre: Failing over lustre-OST0000 [ 4053.176865] Lustre: server umount lustre-OST0000 complete [ 4055.012991] 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 [ 4055.026592] LustreError: 8442:0:(ldlm_lib.c:1190: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. [ 4060.827218] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [ 4060.848102] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 4062.698143] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4062.946302] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 4062.946330] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 4067.118382] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4074.992898] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 4079.662452] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 4084.294500] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 4089.364556] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 4094.059202] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 4099.094706] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 4149.172458] Lustre: DEBUG MARKER: == sanity-quota test 7c: Quota reintegration (restart mds during reintegration) ========================================================== 01:36:57 (1787377017) [ 4174.211765] LustreError: 91360:0:(qsd_reint.c:488:qsd_reint_main()) cfs_fail_timeout id a03 sleeping for 10000ms [ 4174.216906] LustreError: 91360:0:(qsd_reint.c:488:qsd_reint_main()) Skipped 3 previous similar messages [ 4175.929967] Lustre: Failing over lustre-MDT0000 [ 4176.240700] Lustre: server umount lustre-MDT0000 complete [ 4179.053325] LustreError: 91364:0:(qsd_reint.c:488:qsd_reint_main()) cfs_fail_timeout interrupted [ 4184.280579] LustreError: MGC192.168.201.141@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4184.850805] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4184.944701] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4185.682375] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4185.784857] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4185.823958] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:116 to 0x280000400:161) [ 4185.824132] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:145 to 0x240000400:161) [ 4189.120363] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4190.175864] 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 [ 4190.200678] Lustre: Skipped 1 previous similar message [ 4190.202307] LustreError: 3304:0:(ldlm_resource.c:1207:ldlm_resource_complain()) lustre-MDT0000-lwp-OST0000: namespace resource [0x200000006:0x20000:0x0].0x0 (ffff926f039e3800) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 4190.234356] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 4195.296379] Lustre: 3306:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787377047/real 1787377047] req@ffff926f07102300 x1874196430926720/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787377063 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4196.953515] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 4296.162844] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 4301.407153] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 4307.075851] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 4313.488894] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 4319.504691] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 4357.647513] Lustre: DEBUG MARKER: == sanity-quota test 7d: Quota reintegration (Transfer index in multiple bulks) ========================================================== 01:40:25 (1787377225) [ 4387.290588] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 4393.609440] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 4449.292132] Lustre: DEBUG MARKER: == sanity-quota test 7e: Quota reintegration (inode limits) ========================================================== 01:41:57 (1787377317) [ 4451.270318] Lustre: DEBUG MARKER: SKIP: sanity-quota test_7e needs >= 2 MDTs [ 4453.285250] Lustre: DEBUG MARKER: == sanity-quota test 7f: Quota reintegration automatically ========================================================== 01:42:01 (1787377321) [ 4473.165289] Lustre: *** cfs_fail_loc=a11, val=0*** [ 4479.701204] Lustre: *** cfs_fail_loc=a11, val=0*** [ 4531.186245] Lustre: *** cfs_fail_loc=a11, val=0*** [ 4684.776456] Lustre: DEBUG MARKER: == sanity-quota test 8: Run dbench with quota enabled ==== 01:45:52 (1787377552) [ 4892.806883] LustreError: 3307:0:(qsd_reint.c:633:qqi_reint_delayed()) lustre-OST0000: Delaying reintegration for qtype:0 until pending updates are flushed. [ 4897.134184] Lustre: DEBUG MARKER: SKIP: sanity-quota test_9 skipping SLOW test 9 [ 4899.430818] Lustre: DEBUG MARKER: == sanity-quota test 10: Test quota for root user ======== 01:49:27 (1787377767) [ 4961.174589] Lustre: DEBUG MARKER: == sanity-quota test 11: Chown/chgrp ignores quota ======= 01:50:28 (1787377828) [ 5018.697279] Lustre: DEBUG MARKER: SKIP: sanity-quota test_12a skipping SLOW test 12a [ 5020.876790] Lustre: DEBUG MARKER: == sanity-quota test 12b: Inode quota rebalancing ======== 01:51:28 (1787377888) [ 5022.818683] Lustre: DEBUG MARKER: SKIP: sanity-quota test_12b needs >= 2 MDTs [ 5024.683216] Lustre: DEBUG MARKER: == sanity-quota test 13: Cancel per-ID lock in the LRU list ========================================================== 01:51:32 (1787377892) [ 5093.777481] Lustre: DEBUG MARKER: == sanity-quota test 14: check panic in qmt_site_recalc_cb ========================================================== 01:52:41 (1787377961) [ 5123.084500] Lustre: Failing over lustre-OST0000 [ 5123.246915] Lustre: server umount lustre-OST0000 complete [ 5127.136940] 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 [ 5127.176525] LustreError: 39563:0:(ldlm_lib.c:1190: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. [ 5127.203185] LustreError: 39563:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 2 previous similar messages [ 5132.286218] LustreError: 39562:0:(ldlm_lib.c:1190: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. [ 5132.384148] LustreError: 39562:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 1 previous similar message [ 5137.386455] LustreError: 102181:0:(ldlm_lib.c:1190: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. [ 5137.418381] LustreError: 102181:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 1 previous similar message [ 5141.893191] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [ 5141.924916] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 5143.084286] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 5143.966176] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 5143.975442] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 5143.987183] Lustre: Skipped 1 previous similar message [ 5151.162708] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5199.143039] Lustre: DEBUG MARKER: == sanity-quota test 15: Set over 4T block quota ========= 01:54:26 (1787378066) [ 5231.828670] Lustre: DEBUG MARKER: == sanity-quota test 16a: lfs quota should skip the inactive MDT/OST ========================================================== 01:54:59 (1787378099) [ 5257.956374] Lustre: lustre-OST0000: Client da56c13d-15fb-473d-a613-5e4f4c502836 (at 192.168.201.41@tcp) reconnecting [ 5287.495428] Lustre: DEBUG MARKER: == sanity-quota test 16b: lfs quota should skip the nonexistent MDT/OST ========================================================== 01:55:54 (1787378154) [ 5289.298134] Lustre: DEBUG MARKER: SKIP: sanity-quota test_16b needs >= 3 MDTs [ 5291.098277] Lustre: DEBUG MARKER: == sanity-quota test 17: DQACQ return recoverable error == 01:55:59 (1787378159) [ 5320.831533] Lustre: *** cfs_fail_loc=a04, val=37*** [ 5320.835853] LustreError: 102152:0:(qsd_handler.c:298:qsd_req_completion()) $$$ DQACQ failed with -37, flags:0x1 qsd:lustre-OST0000 qtype:usr lqe: ffff927008de8600 id:60000 enforced:1 granted: 0 pending:0 waiting:1 req:1 usage: 0 qunit:0 qtune:0 edquot:0 default:no revoke:0 [ 5321.923098] Lustre: *** cfs_fail_loc=a04, val=37*** [ 5321.927821] LustreError: 6681:0:(qsd_handler.c:298:qsd_req_completion()) $$$ DQACQ failed with -37, flags:0x1 qsd:lustre-OST0000 qtype:usr lqe: ffff927008de8600 id:60000 enforced:1 granted: 0 pending:0 waiting:1024 req:1 usage: 0 qunit:0 qtune:0 edquot:0 default:no revoke:0 [ 5324.053636] Lustre: *** cfs_fail_loc=a04, val=37*** [ 5324.067175] LustreError: 39473:0:(qsd_handler.c:298:qsd_req_completion()) $$$ DQACQ failed with -37, flags:0x1 qsd:lustre-OST0000 qtype:usr lqe: ffff927008de8600 id:60000 enforced:1 granted: 0 pending:0 waiting:1024 req:1 usage: 0 qunit:0 qtune:0 edquot:0 default:no revoke:0 [ 5394.787871] Lustre: *** cfs_fail_loc=a04, val=11*** [ 5461.296863] Lustre: *** cfs_fail_loc=a04, val=110*** [ 5461.306039] Lustre: Skipped 1 previous similar message [ 5531.150493] Lustre: *** cfs_fail_loc=a04, val=107*** [ 5531.152576] Lustre: Skipped 1 previous similar message [ 5534.237406] 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 [ 5534.262889] Lustre: lustre-MDT0000: Client lustre-MDT0000-lwp-OST0001_UUID (at 0@lo) reconnecting [ 5534.287663] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 5640.761160] Lustre: DEBUG MARKER: == sanity-quota test 18: MDS failover while writing, no watchdog triggered (b14840) ========================================================== 02:01:49 (1787378509) [ 5657.451199] Lustre: DEBUG MARKER: User quota (limit: 200) [ 5664.485114] Lustre: DEBUG MARKER: Write 100M (buffered) ... [ 5668.640328] LustreError: 122116:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 5669.716400] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5671.942942] Lustre: DEBUG MARKER: Fail mds for 40 seconds [ 5674.849173] Lustre: Failing over lustre-MDT0000 [ 5675.408806] Lustre: server umount lustre-MDT0000 complete [ 5692.959194] Lustre: 3305:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787378545/real 1787378545] req@ffff927024114380 x1874196432027520/t0(0) o601->lustre-MDT0000-lwp-OST0000@0@lo:23/10 lens 336/336 e 0 to 1 dl 1787378561 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'lquota_wb_lustr.0' uid:0 gid:0 projid:4294967295 [ 5692.995795] Lustre: 3305:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 5693.017581] 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 [ 5693.032595] Lustre: Skipped 1 previous similar message [ 5695.141600] LustreError: MGC192.168.201.141@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5695.644553] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 5695.693670] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 5696.225769] Lustre: 3307:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787378548/real 1787378548] req@ffff926f4406e680 x1874196432027776/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787378564 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5698.595368] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 5698.607269] Lustre: Skipped 1 previous similar message [ 5700.488326] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5700.639225] Lustre: 3308:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787378553/real 1787378553] req@ffff927024116d80 x1874196432028288/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787378569 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5700.665994] Lustre: 3308:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 5702.182860] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 5702.295122] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 5702.362476] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:536 to 0x240000400:577) [ 5702.364419] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:533 to 0x280000400:577) [ 5705.759592] Lustre: 3305:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787378558/real 1787378558] req@ffff926f03457480 x1874196432028672/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787378574 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5705.785613] Lustre: 3305:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 5711.191692] Lustre: DEBUG MARKER: oleg141-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5713.053737] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5723.683876] Lustre: DEBUG MARKER: (dd_pid=115100, time=3, timeout=600) [ 5772.349657] Lustre: DEBUG MARKER: User quota (limit: 200) [ 5779.799347] Lustre: DEBUG MARKER: Write 100M (directio) ... [ 5783.125450] LustreError: 124975:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 5784.178953] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5786.109386] Lustre: DEBUG MARKER: Fail mds for 40 seconds [ 5788.394600] Lustre: Failing over lustre-MDT0000 [ 5788.796107] LustreError: lustre-MDT0000-lwp-OST0000: operation quota_acquire to node 0@lo failed: rc = -107 [ 5788.801268] 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 [ 5788.811775] Lustre: Skipped 1 previous similar message [ 5788.816189] LustreError: 122762:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: 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. [ 5788.832514] LustreError: 122762:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 1 previous similar message [ 5788.938830] Lustre: server umount lustre-MDT0000 complete [ 5805.988046] Lustre: 3305:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787378658/real 1787378658] req@ffff926f06b25180 x1874196432067072/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787378674 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5806.052383] Lustre: 3305:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 5806.079538] LustreError: MGC192.168.201.141@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5816.287918] LustreError: 3304:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff926f03df8000 x1874196432070144/t0(0) o250->MGC192.168.201.141@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 [ 5816.743391] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 5816.941373] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 5821.955458] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5825.009511] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 5825.018678] Lustre: Skipped 1 previous similar message [ 5826.186350] LustreError: 125636:0:(tgt_handler.c:534:tgt_filter_recovery_request()) @@@ not permitted during recovery req@ffff926f03df9180 x1874196432081152/t0(0) o601->lustre-MDT0000-lwp-OST0000_UUID@0@lo:10/0 lens 336/0 e 0 to 0 dl 1787378705 ref 1 fl Interpret:/200/ffffffff rc 0/-1 job:'qsd_reint_0.lus.0' uid:0 gid:0 projid:4294967295 [ 5826.202080] LustreError: lustre-MDT0000-lwp-OST0000: operation quota_acquire to node 0@lo failed: rc = -11 [ 5831.219416] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 5831.372414] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 5831.432717] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:579 to 0x240000400:609) [ 5831.433533] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:533 to 0x280000400:609) [ 5837.072229] Lustre: DEBUG MARKER: oleg141-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5838.685235] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5844.179342] Lustre: DEBUG MARKER: (dd_pid=117509, time=0, timeout=600) [ 5905.904090] Lustre: DEBUG MARKER: == sanity-quota test 19: Updating admin limits doesn't zero operational limits(b14790) ========================================================== 02:06:14 (1787378774) [ 5927.470259] Lustre: DEBUG MARKER: Files for user (quota_usr), count=1: [ 5929.606990] Lustre: DEBUG MARKER: Block quota isn't 0 (u:quota_usr:2). [ 5937.199468] Lustre: DEBUG MARKER: Files for user (quota_usr), count=1: [ 5938.834985] Lustre: DEBUG MARKER: Block quota isn't 0 (u:quota_usr:2). [ 5976.335993] Lustre: DEBUG MARKER: == sanity-quota test 20: Test if setquota specifiers work properly (b15754) ========================================================== 02:07:24 (1787378844) [ 6001.624124] Lustre: DEBUG MARKER: == sanity-quota test 21: Setquota while writing [ 6017.931500] Lustre: DEBUG MARKER: Set limit(block:10G; file:1000000) for user: quota_usr [ 6019.578255] Lustre: DEBUG MARKER: Set limit(block:10G; file:1000000) for group: quota_usr [ 6021.304962] Lustre: DEBUG MARKER: Set limit(block:10G; file:) for project: 1000 [ 6023.458942] Lustre: DEBUG MARKER: Set quota for 1 times [ 6027.236708] Lustre: DEBUG MARKER: Set quota for 2 times [ 6031.318531] Lustre: DEBUG MARKER: Set quota for 3 times [ 6035.515818] Lustre: DEBUG MARKER: Set quota for 4 times [ 6039.979451] Lustre: DEBUG MARKER: Set quota for 5 times [ 6044.484847] Lustre: DEBUG MARKER: Set quota for 6 times [ 6048.847396] Lustre: DEBUG MARKER: Set quota for 7 times [ 6052.680717] Lustre: DEBUG MARKER: Set quota for 8 times [ 6104.666352] Lustre: DEBUG MARKER: == sanity-quota test 22: enable/disable quota by 'lctl conf_param/set_param -P' ========================================================== 02:09:32 (1787378972) [ 6117.864022] 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 [ 6117.866947] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 6117.881052] Lustre: Skipped 2 previous similar messages [ 6117.904224] Lustre: Skipped 1 previous similar message [ 6119.106463] Lustre: server umount lustre-MDT0000 complete [ 6122.931485] LustreError: 14275:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787378991 with bad export cookie 16509150702436224578 [ 6122.947758] LustreError: MGC192.168.201.141@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 6123.025431] Lustre: server umount lustre-OST0000 complete [ 6126.404719] Lustre: server umount lustre-OST0001 complete [ 6140.749591] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing load_modules_local [ 6149.949410] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 6154.521508] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6157.683054] Lustre: 134748:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 6163.834419] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 6169.633856] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6175.080761] LustreError: 135110:0:(ldlm_lib.c:1190: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. [ 6175.149209] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:612 to 0x240000400:641) [ 6177.732822] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 6182.914879] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:611 to 0x280000400:641) [ 6184.568993] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6191.964625] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 6196.016320] Lustre: 136667:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 6213.601624] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 6213.610275] Lustre: Skipped 1 previous similar message [ 6213.817080] Lustre: server umount lustre-MDT0000 complete [ 6219.156739] LustreError: 134292:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787379087 with bad export cookie 16509150702436231648 [ 6219.166451] LustreError: MGC192.168.201.141@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 6219.172489] LustreError: 134292:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 6219.366405] Lustre: server umount lustre-OST0000 complete [ 6223.964481] Lustre: server umount lustre-OST0001 complete [ 6240.552484] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing load_modules_local [ 6250.029376] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 6254.261855] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6257.073507] Lustre: 139322:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 6270.591544] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6274.978393] LustreError: 139687:0:(ldlm_lib.c:1190: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. [ 6275.015044] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:612 to 0x240000400:673) [ 6279.221031] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 6279.225216] Lustre: Skipped 1 previous similar message [ 6284.317927] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:611 to 0x280000400:673) [ 6286.796929] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6295.641799] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 6300.325371] Lustre: 141212:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 6313.204954] Lustre: DEBUG MARKER: == sanity-quota test 23: Quota should be honored with directIO (b16125) ========================================================== 02:13:00 (1787379180) [ 6315.867659] Lustre: DEBUG MARKER: SKIP: sanity-quota test_23 Overwrite in place is not guaranteed to be space neutral on ZFS [ 6318.146678] Lustre: DEBUG MARKER: == sanity-quota test 24: lfs draws an asterix when limit is reached (b16646) ========================================================== 02:13:05 (1787379185) [ 6377.759873] Lustre: DEBUG MARKER: == sanity-quota test 25: check indexes versions ========== 02:14:05 (1787379245) [ 6430.045693] Lustre: DEBUG MARKER: Write... [ 6432.930645] Lustre: DEBUG MARKER: Write out of block quota ... [ 6496.350557] Lustre: DEBUG MARKER: == sanity-quota test 27a: lfs quota/setquota should handle wrong arguments (b19612) ========================================================== 02:16:04 (1787379364) [ 6503.136755] Lustre: DEBUG MARKER: == sanity-quota test 27b: lfs quota/setquota should handle user/group/project ID (b20200) ========================================================== 02:16:11 (1787379371) [ 6514.802652] Lustre: DEBUG MARKER: == sanity-quota test 27c: lfs quota should support human-readable output ========================================================== 02:16:22 (1787379382) [ 6527.155983] Lustre: DEBUG MARKER: == sanity-quota test 27d: lfs setquota should support fraction block limit ========================================================== 02:16:34 (1787379394) [ 6536.759803] Lustre: DEBUG MARKER: == sanity-quota test 30: Hard limit updates should not reset grace times ========================================================== 02:16:44 (1787379404) [ 6602.980092] Lustre: DEBUG MARKER: == sanity-quota test 33: Basic usage tracking for user [ 6769.597544] Lustre: DEBUG MARKER: == sanity-quota test 34: Usage transfer for user [ 6975.102545] Lustre: DEBUG MARKER: == sanity-quota test 35: Usage is still accessible across reboot ========================================================== 02:24:02 (1787379842) [ 7046.459334] Lustre: DEBUG MARKER: Restart... [ 7052.258252] 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 [ 7052.264986] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 7052.289995] Lustre: Skipped 3 previous similar messages [ 7052.313836] Lustre: Skipped 1 previous similar message [ 7053.448544] Lustre: server umount lustre-MDT0000 complete [ 7058.069651] LustreError: 138875:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787379926 with bad export cookie 16509150702436233181 [ 7058.071469] LustreError: MGC192.168.201.141@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 7058.080462] LustreError: 138875:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 7058.235860] Lustre: server umount lustre-OST0000 complete [ 7062.629421] Lustre: server umount lustre-OST0001 complete [ 7081.309434] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing load_modules_local [ 7094.636717] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 7100.447851] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7103.848084] Lustre: 159825:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 7112.448318] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 7119.595802] LustreError: 160202:0:(ldlm_lib.c:1190: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. [ 7119.640748] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:682 to 0x240000400:705) [ 7121.527565] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7124.965517] LustreError: 160203:0:(ldlm_lib.c:1190: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. [ 7130.082173] LustreError: 160202:0:(ldlm_lib.c:1190: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. [ 7132.798941] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 7137.804422] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:682 to 0x280000400:705) [ 7141.044309] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7149.870924] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 7154.074902] Lustre: 161760:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 7229.679646] Lustre: DEBUG MARKER: == sanity-quota test 37: Quota accounted properly for file created by 'lfs setstripe' ========================================================== 02:28:17 (1787380097) [ 7308.954903] Lustre: DEBUG MARKER: == sanity-quota test 38: Quota accounting iterator doesn't skip id entries ========================================================== 02:29:36 (1787380176) [ 9144.385921] Lustre: DEBUG MARKER: == sanity-quota test 39: Project ID interface works correctly ========================================================== 03:00:12 (1787382012) [ 9158.297656] Lustre: server umount lustre-MDT0000 complete [ 9162.404356] LustreError: 159380:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787382030 with bad export cookie 16509150702436239677 [ 9162.428475] LustreError: MGC192.168.201.141@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 9172.043408] Lustre: server umount lustre-OST0000 complete [ 9176.031176] Lustre: 3306:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787382028/real 1787382028] req@ffff926f42ba1c00 x1874196435472128/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787382044 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 9176.033115] 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 [ 9176.054430] Lustre: 3306:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 5 previous similar messages [ 9176.644466] Lustre: server umount lustre-OST0001 complete [ 9191.894258] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing load_modules_local [ 9202.859782] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 9207.589506] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 9210.127466] Lustre: 170031:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 9215.994973] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 9221.543576] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 9228.211196] LustreError: 170401:0:(ldlm_lib.c:1190: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. [ 9228.269244] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5708 to 0x240000400:5729) [ 9230.599520] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 9235.974085] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5706 to 0x280000400:5729) [ 9236.633955] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 9244.317929] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 9247.460763] Lustre: 171956:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 9283.870788] Lustre: DEBUG MARKER: == sanity-quota test 40a: Hard link across different project ID ========================================================== 03:02:32 (1787382152) [ 9329.263385] Lustre: DEBUG MARKER: == sanity-quota test 40b: Mv across different project ID ========================================================== 03:03:17 (1787382197) [ 9374.158645] Lustre: DEBUG MARKER: == sanity-quota test 40c: Remote child Dir inherit project quota properly ========================================================== 03:04:02 (1787382242) [ 9375.796865] Lustre: DEBUG MARKER: SKIP: sanity-quota test_40c needs >= 2 MDTs [ 9378.069120] Lustre: DEBUG MARKER: == sanity-quota test 40d: Stripe Directory inherit project quota properly ========================================================== 03:04:05 (1787382245) [ 9379.787739] Lustre: DEBUG MARKER: SKIP: sanity-quota test_40d needs >= 2 MDTs [ 9381.741347] Lustre: DEBUG MARKER: == sanity-quota test 41: df should return projid-specific values ========================================================== 03:04:09 (1787382249) [ 9472.695948] Lustre: DEBUG MARKER: == sanity-quota test 42: lfs quota should include default quota info ========================================================== 03:05:40 (1787382340) [ 9522.319260] Lustre: DEBUG MARKER: == sanity-quota test 48: lfs quota --delete should delete quota project ID ========================================================== 03:06:30 (1787382390) [ 9608.262390] Lustre: DEBUG MARKER: == sanity-quota test 49a: lfs quota -a prints the quota usage for all quota IDs ========================================================== 03:07:56 (1787382476) [ 9619.338045] Lustre: *** cfs_fail_loc=a09, val=0*** [ 9619.339456] Lustre: Skipped 4 previous similar messages [ 9621.368824] Lustre: *** cfs_fail_loc=a09, val=0*** [ 9621.370501] Lustre: Skipped 111 previous similar messages [ 9625.373373] Lustre: *** cfs_fail_loc=a09, val=0*** [ 9625.378697] Lustre: Skipped 212 previous similar messages [ 9633.399875] Lustre: *** cfs_fail_loc=a09, val=0*** [ 9633.404282] Lustre: Skipped 446 previous similar messages [ 9649.405796] Lustre: *** cfs_fail_loc=a09, val=0*** [ 9649.408023] Lustre: Skipped 785 previous similar messages [ 9681.445128] Lustre: *** cfs_fail_loc=a09, val=0*** [ 9681.449201] Lustre: Skipped 1601 previous similar messages [ 9745.446563] Lustre: *** cfs_fail_loc=a09, val=0*** [ 9745.451572] Lustre: Skipped 2944 previous similar messages [10154.788651] Lustre: *** cfs_fail_loc=a08, val=0*** [10154.790184] Lustre: Skipped 1894 previous similar messages [10154.800897] Lustre: *** cfs_fail_loc=a08, val=0*** [10154.802365] Lustre: Skipped 1 previous similar message [10336.754694] 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 [10336.767774] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [10336.776656] Lustre: Skipped 1 previous similar message [10340.765835] Lustre: server umount lustre-MDT0000 complete [10345.659593] LustreError: 169586:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787383214 with bad export cookie 16509150702438019294 [10345.668193] LustreError: MGC192.168.201.141@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [10346.095939] Lustre: server umount lustre-OST0000 complete [10351.534372] Lustre: server umount lustre-OST0001 complete [10358.703920] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing set_hostid [10366.550659] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing load_modules_local [10376.454988] vdc: vdc1 vdc9 [10376.501768] vdc: vdc1 vdc9 [10376.528250] vdc: vdc1 vdc9 [10386.448788] vde: vde1 vde9 [10397.229988] vdf: vdf1 vdf9 [10413.976436] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing load_modules_local [10422.250408] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [10422.519375] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [10422.602609] Lustre: lustre-MDT0000: new disk, initializing [10422.993391] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [10423.071698] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [10427.423493] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [10432.649225] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [10440.459202] Lustre: lustre-OST0000: new disk, initializing [10440.461682] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [10440.466400] Lustre: Skipped 1 previous similar message [10440.557788] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [10442.334546] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:0:ost [10442.343609] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:0:ost] [10442.641088] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x240000400 [10448.977596] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [10459.524982] Lustre: lustre-OST0001: new disk, initializing [10459.531114] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [10459.636126] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [10461.667239] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:1:ost [10461.685404] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:1:ost] [10461.966121] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x280000400 [10465.620430] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [10474.988402] Lustre: DEBUG MARKER: Using TIMEOUT=20 [10478.924170] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [10516.512385] Lustre: DEBUG MARKER: == sanity-quota test 49b: lfs quota -a --blocks has a delimiter ========================================================== 03:23:04 (1787383384) [10523.170045] Lustre: DEBUG MARKER: == sanity-quota test 50: Test if lfs find --projid works ========================================================== 03:23:11 (1787383391) [10572.642114] Lustre: DEBUG MARKER: == sanity-quota test 51: Test project accounting with mv/cp ========================================================== 03:24:00 (1787383440) [10636.572796] Lustre: DEBUG MARKER: == sanity-quota test 52: Rename normal file across project ID ========================================================== 03:25:04 (1787383504) [10671.088367] Lustre: DEBUG MARKER: rename directory return 255 [10720.650384] Lustre: DEBUG MARKER: == sanity-quota test 53: Project inherit attribute could be cleared ========================================================== 03:26:28 (1787383588) [10754.838776] Lustre: DEBUG MARKER: == sanity-quota test 54: basic lfs project interface test ========================================================== 03:27:02 (1787383622) [10800.428678] Lustre: DEBUG MARKER: == sanity-quota test 55: Chgrp should be affected by group quota ========================================================== 03:27:48 (1787383668) [10982.417726] Lustre: DEBUG MARKER: == sanity-quota test 56: lfs quota -t should work well === 03:30:50 (1787383850) [11023.174771] Lustre: DEBUG MARKER: == sanity-quota test 57: lfs project could tolerate errors ========================================================== 03:31:30 (1787383890) [11073.904092] Lustre: DEBUG MARKER: == sanity-quota test 58: project ID should be kept for new mirrors created by FID ========================================================== 03:32:21 (1787383941) [11253.513296] Lustre: DEBUG MARKER: == sanity-quota test 59: lfs project dosen't crash kernel with project disabled ========================================================== 03:35:21 (1787384121) [11255.104922] Lustre: DEBUG MARKER: SKIP: sanity-quota test_59 ldiskfs only test [11256.853748] Lustre: DEBUG MARKER: == sanity-quota test 60: Test quota for root with setgid ========================================================== 03:35:24 (1787384124) [11319.338267] Lustre: DEBUG MARKER: SKIP: sanity-quota test_61 skipping SLOW test 61 [11321.190886] Lustre: DEBUG MARKER: == sanity-quota test 62: Project inherit should be only changed by root ========================================================== 03:36:29 (1787384189) [11357.213397] Lustre: DEBUG MARKER: SKIP: sanity-quota test_63 skipping excluded test 63 [11359.101820] Lustre: DEBUG MARKER: == sanity-quota test 64: lfs project on non-dir/files should succeed ========================================================== 03:37:07 (1787384227) [11415.862891] Lustre: DEBUG MARKER: SKIP: sanity-quota test_65 skipping excluded test 65 [11417.523839] Lustre: DEBUG MARKER: == sanity-quota test 66: nonroot user can not change project state in default ========================================================== 03:38:05 (1787384285) [11468.127754] Lustre: DEBUG MARKER: == sanity-quota test 67: quota pools recalculation ======= 03:38:55 (1787384335) [11470.135095] Lustre: DEBUG MARKER: SKIP: sanity-quota test_67 ZFS grants some block space together with inode [11472.153568] Lustre: DEBUG MARKER: == sanity-quota test 68: slave number in quota pool changed after each add/remove OST ========================================================== 03:38:59 (1787384339) [11501.187277] LustreError: 210054:0:(mgs_handler.c:1144:mgs_iocontrol_pool()) OBD_IOC_POOL err -17, cmd CE021 for pool lustre.qpool1 [11549.952576] Lustre: DEBUG MARKER: == sanity-quota test 69: EDQUOT at one of pools shouldn't affect DOM ========================================================== 03:40:17 (1787384417) [11576.989277] Lustre: DEBUG MARKER: User quota (block hardlimit:200 MB) [11579.280517] Lustre: DEBUG MARKER: User quota (block hardlimit:10 MB) [11770.981101] Lustre: DEBUG MARKER: == sanity-quota test 70a: check lfs setquota/quota with a pool option ========================================================== 03:43:58 (1787384638) [11824.507583] Lustre: DEBUG MARKER: == sanity-quota test 70b: lfs setquota pool works properly ========================================================== 03:44:52 (1787384692) [11861.768724] Lustre: DEBUG MARKER: == sanity-quota test 71a: Check PFL with quota pools ===== 03:45:29 (1787384729) [11863.440918] Lustre: DEBUG MARKER: SKIP: sanity-quota test_71a ZFS grants some block space together with inode [11865.738270] Lustre: DEBUG MARKER: == sanity-quota test 71b: Check SEL with quota pools ===== 03:45:33 (1787384733) [11867.753285] Lustre: DEBUG MARKER: SKIP: sanity-quota test_71b ZFS grants some block space together with inode [11869.799298] Lustre: DEBUG MARKER: == sanity-quota test 72: lfs quota --pool prints only pool's OSTs ========================================================== 03:45:37 (1787384737) [11889.562744] Lustre: DEBUG MARKER: User quota (block hardlimit:50 MB) [11909.075467] Lustre: DEBUG MARKER: Write... [11912.125675] Lustre: DEBUG MARKER: Write out of block quota ... [11975.701486] Lustre: DEBUG MARKER: == sanity-quota test 73a: default limits at OST Pool Quotas ========================================================== 03:47:23 (1787384843) [12006.256259] Lustre: DEBUG MARKER: set to use default quota [12008.117414] Lustre: DEBUG MARKER: set default quota [12010.230350] Lustre: DEBUG MARKER: get default quota [12017.140949] Lustre: DEBUG MARKER: Test not out of quota [12021.721926] Lustre: DEBUG MARKER: Test out of quota [12034.742376] Lustre: DEBUG MARKER: Increase default quota [12065.088379] Lustre: DEBUG MARKER: Set quota to override default quota [12065.168820] LustreError: 189577: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:1787989733 qunit: 1024 edquot:0 may_rel:0 revoke:0 default:no [12079.030360] Lustre: DEBUG MARKER: Set to use default quota again [12101.981428] Lustre: DEBUG MARKER: Cleanup [12174.240726] Lustre: DEBUG MARKER: == sanity-quota test 73b: default OST Pool Quotas limit for new user ========================================================== 03:50:42 (1787385042) [12200.805281] Lustre: DEBUG MARKER: set default quota for qpool1 [12202.763979] Lustre: DEBUG MARKER: Write from user that hasn't lqe [12255.986188] Lustre: DEBUG MARKER: == sanity-quota test 74: check quota pools per user ====== 03:52:03 (1787385123) [12342.565176] Lustre: DEBUG MARKER: == sanity-quota test 75: nodemap squashed root respects quota enforcement ========================================================== 03:53:30 (1787385210) [12416.773957] Lustre: DEBUG MARKER: Write... [12420.292984] Lustre: DEBUG MARKER: Write out of block quota ... [12549.013365] Lustre: DEBUG MARKER: == sanity-quota test 76: project ID 4294967295 should be not allowed ========================================================== 03:56:56 (1787385416) [12593.992842] Lustre: DEBUG MARKER: == sanity-quota test 77: lfs setquota should fail in Lustre mount with 'ro' ========================================================== 03:57:41 (1787385461) [12601.435361] Lustre: DEBUG MARKER: == sanity-quota test 78A: Check fallocate increase quota usage ========================================================== 03:57:49 (1787385469) [12602.965935] Lustre: DEBUG MARKER: SKIP: sanity-quota test_78A need >= 2.13.57 and ldiskfs for fallocate [12604.553662] Lustre: DEBUG MARKER: == sanity-quota test 78a: Check fallocate increase projectid usage ========================================================== 03:57:52 (1787385472) [12606.292741] Lustre: DEBUG MARKER: SKIP: sanity-quota test_78a need >= 2.13.57 and ldiskfs for fallocate [12608.155889] Lustre: DEBUG MARKER: == sanity-quota test 79: access to non-existed dt-pool/info doesn't cause a panic ========================================================== 03:57:56 (1787385476) [12629.347529] Lustre: DEBUG MARKER: == sanity-quota test 80: check for EDQUOT after OST failover ========================================================== 03:58:17 (1787385497) [12631.365506] Lustre: DEBUG MARKER: SKIP: sanity-quota test_80 ZFS grants some block space together with inode [12633.531750] Lustre: DEBUG MARKER: == sanity-quota test 81: Race qmt_start_pool_recalc with qmt_pool_free ========================================================== 03:58:21 (1787385501) [12650.529625] Lustre: DEBUG MARKER: User quota (block hardlimit:20 MB) [12658.284099] LustreError: 235124:0:(qmt_pool.c:1407:qmt_pool_recalc()) cfs_fail_timeout id a07 sleeping for 10000ms [12661.310658] Lustre: lustre-MDT0000: Not available for connect from 192.168.201.41@tcp (stopping) [12663.280088] 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 [12663.294984] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [12663.322594] Lustre: Skipped 2 previous similar messages [12663.338927] Lustre: Skipped 1 previous similar message [12666.408550] Lustre: lustre-MDT0000: Not available for connect from 192.168.201.41@tcp (stopping) [12668.375115] LustreError: 235124:0:(qmt_pool.c:1407:qmt_pool_recalc()) cfs_fail_timeout id a07 awake [12668.581798] Lustre: server umount lustre-MDT0000 complete [12677.476788] LustreError: MGC192.168.201.141@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [12678.062944] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [12678.187192] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:27 to 0x280000400:65) [12678.187779] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:27 to 0x240000400:65) [12682.316546] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [12693.356084] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [12693.369438] Lustre: Skipped 1 previous similar message [12723.838793] Lustre: DEBUG MARKER: == sanity-quota test 82: verify more than 8 qids for single operation ========================================================== 03:59:51 (1787385591) [12760.004453] Lustre: DEBUG MARKER: == sanity-quota test 83: Setting default quota shouldn't affect grace time ========================================================== 04:00:27 (1787385627) [12796.186949] Lustre: DEBUG MARKER: == sanity-quota test 84: Reset quota should fix the insane granted quota ========================================================== 04:01:04 (1787385664) [12851.363471] LustreError: 188603:0:(qsd_reint.c:633:qqi_reint_delayed()) lustre-OST0001: Delaying reintegration for qtype:0 until pending updates are flushed. [12851.366926] Lustre: *** cfs_fail_loc=a08, val=0*** [12851.376870] LustreError: 188603:0:(qsd_reint.c:633:qqi_reint_delayed()) Skipped 2 previous similar messages [12851.379327] Lustre: Skipped 11 previous similar messages [12851.381698] Lustre: *** cfs_fail_loc=a08, val=0*** [12851.381706] Lustre: Skipped 15 previous similar messages [12975.583865] Lustre: DEBUG MARKER: == sanity-quota test 85: do not hung at write with the least_qunit ========================================================== 04:04:03 (1787385843) [13063.441558] Lustre: DEBUG MARKER: == sanity-quota test 86: Pre-acquired quota should be released if quota is over limit ========================================================== 04:05:31 (1787385931) [13146.263139] LustreError: 235710: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:1787990814 qunit: 1024 edquot:0 may_rel:0 revoke:0 default:no [13328.121755] LustreError: 244327: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:1787990996 qunit: 1024 edquot:0 may_rel:0 revoke:0 default:no [13501.307295] LustreError: 235710: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:1787991169 qunit: 1024 edquot:0 may_rel:0 revoke:0 default:no [13643.361179] Lustre: DEBUG MARKER: == sanity-quota test 87: lfs quota -a should print default quota setting ========================================================== 04:15:10 (1787386510) [13656.738755] Lustre: *** cfs_fail_loc=a09, val=0*** [13660.738290] Lustre: *** cfs_fail_loc=a09, val=0*** [13660.740034] Lustre: Skipped 183 previous similar messages [13668.811521] Lustre: *** cfs_fail_loc=a09, val=0*** [13668.819303] Lustre: Skipped 253 previous similar messages [13756.384500] 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 [13756.385609] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [13756.396605] Lustre: Skipped 1 previous similar message [13756.409731] Lustre: Skipped 3 previous similar messages [13756.995222] Lustre: lustre-MDT0000: Not available for connect from 192.168.201.41@tcp (stopping) [13761.514937] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [13761.525664] Lustre: Skipped 1 previous similar message [13761.769057] Lustre: server umount lustre-MDT0000 complete [13769.956740] LustreError: MGC192.168.201.141@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [13770.501060] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [13770.745716] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:67 to 0x240000400:97) [13770.753614] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:67 to 0x280000400:97) [13777.175155] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [13786.811537] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [13786.828278] Lustre: Skipped 1 previous similar message [13804.401668] Lustre: DEBUG MARKER: == sanity-quota test 88: Writing over quota should not hang ========================================================== 04:17:52 (1787386672) [13806.243504] Lustre: DEBUG MARKER: SKIP: sanity-quota test_88 require client with >4k pages [13808.295983] Lustre: DEBUG MARKER: == sanity-quota test 89: Show default quota with squash_uid ========================================================== 04:17:56 (1787386676) [13837.471391] Lustre: DEBUG MARKER: == sanity-quota test 90a: lfs quota should work without mount point ========================================================== 04:18:24 (1787386704) [13862.030051] Lustre: DEBUG MARKER: == sanity-quota test 90b: lfs quota should work with multiple mount points ========================================================== 04:18:49 (1787386729) [13891.221928] Lustre: DEBUG MARKER: == sanity-quota test 91: new quota index files in quota_master ========================================================== 04:19:18 (1787386758) [13909.985075] 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 [13909.991964] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [13909.994444] Lustre: Skipped 1 previous similar message [13913.441434] Lustre: server umount lustre-MDT0000 complete [13917.916645] LustreError: 210421:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787386786 with bad export cookie 16509150702439521998 [13917.946572] LustreError: MGC192.168.201.141@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [13917.951076] LustreError: 210421:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [13920.069900] Lustre: server umount lustre-OST0000 complete [13931.153924] Lustre: server umount lustre-OST0001 complete [13939.271486] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing set_hostid [13948.480321] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing load_modules_local [13958.990459] vdc: vdc1 vdc9 [13969.048610] vde: vde1 vde9 [13981.713126] vdf: vdf1 vdf9 [13993.347230] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [13993.615830] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [13993.685644] Lustre: lustre-MDT0000: new disk, initializing [13994.048507] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [13994.111757] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [13999.861307] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [14012.504725] Lustre: DEBUG MARKER: oleg141-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [14020.776514] Lustre: lustre-OST0000: new disk, initializing [14020.781771] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [14020.789143] Lustre: Skipped 1 previous similar message [14020.892994] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [14022.943659] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:0:ost [14022.961980] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:0:ost] [14023.075121] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x240000400 [14028.478162] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [14038.935411] Lustre: DEBUG MARKER: oleg141-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [14046.551961] Lustre: lustre-OST0001: new disk, initializing [14046.565673] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [14046.906667] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [14047.874767] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:1:ost [14047.892330] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:1:ost] [14048.312225] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x280000400 [14056.430224] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [14070.132605] Lustre: DEBUG MARKER: oleg141-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0001-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [14086.241368] Lustre: lustre-MDT0000: Not available for connect from 192.168.201.41@tcp (stopping) [14086.991624] Lustre: server umount lustre-MDT0000 complete [14101.250848] LustreError: MGC192.168.201.141@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [14101.649175] 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 [14101.664460] Lustre: Skipped 1 previous similar message [14101.817612] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [14104.736507] Lustre: 3305:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787386957/real 1787386957] req@ffff927005244e00 x1874196442204416/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787386973 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [14106.937948] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [14107.118736] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [14107.128533] Lustre: Skipped 1 previous similar message [14110.176261] Lustre: 3306:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787386962/real 1787386962] req@ffff927037b69880 x1874196442204800/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787386978 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [14110.204857] Lustre: 3306:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [14115.247916] Lustre: DEBUG MARKER: oleg141-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [14115.299110] Lustre: 3308:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787386967/real 1787386967] req@ffff926f4324d180 x1874196442205056/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787386983 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [14117.487245] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [14132.693559] Lustre: server umount lustre-MDT0000 complete [14138.433481] LustreError: 255543:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787387006 with bad export cookie 16509150702439524448 [14138.453746] LustreError: MGC192.168.201.141@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [14148.211834] Lustre: server umount lustre-OST0000 complete [14148.640120] Lustre: 3306:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787387001/real 1787387001] req@ffff926f4324f480 x1874196442221568/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787387017 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [14148.662936] Lustre: 3306:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 1 previous similar message [14148.669983] 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 [14148.677802] Lustre: Skipped 1 previous similar message [14152.653268] LustreError: 3308:0:(qsd_handler.c:298:qsd_req_completion()) $$$ DQACQ failed with -5, flags:0x8 qsd:lustre-OST0001 qtype:usr lqe: ffff926f4a6a6d80 id:0 enforced:0 granted: 0 pending:0 waiting:0 req:1 usage: 2289 qunit:0 qtune:0 edquot:0 default:no revoke:0 [14152.903840] Lustre: server umount lustre-OST0001 complete [14170.495250] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing set_hostid [14180.342347] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing load_modules_local [14192.539315] vdc: vdc1 vdc9 [14192.569626] vdc: vdc1 vdc9 [14206.360892] vde: vde1 vde9 [14217.805749] vdf: vdf1 vdf9 [14237.148456] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing load_modules_local [14247.220908] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [14247.490883] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [14247.599471] Lustre: lustre-MDT0000: new disk, initializing [14247.943784] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [14247.998331] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [14253.425244] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [14258.878976] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [14265.019735] Lustre: lustre-OST0000: new disk, initializing [14265.025084] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [14265.031648] Lustre: Skipped 1 previous similar message [14265.169281] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [14266.281194] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:0:ost [14266.299338] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:0:ost] [14266.409038] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x240000400 [14272.592621] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [14283.297774] Lustre: lustre-OST0001: new disk, initializing [14283.303190] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [14285.345174] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:1:ost [14285.360523] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:1:ost] [14285.637970] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x280000400 [14291.178755] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [14303.190704] Lustre: DEBUG MARKER: Using TIMEOUT=20 [14308.021261] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [14317.678887] Lustre: DEBUG MARKER: == sanity-quota test 92: Cannot set inode limit with Quota Pools ========================================================== 04:26:25 (1787387185) [14334.385346] Lustre: DEBUG MARKER: == sanity-quota test 93: update projid while client write to OST ========================================================== 04:26:42 (1787387202) [14363.091938] Lustre: *** cfs_fail_loc=170c, val=0*** [14428.411546] Lustre: DEBUG MARKER: == sanity-quota test 94: lfs quota all respects nodemap offset ========================================================== 04:28:16 (1787387296) [14475.362450] Lustre: lustre-MDT0000: Not available for connect from 192.168.201.41@tcp (stopping) [14477.795419] 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 [14480.699570] Lustre: server umount lustre-MDT0000 complete [14490.239375] LustreError: MGC192.168.201.141@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [14490.959816] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [14490.966826] Lustre: Skipped 1 previous similar message [14491.048797] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3 to 0x240000400:33) [14495.893311] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [14498.274995] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [14498.281282] Lustre: Skipped 1 previous similar message [14511.193024] Lustre: lustre-MDT0000: Not available for connect from 192.168.201.41@tcp (stopping) [14511.228423] Lustre: Skipped 3 previous similar messages [14513.634819] 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 [14513.657617] Lustre: Skipped 2 previous similar messages [14517.822779] Lustre: server umount lustre-MDT0000 complete [14528.895377] LustreError: MGC192.168.201.141@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [14530.107118] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3 to 0x240000400:65) [14533.800792] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [14533.817966] Lustre: Skipped 1 previous similar message [14536.700533] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [14548.321298] Lustre: DEBUG MARKER: == sanity-quota test 95a: Correct limits for squashed root ========================================================== 04:30:15 (1787387415) [14584.367174] Lustre: DEBUG MARKER: == sanity-quota test 95b: df respects squashed project id ========================================================== 04:30:51 (1787387451) [14635.390228] Lustre: DEBUG MARKER: == sanity-quota test 96: quota grant should be released when big files are deleted ========================================================== 04:31:43 (1787387503) [14637.782763] Lustre: DEBUG MARKER: SKIP: sanity-quota test_96 the test in only needed to run on LDiskFS [14639.912853] Lustre: DEBUG MARKER: == sanity-quota test 97a: LQA control commands =========== 04:31:47 (1787387507) [14670.484579] LustreError: 273313:0:(qmt_lqa.c:79:qmt_lqa_destroy()) lustre-QMT0000: cannot destroy lqa-dt-lqa1: rc = -2 [14670.494582] LustreError: 273313:0:(qmt_lqa.c:84:qmt_lqa_destroy()) lustre-QMT0000: cannot destroy lqa-md-lqa1: rc = -2 [14672.751596] Lustre: DEBUG MARKER: == sanity-quota test 97b: Check LQA internals ============ 04:32:20 (1787387540) [14696.279295] LustreError: 274113:0:(qmt_lqa.c:250:qmt_lqa_insert_range()) lustre-QMT0000: LQA range 15-31 partially overlaps with existing range 10-19: rc = -34 [14696.288805] LustreError: 274113:0:(qmt_lqa.c:669:qmt_lqa_add()) lustre-QMT0000: lqa:lqa1 can't add range 15:31: rc = -17 [14701.436662] LustreError: 274310:0:(qmt_lqa.c:825:qmt_lqa_remove()) lustre-QMT0000: lqa-md-lqa1 cannot remove range 10:19: rc = -2 [14716.672918] Lustre: DEBUG MARKER: adding 50 LQA ranges took 2s [14723.331353] Lustre: DEBUG MARKER: Removing 50 LQA ranges took 1s [14735.048898] Lustre: DEBUG MARKER: == sanity-quota test 97c: LQA lfs quota commands and MDS restart consistency ========================================================== 04:33:22 (1787387602) [14739.934570] Lustre: Failing over lustre-MDT0000 [14740.456304] Lustre: server umount lustre-MDT0000 complete [14752.721871] LustreError: MGC192.168.201.141@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [14753.206764] Lustre: 276180:0:(scrub.c:697:lustre_index_register()) lustre-MDT0000: the index [0x200000003:0x74:0x0] has registered with 8/8, may be invalid, replace with 4/8 [14753.309149] 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 [14753.627040] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [14753.634361] Lustre: Skipped 1 previous similar message [14753.756711] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [14755.923376] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [14756.029970] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [14756.060413] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3 to 0x240000400:97) [14758.890223] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [14758.909215] Lustre: Skipped 1 previous similar message [14759.610508] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [14760.482418] Lustre: 3305:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787387612/real 1787387612] req@ffff927032ba9500 x1874196442380160/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787387628 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [14767.114281] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [14776.482481] Lustre: DEBUG MARKER: == sanity-quota test 97d: LQA disk persistence using standard commands ========================================================== 04:34:04 (1787387644) [14803.301460] Lustre: Failing over lustre-MDT0000 [14804.968895] 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 [14804.975520] LustreError: 276164:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: 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. [14804.990588] Lustre: Skipped 2 previous similar messages [14805.012130] LustreError: 276164:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 1 previous similar message [14805.620465] Lustre: server umount lustre-MDT0000 complete [14817.356630] LustreError: MGC192.168.201.141@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [14817.692308] Lustre: 278233:0:(scrub.c:697:lustre_index_register()) lustre-MDT0000: the index [0x200000003:0x87:0x0] has registered with 8/8, may be invalid, replace with 4/8 [14817.700779] LustreError: 278233:0:(qmt_lqa.c:522:qmt_lqa_load_ranges_from_disk()) lustre-QMT0000: Failed to get record from IAM iterator: rc = -2 [14818.211982] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [14822.495365] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [14822.621068] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [14822.676121] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3 to 0x240000400:129) [14823.175823] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [14824.933341] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [14824.945237] Lustre: Skipped 1 previous similar message [14828.714871] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [14872.975622] Lustre: DEBUG MARKER: == sanity-quota test 97e: LQA add/remove should reject invalid ranges ========================================================== 04:35:40 (1787387740) [14887.209020] LustreError: 280568:0:(qmt_lqa.c:79:qmt_lqa_destroy()) lustre-QMT0000: cannot destroy lqa-dt-lqa1: rc = -2 [14887.226635] LustreError: 280568:0:(qmt_lqa.c:84:qmt_lqa_destroy()) lustre-QMT0000: cannot destroy lqa-md-lqa1: rc = -2 [14889.262122] Lustre: DEBUG MARKER: == sanity-quota test 98: Verify MDT retry on -EDQUOT during mkdir ========================================================== 04:35:57 (1787387757) [14891.140478] Lustre: DEBUG MARKER: SKIP: sanity-quota test_98 needs >= 2 MDTs [14893.743608] Lustre: DEBUG MARKER: == sanity-quota test 300: inode quota with MDT directory migration at 80% limit ========================================================== 04:36:01 (1787387761) [14895.978865] Lustre: DEBUG MARKER: SKIP: sanity-quota test_300 needs >= 2 MDTs [14902.153475] Lustre: DEBUG MARKER: == sanity-quota test complete, duration 14611 sec ======== 04:36:09 (1787387769) [14904.602433] Lustre: DEBUG MARKER: === sanity-quota: start cleanup 04:36:12 (1787387772) === [14908.871871] Lustre: DEBUG MARKER: === sanity-quota: finish cleanup 04:36:16 (1787387776) === [14914.328992] Lustre: server umount lustre-MDT0000 complete [14919.687572] LustreError: 260767:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787387788 with bad export cookie 16509150702439529999 [14919.713284] LustreError: MGC192.168.201.141@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [14929.971551] Lustre: server umount lustre-OST0000 complete [14933.280059] Lustre: 3307:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787387785/real 1787387785] req@ffff927004ac8e00 x1874196442426624/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787387801 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [14933.329137] Lustre: 3307:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [14933.351636] 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 [14935.153205] Lustre: server umount lustre-OST0001 complete [14949.525894] Lustre: DEBUG MARKER: oleg141-server.virtnet: executing unload_modules_local [14952.740602] Key type lgssc unregistered [14953.000644] LNet: 282114:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [14953.005679] LNetError: 282114:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [14953.021935] LNet: Removed LNI 192.168.201.141@tcp [14953.786110] Key type .llcrypt unregistered [14953.789173] Key type ._llcrypt unregistered