[ 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 503216905 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, 524584K 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.001011] APIC: Switch to symmetric I/O mode setup [ 0.003245] x2apic enabled [ 0.005004] Switched APIC routing to physical x2apic. [ 0.006016] kvm-guest: setup PV IPIs [ 0.009551] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.010000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.010021] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.011012] pid_max: default: 32768 minimum: 301 [ 0.013014] LSM: Security Framework initializing [ 0.014057] Yama: becoming mindful. [ 0.015046] SELinux: Initializing. [ 0.016086] *** VALIDATE selinux *** [ 0.024422] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.028707] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.029168] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.030116] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.031122] *** VALIDATE tmpfs *** [ 0.033045] *** VALIDATE proc *** [ 0.034253] *** VALIDATE cgroup *** [ 0.035015] *** VALIDATE cgroup2 *** [ 0.036269] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.038153] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.039008] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.040035] Spectre V2 : User space: Vulnerable [ 0.041010] Speculative Store Bypass: Vulnerable [ 0.044132] debug: unmapping init [mem 0xffffffffb5a59000-0xffffffffb5a60fff] [ 0.046189] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.047736] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.048026] ... version: 2 [ 0.049014] ... bit width: 48 [ 0.050014] ... generic registers: 4 [ 0.051014] ... value mask: 0000ffffffffffff [ 0.052016] ... max period: 00007fffffffffff [ 0.053016] ... fixed-purpose events: 3 [ 0.054012] ... event mask: 000000070000000f [ 0.056236] rcu: Hierarchical SRCU implementation. [ 0.058494] smp: Bringing up secondary CPUs ... [ 0.059614] x86: Booting SMP configuration: [ 0.060028] .... node #0, CPUs: #1 #2 #3 [ 0.063596] smp: Brought up 1 node, 4 CPUs [ 0.065017] smpboot: Max logical packages: 1 [ 0.066024] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.250033] node 0 deferred pages initialised in 181ms [ 0.253145] devtmpfs: initialized [ 0.254370] x86/mm: Memory block size: 128MB [ 0.258065] gcov: version magic: 0x41383552 [ 0.261364] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.266098] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.269308] pinctrl core: initialized pinctrl subsystem [ 0.271207] [ 0.271824] ************************************************************* [ 0.275015] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.277014] ** ** [ 0.280018] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.283016] ** ** [ 0.285014] ** This means that this kernel is built to expose internal ** [ 0.287015] ** IOMMU data structures, which may compromise security on ** [ 0.289014] ** your system. ** [ 0.291015] ** ** [ 0.293014] ** If you see this message and you are not debugging the ** [ 0.295017] ** kernel, report this immediately to your vendor! ** [ 0.298014] ** ** [ 0.301013] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.303013] ************************************************************* [ 0.306828] NET: Registered protocol family 16 [ 0.309553] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.312062] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.314062] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.319075] cpuidle: using governor menu [ 0.320867] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.321632] PCI: Using configuration type 1 for base access [ 0.322166] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.329187] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.332029] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.336148] cryptd: max_cpu_qlen set to 1000 [ 0.339284] ACPI: Added _OSI(Module Device) [ 0.341086] ACPI: Added _OSI(Processor Device) [ 0.342016] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.344016] ACPI: Added _OSI(Processor Aggregator Device) [ 0.349545] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.356422] ACPI: Interpreter enabled [ 0.357088] ACPI: PM: (supports S0 S3 S4 S5) [ 0.359024] ACPI: Using IOAPIC for interrupt routing [ 0.361189] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.364496] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.375292] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.377060] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.379020] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.382135] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.387049] acpiphp: Slot [2] registered [ 0.388275] acpiphp: Slot [5] registered [ 0.390191] acpiphp: Slot [6] registered [ 0.392166] acpiphp: Slot [7] registered [ 0.393161] acpiphp: Slot [8] registered [ 0.394189] acpiphp: Slot [9] registered [ 0.396172] acpiphp: Slot [10] registered [ 0.398200] acpiphp: Slot [3] registered [ 0.400131] acpiphp: Slot [4] registered [ 0.402137] acpiphp: Slot [11] registered [ 0.404123] acpiphp: Slot [12] registered [ 0.405127] acpiphp: Slot [13] registered [ 0.407185] acpiphp: Slot [14] registered [ 0.409123] acpiphp: Slot [15] registered [ 0.410153] acpiphp: Slot [16] registered [ 0.412122] acpiphp: Slot [17] registered [ 0.414115] acpiphp: Slot [18] registered [ 0.415131] acpiphp: Slot [19] registered [ 0.417123] acpiphp: Slot [20] registered [ 0.418138] acpiphp: Slot [21] registered [ 0.420133] acpiphp: Slot [22] registered [ 0.422132] acpiphp: Slot [23] registered [ 0.424129] acpiphp: Slot [24] registered [ 0.426162] acpiphp: Slot [25] registered [ 0.427121] acpiphp: Slot [26] registered [ 0.429133] acpiphp: Slot [27] registered [ 0.431161] acpiphp: Slot [28] registered [ 0.432108] acpiphp: Slot [29] registered [ 0.434170] acpiphp: Slot [30] registered [ 0.437170] acpiphp: Slot [31] registered [ 0.438083] PCI host bridge to bus 0000:00 [ 0.440027] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.442035] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.444032] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.447032] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.450037] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.453039] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.455206] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.458000] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.462399] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.472960] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.479000] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.481036] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.483022] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.484017] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.488739] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.492898] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.495051] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.498870] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.505016] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.518025] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.524019] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.531455] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.539019] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.551017] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.573021] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.584737] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.594018] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.601020] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.619024] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.629060] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.643016] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.654022] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.674022] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.698025] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.707021] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.713022] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.733025] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.748693] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.760021] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.767022] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.791030] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 0.802148] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.809021] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.817022] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.839027] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 0.859000] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.863968] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.866557] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.870449] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.872403] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.877162] iommu: Default domain type: Passthrough [ 0.881780] SCSI subsystem initialized [ 0.884416] ACPI: bus type USB registered [ 0.887194] usbcore: registered new interface driver usbfs [ 0.890164] usbcore: registered new interface driver hub [ 0.892185] usbcore: registered new device driver usb [ 0.894244] pps_core: LinuxPPS API ver. 1 registered [ 0.897018] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.900091] PTP clock support registered [ 0.903155] EDAC MC: Ver: 3.0.0 [ 0.905142] PCI: Using ACPI for IRQ routing [ 0.907607] NetLabel: Initializing [ 0.909023] NetLabel: domain hash size = 128 [ 0.911018] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.913114] NetLabel: unlabeled traffic allowed by default [ 0.916157] vgaarb: loaded [ 0.917445] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.920020] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.928013] clocksource: Switched to clocksource kvm-clock [ 1.046586] VFS: Disk quotas dquot_6.6.0 [ 1.048383] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 1.050244] *** VALIDATE ramfs *** [ 1.051354] *** VALIDATE hugetlbfs *** [ 1.052912] pnp: PnP ACPI init [ 1.056112] pnp: PnP ACPI: found 6 devices [ 1.076293] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 1.079927] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 1.082241] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 1.084462] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 1.086530] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 1.088958] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 1.092079] NET: Registered protocol family 2 [ 1.094659] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 1.099126] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 1.103921] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 1.108504] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 1.115017] TCP: Hash tables configured (established 65536 bind 65536) [ 1.119570] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 1.124229] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 1.128671] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 1.133191] NET: Registered protocol family 1 [ 1.136767] RPC: Registered named UNIX socket transport module. [ 1.140089] RPC: Registered udp transport module. [ 1.142803] RPC: Registered tcp transport module. [ 1.145211] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 1.148638] NET: Registered protocol family 44 [ 1.151129] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 1.153831] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 1.156190] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 1.158671] PCI: CLS 0 bytes, default 64 [ 1.160634] Unpacking initramfs... [ 2.692323] debug: unmapping init [mem 0xffff9d237cc54000-0xffff9d237ffbffff] [ 2.697512] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.700268] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.703384] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 3.221232] Initialise system trusted keyrings [ 3.223620] Key type blacklist registered [ 3.226041] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 3.235056] zbud: loaded [ 3.238539] *** VALIDATE nfs *** [ 3.240051] *** VALIDATE nfs4 *** [ 3.242248] pstore: using deflate compression [ 3.247807] Platform Keyring initialized [ 3.371068] NET: Registered protocol family 38 [ 3.372963] Key type asymmetric registered [ 3.374647] Asymmetric key parser 'x509' registered [ 3.376769] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 3.380292] io scheduler mq-deadline registered [ 3.384460] io scheduler kyber registered [ 3.386177] io scheduler bfq registered [ 3.388478] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 3.392103] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 3.395526] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 3.398947] ACPI: Power Button [PWRF] [ 3.403905] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 3.412316] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 3.424928] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 3.431442] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 3.444872] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 3.473727] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.503785] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.508496] Non-volatile memory driver v1.3 [ 3.510457] Linux agpgart interface v0.103 [ 3.542584] virtio_blk virtio1: [vda] 146648 512-byte logical blocks (75.1 MB/71.6 MiB) [ 3.546232] vda: detected capacity change from 0 to 75083776 [ 3.564950] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.568159] vdb: detected capacity change from 0 to 1073741824 [ 3.585678] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.589091] vdc: detected capacity change from 0 to 2621440000 [ 3.610768] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.614677] vdd: detected capacity change from 0 to 2621440000 [ 3.638672] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.641894] vde: detected capacity change from 0 to 4294967296 [ 3.656649] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.659622] vdf: detected capacity change from 0 to 4294967296 [ 3.666911] libphy: Fixed MDIO Bus: probed [ 3.672099] usbcore: registered new interface driver usbserial_generic [ 3.674254] usbserial: USB Serial support registered for generic [ 3.676204] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.679800] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.681285] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.683426] mousedev: PS/2 mouse device common for all mice [ 3.686491] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.688849] rtc_cmos 00:05: RTC can wake from S4 [ 3.693934] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.694235] rtc_cmos 00:05: registered as rtc0 [ 3.703157] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.703286] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.706274] intel_pstate: CPU model not supported [ 3.713245] hid: raw HID events driver (C) Jiri Kosina [ 3.715602] usbcore: registered new interface driver usbhid [ 3.717158] usbhid: USB HID core driver [ 3.718912] drop_monitor: Initializing network drop monitor service [ 3.721505] Initializing XFRM netlink socket [ 3.723954] NET: Registered protocol family 10 [ 3.727953] Segment Routing with IPv6 [ 3.729717] NET: Registered protocol family 17 [ 3.732137] mpls_gso: MPLS GSO support [ 3.738363] RAS: Correctable Errors collector initialized. [ 3.740032] AVX version of gcm_enc/dec engaged. [ 3.741348] AES CTR mode by8 optimization enabled [ 3.819750] sched_clock: Marking stable (3819717522, 0)->(4772105568, -952388046) [ 3.823728] registered taskstats version 1 [ 3.825757] Loading compiled-in X.509 certificates [ 3.827749] zswap: loaded using pool lzo/zbud [ 3.855586] Key type big_key registered [ 3.868777] Key type encrypted registered [ 3.870484] ima: No TPM chip found, activating TPM-bypass! [ 3.872481] ima: Allocated hash algorithm: sha1 [ 3.874130] ima: No architecture policies found [ 3.875711] evm: Initialising EVM extended attributes: [ 3.877337] evm: security.selinux [ 3.878311] evm: security.ima [ 3.879155] evm: security.capability [ 3.880635] evm: HMAC attrs: 0x1 [ 3.883205] rtc_cmos 00:05: setting system clock to 2026-09-06 20:10:27 UTC (1788725427) [ 3.889642] debug: unmapping init [mem 0xffffffffb6a03000-0xffffffffb6bfffff] [ 3.892481] debug: unmapping init [mem 0xffffffffb5782000-0xffffffffb5a58fff] [ 3.901086] Write protecting the kernel read-only data: 28672k [ 3.905728] debug: unmapping init [mem 0xffffffffb3e03000-0xffffffffb3ffffff] [ 3.908403] debug: unmapping init [mem 0xffffffffb4714000-0xffffffffb47fffff] [ 3.942613] 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.950588] systemd[1]: Detected virtualization kvm. [ 3.952830] systemd[1]: Detected architecture x86-64. [ 3.954936] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.984309] systemd[1]: No hostname configured. [ 3.986085] systemd[1]: Set hostname to . [ 3.988344] random: systemd: uninitialized urandom read (16 bytes read) [ 3.991058] systemd[1]: Initializing machine ID from random generator. [ 4.044934] random: ln: uninitialized urandom read (6 bytes read) [ 4.156586] random: systemd: uninitialized urandom read (16 bytes read) [ 4.159159] systemd[1]: Reached target Swap. [ OK ] Reached target Swap. [ 4.163809] systemd[1]: Reached target Initrd Root Device. [ OK ] Reached target Initrd Root Device. [ 4.169096] systemd[1]: Listening on udev Kernel Socket. [ OK ] Listening on udev Kernel Socket. [ OK ] Reached target Slices. [ OK ] Listening on Journal Socket (/dev/log). [ OK ] Reached target Timers. [ OK ] Listening on Journal Socket. [ OK ] Started Memstrack Anylazing Service. Starting Journal Service... Starting Create list of required st…ce nodes for the current kernel... [ OK ] Listening on udev Control Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Local File Systems. Starting Create Volatile Files and Directories... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. Starting Setup Virtual Console... Starting Apply Kernel Variables... [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Setup Virtual Console. [ OK ] Started Apply Kernel Variables. 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.845591] device-mapper: uevent: version 1.0.3 [ 4.848156] 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. [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting dracut initqueue hook... [ 5.660170] virtio_net virtio0 ens2: renamed from eth0 [ 5.678970] random: fast init done [ 5.714239] scsi host0: ata_piix [ 5.729886] scsi host1: ata_piix [ 5.776650] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 5.779332] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 9.645094] dracut-initqueue[582]: RTNETLINK answers: File exists [ 10.385666] random: crng init done [ 10.387606] random: 7 urandom warning(s) missed due to ratelimiting Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Mounting /sysroot... [ 11.035366] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped target Timers. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Slices. [ OK ] Stopped target Sockets. [ OK ] Stopped target Paths. [ OK ] Stopped target System Initialization. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. Stopping udev Kernel Device Manager... [ OK ] Stopped target Swap. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Closed udev Control Socket. [ OK ] Closed udev Kernel Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 12.340705] printk: systemd: 25 output lines suppressed due to ratelimiting [ 12.636038] SELinux: Disabled at runtime. [ 12.714853] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 12.724878] systemd[1]: Detected virtualization kvm. [ 12.727176] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 13.303132] systemd[1]: initrd-switch-root.service: Succeeded. [ 13.307112] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 13.311602] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 13.317338] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 13.321374] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 13.329408] systemd[1]: Starting Journal Service... Starting Journal Service... [ 13.336561] systemd[1]: Created slice system-getty.slice. [ OK ] Created slice system-getty.slice. [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd File Systems. [ OK ] Stopped target Initrd Root File System. [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Listening on udev Kernel Socket. Activating swap /dev/disk/by-label/SWAP... [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Reached target rpc_pipefs.target. Starting Remount Root and Kernel File Systems... [ 13.395063] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS [ OK ] Listening on Process Core Dump Socket. [ OK ] Created slice User and Session Slice. [ OK ] Reached target Slices. Starting Create list of required st…ce nodes for the current kernel... Mounting Huge Pages File System... [ OK ] Listening on udev Control Socket. Starting udev Coldplug all Devices... Starting Apply Kernel Variables... Mounting Kernel Debug File System... Mounting POSIX Message Queue File System... [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Reached target RPC Port Mapper. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. [ OK ] Started Journal Service. [ OK ] Activated swap /dev/disk/by-label/SWAP. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Mounted Huge Pages File System. [ OK ] Started Apply Kernel Variables. [ OK ] Mounted Kernel Debug File System. [ OK ] Mounted POSIX Message Queue File System. Starting Create Static Device Nodes in /dev... Starting Configure read-only root support... [ OK ] Reached target Swap. Starting Flush Journal to Persistent Storage... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. Starting udev Kernel Device Manager... [ OK ] Reached target Local File Systems (Pre). Mounting /home/green/git/lustre-release... Mounting /mnt... [ OK ] Mounted /mnt. [ OK ] Started udev Coldplug all Devices. [ 13.885288] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 14.260480] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 14.267120] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 14.460707] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 14.488869] EDAC sbridge: Ver: 1.1.2 [ 16.511406] Key type dns_resolver registered [ 16.831162] NFS: Registering the id_resolver key type [ 16.835203] Key type id_resolver registered [ 16.837419] Key type id_legacy registered [ OK ] Started Configure read-only root support. Starting Load/Save Random Seed... [ OK ] Reached target Local File Systems. Starting Mark the need to relabel after reboot... Starting Rebuild Dynamic Linker Cache... Starting Create Volatile Files and Directories... [ OK ] Started Load/Save Random Seed. [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Create Volatile Files and Directories. Starting Update UTMP about System Boot/Shutdown... Starting RPC Bind... [ OK ] Started RPC Bind. [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Started irqbalance daemon. Starting Login Service... [ OK ] Started D-Bus System Message Bus. Starting Network Manager... Starting Restore /run/initramfs on shutdown... [ OK ] Started dnf makecache --timer. [ OK ] Reached target sshd-keygen.target. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Reached target Timers. [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Login Service. [ OK ] Started Network Manager. [ OK ] Reached target Network. Starting GSSAPI Proxy Daemon... Starting Dynamic System Tuning Daemon... Starting OpenSSH server daemon... Starting Network Manager Wait Online... [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Started OpenSSH server daemon. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... Starting Hostname Service... [ OK ] Started Permit User Sessions. [ OK ] Started Command Scheduler. [ OK ] Started Getty on tty1. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Serial Getty on ttyS1. [ OK ] Reached target Login Prompts. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting System Logging Service... Starting Crash recovery kernel arming... Starting Notify NFS peers of a restart... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Starting Authorization Manager... [ OK ] Started Authorization Manager. [ OK ] Started Dynamic System Tuning Daemon. [ OK ] Reached target Multi-User System. [ OK ] Reached target Graphical Interface. Starting Update UTMP about System Runlevel Changes... [ OK ] Started Update UTMP about System Runlevel Changes. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg435-server login: [ 73.593883] libcfs: loading out-of-tree module taints kernel. [ 73.702065] Key type ._llcrypt registered [ 73.704024] Key type .llcrypt registered [ 73.885769] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_hostid [ 94.366324] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing load_modules_local [ 96.722613] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 96.755810] alg: No test for adler32 (adler32-zlib) [ 98.562985] Lustre: Lustre: Build Version: 2.17.57_103_g794a134 [ 99.724495] LNet: Added LNI 192.168.204.135@tcp [8/256/0/180] [ 101.568391] Key type lgssc registered [ 102.026414] hrtimer: interrupt took 6421405 ns [ 104.100846] Lustre: Echo OBD driver; http://www.lustre.org/ [ 125.316627] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 167.324957] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing load_modules_local [ 179.988229] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 180.019097] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 181.253193] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 181.293827] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 181.397280] Lustre: lustre-MDT0000: new disk, initializing [ 181.484182] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 181.505234] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 186.272990] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 202.515822] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 202.713117] Lustre: 6514:0:(mgs_llog.c:1453:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 202.772756] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 202.776800] Lustre: Skipped 1 previous similar message [ 202.911095] Lustre: lustre-MDT0001: new disk, initializing [ 203.002703] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 203.036188] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 203.051228] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 208.257771] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 213.881795] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 225.808843] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 226.255224] Lustre: lustre-OST0000: new disk, initializing [ 226.259778] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 226.281777] Lustre: 8452:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 226.458398] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 232.027485] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 232.035106] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 232.131309] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 234.488458] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 252.599838] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 252.733763] Lustre: lustre-OST0001: new disk, initializing [ 252.738524] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 252.745301] Lustre: 9526:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 252.805966] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 261.462232] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 262.305739] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 262.328568] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 262.389588] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 276.193803] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 285.796764] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 293.952330] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing check_logdir /tmp/testlogs/ [ 299.860420] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing yml_node [ 305.760701] Lustre: DEBUG MARKER: Client: 2.17.57.103 [ 309.662489] Lustre: DEBUG MARKER: MDS: 2.17.57.103 [ 313.067719] Lustre: DEBUG MARKER: OSS: 2.17.57.103 [ 315.079308] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity-quota ============----- Sun Sep 6 16:15:37 EDT 2026 [ 335.433810] Lustre: DEBUG MARKER: excepting tests: 2 4a 63 65 [ 337.169546] Lustre: DEBUG MARKER: skipping tests SLOW=no: 61 [ 340.947172] Lustre: DEBUG MARKER: === sanity-quota: start setup 16:16:03 (1788725763) === [ 348.157441] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing check_config_client /mnt/lustre [ 370.990506] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 374.963438] Lustre: 13437:0:(mgs_llog.c:1453:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 381.476349] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 388.281062] Lustre: DEBUG MARKER: === sanity-quota: finish setup 16:16:50 (1788725810) === [ 459.022381] Lustre: DEBUG MARKER: == sanity-quota test 0: Test basic quota performance ===== 16:18:01 (1788725881) [ 505.114548] Lustre: DEBUG MARKER: == sanity-quota test 1a: Block hard limit (normal use and out of quota) ========================================================== 16:18:47 (1788725927) [ 518.169388] Lustre: DEBUG MARKER: User quota (block hardlimit:10 MB) [ 526.484512] Lustre: DEBUG MARKER: Write... [ 529.205396] Lustre: DEBUG MARKER: Write out of block quota ... [ 565.096365] Lustre: DEBUG MARKER: -------------------------------------- [ 566.936318] Lustre: DEBUG MARKER: Group quota (block hardlimit:10 MB) [ 574.876277] Lustre: DEBUG MARKER: Write... [ 577.462825] Lustre: DEBUG MARKER: Write out of block quota ... [ 610.889498] Lustre: DEBUG MARKER: -------------------------------------- [ 612.163384] Lustre: DEBUG MARKER: Project quota (block hardlimit:10 mb) [ 615.094488] Lustre: DEBUG MARKER: Write... [ 617.653396] Lustre: DEBUG MARKER: Write out of block quota ... [ 669.821199] Lustre: DEBUG MARKER: == sanity-quota test 1b: Quota pools: Block hard limit (normal use and out of quota) ========================================================== 16:21:32 (1788726092) [ 682.358239] Lustre: DEBUG MARKER: User quota (block hardlimit:20 MB) [ 707.350187] Lustre: DEBUG MARKER: Write... [ 710.564209] Lustre: DEBUG MARKER: Write out of block quota ... [ 744.332388] Lustre: DEBUG MARKER: -------------------------------------- [ 746.867861] Lustre: DEBUG MARKER: Group quota (block hardlimit:20 MB) [ 754.252771] Lustre: DEBUG MARKER: Write... [ 756.835881] Lustre: DEBUG MARKER: Write out of block quota ... [ 793.929826] Lustre: DEBUG MARKER: -------------------------------------- [ 796.224511] Lustre: DEBUG MARKER: Project quota (block hardlimit:20 mb) [ 799.424821] Lustre: DEBUG MARKER: Write... [ 801.868425] Lustre: DEBUG MARKER: Write out of block quota ... [ 866.338941] Lustre: DEBUG MARKER: == sanity-quota test 1c: Quota pools: check 3 pools with hardlimit only for global ========================================================== 16:24:48 (1788726288) [ 879.355701] Lustre: DEBUG MARKER: User quota (block hardlimit:20 MB) [ 912.373586] Lustre: DEBUG MARKER: Write... [ 916.189592] Lustre: DEBUG MARKER: Write out of block quota ... [ 1005.832394] Lustre: DEBUG MARKER: == sanity-quota test 1d: Quota pools: check block hardlimit on different pools ========================================================== 16:27:08 (1788726428) [ 1019.127570] Lustre: DEBUG MARKER: User quota (block hardlimit:20 MB) [ 1047.743257] Lustre: DEBUG MARKER: Write... [ 1050.321766] Lustre: DEBUG MARKER: Write out of block quota ... [ 1142.769616] Lustre: DEBUG MARKER: == sanity-quota test 1e: Quota pools: global pool high block limit vs quota pool with small ========================================================== 16:29:24 (1788726564) [ 1158.146441] Lustre: DEBUG MARKER: User quota (block hardlimit:53000000 MB) [ 1175.832551] Lustre: DEBUG MARKER: Write... [ 1179.172616] Lustre: DEBUG MARKER: Write out of block quota ... [ 1193.790958] Lustre: DEBUG MARKER: Write... [ 1252.198540] Lustre: DEBUG MARKER: == sanity-quota test 1f: Quota pools: correct qunit after removing/adding OST ========================================================== 16:31:14 (1788726674) [ 1265.023709] Lustre: DEBUG MARKER: User quota (block hardlimit:200 MB) [ 1279.671468] Lustre: DEBUG MARKER: Write... [ 1282.154283] Lustre: DEBUG MARKER: Write out of block quota ... [ 1316.926350] Lustre: DEBUG MARKER: Write... [ 1319.301395] Lustre: DEBUG MARKER: Write out of block quota ... [ 1369.216296] Lustre: DEBUG MARKER: == sanity-quota test 1g: Quota pools: Block hard limit with wide striping ========================================================== 16:33:11 (1788726791) [ 1383.111710] Lustre: DEBUG MARKER: User quota (block hardlimit:40 MB) [ 1398.363811] Lustre: 30084:0:(osd_handler.c:2191:osd_trans_start()) lustre-MDT0000: credits 6570 > trans_max 3200 [ 1398.370060] Lustre: 30084:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 4/16/0, destroy: 0/0/0 [ 1398.375828] Lustre: 30084:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 401/401/0, xattr_set: 602/5615/0 [ 1398.380863] Lustre: 30084:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 20/142/0, punch: 0/0/0, quota 8/328/0 [ 1398.386117] Lustre: 30084:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/68/0, delete: 0/0/0 [ 1398.391479] Lustre: 30084:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 1398.398018] CPU: 1 PID: 30084 Comm: mdt00_005 Kdump: loaded Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 1398.406359] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.17.0-10.fc44 06/10/2025 [ 1398.421129] Call Trace: [ 1398.422064] ? dump_stack+0xbb/0x10e [ 1398.423045] ? osd_trans_start+0x8db/0x9d0 [osd_ldiskfs] [ 1398.432614] ? dt_trans_start+0x1c/0x70 [obdclass] [ 1398.443685] ? top_trans_start+0x4fd/0xd00 [ptlrpc] [ 1398.450081] ? lod_xattr_list+0x30/0x30 [lod] [ 1398.452073] ? lod_trans_start+0x109/0x4c0 [lod] [ 1398.457196] ? mdd_declare_attr_set+0x91/0x880 [mdd] [ 1398.461285] ? mdd_env_info+0x25/0xc0 [mdd] [ 1398.470765] ? mdd_trans_start+0x18/0x30 [mdd] [ 1398.474132] ? mdd_attr_set+0xa5a/0x1330 [mdd] [ 1398.477366] ? mdt_reint_setattr+0x14aa/0x2030 [mdt] [ 1398.480485] ? mdt_reint_setattr+0x14aa/0x2030 [mdt] [ 1398.486925] ? mdt_reint_rec+0x139/0x2b0 [mdt] [ 1398.490580] ? mdt_reint_internal+0x693/0xdc0 [mdt] [ 1398.496212] ? mdt_reint+0x163/0x190 [mdt] [ 1398.502222] ? tgt_handle_request0+0x137/0xaf0 [ptlrpc] [ 1398.506024] ? tgt_request_handle+0x575/0x1f70 [ptlrpc] [ 1398.510610] ? ptlrpc_server_handle_request+0x443/0x13b0 [ptlrpc] [ 1398.514992] ? lprocfs_counter_add+0x15b/0x210 [obdclass] [ 1398.519024] ? ptlrpc_main+0xce8/0x1400 [ptlrpc] [ 1398.521564] ? ptlrpc_wait_event+0x690/0x690 [ptlrpc] [ 1398.526066] ? kthread+0x1d1/0x200 [ 1398.533140] ? set_kthread_struct+0x70/0x70 [ 1398.547716] ? ret_from_fork+0x1f/0x30 [ 1400.172646] Lustre: DEBUG MARKER: Write... [ 1411.762254] Lustre: DEBUG MARKER: Write out of block quota ... [ 1480.726845] Lustre: DEBUG MARKER: == sanity-quota test 1h: Block hard limit test using fallocate ========================================================== 16:35:03 (1788726903) [ 1495.256983] Lustre: DEBUG MARKER: User quota (block hardlimit:10 MB) [ 1504.147355] Lustre: DEBUG MARKER: Write 5MiB Using Fallocate [ 1513.193408] Lustre: DEBUG MARKER: Write 11MiB Using Fallocate [ 1595.456975] Lustre: DEBUG MARKER: == sanity-quota test 1i: Quota pools: different limit and usage relations ========================================================== 16:36:57 (1788727017) [ 1607.312496] Lustre: DEBUG MARKER: User quota (block hardlimit:200 MB) [ 1622.099895] Lustre: DEBUG MARKER: Write... [ 1624.649583] Lustre: DEBUG MARKER: Write out of block quota ... [ 1657.548910] Lustre: DEBUG MARKER: Write... [ 1660.190157] Lustre: DEBUG MARKER: Write out of block quota ... [ 1672.778133] LustreError: 6522: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:15360 time:0 qunit: 1024 edquot:0 may_rel:0 revoke:0 default:no [ 1721.604557] Lustre: DEBUG MARKER: == sanity-quota test 1j: Enable project quota enforcement for root ========================================================== 16:39:03 (1788727143) [ 1740.923574] Lustre: DEBUG MARKER: -------------------------------------- [ 1742.912510] Lustre: DEBUG MARKER: Project quota (hardlimit: 40 mb, 2048 files) [ 2130.083978] Lustre: DEBUG MARKER: == sanity-quota test 1k: LQA: Block hard limit (normal use and out of quota) ========================================================== 16:45:52 (1788727552) [ 2145.254954] Lustre: DEBUG MARKER: Write... [ 2148.241456] Lustre: DEBUG MARKER: Write out of block quota ... [ 2178.133858] Lustre: DEBUG MARKER: Write... [ 2181.076159] Lustre: DEBUG MARKER: Write out of block quota ... [ 2209.608171] Lustre: DEBUG MARKER: Write... [ 2212.300445] Lustre: DEBUG MARKER: Write out of block quota ... [ 2250.465886] Lustre: DEBUG MARKER: == sanity-quota test 1l: Async writes should not be rejected by quota with root_prj_enable ========================================================== 16:47:52 (1788727672) [ 2294.610177] Lustre: DEBUG MARKER: SKIP: sanity-quota test_2 skipping excluded test 2 [ 2295.926617] Lustre: DEBUG MARKER: == sanity-quota test 3a: Block soft limit (start timer, timer goes off, stop timer) ========================================================== 16:48:38 (1788727718) [ 2337.335985] Lustre: DEBUG MARKER: Write after timer goes off [ 2338.996812] Lustre: DEBUG MARKER: Write after cancel lru locks [ 2408.917870] Lustre: DEBUG MARKER: Write after timer goes off [ 2411.367946] Lustre: DEBUG MARKER: Write after cancel lru locks [ 2481.016952] Lustre: DEBUG MARKER: Write after timer goes off [ 2483.622185] Lustre: DEBUG MARKER: Write after cancel lru locks [ 2543.065735] Lustre: DEBUG MARKER: == sanity-quota test 3b: Quota pools: Block soft limit (start timer, expires, stop timer) ========================================================== 16:52:45 (1788727965) [ 2593.104961] Lustre: DEBUG MARKER: Write after timer goes off [ 2595.373325] Lustre: DEBUG MARKER: Write after cancel lru locks [ 2661.134347] Lustre: DEBUG MARKER: Write after timer goes off [ 2664.326961] Lustre: DEBUG MARKER: Write after cancel lru locks [ 2734.957147] Lustre: DEBUG MARKER: Write after timer goes off [ 2737.135835] Lustre: DEBUG MARKER: Write after cancel lru locks [ 2807.193783] Lustre: DEBUG MARKER: == sanity-quota test 3c: Quota pools: check block soft limit on different pools ========================================================== 16:57:09 (1788728229) [ 2864.265975] Lustre: DEBUG MARKER: Write after timer goes off [ 2866.184930] Lustre: DEBUG MARKER: Write after cancel lru locks [ 2931.384985] Lustre: DEBUG MARKER: SKIP: sanity-quota test_4a skipping excluded test 4a [ 2933.349492] Lustre: DEBUG MARKER: == sanity-quota test 4b: Grace time strings handling ===== 16:59:15 (1788728355) [ 2942.784841] Lustre: DEBUG MARKER: == sanity-quota test 5: Chown [ 3052.260246] Lustre: DEBUG MARKER: == sanity-quota test 6: Test dropping acquire request on master ========================================================== 17:01:14 (1788728474) [ 3086.817492] Lustre: *** cfs_fail_loc=513, val=601*** [ 3086.820625] Lustre: Skipped 11 previous similar messages [ 3087.441927] Lustre: *** cfs_fail_loc=513, val=601*** [ 3087.901217] LustreError: 6524:0:(service.c:2341:ptlrpc_server_handle_req_in()) drop incoming rpc opc 601, x1875614657093632 [ 3088.863751] Lustre: *** cfs_fail_loc=513, val=601*** [ 3088.866472] Lustre: Skipped 19 previous similar messages [ 3090.904533] Lustre: *** cfs_fail_loc=513, val=601*** [ 3090.907964] Lustre: Skipped 4 previous similar messages [ 3096.025617] Lustre: *** cfs_fail_loc=513, val=601*** [ 3096.027635] Lustre: Skipped 19 previous similar messages [ 3103.202290] Lustre: 42219:0:(service.c:1612:ptlrpc_at_send_early_reply()) @@@ Could not add any time (5/5), not sending early reply req@ffff9d22ce1cf480 x1875614639175296/t0(0) o4->c21fe6a3-40bb-400a-8680-4ddd01a8cf0b@192.168.204.35@tcp:651/0 lens 488/448 e 1 to 0 dl 1788728531 ref 2 fl Interpret:/600/0 rc 0/0 job:'dd.60000' uid:60000 gid:60000 projid:0 [ 3104.223295] Lustre: 42220:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788728511/real 1788728511] req@ffff9d23f47cea00 x1875614657093632/t0(0) o601->lustre-MDT0000-lwp-OST0000@0@lo:23/10 lens 336/336 e 0 to 1 dl 1788728527 ref 2 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'ll_ost_io00_006.0' uid:0 gid:0 projid:4294967295 [ 3104.225402] Lustre: *** cfs_fail_loc=513, val=601*** [ 3104.242948] 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 [ 3104.245038] Lustre: lustre-MDT0000: Client lustre-MDT0000-lwp-OST0000_UUID (at 0@lo) reconnecting [ 3104.245409] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 3104.248153] LustreError: 16575:0:(service.c:2341:ptlrpc_server_handle_req_in()) drop incoming rpc opc 601, x1875614657102080 [ 3104.294972] Lustre: Skipped 54 previous similar messages [ 3119.567207] Lustre: 3645:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788728527/real 1788728527] req@ffff9d22c6caf480 x1875614657102080/t0(0) o601->lustre-MDT0000-lwp-OST0000@0@lo:23/10 lens 336/336 e 0 to 1 dl 1788728543 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'ll_ost_io00_006.0' uid:0 gid:0 projid:4294967295 [ 3119.603294] 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 [ 3119.626444] Lustre: lustre-MDT0000: Client lustre-MDT0000-lwp-OST0000_UUID (at 0@lo) reconnecting [ 3119.637272] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 3121.623501] Lustre: *** cfs_fail_loc=513, val=601*** [ 3121.625744] Lustre: Skipped 70 previous similar messages [ 3122.664541] LustreError: 16578:0:(service.c:2341:ptlrpc_server_handle_req_in()) drop incoming rpc opc 601, x1875614657110400 [ 3130.336979] LustreError: 16586:0:(service.c:2341:ptlrpc_server_handle_req_in()) drop incoming rpc opc 601, x1875614657114752 [ 3130.351990] LustreError: 16586:0:(service.c:2341:ptlrpc_server_handle_req_in()) Skipped 5 previous similar messages [ 3139.039653] Lustre: 42220:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788728546/real 1788728546] req@ffff9d23d1657800 x1875614657110400/t0(0) o601->lustre-MDT0000-lwp-OST0000@0@lo:23/10 lens 336/336 e 0 to 1 dl 1788728562 ref 2 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'ll_ost_io00_006.0' uid:0 gid:0 projid:4294967295 [ 3139.084360] 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 [ 3139.109100] Lustre: lustre-MDT0000: Client lustre-MDT0000-lwp-OST0000_UUID (at 0@lo) reconnecting [ 3139.115661] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 3146.199127] Lustre: 3644:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788728553/real 1788728553] req@ffff9d23ff456680 x1875614657115136/t0(0) o601->lustre-MDT0000-lwp-OST0001@0@lo:23/10 lens 336/336 e 0 to 1 dl 1788728569 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'lquota_wb_lustr.0' uid:0 gid:0 projid:4294967295 [ 3146.202119] Lustre: lustre-MDT0000-lwp-MDT0001: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 3146.240953] Lustre: 3644:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 3146.257623] Lustre: lustre-MDT0000: Received new LWP connection from 0@lo, keep former export from same NID [ 3146.264039] Lustre: lustre-MDT0000: Client lustre-MDT0000-lwp-OST0001_UUID (at 0@lo) reconnecting [ 3146.286743] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 3170.268572] Lustre: DEBUG MARKER: == sanity-quota test 7a: Quota reintegration (global index) ========================================================== 17:03:12 (1788728592) [ 3194.684717] Lustre: Failing over lustre-OST0000 [ 3194.793688] Lustre: server umount lustre-OST0000 complete [ 3196.898378] LustreError: lustre-OST0000-osc-MDT0001: operation ost_statfs to node 0@lo failed: rc = -107 [ 3196.911636] Lustre: lustre-OST0000-osc-MDT0001: Connection to lustre-OST0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 3196.918128] Lustre: Skipped 1 previous similar message [ 3202.532864] LustreError: 42218: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. [ 3202.552201] LustreError: 42218:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 7 previous similar messages [ 3203.545616] LustreError: 42524:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.204.35@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3204.819538] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3205.070289] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [ 3205.106767] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 3206.180912] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 3206.398791] Lustre: lustre-OST0000: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [ 3206.398801] Lustre: lustre-OST0000-osc-MDT0001: Connection restored to 0@lo (at 0@lo) [ 3206.398807] Lustre: Skipped 1 previous similar message [ 3209.332337] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3214.113735] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3217.610777] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3221.822081] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3225.496736] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3229.430421] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3233.460354] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3252.946334] Lustre: Failing over lustre-OST0000 [ 3253.042563] Lustre: server umount lustre-OST0000 complete [ 3254.772560] LustreError: 42524:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.204.35@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3256.293272] 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 [ 3256.307646] Lustre: Skipped 1 previous similar message [ 3259.546786] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3259.783699] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [ 3259.808528] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 3259.870076] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 3261.558424] Lustre: lustre-OST0000: Recovery over after 0:02, of 3 clients 3 recovered and 0 were evicted. [ 3261.559382] Lustre: lustre-OST0000-osc-MDT0001: Connection restored to 0@lo (at 0@lo) [ 3261.571578] Lustre: Skipped 1 previous similar message [ 3263.830596] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3269.403683] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3273.663359] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3277.181182] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3280.515069] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3284.295722] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3287.901481] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3308.149581] Lustre: DEBUG MARKER: == sanity-quota test 7b: Quota reintegration (slave index) ========================================================== 17:05:31 (1788728731) [ 3333.577283] Lustre: *** cfs_fail_loc=a02, val=0*** [ 3339.823128] LustreError: 3645:0:(qsd_handler.c:298:qsd_req_completion()) $$$ DQACQ failed with -5, flags:0x8 qsd:lustre-OST0000 qtype:usr lqe: ffff9d23ff5af800 id:60000 enforced:1 granted: 1024 pending:0 waiting:0 req:1 usage: 2048 qunit:0 qtune:0 edquot:0 default:no revoke:0 [ 3339.846358] Lustre: Failing over lustre-OST0000 [ 3339.933197] Lustre: server umount lustre-OST0000 complete [ 3341.797359] Lustre: lustre-OST0000-osc-MDT0001: Connection to lustre-OST0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 3341.799644] LustreError: 42222: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. [ 3341.810913] Lustre: Skipped 2 previous similar messages [ 3341.827405] LustreError: 42222:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 4 previous similar messages [ 3346.914701] LustreError: 8436: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. [ 3346.940157] LustreError: 8436:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 2 previous similar messages [ 3347.394387] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3347.634094] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [ 3347.654976] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 3348.973067] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 3349.318906] Lustre: lustre-OST0000: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [ 3349.330923] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 3349.341898] Lustre: Skipped 1 previous similar message [ 3352.616829] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3358.253153] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3362.743320] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3367.361625] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3371.443222] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3376.475776] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3381.088138] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3414.293860] Lustre: DEBUG MARKER: == sanity-quota test 7c: Quota reintegration (restart mds during reintegration) ========================================================== 17:07:17 (1788728837) [ 3433.729052] LustreError: 97897:0:(qsd_reint.c:488:qsd_reint_main()) cfs_fail_timeout id a03 sleeping for 10000ms [ 3433.740637] LustreError: 97897:0:(qsd_reint.c:488:qsd_reint_main()) Skipped 5 previous similar messages [ 3434.967320] Lustre: Failing over lustre-MDT0000 [ 3435.144670] Lustre: lustre-MDT0000-osp-MDT0001: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 3435.151072] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3435.158595] Lustre: Skipped 2 previous similar messages [ 3435.165219] Lustre: Skipped 3 previous similar messages [ 3435.349178] Lustre: server umount lustre-MDT0000 complete [ 3437.703081] LustreError: 97899:0:(qsd_reint.c:488:qsd_reint_main()) cfs_fail_timeout interrupted [ 3439.097804] LustreError: 6520:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.204.35@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3442.681808] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3442.775672] LustreError: MGC192.168.204.135@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3443.016254] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3443.075646] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 3444.192837] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 3446.914592] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3448.303829] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 3448.313991] Lustre: Skipped 1 previous similar message [ 3448.320808] LustreError: 3643:0:(ldlm_resource.c:1207:ldlm_resource_complain()) lustre-MDT0000-lwp-OST0001: namespace resource [0x200000006:0x2020000:0x0].0x0 (ffff9d23d056cd00) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 3448.377818] Lustre: lustre-MDT0000: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 3448.425781] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:170 to 0x280000401:193) [ 3448.429546] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:94 to 0x2c0000401:129) [ 3453.434647] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3556.066694] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3559.947825] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3563.954239] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3567.844242] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3571.999452] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3589.190619] Lustre: DEBUG MARKER: == sanity-quota test 7d: Quota reintegration (Transfer index in multiple bulks) ========================================================== 17:10:12 (1788729012) [ 3606.997585] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3610.792249] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3640.871838] Lustre: DEBUG MARKER: == sanity-quota test 7e: Quota reintegration (inode limits) ========================================================== 17:11:03 (1788729063) [ 3660.800476] Lustre: Failing over lustre-MDT0001 [ 3661.039110] Lustre: server umount lustre-MDT0001 complete [ 3663.334171] Lustre: lustre-MDT0001-lwp-OST0001: Connection to lustre-MDT0001 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 3663.336559] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 3663.337102] LustreError: 16280:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: 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. [ 3663.337110] LustreError: 16280:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 4 previous similar messages [ 3663.350524] Lustre: Skipped 3 previous similar messages [ 3663.360894] LustreError: Skipped 1 previous similar message [ 3672.806961] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3673.202778] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 3673.252819] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 3674.341849] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 3676.522499] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3678.700031] Lustre: lustre-MDT0001-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 3678.707067] Lustre: Skipped 3 previous similar messages [ 3678.713750] Lustre: lustre-MDT0001: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 3678.750969] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:3 to 0x280000400:33) [ 3682.582868] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 3687.309854] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0001.recovery_status 1475 [ 3691.799349] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 3696.251263] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0001.recovery_status 1475 [ 3701.039513] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 3704.974466] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0001.recovery_status 1475 [ 3775.311839] Lustre: Failing over lustre-MDT0001 [ 3775.549864] Lustre: server umount lustre-MDT0001 complete [ 3775.970816] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 3775.976861] LustreError: 8917:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: 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. [ 3776.000511] LustreError: 8917:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 10 previous similar messages [ 3782.716349] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3783.168508] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 3783.215591] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 3784.631438] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 3786.347498] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3788.291155] Lustre: lustre-MDT0001: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 3788.330951] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:3 to 0x280000400:65) [ 3791.975926] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 3795.797601] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0001.recovery_status 1475 [ 3800.587924] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 3805.090487] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0001.recovery_status 1475 [ 3809.135363] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 3813.214457] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0001.recovery_status 1475 [ 3889.107227] Lustre: DEBUG MARKER: == sanity-quota test 7f: Quota reintegration automatically ========================================================== 17:15:11 (1788729311) [ 3899.578769] Lustre: *** cfs_fail_loc=a11, val=0*** [ 3899.584941] Lustre: Skipped 3 previous similar messages [ 3905.564202] Lustre: *** cfs_fail_loc=a11, val=0*** [ 3961.860617] Lustre: 115532:0:(qsd_reint.c:249:qsd_reint_index()) lustre-MDT0001: index version for fid [0x200000005:0x1004:0x0] is 0, but index isn't empty (1) [ 3975.907629] Lustre: DEBUG MARKER: == sanity-quota test 8: Run dbench with quota enabled ==== 17:16:38 (1788729398) [ 4158.508716] Lustre: DEBUG MARKER: == sanity-quota test 9: Block limit larger than 4GB (b10707) ========================================================== 17:19:41 (1788729581) [ 4159.572057] Lustre: DEBUG MARKER: OST0_SIZE: 3605244 required: 4900000 [ 4163.975264] Lustre: DEBUG MARKER: == sanity-quota test 10: Test quota for root user ======== 17:19:46 (1788729586) [ 4196.157444] Lustre: DEBUG MARKER: == sanity-quota test 11: Chown/chgrp ignores quota ======= 17:20:19 (1788729619) [ 4227.058071] Lustre: DEBUG MARKER: == sanity-quota test 12a: Block quota rebalancing ======== 17:20:49 (1788729649) [ 4280.369504] Lustre: DEBUG MARKER: == sanity-quota test 12b: Inode quota rebalancing ======== 17:21:43 (1788729703) [ 4392.553323] Lustre: DEBUG MARKER: == sanity-quota test 13: Cancel per-ID lock in the LRU list ========================================================== 17:23:35 (1788729815) [ 4430.051581] Lustre: DEBUG MARKER: == sanity-quota test 14: check panic in qmt_site_recalc_cb ========================================================== 17:24:13 (1788729853) [ 4444.703882] Lustre: Failing over lustre-OST0000 [ 4444.810369] Lustre: server umount lustre-OST0000 complete [ 4445.669073] LustreError: 116839:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.204.35@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4445.682547] LustreError: 116839:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 4 previous similar messages [ 4447.201277] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 4447.208491] 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 [ 4447.221099] Lustre: Skipped 3 previous similar messages [ 4448.739685] LustreError: lustre-OST0000-osc-MDT0001: operation ost_statfs to node 0@lo failed: rc = -107 [ 4453.508367] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4453.738227] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [ 4453.753979] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 4455.204558] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 4455.425259] Lustre: lustre-OST0000: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [ 4455.425327] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 4455.435401] Lustre: Skipped 5 previous similar messages [ 4457.595387] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4482.508885] Lustre: DEBUG MARKER: == sanity-quota test 15: Set over 4T block quota ========= 17:25:05 (1788729905) [ 4498.600261] Lustre: DEBUG MARKER: == sanity-quota test 16a: lfs quota should skip the inactive MDT/OST ========================================================== 17:25:21 (1788729921) [ 4511.831501] Lustre: lustre-MDT0001: Client c21fe6a3-40bb-400a-8680-4ddd01a8cf0b (at 192.168.204.35@tcp) reconnecting [ 4528.099678] Lustre: DEBUG MARKER: == sanity-quota test 16b: lfs quota should skip the nonexistent MDT/OST ========================================================== 17:25:51 (1788729951) [ 4529.085968] Lustre: DEBUG MARKER: SKIP: sanity-quota test_16b needs >= 3 MDTs [ 4530.180561] Lustre: DEBUG MARKER: == sanity-quota test 16c: lfs quota should preserve usage with an unavailable OST ========================================================== 17:25:53 (1788729953) [ 4540.116540] Lustre: setting import lustre-OST0000_UUID INACTIVE by administrator request [ 4540.701154] Lustre: setting import lustre-OST0000_UUID INACTIVE by administrator request [ 4541.985577] Lustre: Failing over lustre-OST0000 [ 4542.079925] Lustre: server umount lustre-OST0000 complete [ 4549.627677] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state (DISCONN|IDLE) osc.lustre-OST0000-osc-ffff9d7d834e6800.ost_server_uuid 50 [ 4550.787986] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9d7d834e6800.ost_server_uuid in DISCONN state after 0 sec [ 4555.944154] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4556.120070] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [ 4556.134798] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 4558.046374] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 4558.057762] Lustre: lustre-OST0000: Denying connection for new client 1c3335eb-d0f6-4f93-b206-39e6119d420e (at 192.168.204.35@tcp), waiting for 3 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 1:00 [ 4559.582421] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4560.857404] Lustre: lustre-OST0000: Denying connection for new client 1c3335eb-d0f6-4f93-b206-39e6119d420e (at 192.168.204.35@tcp), waiting for 3 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:57 [ 4561.425904] 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 [ 4561.432906] Lustre: Skipped 1 previous similar message [ 4561.439111] LustreError: lustre-OST0000-osc-MDT0000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 4561.448532] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 4561.449421] LustreError: 116839:0:(tgt_handler.c:534:tgt_filter_recovery_request()) @@@ not permitted during recovery req@ffff9d23c79e9f80 x1875614659673984/t0(0) o7->lustre-MDT0000-mdtlov_UUID@0@lo:606/0 lens 264/0 e 0 to 0 dl 1788729996 ref 1 fl Interpret:/200/ffffffff rc 0/-1 job:'osp-pre-0-0.0' uid:0 gid:0 projid:4294967295 [ 4561.450461] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -11 [ 4561.453669] Lustre: Skipped 1 previous similar message [ 4561.487023] LustreError: 116839:0:(tgt_handler.c:534:tgt_filter_recovery_request()) Skipped 1 previous similar message [ 4562.110772] LustreError: lustre-OST0000-osc-MDT0001: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 4562.120179] LustreError: 116840:0:(tgt_handler.c:534:tgt_filter_recovery_request()) @@@ not permitted during recovery req@ffff9d22ccd3ca80 x1875614659674368/t0(0) o7->lustre-MDT0001-mdtlov_UUID@0@lo:606/0 lens 264/0 e 0 to 0 dl 1788729996 ref 1 fl Interpret:/200/ffffffff rc 0/-1 job:'osp-pre-0-1.0' uid:0 gid:0 projid:4294967295 [ 4562.140294] LustreError: 116840:0:(tgt_handler.c:534:tgt_filter_recovery_request()) Skipped 1 previous similar message [ 4564.341471] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 4565.976644] Lustre: lustre-OST0000: Denying connection for new client 1c3335eb-d0f6-4f93-b206-39e6119d420e (at 192.168.204.35@tcp), waiting for 3 known clients (0 recovered, 2 in progress, and 0 evicted) to recover in 1:02 [ 4571.094896] Lustre: lustre-OST0000: Denying connection for new client 1c3335eb-d0f6-4f93-b206-39e6119d420e (at 192.168.204.35@tcp), waiting for 3 known clients (0 recovered, 2 in progress, and 0 evicted) to recover in 0:57 [ 4576.222623] Lustre: lustre-OST0000: Denying connection for new client 1c3335eb-d0f6-4f93-b206-39e6119d420e (at 192.168.204.35@tcp), waiting for 3 known clients (0 recovered, 2 in progress, and 0 evicted) to recover in 0:52 [ 4586.455786] Lustre: lustre-OST0000: Denying connection for new client 1c3335eb-d0f6-4f93-b206-39e6119d420e (at 192.168.204.35@tcp), waiting for 3 known clients (0 recovered, 2 in progress, and 0 evicted) to recover in 0:42 [ 4586.467967] Lustre: Skipped 1 previous similar message [ 4606.947600] Lustre: lustre-OST0000: Denying connection for new client 1c3335eb-d0f6-4f93-b206-39e6119d420e (at 192.168.204.35@tcp), waiting for 3 known clients (0 recovered, 2 in progress, and 0 evicted) to recover in 0:21 [ 4606.962926] Lustre: Skipped 3 previous similar messages [ 4628.500217] Lustre: lustre-OST0000: recovery is timed out, evict stale exports [ 4628.502648] Lustre: 132901:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-OST0000: disconnect stale client c21fe6a3-40bb-400a-8680-4ddd01a8cf0b@ [ 4628.508167] Lustre: lustre-OST0000: disconnecting 1 stale clients [ 4642.774981] Lustre: lustre-OST0000: Denying connection for new client 1c3335eb-d0f6-4f93-b206-39e6119d420e (at 192.168.204.35@tcp), waiting for 3 known clients (0 recovered, 2 in progress, and 1 evicted) to recover in 0:15 [ 4642.785340] Lustre: Skipped 6 previous similar messages [ 4658.500754] Lustre: lustre-OST0000: recovery is timed out, evict stale exports [ 4658.511084] Lustre: 132901:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-OST0000: disconnect stale client lustre-MDT0000-mdtlov_UUID@0@lo [ 4658.518497] Lustre: lustre-OST0000: disconnecting 2 stale clients [ 4658.533543] Lustre: lustre-OST0000: Recovery over after 1:40, of 3 clients 0 recovered and 3 were evicted. [ 4658.658122] 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 [ 4658.659696] LustreError: lustre-OST0000-osc-MDT0001: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 4658.673258] Lustre: Skipped 2 previous similar messages [ 4658.687926] Lustre: lustre-OST0000-osc-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4658.688976] LustreError: lustre-OST0000-osc-MDT0000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 4658.695227] Lustre: Skipped 1 previous similar message [ 4662.561382] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing wait_import_state FULL os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid 50 [ 4662.716727] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid in FULL state after 0 sec [ 4665.571219] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing wait_import_state FULL os[cp].lustre-OST0000-osc-MDT0001.ost_server_uuid 50 [ 4665.740959] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0001.ost_server_uuid in FULL state after 0 sec [ 4669.660914] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0000-osc-ffff9d7d834e6800.ost_server_uuid 50 [ 4670.736951] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9d7d834e6800.ost_server_uuid in FULL state after 0 sec [ 4689.652091] Lustre: DEBUG MARKER: == sanity-quota test 17: DQACQ return recoverable error == 17:28:32 (1788730112) [ 4702.296536] Lustre: *** cfs_fail_loc=a04, val=37*** [ 4702.299805] LustreError: 116828:0:(qsd_handler.c:298:qsd_req_completion()) $$$ DQACQ failed with -37, flags:0x1 qsd:lustre-OST0001 qtype:usr lqe: ffff9d22c379d680 id:60000 enforced:1 granted: 0 pending:0 waiting:1056 req:1 usage: 0 qunit:0 qtune:0 edquot:0 default:no revoke:0 [ 4703.405921] Lustre: *** cfs_fail_loc=a04, val=37*** [ 4703.411400] LustreError: 8441:0:(qsd_handler.c:298:qsd_req_completion()) $$$ DQACQ failed with -37, flags:0x1 qsd:lustre-OST0001 qtype:usr lqe: ffff9d22c379d680 id:60000 enforced:1 granted: 0 pending:0 waiting:1056 req:1 usage: 0 qunit:0 qtune:0 edquot:0 default:no revoke:0 [ 4737.840596] Lustre: *** cfs_fail_loc=a04, val=11*** [ 4771.828221] Lustre: *** cfs_fail_loc=a04, val=110*** [ 4771.830752] Lustre: Skipped 1 previous similar message [ 4807.621778] Lustre: *** cfs_fail_loc=a04, val=107*** [ 4807.625387] Lustre: Skipped 1 previous similar message [ 4857.184659] Lustre: DEBUG MARKER: == sanity-quota test 18: MDS failover while writing, no watchdog triggered (b14840) ========================================================== 17:31:20 (1788730280) [ 4865.151079] Lustre: DEBUG MARKER: User quota (limit: 200) [ 4868.083974] Lustre: DEBUG MARKER: Write 100M (buffered) ... [ 4872.187335] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4872.937107] Lustre: DEBUG MARKER: Fail mds for 40 seconds [ 4873.840646] Lustre: Failing over lustre-MDT0000 [ 4874.208130] Lustre: server umount lustre-MDT0000 complete [ 4878.311541] LustreError: 16280:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.204.35@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4878.329268] LustreError: 16280:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 8 previous similar messages [ 4878.817696] Lustre: lustre-MDT0000-lwp-MDT0001: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 4878.818446] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4878.825389] Lustre: Skipped 1 previous similar message [ 4878.836157] LustreError: Skipped 3 previous similar messages [ 4891.091961] LDISKFS-fs (dm-0): 7 truncates cleaned up [ 4891.093750] LDISKFS-fs (dm-0): recovery complete [ 4891.099764] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4891.156356] LustreError: MGC192.168.204.135@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4891.296836] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4891.328518] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4893.245753] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4893.654798] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4896.742661] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 4896.747338] Lustre: Skipped 1 previous similar message [ 4896.777769] Lustre: lustre-MDT0000: Recovery over after 0:03, of 2 clients 2 recovered and 0 were evicted. [ 4896.798506] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:855 to 0x280000401:897) [ 4896.798647] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:788 to 0x2c0000401:833) [ 4899.487466] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4900.236583] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4903.213103] Lustre: DEBUG MARKER: (dd_pid=130984, time=0, timeout=600) [ 4917.102772] Lustre: DEBUG MARKER: User quota (limit: 200) [ 4919.786748] Lustre: DEBUG MARKER: Write 100M (directio) ... [ 4923.720691] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4924.396937] Lustre: DEBUG MARKER: Fail mds for 40 seconds [ 4925.239338] Lustre: Failing over lustre-MDT0000 [ 4925.592129] Lustre: server umount lustre-MDT0000 complete [ 4927.455586] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4941.085293] LDISKFS-fs (dm-0): 3 truncates cleaned up [ 4941.088973] LDISKFS-fs (dm-0): recovery complete [ 4941.094904] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4941.164670] LustreError: MGC192.168.204.135@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4941.301283] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4941.338598] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4943.188854] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4944.855880] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4946.426608] Lustre: lustre-MDT0000: Recovery over after 0:02, of 2 clients 2 recovered and 0 were evicted. [ 4946.450848] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:899 to 0x280000401:929) [ 4946.451071] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:788 to 0x2c0000401:865) [ 4948.766055] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4949.413422] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4952.289990] Lustre: DEBUG MARKER: (dd_pid=133448, time=0, timeout=600) [ 4972.517817] Lustre: DEBUG MARKER: == sanity-quota test 19: Updating admin limits doesn't zero operational limits(b14790) ========================================================== 17:33:15 (1788730395) [ 4993.149828] Lustre: DEBUG MARKER: == sanity-quota test 20: Test if setquota specifiers work properly (b15754) ========================================================== 17:33:36 (1788730416) [ 5004.153888] Lustre: DEBUG MARKER: == sanity-quota test 21: Setquota while writing [ 5008.374373] Lustre: DEBUG MARKER: Set limit(block:10G; file:1000000) for user: quota_usr [ 5008.975072] Lustre: DEBUG MARKER: Set limit(block:10G; file:1000000) for group: quota_usr [ 5009.613185] Lustre: DEBUG MARKER: Set limit(block:10G; file:) for project: 1000 [ 5010.359772] Lustre: DEBUG MARKER: Set quota for 1 times [ 5012.140952] Lustre: DEBUG MARKER: Set quota for 2 times [ 5014.077482] Lustre: DEBUG MARKER: Set quota for 3 times [ 5016.011095] Lustre: DEBUG MARKER: Set quota for 4 times [ 5017.878639] Lustre: DEBUG MARKER: Set quota for 5 times [ 5019.807279] Lustre: DEBUG MARKER: Set quota for 6 times [ 5021.657081] Lustre: DEBUG MARKER: Set quota for 7 times [ 5023.562581] Lustre: DEBUG MARKER: Set quota for 8 times [ 5025.453966] Lustre: DEBUG MARKER: Set quota for 9 times [ 5027.338166] Lustre: DEBUG MARKER: Set quota for 10 times [ 5029.066559] Lustre: DEBUG MARKER: Set quota for 11 times [ 5030.866232] Lustre: DEBUG MARKER: Set quota for 12 times [ 5032.633067] Lustre: DEBUG MARKER: Set quota for 13 times [ 5034.341722] Lustre: DEBUG MARKER: Set quota for 14 times [ 5036.035607] Lustre: DEBUG MARKER: Set quota for 15 times [ 5037.879908] Lustre: DEBUG MARKER: Set quota for 16 times [ 5039.829731] Lustre: DEBUG MARKER: Set quota for 17 times [ 5058.711537] Lustre: DEBUG MARKER: == sanity-quota test 22: enable/disable quota by 'lctl conf_param/set_param -P' ========================================================== 17:34:42 (1788730482) [ 5067.770562] Lustre: server umount lustre-MDT0000 complete [ 5069.279952] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 5069.280326] Lustre: lustre-MDT0000-lwp-MDT0001: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 5069.288809] Lustre: Skipped 9 previous similar messages [ 5069.374682] LustreError: 7462:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788730492 with bad export cookie 8837947703563409861 [ 5069.375890] LustreError: MGC192.168.204.135@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5069.378417] LustreError: 7462:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 5069.494754] Lustre: server umount lustre-MDT0001 complete [ 5080.577700] Lustre: server umount lustre-OST0000 complete [ 5092.165646] Lustre: server umount lustre-OST0001 complete [ 5097.603691] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing load_modules_local [ 5101.611764] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5101.798642] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 5103.161438] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5106.474493] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5106.634695] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 5108.224504] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5109.387098] Lustre: 160207:0:(mgs_llog.c:1453:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 5111.851562] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5111.976751] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 5114.275312] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5117.091181] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:3 to 0x280000400:97) [ 5117.502601] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5119.807864] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5127.138233] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:931 to 0x280000401:961) [ 5127.139310] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:868 to 0x2c0000401:897) [ 5134.230047] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5135.885537] Lustre: 162105:0:(mgs_llog.c:1453:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 5147.615594] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 5147.616161] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5147.621341] Lustre: Skipped 3 previous similar messages [ 5151.769650] Lustre: server umount lustre-MDT0000 complete [ 5152.735550] LustreError: 159055: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. [ 5152.741741] LustreError: 159055:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 38 previous similar messages [ 5153.170289] LustreError: 159037:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788730576 with bad export cookie 8837947703563435656 [ 5153.171950] LustreError: MGC192.168.204.135@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5153.175215] LustreError: 159037:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 5153.293443] Lustre: server umount lustre-MDT0001 complete [ 5165.068136] Lustre: server umount lustre-OST0000 complete [ 5177.126803] Lustre: server umount lustre-OST0001 complete [ 5183.246683] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing load_modules_local [ 5187.257391] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5187.440585] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 5187.443529] Lustre: Skipped 1 previous similar message [ 5188.941601] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5192.223254] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5193.929264] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5195.138334] Lustre: 165937:0:(mgs_llog.c:1453:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 5197.792169] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5200.091548] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5202.021165] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:3 to 0x280000400:129) [ 5203.746247] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5203.861259] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 5203.864131] Lustre: Skipped 2 previous similar messages [ 5206.290077] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5213.158653] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:868 to 0x2c0000401:929) [ 5213.160440] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:931 to 0x280000401:993) [ 5220.879713] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5222.362146] Lustre: 167829:0:(mgs_llog.c:1453:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 5226.501249] Lustre: DEBUG MARKER: == sanity-quota test 23: Quota should be honored with directIO (b16125) ========================================================== 17:37:29 (1788730649) [ 5227.183700] Lustre: DEBUG MARKER: OST0_SIZE: 3605396 required: 6144 [ 5227.838598] Lustre: DEBUG MARKER: run for 4MB test file [ 5233.773182] Lustre: DEBUG MARKER: User quota (limit: 4 MB) [ 5236.188940] Lustre: DEBUG MARKER: Step1: trigger EDQUOT with O_DIRECT [ 5236.800794] Lustre: DEBUG MARKER: Write half of file [ 5237.545058] Lustre: DEBUG MARKER: Write out of block quota ... [ 5238.258853] Lustre: DEBUG MARKER: Step1: done [ 5238.899390] Lustre: DEBUG MARKER: Step2: rewrite should succeed [ 5239.560969] Lustre: DEBUG MARKER: Step2: done [ 5255.252647] Lustre: DEBUG MARKER: OST0_SIZE: 3605396 required: 61440 [ 5255.794164] Lustre: DEBUG MARKER: run for 40MB test file [ 5260.115166] Lustre: DEBUG MARKER: User quota (limit: 40 MB) [ 5262.515772] Lustre: DEBUG MARKER: Step1: trigger EDQUOT with O_DIRECT [ 5263.133777] Lustre: DEBUG MARKER: Write half of file [ 5264.296579] Lustre: DEBUG MARKER: Write out of block quota ... [ 5265.276111] Lustre: DEBUG MARKER: Step1: done [ 5265.785956] Lustre: DEBUG MARKER: Step2: rewrite should succeed [ 5266.394431] Lustre: DEBUG MARKER: Step2: done [ 5290.735473] Lustre: DEBUG MARKER: == sanity-quota test 24: lfs draws an asterix when limit is reached (b16646) ========================================================== 17:38:33 (1788730713) [ 5310.548664] Lustre: DEBUG MARKER: == sanity-quota test 25: check indexes versions ========== 17:38:53 (1788730733) [ 5325.338453] Lustre: DEBUG MARKER: Write... [ 5326.134259] Lustre: DEBUG MARKER: Write out of block quota ... [ 5357.175669] Lustre: DEBUG MARKER: == sanity-quota test 27a: lfs quota/setquota should handle wrong arguments (b19612) ========================================================== 17:39:40 (1788730780) [ 5359.870806] Lustre: DEBUG MARKER: == sanity-quota test 27b: lfs quota/setquota should handle user/group/project ID (b20200) ========================================================== 17:39:43 (1788730783) [ 5365.003704] Lustre: DEBUG MARKER: == sanity-quota test 27c: lfs quota should support human-readable output ========================================================== 17:39:48 (1788730788) [ 5369.165924] Lustre: DEBUG MARKER: == sanity-quota test 27d: lfs setquota should support fraction block limit ========================================================== 17:39:52 (1788730792) [ 5373.070407] Lustre: DEBUG MARKER: == sanity-quota test 30: Hard limit updates should not reset grace times ========================================================== 17:39:56 (1788730796) [ 5402.848245] Lustre: DEBUG MARKER: == sanity-quota test 33: Basic usage tracking for user [ 5459.721892] Lustre: DEBUG MARKER: == sanity-quota test 34: Usage transfer for user [ 5545.076646] Lustre: DEBUG MARKER: == sanity-quota test 35: Usage is still accessible across reboot ========================================================== 17:42:48 (1788730968) [ 5569.248162] Lustre: DEBUG MARKER: Restart... [ 5571.552209] Lustre: lustre-MDT0000-osp-MDT0001: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 5571.553261] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 5571.555210] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5571.557731] Lustre: Skipped 6 previous similar messages [ 5576.671929] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5576.675060] Lustre: Skipped 6 previous similar messages [ 5576.817163] Lustre: server umount lustre-MDT0000 complete [ 5578.160110] LustreError: 165941:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788731001 with bad export cookie 8837947703563437959 [ 5578.162362] LustreError: MGC192.168.204.135@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5578.164521] LustreError: 165941:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 5578.269276] Lustre: server umount lustre-MDT0001 complete [ 5587.938164] LustreError: 3645:0:(client.c:1394:ptlrpc_import_delay_req()) @@@ IMP_CLOSED req@ffff9d23f4f11c00 x1875614660412416/t0(0) o601->lustre-MDT0000-lwp-OST0000@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 [ 5587.947745] LustreError: 3645:0:(qsd_handler.c:298:qsd_req_completion()) $$$ DQACQ failed with -5, flags:0x8 qsd:lustre-OST0000 qtype:usr lqe: ffff9d23f44c5980 id:0 enforced:0 granted: 0 pending:0 waiting:0 req:1 usage: 1596 qunit:0 qtune:0 edquot:0 default:no revoke:0 [ 5590.022335] Lustre: server umount lustre-OST0000 complete [ 5601.887955] Lustre: server umount lustre-OST0001 complete [ 5607.263245] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing load_modules_local [ 5611.246245] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5611.408349] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 5612.822526] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5615.897652] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5617.419956] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5618.449187] Lustre: 193627:0:(mgs_llog.c:1453:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 5620.787787] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5621.923860] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1005 to 0x280000401:1025) [ 5622.987704] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5626.018719] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:3 to 0x280000400:161) [ 5626.052461] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5628.035244] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5631.112027] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5631.458676] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:937 to 0x2c0000401:961) [ 5632.263481] Lustre: 195499:0:(mgs_llog.c:1453:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 5657.441435] Lustre: DEBUG MARKER: == sanity-quota test 37: Quota accounted properly for file created by 'lfs setstripe' ========================================================== 17:44:40 (1788731080) [ 5686.753476] Lustre: DEBUG MARKER: == sanity-quota test 38: Quota accounting iterator doesn't skip id entries ========================================================== 17:45:10 (1788731110) [ 6183.456609] Lustre: DEBUG MARKER: == sanity-quota test 39: Project ID interface works correctly ========================================================== 17:53:26 (1788731606) [ 6189.536096] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 6189.537849] 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 [ 6189.538485] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 6189.544716] Lustre: Skipped 4 previous similar messages [ 6192.379098] Lustre: server umount lustre-MDT0000 complete [ 6193.623930] LustreError: 192467:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788731617 with bad export cookie 8837947703563446695 [ 6193.626584] LustreError: MGC192.168.204.135@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 6193.627612] LustreError: 192467:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 6193.736278] Lustre: server umount lustre-MDT0001 complete [ 6205.197534] Lustre: server umount lustre-OST0000 complete [ 6216.678219] Lustre: server umount lustre-OST0001 complete [ 6222.252366] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing load_modules_local [ 6226.224312] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 6226.374577] LustreError: 203164:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: 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. [ 6226.381066] LustreError: 203164:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 6 previous similar messages [ 6226.400178] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 6226.403076] Lustre: Skipped 3 previous similar messages [ 6227.861812] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6231.134845] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 6232.852968] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6233.884865] Lustre: 204306:0:(mgs_llog.c:1453:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 6236.202358] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 6238.467158] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6240.485226] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:3 to 0x280000400:193) [ 6241.461740] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 6243.431043] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6250.979115] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:5963 to 0x2c0000401:5985) [ 6250.983013] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:6027 to 0x280000401:6049) [ 6257.049620] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 6270.512987] Lustre: DEBUG MARKER: == sanity-quota test 40a: Hard link across different project ID ========================================================== 17:54:53 (1788731693) [ 6286.090034] Lustre: DEBUG MARKER: == sanity-quota test 40b: Mv across different project ID ========================================================== 17:55:09 (1788731709) [ 6301.544593] Lustre: DEBUG MARKER: == sanity-quota test 40c: Remote child Dir inherit project quota properly ========================================================== 17:55:24 (1788731724) [ 6317.565277] Lustre: DEBUG MARKER: == sanity-quota test 40d: Stripe Directory inherit project quota properly ========================================================== 17:55:40 (1788731740) [ 6331.994866] Lustre: DEBUG MARKER: == sanity-quota test 41: df should return projid-specific values ========================================================== 17:55:55 (1788731755) [ 6368.080755] Lustre: DEBUG MARKER: == sanity-quota test 42: lfs quota should include default quota info ========================================================== 17:56:31 (1788731791) [ 6379.878849] Lustre: DEBUG MARKER: == sanity-quota test 48: lfs quota --delete should delete quota project ID ========================================================== 17:56:43 (1788731803) [ 6408.728866] Lustre: DEBUG MARKER: == sanity-quota test 49a: lfs quota -a prints the quota usage for all quota IDs ========================================================== 17:57:12 (1788731832) [ 6410.526332] Lustre: *** cfs_fail_loc=a09, val=0*** [ 6410.527527] Lustre: Skipped 1 previous similar message [ 6411.536858] Lustre: *** cfs_fail_loc=a09, val=0*** [ 6411.538786] Lustre: Skipped 179 previous similar messages [ 6413.540281] Lustre: *** cfs_fail_loc=a09, val=0*** [ 6413.541620] Lustre: Skipped 335 previous similar messages [ 6417.544918] Lustre: *** cfs_fail_loc=a09, val=0*** [ 6417.546917] Lustre: Skipped 697 previous similar messages [ 6425.547664] Lustre: *** cfs_fail_loc=a09, val=0*** [ 6425.550007] Lustre: Skipped 1375 previous similar messages [ 6441.554328] Lustre: *** cfs_fail_loc=a09, val=0*** [ 6441.556284] Lustre: Skipped 2693 previous similar messages [ 6573.539699] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 6573.542281] Lustre: Skipped 6 previous similar messages [ 6578.656101] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 6578.658907] Lustre: Skipped 2 previous similar messages [ 6578.747735] Lustre: server umount lustre-MDT0000 complete [ 6579.899877] LustreError: 204310:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788732003 with bad export cookie 8837947703565192054 [ 6579.902495] LustreError: MGC192.168.204.135@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 6579.904239] LustreError: 204310:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 3 previous similar messages [ 6583.777673] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 6583.779732] Lustre: Skipped 1 previous similar message [ 6586.093167] Lustre: server umount lustre-MDT0001 complete [ 6587.594777] Lustre: server umount lustre-OST0000 complete [ 6588.910885] Lustre: server umount lustre-OST0001 complete [ 6591.020909] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_hostid [ 6593.513347] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing load_modules_local [ 6608.759201] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing load_modules_local [ 6612.231527] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 6612.317657] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 6612.326906] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 6612.360851] Lustre: lustre-MDT0000: new disk, initializing [ 6612.381928] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 6612.384039] Lustre: Skipped 3 previous similar messages [ 6612.389966] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 6613.642528] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6617.638563] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 6617.671779] Lustre: 223401:0:(mgs_llog.c:1453:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 6617.676176] Lustre: 223401:0:(mgs_llog.c:1453:mgs_modify_param()) Skipped 1 previous similar message [ 6617.687872] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 6617.689494] Lustre: Skipped 1 previous similar message [ 6617.726824] Lustre: lustre-MDT0001: new disk, initializing [ 6617.754096] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 6617.756733] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 6619.045783] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6621.264983] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 6623.370738] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 6623.464958] Lustre: lustre-OST0000: new disk, initializing [ 6623.466370] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 6623.468451] Lustre: 225037:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 6625.196576] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 6625.199892] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 6625.224306] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 6625.422019] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6629.523568] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 6629.565341] Lustre: lustre-OST0001: new disk, initializing [ 6629.567256] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 6629.569317] Lustre: 225907:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 6630.634370] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 6630.637791] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 6630.650871] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 6631.500539] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6635.799099] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 6636.995750] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 6646.549128] Lustre: DEBUG MARKER: == sanity-quota test 49b: lfs quota -a --blocks has a delimiter ========================================================== 18:01:09 (1788732069) [ 6648.640495] Lustre: DEBUG MARKER: == sanity-quota test 49c: lfs quota long options don't consume an extra argument ========================================================== 18:01:12 (1788732072) [ 6650.719441] Lustre: DEBUG MARKER: == sanity-quota test 49d: lfs quota -d and --delimiter both work ========================================================== 18:01:14 (1788732074) [ 6652.644514] Lustre: DEBUG MARKER: == sanity-quota test 50: Test if lfs find --projid works ========================================================== 18:01:16 (1788732076) [ 6666.489088] Lustre: DEBUG MARKER: == sanity-quota test 51: Test project accounting with mv/cp ========================================================== 18:01:29 (1788732089) [ 6691.740369] Lustre: DEBUG MARKER: == sanity-quota test 52: Rename normal file across project ID ========================================================== 18:01:55 (1788732115) [ 6698.198958] Lustre: DEBUG MARKER: rename directory return 255 [ 6717.238184] Lustre: DEBUG MARKER: == sanity-quota test 53: Project inherit attribute could be cleared ========================================================== 18:02:20 (1788732140) [ 6724.218222] Lustre: DEBUG MARKER: == sanity-quota test 54: basic lfs project interface test ========================================================== 18:02:27 (1788732147) [ 6733.126593] Lustre: DEBUG MARKER: == sanity-quota test 55: Chgrp should be affected by group quota ========================================================== 18:02:36 (1788732156) [ 6763.643734] LustreError: 235110: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 [ 6777.827977] Lustre: DEBUG MARKER: == sanity-quota test 56: lfs quota -t should work well === 18:03:21 (1788732201) [ 6787.293783] Lustre: DEBUG MARKER: == sanity-quota test 57: lfs project could tolerate errors ========================================================== 18:03:30 (1788732210) [ 6803.715986] Lustre: DEBUG MARKER: == sanity-quota test 58: project ID should be kept for new mirrors created by FID ========================================================== 18:03:47 (1788732227) [ 6861.197629] Lustre: DEBUG MARKER: == sanity-quota test 59: lfs project dosen't crash kernel with project disabled ========================================================== 18:04:44 (1788732284) [ 6863.839653] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 6863.843509] Lustre: lustre-MDT0000-osp-MDT0001: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 6863.847093] Lustre: Skipped 6 previous similar messages [ 6863.848854] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 6863.850790] Lustre: Skipped 2 previous similar messages [ 6868.638752] Lustre: server umount lustre-MDT0000 complete [ 6869.919568] LustreError: 223396:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788732293 with bad export cookie 8837947703565564139 [ 6869.923177] LustreError: MGC192.168.204.135@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 6869.924295] LustreError: 223396:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 6870.034248] Lustre: server umount lustre-MDT0001 complete [ 6880.707808] Lustre: server umount lustre-OST0000 complete [ 6892.158452] Lustre: server umount lustre-OST0001 complete [ 6898.918342] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing load_modules_local [ 6902.788475] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 6902.925111] LustreError: 244390:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: 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. [ 6902.930521] LustreError: 244390:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 5 previous similar messages [ 6902.945066] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 6902.946790] Lustre: Skipped 3 previous similar messages [ 6902.949351] LustreError: lustre-MDT0000: can't enable quota enforcement since space accounting isn't functional. Please run tunefs.lustre --quota on an unmounted filesystem if not done already [ 6904.339780] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6907.304510] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 6907.424211] LustreError: lustre-MDT0001: can't enable quota enforcement since space accounting isn't functional. Please run tunefs.lustre --quota on an unmounted filesystem if not done already [ 6908.793257] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6909.761246] Lustre: 245536:0:(mgs_llog.c:1453:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 6911.996750] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 6912.119835] LustreError: lustre-OST0000: can't enable quota enforcement since space accounting isn't functional. Please run tunefs.lustre --quota on an unmounted filesystem if not done already [ 6913.122866] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:20 to 0x280000401:65) [ 6914.095338] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6916.985508] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 6917.041210] LustreError: lustre-OST0001: can't enable quota enforcement since space accounting isn't functional. Please run tunefs.lustre --quota on an unmounted filesystem if not done already [ 6918.052720] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:20 to 0x2c0000401:65) [ 6918.991071] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6922.072763] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 6925.370549] LustreError: 244386:0:(osd_handler.c:3425:osd_quota_transfer()) lustre-MDT0000: quota transfer failed. Is project enforcement enabled on the ldiskfs filesystem? rc = -95 [ 6927.840376] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 6927.842218] Lustre: Skipped 4 previous similar messages [ 6932.760264] Lustre: server umount lustre-MDT0000 complete [ 6933.983179] LustreError: 244371:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788732357 with bad export cookie 8837947703565612733 [ 6933.985690] LustreError: MGC192.168.204.135@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 6933.986342] LustreError: 244371:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 3 previous similar messages [ 6934.093070] Lustre: server umount lustre-MDT0001 complete [ 6945.795687] Lustre: server umount lustre-OST0000 complete [ 6957.330564] Lustre: server umount lustre-OST0001 complete [ 6963.955670] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing load_modules_local [ 6967.579659] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 6969.128573] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6972.032260] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 6973.515272] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6976.642451] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 6977.829122] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:20 to 0x280000401:97) [ 6978.828947] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6981.731944] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 6982.819074] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:67 to 0x2c0000401:97) [ 6983.844218] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6987.069961] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 7003.074960] Lustre: DEBUG MARKER: == sanity-quota test 60: Test quota for root with setgid ========================================================== 18:07:06 (1788732426) [ 7023.199784] Lustre: DEBUG MARKER: SKIP: sanity-quota test_61 skipping SLOW test 61 [ 7023.834803] Lustre: DEBUG MARKER: == sanity-quota test 62: Project inherit should be only changed by root ========================================================== 18:07:27 (1788732447) [ 7031.429781] Lustre: DEBUG MARKER: SKIP: sanity-quota test_63 skipping excluded test 63 [ 7032.039077] Lustre: DEBUG MARKER: == sanity-quota test 64: lfs project on non-dir/files should succeed ========================================================== 18:07:35 (1788732455) [ 7048.731468] Lustre: DEBUG MARKER: SKIP: sanity-quota test_65 skipping excluded test 65 [ 7049.319940] Lustre: DEBUG MARKER: == sanity-quota test 66: nonroot user can not change project state in default ========================================================== 18:07:52 (1788732472) [ 7063.670561] Lustre: DEBUG MARKER: == sanity-quota test 67: quota pools recalculation ======= 18:08:07 (1788732487) [ 7067.197753] Lustre: DEBUG MARKER: User quota (block hardlimit:20 MB) [ 7069.130734] Lustre: 259698:0:(qsd_reint.c:249:qsd_reint_index()) lustre-OST0001: index version for fid [0x200000005:0x100b:0x0] is 0, but index isn't empty (1) [ 7069.138132] Lustre: 259698:0:(qsd_reint.c:249:qsd_reint_index()) Skipped 2 previous similar messages [ 7070.544832] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 7072.309667] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 7073.477345] Lustre: DEBUG MARKER: Write... [ 7082.511665] LustreError: 261038:0:(mgs_handler.c:1144:mgs_iocontrol_pool()) OBD_IOC_POOL err -17, cmd CE021 for pool lustre.qpool1 [ 7086.354873] Lustre: DEBUG MARKER: Write... [ 7090.334107] Lustre: DEBUG MARKER: Write... [ 7131.396607] Lustre: DEBUG MARKER: == sanity-quota test 68: slave number in quota pool changed after each add/remove OST ========================================================== 18:09:14 (1788732554) [ 7141.913711] LustreError: 265479:0:(mgs_handler.c:1144:mgs_iocontrol_pool()) OBD_IOC_POOL err -17, cmd CE021 for pool lustre.qpool1 [ 7162.061976] Lustre: DEBUG MARKER: == sanity-quota test 69: EDQUOT at one of pools shouldn't affect DOM ========================================================== 18:09:45 (1788732585) [ 7172.730712] Lustre: DEBUG MARKER: User quota (block hardlimit:200 MB) [ 7173.278849] Lustre: DEBUG MARKER: User quota (block hardlimit:10 MB) [ 7202.417695] Lustre: DEBUG MARKER: == sanity-quota test 70a: check lfs setquota/quota with a pool option ========================================================== 18:10:25 (1788732625) [ 7221.940949] Lustre: DEBUG MARKER: == sanity-quota test 70b: lfs setquota pool works properly ========================================================== 18:10:45 (1788732645) [ 7239.309557] Lustre: DEBUG MARKER: == sanity-quota test 71a: Check PFL with quota pools ===== 18:11:02 (1788732662) [ 7242.894687] Lustre: DEBUG MARKER: User quota (block hardlimit:100 MB) [ 7254.375130] Lustre: DEBUG MARKER: Write... [ 7254.968490] Lustre: DEBUG MARKER: Write out of block quota ... [ 7299.289764] Lustre: DEBUG MARKER: == sanity-quota test 71b: Check SEL with quota pools ===== 18:12:02 (1788732722) [ 7302.930429] Lustre: DEBUG MARKER: User quota (block hardlimit:1000 MB) [ 7346.154777] Lustre: DEBUG MARKER: == sanity-quota test 72: lfs quota --pool prints only pool's OSTs ========================================================== 18:12:49 (1788732769) [ 7349.919740] Lustre: DEBUG MARKER: User quota (block hardlimit:50 MB) [ 7357.522869] Lustre: DEBUG MARKER: Write... [ 7358.120768] Lustre: DEBUG MARKER: Write out of block quota ... [ 7358.228283] LustreError: 259700: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:10240 time:0 qunit: 1024 edquot:0 may_rel:0 revoke:0 default:no [ 7387.059929] Lustre: DEBUG MARKER: == sanity-quota test 73a: default limits at OST Pool Quotas ========================================================== 18:13:30 (1788732810) [ 7398.022767] Lustre: DEBUG MARKER: set to use default quota [ 7398.508155] Lustre: DEBUG MARKER: set default quota [ 7398.990030] Lustre: DEBUG MARKER: get default quota [ 7400.873568] Lustre: DEBUG MARKER: Test not out of quota [ 7401.884297] Lustre: DEBUG MARKER: Test out of quota [ 7405.106561] Lustre: DEBUG MARKER: Increase default quota [ 7417.250446] Lustre: DEBUG MARKER: Set quota to override default quota [ 7417.267980] LustreError: 251479: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:45056 time:1789337640 qunit: 1024 edquot:0 may_rel:0 revoke:0 default:no [ 7420.694706] Lustre: DEBUG MARKER: Set to use default quota again [ 7429.984428] Lustre: DEBUG MARKER: Cleanup [ 7457.671184] Lustre: DEBUG MARKER: == sanity-quota test 73b: default OST Pool Quotas limit for new user ========================================================== 18:14:41 (1788732881) [ 7467.389703] Lustre: DEBUG MARKER: set default quota for qpool1 [ 7467.916771] Lustre: DEBUG MARKER: Write from user that hasn't lqe [ 7494.039616] Lustre: DEBUG MARKER: == sanity-quota test 74: check quota pools per user ====== 18:15:17 (1788732917) [ 7529.274584] Lustre: DEBUG MARKER: == sanity-quota test 75: nodemap squashed root respects quota enforcement ========================================================== 18:15:52 (1788732952) [ 7555.233360] Lustre: DEBUG MARKER: Write... [ 7556.489485] Lustre: DEBUG MARKER: Write out of block quota ... [ 7602.422470] Lustre: DEBUG MARKER: == sanity-quota test 76: project ID 4294967295 should be not allowed ========================================================== 18:17:05 (1788733025) [ 7621.922727] Lustre: DEBUG MARKER: == sanity-quota test 77: lfs setquota should fail in Lustre mount with 'ro' ========================================================== 18:17:25 (1788733045) [ 7624.425239] Lustre: DEBUG MARKER: == sanity-quota test 78A: Check fallocate increase quota usage ========================================================== 18:17:27 (1788733047) [ 7642.758816] Lustre: DEBUG MARKER: == sanity-quota test 78a: Check fallocate increase projectid usage ========================================================== 18:17:46 (1788733066) [ 7663.926303] Lustre: DEBUG MARKER: == sanity-quota test 79: access to non-existed dt-pool/info doesn't cause a panic ========================================================== 18:18:07 (1788733087) [ 7673.528842] Lustre: DEBUG MARKER: == sanity-quota test 80: check for EDQUOT after OST failover ========================================================== 18:18:16 (1788733096) [ 7686.678644] Lustre: *** cfs_fail_loc=a06, val=0*** [ 7686.680148] Lustre: Skipped 2715 previous similar messages [ 7686.773405] LustreError: 249804:0:(qmt_lock.c:479:qmt_lvbo_update()) $$$ failed to release quota space on glimpse 0!=2048 : rc = -11 [ 7686.773405] qmt:lustre-QMT0000 pool:dt-0x0 id:60000 enforced:1 hard:102400 soft:0 granted:25600 time:0 qunit: 16384 edquot:0 may_rel:0 revoke:0 default:no [ 7690.476385] Lustre: Failing over lustre-OST0001 [ 7690.524795] Lustre: server umount lustre-OST0001 complete [ 7690.678369] Lustre: *** cfs_fail_loc=a06, val=0*** [ 7690.680660] Lustre: Skipped 5542 previous similar messages [ 7693.312355] LustreError: lustre-OST0001-osc-MDT0000: operation ost_destroy to node 0@lo failed: rc = -107 [ 7693.314543] LustreError: Skipped 1 previous similar message [ 7693.316178] Lustre: lustre-OST0001-osc-MDT0000: Connection to lustre-OST0001 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 7693.319873] Lustre: Skipped 7 previous similar messages [ 7693.321776] LustreError: 251290: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. [ 7693.325903] LustreError: 251290:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 7 previous similar messages [ 7693.970655] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 7694.173960] Lustre: lustre-OST0001: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [ 7694.181974] Lustre: lustre-OST0001: in recovery but waiting for the first client to connect [ 7695.459073] Lustre: lustre-OST0001: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 7695.523642] Lustre: lustre-OST0001-osc-MDT0001: Connection restored to 0@lo (at 0@lo) [ 7695.524023] Lustre: lustre-OST0001: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [ 7695.526219] Lustre: Skipped 7 previous similar messages [ 7696.387877] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7724.531264] Lustre: DEBUG MARKER: == sanity-quota test 81: Race qmt_start_pool_recalc with qmt_pool_free ========================================================== 18:19:07 (1788733147) [ 7728.110198] Lustre: DEBUG MARKER: User quota (block hardlimit:20 MB) [ 7731.459414] LustreError: 306917:0:(qmt_pool.c:1407:qmt_pool_recalc()) cfs_fail_timeout id a07 sleeping for 10000ms [ 7734.748473] Lustre: lustre-MDT0000: Not available for connect from 192.168.204.35@tcp (stopping) [ 7734.750612] Lustre: Skipped 4 previous similar messages [ 7739.862426] Lustre: lustre-MDT0000: Not available for connect from 192.168.204.35@tcp (stopping) [ 7739.864577] Lustre: Skipped 4 previous similar messages [ 7741.551082] LustreError: 306917:0:(qmt_pool.c:1407:qmt_pool_recalc()) cfs_fail_timeout id a07 awake [ 7741.642920] Lustre: server umount lustre-MDT0000 complete [ 7744.626608] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 7744.664969] LustreError: MGC192.168.204.135@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 7744.746340] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 7744.748971] Lustre: Skipped 7 previous similar messages [ 7744.790961] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:112 to 0x280000401:129) [ 7744.790971] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:113 to 0x2c0000401:129) [ 7746.087954] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7750.113860] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 7750.116232] Lustre: Skipped 1 previous similar message [ 7759.476158] Lustre: DEBUG MARKER: == sanity-quota test 82: verify more than 8 qids for single operation ========================================================== 18:19:42 (1788733182) [ 7767.692158] Lustre: DEBUG MARKER: == sanity-quota test 83: Setting default quota shouldn't affect grace time ========================================================== 18:19:51 (1788733191) [ 7775.756515] Lustre: DEBUG MARKER: == sanity-quota test 84: Reset quota should fix the insane granted quota ========================================================== 18:19:59 (1788733199) [ 7795.625836] Lustre: *** cfs_fail_loc=a08, val=0*** [ 7795.627094] Lustre: Skipped 1097 previous similar messages [ 7795.628829] Lustre: *** cfs_fail_loc=a08, val=0*** [ 7795.629930] Lustre: Skipped 1 previous similar message [ 7836.073739] Lustre: DEBUG MARKER: == sanity-quota test 85: do not hung at write with the least_qunit ========================================================== 18:20:59 (1788733259) [ 7850.099543] LustreError: 249789:0:(qmt_entry.c:558:qmt_adjust_edquot()) $$$ set revoke_time explicitly qmt:lustre-QMT0000 pool:dt-qpool1 id:60000 enforced:1 hard:3072 soft:0 granted:3072 time:0 qunit: 1024 edquot:0 may_rel:0 revoke:0 default:no [ 7878.294175] Lustre: DEBUG MARKER: == sanity-quota test 86: Pre-acquired quota should be released if quota is over limit ========================================================== 18:21:41 (1788733301) [ 7896.656312] LustreError: 249787: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:16384 time:1789338120 qunit: 1024 edquot:0 may_rel:0 revoke:0 default:no [ 7945.951515] LustreError: 277845: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:16384 time:1789338169 qunit: 1024 edquot:0 may_rel:0 revoke:0 default:no [ 7992.690753] LustreError: 249787: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:16385 time:1789338216 qunit: 1024 edquot:0 may_rel:0 revoke:0 default:no [ 8034.958503] Lustre: DEBUG MARKER: == sanity-quota test 87: lfs quota -a should print default quota setting ========================================================== 18:24:18 (1788733458) [ 8036.973439] Lustre: *** cfs_fail_loc=a09, val=0*** [ 8036.974677] Lustre: Skipped 1 previous similar message [ 8062.433894] Lustre: lustre-MDT0000: Not available for connect from 192.168.204.35@tcp (stopping) [ 8062.436433] Lustre: Skipped 8 previous similar messages [ 8065.400861] Lustre: server umount lustre-MDT0000 complete [ 8068.832375] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 8068.901455] LustreError: MGC192.168.204.135@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 8069.124088] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:131 to 0x280000401:161) [ 8069.124151] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:131 to 0x2c0000401:161) [ 8070.563591] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 8074.213784] LustreError: lustre-MDT0000-osp-MDT0001: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 8074.220489] Lustre: lustre-MDT0000-osp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 8074.222258] Lustre: Skipped 3 previous similar messages [ 8077.386686] Lustre: DEBUG MARKER: == sanity-quota test 88: Writing over quota should not hang ========================================================== 18:25:00 (1788733500) [ 8077.871866] Lustre: DEBUG MARKER: SKIP: sanity-quota test_88 require client with >4k pages [ 8078.382277] Lustre: DEBUG MARKER: == sanity-quota test 89: Show default quota with squash_uid ========================================================== 18:25:01 (1788733501) [ 8084.894268] Lustre: DEBUG MARKER: == sanity-quota test 90a: lfs quota should work without mount point ========================================================== 18:25:08 (1788733508) [ 8090.408850] Lustre: DEBUG MARKER: == sanity-quota test 90b: lfs quota should work with multiple mount points ========================================================== 18:25:13 (1788733513) [ 8097.801250] Lustre: DEBUG MARKER: == sanity-quota test 91: new quota index files in quota_master ========================================================== 18:25:21 (1788733521) [ 8110.050307] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 8110.052607] Lustre: Skipped 3 previous similar messages [ 8115.557667] Lustre: server umount lustre-MDT0000 complete [ 8116.934247] LustreError: 251315:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788733540 with bad export cookie 8837947703566718131 [ 8116.937463] LustreError: MGC192.168.204.135@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 8116.937671] LustreError: 251315:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 5 previous similar messages [ 8119.263728] LustreError: 3645:0:(client.c:1394:ptlrpc_import_delay_req()) @@@ IMP_CLOSED req@ffff9d22c6f4e680 x1875614673590784/t0(0) o601->lustre-MDT0000-lwp-MDT0001@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 [ 8119.276942] LustreError: 3645:0:(qsd_handler.c:298:qsd_req_completion()) $$$ DQACQ failed with -5, flags:0x8 qsd:lustre-MDT0001 qtype:usr lqe: ffff9d22d32bb800 id:0 enforced:0 granted: 0 pending:0 waiting:0 req:1 usage: 1628 qunit:0 qtune:0 edquot:0 default:no revoke:0 [ 8119.294352] LustreError: 3645:0:(qsd_handler.c:298:qsd_req_completion()) Skipped 3 previous similar messages [ 8123.130948] Lustre: server umount lustre-MDT0001 complete [ 8130.684114] Lustre: server umount lustre-OST0000 complete [ 8138.330666] Lustre: server umount lustre-OST0001 complete [ 8140.902150] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_hostid [ 8143.356214] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing load_modules_local [ 8159.954839] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 8160.048277] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 8160.059270] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 8160.101897] Lustre: lustre-MDT0000: new disk, initializing [ 8160.127248] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 8161.724228] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 8165.801603] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 8168.447055] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 8168.557752] Lustre: lustre-OST0000: new disk, initializing [ 8168.560262] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 8168.562894] Lustre: Skipped 1 previous similar message [ 8168.565117] Lustre: 325761:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 8169.912986] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:0:ost [ 8169.918359] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:0:ost] [ 8169.930767] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x240000400 [ 8170.834730] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 8175.155433] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 8177.978289] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 8178.042005] Lustre: lustre-OST0001: new disk, initializing [ 8178.044028] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 8178.047181] Lustre: 326817:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 8179.888555] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:1:ost [ 8179.891218] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:1:ost] [ 8179.899807] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x280000400 [ 8180.071560] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 8183.835061] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0001-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 8194.532327] Lustre: lustre-MDT0000: Not available for connect from 192.168.204.35@tcp (stopping) [ 8194.537312] Lustre: Skipped 8 previous similar messages [ 8197.035067] Lustre: server umount lustre-MDT0000 complete [ 8201.026424] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 8201.068039] LustreError: MGC192.168.204.135@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 8202.734423] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 8205.735854] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 8215.456918] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 8216.708409] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 10 sec [ 8217.213234] LustreError: 328496:0:(qmt_entry.c:1150:qmt_map_lge_idx()) qmt: cannot map ostidx 1, num_used 1: rc = -22 [ 8224.839411] Lustre: server umount lustre-MDT0000 complete [ 8227.255638] LustreError: 324755:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788733650 with bad export cookie 8837947703566720546 [ 8227.259652] LustreError: 324755:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 8227.328810] Lustre: server umount lustre-OST0000 complete [ 8228.606457] Lustre: server umount lustre-OST0001 complete [ 8234.500220] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_hostid [ 8236.805152] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing load_modules_local [ 8252.343162] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing load_modules_local [ 8255.692253] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 8255.779994] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 8255.791472] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 8255.827127] Lustre: lustre-MDT0000: new disk, initializing [ 8255.851504] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 8257.122267] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 8261.067982] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 8261.106275] Lustre: 333315:0:(mgs_llog.c:1453:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 8261.112050] Lustre: 333315:0:(mgs_llog.c:1453:mgs_modify_param()) Skipped 3 previous similar messages [ 8261.123121] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 8261.125621] Lustre: Skipped 1 previous similar message [ 8261.167398] Lustre: lustre-MDT0001: new disk, initializing [ 8261.191926] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 8261.194379] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 8262.426041] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 8264.608980] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 8266.564422] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 8266.646314] Lustre: 334950:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 8268.450592] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 8268.585373] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 8268.605261] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 8272.616088] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 8272.689177] Lustre: lustre-OST0001: new disk, initializing [ 8272.691266] Lustre: Skipped 1 previous similar message [ 8272.693281] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 8272.695866] Lustre: Skipped 1 previous similar message [ 8272.698147] Lustre: 335821:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 8274.423780] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 8274.429927] Lustre: Skipped 1 previous similar message [ 8274.432958] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 8274.456638] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 8274.910656] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 8279.897173] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 8281.100390] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 8283.545108] Lustre: DEBUG MARKER: == sanity-quota test 92: Cannot set inode limit with Quota Pools ========================================================== 18:28:26 (1788733706) [ 8290.917405] Lustre: DEBUG MARKER: == sanity-quota test 93: update projid while client write to OST ========================================================== 18:28:34 (1788733714) [ 8302.526071] Lustre: *** cfs_fail_loc=170c, val=0*** [ 8335.404685] Lustre: DEBUG MARKER: == sanity-quota test 94: lfs quota all respects nodemap offset ========================================================== 18:29:18 (1788733758) [ 8348.127882] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 8348.130886] LustreError: Skipped 3 previous similar messages [ 8348.132333] Lustre: lustre-MDT0000-osp-MDT0001: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 8348.135743] Lustre: Skipped 19 previous similar messages [ 8348.137536] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 8348.140171] Lustre: Skipped 4 previous similar messages [ 8353.236316] Lustre: server umount lustre-MDT0000 complete [ 8354.262731] LustreError: 333322:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.204.35@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 8354.273073] LustreError: 333322:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 10 previous similar messages [ 8356.839555] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 8356.891531] LustreError: MGC192.168.204.135@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 8356.896708] LustreError: Skipped 1 previous similar message [ 8356.976588] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 8356.979426] Lustre: Skipped 9 previous similar messages [ 8357.019245] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3 to 0x280000401:33) [ 8358.436199] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 8368.271691] Lustre: server umount lustre-MDT0000 complete [ 8371.320467] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 8371.499381] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3 to 0x280000401:65) [ 8372.960360] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 8376.678832] Lustre: DEBUG MARKER: == sanity-quota test 95a: Correct limits for squashed root ========================================================== 18:29:59 (1788733799) [ 8376.806841] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 8376.809679] Lustre: Skipped 1 previous similar message [ 8376.814625] LustreError: lustre-MDT0000-osp-MDT0001: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 8385.850071] Lustre: DEBUG MARKER: == sanity-quota test 95b: df respects squashed project id ========================================================== 18:30:09 (1788733809) [ 8399.859899] Lustre: DEBUG MARKER: == sanity-quota test 96: quota grant should be released when big files are deleted ========================================================== 18:30:23 (1788733823) [ 8400.422638] Lustre: DEBUG MARKER: SKIP: sanity-quota test_96 OST is too small, skip the test [ 8401.219994] Lustre: DEBUG MARKER: == sanity-quota test 97a: LQA control commands =========== 18:30:24 (1788733824) [ 8411.330661] LustreError: 346714:0:(qmt_lqa.c:79:qmt_lqa_destroy()) lustre-QMT0000: cannot destroy lqa-dt-lqa1: rc = -2 [ 8411.335068] LustreError: 346714:0:(qmt_lqa.c:84:qmt_lqa_destroy()) lustre-QMT0000: cannot destroy lqa-md-lqa1: rc = -2 [ 8411.986600] Lustre: DEBUG MARKER: == sanity-quota test 97b: Check LQA internals ============ 18:30:35 (1788733835) [ 8420.469393] LustreError: 347606:0:(qmt_lqa.c:250:qmt_lqa_insert_range()) lustre-QMT0000: LQA range 15-31 partially overlaps with existing range 10-19: rc = -34 [ 8420.476114] LustreError: 347606:0:(qmt_lqa.c:669:qmt_lqa_add()) lustre-QMT0000: lqa:lqa1 can't add range 15:31: rc = -17 [ 8421.836923] LustreError: 347802:0:(qmt_lqa.c:825:qmt_lqa_remove()) lustre-QMT0000: lqa-md-lqa1 cannot remove range 10:19: rc = -2 [ 8425.721313] Lustre: DEBUG MARKER: adding 50 LQA ranges took 1s [ 8427.225013] Lustre: DEBUG MARKER: Removing 50 LQA ranges took 0s [ 8429.865112] Lustre: DEBUG MARKER: == sanity-quota test 97c: LQA lfs quota commands and MDS restart consistency ========================================================== 18:30:53 (1788733853) [ 8431.149084] Lustre: Failing over lustre-MDT0000 [ 8431.395416] Lustre: server umount lustre-MDT0000 complete [ 8434.138731] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 8434.287552] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 8435.511204] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 8436.198738] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 8437.203870] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 8439.270330] Lustre: lustre-MDT0000: Recovery over after 0:03, of 2 clients 2 recovered and 0 were evicted. [ 8439.285739] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3 to 0x280000401:97) [ 8444.627743] Lustre: DEBUG MARKER: == sanity-quota test 97d: LQA disk persistence using standard commands ========================================================== 18:31:08 (1788733868) [ 8449.113264] Lustre: Failing over lustre-MDT0000 [ 8449.411334] Lustre: server umount lustre-MDT0000 complete [ 8451.864552] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 8451.978624] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 8453.117513] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 8454.802992] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 8456.662392] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 8457.189165] Lustre: lustre-MDT0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 8457.205453] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3 to 0x280000401:129) [ 8471.786487] Lustre: DEBUG MARKER: == sanity-quota test 97e: LQA add/remove should reject invalid ranges ========================================================== 18:31:35 (1788733895) [ 8477.136531] LustreError: 353942:0:(qmt_lqa.c:79:qmt_lqa_destroy()) lustre-QMT0000: cannot destroy lqa-dt-lqa1: rc = -2 [ 8477.139660] LustreError: 353942:0:(qmt_lqa.c:84:qmt_lqa_destroy()) lustre-QMT0000: cannot destroy lqa-md-lqa1: rc = -2 [ 8477.845343] Lustre: DEBUG MARKER: == sanity-quota test 98: Verify MDT retry on -EDQUOT during mkdir ========================================================== 18:31:41 (1788733901) [ 8480.169638] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 8480.936735] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8483.354885] Lustre: DEBUG MARKER: oleg435-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [ 8483.935890] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8489.359523] Lustre: *** cfs_fail_loc=a02, val=1*** [ 8489.361524] LustreError: 333351:0:(lod_object.c:6285:lod_declare_create()) lustre-MDT0000-mdtlov: Injecting -EDQUOT for directory create on MDT0000 (fail_val=1): rc = -122 [ 8491.877481] Lustre: DEBUG MARKER: == sanity-quota test 300: inode quota with MDT directory migration at 80% limit ========================================================== 18:31:55 (1788733915) [ 8499.701080] Lustre: DEBUG MARKER: Creating 819 files as quota_usr ... [ 8504.765557] Lustre: DEBUG MARKER: Migrating directory from MDT0 to MDT1 ... [ 8527.399196] Lustre: DEBUG MARKER: Migration completed successfully [ 8542.064077] Lustre: DEBUG MARKER: == sanity-quota test complete, duration 8226 sec ========= 18:32:45 (1788733965) [ 8542.717572] Lustre: DEBUG MARKER: === sanity-quota: start cleanup 18:32:45 (1788733965) === [ 8543.907497] Lustre: DEBUG MARKER: === sanity-quota: finish cleanup 18:32:47 (1788733967) === [ 8549.345574] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 8549.351248] Lustre: Skipped 17 previous similar messages [ 8551.212358] Lustre: server umount lustre-MDT0000 complete [ 8554.687782] LustreError: 333309:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788733978 with bad export cookie 8837947703566726937 [ 8554.695051] LustreError: 333309:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 8554.833455] Lustre: server umount lustre-MDT0001 complete [ 8568.845522] Lustre: server umount lustre-OST0000 complete [ 8583.025048] Lustre: server umount lustre-OST0001 complete [ 8590.215563] Lustre: DEBUG MARKER: oleg435-server.virtnet: executing unload_modules_local [ 8591.575840] Key type lgssc unregistered [ 8591.748395] LNet: 358979:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 8591.752093] LNetError: 358979:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 8591.761427] LNet: Removed LNI 192.168.204.135@tcp [ 8592.203151] Key type .llcrypt unregistered [ 8592.205442] Key type ._llcrypt unregistered