[ 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 466659002 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2399.998 MHz processor [ 0.000000] last_pfn = 0x146e00 max_arch_pfn = 0x400000000 [ 0.000000] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT [ 0.000000] last_pfn = 0xbffce max_arch_pfn = 0x400000000 [ 0.000000] found SMP MP-table at [mem 0x000f54b0-0x000f54bf] [ 0.000000] RAMDISK: [mem 0xbcc54000-0xbffbffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F52D0 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE247C 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE2318 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 0022D8 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE238C 000090 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE241C 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE2454 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe2318-0xbffe238b] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe2317] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe238c-0xbffe241b] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe241c-0xbffe2453] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe2454-0xbffe247b] [ 0.000000] No NUMA configuration found [ 0.000000] Faking a node at [mem 0x0000000000000000-0x0000000146dfffff] [ 0.000000] NODE_DATA(0) allocated [mem 0x1465a3000-0x1465cdfff] [ 0.000000] Reserving 256MB of memory at 2752MB for crashkernel (System RAM: 4205MB) [ 0.000000] Zone ranges: [ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.000000] DMA32 [mem 0x0000000001000000-0x00000000ffffffff] [ 0.000000] Normal [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Device empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff] [ 0.000000] node 0: [mem 0x0000000000100000-0x00000000bffcdfff] [ 0.000000] node 0: [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Zeroed struct page in unavailable ranges: 4756 pages [ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x0000000146dfffff] [ 0.000000] ACPI: PM-Timer IO Port: 0x608 [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) [ 0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) [ 0.000000] Using ACPI (MADT) for SMP configuration information [ 0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000] TSC deadline timer available [ 0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs [ 0.000000] kvm-guest: KVM setup pv remote TLB flush [ 0.000000] kvm-guest: setup PV sched yield [ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff] [ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff] [ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff] [ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff] [ 0.000000] PM: Registered nosave memory: [mem 0xbffce000-0xbfffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xc0000000-0xfeffbfff] [ 0.000000] PM: Registered nosave memory: [mem 0xfeffc000-0xfeffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xff000000-0xfffbffff] [ 0.000000] PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff] [ 0.000000] [mem 0xc0000000-0xfeffbfff] available for PCI devices [ 0.000000] Booting paravirtualized kernel on KVM [ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns [ 0.000000] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1 [ 0.000000] percpu: Embedded 63 pages/cpu s221184 r8192 d28672 u524288 [ 0.000000] kvm-guest: PV spinlocks enabled [ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1059606 [ 0.000000] Policy zone: Normal [ 0.000000] Kernel command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] Specific versions of hardware are certified with Red Hat Enterprise Linux 8. Please see the list of hardware certified with Red Hat Enterprise Linux 8 at https://catalog.redhat.com. [ 0.000000] audit: disabled (until reboot) [ 0.000000] software IO TLB: area num 4. [ 0.000000] Memory: 2829652K/4306352K available (18435K kernel code, 11221K rwdata, 7248K rodata, 2908K init, 18040K bss, 524580K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] ftrace: allocating 41240 entries in 162 pages [ 0.000000] ftrace: allocated 162 pages with 3 groups [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] rcu: RCU event tracing is enabled. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ 0.000000] rcu: RCU callback double-/use-after-free debug enabled. [ 0.000000] Rude variant of Tasks RCU enabled. [ 0.000000] Tracing variant of Tasks RCU enabled. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 0.000000] NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16 [ 0.000000] random: get_random_bytes called from start_kernel+0x622/0x9a8 with crng_init=0 [ 0.001000] Console: colour *CGA 80x25 [ 0.001000] printk: console [ttyS1] enabled [ 0.001000] ACPI: Core revision 20220331 [ 0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.001008] APIC: Switch to symmetric I/O mode setup [ 0.002234] x2apic enabled [ 0.003004] Switched APIC routing to physical x2apic. [ 0.004011] kvm-guest: setup PV IPIs [ 0.006877] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.007000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.007019] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.008008] pid_max: default: 32768 minimum: 301 [ 0.009125] LSM: Security Framework initializing [ 0.010033] Yama: becoming mindful. [ 0.011021] SELinux: Initializing. [ 0.012052] *** VALIDATE selinux *** [ 0.020075] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.024207] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.025117] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.026096] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.027081] *** VALIDATE tmpfs *** [ 0.028304] *** VALIDATE proc *** [ 0.029156] *** VALIDATE cgroup *** [ 0.030005] *** VALIDATE cgroup2 *** [ 0.032267] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.033107] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.034005] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.035027] Spectre V2 : User space: Vulnerable [ 0.036008] Speculative Store Bypass: Vulnerable [ 0.039019] debug: unmapping init [mem 0xffffffff8c059000-0xffffffff8c060fff] [ 0.042000] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.042648] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.043019] ... version: 2 [ 0.044010] ... bit width: 48 [ 0.045010] ... generic registers: 4 [ 0.046012] ... value mask: 0000ffffffffffff [ 0.047014] ... max period: 00007fffffffffff [ 0.048014] ... fixed-purpose events: 3 [ 0.049010] ... event mask: 000000070000000f [ 0.051212] rcu: Hierarchical SRCU implementation. [ 0.053285] smp: Bringing up secondary CPUs ... [ 0.054422] x86: Booting SMP configuration: [ 0.055028] .... node #0, CPUs: #1 #2 #3 [ 0.058487] smp: Brought up 1 node, 4 CPUs [ 0.060010] smpboot: Max logical packages: 1 [ 0.060900] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.220402] node 0 deferred pages initialised in 158ms [ 0.224015] devtmpfs: initialized [ 0.225226] x86/mm: Memory block size: 128MB [ 0.227830] gcov: version magic: 0x41383552 [ 0.228593] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.232101] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.234387] pinctrl core: initialized pinctrl subsystem [ 0.236184] [ 0.236507] ************************************************************* [ 0.238017] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.241015] ** ** [ 0.242014] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.244024] ** ** [ 0.246020] ** This means that this kernel is built to expose internal ** [ 0.248015] ** IOMMU data structures, which may compromise security on ** [ 0.249015] ** your system. ** [ 0.251017] ** ** [ 0.254016] ** If you see this message and you are not debugging the ** [ 0.256010] ** kernel, report this immediately to your vendor! ** [ 0.258014] ** ** [ 0.260013] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.261013] ************************************************************* [ 0.263743] NET: Registered protocol family 16 [ 0.266506] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.268076] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.270070] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.273138] cpuidle: using governor menu [ 0.275536] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.276822] PCI: Using configuration type 1 for base access [ 0.279166] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.289045] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.291022] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.295040] cryptd: max_cpu_qlen set to 1000 [ 0.299378] ACPI: Added _OSI(Module Device) [ 0.301021] ACPI: Added _OSI(Processor Device) [ 0.302014] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.304016] ACPI: Added _OSI(Processor Aggregator Device) [ 0.307517] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.314439] ACPI: Interpreter enabled [ 0.316068] ACPI: PM: (supports S0 S3 S4 S5) [ 0.317013] ACPI: Using IOAPIC for interrupt routing [ 0.318123] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.321534] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.330211] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.332075] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.334037] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.337081] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.341447] acpiphp: Slot [2] registered [ 0.342153] acpiphp: Slot [5] registered [ 0.343167] acpiphp: Slot [6] registered [ 0.345178] acpiphp: Slot [7] registered [ 0.346130] acpiphp: Slot [8] registered [ 0.347083] acpiphp: Slot [9] registered [ 0.348146] acpiphp: Slot [10] registered [ 0.350147] acpiphp: Slot [3] registered [ 0.352124] acpiphp: Slot [4] registered [ 0.353082] acpiphp: Slot [11] registered [ 0.354113] acpiphp: Slot [12] registered [ 0.356079] acpiphp: Slot [13] registered [ 0.356915] acpiphp: Slot [14] registered [ 0.358125] acpiphp: Slot [15] registered [ 0.359099] acpiphp: Slot [16] registered [ 0.360070] acpiphp: Slot [17] registered [ 0.361084] acpiphp: Slot [18] registered [ 0.363096] acpiphp: Slot [19] registered [ 0.364094] acpiphp: Slot [20] registered [ 0.366097] acpiphp: Slot [21] registered [ 0.366938] acpiphp: Slot [22] registered [ 0.368089] acpiphp: Slot [23] registered [ 0.368984] acpiphp: Slot [24] registered [ 0.370072] acpiphp: Slot [25] registered [ 0.371104] acpiphp: Slot [26] registered [ 0.372092] acpiphp: Slot [27] registered [ 0.373137] acpiphp: Slot [28] registered [ 0.375075] acpiphp: Slot [29] registered [ 0.376098] acpiphp: Slot [30] registered [ 0.377095] acpiphp: Slot [31] registered [ 0.378086] PCI host bridge to bus 0000:00 [ 0.379016] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.381030] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.383025] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.386028] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.388028] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.391031] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.393208] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.395350] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.396000] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.403646] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.408057] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.411019] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.412015] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.415020] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.416593] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.419821] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.422048] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.424821] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.429017] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.439934] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.444014] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.448752] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.456023] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.465023] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.492019] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.507010] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.515016] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.524019] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.539018] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.547264] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.555018] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.562074] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.581017] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.592526] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.598015] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.605019] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.622017] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.632884] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.642015] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.648014] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.672013] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 0.683739] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.693017] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.706015] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.721022] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 0.736038] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.739388] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.741330] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.744355] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.746193] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.749094] iommu: Default domain type: Passthrough [ 0.751390] SCSI subsystem initialized [ 0.753160] ACPI: bus type USB registered [ 0.755132] usbcore: registered new interface driver usbfs [ 0.757074] usbcore: registered new interface driver hub [ 0.759097] usbcore: registered new device driver usb [ 0.760000] pps_core: LinuxPPS API ver. 1 registered [ 0.761012] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.764057] PTP clock support registered [ 0.769047] EDAC MC: Ver: 3.0.0 [ 0.773031] PCI: Using ACPI for IRQ routing [ 0.776075] NetLabel: Initializing [ 0.777010] NetLabel: domain hash size = 128 [ 0.779011] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.782100] NetLabel: unlabeled traffic allowed by default [ 0.784119] vgaarb: loaded [ 0.785289] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.786000] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.789000] clocksource: Switched to clocksource kvm-clock [ 0.898302] VFS: Disk quotas dquot_6.6.0 [ 0.899719] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.902151] *** VALIDATE ramfs *** [ 0.903300] *** VALIDATE hugetlbfs *** [ 0.904757] pnp: PnP ACPI init [ 0.907069] pnp: PnP ACPI: found 6 devices [ 0.926398] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.929900] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.932043] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.934288] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.936540] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.938895] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.941587] NET: Registered protocol family 2 [ 0.943780] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.948245] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.951663] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.956561] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.959688] TCP: Hash tables configured (established 65536 bind 65536) [ 0.962451] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.965643] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.968601] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.971455] NET: Registered protocol family 1 [ 0.974537] RPC: Registered named UNIX socket transport module. [ 0.976731] RPC: Registered udp transport module. [ 0.978847] RPC: Registered tcp transport module. [ 0.980672] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.982796] NET: Registered protocol family 44 [ 0.984422] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.986442] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.988539] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.990610] PCI: CLS 0 bytes, default 64 [ 0.992136] Unpacking initramfs... [ 2.365757] debug: unmapping init [mem 0xffff938afcc54000-0xffff938afffbffff] [ 2.369841] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.372078] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.375191] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 2.845857] Initialise system trusted keyrings [ 2.847438] Key type blacklist registered [ 2.849648] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.857471] zbud: loaded [ 2.860615] *** VALIDATE nfs *** [ 2.861731] *** VALIDATE nfs4 *** [ 2.863313] pstore: using deflate compression [ 2.866908] Platform Keyring initialized [ 2.975954] NET: Registered protocol family 38 [ 2.977736] Key type asymmetric registered [ 2.978864] Asymmetric key parser 'x509' registered [ 2.980146] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 2.984251] io scheduler mq-deadline registered [ 2.986222] io scheduler kyber registered [ 2.987867] io scheduler bfq registered [ 2.989196] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 2.991920] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 2.994675] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 2.997671] ACPI: Power Button [PWRF] [ 3.002870] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 3.009152] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 3.022624] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 3.030435] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 3.046106] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 3.076207] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.105669] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.112511] Non-volatile memory driver v1.3 [ 3.114048] Linux agpgart interface v0.103 [ 3.147286] virtio_blk virtio1: [vda] 136600 512-byte logical blocks (69.9 MB/66.7 MiB) [ 3.149907] vda: detected capacity change from 0 to 69939200 [ 3.162785] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.165827] vdb: detected capacity change from 0 to 1073741824 [ 3.180199] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.183347] vdc: detected capacity change from 0 to 2621440000 [ 3.198599] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.201681] vdd: detected capacity change from 0 to 2621440000 [ 3.217745] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.219954] vde: detected capacity change from 0 to 4294967296 [ 3.244060] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.247149] vdf: detected capacity change from 0 to 4294967296 [ 3.257933] libphy: Fixed MDIO Bus: probed [ 3.263553] usbcore: registered new interface driver usbserial_generic [ 3.265978] usbserial: USB Serial support registered for generic [ 3.268754] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.273219] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.274992] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.278089] mousedev: PS/2 mouse device common for all mice [ 3.281761] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.285386] rtc_cmos 00:05: RTC can wake from S4 [ 3.287218] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.290799] rtc_cmos 00:05: registered as rtc0 [ 3.294176] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.294958] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.297214] intel_pstate: CPU model not supported [ 3.302909] hid: raw HID events driver (C) Jiri Kosina [ 3.305164] usbcore: registered new interface driver usbhid [ 3.307442] usbhid: USB HID core driver [ 3.309201] drop_monitor: Initializing network drop monitor service [ 3.311261] Initializing XFRM netlink socket [ 3.313157] NET: Registered protocol family 10 [ 3.315386] Segment Routing with IPv6 [ 3.316207] NET: Registered protocol family 17 [ 3.317558] mpls_gso: MPLS GSO support [ 3.322658] RAS: Correctable Errors collector initialized. [ 3.324742] AVX version of gcm_enc/dec engaged. [ 3.326888] AES CTR mode by8 optimization enabled [ 3.401536] sched_clock: Marking stable (3401514451, 0)->(4243110613, -841596162) [ 3.404748] registered taskstats version 1 [ 3.407636] Loading compiled-in X.509 certificates [ 3.409790] zswap: loaded using pool lzo/zbud [ 3.433314] Key type big_key registered [ 3.447745] Key type encrypted registered [ 3.449244] ima: No TPM chip found, activating TPM-bypass! [ 3.451420] ima: Allocated hash algorithm: sha1 [ 3.453422] ima: No architecture policies found [ 3.454897] evm: Initialising EVM extended attributes: [ 3.456189] evm: security.selinux [ 3.456967] evm: security.ima [ 3.458082] evm: security.capability [ 3.459335] evm: HMAC attrs: 0x1 [ 3.461704] rtc_cmos 00:05: setting system clock to 2026-06-12 02:58:41 UTC (1781233121) [ 3.467896] debug: unmapping init [mem 0xffffffff8d003000-0xffffffff8d1fffff] [ 3.470987] debug: unmapping init [mem 0xffffffff8bd82000-0xffffffff8c058fff] [ 3.481891] Write protecting the kernel read-only data: 28672k [ 3.485022] debug: unmapping init [mem 0xffffffff8a403000-0xffffffff8a5fffff] [ 3.487570] debug: unmapping init [mem 0xffffffff8ad14000-0xffffffff8adfffff] [ 3.555601] 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.562716] systemd[1]: Detected virtualization kvm. [ 3.564338] systemd[1]: Detected architecture x86-64. [ 3.565784] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.596287] systemd[1]: No hostname configured. [ 3.598253] systemd[1]: Set hostname to . [ 3.600597] random: systemd: uninitialized urandom read (16 bytes read) [ 3.603301] systemd[1]: Initializing machine ID from random generator. [ 3.643316] random: ln: uninitialized urandom read (6 bytes read) [ 3.725429] random: systemd: uninitialized urandom read (16 bytes read) [ 3.727879] systemd[1]: Reached target Initrd Root Device. [ OK ] Reached target Initrd Root Device. [ 3.732232] systemd[1]: Listening on Journal Socket (/dev/log). [ OK ] Listening on Journal Socket (/dev/log). [ 3.736368] systemd[1]: Started Dispatch Password Requests to Console Directory Watch. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Paths. [ OK ] Reached target Swap. [ OK ] Listening on udev Kernel Socket. [ OK ] Listening on Journal Socket. Starting Setup Virtual Console... [ OK ] Started Memstrack Anylazing Service. Starting Journal Service... [ OK ] Reached target Slices. Starting Apply Kernel Variables... [ OK ] Reached target Local File Systems. Starting Create Volatile Files and Directories... [ OK ] Listening on udev Control Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Local Encrypted Volumes. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Reached target Timers. [ OK ] Started Setup Virtual Console. [ OK ] Started Apply Kernel Variables. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Create list of required sta…vice nodes for the current kernel. Starting Create Static Device Nodes in /dev... Starting dracut cmdline hook... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started Journal Service. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 4.352139] device-mapper: uevent: version 1.0.3 [ 4.353743] device-mapper: ioctl: 4.46.0-ioctl (2022-02-22) initialised: dm-devel@redhat.com [ OK ] Started dracut pre-udev hook. Starting udev Kernel Device Manager... [ OK ] Started udev Kernel Device Manager. Starting dracut pre-trigger hook... [ OK ] Started dracut pre-trigger hook. Starting udev Coldplug all Devices... Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. Starting dracut initqueue hook... [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ 4.993255] random: fast init done [ 5.001912] virtio_net virtio0 ens2: renamed from eth0 [ 5.055279] scsi host0: ata_piix [ 5.063512] scsi host1: ata_piix [ 5.065089] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 5.066756] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 9.234840] dracut-initqueue[588]: RTNETLINK answers: File exists [ 9.966552] random: crng init done [ 9.967828] random: 7 urandom warning(s) missed due to ratelimiting Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. Mounting /sysroot... [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. [ 10.244524] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped target Timers. [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Sockets. [ OK ] Stopped target Slices. [ OK ] Stopped target Paths. [ OK ] Stopped target System Initialization. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Swap. [ OK ] Stopped target Local File Systems. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. Stopping udev Kernel Device Manager... [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Closed udev Control Socket. [ OK ] Closed udev Kernel Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 11.374236] printk: systemd: 26 output lines suppressed due to ratelimiting [ 11.635531] SELinux: Disabled at runtime. [ 11.701530] 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) [ 11.708884] systemd[1]: Detected virtualization kvm. [ 11.710553] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 12.169360] systemd[1]: initrd-switch-root.service: Succeeded. [ 12.172105] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 12.176860] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 12.181255] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 12.184137] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 12.196748] systemd[1]: Starting Journal Service... Starting Journal Service... [ 12.203162] systemd[1]: Starting Remount Root and Kernel File Systems... Starting Remount Root and Kernel File Systems... [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Listening on udev Control Socket. Mounting POSIX Message Queue File System... [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Reached target RPC Port Mapper. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Listening on udev Kernel Socket. Starting udev Coldplug all Devices... Starting Create list of required st…ce nodes for the current kernel... [ OK ] Started Forward Password Requests to Wall Directory Watch. Mounting Kernel Debug File System... [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Created slice User and Session Slice. [ OK ] Reached target Slices. [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Listening on Process Core Dump Socket. Activating swap /dev/disk/by-label/SWAP... [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target rpc_pipefs.target. [ OK ] Created slice system-getty.slice. Mounting Huge Pages File System... Starting Apply Kernel Variables... [ OK ] Reached target Paths. [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd Root File System. [[ 12.359473] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS  OK ] Stopped target Initrd File Systems. [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Started Journal Service. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Mounted Kernel Debug File System. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Mounted Huge Pages File System. [ OK ] Started Apply Kernel Variables. [ OK ] Reached target Swap. Starting Configure read-only root support... Starting Create Static Device Nodes in /dev... Starting Flush Journal to Persistent Storage... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Reached target Local File Systems (Pre). Mounting /mnt... Mounting /home/green/git/lustre-release... Starting udev Kernel Device Manager... [ OK ] Started udev Coldplug all Devices. [ OK ] Mounted /mnt. [ 12.631774] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 12.943818] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 12.949430] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 13.127732] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 13.137036] EDAC sbridge: Ver: 1.1.2 [ 14.698168] Key type dns_resolver registered [ 14.994140] NFS: Registering the id_resolver key type [ 14.995830] Key type id_resolver registered [ 14.997274] Key type id_legacy registered [ OK ] Started Configure read-only root support. [ OK ] Reached target Local File Systems. Starting Rebuild Dynamic Linker Cache... Starting Mark the need to relabel after reboot... Starting Load/Save Random Seed... Starting Create Volatile Files and Directories... [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Load/Save Random Seed. [ OK ] Started Create Volatile Files and Directories. Starting Update UTMP about System Boot/Shutdown... Starting RPC Bind... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Reached target Basic System. [ OK ] Started D-Bus System Message Bus. Starting Network Manager... [ OK ] Started irqbalance daemon. Starting Login Service... [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Reached target sshd-keygen.target. [ OK ] Started dnf makecache --timer. [ OK ] Reached target Timers. Starting Restore /run/initramfs on shutdown... [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Login Service. [ OK ] Started Network Manager. [ OK ] Reached target Network. Starting GSSAPI Proxy Daemon... Starting OpenSSH server daemon... Starting Dynamic System Tuning Daemon... Starting Network Manager Wait Online... Starting Hostname Service... [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... [ OK ] Started OpenSSH server daemon. [ OK ] Started Permit User Sessions. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Getty on tty1. [ OK ] Started Command Scheduler. [ 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 Notify NFS peers of a restart... Starting Crash recovery kernel arming... Starting System Logging Service... [ 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 oleg618-server login: [ 39.768901] libcfs: loading out-of-tree module taints kernel. [ 39.787970] Key type ._llcrypt registered [ 39.789429] Key type .llcrypt registered [ 39.836799] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_hostid [ 48.912542] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing load_modules_local [ 49.672941] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 49.681239] alg: No test for adler32 (adler32-zlib) [ 50.793632] Lustre: Lustre: Build Version: 2.17.53_83_gc434fe8 [ 51.212166] LNet: Added LNI 192.168.206.118@tcp [8/256/0/180] [ 52.855158] Key type lgssc registered [ 53.674964] Lustre: Echo OBD driver; http://www.lustre.org/ [ 61.566280] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 79.078921] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing load_modules_local [ 84.933329] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 84.947508] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 86.080497] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 86.101119] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 86.159806] Lustre: lustre-MDT0000: new disk, initializing [ 86.198339] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 86.207066] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 87.875590] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 94.720583] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 94.792723] Lustre: 6475:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 94.813623] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 94.816702] Lustre: Skipped 1 previous similar message [ 94.870632] Lustre: lustre-MDT0001: new disk, initializing [ 94.910995] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 94.927646] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 94.934855] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 97.025503] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 99.942898] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 104.608301] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 104.739805] Lustre: lustre-OST0000: new disk, initializing [ 104.742495] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 104.747701] Lustre: 8379:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 104.791275] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 106.431966] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 106.437671] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 106.482964] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 107.787282] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 115.144220] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 115.209132] Lustre: lustre-OST0001: new disk, initializing [ 115.211764] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 115.217466] Lustre: 9436:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 115.260695] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 116.355548] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 116.361839] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 116.398188] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 117.989648] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 125.293504] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 129.110563] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 132.774747] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing check_logdir /tmp/testlogs/ [ 136.030422] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing yml_node [ 138.285601] Lustre: DEBUG MARKER: Client: 2.17.53.83 [ 139.618375] Lustre: DEBUG MARKER: MDS: 2.17.53.83 [ 140.923304] Lustre: DEBUG MARKER: OSS: 2.17.53.83 [ 141.772577] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity-quota ============----- Thu Jun 11 23:00:59 EDT 2026 [ 150.796765] Lustre: DEBUG MARKER: excepting tests: 2 4a 63 65 [ 151.555067] Lustre: DEBUG MARKER: skipping tests SLOW=no: 61 [ 153.022684] Lustre: DEBUG MARKER: === sanity-quota: start setup 23:01:11 (1781233271) === [ 154.628897] Lustre: DEBUG MARKER: oleg618-client.virtnet: executing check_config_client /mnt/lustre [ 163.945585] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 165.494357] Lustre: 13249:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 167.038832] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 169.564971] Lustre: DEBUG MARKER: === sanity-quota: finish setup 23:01:27 (1781233287) === [ 196.898983] Lustre: DEBUG MARKER: == sanity-quota test 0: Test basic quota performance ===== 23:01:55 (1781233315) [ 224.181675] Lustre: DEBUG MARKER: == sanity-quota test 1a: Block hard limit (normal use and out of quota) ========================================================== 23:02:22 (1781233342) [ 229.628730] Lustre: DEBUG MARKER: User quota (block hardlimit:10 MB) [ 233.075836] Lustre: DEBUG MARKER: Write... [ 234.263716] Lustre: DEBUG MARKER: Write out of block quota ... [ 257.688724] Lustre: DEBUG MARKER: -------------------------------------- [ 258.660973] Lustre: DEBUG MARKER: Group quota (block hardlimit:10 MB) [ 262.317155] Lustre: DEBUG MARKER: Write... [ 263.448227] Lustre: DEBUG MARKER: Write out of block quota ... [ 289.925971] Lustre: DEBUG MARKER: -------------------------------------- [ 290.665575] Lustre: DEBUG MARKER: Project quota (block hardlimit:10 mb) [ 291.938521] Lustre: DEBUG MARKER: Write... [ 292.927383] Lustre: DEBUG MARKER: Write out of block quota ... [ 328.873744] Lustre: DEBUG MARKER: == sanity-quota test 1b: Quota pools: Block hard limit (normal use and out of quota) ========================================================== 23:04:07 (1781233447) [ 334.165254] Lustre: DEBUG MARKER: User quota (block hardlimit:20 MB) [ 347.058423] Lustre: DEBUG MARKER: Write... [ 348.146332] Lustre: DEBUG MARKER: Write out of block quota ... [ 371.459669] Lustre: DEBUG MARKER: -------------------------------------- [ 372.123250] Lustre: DEBUG MARKER: Group quota (block hardlimit:20 MB) [ 375.381785] Lustre: DEBUG MARKER: Write... [ 376.586703] Lustre: DEBUG MARKER: Write out of block quota ... [ 403.020352] Lustre: DEBUG MARKER: -------------------------------------- [ 403.882809] Lustre: DEBUG MARKER: Project quota (block hardlimit:20 mb) [ 405.244267] Lustre: DEBUG MARKER: Write... [ 406.309724] Lustre: DEBUG MARKER: Write out of block quota ... [ 445.112749] Lustre: DEBUG MARKER: == sanity-quota test 1c: Quota pools: check 3 pools with hardlimit only for global ========================================================== 23:06:03 (1781233563) [ 449.867353] Lustre: DEBUG MARKER: User quota (block hardlimit:20 MB) [ 464.022995] Lustre: DEBUG MARKER: Write... [ 465.289546] Lustre: DEBUG MARKER: Write out of block quota ... [ 518.029935] Lustre: DEBUG MARKER: == sanity-quota test 1d: Quota pools: check block hardlimit on different pools ========================================================== 23:07:16 (1781233636) [ 522.990727] Lustre: DEBUG MARKER: User quota (block hardlimit:20 MB) [ 538.111179] Lustre: DEBUG MARKER: Write... [ 538.992355] Lustre: DEBUG MARKER: Write out of block quota ... [ 591.193878] Lustre: DEBUG MARKER: == sanity-quota test 1e: Quota pools: global pool high block limit vs quota pool with small ========================================================== 23:08:29 (1781233709) [ 595.787258] Lustre: DEBUG MARKER: User quota (block hardlimit:53000000 MB) [ 602.273862] Lustre: DEBUG MARKER: Write... [ 603.206483] Lustre: DEBUG MARKER: Write out of block quota ... [ 611.399648] Lustre: DEBUG MARKER: Write... [ 635.817645] Lustre: DEBUG MARKER: == sanity-quota test 1f: Quota pools: correct qunit after removing/adding OST ========================================================== 23:09:14 (1781233754) [ 640.501687] Lustre: DEBUG MARKER: User quota (block hardlimit:200 MB) [ 646.585952] Lustre: DEBUG MARKER: Write... [ 647.541739] Lustre: DEBUG MARKER: Write out of block quota ... [ 672.089268] Lustre: DEBUG MARKER: Write... [ 672.986758] Lustre: DEBUG MARKER: Write out of block quota ... [ 706.100069] Lustre: DEBUG MARKER: == sanity-quota test 1g: Quota pools: Block hard limit with wide striping ========================================================== 23:10:24 (1781233824) [ 711.382734] Lustre: DEBUG MARKER: User quota (block hardlimit:40 MB) [ 718.845139] Lustre: 6482:0:(osd_handler.c:2191:osd_trans_start()) lustre-MDT0000: credits 6570 > trans_max 3200 [ 718.850510] Lustre: 6482:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 4/16/0, destroy: 0/0/0 [ 718.854973] Lustre: 6482:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 401/401/0, xattr_set: 602/5615/0 [ 718.860016] Lustre: 6482:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 20/142/0, punch: 0/0/0, quota 8/328/0 [ 718.866315] Lustre: 6482:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/68/0, delete: 0/0/0 [ 718.869457] Lustre: 6482:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 718.872512] CPU: 0 PID: 6482 Comm: mdt00_000 Kdump: loaded Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 718.877185] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.17.0-10.fc44 06/10/2025 [ 718.880327] Call Trace: [ 718.882491] ? dump_stack+0xbb/0x10e [ 718.884929] ? osd_trans_start+0x8db/0x9d0 [osd_ldiskfs] [ 718.887457] ? top_trans_start+0x599/0xd80 [ptlrpc] [ 718.889310] ? lod_ref_add+0x30/0x30 [lod] [ 718.890797] ? lod_trans_start+0x109/0x4c0 [lod] [ 718.893043] ? mdd_declare_attr_set+0x190/0x690 [mdd] [ 718.894547] ? mdd_env_info+0x25/0xc0 [mdd] [ 718.895912] ? mdd_trans_start+0x18/0x30 [mdd] [ 718.897177] ? mdd_attr_set+0xa5a/0x1240 [mdd] [ 718.898897] ? mdt_reint_setattr+0x14aa/0x2030 [mdt] [ 718.902206] ? mdt_reint_setattr+0x14aa/0x2030 [mdt] [ 718.904136] ? mdt_reint_rec+0x139/0x2b0 [mdt] [ 718.906774] ? mdt_reint_internal+0x693/0xdc0 [mdt] [ 718.909216] ? mdt_reint+0x163/0x190 [mdt] [ 718.910682] ? tgt_handle_request0+0x137/0xaf0 [ptlrpc] [ 718.914227] ? tgt_request_handle+0x575/0x1f70 [ptlrpc] [ 718.917004] ? ptlrpc_server_handle_request+0x443/0x13b0 [ptlrpc] [ 718.920170] ? lprocfs_counter_add+0x15b/0x210 [obdclass] [ 718.922723] ? ptlrpc_main+0xce8/0x1400 [ptlrpc] [ 718.925287] ? ptlrpc_wait_event+0x690/0x690 [ptlrpc] [ 718.927623] ? kthread+0x1d1/0x200 [ 718.929056] ? set_kthread_struct+0x70/0x70 [ 718.930631] ? ret_from_fork+0x1f/0x30 [ 719.888489] Lustre: DEBUG MARKER: Write... [ 725.479612] Lustre: DEBUG MARKER: Write out of block quota ... [ 769.816184] Lustre: DEBUG MARKER: == sanity-quota test 1h: Block hard limit test using fallocate ========================================================== 23:11:28 (1781233888) [ 775.747383] Lustre: DEBUG MARKER: User quota (block hardlimit:10 MB) [ 779.047346] Lustre: DEBUG MARKER: Write 5MiB Using Fallocate [ 783.768562] Lustre: DEBUG MARKER: Write 11MiB Using Fallocate [ 843.904695] Lustre: DEBUG MARKER: == sanity-quota test 1i: Quota pools: different limit and usage relations ========================================================== 23:12:42 (1781233962) [ 849.578667] Lustre: DEBUG MARKER: User quota (block hardlimit:200 MB) [ 859.701353] Lustre: DEBUG MARKER: Write... [ 860.768579] Lustre: DEBUG MARKER: Write out of block quota ... [ 885.030604] Lustre: DEBUG MARKER: Write... [ 886.270187] Lustre: DEBUG MARKER: Write out of block quota ... [ 894.419687] LustreError: 7786:0:(qmt_entry.c:552:qmt_adjust_edquot()) $$$ set revoke_time explicitly qmt:lustre-QMT0000 pool:dt-qpool1 id:60000 enforced:1 hard:10240 soft:0 granted:14344 time:0 qunit: 1024 edquot:0 may_rel:0 revoke:0 default:no [ 921.101257] Lustre: DEBUG MARKER: == sanity-quota test 1j: Enable project quota enforcement for root ========================================================== 23:13:59 (1781234039) [ 929.691612] Lustre: DEBUG MARKER: -------------------------------------- [ 930.286204] Lustre: DEBUG MARKER: Project quota (hardlimit: 40 mb, 2048 files) [ 1106.112450] Lustre: DEBUG MARKER: == sanity-quota test 1k: LQA: Block hard limit (normal use and out of quota) ========================================================== 23:17:04 (1781234224) [ 1113.321610] Lustre: DEBUG MARKER: Write... [ 1114.731826] Lustre: DEBUG MARKER: Write out of block quota ... [ 1134.698394] Lustre: DEBUG MARKER: Write... [ 1135.911186] Lustre: DEBUG MARKER: Write out of block quota ... [ 1155.387368] Lustre: DEBUG MARKER: Write... [ 1156.575498] Lustre: DEBUG MARKER: Write out of block quota ... [ 1177.895695] Lustre: DEBUG MARKER: == sanity-quota test 1l: Async writes should not be rejected by quota with root_prj_enable ========================================================== 23:18:16 (1781234296) [ 1198.570706] Lustre: DEBUG MARKER: SKIP: sanity-quota test_2 skipping excluded test 2 [ 1199.298883] Lustre: DEBUG MARKER: == sanity-quota test 3a: Block soft limit (start timer, timer goes off, stop timer) ========================================================== 23:18:37 (1781234317) [ 1231.821302] Lustre: DEBUG MARKER: Write after timer goes off [ 1232.470405] Lustre: DEBUG MARKER: Write after cancel lru locks [ 1294.973385] Lustre: DEBUG MARKER: Write after timer goes off [ 1295.751490] Lustre: DEBUG MARKER: Write after cancel lru locks [ 1355.006991] Lustre: DEBUG MARKER: Write after timer goes off [ 1355.984230] Lustre: DEBUG MARKER: Write after cancel lru locks [ 1400.773157] Lustre: DEBUG MARKER: == sanity-quota test 3b: Quota pools: Block soft limit (start timer, expires, stop timer) ========================================================== 23:21:58 (1781234518) [ 1439.720526] Lustre: DEBUG MARKER: Write after timer goes off [ 1440.838364] Lustre: DEBUG MARKER: Write after cancel lru locks [ 1497.315368] Lustre: DEBUG MARKER: Write after timer goes off [ 1498.191101] Lustre: DEBUG MARKER: Write after cancel lru locks [ 1550.096611] Lustre: DEBUG MARKER: Write after timer goes off [ 1551.423760] Lustre: DEBUG MARKER: Write after cancel lru locks [ 1607.630366] Lustre: DEBUG MARKER: == sanity-quota test 3c: Quota pools: check block soft limit on different pools ========================================================== 23:25:25 (1781234725) [ 1652.543706] Lustre: DEBUG MARKER: Write after timer goes off [ 1653.757289] Lustre: DEBUG MARKER: Write after cancel lru locks [ 1704.279981] Lustre: DEBUG MARKER: SKIP: sanity-quota test_4a skipping excluded test 4a [ 1705.180371] Lustre: DEBUG MARKER: == sanity-quota test 4b: Grace time strings handling ===== 23:27:03 (1781234823) [ 1709.954114] Lustre: DEBUG MARKER: == sanity-quota test 5: Chown [ 1772.155061] Lustre: DEBUG MARKER: == sanity-quota test 6: Test dropping acquire request on master ========================================================== 23:28:10 (1781234890) [ 1796.064268] Lustre: *** cfs_fail_loc=513, val=601*** [ 1796.066569] Lustre: Skipped 9 previous similar messages [ 1796.785286] Lustre: *** cfs_fail_loc=513, val=601*** [ 1796.787691] Lustre: Skipped 5 previous similar messages [ 1797.030743] LustreError: 76074:0:(service.c:2344:ptlrpc_server_handle_req_in()) drop incoming rpc opc 601, x1867758353889280 [ 1799.135532] Lustre: *** cfs_fail_loc=513, val=601*** [ 1799.140160] Lustre: Skipped 17 previous similar messages [ 1801.184422] Lustre: *** cfs_fail_loc=513, val=601*** [ 1801.186715] Lustre: Skipped 15 previous similar messages [ 1805.281200] Lustre: *** cfs_fail_loc=513, val=601*** [ 1805.282984] Lustre: Skipped 5 previous similar messages [ 1812.447363] Lustre: 43470:0:(service.c:1615:ptlrpc_at_send_early_reply()) @@@ Could not add any time (5/5), not sending early reply req@ffff938a4445cb40 x1867758349062528/t0(0) o4->6c55f9ca-d72d-4b78-b7b1-c36e45fe8e0b@192.168.206.18@tcp:430/0 lens 488/448 e 1 to 0 dl 1781234935 ref 2 fl Interpret:/600/0 rc 0/0 job:'dd.60000' uid:60000 gid:60000 projid:0 [ 1813.471767] Lustre: 43469:0:(client.c:2480:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1781234915/real 1781234915] req@ffff938b69a34780 x1867758353889280/t0(0) o601->lustre-MDT0000-lwp-OST0000@0@lo:23/10 lens 336/336 e 0 to 1 dl 1781234931 ref 2 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'ll_ost_io00_004.0' uid:0 gid:0 projid:4294967295 [ 1813.487222] 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 [ 1813.495361] Lustre: *** cfs_fail_loc=513, val=601*** [ 1813.498946] Lustre: Skipped 48 previous similar messages [ 1813.499646] Lustre: lustre-MDT0000: Client lustre-MDT0000-lwp-OST0000_UUID (at 0@lo) reconnecting [ 1813.508585] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 1813.533822] LustreError: 6485:0:(service.c:2344:ptlrpc_server_handle_req_in()) drop incoming rpc opc 601, x1867758353898112 [ 1829.855258] Lustre: 3632:0:(client.c:2480:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1781234931/real 1781234931] req@ffff938a445a0780 x1867758353898112/t0(0) o601->lustre-MDT0000-lwp-OST0000@0@lo:23/10 lens 336/336 e 0 to 1 dl 1781234947 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'ll_ost_io00_008.0' uid:0 gid:0 projid:4294967295 [ 1829.855796] Lustre: *** cfs_fail_loc=513, val=601*** [ 1829.875655] 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 [ 1829.878447] Lustre: Skipped 73 previous similar messages [ 1829.893929] Lustre: lustre-MDT0000: Client lustre-MDT0000-lwp-OST0000_UUID (at 0@lo) reconnecting [ 1829.898452] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 1831.905157] LustreError: 16280:0:(service.c:2344:ptlrpc_server_handle_req_in()) drop incoming rpc opc 601, x1867758353907840 [ 1831.914128] LustreError: 16280:0:(service.c:2344:ptlrpc_server_handle_req_in()) Skipped 2 previous similar messages [ 1847.263502] Lustre: 3632:0:(client.c:2480:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1781234949/real 1781234949] req@ffff938b7fa2e1c0 x1867758353907712/t0(0) o601->lustre-MDT0000-lwp-MDT0001@0@lo:23/10 lens 336/336 e 0 to 1 dl 1781234965 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'lquota_wb_lustr.0' uid:0 gid:0 projid:4294967295 [ 1847.267618] 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 [ 1847.280031] Lustre: 3632:0:(client.c:2480:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 1847.302347] Lustre: lustre-MDT0000: Received new LWP connection from 0@lo, keep former export from same NID [ 1847.307481] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1848.804981] Lustre: lustre-MDT0000: Client lustre-MDT0000-lwp-OST0000_UUID (at 0@lo) reconnecting [ 1874.182815] Lustre: DEBUG MARKER: == sanity-quota test 7a: Quota reintegration (global index) ========================================================== 23:29:52 (1781234992) [ 1887.883921] Lustre: Failing over lustre-OST0000 [ 1887.957751] Lustre: server umount lustre-OST0000 complete [ 1888.223683] LustreError: lustre-OST0000-osc-MDT0001: operation ost_statfs to node 0@lo failed: rc = -107 [ 1888.227282] 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 [ 1888.233051] Lustre: Skipped 1 previous similar message [ 1893.580125] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 1893.705805] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [ 1893.715864] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 1893.765371] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 1895.664135] Lustre: lustre-OST0000: Recovery over after 0:02, of 3 clients 3 recovered and 0 were evicted. [ 1895.664465] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 1895.670752] Lustre: Skipped 1 previous similar message [ 1896.275166] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1899.491558] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 1901.754231] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 1904.122619] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 1906.195559] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 1908.421355] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 1910.573282] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 1927.293717] Lustre: Failing over lustre-OST0000 [ 1927.355205] Lustre: server umount lustre-OST0000 complete [ 1929.619716] LustreError: 43756:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.206.18@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1929.627253] LustreError: 43756:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 6 previous similar messages [ 1929.698500] 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 [ 1929.714943] Lustre: Skipped 2 previous similar messages [ 1931.314924] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 1931.517284] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [ 1931.534174] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 1933.090619] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 1933.342258] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 1933.342277] Lustre: lustre-OST0000: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [ 1933.345956] Lustre: Skipped 1 previous similar message [ 1934.145499] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1937.707612] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 1940.144258] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 1943.006034] hrtimer: interrupt took 9025132 ns [ 1943.269893] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 1946.442353] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 1949.183259] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 1951.677946] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 1968.061675] Lustre: DEBUG MARKER: == sanity-quota test 7b: Quota reintegration (slave index) ========================================================== 23:31:26 (1781235086) [ 1983.793663] Lustre: *** cfs_fail_loc=a02, val=0*** [ 1986.775386] LustreError: 3632:0:(qsd_handler.c:298:qsd_req_completion()) $$$ DQACQ failed with -5, flags:0x8 qsd:lustre-OST0000 qtype:usr lqe: ffff938a45124300 id:60000 enforced:1 granted: 1024 pending:0 waiting:0 req:1 usage: 2048 qunit:0 qtune:0 edquot:0 default:no revoke:0 [ 1986.791756] Lustre: Failing over lustre-OST0000 [ 1986.832921] Lustre: server umount lustre-OST0000 complete [ 1988.074047] 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 [ 1988.076912] LustreError: 43474:0:(ldlm_lib.c:1179: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. [ 1988.082377] Lustre: Skipped 1 previous similar message [ 1988.103633] LustreError: 43474:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 3 previous similar messages [ 1990.862464] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 1991.050962] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [ 1991.066459] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 1992.355092] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 1992.640291] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 1992.640411] Lustre: lustre-OST0000: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [ 1992.648415] Lustre: Skipped 1 previous similar message [ 1993.724242] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1997.054178] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 1999.361074] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 2002.108777] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 2005.333885] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 2008.518627] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 2011.449576] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 2034.609250] Lustre: DEBUG MARKER: == sanity-quota test 7c: Quota reintegration (restart mds during reintegration) ========================================================== 23:32:32 (1781235152) [ 2047.136966] LustreError: 102388:0:(qsd_reint.c:482:qsd_reint_main()) cfs_fail_timeout id a03 sleeping for 10000ms [ 2048.118639] Lustre: Failing over lustre-MDT0000 [ 2048.547629] Lustre: server umount lustre-MDT0000 complete [ 2050.248048] LustreError: 102389:0:(qsd_reint.c:482:qsd_reint_main()) cfs_fail_timeout interrupted [ 2050.255256] LustreError: lustre-MDT0000-lwp-OST0000: operation dt_index_read to node 0@lo failed: rc = -107 [ 2050.263524] LustreError: Skipped 1 previous similar message [ 2050.268547] 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 [ 2050.278779] LustreError: 6484:0:(ldlm_lib.c:1179: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. [ 2052.512090] LustreError: 28223:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.206.18@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 2052.529282] LustreError: 28223:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 2 previous similar messages [ 2054.318971] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2054.413348] LustreError: MGC192.168.206.118@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2054.600338] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 2054.631450] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 2056.886449] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2057.605579] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 2059.750194] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 2059.756074] Lustre: Skipped 1 previous similar message [ 2059.759374] LustreError: 3630:0:(ldlm_resource.c:1180:ldlm_resource_complain()) lustre-MDT0000-lwp-OST0001: namespace resource [0x200000006:0x2020000:0x0].0x0 (ffff938a41b7b600) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 2059.798956] Lustre: 102393:0:(qsd_reint.c:245:qsd_reint_index()) lustre-OST0001: index version for fid [0x200000005:0x100c:0x0] is 0, but index isn't empty (1) [ 2059.800371] Lustre: lustre-MDT0000: Recovery over after 0:02, of 2 clients 2 recovered and 0 were evicted. [ 2059.825701] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:115 to 0x2c0000401:161) [ 2059.831421] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:149 to 0x280000401:193) [ 2060.475197] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 2170.858509] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 2173.278713] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 2175.534181] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 2177.793409] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 2180.098177] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 2193.192463] Lustre: DEBUG MARKER: == sanity-quota test 7d: Quota reintegration (Transfer index in multiple bulks) ========================================================== 23:35:11 (1781235311) [ 2205.615860] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 2207.979140] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 2228.868754] Lustre: DEBUG MARKER: == sanity-quota test 7e: Quota reintegration (inode limits) ========================================================== 23:35:47 (1781235347) [ 2243.439576] Lustre: Failing over lustre-MDT0001 [ 2243.550910] Lustre: server umount lustre-MDT0001 complete [ 2244.065847] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 2244.067293] Lustre: lustre-MDT0001-lwp-OST0000: Connection to lustre-MDT0001 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 2244.071519] LustreError: Skipped 2 previous similar messages [ 2244.081463] Lustre: Skipped 3 previous similar messages [ 2244.083193] LustreError: 15472:0:(ldlm_lib.c:1179: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. [ 2244.100281] LustreError: 15472:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 6 previous similar messages [ 2250.964390] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2251.190939] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 2251.231314] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 2252.168335] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 2252.969769] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2256.356503] Lustre: lustre-MDT0001-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 2256.360484] Lustre: Skipped 3 previous similar messages [ 2256.371537] Lustre: lustre-MDT0001: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 2256.392081] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:33) [ 2256.477293] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 2258.754267] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0001.recovery_status 1475 [ 2261.307820] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 2263.365075] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0001.recovery_status 1475 [ 2265.339058] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 2267.177800] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0001.recovery_status 1475 [ 2307.881886] Lustre: Failing over lustre-MDT0001 [ 2307.995390] Lustre: server umount lustre-MDT0001 complete [ 2308.503424] LustreError: 6483:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0001: not available for connect from 192.168.206.18@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 2308.514406] LustreError: 6483:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 4 previous similar messages [ 2311.937843] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2312.098490] Lustre: lustre-MDT0001-lwp-OST0000: Connection to lustre-MDT0001 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 2312.106283] Lustre: Skipped 4 previous similar messages [ 2312.209627] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 2312.248224] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 2313.236655] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 2313.942851] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2317.292166] Lustre: lustre-MDT0001: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 2317.320204] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:65) [ 2317.367078] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 2319.655737] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0001.recovery_status 1475 [ 2322.036181] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 2324.412587] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0001.recovery_status 1475 [ 2326.818645] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 2329.144599] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0001.recovery_status 1475 [ 2375.066447] Lustre: DEBUG MARKER: == sanity-quota test 7f: Quota reintegration automatically ========================================================== 23:38:13 (1781235493) [ 2382.002643] Lustre: *** cfs_fail_loc=a11, val=0*** [ 2382.005768] Lustre: Skipped 3 previous similar messages [ 2387.569627] Lustre: *** cfs_fail_loc=a11, val=0*** [ 2428.932405] Lustre: DEBUG MARKER: == sanity-quota test 8: Run dbench with quota enabled ==== 23:39:07 (1781235547) [ 2442.500124] LustreError: 3633:0:(qsd_reint.c:627:qqi_reint_delayed()) lustre-MDT0000: Delaying reintegration for qtype:0 until pending updates are flushed. [ 2442.506091] LustreError: 3633:0:(qsd_reint.c:627:qqi_reint_delayed()) Skipped 8 previous similar messages [ 2499.576329] Lustre: 121888:0:(qsd_reint.c:245:qsd_reint_index()) lustre-MDT0001: index version for fid [0x200000005:0x1004:0x0] is 0, but index isn't empty (1) [ 2598.479205] Lustre: DEBUG MARKER: == sanity-quota test 9: Block limit larger than 4GB (b10707) ========================================================== 23:41:56 (1781235716) [ 2599.148972] Lustre: DEBUG MARKER: OST0_SIZE: 3601412 required: 4900000 [ 2601.636355] Lustre: DEBUG MARKER: == sanity-quota test 10: Test quota for root user ======== 23:42:00 (1781235720) [ 2625.116161] Lustre: DEBUG MARKER: == sanity-quota test 11: Chown/chgrp ignores quota ======= 23:42:23 (1781235743) [ 2650.741377] Lustre: DEBUG MARKER: == sanity-quota test 12a: Block quota rebalancing ======== 23:42:48 (1781235768) [ 2691.431974] Lustre: DEBUG MARKER: == sanity-quota test 12b: Inode quota rebalancing ======== 23:43:29 (1781235809) [ 2764.549978] Lustre: DEBUG MARKER: == sanity-quota test 13: Cancel per-ID lock in the LRU list ========================================================== 23:44:42 (1781235882) [ 2796.848389] Lustre: DEBUG MARKER: == sanity-quota test 14: check panic in qmt_site_recalc_cb ========================================================== 23:45:15 (1781235915) [ 2809.428223] Lustre: Failing over lustre-OST0000 [ 2809.525800] Lustre: server umount lustre-OST0000 complete [ 2812.896697] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 2812.900863] 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 [ 2812.906616] LustreError: 43757:0:(ldlm_lib.c:1179: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. [ 2816.806848] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2816.986279] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [ 2816.997889] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 2818.122710] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 2818.238590] Lustre: lustre-OST0000-osc-MDT0001: Connection restored to 0@lo (at 0@lo) [ 2818.240201] Lustre: lustre-OST0000: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [ 2818.241795] Lustre: Skipped 5 previous similar messages [ 2819.728888] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2843.608711] Lustre: DEBUG MARKER: == sanity-quota test 15: Set over 4T block quota ========= 23:46:01 (1781235961) [ 2856.236260] Lustre: DEBUG MARKER: == sanity-quota test 16a: lfs quota should skip the inactive MDT/OST ========================================================== 23:46:14 (1781235974) [ 2864.731488] Lustre: lustre-MDT0001: Client 6c55f9ca-d72d-4b78-b7b1-c36e45fe8e0b (at 192.168.206.18@tcp) reconnecting [ 2878.157459] Lustre: DEBUG MARKER: == sanity-quota test 16b: lfs quota should skip the nonexistent MDT/OST ========================================================== 23:46:36 (1781235996) [ 2878.836116] Lustre: DEBUG MARKER: SKIP: sanity-quota test_16b needs >= 3 MDTs [ 2879.618623] Lustre: DEBUG MARKER: == sanity-quota test 17: DQACQ return recoverable error == 23:46:37 (1781235997) [ 2889.863076] Lustre: *** cfs_fail_loc=a04, val=37*** [ 2889.865718] LustreError: 121878:0:(qsd_handler.c:298:qsd_req_completion()) $$$ DQACQ failed with -37, flags:0x1 qsd:lustre-OST0001 qtype:usr lqe: ffff938b7abb0780 id:60000 enforced:1 granted: 0 pending:0 waiting:1056 req:1 usage: 0 qunit:0 qtune:0 edquot:0 default:no revoke:0 [ 2890.894174] Lustre: *** cfs_fail_loc=a04, val=37*** [ 2890.896650] LustreError: 43470:0:(qsd_handler.c:298:qsd_req_completion()) $$$ DQACQ failed with -37, flags:0x1 qsd:lustre-OST0001 qtype:usr lqe: ffff938b7abb0780 id:60000 enforced:1 granted: 0 pending:0 waiting:1056 req:1 usage: 0 qunit:0 qtune:0 edquot:0 default:no revoke:0 [ 2918.273129] Lustre: *** cfs_fail_loc=a04, val=11*** [ 2946.860205] Lustre: *** cfs_fail_loc=a04, val=110*** [ 2946.865995] Lustre: Skipped 1 previous similar message [ 2981.187834] Lustre: *** cfs_fail_loc=a04, val=107*** [ 2981.189754] Lustre: Skipped 1 previous similar message [ 3021.187969] Lustre: DEBUG MARKER: == sanity-quota test 18: MDS failover while writing, no watchdog triggered (b14840) ========================================================== 23:48:59 (1781236139) [ 3027.604871] Lustre: DEBUG MARKER: User quota (limit: 200) [ 3030.405587] Lustre: DEBUG MARKER: Write 100M (buffered) ... [ 3033.910514] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3034.623485] Lustre: DEBUG MARKER: Fail mds for 40 seconds [ 3035.435961] Lustre: Failing over lustre-MDT0000 [ 3035.818989] Lustre: server umount lustre-MDT0000 complete [ 3036.296418] LustreError: lustre-MDT0000-lwp-OST0000: operation quota_acquire to node 0@lo failed: rc = -107 [ 3036.300851] LustreError: Skipped 1 previous similar message [ 3036.303679] LustreError: 6483:0:(ldlm_lib.c:1179: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. [ 3036.311050] LustreError: 6483:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 3 previous similar messages [ 3051.387891] LDISKFS-fs (dm-0): 7 truncates cleaned up [ 3051.389929] LDISKFS-fs (dm-0): recovery complete [ 3051.400627] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3051.505379] LustreError: MGC192.168.206.118@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3051.639534] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3051.690471] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 3053.358803] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3054.981972] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 3057.122995] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 3057.125937] Lustre: Skipped 1 previous similar message [ 3057.151625] Lustre: lustre-MDT0000: Recovery over after 0:03, of 2 clients 2 recovered and 0 were evicted. [ 3057.175127] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1320 to 0x280000401:1345) [ 3057.175128] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1283 to 0x2c0000401:1313) [ 3058.565636] Lustre: DEBUG MARKER: oleg618-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3059.236239] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3066.033630] Lustre: DEBUG MARKER: (dd_pid=132873, time=4, timeout=600) [ 3081.804676] Lustre: DEBUG MARKER: User quota (limit: 200) [ 3084.247767] Lustre: DEBUG MARKER: Write 100M (directio) ... [ 3087.680312] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3088.481395] Lustre: DEBUG MARKER: Fail mds for 40 seconds [ 3089.356626] Lustre: Failing over lustre-MDT0000 [ 3089.375834] LustreError: lustre-MDT0000-lwp-MDT0001: operation quota_acquire to node 0@lo failed: rc = -107 [ 3089.375916] 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 [ 3089.382823] LustreError: Skipped 1 previous similar message [ 3089.383831] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3089.391638] Lustre: Skipped 6 previous similar messages [ 3089.400164] Lustre: Skipped 1 previous similar message [ 3089.610409] Lustre: server umount lustre-MDT0000 complete [ 3101.061772] LustreError: 15472:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.206.18@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3101.069652] LustreError: 15472:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 25 previous similar messages [ 3104.659088] LDISKFS-fs (dm-0): 3 truncates cleaned up [ 3104.660868] LDISKFS-fs (dm-0): recovery complete [ 3104.664098] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3104.720521] LustreError: MGC192.168.206.118@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3104.816031] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3106.645335] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3109.918851] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1347 to 0x280000401:1377) [ 3109.918937] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1283 to 0x2c0000401:1345) [ 3111.706494] Lustre: DEBUG MARKER: oleg618-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3112.456516] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3115.383499] Lustre: DEBUG MARKER: (dd_pid=135373, time=0, timeout=600) [ 3137.578267] Lustre: DEBUG MARKER: == sanity-quota test 19: Updating admin limits doesn't zero operational limits(b14790) ========================================================== 23:50:55 (1781236255) [ 3161.316951] Lustre: DEBUG MARKER: == sanity-quota test 20: Test if setquota specifiers work properly (b15754) ========================================================== 23:51:19 (1781236279) [ 3172.765269] Lustre: DEBUG MARKER: == sanity-quota test 21: Setquota while writing [ 3177.435292] Lustre: DEBUG MARKER: Set limit(block:10G; file:1000000) for user: quota_usr [ 3178.158895] Lustre: DEBUG MARKER: Set limit(block:10G; file:1000000) for group: quota_usr [ 3178.875764] Lustre: DEBUG MARKER: Set limit(block:10G; file:) for project: 1000 [ 3179.573270] Lustre: DEBUG MARKER: Set quota for 1 times [ 3181.307963] Lustre: DEBUG MARKER: Set quota for 2 times [ 3183.136627] Lustre: DEBUG MARKER: Set quota for 3 times [ 3185.059915] Lustre: DEBUG MARKER: Set quota for 4 times [ 3187.087305] Lustre: DEBUG MARKER: Set quota for 5 times [ 3189.042645] Lustre: DEBUG MARKER: Set quota for 6 times [ 3190.911706] Lustre: DEBUG MARKER: Set quota for 7 times [ 3192.744128] Lustre: DEBUG MARKER: Set quota for 8 times [ 3194.626530] Lustre: DEBUG MARKER: Set quota for 9 times [ 3196.422813] Lustre: DEBUG MARKER: Set quota for 10 times [ 3198.200854] Lustre: DEBUG MARKER: Set quota for 11 times [ 3200.034462] Lustre: DEBUG MARKER: Set quota for 12 times [ 3201.936054] Lustre: DEBUG MARKER: Set quota for 13 times [ 3203.778678] Lustre: DEBUG MARKER: Set quota for 14 times [ 3205.589284] Lustre: DEBUG MARKER: Set quota for 15 times [ 3207.463716] Lustre: DEBUG MARKER: Set quota for 16 times [ 3228.638668] Lustre: DEBUG MARKER: == sanity-quota test 22: enable/disable quota by 'lctl conf_param/set_param -P' ========================================================== 23:52:26 (1781236346) [ 3237.857391] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3237.858148] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3237.865553] LustreError: Skipped 1 previous similar message [ 3237.872853] Lustre: Skipped 3 previous similar messages [ 3242.792786] Lustre: server umount lustre-MDT0000 complete [ 3242.976073] LustreError: 6487:0:(ldlm_lib.c:1179: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. [ 3242.988604] LustreError: 6487:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 7 previous similar messages [ 3244.519856] LustreError: 6467:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1781236362 with bad export cookie 18263944364393901661 [ 3244.521111] LustreError: MGC192.168.206.118@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3244.524806] LustreError: 6467:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 3244.645930] Lustre: server umount lustre-MDT0001 complete [ 3256.334343] Lustre: server umount lustre-OST0000 complete [ 3267.081276] Lustre: server umount lustre-OST0001 complete [ 3272.560977] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing load_modules_local [ 3276.645141] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3276.834403] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3278.267826] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3281.513876] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3281.676840] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 3283.078968] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3284.231504] Lustre: 161930:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3286.800549] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3286.944864] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 3289.101888] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3292.287251] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3294.652255] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3297.765113] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:97) [ 3301.860688] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1347 to 0x2c0000401:1377) [ 3301.862192] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1380 to 0x280000401:1409) [ 3309.055536] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3310.737305] Lustre: 163792:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 3322.339917] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3322.342279] Lustre: Skipped 2 previous similar messages [ 3327.456641] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3327.462722] Lustre: Skipped 3 previous similar messages [ 3327.722819] Lustre: server umount lustre-MDT0000 complete [ 3329.577383] LustreError: 161542:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1781236447 with bad export cookie 18263944364393911118 [ 3329.579674] LustreError: MGC192.168.206.118@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3329.586956] LustreError: 161542:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 3329.763393] Lustre: server umount lustre-MDT0001 complete [ 3341.832601] Lustre: server umount lustre-OST0000 complete [ 3353.704457] Lustre: server umount lustre-OST0001 complete [ 3360.257457] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing load_modules_local [ 3364.412523] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3364.621818] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3364.624625] Lustre: Skipped 1 previous similar message [ 3366.269353] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3369.747437] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3371.502805] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3372.741094] Lustre: 167574:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3375.810819] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3378.520471] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3382.210698] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3382.323548] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 3382.326849] Lustre: Skipped 2 previous similar messages [ 3384.687427] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3387.370062] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:129) [ 3389.414584] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1347 to 0x2c0000401:1409) [ 3389.415747] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1380 to 0x280000401:1441) [ 3393.525332] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3395.055077] Lustre: 169409:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 3399.355111] Lustre: DEBUG MARKER: == sanity-quota test 23: Quota should be honored with directIO (b16125) ========================================================== 23:55:17 (1781236517) [ 3400.069752] Lustre: DEBUG MARKER: OST0_SIZE: 3605396 required: 6144 [ 3400.655379] Lustre: DEBUG MARKER: run for 4MB test file [ 3406.589832] Lustre: DEBUG MARKER: User quota (limit: 4 MB) [ 3408.954784] Lustre: DEBUG MARKER: Step1: trigger EDQUOT with O_DIRECT [ 3409.611530] Lustre: DEBUG MARKER: Write half of file [ 3410.371390] Lustre: DEBUG MARKER: Write out of block quota ... [ 3411.035879] Lustre: DEBUG MARKER: Step1: done [ 3411.614682] Lustre: DEBUG MARKER: Step2: rewrite should succeed [ 3412.274490] Lustre: DEBUG MARKER: Step2: done [ 3426.440751] Lustre: DEBUG MARKER: OST0_SIZE: 3605396 required: 61440 [ 3427.142735] Lustre: DEBUG MARKER: run for 40MB test file [ 3432.062555] Lustre: DEBUG MARKER: User quota (limit: 40 MB) [ 3434.482605] Lustre: DEBUG MARKER: Step1: trigger EDQUOT with O_DIRECT [ 3435.134412] Lustre: DEBUG MARKER: Write half of file [ 3436.353511] Lustre: DEBUG MARKER: Write out of block quota ... [ 3437.450709] Lustre: DEBUG MARKER: Step1: done [ 3438.061380] Lustre: DEBUG MARKER: Step2: rewrite should succeed [ 3438.707846] Lustre: DEBUG MARKER: Step2: done [ 3463.471357] Lustre: DEBUG MARKER: == sanity-quota test 24: lfs draws an asterix when limit is reached (b16646) ========================================================== 23:56:21 (1781236581) [ 3486.776974] Lustre: DEBUG MARKER: == sanity-quota test 25: check indexes versions ========== 23:56:45 (1781236605) [ 3504.221866] Lustre: DEBUG MARKER: Write... [ 3505.106711] Lustre: DEBUG MARKER: Write out of block quota ... [ 3538.856355] Lustre: DEBUG MARKER: == sanity-quota test 27a: lfs quota/setquota should handle wrong arguments (b19612) ========================================================== 23:57:37 (1781236657) [ 3541.793337] Lustre: DEBUG MARKER: == sanity-quota test 27b: lfs quota/setquota should handle user/group/project ID (b20200) ========================================================== 23:57:40 (1781236660) [ 3547.110420] Lustre: DEBUG MARKER: == sanity-quota test 27c: lfs quota should support human-readable output ========================================================== 23:57:45 (1781236665) [ 3551.236386] Lustre: DEBUG MARKER: == sanity-quota test 27d: lfs setquota should support fraction block limit ========================================================== 23:57:49 (1781236669) [ 3555.786736] Lustre: DEBUG MARKER: == sanity-quota test 30: Hard limit updates should not reset grace times ========================================================== 23:57:53 (1781236673) [ 3584.854212] Lustre: DEBUG MARKER: == sanity-quota test 33: Basic usage tracking for user [ 3640.560475] Lustre: DEBUG MARKER: == sanity-quota test 34: Usage transfer for user [ 3722.357529] Lustre: DEBUG MARKER: == sanity-quota test 35: Usage is still accessible across reboot ========================================================== 00:00:40 (1781236840) [ 3747.831242] Lustre: DEBUG MARKER: Restart... [ 3752.929440] 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 [ 3752.931982] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3752.936673] Lustre: Skipped 12 previous similar messages [ 3752.940191] Lustre: Skipped 1 previous similar message [ 3755.293668] Lustre: server umount lustre-MDT0000 complete [ 3756.933758] LustreError: 166448:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1781236874 with bad export cookie 18263944364393913421 [ 3756.936072] LustreError: MGC192.168.206.118@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3756.943849] LustreError: 166448:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 3 previous similar messages [ 3757.082786] Lustre: server umount lustre-MDT0001 complete [ 3768.902051] Lustre: server umount lustre-OST0000 complete [ 3780.577438] Lustre: server umount lustre-OST0001 complete [ 3786.412855] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing load_modules_local [ 3790.414870] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3790.615877] LustreError: 193729:0:(ldlm_lib.c:1179: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. [ 3790.623711] LustreError: 193729:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 4 previous similar messages [ 3790.664699] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3792.356267] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3796.352066] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3798.144120] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3799.250206] Lustre: 194835:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3801.950217] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3804.376829] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3808.093838] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3810.414261] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3813.347399] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:161) [ 3815.397444] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:1452 to 0x280000401:1473) [ 3815.397467] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:1418 to 0x2c0000401:1441) [ 3819.046449] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3820.428995] Lustre: 196673:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 3852.023816] Lustre: DEBUG MARKER: == sanity-quota test 37: Quota accounted properly for file created by 'lfs setstripe' ========================================================== 00:02:50 (1781236970) [ 3887.212724] Lustre: DEBUG MARKER: == sanity-quota test 38: Quota accounting iterator doesn't skip id entries ========================================================== 00:03:25 (1781237005) [ 4588.904105] Lustre: DEBUG MARKER: == sanity-quota test 39: Project ID interface works correctly ========================================================== 00:15:07 (1781237707) [ 4593.634694] 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 [ 4593.636586] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4593.643069] Lustre: Skipped 2 previous similar messages [ 4593.648879] Lustre: Skipped 3 previous similar messages [ 4598.609109] Lustre: server umount lustre-MDT0000 complete [ 4598.754078] LustreError: 196438:0:(ldlm_lib.c:1179: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. [ 4598.761986] LustreError: 196438:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 5 previous similar messages [ 4600.273460] LustreError: 193709:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1781237718 with bad export cookie 18263944364393922164 [ 4600.277620] LustreError: MGC192.168.206.118@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4600.278958] LustreError: 193709:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 4600.419646] Lustre: server umount lustre-MDT0001 complete [ 4612.120931] Lustre: server umount lustre-OST0000 complete [ 4623.994403] Lustre: server umount lustre-OST0001 complete [ 4630.489229] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing load_modules_local [ 4635.274790] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4635.610860] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4635.614078] Lustre: Skipped 3 previous similar messages [ 4637.457217] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4641.391731] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4643.621092] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4644.930295] Lustre: 205799:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 4647.840168] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4648.005225] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 4648.009819] Lustre: Skipped 1 previous similar message [ 4650.298564] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4654.032647] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4656.503131] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4659.170639] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:193) [ 4660.196238] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:6443 to 0x2c0000401:6465) [ 4660.204709] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:6475 to 0x280000401:6497) [ 4665.243426] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4666.658873] Lustre: 207637:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 4680.755971] Lustre: DEBUG MARKER: == sanity-quota test 40a: Hard link across different project ID ========================================================== 00:16:39 (1781237799) [ 4696.478558] Lustre: DEBUG MARKER: == sanity-quota test 40b: Mv across different project ID ========================================================== 00:16:54 (1781237814) [ 4711.593601] Lustre: DEBUG MARKER: == sanity-quota test 40c: Remote child Dir inherit project quota properly ========================================================== 00:17:09 (1781237829) [ 4732.105722] Lustre: DEBUG MARKER: == sanity-quota test 40d: Stripe Directory inherit project quota properly ========================================================== 00:17:30 (1781237850) [ 4751.681297] Lustre: DEBUG MARKER: == sanity-quota test 41: df should return projid-specific values ========================================================== 00:17:49 (1781237869) [ 4797.116412] Lustre: DEBUG MARKER: == sanity-quota test 42: lfs quota should include default quota info ========================================================== 00:18:35 (1781237915) [ 4811.717308] Lustre: DEBUG MARKER: == sanity-quota test 48: lfs quota --delete should delete quota project ID ========================================================== 00:18:50 (1781237930) [ 4818.338542] LustreError: 206159:0:(qsd_handler.c:298:qsd_req_completion()) $$$ DQACQ failed with -3, flags:0x1 qsd:lustre-OST0000 qtype:usr lqe: ffff938a4cf9f380 id:60000 enforced:1 granted: 0 pending:0 waiting:1032 req:1 usage: 0 qunit:0 qtune:0 edquot:0 default:no revoke:0 [ 4818.355266] LustreError: 206159:0:(qsd_handler.c:772:qsd_op_begin0()) $$$ ID isn't enforced on master, it probably due to a legeal race, if this message is showing up constantly, there could be some inconsistence between master & slave, and quota reintegration needs be re-triggered. qsd:lustre-OST0000 qtype:usr lqe: ffff938a4cf9f380 id:60000 enforced:1 granted: 0 pending:0 waiting:0 req:0 usage: 0 qunit:0 qtune:0 edquot:0 default:no revoke:0 [ 4846.590501] Lustre: DEBUG MARKER: == sanity-quota test 49a: lfs quota -a prints the quota usage for all quota IDs ========================================================== 00:19:24 (1781237964) [ 4849.018797] Lustre: *** cfs_fail_loc=a09, val=0*** [ 4849.020541] Lustre: Skipped 1 previous similar message [ 4850.018992] Lustre: *** cfs_fail_loc=a09, val=0*** [ 4850.020442] Lustre: Skipped 109 previous similar messages [ 4852.019716] Lustre: *** cfs_fail_loc=a09, val=0*** [ 4852.023220] Lustre: Skipped 234 previous similar messages [ 4856.023016] Lustre: *** cfs_fail_loc=a09, val=0*** [ 4856.025360] Lustre: Skipped 448 previous similar messages [ 4864.030785] Lustre: *** cfs_fail_loc=a09, val=0*** [ 4864.033024] Lustre: Skipped 863 previous similar messages [ 4880.030338] Lustre: *** cfs_fail_loc=a09, val=0*** [ 4880.033378] Lustre: Skipped 1416 previous similar messages [ 4912.032684] Lustre: *** cfs_fail_loc=a09, val=0*** [ 4912.036139] Lustre: Skipped 2674 previous similar messages [ 5143.519980] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 5143.524214] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5146.597243] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5146.601766] Lustre: Skipped 3 previous similar messages [ 5148.812996] Lustre: server umount lustre-MDT0000 complete [ 5150.481229] LustreError: 213245:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1781238268 with bad export cookie 18263944364395677491 [ 5150.485484] LustreError: MGC192.168.206.118@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5150.491081] LustreError: 213245:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 5151.714975] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 5151.718126] Lustre: Skipped 1 previous similar message [ 5156.759778] Lustre: server umount lustre-MDT0001 complete [ 5158.881142] Lustre: server umount lustre-OST0000 complete [ 5160.961809] Lustre: server umount lustre-OST0001 complete [ 5164.417930] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_hostid [ 5168.100172] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing load_modules_local [ 5190.183102] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing load_modules_local [ 5194.744301] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5194.850051] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 5194.865192] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 5194.904742] Lustre: lustre-MDT0000: new disk, initializing [ 5194.938710] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 5194.943253] Lustre: Skipped 1 previous similar message [ 5194.951990] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 5196.791606] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5201.955101] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5201.997151] Lustre: 224570:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 5202.013185] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 5202.015015] Lustre: Skipped 1 previous similar message [ 5202.060965] Lustre: lustre-MDT0001: new disk, initializing [ 5202.099170] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 5202.104490] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 5203.725946] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5206.501649] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 5209.803106] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5209.944100] Lustre: lustre-OST0000: new disk, initializing [ 5209.946311] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 5209.949372] Lustre: 226169:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 5211.846293] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 5211.858356] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 5211.903053] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 5212.634865] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5218.831480] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5218.902286] Lustre: lustre-OST0001: new disk, initializing [ 5218.906425] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 5218.912201] Lustre: 227021:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 5220.816113] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 5220.823511] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 5220.852635] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 5222.071919] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5227.654185] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5229.382967] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 5242.901779] Lustre: DEBUG MARKER: == sanity-quota test 49b: lfs quota -a --blocks has a delimiter ========================================================== 00:26:01 (1781238361) [ 5245.972543] Lustre: DEBUG MARKER: == sanity-quota test 50: Test if lfs find --projid works ========================================================== 00:26:04 (1781238364) [ 5262.441838] Lustre: DEBUG MARKER: == sanity-quota test 51: Test project accounting with mv/cp ========================================================== 00:26:20 (1781238380) [ 5288.237857] Lustre: DEBUG MARKER: == sanity-quota test 52: Rename normal file across project ID ========================================================== 00:26:46 (1781238406) [ 5297.528430] Lustre: DEBUG MARKER: rename directory return 255 [ 5319.121992] Lustre: DEBUG MARKER: == sanity-quota test 53: Project inherit attribute could be cleared ========================================================== 00:27:17 (1781238437) [ 5329.661543] Lustre: DEBUG MARKER: == sanity-quota test 54: basic lfs project interface test ========================================================== 00:27:27 (1781238447) [ 5344.620294] Lustre: DEBUG MARKER: == sanity-quota test 55: Chgrp should be affected by group quota ========================================================== 00:27:42 (1781238462) [ 5382.791963] LustreError: 235425:0:(qmt_entry.c:552: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 [ 5400.927283] Lustre: DEBUG MARKER: == sanity-quota test 56: lfs quota -t should work well === 00:28:39 (1781238519) [ 5413.407616] Lustre: DEBUG MARKER: == sanity-quota test 57: lfs project could tolerate errors ========================================================== 00:28:51 (1781238531) [ 5431.321686] Lustre: DEBUG MARKER: == sanity-quota test 58: project ID should be kept for new mirrors created by FID ========================================================== 00:29:09 (1781238549) [ 5491.897149] Lustre: DEBUG MARKER: == sanity-quota test 59: lfs project dosen't crash kernel with project disabled ========================================================== 00:30:10 (1781238610) [ 5494.239875] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 5494.244896] 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 [ 5494.252849] Lustre: Skipped 8 previous similar messages [ 5494.255792] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5494.258171] Lustre: Skipped 2 previous similar messages [ 5499.362781] Lustre: server umount lustre-MDT0000 complete [ 5500.847131] LustreError: 224561:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1781238618 with bad export cookie 18263944364396049590 [ 5500.851661] LustreError: MGC192.168.206.118@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5500.851705] LustreError: 224561:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 5500.998698] Lustre: server umount lustre-MDT0001 complete [ 5512.781581] Lustre: server umount lustre-OST0000 complete [ 5524.548045] Lustre: server umount lustre-OST0001 complete [ 5532.361185] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing load_modules_local [ 5536.633254] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5536.830146] LustreError: 244357:0:(ldlm_lib.c:1179: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. [ 5536.839287] LustreError: 244357:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 7 previous similar messages [ 5536.868093] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 5536.871238] Lustre: Skipped 3 previous similar messages [ 5536.876433] 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 [ 5538.597427] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5542.149087] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5542.272213] 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 [ 5543.782746] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5544.881259] Lustre: 245466:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 5547.411261] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5547.531706] 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 [ 5549.737722] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5553.417550] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5553.503316] 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 [ 5555.925989] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5561.827538] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:20 to 0x2c0000401:65) [ 5561.832401] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:20 to 0x280000401:65) [ 5564.762507] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5566.226054] Lustre: 247303:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 5569.126530] LustreError: 244354:0:(osd_handler.c:3426:osd_quota_transfer()) lustre-MDT0000: quota transfer failed. Is project enforcement enabled on the ldiskfs filesystem? rc = -95 [ 5572.067966] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5572.071494] Lustre: Skipped 6 previous similar messages [ 5576.740644] Lustre: server umount lustre-MDT0000 complete [ 5578.569791] LustreError: 247306:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1781238696 with bad export cookie 18263944364396098275 [ 5578.570229] LustreError: MGC192.168.206.118@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5578.575177] LustreError: 247306:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 3 previous similar messages [ 5578.717101] Lustre: server umount lustre-MDT0001 complete [ 5590.538593] Lustre: server umount lustre-OST0000 complete [ 5602.526547] Lustre: server umount lustre-OST0001 complete [ 5610.701115] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing load_modules_local [ 5615.117800] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5615.345241] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 5615.347929] Lustre: Skipped 3 previous similar messages [ 5617.026300] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5620.726472] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5622.424992] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5623.674432] Lustre: 250783:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 5626.442672] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5629.099264] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5633.052421] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5635.922891] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5640.678884] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:67 to 0x2c0000401:97) [ 5640.679057] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:20 to 0x280000401:97) [ 5645.079797] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5667.425766] Lustre: DEBUG MARKER: == sanity-quota test 60: Test quota for root with setgid ========================================================== 00:33:05 (1781238785) [ 5691.981394] Lustre: DEBUG MARKER: SKIP: sanity-quota test_61 skipping SLOW test 61 [ 5692.681801] Lustre: DEBUG MARKER: == sanity-quota test 62: Project inherit should be only changed by root ========================================================== 00:33:31 (1781238811) [ 5701.454919] Lustre: DEBUG MARKER: SKIP: sanity-quota test_63 skipping excluded test 63 [ 5702.140712] Lustre: DEBUG MARKER: == sanity-quota test 64: lfs project on non-dir/files should succeed ========================================================== 00:33:40 (1781238820) [ 5724.125435] Lustre: DEBUG MARKER: SKIP: sanity-quota test_65 skipping excluded test 65 [ 5724.947935] Lustre: DEBUG MARKER: == sanity-quota test 66: nonroot user can not change project state in default ========================================================== 00:34:03 (1781238843) [ 5743.042001] Lustre: DEBUG MARKER: == sanity-quota test 67: quota pools recalculation ======= 00:34:21 (1781238861) [ 5748.329632] Lustre: DEBUG MARKER: User quota (block hardlimit:20 MB) [ 5750.992564] Lustre: 259556:0:(qsd_reint.c:245:qsd_reint_index()) lustre-OST0000: index version for fid [0x200000005:0x1007:0x0] is 0, but index isn't empty (1) [ 5750.999130] Lustre: 259556:0:(qsd_reint.c:245:qsd_reint_index()) Skipped 1 previous similar message [ 5752.777563] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 5754.779997] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 5756.354797] Lustre: DEBUG MARKER: Write... [ 5767.295499] LustreError: 260865:0:(mgs_handler.c:1140:mgs_iocontrol_pool()) OBD_IOC_POOL err -17, cmd CE021 for pool lustre.qpool1 [ 5771.847187] Lustre: DEBUG MARKER: Write... [ 5777.327525] Lustre: DEBUG MARKER: Write... [ 5825.349772] Lustre: DEBUG MARKER: == sanity-quota test 68: slave number in quota pool changed after each add/remove OST ========================================================== 00:35:43 (1781238943) [ 5837.894313] LustreError: 265214:0:(mgs_handler.c:1140:mgs_iocontrol_pool()) OBD_IOC_POOL err -17, cmd CE021 for pool lustre.qpool1 [ 5860.091042] Lustre: DEBUG MARKER: == sanity-quota test 69: EDQUOT at one of pools shouldn't affect DOM ========================================================== 00:36:18 (1781238978) [ 5873.528981] Lustre: DEBUG MARKER: User quota (block hardlimit:200 MB) [ 5874.225379] Lustre: DEBUG MARKER: User quota (block hardlimit:10 MB) [ 5917.951444] Lustre: DEBUG MARKER: == sanity-quota test 70a: check lfs setquota/quota with a pool option ========================================================== 00:37:16 (1781239036) [ 5942.779664] Lustre: DEBUG MARKER: == sanity-quota test 70b: lfs setquota pool works properly ========================================================== 00:37:41 (1781239061) [ 5965.086211] Lustre: DEBUG MARKER: == sanity-quota test 71a: Check PFL with quota pools ===== 00:38:03 (1781239083) [ 5970.507867] Lustre: DEBUG MARKER: User quota (block hardlimit:100 MB) [ 5983.924456] Lustre: DEBUG MARKER: Write... [ 5984.796713] Lustre: DEBUG MARKER: Write out of block quota ... [ 6040.952208] Lustre: DEBUG MARKER: == sanity-quota test 71b: Check SEL with quota pools ===== 00:39:19 (1781239159) [ 6046.381332] Lustre: DEBUG MARKER: User quota (block hardlimit:1000 MB) [ 6090.989078] Lustre: DEBUG MARKER: == sanity-quota test 72: lfs quota --pool prints only pool's OSTs ========================================================== 00:40:09 (1781239209) [ 6095.757407] Lustre: DEBUG MARKER: User quota (block hardlimit:50 MB) [ 6105.374317] Lustre: DEBUG MARKER: Write... [ 6106.103394] Lustre: DEBUG MARKER: Write out of block quota ... [ 6106.237892] LustreError: 254000:0:(qmt_entry.c:552: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 [ 6138.259065] Lustre: DEBUG MARKER: == sanity-quota test 73a: default limits at OST Pool Quotas ========================================================== 00:40:56 (1781239256) [ 6150.415826] Lustre: DEBUG MARKER: set to use default quota [ 6151.140170] Lustre: DEBUG MARKER: set default quota [ 6151.916583] Lustre: DEBUG MARKER: get default quota [ 6154.762537] Lustre: DEBUG MARKER: Test not out of quota [ 6156.359173] Lustre: DEBUG MARKER: Test out of quota [ 6161.102333] Lustre: DEBUG MARKER: Increase default quota [ 6173.655808] Lustre: DEBUG MARKER: Set quota to override default quota [ 6173.687903] LustreError: 249668:0:(qmt_entry.c:552:qmt_adjust_edquot()) $$$ set revoke_time explicitly qmt:lustre-QMT0000 pool:dt-qpool1 id:60000 enforced:1 hard:20480 soft:20480 granted:45056 time:1781844091 qunit: 1024 edquot:0 may_rel:0 revoke:0 default:no [ 6178.834832] Lustre: DEBUG MARKER: Set to use default quota again [ 6190.499686] Lustre: DEBUG MARKER: Cleanup [ 6223.817164] Lustre: DEBUG MARKER: == sanity-quota test 73b: default OST Pool Quotas limit for new user ========================================================== 00:42:22 (1781239342) [ 6235.846695] Lustre: DEBUG MARKER: set default quota for qpool1 [ 6236.592790] Lustre: DEBUG MARKER: Write from user that hasn't lqe [ 6265.481544] Lustre: DEBUG MARKER: == sanity-quota test 74: check quota pools per user ====== 00:43:03 (1781239383) [ 6305.037050] Lustre: DEBUG MARKER: == sanity-quota test 75: nodemap squashed root respects quota enforcement ========================================================== 00:43:43 (1781239423) [ 6336.163760] Lustre: DEBUG MARKER: Write... [ 6337.420472] Lustre: DEBUG MARKER: Write out of block quota ... [ 6388.704271] Lustre: DEBUG MARKER: == sanity-quota test 76: project ID 4294967295 should be not allowed ========================================================== 00:45:07 (1781239507) [ 6407.951180] Lustre: DEBUG MARKER: == sanity-quota test 77: lfs setquota should fail in Lustre mount with 'ro' ========================================================== 00:45:26 (1781239526) [ 6410.554370] Lustre: DEBUG MARKER: == sanity-quota test 78A: Check fallocate increase quota usage ========================================================== 00:45:28 (1781239528) [ 6428.883906] Lustre: DEBUG MARKER: == sanity-quota test 78a: Check fallocate increase projectid usage ========================================================== 00:45:47 (1781239547) [ 6449.974497] Lustre: DEBUG MARKER: == sanity-quota test 79: access to non-existed dt-pool/info doesn't cause a panic ========================================================== 00:46:08 (1781239568) [ 6460.383908] Lustre: DEBUG MARKER: == sanity-quota test 80: check for EDQUOT after OST failover ========================================================== 00:46:18 (1781239578) [ 6474.838362] Lustre: *** cfs_fail_loc=a06, val=0*** [ 6474.839910] Lustre: Skipped 2249 previous similar messages [ 6474.969085] LustreError: 249686:0:(qmt_lock.c:476:qmt_lvbo_update()) $$$ failed to release quota space on glimpse 0!=1024 : rc = -11 [ 6474.969085] qmt:lustre-QMT0000 pool:dt-0x0 id:60000 enforced:1 hard:102400 soft:0 granted:24576 time:0 qunit: 16384 edquot:0 may_rel:0 revoke:0 default:no [ 6478.648071] Lustre: Failing over lustre-OST0001 [ 6478.697387] Lustre: server umount lustre-OST0001 complete [ 6479.757342] LustreError: 251140:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-OST0001: not available for connect from 192.168.206.18@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 6479.762975] LustreError: 251140:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 8 previous similar messages [ 6480.354058] 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 [ 6480.354593] LustreError: lustre-OST0001-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 6480.358542] Lustre: Skipped 7 previous similar messages [ 6482.034846] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 6482.134085] Lustre: lustre-OST0001: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [ 6482.143609] Lustre: lustre-OST0001: in recovery but waiting for the first client to connect [ 6482.146213] Lustre: Skipped 1 previous similar message [ 6483.490390] Lustre: lustre-OST0001: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 6483.493603] Lustre: Skipped 1 previous similar message [ 6483.856843] Lustre: lustre-OST0001-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 6483.857550] Lustre: lustre-OST0001: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [ 6483.860992] Lustre: Skipped 7 previous similar messages [ 6483.864395] Lustre: Skipped 1 previous similar message [ 6484.226724] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6513.503721] Lustre: DEBUG MARKER: == sanity-quota test 81: Race qmt_start_pool_recalc with qmt_pool_free ========================================================== 00:47:11 (1781239631) [ 6517.819410] Lustre: DEBUG MARKER: User quota (block hardlimit:20 MB) [ 6521.649903] LustreError: 306086:0:(qmt_pool.c:1399:qmt_pool_recalc()) cfs_fail_timeout id a07 sleeping for 10000ms [ 6521.653530] LustreError: 306086:0:(qmt_pool.c:1399:qmt_pool_recalc()) Skipped 5 previous similar messages [ 6525.837530] Lustre: lustre-MDT0000: Not available for connect from 192.168.206.18@tcp (stopping) [ 6527.455710] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 6530.949413] Lustre: lustre-MDT0000: Not available for connect from 192.168.206.18@tcp (stopping) [ 6530.956259] Lustre: Skipped 5 previous similar messages [ 6531.695171] LustreError: 306086:0:(qmt_pool.c:1399:qmt_pool_recalc()) cfs_fail_timeout id a07 awake [ 6531.793710] Lustre: server umount lustre-MDT0000 complete [ 6535.416042] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 6535.489477] LustreError: MGC192.168.206.118@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 6535.633896] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 6535.636965] Lustre: Skipped 3 previous similar messages [ 6535.658670] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:113 to 0x2c0000401:129) [ 6535.660117] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:112 to 0x280000401:129) [ 6537.247711] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6540.770638] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 6540.774166] Lustre: Skipped 1 previous similar message [ 6551.719276] Lustre: DEBUG MARKER: == sanity-quota test 82: verify more than 8 qids for single operation ========================================================== 00:47:50 (1781239670) [ 6554.768157] LustreError: 250405:0:(qsd_reint.c:627:qqi_reint_delayed()) lustre-MDT0001: Delaying reintegration for qtype:2 until pending updates are flushed. [ 6554.774607] LustreError: 250405:0:(qsd_reint.c:627:qqi_reint_delayed()) Skipped 2 previous similar messages [ 6562.685110] Lustre: DEBUG MARKER: == sanity-quota test 83: Setting default quota shouldn't affect grace time ========================================================== 00:48:00 (1781239680) [ 6572.998470] Lustre: DEBUG MARKER: == sanity-quota test 84: Reset quota should fix the insane granted quota ========================================================== 00:48:11 (1781239691) [ 6595.341938] Lustre: *** cfs_fail_loc=a08, val=0*** [ 6595.347218] Lustre: Skipped 7 previous similar messages [ 6595.349787] Lustre: *** cfs_fail_loc=a08, val=0*** [ 6595.349787] Lustre: *** cfs_fail_loc=a08, val=0*** [ 6638.285542] Lustre: DEBUG MARKER: == sanity-quota test 85: do not hung at write with the least_qunit ========================================================== 00:49:16 (1781239756) [ 6650.870654] LustreError: 254000:0:(qmt_entry.c:552: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 [ 6684.866710] Lustre: DEBUG MARKER: == sanity-quota test 86: Pre-acquired quota should be released if quota is over limit ========================================================== 00:50:03 (1781239803) [ 6714.439450] LustreError: 249669:0:(qmt_entry.c:552:qmt_adjust_edquot()) $$$ set revoke_time explicitly qmt:lustre-QMT0000 pool:md-0x0 id:60000 enforced:1 hard:2048 soft:2048 granted:16384 time:1781844632 qunit: 1024 edquot:0 may_rel:0 revoke:0 default:no [ 6783.229660] LustreError: 253557:0:(qmt_entry.c:552:qmt_adjust_edquot()) $$$ set revoke_time explicitly qmt:lustre-QMT0000 pool:md-0x0 id:60000 enforced:1 hard:2048 soft:2048 granted:12352 time:1781844701 qunit: 1024 edquot:0 may_rel:0 revoke:0 default:no [ 6859.407642] LustreError: 253557:0:(qmt_entry.c:552:qmt_adjust_edquot()) $$$ set revoke_time explicitly qmt:lustre-QMT0000 pool:md-0x0 id:1000 enforced:1 hard:2048 soft:2048 granted:16385 time:1781844777 qunit: 1024 edquot:0 may_rel:0 revoke:0 default:no [ 6907.061966] Lustre: DEBUG MARKER: == sanity-quota test 87: lfs quota -a should print default quota setting ========================================================== 00:53:45 (1781240025) [ 6909.642419] Lustre: *** cfs_fail_loc=a09, val=0*** [ 6909.645324] Lustre: Skipped 1 previous similar message [ 6935.010181] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 6935.011544] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 6935.016454] Lustre: Skipped 3 previous similar messages [ 6940.717344] Lustre: server umount lustre-MDT0000 complete [ 6944.102819] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 6944.174434] LustreError: MGC192.168.206.118@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 6944.314173] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 6944.353409] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:132 to 0x280000401:161) [ 6944.361291] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:113 to 0x2c0000401:161) [ 6945.992764] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6949.350911] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 6949.353815] Lustre: Skipped 2 previous similar messages [ 6949.359512] LustreError: lustre-MDT0000-osp-MDT0001: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 6953.529083] Lustre: DEBUG MARKER: == sanity-quota test 88: Writing over quota should not hang ========================================================== 00:54:31 (1781240071) [ 6954.139194] Lustre: DEBUG MARKER: SKIP: sanity-quota test_88 require client with >4k pages [ 6954.867282] Lustre: DEBUG MARKER: == sanity-quota test 89: Show default quota with squash_uid ========================================================== 00:54:33 (1781240073) [ 6962.885983] Lustre: DEBUG MARKER: == sanity-quota test 90a: lfs quota should work without mount point ========================================================== 00:54:41 (1781240081) [ 6968.821171] Lustre: DEBUG MARKER: == sanity-quota test 90b: lfs quota should work with multiple mount points ========================================================== 00:54:47 (1781240087) [ 6976.250269] Lustre: DEBUG MARKER: == sanity-quota test 91: new quota index files in quota_master ========================================================== 00:54:54 (1781240094) [ 6990.307227] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 6990.308221] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 6990.327931] Lustre: Skipped 9 previous similar messages [ 6994.231079] Lustre: server umount lustre-MDT0000 complete [ 6995.729855] LustreError: 249652:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1781240113 with bad export cookie 18263944364397206795 [ 6995.732855] LustreError: MGC192.168.206.118@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 6995.738743] LustreError: 249652:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 6996.959314] LustreError: 3633:0:(client.c:1380:ptlrpc_import_delay_req()) @@@ IMP_CLOSED req@ffff938a4cc2c3c0 x1867758370127744/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 [ 6996.969546] LustreError: 3633:0:(qsd_handler.c:298:qsd_req_completion()) $$$ DQACQ failed with -5, flags:0x8 qsd:lustre-MDT0001 qtype:usr lqe: ffff938a44b19200 id:0 enforced:0 granted: 0 pending:0 waiting:0 req:1 usage: 249 qunit:0 qtune:0 edquot:0 default:no revoke:0 [ 6996.977438] LustreError: 3633:0:(qsd_handler.c:298:qsd_req_completion()) Skipped 6 previous similar messages [ 7010.271116] Lustre: lustre-MDT0001 is waiting for obd_unlinked_exports more than 8 seconds. The obd refcount = 3. Is it stuck? [ 7010.369515] Lustre: server umount lustre-MDT0001 complete [ 7026.143117] Lustre: lustre-OST0000 is waiting for obd_unlinked_exports more than 8 seconds. The obd refcount = 3. Is it stuck? [ 7026.199620] Lustre: server umount lustre-OST0000 complete [ 7034.031484] Lustre: server umount lustre-OST0001 complete [ 7036.568359] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_hostid [ 7039.382709] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing load_modules_local [ 7056.398870] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 7056.502874] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 7056.517233] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 7056.557202] Lustre: lustre-MDT0000: new disk, initializing [ 7056.589918] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 7056.603378] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 7058.208910] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7061.654181] Lustre: DEBUG MARKER: oleg618-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 7064.367934] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 7064.461746] Lustre: lustre-OST0000: new disk, initializing [ 7064.463755] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 7064.466525] Lustre: Skipped 1 previous similar message [ 7064.469155] Lustre: 324677:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 7065.526562] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:0:ost [ 7065.531679] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:0:ost] [ 7065.546465] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x240000400 [ 7066.818623] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7070.369973] Lustre: DEBUG MARKER: oleg618-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 7073.144115] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 7073.206023] Lustre: lustre-OST0001: new disk, initializing [ 7073.209322] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 7073.213292] Lustre: 325619:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 7074.809964] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:1:ost [ 7074.814258] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:1:ost] [ 7074.829681] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x280000400 [ 7075.620886] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7079.041747] Lustre: DEBUG MARKER: oleg618-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0001-osc-[-0-9a-f]*.ost_server_uuid [ 7089.548441] Lustre: lustre-MDT0000: Not available for connect from 192.168.206.18@tcp (stopping) [ 7089.552308] Lustre: Skipped 4 previous similar messages [ 7090.143777] 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 [ 7090.150168] Lustre: Skipped 15 previous similar messages [ 7092.387499] Lustre: server umount lustre-MDT0000 complete [ 7096.502070] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 7096.563898] LustreError: MGC192.168.206.118@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 7098.111164] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7100.344660] Lustre: DEBUG MARKER: oleg618-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 7110.949968] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 7110.952919] Lustre: Skipped 3 previous similar messages [ 7111.482415] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 10 sec [ 7112.041866] LustreError: 327182:0:(qmt_entry.c:1166:qmt_map_lge_idx()) qmt: cannot map ostidx 1, num_used 1: rc = -22 [ 7112.588664] LustreError: 327183:0:(qmt_entry.c:1166:qmt_map_lge_idx()) qmt: cannot map ostidx 1, num_used 1: rc = -22 [ 7119.666673] Lustre: server umount lustre-MDT0000 complete [ 7122.390029] LustreError: 324676:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1781240240 with bad export cookie 18263944364397209224 [ 7122.392670] LustreError: MGC192.168.206.118@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 7122.395333] LustreError: 324676:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 7122.474981] Lustre: server umount lustre-OST0000 complete [ 7123.982335] Lustre: server umount lustre-OST0001 complete [ 7131.135419] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_hostid [ 7134.061447] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing load_modules_local [ 7152.834637] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing load_modules_local [ 7156.695291] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 7156.805284] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 7156.824606] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 7156.865203] Lustre: lustre-MDT0000: new disk, initializing [ 7156.897303] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 7156.899981] Lustre: Skipped 3 previous similar messages [ 7156.912113] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 7158.533989] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7163.674246] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 7163.724520] Lustre: 331839:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 7163.730644] Lustre: 331839:0:(mgs_llog.c:1437:mgs_modify_param()) Skipped 1 previous similar message [ 7163.742978] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 7163.745844] Lustre: Skipped 1 previous similar message [ 7163.783409] Lustre: lustre-MDT0001: new disk, initializing [ 7163.832968] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 7163.843433] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 7165.450632] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7167.993123] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 7170.552135] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 7170.645178] Lustre: 333441:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 7170.647693] Lustre: lustre-OST0000: Not available for connect from 0@lo (not set up) [ 7170.653587] Lustre: Skipped 4 previous similar messages [ 7172.890900] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7176.173472] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 7176.178701] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 7176.199317] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 7177.754089] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 7177.807841] Lustre: lustre-OST0001: new disk, initializing [ 7177.809491] Lustre: Skipped 1 previous similar message [ 7177.811475] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 7177.814204] Lustre: Skipped 1 previous similar message [ 7177.817107] Lustre: 334294:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 7179.145894] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 7180.189238] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7185.089325] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 7186.338108] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 7189.057784] Lustre: DEBUG MARKER: == sanity-quota test 92: Cannot set inode limit with Quota Pools ========================================================== 00:58:27 (1781240307) [ 7197.831434] Lustre: DEBUG MARKER: == sanity-quota test 93: update projid while client write to OST ========================================================== 00:58:36 (1781240316) [ 7208.524275] Lustre: *** cfs_fail_loc=170c, val=0*** [ 7241.619412] Lustre: DEBUG MARKER: == sanity-quota test 94: lfs quota all respects nodemap offset ========================================================== 00:59:19 (1781240359) [ 7256.032364] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 7261.414907] Lustre: server umount lustre-MDT0000 complete [ 7264.645346] LustreError: 331846:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.206.18@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 7264.658289] LustreError: 331846:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 14 previous similar messages [ 7264.891434] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 7264.947187] LustreError: MGC192.168.206.118@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 7265.069177] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3 to 0x280000401:33) [ 7266.710859] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7270.375378] LustreError: lustre-MDT0000-osp-MDT0001: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 7275.489842] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 7277.215659] Lustre: server umount lustre-MDT0000 complete [ 7280.909592] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 7281.164543] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3 to 0x280000401:65) [ 7282.912222] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7286.243490] LustreError: lustre-MDT0000-osp-MDT0001: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 7286.584623] Lustre: DEBUG MARKER: == sanity-quota test 95a: Correct limits for squashed root ========================================================== 01:00:04 (1781240404) [ 7297.317769] Lustre: DEBUG MARKER: == sanity-quota test 95b: df respects squashed project id ========================================================== 01:00:15 (1781240415) [ 7312.192861] Lustre: DEBUG MARKER: == sanity-quota test 96: quota grant should be released when big files are deleted ========================================================== 01:00:30 (1781240430) [ 7312.909415] Lustre: DEBUG MARKER: SKIP: sanity-quota test_96 OST is too small, skip the test [ 7313.645785] Lustre: DEBUG MARKER: == sanity-quota test 97a: LQA control commands =========== 01:00:31 (1781240431) [ 7325.307129] LustreError: 345137:0:(qmt_lqa.c:79:qmt_lqa_destroy()) lustre-QMT0000: cannot destroy lqa-dt-lqa1: rc = -2 [ 7325.311430] LustreError: 345137:0:(qmt_lqa.c:84:qmt_lqa_destroy()) lustre-QMT0000: cannot destroy lqa-md-lqa1: rc = -2 [ 7326.215966] Lustre: DEBUG MARKER: == sanity-quota test 97b: Check LQA internals ============ 01:00:44 (1781240444) [ 7337.809961] LustreError: 346030:0:(qmt_lqa.c:250:qmt_lqa_insert_range()) lustre-QMT0000: LQA range 15-31 partially overlaps with existing range 10-19: rc = -34 [ 7337.815145] LustreError: 346030:0:(qmt_lqa.c:669:qmt_lqa_add()) lustre-QMT0000: lqa:lqa1 can't add range 15:31: rc = -17 [ 7339.403076] LustreError: 346227:0:(qmt_lqa.c:825:qmt_lqa_remove()) lustre-QMT0000: lqa-md-lqa1 cannot remove range 10:19: rc = -2 [ 7344.185618] Lustre: DEBUG MARKER: adding 50 LQA ranges took 1s [ 7346.499646] Lustre: DEBUG MARKER: Removing 50 LQA ranges took 0s [ 7350.093139] Lustre: DEBUG MARKER: == sanity-quota test 97c: LQA lfs quota commands and MDS restart consistency ========================================================== 01:01:08 (1781240468) [ 7351.737597] Lustre: Failing over lustre-MDT0000 [ 7351.908527] Lustre: server umount lustre-MDT0000 complete [ 7352.800360] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 7355.576707] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 7355.667642] LustreError: MGC192.168.206.118@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 7355.673180] LustreError: Skipped 1 previous similar message [ 7355.799973] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 7355.803477] Lustre: Skipped 5 previous similar messages [ 7355.832055] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 7356.816378] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 7357.597355] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7359.859809] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 7361.005129] Lustre: lustre-MDT0000: Recovery over after 0:05, of 2 clients 2 recovered and 0 were evicted. [ 7361.022769] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3 to 0x280000401:97) [ 7367.908671] Lustre: DEBUG MARKER: == sanity-quota test 97d: LQA disk persistence using standard commands ========================================================== 01:01:26 (1781240486) [ 7373.766285] Lustre: Failing over lustre-MDT0000 [ 7373.939294] Lustre: server umount lustre-MDT0000 complete [ 7377.748892] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 7377.927993] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 7379.477710] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7381.747876] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 7382.406113] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 7383.013175] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 7383.020835] Lustre: Skipped 13 previous similar messages [ 7383.033718] Lustre: lustre-MDT0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 7383.056625] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3 to 0x280000401:129) [ 7399.863905] Lustre: DEBUG MARKER: == sanity-quota test 98: Verify MDT retry on -EDQUOT during mkdir ========================================================== 01:01:58 (1781240518) [ 7401.257602] Lustre: DEBUG MARKER: oleg618-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 7401.896370] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7403.508747] Lustre: DEBUG MARKER: oleg618-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0001-mdc-*.mds_server_uuid [ 7404.279225] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7409.775723] Lustre: *** cfs_fail_loc=a02, val=0*** [ 7414.421417] Lustre: DEBUG MARKER: == sanity-quota test complete, duration 7272 sec ========= 01:02:12 (1781240532) [ 7415.073742] Lustre: DEBUG MARKER: === sanity-quota: start cleanup 01:02:13 (1781240533) === [ 7416.476730] Lustre: DEBUG MARKER: === sanity-quota: finish cleanup 01:02:14 (1781240534) === [ 7418.848292] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 7418.848815] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 7418.855547] LustreError: Skipped 1 previous similar message [ 7418.860067] Lustre: Skipped 17 previous similar messages [ 7423.904430] Lustre: server umount lustre-MDT0000 complete [ 7427.068788] LustreError: 332619:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1781240545 with bad export cookie 18263944364397215650 [ 7427.070384] LustreError: MGC192.168.206.118@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 7427.073345] LustreError: 332619:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 7427.077232] LustreError: Skipped 1 previous similar message [ 7427.173647] Lustre: server umount lustre-MDT0001 complete [ 7440.452227] Lustre: server umount lustre-OST0000 complete [ 7453.100830] Lustre: server umount lustre-OST0001 complete [ 7460.417939] Lustre: DEBUG MARKER: oleg618-server.virtnet: executing unload_modules_local [ 7461.709266] Key type lgssc unregistered [ 7461.863642] LNet: 354787:0:(lib-ptl.c:967:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 7461.867245] LNetError: 354787:0:(acceptor.c:246:lnet_acceptor_remove_socket()) Interface ens2 not found [ 7461.880030] LNet: Removed LNI 192.168.206.118@tcp [ 7462.259148] Key type .llcrypt unregistered [ 7462.263065] Key type ._llcrypt unregistered