[ 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 502058326 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2399.998 MHz processor [ 0.000000] last_pfn = 0x146e00 max_arch_pfn = 0x400000000 [ 0.000000] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT [ 0.000000] last_pfn = 0xbffce max_arch_pfn = 0x400000000 [ 0.000000] found SMP MP-table at [mem 0x000f54b0-0x000f54bf] [ 0.000000] RAMDISK: [mem 0xbcc54000-0xbffbffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F52D0 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE247C 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE2318 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 0022D8 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE238C 000090 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE241C 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE2454 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe2318-0xbffe238b] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe2317] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe238c-0xbffe241b] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe241c-0xbffe2453] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe2454-0xbffe247b] [ 0.000000] No NUMA configuration found [ 0.000000] Faking a node at [mem 0x0000000000000000-0x0000000146dfffff] [ 0.000000] NODE_DATA(0) allocated [mem 0x1465a3000-0x1465cdfff] [ 0.000000] Reserving 256MB of memory at 2752MB for crashkernel (System RAM: 4205MB) [ 0.000000] Zone ranges: [ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.000000] DMA32 [mem 0x0000000001000000-0x00000000ffffffff] [ 0.000000] Normal [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Device empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff] [ 0.000000] node 0: [mem 0x0000000000100000-0x00000000bffcdfff] [ 0.000000] node 0: [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Zeroed struct page in unavailable ranges: 4756 pages [ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x0000000146dfffff] [ 0.000000] ACPI: PM-Timer IO Port: 0x608 [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) [ 0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) [ 0.000000] Using ACPI (MADT) for SMP configuration information [ 0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000] TSC deadline timer available [ 0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs [ 0.000000] kvm-guest: KVM setup pv remote TLB flush [ 0.000000] kvm-guest: setup PV sched yield [ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff] [ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff] [ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff] [ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff] [ 0.000000] PM: Registered nosave memory: [mem 0xbffce000-0xbfffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xc0000000-0xfeffbfff] [ 0.000000] PM: Registered nosave memory: [mem 0xfeffc000-0xfeffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xff000000-0xfffbffff] [ 0.000000] PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff] [ 0.000000] [mem 0xc0000000-0xfeffbfff] available for PCI devices [ 0.000000] Booting paravirtualized kernel on KVM [ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns [ 0.000000] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1 [ 0.000000] percpu: Embedded 63 pages/cpu s221184 r8192 d28672 u524288 [ 0.000000] kvm-guest: PV spinlocks enabled [ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1059606 [ 0.000000] Policy zone: Normal [ 0.000000] Kernel command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] Specific versions of hardware are certified with Red Hat Enterprise Linux 8. Please see the list of hardware certified with Red Hat Enterprise Linux 8 at https://catalog.redhat.com. [ 0.000000] audit: disabled (until reboot) [ 0.000000] software IO TLB: area num 4. [ 0.000000] Memory: 2829652K/4306352K available (18435K kernel code, 11221K rwdata, 7248K rodata, 2908K init, 18040K bss, 524580K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] ftrace: allocating 41240 entries in 162 pages [ 0.000000] ftrace: allocated 162 pages with 3 groups [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] rcu: RCU event tracing is enabled. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ 0.000000] rcu: RCU callback double-/use-after-free debug enabled. [ 0.000000] Rude variant of Tasks RCU enabled. [ 0.000000] Tracing variant of Tasks RCU enabled. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 0.000000] NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16 [ 0.000000] random: get_random_bytes called from start_kernel+0x622/0x9a8 with crng_init=0 [ 0.001000] Console: colour *CGA 80x25 [ 0.001000] printk: console [ttyS1] enabled [ 0.001000] ACPI: Core revision 20220331 [ 0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.001010] APIC: Switch to symmetric I/O mode setup [ 0.003246] x2apic enabled [ 0.004010] Switched APIC routing to physical x2apic. [ 0.005016] kvm-guest: setup PV IPIs [ 0.008676] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.009000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.009020] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.010012] pid_max: default: 32768 minimum: 301 [ 0.011128] LSM: Security Framework initializing [ 0.012000] Yama: becoming mindful. [ 0.012041] SELinux: Initializing. [ 0.013068] *** VALIDATE selinux *** [ 0.022005] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.026730] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.027156] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.028113] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.029112] *** VALIDATE tmpfs *** [ 0.030472] *** VALIDATE proc *** [ 0.032202] *** VALIDATE cgroup *** [ 0.033010] *** VALIDATE cgroup2 *** [ 0.035035] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.036174] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.037009] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.038031] Spectre V2 : User space: Vulnerable [ 0.039010] Speculative Store Bypass: Vulnerable [ 0.042410] debug: unmapping init [mem 0xffffffff92459000-0xffffffff92460fff] [ 0.045170] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.046677] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.047025] ... version: 2 [ 0.048012] ... bit width: 48 [ 0.049018] ... generic registers: 4 [ 0.050012] ... value mask: 0000ffffffffffff [ 0.051014] ... max period: 00007fffffffffff [ 0.052016] ... fixed-purpose events: 3 [ 0.053012] ... event mask: 000000070000000f [ 0.054265] rcu: Hierarchical SRCU implementation. [ 0.056430] smp: Bringing up secondary CPUs ... [ 0.057559] x86: Booting SMP configuration: [ 0.058025] .... node #0, CPUs: #1 #2 #3 [ 0.061685] smp: Brought up 1 node, 4 CPUs [ 0.063020] smpboot: Max logical packages: 1 [ 0.064014] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.136876] node 0 deferred pages initialised in 69ms [ 0.140120] devtmpfs: initialized [ 0.141668] x86/mm: Memory block size: 128MB [ 0.146000] gcov: version magic: 0x41383552 [ 0.148183] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.151159] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.154267] pinctrl core: initialized pinctrl subsystem [ 0.156191] [ 0.156772] ************************************************************* [ 0.159018] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.162014] ** ** [ 0.165012] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.167012] ** ** [ 0.170013] ** This means that this kernel is built to expose internal ** [ 0.173015] ** IOMMU data structures, which may compromise security on ** [ 0.175010] ** your system. ** [ 0.177013] ** ** [ 0.180014] ** If you see this message and you are not debugging the ** [ 0.182013] ** kernel, report this immediately to your vendor! ** [ 0.184015] ** ** [ 0.187020] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.189010] ************************************************************* [ 0.191669] NET: Registered protocol family 16 [ 0.193494] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.196054] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.199067] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.202112] cpuidle: using governor menu [ 0.203730] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.206591] PCI: Using configuration type 1 for base access [ 0.208122] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.219210] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.221018] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.225054] cryptd: max_cpu_qlen set to 1000 [ 0.229295] ACPI: Added _OSI(Module Device) [ 0.230028] ACPI: Added _OSI(Processor Device) [ 0.231000] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.233015] ACPI: Added _OSI(Processor Aggregator Device) [ 0.237295] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.244548] ACPI: Interpreter enabled [ 0.246055] ACPI: PM: (supports S0 S3 S4 S5) [ 0.247010] ACPI: Using IOAPIC for interrupt routing [ 0.249128] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.252446] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.264102] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.266035] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.269022] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.274092] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.280388] acpiphp: Slot [2] registered [ 0.282177] acpiphp: Slot [5] registered [ 0.283243] acpiphp: Slot [6] registered [ 0.285118] acpiphp: Slot [7] registered [ 0.287115] acpiphp: Slot [8] registered [ 0.288117] acpiphp: Slot [9] registered [ 0.290130] acpiphp: Slot [10] registered [ 0.291165] acpiphp: Slot [3] registered [ 0.293125] acpiphp: Slot [4] registered [ 0.294115] acpiphp: Slot [11] registered [ 0.296096] acpiphp: Slot [12] registered [ 0.297107] acpiphp: Slot [13] registered [ 0.299109] acpiphp: Slot [14] registered [ 0.300112] acpiphp: Slot [15] registered [ 0.302175] acpiphp: Slot [16] registered [ 0.303100] acpiphp: Slot [17] registered [ 0.305087] acpiphp: Slot [18] registered [ 0.306104] acpiphp: Slot [19] registered [ 0.308175] acpiphp: Slot [20] registered [ 0.310110] acpiphp: Slot [21] registered [ 0.311167] acpiphp: Slot [22] registered [ 0.313129] acpiphp: Slot [23] registered [ 0.315107] acpiphp: Slot [24] registered [ 0.316203] acpiphp: Slot [25] registered [ 0.318098] acpiphp: Slot [26] registered [ 0.320091] acpiphp: Slot [27] registered [ 0.321094] acpiphp: Slot [28] registered [ 0.323129] acpiphp: Slot [29] registered [ 0.324098] acpiphp: Slot [30] registered [ 0.326101] acpiphp: Slot [31] registered [ 0.328060] PCI host bridge to bus 0000:00 [ 0.329059] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.332025] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.335021] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.337021] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.340021] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.343027] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.345193] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.349055] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.352530] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.364837] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.368627] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.371017] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.373015] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.376017] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.381599] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.383712] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.386034] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.389378] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.395015] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.409014] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.414014] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.423301] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.431020] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.435000] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.452018] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.461973] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.472014] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.489022] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.519015] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.534774] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.540019] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.546016] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.571015] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.588372] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.598014] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.608019] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.631017] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.642044] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.653016] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.662019] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.695025] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 0.707970] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.718021] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.727022] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.745027] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 0.758584] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.761480] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.763368] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.766473] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.768237] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.773043] iommu: Default domain type: Passthrough [ 0.775327] SCSI subsystem initialized [ 0.777173] ACPI: bus type USB registered [ 0.779743] usbcore: registered new interface driver usbfs [ 0.781082] usbcore: registered new interface driver hub [ 0.783083] usbcore: registered new device driver usb [ 0.785173] pps_core: LinuxPPS API ver. 1 registered [ 0.787264] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.790061] PTP clock support registered [ 0.793128] EDAC MC: Ver: 3.0.0 [ 0.795299] PCI: Using ACPI for IRQ routing [ 0.796727] NetLabel: Initializing [ 0.797000] NetLabel: domain hash size = 128 [ 0.799011] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.801092] NetLabel: unlabeled traffic allowed by default [ 0.803299] vgaarb: loaded [ 0.805263] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.807014] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.813000] clocksource: Switched to clocksource kvm-clock [ 0.924882] VFS: Disk quotas dquot_6.6.0 [ 0.926441] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.928896] *** VALIDATE ramfs *** [ 0.930256] *** VALIDATE hugetlbfs *** [ 0.932172] pnp: PnP ACPI init [ 0.934977] pnp: PnP ACPI: found 6 devices [ 0.951189] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.954351] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.956824] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.959049] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.961605] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.963941] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.966939] NET: Registered protocol family 2 [ 0.969492] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.974018] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.977784] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.982515] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.986834] TCP: Hash tables configured (established 65536 bind 65536) [ 0.990373] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.993561] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.996504] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 1.000100] NET: Registered protocol family 1 [ 1.004050] RPC: Registered named UNIX socket transport module. [ 1.006391] RPC: Registered udp transport module. [ 1.007839] RPC: Registered tcp transport module. [ 1.009637] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 1.011604] NET: Registered protocol family 44 [ 1.013631] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 1.016319] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 1.018558] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 1.021069] PCI: CLS 0 bytes, default 64 [ 1.023171] Unpacking initramfs... [ 2.437790] debug: unmapping init [mem 0xffff92ae3cc54000-0xffff92ae3ffbffff] [ 2.441472] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.443498] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.445865] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 2.932717] Initialise system trusted keyrings [ 2.934074] Key type blacklist registered [ 2.935697] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.944089] zbud: loaded [ 2.947032] *** VALIDATE nfs *** [ 2.948057] *** VALIDATE nfs4 *** [ 2.949324] pstore: using deflate compression [ 2.952342] Platform Keyring initialized [ 3.065804] NET: Registered protocol family 38 [ 3.067513] Key type asymmetric registered [ 3.069351] Asymmetric key parser 'x509' registered [ 3.072440] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 3.075249] io scheduler mq-deadline registered [ 3.076803] io scheduler kyber registered [ 3.078542] io scheduler bfq registered [ 3.080730] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 3.084171] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 3.086947] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 3.089724] ACPI: Power Button [PWRF] [ 3.095629] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 3.103625] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 3.127319] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 3.137098] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 3.165679] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 3.193499] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.221378] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.226168] Non-volatile memory driver v1.3 [ 3.227863] Linux agpgart interface v0.103 [ 3.259845] virtio_blk virtio1: [vda] 146712 512-byte logical blocks (75.1 MB/71.6 MiB) [ 3.262837] vda: detected capacity change from 0 to 75116544 [ 3.286514] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.289052] vdb: detected capacity change from 0 to 1073741824 [ 3.306032] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.308711] vdc: detected capacity change from 0 to 2621440000 [ 3.327455] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.330112] vdd: detected capacity change from 0 to 2621440000 [ 3.346585] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.349292] vde: detected capacity change from 0 to 4294967296 [ 3.367193] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.370969] vdf: detected capacity change from 0 to 4294967296 [ 3.382649] libphy: Fixed MDIO Bus: probed [ 3.389218] usbcore: registered new interface driver usbserial_generic [ 3.391555] usbserial: USB Serial support registered for generic [ 3.393420] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.399055] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.400181] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.402218] mousedev: PS/2 mouse device common for all mice [ 3.405189] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.407127] rtc_cmos 00:05: RTC can wake from S4 [ 3.417204] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.420419] rtc_cmos 00:05: registered as rtc0 [ 3.424496] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.427131] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.428075] intel_pstate: CPU model not supported [ 3.436152] hid: raw HID events driver (C) Jiri Kosina [ 3.438419] usbcore: registered new interface driver usbhid [ 3.440534] usbhid: USB HID core driver [ 3.443777] drop_monitor: Initializing network drop monitor service [ 3.447502] Initializing XFRM netlink socket [ 3.450485] NET: Registered protocol family 10 [ 3.454415] Segment Routing with IPv6 [ 3.456620] NET: Registered protocol family 17 [ 3.459783] mpls_gso: MPLS GSO support [ 3.466291] RAS: Correctable Errors collector initialized. [ 3.468053] AVX version of gcm_enc/dec engaged. [ 3.469880] AES CTR mode by8 optimization enabled [ 3.553813] sched_clock: Marking stable (3553787244, 0)->(4487280672, -933493428) [ 3.557937] registered taskstats version 1 [ 3.560443] Loading compiled-in X.509 certificates [ 3.562827] zswap: loaded using pool lzo/zbud [ 3.588408] Key type big_key registered [ 3.601217] Key type encrypted registered [ 3.604082] ima: No TPM chip found, activating TPM-bypass! [ 3.607875] ima: Allocated hash algorithm: sha1 [ 3.611198] ima: No architecture policies found [ 3.612874] evm: Initialising EVM extended attributes: [ 3.614756] evm: security.selinux [ 3.616524] evm: security.ima [ 3.617703] evm: security.capability [ 3.619118] evm: HMAC attrs: 0x1 [ 3.621962] rtc_cmos 00:05: setting system clock to 2026-09-08 04:55:06 UTC (1788843306) [ 3.628596] debug: unmapping init [mem 0xffffffff93403000-0xffffffff935fffff] [ 3.632385] debug: unmapping init [mem 0xffffffff92182000-0xffffffff92458fff] [ 3.642185] Write protecting the kernel read-only data: 28672k [ 3.645976] debug: unmapping init [mem 0xffffffff90803000-0xffffffff909fffff] [ 3.648180] debug: unmapping init [mem 0xffffffff91114000-0xffffffff911fffff] [ 3.686891] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 3.695802] systemd[1]: Detected virtualization kvm. [ 3.697913] systemd[1]: Detected architecture x86-64. [ 3.699957] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.725055] systemd[1]: No hostname configured. [ 3.726941] systemd[1]: Set hostname to . [ 3.729229] random: systemd: uninitialized urandom read (16 bytes read) [ 3.731944] systemd[1]: Initializing machine ID from random generator. [ 3.781736] random: ln: uninitialized urandom read (6 bytes read) [ 3.883059] random: systemd: uninitialized urandom read (16 bytes read) [ 3.887081] systemd[1]: Listening on udev Control Socket. [ OK ] Listening on udev Control Socket. [ 3.893494] systemd[1]: Listening on Journal Socket (/dev/log). [ OK ] Listening on Journal Socket (/dev/log). [ 3.899134] systemd[1]: Reached target Timers. [ OK ] Reached target Timers. [ OK ] Reached target Local File Systems. [ OK ] Reached target Slices. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. [ OK ] Listening on udev Kernel Socket. [ OK ] Listening on Journal Socket. [ OK ] Reached target Sockets. Starting Create Volatile Files and Directories... Starting Journal Service... [ OK ] Reached target Swap. Starting Apply Kernel Variables... Starting Create list of required st…ce nodes for the current kernel... Starting Setup Virtual Console... [ OK ] Started Memstrack Anylazing Service. [ OK ] Reached target Initrd Root Device. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Apply Kernel Variables. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Setup Virtual Console. Starting dracut cmdline hook... Starting Create Static Device Nodes in /dev... [ OK ] Started Journal Service. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 4.575442] device-mapper: uevent: version 1.0.3 [ 4.577860] device-mapper: ioctl: 4.46.0-ioctl (2022-02-22) initialised: dm-devel@redhat.com [ OK ] Started dracut pre-udev hook. Starting udev Kernel Device Manager... [ OK ] Started udev Kernel Device Manager. Starting dracut pre-trigger hook... [ OK ] Started dracut pre-trigger hook. Starting udev Coldplug all Devices... Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. Starting dracut initqueue hook... [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ 5.324337] virtio_net virtio0 ens2: renamed from eth0 [ 5.324602] random: fast init done [ 5.354291] scsi host0: ata_piix [ 5.392274] scsi host1: ata_piix [ 5.490205] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 5.492876] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 9.081056] dracut-initqueue[578]: RTNETLINK answers: File exists [ 10.124183] random: crng init done [ 10.126894] random: 7 urandom warning(s) missed due to ratelimiting Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. Mounting /sysroot... [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. [ 11.203988] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped target Timers. [ 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 Sockets. [ OK ] Stopped target Slices. [ OK ] Stopped target Paths. [ OK ] Stopped target System Initialization. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped target Swap. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. Stopping udev Kernel Device Manager... [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Closed udev Control Socket. [ OK ] Closed udev Kernel Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 14.300850] printk: systemd: 25 output lines suppressed due to ratelimiting [ 15.125345] SELinux: Disabled at runtime. [ 15.268631] 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) [ 15.284444] systemd[1]: Detected virtualization kvm. [ 15.294625] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 16.730385] systemd[1]: initrd-switch-root.service: Succeeded. [ 16.735801] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 16.745677] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 16.748930] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 16.754492] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 16.775936] systemd[1]: Starting Journal Service... Starting Journal Service... [ 16.795058] systemd[1]: Starting Create list of required static device nodes for the current kernel... Starting Create list of required st…ce nodes for the current kernel... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Created slice system-getty.slice. [ OK ] Created slice User and Session Slice. [ OK ] Reached target Slices. [ OK ] Stopped target Switch Root. Starting Remount Root and Kernel File Systems... Mounting Huge Pages 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. Activating swap /dev/disk/by-label/SWAP... [ OK ] Stopped target Initrd File Systems. Mounting POSIX Message Queue File System... [ OK ] Stopped target Initrd Root File System. [ OK ] Reached target rpc_pipefs.target. [ OK ] Listening on udev Kernel Socket. [ 17.026804] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Listening on Process Core Dump Socket. Mounting Kernel Debug File System... [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Reached target Paths. [ OK ] Listening on udev Control Socket. Starting udev Coldplug all Devices... [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Reached target RPC Port Mapper. [ OK ] Reached target Local Encrypted Volumes. Starting Apply Kernel Variables... [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Started Journal Service. [ 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 Huge Pages File System. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Mounted Kernel Debug File System. [ OK ] Started Apply Kernel Variables. [ OK ] Reached target Swap. Starting Configure read-only root support... Starting Create Static Device Nodes in /dev... Starting Flush Journal to Persistent Storage... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Reached target Local File Systems (Pre). Mounting /mnt... Mounting /home/green/git/lustre-release... Starting udev Kernel Device Manager... [ OK ] Started udev Coldplug all Devices. [ OK ] Mounted /mnt. [ 18.055213] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 19.017567] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 19.026776] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 19.276300] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 19.312728] EDAC sbridge: Ver: 1.1.2 [* ] A start job is running for Configur…-only root support (7s / no limit)[ 23.838635] Key type dns_resolver registered [** ] A start job is running for Configur…-only root support (7s / no limit)[ 24.553332] NFS: Registering the id_resolver key type [ 24.564046] Key type id_resolver registered [ 24.568826] Key type id_legacy registered [*** ] A start job is running for Configur…-only root support (8s / no limit) [ *** ] A start job is running for Configur…-only root support (8s / no limit) [ OK ] Started Configure read-only root support. Starting Load/Save Random Seed... [ OK ] Reached target Local File Systems. Starting Rebuild Dynamic Linker Cache... Starting Mark the need to relabel after reboot... Starting Create Volatile Files and Directories... [ OK ] Started Load/Save Random Seed. [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Create Volatile Files and Directories. Starting RPC Bind... Starting Update UTMP about System Boot/Shutdown... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. [ OK ] Started D-Bus System Message Bus. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting Login Service... Starting Network Manager... [ OK ] Started dnf makecache --timer. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Reached target sshd-keygen.target. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Reached target Timers. [ OK ] Started irqbalance daemon. Starting Restore /run/initramfs on shutdown... [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Login Service. [ OK ] Started Network Manager. Starting Network Manager Wait Online... [ OK ] Reached target Network. Starting Dynamic System Tuning Daemon... Starting OpenSSH server daemon... Starting GSSAPI Proxy Daemon... Starting Hostname Service... [ OK ] Started 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 ttyS1. [ OK ] Started Serial Getty on ttyS0. [ OK ] Reached target Login Prompts. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting System Logging Service... Starting Crash recovery kernel arming... Starting Notify NFS peers of a restart... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg626-server login: [ 59.103793] spl: loading out-of-tree module taints kernel. [ 65.373054] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 76.304650] Key type ._llcrypt registered [ 76.309179] Key type .llcrypt registered [ 76.431890] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing set_hostid [ 92.977617] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing load_modules_local [ 94.237184] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 94.257316] alg: No test for adler32 (adler32-zlib) [ 95.773224] Lustre: Lustre: Build Version: 2.17.57_111_g33f3974 [ 96.712734] LNet: Added LNI 192.168.206.126@tcp [8/256/0/180] [ 98.495206] Key type lgssc registered [ 100.204915] Lustre: Echo OBD driver; http://www.lustre.org/ [ 110.162120] vdc: vdc1 vdc9 [ 119.856147] vde: vde1 vde9 [ 128.681338] vdf: vdf1 vdf9 [ 144.785025] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing load_modules_local [ 153.327764] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 154.577341] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 154.830711] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 154.959263] Lustre: lustre-MDT0000: new disk, initializing [ 155.456624] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 155.514794] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 162.164793] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 167.851748] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 175.320410] Lustre: lustre-OST0000: new disk, initializing [ 175.322490] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 175.325364] Lustre: Skipped 1 previous similar message [ 175.391256] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 178.030501] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:0:ost [ 178.041858] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:0:ost] [ 178.229762] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x240000400 [ 183.829371] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 195.770646] Lustre: lustre-OST0001: new disk, initializing [ 195.773556] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 195.857145] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 201.382550] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:1:ost [ 201.388375] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:1:ost] [ 201.483495] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x280000400 [ 201.911297] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 214.564944] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 221.114407] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 227.583457] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing check_logdir /tmp/testlogs/ [ 232.947275] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing yml_node [ 236.722099] Lustre: DEBUG MARKER: Client: 2.17.57.111 [ 238.795996] Lustre: DEBUG MARKER: MDS: 2.17.57.111 [ 241.015345] Lustre: DEBUG MARKER: OSS: 2.17.57.111 [ 242.484182] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity-quota ============----- Tue Sep 8 00:59:03 EDT 2026 [ 259.902952] Lustre: DEBUG MARKER: excepting tests: 2 4a 63 65 [ 261.746245] Lustre: DEBUG MARKER: skipping tests SLOW=no: 61 12a 9 [ 261.881748] hrtimer: interrupt took 10359625 ns [ 264.056474] Lustre: DEBUG MARKER: === sanity-quota: start setup 00:59:25 (1788843565) === [ 269.907460] Lustre: DEBUG MARKER: oleg626-client.virtnet: executing check_config_client /mnt/lustre [ 286.060552] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 290.352454] Lustre: 11359:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 295.587144] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 300.129358] Lustre: DEBUG MARKER: === sanity-quota: finish setup 01:00:00 (1788843600) === [ 358.266958] Lustre: DEBUG MARKER: == sanity-quota test 0: Test basic quota performance ===== 01:00:59 (1788843659) [ 411.543827] Lustre: DEBUG MARKER: == sanity-quota test 1a: Block hard limit (normal use and out of quota) ========================================================== 01:01:52 (1788843712) [ 428.335793] Lustre: DEBUG MARKER: User quota (block hardlimit:10 MB) [ 435.466681] Lustre: DEBUG MARKER: Write... [ 437.876488] Lustre: DEBUG MARKER: Write out of block quota ... [ 479.455214] Lustre: DEBUG MARKER: -------------------------------------- [ 481.204369] Lustre: DEBUG MARKER: Group quota (block hardlimit:10 MB) [ 488.757948] Lustre: DEBUG MARKER: Write... [ 490.986679] Lustre: DEBUG MARKER: Write out of block quota ... [ 534.779740] Lustre: DEBUG MARKER: -------------------------------------- [ 535.929204] Lustre: DEBUG MARKER: Project quota (block hardlimit:10 mb) [ 537.995322] Lustre: DEBUG MARKER: Write... [ 539.826487] Lustre: DEBUG MARKER: Write out of block quota ... [ 600.903311] Lustre: DEBUG MARKER: == sanity-quota test 1b: Quota pools: Block hard limit (normal use and out of quota) ========================================================== 01:05:01 (1788843901) [ 616.063071] Lustre: DEBUG MARKER: User quota (block hardlimit:20 MB) [ 633.304464] Lustre: DEBUG MARKER: Write... [ 635.924496] Lustre: DEBUG MARKER: Write out of block quota ... [ 673.985388] Lustre: DEBUG MARKER: -------------------------------------- [ 675.085265] Lustre: DEBUG MARKER: Group quota (block hardlimit:20 MB) [ 680.424251] Lustre: DEBUG MARKER: Write... [ 682.196712] Lustre: DEBUG MARKER: Write out of block quota ... [ 725.162885] Lustre: DEBUG MARKER: -------------------------------------- [ 726.290445] Lustre: DEBUG MARKER: Project quota (block hardlimit:20 mb) [ 728.672383] Lustre: DEBUG MARKER: Write... [ 730.941156] Lustre: DEBUG MARKER: Write out of block quota ... [ 796.335724] Lustre: DEBUG MARKER: == sanity-quota test 1c: Quota pools: check 3 pools with hardlimit only for global ========================================================== 01:08:17 (1788844097) [ 809.284983] Lustre: DEBUG MARKER: User quota (block hardlimit:20 MB) [ 831.198290] Lustre: DEBUG MARKER: Write... [ 834.306327] Lustre: DEBUG MARKER: Write out of block quota ... [ 918.937501] Lustre: DEBUG MARKER: == sanity-quota test 1d: Quota pools: check block hardlimit on different pools ========================================================== 01:10:20 (1788844220) [ 932.789643] Lustre: DEBUG MARKER: User quota (block hardlimit:20 MB) [ 953.742991] Lustre: DEBUG MARKER: Write... [ 956.216349] Lustre: DEBUG MARKER: Write out of block quota ... [ 1046.682316] Lustre: DEBUG MARKER: == sanity-quota test 1e: Quota pools: global pool high block limit vs quota pool with small ========================================================== 01:12:27 (1788844347) [ 1060.663839] Lustre: DEBUG MARKER: User quota (block hardlimit:53000000 MB) [ 1071.168699] Lustre: DEBUG MARKER: Write... [ 1073.793931] Lustre: DEBUG MARKER: Write out of block quota ... [ 1086.456697] Lustre: DEBUG MARKER: Write... [ 1148.407907] Lustre: DEBUG MARKER: == sanity-quota test 1f: Quota pools: correct qunit after removing/adding OST ========================================================== 01:14:09 (1788844449) [ 1164.282660] Lustre: DEBUG MARKER: User quota (block hardlimit:200 MB) [ 1176.533747] Lustre: DEBUG MARKER: Write... [ 1179.642117] Lustre: DEBUG MARKER: Write out of block quota ... [ 1219.145750] Lustre: DEBUG MARKER: Write... [ 1222.599549] Lustre: DEBUG MARKER: Write out of block quota ... [ 1276.035954] Lustre: DEBUG MARKER: == sanity-quota test 1g: Quota pools: Block hard limit with wide striping ========================================================== 01:16:16 (1788844576) [ 1290.076937] Lustre: DEBUG MARKER: User quota (block hardlimit:40 MB) [ 1301.635053] Lustre: DEBUG MARKER: Write... [ 1313.363556] Lustre: DEBUG MARKER: Write out of block quota ... [ 1392.646665] Lustre: DEBUG MARKER: == sanity-quota test 1h: Block hard limit test using fallocate ========================================================== 01:18:13 (1788844693) [ 1395.245515] Lustre: DEBUG MARKER: SKIP: sanity-quota test_1h fallocate not supported [ 1396.829773] Lustre: DEBUG MARKER: == sanity-quota test 1i: Quota pools: different limit and usage relations ========================================================== 01:18:17 (1788844697) [ 1412.570210] Lustre: DEBUG MARKER: User quota (block hardlimit:200 MB) [ 1422.571455] Lustre: DEBUG MARKER: Write... [ 1424.960903] Lustre: DEBUG MARKER: Write out of block quota ... [ 1462.177559] Lustre: DEBUG MARKER: Write... [ 1464.592701] Lustre: DEBUG MARKER: Write out of block quota ... [ 1475.847722] LustreError: 5831: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 [ 1516.762762] Lustre: DEBUG MARKER: == sanity-quota test 1j: Enable project quota enforcement for root ========================================================== 01:20:17 (1788844817) [ 1537.075565] Lustre: DEBUG MARKER: -------------------------------------- [ 1538.419839] Lustre: DEBUG MARKER: Project quota (hardlimit: 40 mb, 2048 files) [ 1884.102595] Lustre: DEBUG MARKER: == sanity-quota test 1k: LQA: Block hard limit (normal use and out of quota) ========================================================== 01:26:25 (1788845185) [ 1906.272478] Lustre: DEBUG MARKER: Write... [ 1910.729111] Lustre: DEBUG MARKER: Write out of block quota ... [ 1948.859526] Lustre: DEBUG MARKER: Write... [ 1951.727372] Lustre: DEBUG MARKER: Write out of block quota ... [ 1993.284406] Lustre: DEBUG MARKER: Write... [ 1996.356595] Lustre: DEBUG MARKER: Write out of block quota ... [ 2039.121738] Lustre: DEBUG MARKER: == sanity-quota test 1l: Async writes should not be rejected by quota with root_prj_enable ========================================================== 01:29:00 (1788845340) [ 2091.052655] Lustre: DEBUG MARKER: SKIP: sanity-quota test_2 skipping excluded test 2 [ 2092.618988] Lustre: DEBUG MARKER: == sanity-quota test 3a: Block soft limit (start timer, timer goes off, stop timer) ========================================================== 01:29:53 (1788845393) [ 2100.409261] LustreError: 3305:0:(qsd_reint.c:633:qqi_reint_delayed()) lustre-OST0000: Delaying reintegration for qtype:0 until pending updates are flushed. [ 2178.140801] Lustre: DEBUG MARKER: Write after timer goes off [ 2180.000556] Lustre: DEBUG MARKER: Write after cancel lru locks [ 2310.051621] Lustre: DEBUG MARKER: Write after timer goes off [ 2311.741647] Lustre: DEBUG MARKER: Write after cancel lru locks [ 2445.362697] Lustre: DEBUG MARKER: Write after timer goes off [ 2446.972595] Lustre: DEBUG MARKER: Write after cancel lru locks [ 2554.051527] Lustre: DEBUG MARKER: == sanity-quota test 3b: Quota pools: Block soft limit (start timer, expires, stop timer) ========================================================== 01:37:34 (1788845854) [ 2650.410744] Lustre: DEBUG MARKER: Write after timer goes off [ 2652.014872] Lustre: DEBUG MARKER: Write after cancel lru locks [ 2782.496929] Lustre: DEBUG MARKER: Write after timer goes off [ 2784.278774] Lustre: DEBUG MARKER: Write after cancel lru locks [ 2919.554569] Lustre: DEBUG MARKER: Write after timer goes off [ 2921.659260] Lustre: DEBUG MARKER: Write after cancel lru locks [ 3045.039965] Lustre: DEBUG MARKER: == sanity-quota test 3c: Quota pools: check block soft limit on different pools ========================================================== 01:45:46 (1788846346) [ 3145.277505] Lustre: DEBUG MARKER: Write after timer goes off [ 3146.862474] Lustre: DEBUG MARKER: Write after cancel lru locks [ 3241.380406] Lustre: DEBUG MARKER: SKIP: sanity-quota test_4a skipping excluded test 4a [ 3242.887575] Lustre: DEBUG MARKER: == sanity-quota test 4b: Grace time strings handling ===== 01:49:04 (1788846544) [ 3258.454877] Lustre: DEBUG MARKER: == sanity-quota test 5: Chown [ 3389.246878] Lustre: DEBUG MARKER: == sanity-quota test 6: Test dropping acquire request on master ========================================================== 01:51:29 (1788846689) [ 3441.366739] Lustre: *** cfs_fail_loc=513, val=601*** [ 3441.373197] Lustre: Skipped 1 previous similar message [ 3442.075644] Lustre: *** cfs_fail_loc=513, val=601*** [ 3442.077793] Lustre: Skipped 1 previous similar message [ 3442.703610] LustreError: 5833:0:(service.c:2341:ptlrpc_server_handle_req_in()) drop incoming rpc opc 601, x1875738257659392 [ 3444.704590] Lustre: *** cfs_fail_loc=513, val=601*** [ 3444.709590] Lustre: Skipped 20 previous similar messages [ 3447.263984] Lustre: *** cfs_fail_loc=513, val=601*** [ 3447.269984] Lustre: Skipped 8 previous similar messages [ 3451.605920] Lustre: *** cfs_fail_loc=513, val=601*** [ 3451.613371] Lustre: Skipped 4 previous similar messages [ 3458.016621] Lustre: 6690:0:(service.c:1612:ptlrpc_at_send_early_reply()) @@@ Could not add any time (5/5), not sending early reply req@ffff92ae984b0000 x1875738245634176/t0(0) o4->103ee210-6097-4e7b-a05b-9495936ab00d@192.168.206.26@tcp:350/0 lens 488/448 e 1 to 0 dl 1788846765 ref 2 fl Interpret:/600/0 rc 0/0 job:'dd.60000' uid:60000 gid:60000 projid:0 [ 3459.039615] Lustre: 6689:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788846745/real 1788846745] req@ffff92aeab031180 x1875738257659392/t0(0) o601->lustre-MDT0000-lwp-OST0000@0@lo:23/10 lens 336/336 e 0 to 1 dl 1788846761 ref 2 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'ll_ost_io00_001.0' uid:0 gid:0 projid:4294967295 [ 3459.063842] 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 [ 3459.079096] Lustre: lustre-MDT0000: Client lustre-MDT0000-lwp-OST0000_UUID (at 0@lo) reconnecting [ 3459.088486] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 3460.065963] Lustre: *** cfs_fail_loc=513, val=601*** [ 3460.072526] Lustre: Skipped 24 previous similar messages [ 3460.140181] LustreError: 14380:0:(service.c:2341:ptlrpc_server_handle_req_in()) drop incoming rpc opc 601, x1875738257663744 [ 3474.399586] LustreError: 5833:0:(service.c:2341:ptlrpc_server_handle_req_in()) drop incoming rpc opc 601, x1875738257666176 [ 3474.409391] LustreError: 5833:0:(service.c:2341:ptlrpc_server_handle_req_in()) Skipped 2 previous similar messages [ 3476.447174] Lustre: 39119:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788846763/real 1788846763] req@ffff92aeab071c00 x1875738257663744/t0(0) o601->lustre-MDT0000-lwp-OST0000@0@lo:23/10 lens 336/336 e 0 to 1 dl 1788846779 ref 2 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'ll_ost_io00_005.0' uid:0 gid:0 projid:4294967295 [ 3476.481145] 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 [ 3476.491721] Lustre: *** cfs_fail_loc=513, val=601*** [ 3476.494171] Lustre: lustre-MDT0000: Client lustre-MDT0000-lwp-OST0000_UUID (at 0@lo) reconnecting [ 3476.505052] Lustre: Skipped 42 previous similar messages [ 3476.511042] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 3478.593935] LustreError: 14380:0:(service.c:2341:ptlrpc_server_handle_req_in()) drop incoming rpc opc 601, x1875738257668096 [ 3490.783142] Lustre: 3305:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788846777/real 1788846777] req@ffff92ad891e1880 x1875738257666048/t0(0) o601->lustre-MDT0000-lwp-OST0001@0@lo:23/10 lens 336/336 e 0 to 1 dl 1788846793 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'lquota_wb_lustr.0' uid:0 gid:0 projid:4294967295 [ 3490.787364] 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 [ 3490.803595] Lustre: 3305:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 3490.830652] Lustre: lustre-MDT0000: Client lustre-MDT0000-lwp-OST0001_UUID (at 0@lo) reconnecting [ 3490.847610] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 3494.879192] Lustre: 16088:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788846781/real 1788846781] req@ffff92ad89866680 x1875738257668096/t0(0) o601->lustre-MDT0000-lwp-OST0000@0@lo:23/10 lens 336/336 e 0 to 1 dl 1788846797 ref 2 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'ll_ost_io00_003.0' uid:0 gid:0 projid:4294967295 [ 3494.904441] 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 [ 3494.922552] Lustre: lustre-MDT0000: Client lustre-MDT0000-lwp-OST0000_UUID (at 0@lo) reconnecting [ 3494.939264] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 3532.134625] Lustre: DEBUG MARKER: == sanity-quota test 7a: Quota reintegration (global index) ========================================================== 01:53:53 (1788846833) [ 3562.352666] Lustre: Failing over lustre-OST0000 [ 3562.464204] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 3562.472500] 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 [ 3562.489837] Lustre: server umount lustre-OST0000 complete [ 3569.372599] LustreError: 38992:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.206.26@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3569.391437] LustreError: 38992:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 4 previous similar messages [ 3571.685298] LustreError: 6683:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3573.377169] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [ 3573.397076] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 3574.496707] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 3575.164528] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 3575.170033] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 3579.409895] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3587.548236] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3592.786349] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3598.418695] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3604.001576] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3609.671681] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3614.675513] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3646.685657] Lustre: Failing over lustre-OST0000 [ 3646.754313] Lustre: server umount lustre-OST0000 complete [ 3646.944639] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 3646.950688] 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 [ 3646.961506] LustreError: 38995:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3650.022936] LustreError: 28252:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3654.783494] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [ 3654.802989] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 3656.547123] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 3656.633110] Lustre: lustre-OST0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 3656.633299] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 3659.861773] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3666.840299] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3671.708239] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3676.876673] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3682.493874] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3687.599296] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3692.544899] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3729.297920] Lustre: DEBUG MARKER: == sanity-quota test 7b: Quota reintegration (slave index) ========================================================== 01:57:10 (1788847030) [ 3764.956951] Lustre: *** cfs_fail_loc=a02, val=0*** [ 3772.304636] Lustre: Failing over lustre-OST0000 [ 3772.385714] 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 [ 3772.398072] LustreError: 38995:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3772.408953] Lustre: server umount lustre-OST0000 complete [ 3779.147805] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [ 3779.167829] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 3779.289385] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 3781.147979] Lustre: lustre-OST0000: Recovery over after 0:02, of 2 clients 2 recovered and 0 were evicted. [ 3781.154742] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 3784.399099] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3791.705908] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3797.371637] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3802.856201] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3808.156683] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3813.155792] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3818.198485] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3874.963180] Lustre: DEBUG MARKER: == sanity-quota test 7c: Quota reintegration (restart mds during reintegration) ========================================================== 01:59:35 (1788847175) [ 3903.267698] LustreError: 91351:0:(qsd_reint.c:488:qsd_reint_main()) cfs_fail_timeout id a03 sleeping for 10000ms [ 3903.276169] LustreError: 91351:0:(qsd_reint.c:488:qsd_reint_main()) Skipped 5 previous similar messages [ 3905.256027] Lustre: Failing over lustre-MDT0000 [ 3905.699951] Lustre: server umount lustre-MDT0000 complete [ 3909.399068] LustreError: 91355:0:(qsd_reint.c:488:qsd_reint_main()) cfs_fail_timeout interrupted [ 3909.410799] LustreError: 91355:0:(qsd_reint.c:488:qsd_reint_main()) Skipped 1 previous similar message [ 3915.539206] LustreError: MGC192.168.206.126@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3915.846675] 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 [ 3915.864056] Lustre: Skipped 1 previous similar message [ 3916.049411] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3916.133928] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 3917.612475] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 3917.724552] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 3917.780988] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:145 to 0x240000400:161) [ 3917.785061] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:116 to 0x280000400:161) [ 3920.814767] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3921.378146] LustreError: 3302:0:(ldlm_resource.c:1207:ldlm_resource_complain()) lustre-MDT0000-lwp-OST0001: namespace resource [0x200000006:0x2020000:0x0].0x0 (ffff92ae9829fa00) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 3921.401508] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 3922.399155] Lustre: 3305:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788847209/real 1788847209] req@ffff92aec1687b80 x1875738258041344/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788847225 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3928.329117] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 4023.786953] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 4029.580721] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 4033.740836] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 4039.329235] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 4044.349931] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 4080.684844] Lustre: DEBUG MARKER: == sanity-quota test 7d: Quota reintegration (Transfer index in multiple bulks) ========================================================== 02:03:01 (1788847381) [ 4103.906441] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 4109.174793] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 4160.490970] Lustre: DEBUG MARKER: == sanity-quota test 7e: Quota reintegration (inode limits) ========================================================== 02:04:21 (1788847461) [ 4162.388529] Lustre: DEBUG MARKER: SKIP: sanity-quota test_7e needs >= 2 MDTs [ 4164.161414] Lustre: DEBUG MARKER: == sanity-quota test 7f: Quota reintegration automatically ========================================================== 02:04:25 (1788847465) [ 4182.566778] Lustre: *** cfs_fail_loc=a11, val=0*** [ 4182.570761] Lustre: Skipped 2 previous similar messages [ 4188.938388] Lustre: *** cfs_fail_loc=a11, val=0*** [ 4301.795057] Lustre: *** cfs_fail_loc=a11, val=0*** [ 4301.805137] Lustre: Skipped 1 previous similar message [ 4363.202370] Lustre: DEBUG MARKER: == sanity-quota test 8: Run dbench with quota enabled ==== 02:07:44 (1788847664) [ 4569.418494] Lustre: DEBUG MARKER: SKIP: sanity-quota test_9 skipping SLOW test 9 [ 4571.656138] Lustre: DEBUG MARKER: == sanity-quota test 10: Test quota for root user ======== 02:11:12 (1788847872) [ 4637.132787] Lustre: DEBUG MARKER: == sanity-quota test 11: Chown/chgrp ignores quota ======= 02:12:18 (1788847938) [ 4692.142880] Lustre: DEBUG MARKER: SKIP: sanity-quota test_12a skipping SLOW test 12a [ 4694.061664] Lustre: DEBUG MARKER: == sanity-quota test 12b: Inode quota rebalancing ======== 02:13:14 (1788847994) [ 4695.486612] Lustre: DEBUG MARKER: SKIP: sanity-quota test_12b needs >= 2 MDTs [ 4697.338214] Lustre: DEBUG MARKER: == sanity-quota test 13: Cancel per-ID lock in the LRU list ========================================================== 02:13:18 (1788847998) [ 4772.927455] Lustre: DEBUG MARKER: == sanity-quota test 14: check panic in qmt_site_recalc_cb ========================================================== 02:14:33 (1788848073) [ 4800.865773] Lustre: Failing over lustre-OST0000 [ 4800.962613] Lustre: server umount lustre-OST0000 complete [ 4801.504672] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 4801.517952] 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 [ 4801.535160] LustreError: 102218:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4801.553667] LustreError: 102218:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 2 previous similar messages [ 4803.332507] LustreError: 102231:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.206.26@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4803.353925] LustreError: 102231:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 1 previous similar message [ 4807.164333] LustreError: 38992:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4812.267819] LustreError: 6684:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4812.291648] LustreError: 6684:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 1 previous similar message [ 4816.856384] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [ 4816.870625] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 4818.645770] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4818.756115] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 4818.759761] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 4818.789615] Lustre: Skipped 1 previous similar message [ 4824.128189] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4870.669996] Lustre: DEBUG MARKER: == sanity-quota test 15: Set over 4T block quota ========= 02:16:11 (1788848171) [ 4907.324688] Lustre: DEBUG MARKER: == sanity-quota test 16a: lfs quota should skip the inactive MDT/OST ========================================================== 02:16:48 (1788848208) [ 4939.312982] Lustre: lustre-OST0000: Client 103ee210-6097-4e7b-a05b-9495936ab00d (at 192.168.206.26@tcp) reconnecting [ 4969.213857] Lustre: DEBUG MARKER: == sanity-quota test 16b: lfs quota should skip the nonexistent MDT/OST ========================================================== 02:17:49 (1788848269) [ 4971.383571] Lustre: DEBUG MARKER: SKIP: sanity-quota test_16b needs >= 3 MDTs [ 4973.584320] Lustre: DEBUG MARKER: == sanity-quota test 16c: lfs quota should preserve usage with an unavailable OST ========================================================== 02:17:54 (1788848274) [ 5002.324858] Lustre: setting import lustre-OST0000_UUID INACTIVE by administrator request [ 5004.180359] Lustre: Failing over lustre-OST0000 [ 5004.291463] Lustre: server umount lustre-OST0000 complete [ 5008.099871] LustreError: 6683:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.206.26@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 5008.134838] LustreError: 6683:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 1 previous similar message [ 5016.185273] Lustre: DEBUG MARKER: oleg626-client.virtnet: executing wait_import_state (DISCONN|IDLE) osc.lustre-OST0000-osc-ffff8dae90454000.ost_server_uuid 50 [ 5017.809730] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff8dae90454000.ost_server_uuid in DISCONN state after 0 sec [ 5024.755480] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [ 5024.770271] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 5026.010259] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 5026.018118] Lustre: lustre-OST0000: Denying connection for new client d30c5a30-28ed-4fd7-9758-7646bef86820 (at 192.168.206.26@tcp), waiting for 2 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 1:00 [ 5026.742846] Lustre: lustre-OST0000: Denying connection for new client d30c5a30-28ed-4fd7-9758-7646bef86820 (at 192.168.206.26@tcp), waiting for 2 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:59 [ 5030.867456] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5031.126173] Lustre: lustre-OST0000: Denying connection for new client d30c5a30-28ed-4fd7-9758-7646bef86820 (at 192.168.206.26@tcp), waiting for 2 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:55 [ 5033.586456] 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 [ 5033.600326] LustreError: lustre-OST0000-osc-MDT0000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 5033.616960] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 5033.618249] LustreError: 38995:0:(tgt_handler.c:534:tgt_filter_recovery_request()) @@@ not permitted during recovery req@ffff92aeb30d8a80 x1875738259154944/t0(0) o7->lustre-MDT0000-mdtlov_UUID@0@lo:422/0 lens 264/0 e 0 to 0 dl 1788848347 ref 1 fl Interpret:/200/ffffffff rc 0/-1 job:'osp-pre-0-0.0' uid:0 gid:0 projid:4294967295 [ 5033.619153] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -11 [ 5033.673169] LustreError: 38995:0:(tgt_handler.c:534:tgt_filter_recovery_request()) Skipped 1 previous similar message [ 5036.254588] Lustre: lustre-OST0000: Denying connection for new client d30c5a30-28ed-4fd7-9758-7646bef86820 (at 192.168.206.26@tcp), waiting for 2 known clients (0 recovered, 1 in progress, and 0 evicted) to recover in 1:00 [ 5037.137984] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 5041.372614] Lustre: lustre-OST0000: Denying connection for new client d30c5a30-28ed-4fd7-9758-7646bef86820 (at 192.168.206.26@tcp), waiting for 2 known clients (0 recovered, 1 in progress, and 0 evicted) to recover in 0:55 [ 5051.611886] Lustre: lustre-OST0000: Denying connection for new client d30c5a30-28ed-4fd7-9758-7646bef86820 (at 192.168.206.26@tcp), waiting for 2 known clients (0 recovered, 1 in progress, and 0 evicted) to recover in 0:44 [ 5051.641942] Lustre: Skipped 1 previous similar message [ 5072.086935] Lustre: lustre-OST0000: Denying connection for new client d30c5a30-28ed-4fd7-9758-7646bef86820 (at 192.168.206.26@tcp), waiting for 2 known clients (0 recovered, 1 in progress, and 0 evicted) to recover in 0:24 [ 5072.111810] Lustre: Skipped 3 previous similar messages [ 5096.500383] Lustre: lustre-OST0000: recovery is timed out, evict stale exports [ 5096.511412] Lustre: 114077:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-OST0000: disconnect stale client 103ee210-6097-4e7b-a05b-9495936ab00d@ [ 5096.530079] Lustre: lustre-OST0000: disconnecting 1 stale clients [ 5107.926686] Lustre: lustre-OST0000: Denying connection for new client d30c5a30-28ed-4fd7-9758-7646bef86820 (at 192.168.206.26@tcp), waiting for 2 known clients (0 recovered, 1 in progress, and 1 evicted) to recover in 0:18 [ 5107.969510] Lustre: Skipped 6 previous similar messages [ 5126.500174] Lustre: lustre-OST0000: recovery is timed out, evict stale exports [ 5126.504355] Lustre: 114077:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-OST0000: disconnect stale client lustre-MDT0000-mdtlov_UUID@0@lo [ 5126.512920] Lustre: lustre-OST0000: disconnecting 1 stale clients [ 5126.587055] Lustre: lustre-OST0000: Recovery over after 1:40, of 2 clients 0 recovered and 2 were evicted. [ 5127.137975] Lustre: lustre-OST0000-osc-MDT0000: Connection to lustre-OST0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 5127.160034] LustreError: lustre-OST0000-osc-MDT0000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 5127.170672] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 5132.690136] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing wait_import_state FULL os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid 50 [ 5132.875913] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid in FULL state after 0 sec [ 5138.746445] Lustre: DEBUG MARKER: oleg626-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0000-osc-ffff8dae90454000.ost_server_uuid 50 [ 5140.219669] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff8dae90454000.ost_server_uuid in FULL state after 0 sec [ 5171.224505] Lustre: DEBUG MARKER: == sanity-quota test 17: DQACQ return recoverable error == 02:21:12 (1788848472) [ 5197.093259] Lustre: *** cfs_fail_loc=a04, val=37*** [ 5197.096436] LustreError: 102197:0:(qsd_handler.c:298:qsd_req_completion()) $$$ DQACQ failed with -37, flags:0x1 qsd:lustre-OST0000 qtype:usr lqe: ffff92ad82852a80 id:60000 enforced:1 granted: 0 pending:0 waiting:1 req:1 usage: 0 qunit:0 qtune:0 edquot:0 default:no revoke:0 [ 5198.190722] Lustre: *** cfs_fail_loc=a04, val=37*** [ 5198.195787] LustreError: 6688:0:(qsd_handler.c:298:qsd_req_completion()) $$$ DQACQ failed with -37, flags:0x1 qsd:lustre-OST0000 qtype:usr lqe: ffff92ad82852a80 id:60000 enforced:1 granted: 0 pending:0 waiting:1024 req:1 usage: 0 qunit:0 qtune:0 edquot:0 default:no revoke:0 [ 5200.314585] Lustre: *** cfs_fail_loc=a04, val=37*** [ 5200.324771] LustreError: 102221:0:(qsd_handler.c:298:qsd_req_completion()) $$$ DQACQ failed with -37, flags:0x1 qsd:lustre-OST0000 qtype:usr lqe: ffff92ad82852a80 id:60000 enforced:1 granted: 0 pending:0 waiting:1024 req:1 usage: 0 qunit:0 qtune:0 edquot:0 default:no revoke:0 [ 5273.674174] Lustre: *** cfs_fail_loc=a04, val=11*** [ 5343.545320] Lustre: *** cfs_fail_loc=a04, val=110*** [ 5343.550191] Lustre: Skipped 2 previous similar messages [ 5410.089934] Lustre: *** cfs_fail_loc=a04, val=107*** [ 5410.092213] Lustre: Skipped 1 previous similar message [ 5413.475920] 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 [ 5413.495906] Lustre: lustre-MDT0000: Client lustre-MDT0000-lwp-OST0001_UUID (at 0@lo) reconnecting [ 5413.504941] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 5517.230919] Lustre: DEBUG MARKER: == sanity-quota test 18: MDS failover while writing, no watchdog triggered (b14840) ========================================================== 02:26:58 (1788848818) [ 5536.762487] Lustre: DEBUG MARKER: User quota (limit: 200) [ 5542.797943] Lustre: DEBUG MARKER: Write 100M (buffered) ... [ 5546.165850] LustreError: 125615:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 5547.400785] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5549.143729] Lustre: DEBUG MARKER: Fail mds for 40 seconds [ 5551.329103] Lustre: Failing over lustre-MDT0000 [ 5551.707973] Lustre: server umount lustre-MDT0000 complete [ 5567.263339] Lustre: 3304:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788848854/real 1788848854] req@ffff92aebaa9ce00 x1875738259296384/t0(0) o400->MGC192.168.206.126@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1788848870 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5567.290978] Lustre: 3304:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 5567.297098] LustreError: MGC192.168.206.126@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5567.305984] 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 [ 5573.471119] Lustre: 3303:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788848860/real 1788848860] req@ffff92aebaa9df80 x1875738259297024/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788848876 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5573.495223] Lustre: 3303:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 5577.704542] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x33e3cd6cb6a1877b [ 5577.710623] Lustre: MGC192.168.206.126@tcp: Connection restored to 0@lo (at 0@lo) [ 5578.216122] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 5578.273649] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 5578.981815] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 5579.053950] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 5579.082354] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:628 to 0x240000400:673) [ 5579.083202] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:625 to 0x280000400:641) [ 5579.104247] Lustre: 3303:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788848865/real 1788848865] req@ffff92aeb3891880 x1875738259297408/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788848881 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5579.120674] Lustre: 3303:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 5582.896297] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5583.205333] Lustre: 3303:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788848870/real 1788848870] req@ffff92aebaa9ca80 x1875738259297792/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788848886 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5592.498573] Lustre: DEBUG MARKER: oleg626-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5593.832538] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5598.747424] Lustre: DEBUG MARKER: (dd_pid=117646, time=0, timeout=600) [ 5645.077244] Lustre: DEBUG MARKER: User quota (limit: 200) [ 5650.858280] Lustre: DEBUG MARKER: Write 100M (directio) ... [ 5653.656840] LustreError: 128584:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 5654.401326] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5656.033674] Lustre: DEBUG MARKER: Fail mds for 40 seconds [ 5657.852541] Lustre: Failing over lustre-MDT0000 [ 5658.178341] Lustre: server umount lustre-MDT0000 complete [ 5674.463752] Lustre: 3304:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788848961/real 1788848961] req@ffff92aeb8e26d80 x1875738259332480/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788848977 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5674.497277] Lustre: 3304:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 5674.505553] LustreError: MGC192.168.206.126@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5684.705104] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x33e3cd6cb6a19057 [ 5685.063439] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 5685.139875] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 5687.519825] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 5687.750260] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 5687.785934] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:625 to 0x280000400:673) [ 5687.786096] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:675 to 0x240000400:705) [ 5689.763902] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5699.316427] LustreError: 3302:0:(ldlm_resource.c:1207:ldlm_resource_complain()) lustre-MDT0000-lwp-OST0001: namespace resource [0x200000006:0x20000:0x0].0x0 (ffff92aeb32e2200) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 5699.332297] LustreError: 3302:0:(ldlm_resource.c:1207:ldlm_resource_complain()) Skipped 5 previous similar messages [ 5699.393364] Lustre: DEBUG MARKER: oleg626-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5700.956427] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5716.906436] Lustre: DEBUG MARKER: (dd_pid=120116, time=9, timeout=600) [ 5777.068382] Lustre: DEBUG MARKER: == sanity-quota test 19: Updating admin limits doesn't zero operational limits(b14790) ========================================================== 02:31:18 (1788849078) [ 5797.173951] Lustre: DEBUG MARKER: Files for user (quota_usr), count=1: [ 5798.901040] Lustre: DEBUG MARKER: Block quota isn't 0 (u:quota_usr:2). [ 5804.968319] Lustre: DEBUG MARKER: Files for user (quota_usr), count=1: [ 5806.720233] Lustre: DEBUG MARKER: Block quota isn't 0 (u:quota_usr:2). [ 5839.209943] Lustre: DEBUG MARKER: == sanity-quota test 20: Test if setquota specifiers work properly (b15754) ========================================================== 02:32:20 (1788849140) [ 5863.523724] Lustre: DEBUG MARKER: == sanity-quota test 21: Setquota while writing [ 5880.703756] Lustre: DEBUG MARKER: Set limit(block:10G; file:1000000) for user: quota_usr [ 5882.850626] Lustre: DEBUG MARKER: Set limit(block:10G; file:1000000) for group: quota_usr [ 5884.852359] Lustre: DEBUG MARKER: Set limit(block:10G; file:) for project: 1000 [ 5886.937790] Lustre: DEBUG MARKER: Set quota for 1 times [ 5891.059667] Lustre: DEBUG MARKER: Set quota for 2 times [ 5894.907808] Lustre: DEBUG MARKER: Set quota for 3 times [ 5898.848886] Lustre: DEBUG MARKER: Set quota for 4 times [ 5902.701873] Lustre: DEBUG MARKER: Set quota for 5 times [ 5906.852334] Lustre: DEBUG MARKER: Set quota for 6 times [ 5911.061317] Lustre: DEBUG MARKER: Set quota for 7 times [ 5915.013523] Lustre: DEBUG MARKER: Set quota for 8 times [ 5952.763429] Lustre: DEBUG MARKER: == sanity-quota test 22: enable/disable quota by 'lctl conf_param/set_param -P' ========================================================== 02:34:13 (1788849253) [ 5965.796700] 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 [ 5965.809657] Lustre: Skipped 3 previous similar messages [ 5965.813499] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5965.820069] Lustre: Skipped 1 previous similar message [ 5966.881026] Lustre: server umount lustre-MDT0000 complete [ 5970.700410] LustreError: 14055:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788849273 with bad export cookie 3739057982451847255 [ 5970.703345] LustreError: MGC192.168.206.126@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5970.719737] LustreError: 14055:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 5970.907429] Lustre: server umount lustre-OST0000 complete [ 5974.871064] Lustre: server umount lustre-OST0001 complete [ 5988.130325] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing load_modules_local [ 5996.313656] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 5999.940359] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6002.207967] Lustre: 138277:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 6007.465821] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 6013.021981] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6020.571674] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 6021.635706] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:707 to 0x240000400:737) [ 6021.831591] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:676 to 0x280000400:705) [ 6025.657334] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6031.801804] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 6034.842433] Lustre: 140198:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 6052.323166] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 6052.331075] Lustre: Skipped 1 previous similar message [ 6053.725626] Lustre: server umount lustre-MDT0000 complete [ 6056.934695] LustreError: 137824:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788849359 with bad export cookie 3739057982451856628 [ 6056.938236] LustreError: MGC192.168.206.126@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 6056.950164] LustreError: 137824:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 6057.017246] Lustre: server umount lustre-OST0000 complete [ 6060.226503] Lustre: server umount lustre-OST0001 complete [ 6072.590216] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing load_modules_local [ 6079.879812] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 6083.285315] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6085.414727] Lustre: 142954:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 6094.636339] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6101.361645] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 6101.365287] Lustre: Skipped 1 previous similar message [ 6104.434168] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:676 to 0x280000400:737) [ 6104.437255] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:707 to 0x240000400:769) [ 6106.262727] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6113.099606] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 6116.042970] Lustre: 144872:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 6124.317301] Lustre: DEBUG MARKER: == sanity-quota test 23: Quota should be honored with directIO (b16125) ========================================================== 02:37:05 (1788849425) [ 6125.671171] Lustre: DEBUG MARKER: SKIP: sanity-quota test_23 Overwrite in place is not guaranteed to be space neutral on ZFS [ 6127.276166] Lustre: DEBUG MARKER: == sanity-quota test 24: lfs draws an asterix when limit is reached (b16646) ========================================================== 02:37:08 (1788849428) [ 6175.388160] Lustre: DEBUG MARKER: == sanity-quota test 25: check indexes versions ========== 02:37:56 (1788849476) [ 6218.338635] Lustre: DEBUG MARKER: Write... [ 6220.567956] Lustre: DEBUG MARKER: Write out of block quota ... [ 6267.803546] Lustre: DEBUG MARKER: == sanity-quota test 27a: lfs quota/setquota should handle wrong arguments (b19612) ========================================================== 02:39:28 (1788849568) [ 6273.491413] Lustre: DEBUG MARKER: == sanity-quota test 27b: lfs quota/setquota should handle user/group/project ID (b20200) ========================================================== 02:39:34 (1788849574) [ 6283.292419] Lustre: DEBUG MARKER: == sanity-quota test 27c: lfs quota should support human-readable output ========================================================== 02:39:44 (1788849584) [ 6290.419908] Lustre: DEBUG MARKER: == sanity-quota test 27d: lfs setquota should support fraction block limit ========================================================== 02:39:51 (1788849591) [ 6297.236401] Lustre: DEBUG MARKER: == sanity-quota test 30: Hard limit updates should not reset grace times ========================================================== 02:39:58 (1788849598) [ 6354.113185] Lustre: DEBUG MARKER: == sanity-quota test 33: Basic usage tracking for user [ 6474.618371] Lustre: DEBUG MARKER: == sanity-quota test 34: Usage transfer for user [ 6634.383782] Lustre: DEBUG MARKER: == sanity-quota test 35: Usage is still accessible across reboot ========================================================== 02:45:36 (1788849936) [ 6684.442647] Lustre: DEBUG MARKER: Restart... [ 6688.230564] 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 [ 6688.232081] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 6688.246272] Lustre: Skipped 4 previous similar messages [ 6689.097927] Lustre: server umount lustre-MDT0000 complete [ 6691.676386] LustreError: 142510:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788849994 with bad export cookie 3739057982451858161 [ 6691.680366] LustreError: MGC192.168.206.126@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 6691.682869] LustreError: 142510:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 6691.765892] Lustre: server umount lustre-OST0000 complete [ 6694.276561] Lustre: server umount lustre-OST0001 complete [ 6702.909847] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing load_modules_local [ 6709.072812] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 6711.504968] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6713.369807] Lustre: 164002:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 6718.371119] LustreError: 164373:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 6718.384754] LustreError: 164373:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 3 previous similar messages [ 6718.388568] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:779 to 0x240000400:801) [ 6721.328961] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6723.554564] LustreError: 164373:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 6730.654839] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6732.270884] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:745 to 0x280000400:769) [ 6735.912850] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 6738.409971] Lustre: 165919:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 6787.908357] Lustre: DEBUG MARKER: == sanity-quota test 37: Quota accounted properly for file created by 'lfs setstripe' ========================================================== 02:48:09 (1788850089) [ 6847.247652] Lustre: DEBUG MARKER: == sanity-quota test 38: Quota accounting iterator doesn't skip id entries ========================================================== 02:49:08 (1788850148) [ 7756.162421] Lustre: DEBUG MARKER: == sanity-quota test 39: Project ID interface works correctly ========================================================== 03:04:18 (1788851058) [ 7766.426782] Lustre: server umount lustre-MDT0000 complete [ 7767.911048] LustreError: 163558:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788851070 with bad export cookie 3739057982451864629 [ 7767.916549] LustreError: MGC192.168.206.126@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 7777.291852] Lustre: server umount lustre-OST0000 complete [ 7778.817702] LustreError: 3305:0:(qsd_handler.c:298:qsd_req_completion()) $$$ DQACQ failed with -5, flags:0x8 qsd:lustre-OST0001 qtype:usr lqe: ffff92ad82853b00 id:0 enforced:0 granted: 0 pending:0 waiting:0 req:1 usage: 2383 qunit:0 qtune:0 edquot:0 default:no revoke:0 [ 7789.105574] Lustre: server umount lustre-OST0001 complete [ 7794.890349] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing load_modules_local [ 7798.766644] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 7798.769309] Lustre: Skipped 2 previous similar messages [ 7800.289834] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7801.386440] Lustre: 174350:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 7805.889214] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7808.800678] LustreError: 174720:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 7808.813635] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5804 to 0x240000400:5825) [ 7809.215862] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 7809.218931] Lustre: Skipped 1 previous similar message [ 7811.585564] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7814.637472] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5770 to 0x280000400:5793) [ 7815.006373] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 7816.299630] Lustre: 176262:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 7839.355993] Lustre: DEBUG MARKER: == sanity-quota test 40a: Hard link across different project ID ========================================================== 03:05:41 (1788851141) [ 7869.908338] Lustre: DEBUG MARKER: == sanity-quota test 40b: Mv across different project ID ========================================================== 03:06:11 (1788851171) [ 7901.081518] Lustre: DEBUG MARKER: == sanity-quota test 40c: Remote child Dir inherit project quota properly ========================================================== 03:06:42 (1788851202) [ 7901.615040] Lustre: DEBUG MARKER: SKIP: sanity-quota test_40c needs >= 2 MDTs [ 7902.235862] Lustre: DEBUG MARKER: == sanity-quota test 40d: Stripe Directory inherit project quota properly ========================================================== 03:06:44 (1788851204) [ 7902.780866] Lustre: DEBUG MARKER: SKIP: sanity-quota test_40d needs >= 2 MDTs [ 7903.433800] Lustre: DEBUG MARKER: == sanity-quota test 41: df should return projid-specific values ========================================================== 03:06:45 (1788851205) [ 7958.040605] Lustre: DEBUG MARKER: == sanity-quota test 42: lfs quota should include default quota info ========================================================== 03:07:39 (1788851259) [ 7988.471604] Lustre: DEBUG MARKER: == sanity-quota test 48: lfs quota --delete should delete quota project ID ========================================================== 03:08:10 (1788851290) [ 8036.012244] Lustre: DEBUG MARKER: == sanity-quota test 49a: lfs quota -a prints the quota usage for all quota IDs ========================================================== 03:08:57 (1788851337) [ 8043.433517] Lustre: *** cfs_fail_loc=a09, val=0*** [ 8043.434808] Lustre: Skipped 3 previous similar messages [ 8045.436238] Lustre: *** cfs_fail_loc=a09, val=0*** [ 8045.440037] Lustre: Skipped 249 previous similar messages [ 8049.439962] Lustre: *** cfs_fail_loc=a09, val=0*** [ 8049.441648] Lustre: Skipped 527 previous similar messages [ 8057.455384] Lustre: *** cfs_fail_loc=a09, val=0*** [ 8057.457023] Lustre: Skipped 1021 previous similar messages [ 8073.470642] Lustre: *** cfs_fail_loc=a09, val=0*** [ 8073.472847] Lustre: Skipped 1935 previous similar messages [ 8105.479925] Lustre: *** cfs_fail_loc=a09, val=0*** [ 8105.482063] Lustre: Skipped 4177 previous similar messages [ 8306.144696] 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 [ 8306.153736] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 8306.155642] Lustre: Skipped 1 previous similar message [ 8308.334213] Lustre: server umount lustre-MDT0000 complete [ 8310.253188] LustreError: 176265:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788851613 with bad export cookie 3739057982453626417 [ 8310.260814] LustreError: MGC192.168.206.126@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 8310.458955] Lustre: server umount lustre-OST0000 complete [ 8312.512266] Lustre: server umount lustre-OST0001 complete [ 8315.788536] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing set_hostid [ 8319.510861] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing load_modules_local [ 8323.209496] vdc: vdc1 vdc9 [ 8326.916628] vde: vde1 vde9 [ 8330.892085] vdf: vdf1 vdf9 [ 8336.849237] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing load_modules_local [ 8340.526506] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 8340.605794] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 8340.645268] Lustre: lustre-MDT0000: new disk, initializing [ 8340.785335] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 8340.807869] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 8342.442342] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 8344.948287] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 8347.511768] Lustre: lustre-OST0000: new disk, initializing [ 8347.514236] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 8347.516886] Lustre: Skipped 1 previous similar message [ 8349.332513] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:0:ost [ 8349.336147] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:0:ost] [ 8349.366234] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x240000400 [ 8349.748850] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 8354.298731] Lustre: lustre-OST0001: new disk, initializing [ 8354.299975] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 8355.718323] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:1:ost [ 8355.722086] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:1:ost] [ 8355.749125] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x280000400 [ 8356.687708] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 8361.613296] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 8362.926900] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 8384.149717] Lustre: DEBUG MARKER: == sanity-quota test 49b: lfs quota -a --blocks has a delimiter ========================================================== 03:14:45 (1788851685) [ 8386.846295] Lustre: DEBUG MARKER: == sanity-quota test 49c: lfs quota long options don't consume an extra argument ========================================================== 03:14:48 (1788851688) [ 8389.731597] Lustre: DEBUG MARKER: == sanity-quota test 49d: lfs quota -d and --delimiter both work ========================================================== 03:14:51 (1788851691) [ 8392.445766] Lustre: DEBUG MARKER: == sanity-quota test 50: Test if lfs find --projid works ========================================================== 03:14:54 (1788851694) [ 8421.807963] Lustre: DEBUG MARKER: == sanity-quota test 51: Test project accounting with mv/cp ========================================================== 03:15:23 (1788851723) [ 8459.542786] Lustre: DEBUG MARKER: == sanity-quota test 52: Rename normal file across project ID ========================================================== 03:16:01 (1788851761) [ 8479.431576] Lustre: DEBUG MARKER: rename directory return 255 [ 8508.633785] Lustre: DEBUG MARKER: == sanity-quota test 53: Project inherit attribute could be cleared ========================================================== 03:16:50 (1788851810) [ 8527.790930] Lustre: DEBUG MARKER: == sanity-quota test 54: basic lfs project interface test ========================================================== 03:17:09 (1788851829) [ 8550.872340] Lustre: DEBUG MARKER: == sanity-quota test 55: Chgrp should be affected by group quota ========================================================== 03:17:32 (1788851852) [ 8594.575673] LustreError: 191295: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 [ 8616.267778] Lustre: DEBUG MARKER: == sanity-quota test 56: lfs quota -t should work well === 03:18:38 (1788851918) [ 8642.854789] Lustre: DEBUG MARKER: == sanity-quota test 57: lfs project could tolerate errors ========================================================== 03:19:04 (1788851944) [ 8673.871367] Lustre: DEBUG MARKER: == sanity-quota test 58: project ID should be kept for new mirrors created by FID ========================================================== 03:19:35 (1788851975) [ 8775.460225] Lustre: DEBUG MARKER: == sanity-quota test 59: lfs project dosen't crash kernel with project disabled ========================================================== 03:21:17 (1788852077) [ 8776.145913] Lustre: DEBUG MARKER: SKIP: sanity-quota test_59 ldiskfs only test [ 8776.884337] Lustre: DEBUG MARKER: == sanity-quota test 60: Test quota for root with setgid ========================================================== 03:21:18 (1788852078) [ 8812.170408] Lustre: DEBUG MARKER: SKIP: sanity-quota test_61 skipping SLOW test 61 [ 8812.823411] Lustre: DEBUG MARKER: == sanity-quota test 62: Project inherit should be only changed by root ========================================================== 03:21:54 (1788852114) [ 8831.930286] Lustre: DEBUG MARKER: SKIP: sanity-quota test_63 skipping excluded test 63 [ 8832.783960] Lustre: DEBUG MARKER: == sanity-quota test 64: lfs project on non-dir/files should succeed ========================================================== 03:22:14 (1788852134) [ 8868.887695] Lustre: DEBUG MARKER: SKIP: sanity-quota test_65 skipping excluded test 65 [ 8869.708414] Lustre: DEBUG MARKER: == sanity-quota test 66: nonroot user can not change project state in default ========================================================== 03:22:51 (1788852171) [ 8906.598546] Lustre: DEBUG MARKER: == sanity-quota test 67: quota pools recalculation ======= 03:23:27 (1788852207) [ 8907.604711] Lustre: DEBUG MARKER: SKIP: sanity-quota test_67 ZFS grants some block space together with inode [ 8908.595393] Lustre: DEBUG MARKER: == sanity-quota test 68: slave number in quota pool changed after each add/remove OST ========================================================== 03:23:30 (1788852210) [ 8928.976660] LustreError: 214850:0:(mgs_handler.c:1144:mgs_iocontrol_pool()) OBD_IOC_POOL err -17, cmd CE021 for pool lustre.qpool1 [ 8957.268641] Lustre: DEBUG MARKER: == sanity-quota test 69: EDQUOT at one of pools shouldn't affect DOM ========================================================== 03:24:18 (1788852258) [ 8977.052731] Lustre: DEBUG MARKER: User quota (block hardlimit:200 MB) [ 8977.872584] Lustre: DEBUG MARKER: User quota (block hardlimit:10 MB) [ 9072.831410] Lustre: DEBUG MARKER: == sanity-quota test 70a: check lfs setquota/quota with a pool option ========================================================== 03:26:14 (1788852374) [ 9112.208339] Lustre: DEBUG MARKER: == sanity-quota test 70b: lfs setquota pool works properly ========================================================== 03:26:53 (1788852413) [ 9133.825482] Lustre: DEBUG MARKER: == sanity-quota test 71a: Check PFL with quota pools ===== 03:27:15 (1788852435) [ 9134.536926] Lustre: DEBUG MARKER: SKIP: sanity-quota test_71a ZFS grants some block space together with inode [ 9135.278927] Lustre: DEBUG MARKER: == sanity-quota test 71b: Check SEL with quota pools ===== 03:27:17 (1788852437) [ 9135.998241] Lustre: DEBUG MARKER: SKIP: sanity-quota test_71b ZFS grants some block space together with inode [ 9136.752203] Lustre: DEBUG MARKER: == sanity-quota test 72: lfs quota --pool prints only pool's OSTs ========================================================== 03:27:18 (1788852438) [ 9147.253146] Lustre: DEBUG MARKER: User quota (block hardlimit:50 MB) [ 9157.299132] Lustre: DEBUG MARKER: Write... [ 9158.519482] Lustre: DEBUG MARKER: Write out of block quota ... [ 9196.574376] Lustre: DEBUG MARKER: == sanity-quota test 73a: default limits at OST Pool Quotas ========================================================== 03:28:18 (1788852498) [ 9214.790151] Lustre: DEBUG MARKER: set to use default quota [ 9215.700401] Lustre: DEBUG MARKER: set default quota [ 9216.542256] Lustre: DEBUG MARKER: get default quota [ 9219.582822] Lustre: DEBUG MARKER: Test not out of quota [ 9221.692864] Lustre: DEBUG MARKER: Test out of quota [ 9226.964592] Lustre: DEBUG MARKER: Increase default quota [ 9252.552554] Lustre: DEBUG MARKER: Set quota to override default quota [ 9252.575142] LustreError: 191293:0:(qmt_entry.c:558:qmt_adjust_edquot()) $$$ set revoke_time explicitly qmt:lustre-QMT0000 pool:dt-qpool1 id:60000 enforced:1 hard:20480 soft:20480 granted:45063 time:1789457355 qunit: 1024 edquot:0 may_rel:0 revoke:0 default:no [ 9257.569759] Lustre: DEBUG MARKER: Set to use default quota again [ 9268.790467] Lustre: DEBUG MARKER: Cleanup [ 9323.127127] Lustre: DEBUG MARKER: == sanity-quota test 73b: default OST Pool Quotas limit for new user ========================================================== 03:30:24 (1788852624) [ 9338.556894] Lustre: DEBUG MARKER: set default quota for qpool1 [ 9339.171463] Lustre: DEBUG MARKER: Write from user that hasn't lqe [ 9374.081447] Lustre: DEBUG MARKER: == sanity-quota test 74: check quota pools per user ====== 03:31:15 (1788852675) [ 9425.322779] Lustre: DEBUG MARKER: == sanity-quota test 75: nodemap squashed root respects quota enforcement ========================================================== 03:32:07 (1788852727) [ 9475.505884] Lustre: DEBUG MARKER: Write... [ 9476.912810] Lustre: DEBUG MARKER: Write out of block quota ... [ 9554.555183] Lustre: DEBUG MARKER: == sanity-quota test 76: project ID 4294967295 should be not allowed ========================================================== 03:34:16 (1788852856) [ 9584.862456] Lustre: DEBUG MARKER: == sanity-quota test 77: lfs setquota should fail in Lustre mount with 'ro' ========================================================== 03:34:46 (1788852886) [ 9588.044487] Lustre: DEBUG MARKER: == sanity-quota test 78A: Check fallocate increase quota usage ========================================================== 03:34:49 (1788852889) [ 9589.105657] Lustre: DEBUG MARKER: SKIP: sanity-quota test_78A fallocate not supported [ 9589.797818] Lustre: DEBUG MARKER: == sanity-quota test 78a: Check fallocate increase projectid usage ========================================================== 03:34:51 (1788852891) [ 9590.740928] Lustre: DEBUG MARKER: SKIP: sanity-quota test_78a fallocate not supported [ 9591.336619] Lustre: DEBUG MARKER: == sanity-quota test 79: access to non-existed dt-pool/info doesn't cause a panic ========================================================== 03:34:53 (1788852893) [ 9600.940260] Lustre: DEBUG MARKER: == sanity-quota test 80: check for EDQUOT after OST failover ========================================================== 03:35:02 (1788852902) [ 9601.517754] Lustre: DEBUG MARKER: SKIP: sanity-quota test_80 ZFS grants some block space together with inode [ 9602.138110] Lustre: DEBUG MARKER: == sanity-quota test 81: Race qmt_start_pool_recalc with qmt_pool_free ========================================================== 03:35:04 (1788852904) [ 9611.964297] Lustre: DEBUG MARKER: User quota (block hardlimit:20 MB) [ 9615.104057] LustreError: 240950:0:(qmt_pool.c:1407:qmt_pool_recalc()) cfs_fail_timeout id a07 sleeping for 10000ms [ 9619.176158] Lustre: lustre-MDT0000: Not available for connect from 192.168.206.26@tcp (stopping) [ 9620.450470] 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 [ 9620.453964] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 9620.459626] Lustre: Skipped 2 previous similar messages [ 9622.495343] LustreError: 3304:0:(client.c:1394:ptlrpc_import_delay_req()) @@@ IMP_CLOSED req@ffff92aeb236c700 x1875738267969536/t0(0) o601->lustre-MDT0000-lwp-MDT0000@0@lo:23/10 lens 336/336 e 0 to 0 dl 0 ref 1 fl Rpc:NQU/200/ffffffff rc 0/-1 job:'lquota_wb_lustr.0' uid:0 gid:0 projid:4294967295 [ 9622.505130] LustreError: 3304:0:(qsd_handler.c:298:qsd_req_completion()) $$$ DQACQ failed with -5, flags:0x8 qsd:lustre-MDT0000 qtype:grp lqe: ffff92adbd1aa300 id:0 enforced:0 granted: 0 pending:0 waiting:0 req:1 usage: 372 qunit:0 qtune:0 edquot:0 default:no revoke:0 [ 9622.517509] LustreError: 3304:0:(qsd_handler.c:298:qsd_req_completion()) Skipped 2 previous similar messages [ 9624.278243] Lustre: lustre-MDT0000: Not available for connect from 192.168.206.26@tcp (stopping) [ 9624.281572] Lustre: Skipped 1 previous similar message [ 9625.143111] LustreError: 240950:0:(qmt_pool.c:1407:qmt_pool_recalc()) cfs_fail_timeout id a07 awake [ 9625.288897] Lustre: server umount lustre-MDT0000 complete [ 9628.552875] LustreError: MGC192.168.206.126@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 9628.773274] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 9628.777274] Lustre: Skipped 2 previous similar messages [ 9628.861619] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:27 to 0x240000400:65) [ 9628.862499] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:27 to 0x280000400:65) [ 9630.350409] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 9640.994869] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 9640.998325] Lustre: Skipped 5 previous similar messages [ 9650.120541] Lustre: DEBUG MARKER: == sanity-quota test 82: verify more than 8 qids for single operation ========================================================== 03:35:52 (1788852952) [ 9671.872690] Lustre: DEBUG MARKER: == sanity-quota test 83: Setting default quota shouldn't affect grace time ========================================================== 03:36:13 (1788852973) [ 9696.669373] Lustre: DEBUG MARKER: == sanity-quota test 84: Reset quota should fix the insane granted quota ========================================================== 03:36:38 (1788852998) [ 9723.569418] Lustre: *** cfs_fail_loc=a08, val=0*** [ 9723.571225] Lustre: Skipped 85 previous similar messages [ 9723.573288] Lustre: *** cfs_fail_loc=a08, val=0*** [ 9788.246864] Lustre: DEBUG MARKER: == sanity-quota test 85: do not hung at write with the least_qunit ========================================================== 03:38:10 (1788853090) [ 9835.985823] Lustre: DEBUG MARKER: == sanity-quota test 86: Pre-acquired quota should be released if quota is over limit ========================================================== 03:38:57 (1788853137) [ 9880.594267] LustreError: 241531: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:1789457983 qunit: 1024 edquot:0 may_rel:0 revoke:0 default:no [ 9973.077480] LustreError: 241531: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:1789458075 qunit: 1024 edquot:0 may_rel:0 revoke:0 default:no [10056.482823] LustreError: 242446: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:1789458159 qunit: 1024 edquot:0 may_rel:0 revoke:0 default:no [10133.593875] Lustre: DEBUG MARKER: == sanity-quota test 87: lfs quota -a should print default quota setting ========================================================== 03:43:54 (1788853434) [10142.652627] Lustre: *** cfs_fail_loc=a09, val=0*** [10183.785518] 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 [10183.793163] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [10183.797920] Lustre: Skipped 1 previous similar message [10189.279732] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [10189.282373] Lustre: Skipped 2 previous similar messages [10189.982970] Lustre: server umount lustre-MDT0000 complete [10193.911322] LustreError: MGC192.168.206.126@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [10194.170084] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [10194.229891] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:27 to 0x280000400:97) [10194.234939] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:68 to 0x240000400:97) [10195.948535] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [10199.526195] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [10199.528311] Lustre: Skipped 1 previous similar message [10218.981263] Lustre: DEBUG MARKER: == sanity-quota test 88: Writing over quota should not hang ========================================================== 03:45:20 (1788853520) [10219.606697] Lustre: DEBUG MARKER: SKIP: sanity-quota test_88 require client with >4k pages [10220.277462] Lustre: DEBUG MARKER: == sanity-quota test 89: Show default quota with squash_uid ========================================================== 03:45:22 (1788853522) [10229.064569] Lustre: DEBUG MARKER: == sanity-quota test 90a: lfs quota should work without mount point ========================================================== 03:45:30 (1788853530) [10241.281872] Lustre: DEBUG MARKER: == sanity-quota test 90b: lfs quota should work with multiple mount points ========================================================== 03:45:43 (1788853543) [10255.781985] Lustre: DEBUG MARKER: == sanity-quota test 91: new quota index files in quota_master ========================================================== 03:45:57 (1788853557) [10270.714950] Lustre: server umount lustre-MDT0000 complete [10272.701313] LustreError: 191278:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788853575 with bad export cookie 3739057982455128302 [10272.707703] LustreError: MGC192.168.206.126@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [10287.583101] Lustre: 3305:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788853574/real 1788853574] req@ffff92ae88e0ce00 x1875738268721536/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788853590 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [10287.599290] Lustre: 3305:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 7 previous similar messages [10287.606449] 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 [10287.613246] Lustre: Skipped 1 previous similar message [10289.094162] Lustre: server umount lustre-OST0000 complete [10297.324297] Lustre: server umount lustre-OST0001 complete [10300.897688] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing set_hostid [10304.787500] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing load_modules_local [10309.585616] vdc: vdc1 vdc9 [10314.538967] vde: vde1 vde9 [10319.989190] vdf: vdf1 vdf9 [10325.940599] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [10326.076369] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [10326.128179] Lustre: lustre-MDT0000: new disk, initializing [10326.382250] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [10326.423618] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [10329.155304] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [10334.185902] Lustre: DEBUG MARKER: oleg626-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [10337.103938] Lustre: lustre-OST0000: new disk, initializing [10337.106132] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [10337.108953] Lustre: Skipped 1 previous similar message [10338.583836] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:0:ost [10338.586637] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:0:ost] [10338.627515] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x240000400 [10339.499908] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [10343.525859] Lustre: DEBUG MARKER: oleg626-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [10346.173112] Lustre: lustre-OST0001: new disk, initializing [10346.175675] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [10346.211422] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [10346.213978] Lustre: Skipped 1 previous similar message [10347.606042] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:1:ost [10347.610232] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:1:ost] [10347.648612] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x280000400 [10348.733602] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [10353.500764] Lustre: DEBUG MARKER: oleg626-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0001-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [10362.849700] 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 [10362.858584] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [10362.862681] Lustre: Skipped 1 previous similar message [10367.752591] Lustre: server umount lustre-MDT0000 complete [10373.019991] LustreError: MGC192.168.206.126@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [10375.074154] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [10378.816666] Lustre: DEBUG MARKER: oleg626-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [10382.305707] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [10382.308588] Lustre: Skipped 1 previous similar message [10384.598454] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 5 sec [10390.417514] Lustre: server umount lustre-MDT0000 complete [10391.988074] LustreError: 258147:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788853694 with bad export cookie 3739057982455130696 [10391.994228] LustreError: MGC192.168.206.126@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [10401.286462] Lustre: server umount lustre-OST0000 complete [10412.184752] Lustre: server umount lustre-OST0001 complete [10419.108691] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing set_hostid [10422.145363] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing load_modules_local [10426.449310] vdc: vdc1 vdc9 [10431.656530] vde: vde1 vde9 [10437.570739] vdf: vdf1 vdf9 [10447.011771] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing load_modules_local [10452.353966] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [10452.497041] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [10452.540614] Lustre: lustre-MDT0000: new disk, initializing [10452.713808] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [10452.716917] Lustre: Skipped 1 previous similar message [10452.754703] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [10455.003989] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [10457.838197] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [10460.906911] Lustre: lustre-OST0000: new disk, initializing [10460.909241] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [10460.911405] Lustre: Skipped 1 previous similar message [10462.644876] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:0:ost [10462.655091] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:0:ost] [10462.726575] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x240000400 [10463.947964] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [10469.826944] Lustre: lustre-OST0001: new disk, initializing [10469.832802] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [10471.469426] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:1:ost [10471.474325] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:1:ost] [10471.536281] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x280000400 [10472.963789] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [10479.141149] Lustre: DEBUG MARKER: Using TIMEOUT=20 [10481.206595] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [10485.023549] Lustre: DEBUG MARKER: == sanity-quota test 92: Cannot set inode limit with Quota Pools ========================================================== 03:49:46 (1788853786) [10494.296875] Lustre: DEBUG MARKER: == sanity-quota test 93: update projid while client write to OST ========================================================== 03:49:56 (1788853796) [10512.989034] Lustre: *** cfs_fail_loc=170c, val=0*** [10555.836335] Lustre: DEBUG MARKER: == sanity-quota test 94: lfs quota all respects nodemap offset ========================================================== 03:50:57 (1788853857) [10578.148063] Lustre: lustre-MDT0000: Not available for connect from 192.168.206.26@tcp (stopping) [10578.151191] Lustre: Skipped 1 previous similar message [10578.913309] 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 [10578.924805] Lustre: Skipped 2 previous similar messages [10584.031852] LustreError: 267391:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [10584.040144] LustreError: 267391:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 1 previous similar message [10585.417799] Lustre: server umount lustre-MDT0000 complete [10588.988972] LustreError: MGC192.168.206.126@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [10589.176938] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [10589.180124] Lustre: Skipped 2 previous similar messages [10589.252593] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3 to 0x240000400:33) [10590.846717] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [10594.274088] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [10594.278604] Lustre: Skipped 1 previous similar message [10612.958425] Lustre: lustre-MDT0000: Not available for connect from 192.168.206.26@tcp (stopping) [10612.961841] Lustre: Skipped 3 previous similar messages [10616.149829] Lustre: server umount lustre-MDT0000 complete [10620.016747] LustreError: MGC192.168.206.126@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [10620.297469] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3 to 0x240000400:65) [10622.280237] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [10634.597296] Lustre: DEBUG MARKER: == sanity-quota test 95a: Correct limits for squashed root ========================================================== 03:52:16 (1788853936) [10646.473422] Lustre: DEBUG MARKER: == sanity-quota test 95b: df respects squashed project id ========================================================== 03:52:28 (1788853948) [10671.333454] Lustre: DEBUG MARKER: == sanity-quota test 96: quota grant should be released when big files are deleted ========================================================== 03:52:53 (1788853973) [10671.885966] Lustre: DEBUG MARKER: SKIP: sanity-quota test_96 the test in only needed to run on LDiskFS [10672.507634] Lustre: DEBUG MARKER: == sanity-quota test 97a: LQA control commands =========== 03:52:54 (1788853974) [10683.472654] LustreError: 279187:0:(qmt_lqa.c:79:qmt_lqa_destroy()) lustre-QMT0000: cannot destroy lqa-dt-lqa1: rc = -2 [10683.477694] LustreError: 279187:0:(qmt_lqa.c:84:qmt_lqa_destroy()) lustre-QMT0000: cannot destroy lqa-md-lqa1: rc = -2 [10684.273370] Lustre: DEBUG MARKER: == sanity-quota test 97b: Check LQA internals ============ 03:53:06 (1788853986) [10694.529310] LustreError: 279983:0:(qmt_lqa.c:250:qmt_lqa_insert_range()) lustre-QMT0000: LQA range 15-31 partially overlaps with existing range 10-19: rc = -34 [10694.534215] LustreError: 279983:0:(qmt_lqa.c:669:qmt_lqa_add()) lustre-QMT0000: lqa:lqa1 can't add range 15:31: rc = -17 [10696.080229] LustreError: 280179:0:(qmt_lqa.c:825:qmt_lqa_remove()) lustre-QMT0000: lqa-md-lqa1 cannot remove range 10:19: rc = -2 [10700.680141] Lustre: DEBUG MARKER: adding 50 LQA ranges took 1s [10702.812218] Lustre: DEBUG MARKER: Removing 50 LQA ranges took 1s [10706.364991] Lustre: DEBUG MARKER: == sanity-quota test 97c: LQA lfs quota commands and MDS restart consistency ========================================================== 03:53:28 (1788854008) [10708.232046] Lustre: Failing over lustre-MDT0000 [10708.450082] Lustre: server umount lustre-MDT0000 complete [10711.865918] LustreError: MGC192.168.206.126@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [10711.994992] Lustre: 282033:0:(scrub.c:697:lustre_index_register()) lustre-MDT0000: the index [0x200000003:0x74:0x0] has registered with 8/8, may be invalid, replace with 4/8 [10712.000241] LustreError: 282033:0:(qmt_lqa.c:522:qmt_lqa_load_ranges_from_disk()) lustre-QMT0000: Failed to get record from IAM iterator: rc = -2 [10712.017371] 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 [10712.025985] Lustre: Skipped 3 previous similar messages [10712.132385] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [10713.806863] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [10715.372780] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [10715.405104] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [10715.425249] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3 to 0x240000400:97) [10716.047787] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [10719.300939] Lustre: DEBUG MARKER: == sanity-quota test 97d: LQA disk persistence using standard commands ========================================================== 03:53:41 (1788854021) [10727.327206] Lustre: 3305:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788854014/real 1788854014] req@ffff92aeb3fa7800 x1875738268887808/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788854030 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [10730.685692] Lustre: Failing over lustre-MDT0000 [10730.722136] Lustre: lustre-MDT0000: Not available for connect from 192.168.206.26@tcp (stopping) [10730.726384] Lustre: Skipped 2 previous similar messages [10730.926040] Lustre: server umount lustre-MDT0000 complete [10734.546097] Lustre: 284074:0:(scrub.c:697:lustre_index_register()) lustre-MDT0000: the index [0x200000003:0x88:0x0] has registered with 8/8, may be invalid, replace with 4/8 [10734.632753] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [10734.637843] Lustre: Skipped 2 previous similar messages [10734.681328] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [10735.829215] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [10735.856288] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [10735.871904] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3 to 0x240000400:129) [10736.317792] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [10738.289929] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [10739.682290] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [10739.686413] Lustre: Skipped 5 previous similar messages [10748.895091] Lustre: 3305:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788854035/real 1788854035] req@ffff92aeb3fa7100 x1875738268899968/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788854051 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [10748.909200] Lustre: 3305:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [10763.746786] Lustre: DEBUG MARKER: == sanity-quota test 97e: LQA add/remove should reject invalid ranges ========================================================== 03:54:25 (1788854065) [10770.264396] LustreError: 286401:0:(qmt_lqa.c:79:qmt_lqa_destroy()) lustre-QMT0000: cannot destroy lqa-dt-lqa1: rc = -2 [10770.268226] LustreError: 286401:0:(qmt_lqa.c:84:qmt_lqa_destroy()) lustre-QMT0000: cannot destroy lqa-md-lqa1: rc = -2 [10771.165868] Lustre: DEBUG MARKER: == sanity-quota test 98: Verify MDT retry on -EDQUOT during mkdir ========================================================== 03:54:32 (1788854072) [10771.837200] Lustre: DEBUG MARKER: SKIP: sanity-quota test_98 needs >= 2 MDTs [10772.553523] Lustre: DEBUG MARKER: == sanity-quota test 300: inode quota with MDT directory migration at 80% limit ========================================================== 03:54:34 (1788854074) [10773.231676] Lustre: DEBUG MARKER: SKIP: sanity-quota test_300 needs >= 2 MDTs [10775.846537] Lustre: DEBUG MARKER: == sanity-quota test complete, duration 10532 sec ======== 03:54:37 (1788854077) [10776.532461] Lustre: DEBUG MARKER: === sanity-quota: start cleanup 03:54:38 (1788854078) === [10777.820426] Lustre: DEBUG MARKER: === sanity-quota: finish cleanup 03:54:39 (1788854079) === [10779.214245] Lustre: server umount lustre-MDT0000 complete [10780.943728] LustreError: 269331:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788854083 with bad export cookie 3739057982455136177 [10780.948956] LustreError: MGC192.168.206.126@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [10780.953581] LustreError: Skipped 1 previous similar message [10790.408542] Lustre: server umount lustre-OST0000 complete [10802.610726] Lustre: server umount lustre-OST0001 complete [10807.887316] Lustre: DEBUG MARKER: oleg626-server.virtnet: executing unload_modules_local [10809.145260] Key type lgssc unregistered [10809.276523] LNet: 287937:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [10809.279915] LNetError: 287937:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [10809.289313] LNet: Removed LNI 192.168.206.126@tcp [10809.598128] Key type .llcrypt unregistered [10809.599559] Key type ._llcrypt unregistered