[ 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 687907053 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2400.000 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.002390] x2apic enabled [ 0.003012] Switched APIC routing to physical x2apic. [ 0.004022] kvm-guest: setup PV IPIs [ 0.007715] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.008000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x22983777dd9, max_idle_ns: 440795300422 ns [ 0.008028] Calibrating delay loop (skipped) preset value.. 4800.00 BogoMIPS (lpj=2400000) [ 0.009020] pid_max: default: 32768 minimum: 301 [ 0.010175] LSM: Security Framework initializing [ 0.011067] Yama: becoming mindful. [ 0.012045] SELinux: Initializing. [ 0.013077] *** VALIDATE selinux *** [ 0.022206] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.027835] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.028169] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.029129] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.031122] *** VALIDATE tmpfs *** [ 0.033281] *** VALIDATE proc *** [ 0.034311] *** VALIDATE cgroup *** [ 0.036007] *** VALIDATE cgroup2 *** [ 0.038315] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.039148] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.040015] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.041040] Spectre V2 : User space: Vulnerable [ 0.042014] Speculative Store Bypass: Vulnerable [ 0.044848] debug: unmapping init [mem 0xffffffff96259000-0xffffffff96260fff] [ 0.047900] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.048869] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.049026] ... version: 2 [ 0.050018] ... bit width: 48 [ 0.051019] ... generic registers: 4 [ 0.052022] ... value mask: 0000ffffffffffff [ 0.053014] ... max period: 00007fffffffffff [ 0.054021] ... fixed-purpose events: 3 [ 0.055015] ... event mask: 000000070000000f [ 0.056299] rcu: Hierarchical SRCU implementation. [ 0.058771] smp: Bringing up secondary CPUs ... [ 0.059763] x86: Booting SMP configuration: [ 0.060035] .... node #0, CPUs: #1 #2 #3 [ 0.077166] smp: Brought up 1 node, 4 CPUs [ 0.079017] smpboot: Max logical packages: 1 [ 0.080021] smpboot: Total of 4 processors activated (19200.00 BogoMIPS) [ 0.140397] node 0 deferred pages initialised in 57ms [ 0.147442] devtmpfs: initialized [ 0.148504] x86/mm: Memory block size: 128MB [ 0.152610] gcov: version magic: 0x41383552 [ 0.155055] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.156891] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.157273] pinctrl core: initialized pinctrl subsystem [ 0.158833] [ 0.159011] ************************************************************* [ 0.160014] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.161015] ** ** [ 0.162024] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.163017] ** ** [ 0.164019] ** This means that this kernel is built to expose internal ** [ 0.165021] ** IOMMU data structures, which may compromise security on ** [ 0.166019] ** your system. ** [ 0.167020] ** ** [ 0.168029] ** If you see this message and you are not debugging the ** [ 0.169019] ** kernel, report this immediately to your vendor! ** [ 0.170018] ** ** [ 0.171019] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.172015] ************************************************************* [ 0.175018] NET: Registered protocol family 16 [ 0.176721] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.177069] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.178076] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.180643] cpuidle: using governor menu [ 0.185022] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.191084] PCI: Using configuration type 1 for base access [ 0.196128] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.213000] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.215180] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.224230] cryptd: max_cpu_qlen set to 1000 [ 0.230297] ACPI: Added _OSI(Module Device) [ 0.231000] ACPI: Added _OSI(Processor Device) [ 0.233024] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.237017] ACPI: Added _OSI(Processor Aggregator Device) [ 0.252546] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.262016] ACPI: Interpreter enabled [ 0.263114] ACPI: PM: (supports S0 S3 S4 S5) [ 0.264014] ACPI: Using IOAPIC for interrupt routing [ 0.265174] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.266798] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.282461] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.283043] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.284023] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.285164] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.289000] acpiphp: Slot [2] registered [ 0.290388] acpiphp: Slot [5] registered [ 0.291163] acpiphp: Slot [6] registered [ 0.292228] acpiphp: Slot [7] registered [ 0.293361] acpiphp: Slot [8] registered [ 0.294114] acpiphp: Slot [9] registered [ 0.295220] acpiphp: Slot [10] registered [ 0.296209] acpiphp: Slot [3] registered [ 0.297143] acpiphp: Slot [4] registered [ 0.298253] acpiphp: Slot [11] registered [ 0.299146] acpiphp: Slot [12] registered [ 0.300119] acpiphp: Slot [13] registered [ 0.301270] acpiphp: Slot [14] registered [ 0.302124] acpiphp: Slot [15] registered [ 0.303108] acpiphp: Slot [16] registered [ 0.304106] acpiphp: Slot [17] registered [ 0.305130] acpiphp: Slot [18] registered [ 0.306155] acpiphp: Slot [19] registered [ 0.307120] acpiphp: Slot [20] registered [ 0.308082] acpiphp: Slot [21] registered [ 0.309187] acpiphp: Slot [22] registered [ 0.310250] acpiphp: Slot [23] registered [ 0.311100] acpiphp: Slot [24] registered [ 0.312231] acpiphp: Slot [25] registered [ 0.313274] acpiphp: Slot [26] registered [ 0.314136] acpiphp: Slot [27] registered [ 0.315096] acpiphp: Slot [28] registered [ 0.316511] acpiphp: Slot [29] registered [ 0.317264] acpiphp: Slot [30] registered [ 0.318151] acpiphp: Slot [31] registered [ 0.319084] PCI host bridge to bus 0000:00 [ 0.320021] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.321028] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.322025] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.323032] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.324025] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.325031] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.326199] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.328810] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.331253] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.339556] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.342695] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.343017] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.344022] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.345017] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.347358] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.349365] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.350048] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.352214] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.355016] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.364019] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.367017] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.373038] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.376018] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.379020] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.386029] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.393256] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.396021] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.399015] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.407016] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.414118] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.417019] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.420017] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.427021] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.434211] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.437016] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.440025] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.447022] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.458609] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.461021] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.464039] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.471019] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 0.480459] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.483023] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.486025] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.493019] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 0.497000] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.506652] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.510377] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.515282] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.520642] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.525338] iommu: Default domain type: Passthrough [ 0.526665] SCSI subsystem initialized [ 0.530196] ACPI: bus type USB registered [ 0.533128] usbcore: registered new interface driver usbfs [ 0.536108] usbcore: registered new interface driver hub [ 0.539137] usbcore: registered new device driver usb [ 0.542213] pps_core: LinuxPPS API ver. 1 registered [ 0.545017] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.551078] PTP clock support registered [ 0.557097] EDAC MC: Ver: 3.0.0 [ 0.563319] PCI: Using ACPI for IRQ routing [ 0.564000] NetLabel: Initializing [ 0.565012] NetLabel: domain hash size = 128 [ 0.568014] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.570093] NetLabel: unlabeled traffic allowed by default [ 0.577063] vgaarb: loaded [ 0.581086] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.585014] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.595670] clocksource: Switched to clocksource kvm-clock [ 0.975225] VFS: Disk quotas dquot_6.6.0 [ 0.980615] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.989493] *** VALIDATE ramfs *** [ 0.991924] *** VALIDATE hugetlbfs *** [ 0.997716] pnp: PnP ACPI init [ 1.007113] pnp: PnP ACPI: found 6 devices [ 1.082663] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 1.093546] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 1.100841] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 1.106451] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 1.113603] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 1.119941] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 1.128425] NET: Registered protocol family 2 [ 1.136152] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 1.151567] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 1.161211] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 1.178963] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 1.190483] TCP: Hash tables configured (established 65536 bind 65536) [ 1.198948] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 1.212199] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 1.221748] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 1.234923] NET: Registered protocol family 1 [ 1.242758] RPC: Registered named UNIX socket transport module. [ 1.250438] RPC: Registered udp transport module. [ 1.256917] RPC: Registered tcp transport module. [ 1.261801] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 1.270639] NET: Registered protocol family 44 [ 1.274515] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 1.279833] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 1.285961] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 1.292085] PCI: CLS 0 bytes, default 64 [ 1.298696] Unpacking initramfs... [ 4.707555] debug: unmapping init [mem 0xffff95147cc54000-0xffff95147ffbffff] [ 4.718110] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 4.722345] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 4.734598] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x22983777dd9, max_idle_ns: 440795300422 ns [ 7.642004] hrtimer: interrupt took 3284195 ns [ 8.359440] Initialise system trusted keyrings [ 8.369810] Key type blacklist registered [ 8.380692] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 8.418361] zbud: loaded [ 8.438545] *** VALIDATE nfs *** [ 8.443387] *** VALIDATE nfs4 *** [ 8.453070] pstore: using deflate compression [ 8.466068] Platform Keyring initialized [ 9.006601] NET: Registered protocol family 38 [ 9.014874] Key type asymmetric registered [ 9.024123] Asymmetric key parser 'x509' registered [ 9.031351] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 9.044287] io scheduler mq-deadline registered [ 9.057337] io scheduler kyber registered [ 9.065872] io scheduler bfq registered [ 9.076479] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 9.081275] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 9.087426] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 9.092031] ACPI: Power Button [PWRF] [ 9.107900] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 9.128486] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 9.161664] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 9.174620] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 9.225988] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 9.276945] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 9.358418] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 9.374790] Non-volatile memory driver v1.3 [ 9.378468] Linux agpgart interface v0.103 [ 9.468234] virtio_blk virtio1: [vda] 145984 512-byte logical blocks (74.7 MB/71.3 MiB) [ 9.475141] vda: detected capacity change from 0 to 74743808 [ 9.520578] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 9.527216] vdb: detected capacity change from 0 to 1073741824 [ 9.572953] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 9.580546] vdc: detected capacity change from 0 to 2621440000 [ 9.639317] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 9.646268] vdd: detected capacity change from 0 to 2621440000 [ 9.694747] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 9.702258] vde: detected capacity change from 0 to 4294967296 [ 9.749889] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 9.756868] vdf: detected capacity change from 0 to 4294967296 [ 9.775043] libphy: Fixed MDIO Bus: probed [ 9.793969] usbcore: registered new interface driver usbserial_generic [ 9.802891] usbserial: USB Serial support registered for generic [ 9.810754] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 9.823800] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 9.830502] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 9.841860] mousedev: PS/2 mouse device common for all mice [ 9.851438] rtc_cmos 00:05: RTC can wake from S4 [ 9.859411] rtc_cmos 00:05: registered as rtc0 [ 9.867889] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 9.882583] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 9.883679] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 9.900052] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 9.911642] intel_pstate: CPU model not supported [ 9.925441] hid: raw HID events driver (C) Jiri Kosina [ 9.939669] usbcore: registered new interface driver usbhid [ 9.944422] usbhid: USB HID core driver [ 9.948392] drop_monitor: Initializing network drop monitor service [ 9.954774] Initializing XFRM netlink socket [ 9.958664] NET: Registered protocol family 10 [ 9.967830] Segment Routing with IPv6 [ 9.970603] NET: Registered protocol family 17 [ 9.972951] mpls_gso: MPLS GSO support [ 9.980506] RAS: Correctable Errors collector initialized. [ 9.983366] AVX version of gcm_enc/dec engaged. [ 9.985414] AES CTR mode by8 optimization enabled [ 10.288507] sched_clock: Marking stable (10288039009, 0)->(12284841707, -1996802698) [ 10.302958] registered taskstats version 1 [ 10.306403] Loading compiled-in X.509 certificates [ 10.310455] zswap: loaded using pool lzo/zbud [ 10.425394] Key type big_key registered [ 10.477495] Key type encrypted registered [ 10.480090] ima: No TPM chip found, activating TPM-bypass! [ 10.486895] ima: Allocated hash algorithm: sha1 [ 10.493392] ima: No architecture policies found [ 10.498316] evm: Initialising EVM extended attributes: [ 10.504281] evm: security.selinux [ 10.507808] evm: security.ima [ 10.511729] evm: security.capability [ 10.515333] evm: HMAC attrs: 0x1 [ 10.522407] rtc_cmos 00:05: setting system clock to 2026-08-11 20:26:26 UTC (1786479986) [ 10.549617] debug: unmapping init [mem 0xffffffff97203000-0xffffffff973fffff] [ 10.557281] debug: unmapping init [mem 0xffffffff95f82000-0xffffffff96258fff] [ 10.569363] Write protecting the kernel read-only data: 28672k [ 10.577259] debug: unmapping init [mem 0xffffffff94603000-0xffffffff947fffff] [ 10.581721] debug: unmapping init [mem 0xffffffff94f14000-0xffffffff94ffffff] [ 10.761245] 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) [ 10.812582] systemd[1]: Detected virtualization kvm. [ 10.820300] systemd[1]: Detected architecture x86-64. [ 10.826551] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 10.883781] systemd[1]: No hostname configured. [ 10.890081] systemd[1]: Set hostname to . [ 10.897935] random: systemd: uninitialized urandom read (16 bytes read) [ 10.903752] systemd[1]: Initializing machine ID from random generator. [ 11.068181] random: ln: uninitialized urandom read (6 bytes read) [ 11.361926] random: systemd: uninitialized urandom read (16 bytes read) [ 11.369419] systemd[1]: Reached target Local File Systems. [ OK ] Reached target Local File Systems. [ 11.393270] systemd[1]: Reached target Initrd Root Device. [ OK ] Reached target Initrd Root Device. [ 11.405546] systemd[1]: Listening on Journal Socket (/dev/log). [ OK ] Listening on Journal Socket (/dev/log). [ OK ] Listening on udev Control Socket. [ OK ] Reached target Swap. [ 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 Timers. [ OK ] Listening on Journal Socket. Starting Setup Virtual Console... Starting Apply Kernel Variables... Starting Create list of required st…ce nodes for the current kernel... [ OK ] Started Memstrack Anylazing Service. Starting Journal Service... [ OK ] Listening on udev Kernel Socket. [ OK ] Reached target Sockets. Starting Create Volatile Files and Directories... [ OK ] Started Setup Virtual Console. [ OK ] Started Apply Kernel Variables. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Create Volatile Files and Directories. Starting Create Static Device Nodes in /dev... Starting dracut cmdline hook... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started Journal Service. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 13.324907] device-mapper: uevent: version 1.0.3 [ 13.326941] 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.[ 14.070669] random: fast init done Starting udev Coldplug all Devices... Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. Starting dracut initqueue hook... [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ 15.271851] virtio_net virtio0 ens2: renamed from eth0 [ 15.870303] scsi host0: ata_piix [ 15.961414] scsi host1: ata_piix [ 15.962922] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 15.987788] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 21.041238] random: crng init done [ 21.046568] random: 7 urandom warning(s) missed due to ratelimiting [ 24.682994] dracut-initqueue[591]: 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 ] Reached target Remote File Systems. [ 27.232701] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped target Timers. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target System Initialization. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped Apply Kernel Variables. [ 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 Local Encrypted Volumes. [ OK ] Stopped target Swap. [ OK ] Stopped target Slices. [ OK ] Stopped target Sockets. [ OK ] Stopped target Paths. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Closed udev Kernel Socket. [ OK ] Closed udev Control Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 31.443750] printk: systemd: 26 output lines suppressed due to ratelimiting [ 32.386143] SELinux: Disabled at runtime. [ 32.548595] 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) [ 32.577395] systemd[1]: Detected virtualization kvm. [ 32.582605] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 34.743940] systemd[1]: initrd-switch-root.service: Succeeded. [ 34.756528] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 34.793099] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 34.809274] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 34.821926] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 34.840311] systemd[1]: Starting Journal Service... Starting Journal Service... [ 34.860495] systemd[1]: Listening on udev Control Socket. [ OK ] Listening on udev Control Socket. [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Created slice system-getty.slice. Activating swap /dev/disk/by-label/SWAP... Starting Create list of required st…ce nodes for the current kernel... [ 35.003413] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS Starting Remount Root and Kernel File Systems... [ OK ] Created slice User and Session Slice. [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Reached target Slices. Mounting Kernel Debug File System... [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd File Systems. [ OK ] Stopped target Initrd Root File System. [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Listening on initctl Compatibility Named Pipe. Starting Apply Kernel Variables... Mounting Huge Pages File System... [ OK ] Listening on udev Kernel Socket. Starting udev Coldplug all Devices... [ OK ] Reached target rpc_pipefs.target. [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Reached target RPC Port Mapper. [ OK ] Listening on Process Core Dump Socket. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. Mounting POSIX Message Queue File System... [ 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. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Mounted Kernel Debug File System. [ OK ] Started Apply Kernel Variables. [ OK ] Mounted Huge Pages File System. [ OK ] Mounted POSIX Message Queue File System. Starting Configure read-only root support... Starting Create Static Device Nodes in /dev... [ OK ] Reached target Swap. Starting Flush Journal to Persistent Storage... [ 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 /home/green/git/lustre-release... Mounting /mnt... [ OK ] Mounted /mnt. [ 37.994857] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 40.394264] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 40.586700] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 41.007241] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 41.145601] EDAC sbridge: Ver: 1.1.2 [* ] A start job is running for Configur…only root support (10s / no limit) [** ] A start job is running for Configur…only root support (11s / no limit) [*** ] A start job is running for Configur…only root support (11s / no limit) [ *** ] A start job is running for Configur…only root support (12s / no limit) [ *** ] A start job is running for Configur…only root support (12s / no limit) [ ***] A start job is running for Configur…only root support (13s / no limit) [ **] A start job is running for Configur…only root support (13s / 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 (14s / no limit)[ 49.598884] Key type dns_resolver registered [ ***] 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)[ 50.944716] NFS: Registering the id_resolver key type [ 50.949885] Key type id_resolver registered [ 50.952772] Key type id_legacy registered [ *** ] 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) [ OK ] Started Configure read-only root support. Starting Load/Save Random Seed... [ OK ] Reached target Local File Systems. Starting Create Volatile Files and Directories... Starting Rebuild Dynamic Linker Cache... Starting Mark the need to relabel after reboot... [ OK ] Started Load/Save Random Seed. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Mark the need to relabel after reboot. Starting Update UTMP about System Boot/Shutdown... Starting RPC Bind... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Started dnf makecache --timer. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Reached target Timers. [ OK ] Reached target Basic System. [ OK ] Started irqbalance daemon. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Started D-Bus System Message Bus. Starting Network Manager... Starting Restore /run/initramfs on shutdown... [ OK ] Reached target sshd-keygen.target. Starting Login Service... [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Network Manager. [ OK ] Reached target Network. Starting Dynamic System Tuning Daemon... Starting OpenSSH server daemon... Starting GSSAPI Proxy Daemon... Starting Network Manager Wait Online... [ OK ] Started Login Service. Starting Hostname Service... [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... [ OK ] Started OpenSSH server daemon. [ OK ] Started Permit User Sessions. [ OK ] Started Command Scheduler. [ OK ] Started Getty on tty1. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Serial Getty on ttyS1. [ OK ] Reached target Login Prompts. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting System Logging Service... Starting Notify NFS peers of a restart... Starting Crash recovery kernel arming... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg416-server login: [ 100.586949] spl: loading out-of-tree module taints kernel. [ 105.150267] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 119.660483] Key type ._llcrypt registered [ 119.662937] Key type .llcrypt registered [ 119.792551] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing set_hostid [ 138.688321] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing load_modules_local [ 140.475046] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 140.508872] alg: No test for adler32 (adler32-zlib) [ 142.194996] Lustre: Lustre: Build Version: 2.17.56_52_g54963d0 [ 143.019195] LNet: Added LNI 192.168.204.116@tcp [8/256/0/180] [ 144.760138] Key type lgssc registered [ 146.954857] Lustre: Echo OBD driver; http://www.lustre.org/ [ 159.335343] vdc: vdc1 vdc9 [ 170.022360] vde: vde1 vde9 [ 182.723095] vdf: vdf1 vdf9 [ 208.734481] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing load_modules_local [ 222.446230] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 223.868132] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 224.361727] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 224.481324] Lustre: lustre-MDT0000: new disk, initializing [ 225.143700] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 225.233484] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 231.807582] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 238.262412] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 247.672316] Lustre: lustre-OST0000: new disk, initializing [ 247.677758] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 247.683249] Lustre: Skipped 1 previous similar message [ 247.800081] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 257.144779] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 258.089395] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:0:ost [ 258.104673] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:0:ost] [ 258.438309] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x240000400 [ 269.767594] Lustre: lustre-OST0001: new disk, initializing [ 269.771821] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 269.879797] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 277.629969] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 279.798619] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:1:ost [ 279.813091] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:1:ost] [ 280.188463] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x280000400 [ 293.560773] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 301.509835] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 310.492777] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing check_logdir /tmp/testlogs/ [ 317.846616] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing yml_node [ 323.194316] Lustre: DEBUG MARKER: Client: 2.17.56.52 [ 326.313764] Lustre: DEBUG MARKER: MDS: 2.17.56.52 [ 329.257502] Lustre: DEBUG MARKER: OSS: 2.17.56.52 [ 331.094353] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity-quota ============----- Tue Aug 11 16:31:45 EDT 2026 [ 350.485637] Lustre: DEBUG MARKER: excepting tests: 2 4a 63 65 [ 352.355126] Lustre: DEBUG MARKER: skipping tests SLOW=no: 61 12a 9 [ 354.727410] Lustre: DEBUG MARKER: === sanity-quota: start setup 16:32:08 (1786480328) === [ 361.596230] Lustre: DEBUG MARKER: oleg416-client.virtnet: executing check_config_client /mnt/lustre [ 384.193544] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 389.454719] Lustre: 11378:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 394.364330] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 400.513822] Lustre: DEBUG MARKER: === sanity-quota: finish setup 16:32:53 (1786480373) === [ 473.451789] Lustre: DEBUG MARKER: == sanity-quota test 0: Test basic quota performance ===== 16:34:06 (1786480446) [ 538.552454] Lustre: DEBUG MARKER: == sanity-quota test 1a: Block hard limit (normal use and out of quota) ========================================================== 16:35:12 (1786480512) [ 559.183738] Lustre: DEBUG MARKER: User quota (block hardlimit:10 MB) [ 567.421809] Lustre: DEBUG MARKER: Write... [ 570.251793] Lustre: DEBUG MARKER: Write out of block quota ... [ 617.657177] Lustre: DEBUG MARKER: -------------------------------------- [ 619.791692] Lustre: DEBUG MARKER: Group quota (block hardlimit:10 MB) [ 627.156912] Lustre: DEBUG MARKER: Write... [ 630.341913] Lustre: DEBUG MARKER: Write out of block quota ... [ 680.822491] Lustre: DEBUG MARKER: -------------------------------------- [ 683.192572] Lustre: DEBUG MARKER: Project quota (block hardlimit:10 mb) [ 686.397764] Lustre: DEBUG MARKER: Write... [ 689.618701] Lustre: DEBUG MARKER: Write out of block quota ... [ 760.950830] Lustre: DEBUG MARKER: == sanity-quota test 1b: Quota pools: Block hard limit (normal use and out of quota) ========================================================== 16:38:55 (1786480735) [ 778.678180] Lustre: DEBUG MARKER: User quota (block hardlimit:20 MB) [ 799.055313] Lustre: DEBUG MARKER: Write... [ 801.875646] Lustre: DEBUG MARKER: Write out of block quota ... [ 847.413784] Lustre: DEBUG MARKER: -------------------------------------- [ 849.483596] Lustre: DEBUG MARKER: Group quota (block hardlimit:20 MB) [ 858.320549] Lustre: DEBUG MARKER: Write... [ 861.916410] Lustre: DEBUG MARKER: Write out of block quota ... [ 918.084186] Lustre: DEBUG MARKER: -------------------------------------- [ 920.201958] Lustre: DEBUG MARKER: Project quota (block hardlimit:20 mb) [ 924.701437] Lustre: DEBUG MARKER: Write... [ 928.429463] Lustre: DEBUG MARKER: Write out of block quota ... [ 1010.466431] Lustre: DEBUG MARKER: == sanity-quota test 1c: Quota pools: check 3 pools with hardlimit only for global ========================================================== 16:43:04 (1786480984) [ 1029.821627] Lustre: DEBUG MARKER: User quota (block hardlimit:20 MB) [ 1054.335949] Lustre: DEBUG MARKER: Write... [ 1058.122835] Lustre: DEBUG MARKER: Write out of block quota ... [ 1155.091279] Lustre: DEBUG MARKER: == sanity-quota test 1d: Quota pools: check block hardlimit on different pools ========================================================== 16:45:29 (1786481129) [ 1171.016701] Lustre: DEBUG MARKER: User quota (block hardlimit:20 MB) [ 1195.415391] Lustre: DEBUG MARKER: Write... [ 1198.033780] Lustre: DEBUG MARKER: Write out of block quota ... [ 1310.899876] Lustre: DEBUG MARKER: == sanity-quota test 1e: Quota pools: global pool high block limit vs quota pool with small ========================================================== 16:48:04 (1786481284) [ 1332.766574] Lustre: DEBUG MARKER: User quota (block hardlimit:53000000 MB) [ 1347.943477] Lustre: DEBUG MARKER: Write... [ 1351.115468] Lustre: DEBUG MARKER: Write out of block quota ... [ 1364.158533] Lustre: DEBUG MARKER: Write... [ 1444.797713] Lustre: DEBUG MARKER: == sanity-quota test 1f: Quota pools: correct qunit after removing/adding OST ========================================================== 16:50:18 (1786481418) [ 1466.491527] Lustre: DEBUG MARKER: User quota (block hardlimit:200 MB) [ 1482.602796] Lustre: DEBUG MARKER: Write... [ 1486.306131] Lustre: DEBUG MARKER: Write out of block quota ... [ 1537.930656] Lustre: DEBUG MARKER: Write... [ 1541.711519] Lustre: DEBUG MARKER: Write out of block quota ... [ 1604.352736] Lustre: DEBUG MARKER: == sanity-quota test 1g: Quota pools: Block hard limit with wide striping ========================================================== 16:52:57 (1786481577) [ 1625.189710] Lustre: DEBUG MARKER: User quota (block hardlimit:40 MB) [ 1640.738349] Lustre: DEBUG MARKER: Write... [ 1651.270699] Lustre: DEBUG MARKER: Write out of block quota ... [ 1739.711400] Lustre: DEBUG MARKER: == sanity-quota test 1h: Block hard limit test using fallocate ========================================================== 16:55:14 (1786481714) [ 1741.142422] Lustre: DEBUG MARKER: SKIP: sanity-quota test_1h need >= 2.13.57 and ldiskfs for fallocate [ 1743.199705] Lustre: DEBUG MARKER: == sanity-quota test 1i: Quota pools: different limit and usage relations ========================================================== 16:55:17 (1786481717) [ 1759.735958] Lustre: DEBUG MARKER: User quota (block hardlimit:200 MB) [ 1774.448539] Lustre: DEBUG MARKER: Write... [ 1777.787919] Lustre: DEBUG MARKER: Write out of block quota ... [ 1821.815512] Lustre: DEBUG MARKER: Write... [ 1825.185787] Lustre: DEBUG MARKER: Write out of block quota ... [ 1837.974228] LustreError: 5846: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:15365 time:0 qunit: 1024 edquot:0 may_rel:0 revoke:0 default:no [ 1896.159454] Lustre: DEBUG MARKER: == sanity-quota test 1j: Enable project quota enforcement for root ========================================================== 16:57:50 (1786481870) [ 1916.839804] Lustre: DEBUG MARKER: -------------------------------------- [ 1918.879836] Lustre: DEBUG MARKER: Project quota (hardlimit: 40 mb, 2048 files) [ 2276.394574] Lustre: DEBUG MARKER: == sanity-quota test 1k: LQA: Block hard limit (normal use and out of quota) ========================================================== 17:04:11 (1786482251) [ 2293.180927] Lustre: DEBUG MARKER: Write... [ 2296.036362] Lustre: DEBUG MARKER: Write out of block quota ... [ 2333.786529] Lustre: DEBUG MARKER: Write... [ 2336.774901] Lustre: DEBUG MARKER: Write out of block quota ... [ 2375.946512] Lustre: DEBUG MARKER: Write... [ 2378.453731] Lustre: DEBUG MARKER: Write out of block quota ... [ 2421.109909] Lustre: DEBUG MARKER: == sanity-quota test 1l: Async writes should not be rejected by quota with root_prj_enable ========================================================== 17:06:35 (1786482395) [ 2470.172798] Lustre: DEBUG MARKER: SKIP: sanity-quota test_2 skipping excluded test 2 [ 2471.556437] Lustre: DEBUG MARKER: == sanity-quota test 3a: Block soft limit (start timer, timer goes off, stop timer) ========================================================== 17:07:26 (1786482446) [ 2555.983687] Lustre: DEBUG MARKER: Write after timer goes off [ 2557.250046] Lustre: DEBUG MARKER: Write after cancel lru locks [ 2683.679644] Lustre: DEBUG MARKER: Write after timer goes off [ 2685.071472] Lustre: DEBUG MARKER: Write after cancel lru locks [ 2808.969760] Lustre: DEBUG MARKER: Write after timer goes off [ 2810.189914] Lustre: DEBUG MARKER: Write after cancel lru locks [ 2896.220758] Lustre: DEBUG MARKER: == sanity-quota test 3b: Quota pools: Block soft limit (start timer, expires, stop timer) ========================================================== 17:14:31 (1786482871) [ 2983.670148] Lustre: DEBUG MARKER: Write after timer goes off [ 2984.641496] Lustre: DEBUG MARKER: Write after cancel lru locks [ 3106.676051] Lustre: DEBUG MARKER: Write after timer goes off [ 3107.643469] Lustre: DEBUG MARKER: Write after cancel lru locks [ 3230.363895] Lustre: DEBUG MARKER: Write after timer goes off [ 3231.300232] Lustre: DEBUG MARKER: Write after cancel lru locks [ 3317.427519] Lustre: DEBUG MARKER: == sanity-quota test 3c: Quota pools: check block soft limit on different pools ========================================================== 17:21:32 (1786483292) [ 3406.170109] Lustre: DEBUG MARKER: Write after timer goes off [ 3406.892597] Lustre: DEBUG MARKER: Write after cancel lru locks [ 3476.012343] Lustre: DEBUG MARKER: SKIP: sanity-quota test_4a skipping excluded test 4a [ 3476.725123] Lustre: DEBUG MARKER: == sanity-quota test 4b: Grace time strings handling ===== 17:24:11 (1786483451) [ 3486.385375] Lustre: DEBUG MARKER: == sanity-quota test 5: Chown [ 3554.214180] Lustre: DEBUG MARKER: == sanity-quota test 6: Test dropping acquire request on master ========================================================== 17:25:29 (1786483529) [ 3590.760504] Lustre: *** cfs_fail_loc=513, val=601*** [ 3590.980313] LustreError: 14424:0:(service.c:2341:ptlrpc_server_handle_req_in()) drop incoming rpc opc 601, x1873260177982720 [ 3592.672552] Lustre: *** cfs_fail_loc=513, val=601*** [ 3592.675462] Lustre: Skipped 14 previous similar messages [ 3594.255462] Lustre: *** cfs_fail_loc=513, val=601*** [ 3594.257543] Lustre: Skipped 8 previous similar messages [ 3596.257292] Lustre: *** cfs_fail_loc=513, val=601*** [ 3601.376474] Lustre: *** cfs_fail_loc=513, val=601*** [ 3601.378291] Lustre: Skipped 10 previous similar messages [ 3605.472349] Lustre: 39144:0:(service.c:1612:ptlrpc_at_send_early_reply()) @@@ Could not add any time (5/5), not sending early reply req@ffff9513c3000a80 x1873260162750336/t0(0) o4->0e8b1f6b-a3dc-4a62-b0b7-12b139227521@192.168.204.16@tcp:321/0 lens 488/448 e 1 to 0 dl 1786483586 ref 2 fl Interpret:/600/0 rc 0/0 job:'dd.60000' uid:60000 gid:60000 projid:0 [ 3606.496239] Lustre: 38935:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786483566/real 1786483566] req@ffff9514c8b03480 x1873260177982720/t0(0) o601->lustre-MDT0000-lwp-OST0000@0@lo:23/10 lens 336/336 e 0 to 1 dl 1786483582 ref 2 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'ll_ost_io00_007.0' uid:0 gid:0 projid:4294967295 [ 3606.507721] 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 [ 3606.515767] Lustre: lustre-MDT0000: Client lustre-MDT0000-lwp-OST0000_UUID (at 0@lo) reconnecting [ 3606.520378] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 3607.583416] LustreError: 5850:0:(service.c:2341:ptlrpc_server_handle_req_in()) drop incoming rpc opc 601, x1873260177986688 [ 3609.615939] Lustre: *** cfs_fail_loc=513, val=601*** [ 3609.619253] Lustre: Skipped 21 previous similar messages [ 3623.905266] Lustre: 14274:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786483583/real 1786483583] req@ffff9513c2c39f80 x1873260177986688/t0(0) o601->lustre-MDT0000-lwp-OST0000@0@lo:23/10 lens 336/336 e 0 to 1 dl 1786483599 ref 2 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'ll_ost_io00_003.0' uid:0 gid:0 projid:4294967295 [ 3623.918222] 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 [ 3623.925885] Lustre: lustre-MDT0000: Client lustre-MDT0000-lwp-OST0000_UUID (at 0@lo) reconnecting [ 3623.930421] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 3625.999298] Lustre: *** cfs_fail_loc=513, val=601*** [ 3626.001646] Lustre: Skipped 36 previous similar messages [ 3626.018369] LustreError: 5849:0:(service.c:2341:ptlrpc_server_handle_req_in()) drop incoming rpc opc 601, x1873260177990400 [ 3630.048738] LustreError: 14424:0:(service.c:2341:ptlrpc_server_handle_req_in()) drop incoming rpc opc 601, x1873260177991552 [ 3630.053498] LustreError: 14424:0:(service.c:2341:ptlrpc_server_handle_req_in()) Skipped 2 previous similar messages [ 3641.312173] Lustre: 38932:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786483601/real 1786483601] req@ffff9513d2029180 x1873260177990400/t0(0) o601->lustre-MDT0000-lwp-OST0000@0@lo:23/10 lens 336/336 e 0 to 1 dl 1786483617 ref 2 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'ll_ost_io00_005.0' uid:0 gid:0 projid:4294967295 [ 3641.323450] 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 [ 3641.329103] Lustre: lustre-MDT0000: Client lustre-MDT0000-lwp-OST0000_UUID (at 0@lo) reconnecting [ 3641.332536] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 3646.432291] Lustre: 3312:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786483606/real 1786483606] req@ffff9513d223c700 x1873260177991552/t0(0) o601->lustre-MDT0000-lwp-OST0001@0@lo:23/10 lens 336/336 e 0 to 1 dl 1786483622 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'lquota_wb_lustr.0' uid:0 gid:0 projid:4294967295 [ 3646.432405] 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 [ 3646.444297] Lustre: 3312:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 3646.453947] Lustre: lustre-MDT0000: Client lustre-MDT0000-lwp-OST0001_UUID (at 0@lo) reconnecting [ 3646.460113] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 3666.660938] Lustre: DEBUG MARKER: == sanity-quota test 7a: Quota reintegration (global index) ========================================================== 17:27:21 (1786483641) [ 3684.061209] Lustre: Failing over lustre-OST0000 [ 3684.141816] Lustre: server umount lustre-OST0000 complete [ 3687.012120] LustreError: lustre-OST0000-osc-MDT0000: operation ost_setattr to node 0@lo failed: rc = -107 [ 3687.017722] 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 [ 3689.503583] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [ 3689.513950] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 3690.966975] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 3691.513510] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 3691.513579] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 3691.825544] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3694.719908] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3696.825234] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3698.858717] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3700.927385] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3703.107945] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3705.292907] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3729.541894] Lustre: Failing over lustre-OST0000 [ 3729.589621] Lustre: server umount lustre-OST0000 complete [ 3730.401175] 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 [ 3730.405888] LustreError: 6706:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3730.411133] LustreError: 6706:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 3 previous similar messages [ 3732.693713] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [ 3732.701324] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 3734.370991] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 3734.389062] Lustre: lustre-OST0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 3734.389142] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 3734.957755] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3737.953934] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3740.000889] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3742.112461] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3744.039292] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3745.969802] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3747.943731] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3772.463584] Lustre: DEBUG MARKER: == sanity-quota test 7b: Quota reintegration (slave index) ========================================================== 17:29:07 (1786483747) [ 3793.061678] LustreError: 3311:0:(qsd_reint.c:633:qqi_reint_delayed()) lustre-OST0000: Delaying reintegration for qtype:0 until pending updates are flushed. [ 3793.151558] Lustre: *** cfs_fail_loc=a02, val=0*** [ 3796.493499] LustreError: 3311:0:(qsd_handler.c:298:qsd_req_completion()) $$$ DQACQ failed with -5, flags:0x8 qsd:lustre-OST0000 qtype:usr lqe: ffff9514c31a5b00 id:60000 enforced:1 granted: 1026 pending:0 waiting:0 req:1 usage: 2052 qunit:0 qtune:0 edquot:0 default:no revoke:0 [ 3796.505331] Lustre: Failing over lustre-OST0000 [ 3798.594371] Lustre: server umount lustre-OST0000 complete [ 3799.083856] LustreError: 38876:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.204.16@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3799.521874] 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 [ 3802.378934] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [ 3802.387807] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 3803.738794] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 3804.223645] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 3804.223840] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 3805.007301] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3808.256441] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3810.380762] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3812.626551] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3814.852696] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3817.079669] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3819.238079] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3854.394354] Lustre: DEBUG MARKER: == sanity-quota test 7c: Quota reintegration (restart mds during reintegration) ========================================================== 17:30:29 (1786483829) [ 3871.022638] LustreError: 92343:0:(qsd_reint.c:488:qsd_reint_main()) cfs_fail_timeout id a03 sleeping for 10000ms [ 3871.027035] LustreError: 92343:0:(qsd_reint.c:488:qsd_reint_main()) Skipped 5 previous similar messages [ 3871.795876] Lustre: Failing over lustre-MDT0000 [ 3872.166482] Lustre: server umount lustre-MDT0000 complete [ 3873.584110] LustreError: 92344:0:(qsd_reint.c:488:qsd_reint_main()) cfs_fail_timeout interrupted [ 3873.588607] LustreError: 92344:0:(qsd_reint.c:488:qsd_reint_main()) Skipped 3 previous similar messages [ 3876.147497] LustreError: MGC192.168.204.116@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3876.288765] 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 [ 3876.296716] Lustre: Skipped 1 previous similar message [ 3876.365327] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3876.405939] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 3878.165739] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3880.984384] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 3881.014921] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 3881.033543] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:145 to 0x240000400:161) [ 3881.033658] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:116 to 0x280000400:161) [ 3881.178227] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3881.443093] LustreError: 3308:0:(ldlm_resource.c:1207:ldlm_resource_complain()) lustre-MDT0000-lwp-OST0001: namespace resource [0x200000006:0x2020000:0x0].0x0 (ffff9514c2e4be00) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 3881.453927] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 3890.656118] Lustre: 3312:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786483850/real 1786483850] req@ffff9513caa8ca80 x1873260178362752/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786483866 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3890.666502] Lustre: 3312:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 3994.985210] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 4000.013472] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 4005.455943] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 4010.436218] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 4013.876463] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 4044.668666] Lustre: DEBUG MARKER: == sanity-quota test 7d: Quota reintegration (Transfer index in multiple bulks) ========================================================== 17:33:38 (1786484018) [ 4090.947826] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 4100.648671] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 4163.183543] Lustre: DEBUG MARKER: == sanity-quota test 7e: Quota reintegration (inode limits) ========================================================== 17:35:36 (1786484136) [ 4165.503034] Lustre: DEBUG MARKER: SKIP: sanity-quota test_7e needs >= 2 MDTs [ 4167.870800] Lustre: DEBUG MARKER: == sanity-quota test 7f: Quota reintegration automatically ========================================================== 17:35:41 (1786484141) [ 4189.593885] Lustre: *** cfs_fail_loc=a11, val=0*** [ 4189.606697] Lustre: Skipped 2 previous similar messages [ 4195.914383] Lustre: *** cfs_fail_loc=a11, val=0*** [ 4248.548656] Lustre: *** cfs_fail_loc=a11, val=0*** [ 4248.554683] Lustre: Skipped 1 previous similar message [ 4374.056722] Lustre: DEBUG MARKER: == sanity-quota test 8: Run dbench with quota enabled ==== 17:39:08 (1786484348) [ 4568.760886] Lustre: DEBUG MARKER: SKIP: sanity-quota test_9 skipping SLOW test 9 [ 4569.762228] Lustre: DEBUG MARKER: == sanity-quota test 10: Test quota for root user ======== 17:42:24 (1786484544) [ 4608.535528] Lustre: DEBUG MARKER: == sanity-quota test 11: Chown/chgrp ignores quota ======= 17:43:03 (1786484583) [ 4644.137221] Lustre: DEBUG MARKER: SKIP: sanity-quota test_12a skipping SLOW test 12a [ 4644.712294] Lustre: DEBUG MARKER: == sanity-quota test 12b: Inode quota rebalancing ======== 17:43:39 (1786484619) [ 4645.179816] Lustre: DEBUG MARKER: SKIP: sanity-quota test_12b needs >= 2 MDTs [ 4645.752192] Lustre: DEBUG MARKER: == sanity-quota test 13: Cancel per-ID lock in the LRU list ========================================================== 17:43:40 (1786484620) [ 4684.819409] Lustre: DEBUG MARKER: == sanity-quota test 14: check panic in qmt_site_recalc_cb ========================================================== 17:44:20 (1786484660) [ 4699.300360] Lustre: Failing over lustre-OST0000 [ 4699.337757] Lustre: server umount lustre-OST0000 complete [ 4700.182030] LustreError: 104494:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.204.16@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4700.186036] LustreError: 104494:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 1 previous similar message [ 4700.642807] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 4700.642890] 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 [ 4704.680207] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [ 4704.688343] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 4705.295595] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4705.772783] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 4705.772892] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 4705.779943] Lustre: Skipped 1 previous similar message [ 4706.693660] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4734.440921] Lustre: DEBUG MARKER: == sanity-quota test 15: Set over 4T block quota ========= 17:45:09 (1786484709) [ 4748.899309] Lustre: DEBUG MARKER: == sanity-quota test 16a: lfs quota should skip the inactive MDT/OST ========================================================== 17:45:24 (1786484724) [ 4760.103576] Lustre: lustre-OST0000: Client 0e8b1f6b-a3dc-4a62-b0b7-12b139227521 (at 192.168.204.16@tcp) reconnecting [ 4781.339915] Lustre: DEBUG MARKER: == sanity-quota test 16b: lfs quota should skip the nonexistent MDT/OST ========================================================== 17:45:56 (1786484756) [ 4781.850285] Lustre: DEBUG MARKER: SKIP: sanity-quota test_16b needs >= 3 MDTs [ 4782.498798] Lustre: DEBUG MARKER: == sanity-quota test 17: DQACQ return recoverable error == 17:45:57 (1786484757) [ 4796.055806] Lustre: *** cfs_fail_loc=a04, val=37*** [ 4796.057535] LustreError: 6709:0:(qsd_handler.c:298:qsd_req_completion()) $$$ DQACQ failed with -37, flags:0x1 qsd:lustre-OST0000 qtype:usr lqe: ffff9514f5250f00 id:60000 enforced:1 granted: 0 pending:0 waiting:1 req:1 usage: 0 qunit:0 qtune:0 edquot:0 default:no revoke:0 [ 4797.140924] Lustre: *** cfs_fail_loc=a04, val=37*** [ 4797.142521] LustreError: 38932:0:(qsd_handler.c:298:qsd_req_completion()) $$$ DQACQ failed with -37, flags:0x1 qsd:lustre-OST0000 qtype:usr lqe: ffff9514f5250f00 id:60000 enforced:1 granted: 0 pending:0 waiting:1024 req:1 usage: 0 qunit:0 qtune:0 edquot:0 default:no revoke:0 [ 4834.874556] Lustre: *** cfs_fail_loc=a04, val=11*** [ 4875.092413] Lustre: *** cfs_fail_loc=a04, val=110*** [ 4875.093612] Lustre: Skipped 1 previous similar message [ 4915.063603] Lustre: *** cfs_fail_loc=a04, val=107*** [ 4915.065090] Lustre: Skipped 1 previous similar message [ 4980.729478] Lustre: DEBUG MARKER: == sanity-quota test 18: MDS failover while writing, no watchdog triggered (b14840) ========================================================== 17:49:15 (1786484955) [ 4990.973347] Lustre: DEBUG MARKER: User quota (limit: 200) [ 4992.788855] Lustre: DEBUG MARKER: Write 100M (buffered) ... [ 4993.788259] LustreError: 125969:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 4994.074233] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4994.608182] Lustre: DEBUG MARKER: Fail mds for 40 seconds [ 4995.248757] Lustre: Failing over lustre-MDT0000 [ 4995.618651] LustreError: lustre-MDT0000-lwp-OST0000: operation quota_acquire to node 0@lo failed: rc = -107 [ 4995.622573] 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 [ 4995.627863] LustreError: 93615:0:(ldlm_lib.c:1192: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. [ 4995.633421] LustreError: 93615:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 1 previous similar message [ 4997.143907] LustreError: 104496:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.204.16@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4997.148164] LustreError: 104496:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 2 previous similar messages [ 4997.693740] Lustre: server umount lustre-MDT0000 complete [ 5010.346526] LustreError: MGC192.168.204.116@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5010.531391] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 5010.560934] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 5011.904080] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5016.546176] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 5016.591726] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 5016.621232] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 5016.638797] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:823 to 0x240000400:865) [ 5016.639595] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:819 to 0x280000400:865) [ 5018.341690] Lustre: DEBUG MARKER: oleg416-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5018.865394] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5036.868578] Lustre: DEBUG MARKER: (dd_pid=116957, time=15, timeout=600) [ 5065.772784] Lustre: DEBUG MARKER: User quota (limit: 200) [ 5067.769368] Lustre: DEBUG MARKER: Write 100M (directio) ... [ 5068.912940] LustreError: 128931:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 5069.261669] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5069.838678] Lustre: DEBUG MARKER: Fail mds for 40 seconds [ 5070.552242] Lustre: Failing over lustre-MDT0000 [ 5070.711246] LustreError: lustre-MDT0000-lwp-OST0000: operation quota_acquire to node 0@lo failed: rc = -107 [ 5070.713917] 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 [ 5070.717402] Lustre: Skipped 1 previous similar message [ 5070.738243] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5070.903958] Lustre: server umount lustre-MDT0000 complete [ 5083.670215] LustreError: MGC192.168.204.116@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5083.851744] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 5083.878158] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 5084.189335] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 5084.226449] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 5084.244919] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:867 to 0x240000400:897) [ 5084.245211] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:819 to 0x280000400:897) [ 5085.280982] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5087.970566] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 5087.972450] Lustre: Skipped 1 previous similar message [ 5088.992139] Lustre: 3312:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786485048/real 1786485048] req@ffff9513c2835880 x1873260179967744/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786485064 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5089.160725] Lustre: DEBUG MARKER: oleg416-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5089.668269] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5093.088145] Lustre: 3312:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786485053/real 1786485053] req@ffff9514c33b9880 x1873260179968640/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786485069 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5099.488229] Lustre: 3311:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786485059/real 1786485059] req@ffff9514c8b67b80 x1873260179969152/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786485075 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5101.278077] Lustre: DEBUG MARKER: (dd_pid=119449, time=9, timeout=600) [ 5143.116384] Lustre: DEBUG MARKER: == sanity-quota test 19: Updating admin limits doesn't zero operational limits(b14790) ========================================================== 17:51:58 (1786485118) [ 5154.838812] Lustre: DEBUG MARKER: Files for user (quota_usr), count=1: [ 5155.389552] Lustre: DEBUG MARKER: Block quota isn't 0 (u:quota_usr:2). [ 5157.407086] Lustre: DEBUG MARKER: Files for user (quota_usr), count=1: [ 5157.992173] Lustre: DEBUG MARKER: Block quota isn't 0 (u:quota_usr:2). [ 5179.831686] Lustre: DEBUG MARKER: == sanity-quota test 20: Test if setquota specifiers work properly (b15754) ========================================================== 17:52:35 (1786485155) [ 5180.914293] LustreError: 3311:0:(qsd_reint.c:633:qqi_reint_delayed()) lustre-MDT0000: Delaying reintegration for qtype:0 until pending updates are flushed. [ 5189.443375] Lustre: DEBUG MARKER: == sanity-quota test 21: Setquota while writing [ 5198.190081] Lustre: DEBUG MARKER: Set limit(block:10G; file:1000000) for user: quota_usr [ 5198.711513] Lustre: DEBUG MARKER: Set limit(block:10G; file:1000000) for group: quota_usr [ 5199.228479] Lustre: DEBUG MARKER: Set limit(block:10G; file:) for project: 1000 [ 5199.901989] Lustre: DEBUG MARKER: Set quota for 1 times [ 5201.641137] Lustre: DEBUG MARKER: Set quota for 2 times [ 5203.327529] Lustre: DEBUG MARKER: Set quota for 3 times [ 5205.007662] Lustre: DEBUG MARKER: Set quota for 4 times [ 5206.772038] Lustre: DEBUG MARKER: Set quota for 5 times [ 5208.490499] Lustre: DEBUG MARKER: Set quota for 6 times [ 5210.203459] Lustre: DEBUG MARKER: Set quota for 7 times [ 5211.903592] Lustre: DEBUG MARKER: Set quota for 8 times [ 5213.697952] Lustre: DEBUG MARKER: Set quota for 9 times [ 5215.425842] Lustre: DEBUG MARKER: Set quota for 10 times [ 5217.062079] Lustre: DEBUG MARKER: Set quota for 11 times [ 5218.732207] Lustre: DEBUG MARKER: Set quota for 12 times [ 5220.427890] Lustre: DEBUG MARKER: Set quota for 13 times [ 5222.096591] Lustre: DEBUG MARKER: Set quota for 14 times [ 5223.802440] Lustre: DEBUG MARKER: Set quota for 15 times [ 5225.468193] Lustre: DEBUG MARKER: Set quota for 16 times [ 5227.161586] Lustre: DEBUG MARKER: Set quota for 17 times [ 5251.916722] Lustre: DEBUG MARKER: == sanity-quota test 22: enable/disable quota by 'lctl conf_param/set_param -P' ========================================================== 17:53:47 (1786485227) [ 5257.184504] 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 [ 5257.184725] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5257.188851] Lustre: Skipped 2 previous similar messages [ 5257.193310] Lustre: Skipped 1 previous similar message [ 5262.304620] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5262.306430] Lustre: Skipped 1 previous similar message [ 5262.766164] Lustre: server umount lustre-MDT0000 complete [ 5264.024753] LustreError: 104499:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1786485240 with bad export cookie 18062393697905994572 [ 5264.026603] LustreError: MGC192.168.204.116@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5264.028199] LustreError: 104499:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 5264.064330] Lustre: server umount lustre-OST0000 complete [ 5265.356397] Lustre: server umount lustre-OST0001 complete [ 5270.034828] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing load_modules_local [ 5273.608886] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 5275.028702] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5275.969988] Lustre: 139348:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 5277.984557] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 5279.953506] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5282.614392] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 5283.624486] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:899 to 0x280000400:929) [ 5283.625794] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:900 to 0x240000400:929) [ 5284.621222] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5287.625558] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5288.813701] Lustre: 141251:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 5297.135985] Lustre: server umount lustre-MDT0000 complete [ 5298.531752] LustreError: 141255:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1786485274 with bad export cookie 18062393697906003742 [ 5298.535111] LustreError: MGC192.168.204.116@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5308.925692] Lustre: server umount lustre-OST0000 complete [ 5320.536880] Lustre: server umount lustre-OST0001 complete [ 5325.223018] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing load_modules_local [ 5328.257772] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 5329.471966] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5330.349851] Lustre: 143952:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 5334.052520] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5338.436336] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5338.730419] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:899 to 0x280000400:961) [ 5338.730537] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:900 to 0x240000400:961) [ 5341.326755] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5342.506704] Lustre: 145841:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 5345.754061] Lustre: DEBUG MARKER: == sanity-quota test 23: Quota should be honored with directIO (b16125) ========================================================== 17:55:20 (1786485320) [ 5346.227182] Lustre: DEBUG MARKER: SKIP: sanity-quota test_23 Overwrite in place is not guaranteed to be space neutral on ZFS [ 5346.746326] Lustre: DEBUG MARKER: == sanity-quota test 24: lfs draws an asterix when limit is reached (b16646) ========================================================== 17:55:22 (1786485322) [ 5384.427320] Lustre: DEBUG MARKER: == sanity-quota test 25: check indexes versions ========== 17:55:59 (1786485359) [ 5401.728095] Lustre: DEBUG MARKER: Write... [ 5402.606308] Lustre: DEBUG MARKER: Write out of block quota ... [ 5435.994070] Lustre: DEBUG MARKER: == sanity-quota test 27a: lfs quota/setquota should handle wrong arguments (b19612) ========================================================== 17:56:51 (1786485411) [ 5438.156166] Lustre: DEBUG MARKER: == sanity-quota test 27b: lfs quota/setquota should handle user/group/project ID (b20200) ========================================================== 17:56:53 (1786485413) [ 5442.792802] Lustre: DEBUG MARKER: == sanity-quota test 27c: lfs quota should support human-readable output ========================================================== 17:56:57 (1786485417) [ 5447.405878] Lustre: DEBUG MARKER: == sanity-quota test 27d: lfs setquota should support fraction block limit ========================================================== 17:57:02 (1786485422) [ 5454.269168] Lustre: DEBUG MARKER: == sanity-quota test 30: Hard limit updates should not reset grace times ========================================================== 17:57:08 (1786485428) [ 5511.817148] Lustre: DEBUG MARKER: == sanity-quota test 33: Basic usage tracking for user [ 5611.678736] Lustre: DEBUG MARKER: == sanity-quota test 34: Usage transfer for user [ 5760.261992] Lustre: DEBUG MARKER: == sanity-quota test 35: Usage is still accessible across reboot ========================================================== 18:02:15 (1786485735) [ 5803.341256] Lustre: DEBUG MARKER: Restart... [ 5805.025370] 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 [ 5805.030982] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5805.033495] Lustre: Skipped 1 previous similar message [ 5810.145153] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5810.149744] Lustre: Skipped 1 previous similar message [ 5811.256545] Lustre: server umount lustre-MDT0000 complete [ 5813.089553] LustreError: 145843:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1786485789 with bad export cookie 18062393697906005261 [ 5813.090202] LustreError: MGC192.168.204.116@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5813.094360] LustreError: 145843:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 5813.143273] Lustre: server umount lustre-OST0000 complete [ 5815.061969] Lustre: server umount lustre-OST0001 complete [ 5822.088948] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing load_modules_local [ 5827.165482] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 5827.167927] Lustre: Skipped 2 previous similar messages [ 5829.165329] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5830.647774] Lustre: 165402:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 5837.419332] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5837.926735] LustreError: 165779:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 5837.952338] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:971 to 0x240000400:993) [ 5845.151301] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5847.528548] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:969 to 0x280000400:993) [ 5849.512701] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5851.199441] Lustre: 167314:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 5889.056604] Lustre: DEBUG MARKER: == sanity-quota test 37: Quota accounted properly for file created by 'lfs setstripe' ========================================================== 18:04:23 (1786485863) [ 5941.403444] Lustre: DEBUG MARKER: == sanity-quota test 38: Quota accounting iterator doesn't skip id entries ========================================================== 18:05:16 (1786485916) [ 6701.776485] Lustre: DEBUG MARKER: == sanity-quota test 39: Project ID interface works correctly ========================================================== 18:17:56 (1786486676) [ 6711.882676] Lustre: server umount lustre-MDT0000 complete [ 6713.274074] LustreError: 164958:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1786486689 with bad export cookie 18062393697906011582 [ 6713.277782] LustreError: MGC192.168.204.116@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 6723.589238] Lustre: server umount lustre-OST0000 complete [ 6735.324417] Lustre: server umount lustre-OST0001 complete [ 6740.646854] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing load_modules_local [ 6744.651910] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 6744.654372] Lustre: Skipped 2 previous similar messages [ 6746.214247] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6747.314293] Lustre: 175466:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 6749.811677] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 6752.040880] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6754.914798] LustreError: 175834:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 6754.924441] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5996 to 0x240000400:6017) [ 6757.829262] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6760.433523] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5994 to 0x280000400:6017) [ 6761.393619] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 6762.780722] Lustre: 177375:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 6790.782653] Lustre: DEBUG MARKER: == sanity-quota test 40a: Hard link across different project ID ========================================================== 18:19:25 (1786486765) [ 6822.109795] Lustre: DEBUG MARKER: == sanity-quota test 40b: Mv across different project ID ========================================================== 18:19:57 (1786486797) [ 6852.215775] Lustre: DEBUG MARKER: == sanity-quota test 40c: Remote child Dir inherit project quota properly ========================================================== 18:20:27 (1786486827) [ 6852.776349] Lustre: DEBUG MARKER: SKIP: sanity-quota test_40c needs >= 2 MDTs [ 6853.424142] Lustre: DEBUG MARKER: == sanity-quota test 40d: Stripe Directory inherit project quota properly ========================================================== 18:20:28 (1786486828) [ 6854.006403] Lustre: DEBUG MARKER: SKIP: sanity-quota test_40d needs >= 2 MDTs [ 6854.650001] Lustre: DEBUG MARKER: == sanity-quota test 41: df should return projid-specific values ========================================================== 18:20:29 (1786486829) [ 6907.739617] Lustre: DEBUG MARKER: == sanity-quota test 42: lfs quota should include default quota info ========================================================== 18:21:22 (1786486882) [ 6935.691336] Lustre: DEBUG MARKER: == sanity-quota test 48: lfs quota --delete should delete quota project ID ========================================================== 18:21:50 (1786486910) [ 6986.072766] Lustre: DEBUG MARKER: == sanity-quota test 49a: lfs quota -a prints the quota usage for all quota IDs ========================================================== 18:22:41 (1786486961) [ 6993.113538] Lustre: *** cfs_fail_loc=a09, val=0*** [ 6993.115092] Lustre: Skipped 1 previous similar message [ 6994.121263] Lustre: *** cfs_fail_loc=a09, val=0*** [ 6994.122402] Lustre: Skipped 183 previous similar messages [ 6996.125813] Lustre: *** cfs_fail_loc=a09, val=0*** [ 6996.127567] Lustre: Skipped 347 previous similar messages [ 7000.132209] Lustre: *** cfs_fail_loc=a09, val=0*** [ 7000.133659] Lustre: Skipped 683 previous similar messages [ 7008.139029] Lustre: *** cfs_fail_loc=a09, val=0*** [ 7008.140310] Lustre: Skipped 1081 previous similar messages [ 7024.151444] Lustre: *** cfs_fail_loc=a09, val=0*** [ 7024.153011] Lustre: Skipped 2553 previous similar messages [ 7134.189963] LustreError: 175019:0:(qsd_reint.c:633:qqi_reint_delayed()) lustre-MDT0000: Delaying reintegration for qtype:0 until pending updates are flushed. [ 7195.009640] LustreError: 175070:0:(qsd_reint.c:633:qqi_reint_delayed()) lustre-MDT0000: Delaying reintegration for qtype:0 until pending updates are flushed. [ 7195.015773] LustreError: 175070:0:(qsd_reint.c:633:qqi_reint_delayed()) Skipped 3 previous similar messages [ 7216.099650] 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 [ 7216.105479] Lustre: Skipped 1 previous similar message [ 7216.108213] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 7221.216668] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 7221.219567] Lustre: Skipped 2 previous similar messages [ 7222.469785] Lustre: server umount lustre-MDT0000 complete [ 7223.902913] LustreError: 175022:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1786487199 with bad export cookie 18062393697907769282 [ 7223.906797] LustreError: MGC192.168.204.116@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 7224.039812] Lustre: server umount lustre-OST0000 complete [ 7225.532832] Lustre: server umount lustre-OST0001 complete [ 7227.897791] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing set_hostid [ 7230.498041] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing load_modules_local [ 7234.233070] vdc: vdc1 vdc9 [ 7238.176661] vde: vde1 vde9 [ 7242.010989] vdf: vdf1 vdf9 [ 7247.790583] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing load_modules_local [ 7251.415731] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 7251.495157] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 7251.537445] Lustre: lustre-MDT0000: new disk, initializing [ 7251.646262] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 7251.648682] Lustre: Skipped 1 previous similar message [ 7251.672278] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 7253.233307] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7255.605497] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 7258.108792] Lustre: lustre-OST0000: new disk, initializing [ 7258.111140] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 7258.113701] Lustre: Skipped 1 previous similar message [ 7259.993845] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:0:ost [ 7259.998503] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:0:ost] [ 7260.037860] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x240000400 [ 7260.469315] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7264.698922] Lustre: lustre-OST0001: new disk, initializing [ 7264.700801] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 7266.761722] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:1:ost [ 7266.764923] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:1:ost] [ 7266.795445] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x280000400 [ 7266.935375] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7271.518174] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 7272.908050] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 7293.576922] Lustre: DEBUG MARKER: == sanity-quota test 49b: lfs quota -a --blocks has a delimiter ========================================================== 18:27:48 (1786487268) [ 7295.831574] Lustre: DEBUG MARKER: == sanity-quota test 50: Test if lfs find --projid works ========================================================== 18:27:51 (1786487271) [ 7327.095022] Lustre: DEBUG MARKER: == sanity-quota test 51: Test project accounting with mv/cp ========================================================== 18:28:22 (1786487302) [ 7363.680783] Lustre: DEBUG MARKER: == sanity-quota test 52: Rename normal file across project ID ========================================================== 18:28:58 (1786487338) [ 7376.687555] Lustre: DEBUG MARKER: rename directory return 255 [ 7402.840625] Lustre: DEBUG MARKER: == sanity-quota test 53: Project inherit attribute could be cleared ========================================================== 18:29:38 (1786487378) [ 7419.697458] Lustre: DEBUG MARKER: == sanity-quota test 54: basic lfs project interface test ========================================================== 18:29:54 (1786487394) [ 7438.866882] Lustre: DEBUG MARKER: == sanity-quota test 55: Chgrp should be affected by group quota ========================================================== 18:30:14 (1786487414) [ 7473.857716] LustreError: 192601:0:(qmt_entry.c:558:qmt_adjust_edquot()) $$$ set revoke_time explicitly qmt:lustre-QMT0000 pool:dt-0x0 id:60001 enforced:1 hard:51200 soft:0 granted:51200 time:0 qunit: 1024 edquot:0 may_rel:0 revoke:0 default:no [ 7497.161293] Lustre: DEBUG MARKER: == sanity-quota test 56: lfs quota -t should work well === 18:31:12 (1786487472) [ 7516.223228] Lustre: DEBUG MARKER: == sanity-quota test 57: lfs project could tolerate errors ========================================================== 18:31:31 (1786487491) [ 7547.622090] Lustre: DEBUG MARKER: == sanity-quota test 58: project ID should be kept for new mirrors created by FID ========================================================== 18:32:02 (1786487522) [ 7625.142592] Lustre: DEBUG MARKER: == sanity-quota test 59: lfs project dosen't crash kernel with project disabled ========================================================== 18:33:20 (1786487600) [ 7625.592185] Lustre: DEBUG MARKER: SKIP: sanity-quota test_59 ldiskfs only test [ 7626.120936] Lustre: DEBUG MARKER: == sanity-quota test 60: Test quota for root with setgid ========================================================== 18:33:21 (1786487601) [ 7660.565930] Lustre: DEBUG MARKER: SKIP: sanity-quota test_61 skipping SLOW test 61 [ 7661.116372] Lustre: DEBUG MARKER: == sanity-quota test 62: Project inherit should be only changed by root ========================================================== 18:33:56 (1786487636) [ 7678.578422] Lustre: DEBUG MARKER: SKIP: sanity-quota test_63 skipping excluded test 63 [ 7679.072199] Lustre: DEBUG MARKER: == sanity-quota test 64: lfs project on non-dir/files should succeed ========================================================== 18:34:14 (1786487654) [ 7709.566441] Lustre: DEBUG MARKER: SKIP: sanity-quota test_65 skipping excluded test 65 [ 7710.085201] Lustre: DEBUG MARKER: == sanity-quota test 66: nonroot user can not change project state in default ========================================================== 18:34:45 (1786487685) [ 7741.559599] Lustre: DEBUG MARKER: == sanity-quota test 67: quota pools recalculation ======= 18:35:16 (1786487716) [ 7742.066687] Lustre: DEBUG MARKER: SKIP: sanity-quota test_67 ZFS grants some block space together with inode [ 7742.646260] Lustre: DEBUG MARKER: == sanity-quota test 68: slave number in quota pool changed after each add/remove OST ========================================================== 18:35:17 (1786487717) [ 7757.994502] LustreError: 216675:0:(mgs_handler.c:1144:mgs_iocontrol_pool()) OBD_IOC_POOL err -17, cmd CE021 for pool lustre.qpool1 [ 7782.604318] Lustre: DEBUG MARKER: == sanity-quota test 69: EDQUOT at one of pools shouldn't affect DOM ========================================================== 18:35:57 (1786487757) [ 7797.218134] Lustre: DEBUG MARKER: User quota (block hardlimit:200 MB) [ 7797.775239] Lustre: DEBUG MARKER: User quota (block hardlimit:10 MB) [ 7849.387796] Lustre: DEBUG MARKER: == sanity-quota test 70a: check lfs setquota/quota with a pool option ========================================================== 18:37:04 (1786487824) [ 7878.534312] Lustre: DEBUG MARKER: == sanity-quota test 70b: lfs setquota pool works properly ========================================================== 18:37:33 (1786487853) [ 7894.244487] Lustre: DEBUG MARKER: == sanity-quota test 71a: Check PFL with quota pools ===== 18:37:49 (1786487869) [ 7894.732446] Lustre: DEBUG MARKER: SKIP: sanity-quota test_71a ZFS grants some block space together with inode [ 7895.275393] Lustre: DEBUG MARKER: == sanity-quota test 71b: Check SEL with quota pools ===== 18:37:50 (1786487870) [ 7895.775073] Lustre: DEBUG MARKER: SKIP: sanity-quota test_71b ZFS grants some block space together with inode [ 7896.289361] Lustre: DEBUG MARKER: == sanity-quota test 72: lfs quota --pool prints only pool's OSTs ========================================================== 18:37:51 (1786487871) [ 7904.784530] Lustre: DEBUG MARKER: User quota (block hardlimit:50 MB) [ 7912.610279] Lustre: DEBUG MARKER: Write... [ 7913.394923] Lustre: DEBUG MARKER: Write out of block quota ... [ 7947.504716] Lustre: DEBUG MARKER: == sanity-quota test 73a: default limits at OST Pool Quotas ========================================================== 18:38:42 (1786487922) [ 7962.462393] Lustre: DEBUG MARKER: set to use default quota [ 7963.001753] Lustre: DEBUG MARKER: set default quota [ 7963.516359] Lustre: DEBUG MARKER: get default quota [ 7965.390629] Lustre: DEBUG MARKER: Test not out of quota [ 7966.559548] Lustre: DEBUG MARKER: Test out of quota [ 7970.039939] Lustre: DEBUG MARKER: Increase default quota [ 7993.377287] Lustre: DEBUG MARKER: Set quota to override default quota [ 7993.397098] LustreError: 195571: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:45064 time:1787092769 qunit: 1024 edquot:0 may_rel:0 revoke:0 default:no [ 7997.060277] Lustre: DEBUG MARKER: Set to use default quota again [ 8006.493869] Lustre: DEBUG MARKER: Cleanup [ 8053.715511] Lustre: DEBUG MARKER: == sanity-quota test 73b: default OST Pool Quotas limit for new user ========================================================== 18:40:28 (1786488028) [ 8067.873866] Lustre: DEBUG MARKER: set default quota for qpool1 [ 8068.418660] Lustre: DEBUG MARKER: Write from user that hasn't lqe [ 8098.543681] Lustre: DEBUG MARKER: == sanity-quota test 74: check quota pools per user ====== 18:41:13 (1786488073) [ 8141.195905] Lustre: DEBUG MARKER: == sanity-quota test 75: nodemap squashed root respects quota enforcement ========================================================== 18:41:56 (1786488116) [ 8180.433540] Lustre: DEBUG MARKER: Write... [ 8181.451954] Lustre: DEBUG MARKER: Write out of block quota ... [ 8249.273136] Lustre: DEBUG MARKER: == sanity-quota test 76: project ID 4294967295 should be not allowed ========================================================== 18:43:44 (1786488224) [ 8278.650362] Lustre: DEBUG MARKER: == sanity-quota test 77: lfs setquota should fail in Lustre mount with 'ro' ========================================================== 18:44:13 (1786488253) [ 8280.885622] Lustre: DEBUG MARKER: == sanity-quota test 78A: Check fallocate increase quota usage ========================================================== 18:44:16 (1786488256) [ 8281.421703] Lustre: DEBUG MARKER: SKIP: sanity-quota test_78A need >= 2.13.57 and ldiskfs for fallocate [ 8281.943896] Lustre: DEBUG MARKER: == sanity-quota test 78a: Check fallocate increase projectid usage ========================================================== 18:44:17 (1786488257) [ 8282.436221] Lustre: DEBUG MARKER: SKIP: sanity-quota test_78a need >= 2.13.57 and ldiskfs for fallocate [ 8282.979230] Lustre: DEBUG MARKER: == sanity-quota test 79: access to non-existed dt-pool/info doesn't cause a panic ========================================================== 18:44:18 (1786488258) [ 8291.727906] Lustre: DEBUG MARKER: == sanity-quota test 80: check for EDQUOT after OST failover ========================================================== 18:44:26 (1786488266) [ 8292.233150] Lustre: DEBUG MARKER: SKIP: sanity-quota test_80 ZFS grants some block space together with inode [ 8292.728103] Lustre: DEBUG MARKER: == sanity-quota test 81: Race qmt_start_pool_recalc with qmt_pool_free ========================================================== 18:44:28 (1786488268) [ 8301.544213] Lustre: DEBUG MARKER: User quota (block hardlimit:20 MB) [ 8305.458937] LustreError: 243125:0:(qmt_pool.c:1407:qmt_pool_recalc()) cfs_fail_timeout id a07 sleeping for 10000ms [ 8308.757201] Lustre: lustre-MDT0000: Not available for connect from 192.168.204.16@tcp (stopping) [ 8311.265061] 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 [ 8311.265553] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 8311.268246] Lustre: Skipped 2 previous similar messages [ 8313.871775] Lustre: lustre-MDT0000: Not available for connect from 192.168.204.16@tcp (stopping) [ 8313.874074] Lustre: Skipped 1 previous similar message [ 8315.528174] LustreError: 243125:0:(qmt_pool.c:1407:qmt_pool_recalc()) cfs_fail_timeout id a07 awake [ 8315.641415] Lustre: server umount lustre-MDT0000 complete [ 8318.296675] LustreError: MGC192.168.204.116@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 8318.460126] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 8318.462093] Lustre: Skipped 2 previous similar messages [ 8318.503052] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:27 to 0x280000400:65) [ 8318.503094] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:27 to 0x240000400:65) [ 8319.794729] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 8331.747328] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 8331.750698] Lustre: Skipped 1 previous similar message [ 8337.119326] Lustre: DEBUG MARKER: == sanity-quota test 82: verify more than 8 qids for single operation ========================================================== 18:45:12 (1786488312) [ 8355.346126] Lustre: DEBUG MARKER: == sanity-quota test 83: Setting default quota shouldn't affect grace time ========================================================== 18:45:30 (1786488330) [ 8373.269114] Lustre: DEBUG MARKER: == sanity-quota test 84: Reset quota should fix the insane granted quota ========================================================== 18:45:48 (1786488348) [ 8396.208207] Lustre: *** cfs_fail_loc=a08, val=0*** [ 8396.210139] Lustre: Skipped 3147 previous similar messages [ 8396.212686] Lustre: *** cfs_fail_loc=a08, val=0*** [ 8443.728235] Lustre: DEBUG MARKER: == sanity-quota test 85: do not hung at write with the least_qunit ========================================================== 18:46:58 (1786488418) [ 8492.001398] Lustre: DEBUG MARKER: == sanity-quota test 86: Pre-acquired quota should be released if quota is over limit ========================================================== 18:47:47 (1786488467) [ 8519.106190] LustreError: 244114: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:1787093295 qunit: 1024 edquot:0 may_rel:0 revoke:0 default:no [ 8567.846510] LustreError: 244871: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:1787093343 qunit: 1024 edquot:0 may_rel:0 revoke:0 default:no [ 8621.445796] LustreError: 243703: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:1787093397 qunit: 1024 edquot:0 may_rel:0 revoke:0 default:no [ 8670.197248] Lustre: DEBUG MARKER: == sanity-quota test 87: lfs quota -a should print default quota setting ========================================================== 18:50:45 (1786488645) [ 8677.339665] Lustre: *** cfs_fail_loc=a09, val=0*** [ 8702.997656] Lustre: lustre-MDT0000: Not available for connect from 192.168.204.16@tcp (stopping) [ 8705.506064] 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 [ 8705.516350] Lustre: Skipped 1 previous similar message [ 8708.086357] Lustre: server umount lustre-MDT0000 complete [ 8710.785137] LustreError: MGC192.168.204.116@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 8710.955089] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 8710.995681] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:67 to 0x240000400:97) [ 8710.999398] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:67 to 0x280000400:97) [ 8712.393580] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 8725.475587] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 8725.478759] Lustre: Skipped 1 previous similar message [ 8731.965574] Lustre: DEBUG MARKER: == sanity-quota test 88: Writing over quota should not hang ========================================================== 18:51:47 (1786488707) [ 8732.495486] Lustre: DEBUG MARKER: SKIP: sanity-quota test_88 require client with >4k pages [ 8733.049753] Lustre: DEBUG MARKER: == sanity-quota test 89: Show default quota with squash_uid ========================================================== 18:51:48 (1786488708) [ 8740.054453] Lustre: DEBUG MARKER: == sanity-quota test 90a: lfs quota should work without mount point ========================================================== 18:51:55 (1786488715) [ 8750.189994] Lustre: DEBUG MARKER: == sanity-quota test 90b: lfs quota should work with multiple mount points ========================================================== 18:52:05 (1786488725) [ 8761.113106] Lustre: DEBUG MARKER: == sanity-quota test 91: new quota index files in quota_master ========================================================== 18:52:16 (1786488736) [ 8774.940605] Lustre: server umount lustre-MDT0000 complete [ 8776.291945] LustreError: 193464:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1786488752 with bad export cookie 18062393697909272672 [ 8776.296210] LustreError: MGC192.168.204.116@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 8788.979970] Lustre: server umount lustre-OST0000 complete [ 8806.742508] Lustre: server umount lustre-OST0001 complete [ 8809.198634] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing set_hostid [ 8811.873991] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing load_modules_local [ 8815.484141] vdc: vdc1 vdc9 [ 8818.595721] vde: vde1 vde9 [ 8822.199298] vdf: vdf1 vdf9 [ 8825.546912] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 8825.626773] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 8825.661749] Lustre: lustre-MDT0000: new disk, initializing [ 8825.748689] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 8825.766155] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 8827.096702] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 8830.768843] Lustre: DEBUG MARKER: oleg416-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 8832.799692] Lustre: lustre-OST0000: new disk, initializing [ 8832.802523] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 8832.804460] Lustre: Skipped 1 previous similar message [ 8834.512609] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:0:ost [ 8834.515051] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:0:ost] [ 8834.549946] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x240000400 [ 8834.767023] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 8838.463181] Lustre: DEBUG MARKER: oleg416-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 8840.646025] Lustre: lustre-OST0001: new disk, initializing [ 8840.647469] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 8840.682329] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 8840.686366] Lustre: Skipped 1 previous similar message [ 8842.635477] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:1:ost [ 8842.638314] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:1:ost] [ 8842.668254] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x280000400 [ 8842.785770] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 8846.480882] Lustre: DEBUG MARKER: oleg416-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0001-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 8853.261489] 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 [ 8853.265233] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 8853.266867] Lustre: Skipped 3 previous similar messages [ 8859.451894] Lustre: server umount lustre-MDT0000 complete [ 8862.882172] LustreError: MGC192.168.204.116@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 8863.016056] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 8864.342835] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 8866.748130] Lustre: DEBUG MARKER: oleg416-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 8868.322966] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 8868.325627] Lustre: Skipped 1 previous similar message [ 8877.625415] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 10 sec [ 8883.680612] 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 [ 8883.681117] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 8883.688727] Lustre: Skipped 2 previous similar messages [ 8883.693883] Lustre: Skipped 4 previous similar messages [ 8886.058433] Lustre: server umount lustre-MDT0000 complete [ 8887.924416] LustreError: 263035:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1786488863 with bad export cookie 18062393697909275066 [ 8887.924548] LustreError: MGC192.168.204.116@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 8887.931546] LustreError: 263035:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 8887.991605] Lustre: server umount lustre-OST0000 complete [ 8890.399505] Lustre: server umount lustre-OST0001 complete [ 8900.258700] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing set_hostid [ 8904.826328] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing load_modules_local [ 8911.188177] vdc: vdc1 vdc9 [ 8917.323492] vde: vde1 vde9 [ 8923.648485] vdf: vdf1 vdf9 [ 8923.682195] vdf: vdf1 vdf9 [ 8933.188773] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing load_modules_local [ 8939.233989] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 8939.396252] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 8939.441398] Lustre: lustre-MDT0000: new disk, initializing [ 8939.681158] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 8939.723139] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 8942.178777] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 8945.367379] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 8948.807742] Lustre: lustre-OST0000: new disk, initializing [ 8948.810780] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 8948.814555] Lustre: Skipped 1 previous similar message [ 8950.483614] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:0:ost [ 8950.489424] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:0:ost] [ 8950.602662] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x240000400 [ 8952.211844] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 8957.405973] Lustre: lustre-OST0001: new disk, initializing [ 8957.407867] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 8958.682215] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:1:ost [ 8958.686138] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:1:ost] [ 8958.723537] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x280000400 [ 8959.807056] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 8964.734182] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 8966.132230] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 8969.273773] Lustre: DEBUG MARKER: == sanity-quota test 92: Cannot set inode limit with Quota Pools ========================================================== 18:55:44 (1786488944) [ 8978.142698] Lustre: DEBUG MARKER: == sanity-quota test 93: update projid while client write to OST ========================================================== 18:55:53 (1786488953) [ 8995.524076] Lustre: *** cfs_fail_loc=170c, val=0*** [ 9033.237726] Lustre: DEBUG MARKER: == sanity-quota test 94: lfs quota all respects nodemap offset ========================================================== 18:56:48 (1786489008) [ 9049.115130] Lustre: lustre-MDT0000: Not available for connect from 192.168.204.16@tcp (stopping) [ 9051.104566] 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 [ 9051.109391] Lustre: Skipped 1 previous similar message [ 9054.243573] Lustre: server umount lustre-MDT0000 complete [ 9058.257432] LustreError: MGC192.168.204.116@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 9058.500283] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 9058.503553] Lustre: Skipped 2 previous similar messages [ 9058.565948] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3 to 0x240000400:33) [ 9060.653853] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 9076.837630] Lustre: server umount lustre-MDT0000 complete [ 9080.828658] LustreError: MGC192.168.204.116@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 9081.137675] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3 to 0x240000400:65) [ 9083.174776] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 9086.436568] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 9086.441564] Lustre: Skipped 1 previous similar message [ 9095.058642] Lustre: DEBUG MARKER: == sanity-quota test 95a: Correct limits for squashed root ========================================================== 18:57:50 (1786489070) [ 9108.480224] Lustre: DEBUG MARKER: == sanity-quota test 95b: df respects squashed project id ========================================================== 18:58:03 (1786489083) [ 9136.047306] Lustre: DEBUG MARKER: == sanity-quota test 96: quota grant should be released when big files are deleted ========================================================== 18:58:31 (1786489111) [ 9136.700199] Lustre: DEBUG MARKER: SKIP: sanity-quota test_96 the test in only needed to run on LDiskFS [ 9137.415497] Lustre: DEBUG MARKER: == sanity-quota test 97a: LQA control commands =========== 18:58:32 (1786489112) [ 9151.339659] LustreError: 280991:0:(qmt_lqa.c:79:qmt_lqa_destroy()) lustre-QMT0000: cannot destroy lqa-dt-lqa1: rc = -2 [ 9151.345700] LustreError: 280991:0:(qmt_lqa.c:84:qmt_lqa_destroy()) lustre-QMT0000: cannot destroy lqa-md-lqa1: rc = -2 [ 9152.653510] Lustre: DEBUG MARKER: == sanity-quota test 97b: Check LQA internals ============ 18:58:47 (1786489127) [ 9169.647827] LustreError: 281782:0:(qmt_lqa.c:250:qmt_lqa_insert_range()) lustre-QMT0000: LQA range 15-31 partially overlaps with existing range 10-19: rc = -34 [ 9169.656557] LustreError: 281782:0:(qmt_lqa.c:669:qmt_lqa_add()) lustre-QMT0000: lqa:lqa1 can't add range 15:31: rc = -17 [ 9172.565988] LustreError: 281979:0:(qmt_lqa.c:825:qmt_lqa_remove()) lustre-QMT0000: lqa-md-lqa1 cannot remove range 10:19: rc = -2 [ 9181.913519] Lustre: DEBUG MARKER: adding 50 LQA ranges took 2s [ 9186.568095] Lustre: DEBUG MARKER: Removing 50 LQA ranges took 1s [ 9196.268652] Lustre: DEBUG MARKER: == sanity-quota test 97c: LQA lfs quota commands and MDS restart consistency ========================================================== 18:59:30 (1786489170) [ 9200.993355] Lustre: Failing over lustre-MDT0000 [ 9201.364960] Lustre: server umount lustre-MDT0000 complete [ 9208.392544] LustreError: MGC192.168.204.116@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 9208.648481] Lustre: 283842:0:(scrub.c:694:lustre_index_register()) lustre-MDT0000: the index [0x200000003:0x74:0x0] has registered with 8/8, may be invalid, replace with 4/8 [ 9208.670546] 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 [ 9208.680756] Lustre: Skipped 1 previous similar message [ 9208.808428] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 9208.815280] Lustre: Skipped 1 previous similar message [ 9208.868179] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 9211.942786] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 9212.064547] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 9212.111561] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3 to 0x240000400:97) [ 9212.473881] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 9213.926932] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 9213.930794] Lustre: Skipped 1 previous similar message [ 9216.529696] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 9220.064249] Lustre: 3311:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786489180/real 1786489180] req@ffff9514fd55c700 x1873260189363840/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786489196 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 9220.096592] Lustre: 3311:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 9222.445923] Lustre: DEBUG MARKER: == sanity-quota test 97d: LQA disk persistence using standard commands ========================================================== 18:59:57 (1786489197) [ 9238.816481] Lustre: Failing over lustre-MDT0000 [ 9239.113390] Lustre: server umount lustre-MDT0000 complete [ 9245.361698] Lustre: 285898:0:(scrub.c:694:lustre_index_register()) lustre-MDT0000: the index [0x200000003:0x88:0x0] has registered with 8/8, may be invalid, replace with 4/8 [ 9245.568437] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 9247.781085] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 9247.839146] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 9247.879381] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3 to 0x240000400:129) [ 9249.153761] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 9253.121204] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 9255.904243] Lustre: 3309:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786489215/real 1786489215] req@ffff9513c3349880 x1873260189378176/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786489231 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 9255.924911] Lustre: 3309:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 9261.025331] Lustre: 3312:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786489220/real 1786489220] req@ffff9514ca7d3b80 x1873260189378432/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786489236 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 9285.571529] Lustre: DEBUG MARKER: == sanity-quota test 98: Verify MDT retry on -EDQUOT during mkdir ========================================================== 19:01:00 (1786489260) [ 9287.169455] Lustre: DEBUG MARKER: SKIP: sanity-quota test_98 needs >= 2 MDTs [ 9288.487564] Lustre: DEBUG MARKER: == sanity-quota test 300: inode quota with MDT directory migration at 80% limit ========================================================== 19:01:03 (1786489263) [ 9289.613626] Lustre: DEBUG MARKER: SKIP: sanity-quota test_300 needs >= 2 MDTs [ 9293.316274] Lustre: DEBUG MARKER: == sanity-quota test complete, duration 8961 sec ========= 19:01:07 (1786489267) [ 9294.629159] Lustre: DEBUG MARKER: === sanity-quota: start cleanup 19:01:09 (1786489269) === [ 9297.098624] Lustre: DEBUG MARKER: === sanity-quota: finish cleanup 19:01:11 (1786489271) === [ 9301.907763] Lustre: server umount lustre-MDT0000 complete [ 9304.765445] LustreError: 268448:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1786489280 with bad export cookie 18062393697909280512 [ 9304.779961] LustreError: MGC192.168.204.116@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 9304.785057] LustreError: Skipped 1 previous similar message [ 9314.345193] Lustre: server umount lustre-OST0000 complete [ 9326.210890] Lustre: server umount lustre-OST0001 complete [ 9335.035670] Lustre: DEBUG MARKER: oleg416-server.virtnet: executing unload_modules_local [ 9337.183258] Key type lgssc unregistered [ 9337.410164] LNet: 289162:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 9337.416416] LNetError: 289162:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 9337.431486] LNet: Removed LNI 192.168.204.116@tcp [ 9337.950371] Key type .llcrypt unregistered [ 9337.952555] Key type ._llcrypt unregistered