[ 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-8.fc42 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 648449184 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 0x00000000BFFE2439 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE22D5 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 002295 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE2349 000090 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE23D9 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE2411 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe22d5-0xbffe2348] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe22d4] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe2349-0xbffe23d8] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe23d9-0xbffe2410] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe2411-0xbffe2438] [ 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.001011] APIC: Switch to symmetric I/O mode setup [ 0.002000] x2apic enabled [ 0.002000] Switched APIC routing to physical x2apic. [ 0.002000] kvm-guest: setup PV IPIs [ 0.002000] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.002000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.002019] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.003013] pid_max: default: 32768 minimum: 301 [ 0.004120] LSM: Security Framework initializing [ 0.005037] Yama: becoming mindful. [ 0.006031] SELinux: Initializing. [ 0.007056] *** VALIDATE selinux *** [ 0.013474] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.017747] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.018151] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.019188] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.020097] *** VALIDATE tmpfs *** [ 0.021000] *** VALIDATE proc *** [ 0.022147] *** VALIDATE cgroup *** [ 0.023007] *** VALIDATE cgroup2 *** [ 0.025183] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.026136] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.027005] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.028023] Spectre V2 : User space: Vulnerable [ 0.029005] Speculative Store Bypass: Vulnerable [ 0.033034] debug: unmapping init [mem 0xffffffffba459000-0xffffffffba460fff] [ 0.035000] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.035655] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.036019] ... version: 2 [ 0.037007] ... bit width: 48 [ 0.038006] ... generic registers: 4 [ 0.039008] ... value mask: 0000ffffffffffff [ 0.040007] ... max period: 00007fffffffffff [ 0.041007] ... fixed-purpose events: 3 [ 0.041846] ... event mask: 000000070000000f [ 0.042233] rcu: Hierarchical SRCU implementation. [ 0.044596] smp: Bringing up secondary CPUs ... [ 0.045588] x86: Booting SMP configuration: [ 0.046024] .... node #0, CPUs: #1 #2 #3 [ 0.056319] smp: Brought up 1 node, 4 CPUs [ 0.057946] smpboot: Max logical packages: 1 [ 0.058018] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.250064] node 0 deferred pages initialised in 190ms [ 0.254273] devtmpfs: initialized [ 0.257266] x86/mm: Memory block size: 128MB [ 0.261615] gcov: version magic: 0x41383552 [ 0.282461] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.286070] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.288433] pinctrl core: initialized pinctrl subsystem [ 0.290147] [ 0.290818] ************************************************************* [ 0.294012] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.296010] ** ** [ 0.299011] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.302012] ** ** [ 0.305012] ** This means that this kernel is built to expose internal ** [ 0.308011] ** IOMMU data structures, which may compromise security on ** [ 0.311013] ** your system. ** [ 0.314010] ** ** [ 0.319014] ** If you see this message and you are not debugging the ** [ 0.323012] ** kernel, report this immediately to your vendor! ** [ 0.325011] ** ** [ 0.326000] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.326000] ************************************************************* [ 0.326000] NET: Registered protocol family 16 [ 0.328870] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.333049] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.337052] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.340368] cpuidle: using governor menu [ 0.341963] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.347102] PCI: Using configuration type 1 for base access [ 0.349128] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.366307] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.367018] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.371055] cryptd: max_cpu_qlen set to 1000 [ 0.376692] ACPI: Added _OSI(Module Device) [ 0.378009] ACPI: Added _OSI(Processor Device) [ 0.380011] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.381011] ACPI: Added _OSI(Processor Aggregator Device) [ 0.387486] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.394389] ACPI: Interpreter enabled [ 0.395064] ACPI: PM: (supports S0 S3 S4 S5) [ 0.396032] ACPI: Using IOAPIC for interrupt routing [ 0.400106] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.407435] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.410000] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.410000] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.416020] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.419077] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.426088] acpiphp: Slot [2] registered [ 0.427096] acpiphp: Slot [5] registered [ 0.428108] acpiphp: Slot [6] registered [ 0.430187] acpiphp: Slot [7] registered [ 0.431114] acpiphp: Slot [8] registered [ 0.432130] acpiphp: Slot [9] registered [ 0.433123] acpiphp: Slot [10] registered [ 0.436204] acpiphp: Slot [3] registered [ 0.437113] acpiphp: Slot [4] registered [ 0.438158] acpiphp: Slot [11] registered [ 0.440251] acpiphp: Slot [12] registered [ 0.441254] acpiphp: Slot [13] registered [ 0.443115] acpiphp: Slot [14] registered [ 0.444172] acpiphp: Slot [15] registered [ 0.446222] acpiphp: Slot [16] registered [ 0.447088] acpiphp: Slot [17] registered [ 0.449083] acpiphp: Slot [18] registered [ 0.450094] acpiphp: Slot [19] registered [ 0.451123] acpiphp: Slot [20] registered [ 0.453090] acpiphp: Slot [21] registered [ 0.455154] acpiphp: Slot [22] registered [ 0.456089] acpiphp: Slot [23] registered [ 0.457175] acpiphp: Slot [24] registered [ 0.459104] acpiphp: Slot [25] registered [ 0.460289] acpiphp: Slot [26] registered [ 0.462250] acpiphp: Slot [27] registered [ 0.464093] acpiphp: Slot [28] registered [ 0.465291] acpiphp: Slot [29] registered [ 0.467097] acpiphp: Slot [30] registered [ 0.469142] acpiphp: Slot [31] registered [ 0.470065] PCI host bridge to bus 0000:00 [ 0.471017] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.474020] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.476017] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.479021] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.482026] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.485027] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.487207] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.490077] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.493763] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.504521] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.509068] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.516027] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.519015] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.527019] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.529725] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.532801] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.535034] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.542996] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.548011] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.559000] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.564013] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.568997] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.591022] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.624042] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.647016] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.657743] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.666015] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.672020] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.687091] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.697321] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.747013] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.754013] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.782013] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.836814] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.846032] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.851013] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.864017] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.871000] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.877020] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.890015] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.903000] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 0.903000] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.903000] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.911015] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.927015] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 0.945754] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.951084] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.954498] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.956464] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.959470] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.965058] iommu: Default domain type: Passthrough [ 0.967736] SCSI subsystem initialized [ 0.970156] ACPI: bus type USB registered [ 0.972095] usbcore: registered new interface driver usbfs [ 0.975468] usbcore: registered new interface driver hub [ 0.978129] usbcore: registered new device driver usb [ 0.980269] pps_core: LinuxPPS API ver. 1 registered [ 0.983010] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.987055] PTP clock support registered [ 0.990209] EDAC MC: Ver: 3.0.0 [ 0.991129] PCI: Using ACPI for IRQ routing [ 0.995473] NetLabel: Initializing [ 0.997008] NetLabel: domain hash size = 128 [ 0.998008] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 1.002080] NetLabel: unlabeled traffic allowed by default [ 1.005463] vgaarb: loaded [ 1.029339] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 1.032013] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 1.040385] clocksource: Switched to clocksource kvm-clock [ 1.250194] VFS: Disk quotas dquot_6.6.0 [ 1.251741] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 1.254059] *** VALIDATE ramfs *** [ 1.255335] *** VALIDATE hugetlbfs *** [ 1.256728] pnp: PnP ACPI init [ 1.259514] pnp: PnP ACPI: found 6 devices [ 1.278158] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 1.282444] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 1.285345] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 1.288596] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 1.291951] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 1.295654] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 1.299373] NET: Registered protocol family 2 [ 1.302475] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 1.309392] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 1.314419] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 1.320190] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 1.324098] TCP: Hash tables configured (established 65536 bind 65536) [ 1.327488] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 1.330682] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 1.333700] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 1.337400] NET: Registered protocol family 1 [ 1.340793] RPC: Registered named UNIX socket transport module. [ 1.343250] RPC: Registered udp transport module. [ 1.346519] RPC: Registered tcp transport module. [ 1.348703] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 1.352344] NET: Registered protocol family 44 [ 1.354897] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 1.357358] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 1.360421] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 1.363631] PCI: CLS 0 bytes, default 64 [ 1.366266] Unpacking initramfs... [ 3.798605] debug: unmapping init [mem 0xffff93fe7cc54000-0xffff93fe7ffbffff] [ 3.804263] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 3.807030] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 3.811077] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 5.579326] Initialise system trusted keyrings [ 5.580920] Key type blacklist registered [ 5.582752] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 5.591972] zbud: loaded [ 5.594985] *** VALIDATE nfs *** [ 5.596033] *** VALIDATE nfs4 *** [ 5.597901] pstore: using deflate compression [ 5.609108] Platform Keyring initialized [ 5.718655] NET: Registered protocol family 38 [ 5.720343] Key type asymmetric registered [ 5.722881] Asymmetric key parser 'x509' registered [ 5.725828] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 5.730041] io scheduler mq-deadline registered [ 5.731755] io scheduler kyber registered [ 5.733879] io scheduler bfq registered [ 5.737231] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 5.740734] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 5.744797] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 5.748322] ACPI: Power Button [PWRF] [ 5.753850] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 5.761170] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 5.778686] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 5.787727] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 5.801459] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 5.836955] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 5.875893] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 5.880557] Non-volatile memory driver v1.3 [ 5.882117] Linux agpgart interface v0.103 [ 5.933113] virtio_blk virtio1: [vda] 134920 512-byte logical blocks (69.1 MB/65.9 MiB) [ 5.935967] vda: detected capacity change from 0 to 69079040 [ 6.093192] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 6.097462] vdb: detected capacity change from 0 to 1073741824 [ 6.189514] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 6.194556] vdc: detected capacity change from 0 to 2621440000 [ 6.292240] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 6.301901] vdd: detected capacity change from 0 to 2621440000 [ 6.327830] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 6.334250] vde: detected capacity change from 0 to 4294967296 [ 6.415057] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 6.417625] vdf: detected capacity change from 0 to 4294967296 [ 6.427692] libphy: Fixed MDIO Bus: probed [ 6.434391] usbcore: registered new interface driver usbserial_generic [ 6.437775] usbserial: USB Serial support registered for generic [ 6.466185] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 6.506568] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 6.527554] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 6.538984] mousedev: PS/2 mouse device common for all mice [ 6.546306] rtc_cmos 00:05: RTC can wake from S4 [ 6.557671] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 6.561645] rtc_cmos 00:05: registered as rtc0 [ 6.573763] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 6.579165] intel_pstate: CPU model not supported [ 6.587642] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 6.597813] hpet1: lost 1 rtc interrupts [ 6.618185] hid: raw HID events driver (C) Jiri Kosina [ 6.619855] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 6.628543] usbcore: registered new interface driver usbhid [ 6.644354] usbhid: USB HID core driver [ 6.647695] drop_monitor: Initializing network drop monitor service [ 6.651302] Initializing XFRM netlink socket [ 6.654729] NET: Registered protocol family 10 [ 6.659248] Segment Routing with IPv6 [ 6.662105] NET: Registered protocol family 17 [ 6.665159] mpls_gso: MPLS GSO support [ 6.672547] RAS: Correctable Errors collector initialized. [ 6.675316] AVX version of gcm_enc/dec engaged. [ 6.677141] AES CTR mode by8 optimization enabled [ 6.779947] sched_clock: Marking stable (6779853544, 0)->(8121125657, -1341272113) [ 6.784135] registered taskstats version 1 [ 6.786336] Loading compiled-in X.509 certificates [ 6.788691] zswap: loaded using pool lzo/zbud [ 6.815862] Key type big_key registered [ 6.827945] Key type encrypted registered [ 6.829724] ima: No TPM chip found, activating TPM-bypass! [ 6.832420] ima: Allocated hash algorithm: sha1 [ 6.834437] ima: No architecture policies found [ 6.836517] evm: Initialising EVM extended attributes: [ 6.842360] evm: security.selinux [ 6.845460] evm: security.ima [ 6.847470] evm: security.capability [ 6.850334] evm: HMAC attrs: 0x1 [ 6.855443] rtc_cmos 00:05: setting system clock to 2026-05-13 06:02:00 UTC (1778652120) [ 6.872300] debug: unmapping init [mem 0xffffffffbb403000-0xffffffffbb5fffff] [ 6.878355] debug: unmapping init [mem 0xffffffffba182000-0xffffffffba458fff] [ 6.892059] Write protecting the kernel read-only data: 28672k [ 6.899114] debug: unmapping init [mem 0xffffffffb8803000-0xffffffffb89fffff] [ 6.905947] debug: unmapping init [mem 0xffffffffb9114000-0xffffffffb91fffff] [ 6.968259] 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) [ 7.016808] systemd[1]: Detected virtualization kvm. [ 7.019129] systemd[1]: Detected architecture x86-64. [ 7.036599] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 7.146944] systemd[1]: No hostname configured. [ 7.150838] systemd[1]: Set hostname to . [ 7.155156] random: systemd: uninitialized urandom read (16 bytes read) [ 7.159150] systemd[1]: Initializing machine ID from random generator. [ 7.302511] random: ln: uninitialized urandom read (6 bytes read) [ 7.494161] random: systemd: uninitialized urandom read (16 bytes read) [ 7.497412] systemd[1]: Listening on udev Kernel Socket. [ OK ] Listening on udev Kernel Socket. [ 7.503766] systemd[1]: Listening on udev Control Socket. [ OK ] Listening on udev Control Socket. [ 7.512207] systemd[1]: Started Dispatch Password Requests to Console Directory Watch. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Listening on Journal Socket. [ OK ] Started Memstrack Anylazing Service. Starting Create list of required st…ce nodes for the current kernel... Starting Apply Kernel Variables... [ OK ] Reached target Swap. [ OK ] Listening on Journal Socket (/dev/log). Starting Journal Service... [ OK ] Reached target Sockets. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Local File Systems. Starting Create Volatile Files and Directories... [ OK ] Reached target Paths. [ OK ] Reached target Initrd Root Device. Starting Setup Virtual Console... [ OK ] Reached target Slices. [ OK ] Reached target Timers. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Apply Kernel Variables. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Setup Virtual Console. Starting dracut cmdline hook... Starting Create Static Device Nodes in /dev... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started Journal Service. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 9.048348] device-mapper: uevent: version 1.0.3 [ 9.050944] device-mapper: ioctl: 4.46.0-ioctl (2022-02-22) initialised: dm-devel@redhat.com [ OK ] Started dracut pre-udev hook. Starting udev Kernel Device Manager... [ OK ] Started udev Kernel Device Manager. Starting dracut pre-trigger hook... [ OK ] Started dracut pre-trigger hook. Starting udev Coldplug all Devices... Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ 10.537310] random: fast init done Starting dracut [ 10.584951] virtio_net virtio0 ens2: renamed from eth0 initqueue hook... [ 11.308482] scsi host0: ata_piix [ 11.551707] scsi host1: ata_piix [ 11.563760] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 11.580648] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 17.393059] random: crng init done [ 17.394471] random: 7 urandom warning(s) missed due to ratelimiting [ 18.982382] dracut-initqueue[583]: RTNETLINK answers: File exists Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Mounting /sysroot... [ 20.849714] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped target Timers. [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Slices. [ OK ] Stopped target Paths. [ OK ] Stopped target Sockets. [ OK ] Stopped target System Initialization. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. Stopping udev Kernel Device Manager... [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. [ OK ] Stopped target Swap. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Closed udev Kernel Socket. [ OK ] Closed udev Control Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 22.612946] printk: systemd: 26 output lines suppressed due to ratelimiting [ 23.471278] SELinux: Disabled at runtime. [ 23.547435] 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) [ 23.556351] systemd[1]: Detected virtualization kvm. [ 23.557973] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 26.841549] systemd[1]: initrd-switch-root.service: Succeeded. [ 26.845474] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 26.854816] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 26.859129] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 26.864556] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 26.875242] systemd[1]: Starting Journal Service... Starting Journal Service... [ 26.883206] systemd[1]: Created slice system-getty.slice. [ OK ] Created slice system-getty.slice. [ OK ] Listening on udev Kernel Socket. Starting Apply Kernel Variables... [ OK ] Started Forward Password Requests to Wall Directory Watch. Mounting Huge Pages File System... Starting Create list of required st…ce nodes for the current kernel... [ OK ] Reached target rpc_pipefs.target. [ OK ] Listening on initctl Compatibility Named Pipe. Mounting POSIX Message Queue File System... [ OK ] Created slice User and Session Slice. [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Listening on udev Control Socket. Starting udev Coldplug all Devices... Starting Remount Root and Kernel File Systems... [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Reached target RPC Port Mapper. Mounting Kernel Debug File System... [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Reached target Slices. [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. Activating swap /dev/disk/by-label/SWAP... [ OK ] Listening on Process Core Dump Socket. [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd File Systems. [ 27.803252] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS [ OK ] Stopped target Initrd Root File System. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Paths. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Started Journal Service. [ OK ] Started Apply Kernel Variables. [ OK ] Mounted Huge Pages File System. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Mounted POSIX Message Queue File System. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Mounted Kernel Debug File System. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ 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 udev Coldplug all Devices. [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Reached target Local File Systems (Pre). Mounting /home/green/git/lustre-release... Mounting /mnt... Starting udev Kernel Device Manager... [ OK ] Mounted /mnt. [ 29.277207] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 30.672643] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 30.725615] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 31.655245] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 32.534293] EDAC sbridge: Ver: 1.1.2 [* ] A start job is running for Configur…-only root support (8s / no limit) [** ] A start job is running for Configur…-only root support (9s / no limit) [*** ] A start job is running for Configur…-only root support (9s / no limit) [ *** ] A start job is running for Configur…only root support (10s / no limit) [ *** ] A start job is running for Configur…only root support (10s / no limit) [ ***] A start job is running for Configur…only root support (11s / no limit) [ **] A start job is running for Configur…only root support (11s / no limit) [ *] A start job is running for Configur…only root support (11s / no limit)[ 39.211658] Key type dns_resolver registered [ **] A start job is running for Configur…only root support (12s / no limit) [ ***] A start job is running for Configur…only root support (13s / no limit)[ 40.228516] NFS: Registering the id_resolver key type [ 40.246671] Key type id_resolver registered [ 40.251235] Key type id_legacy registered [ *** ] A start job is running for Configur…only root support (13s / no limit) [ *** ] A start job is running for Configur…only root support (13s / no limit) [ OK ] Started Configure read-only root support. Starting Load/Save Random Seed... [ OK ] Reached target Local File Systems. Starting Rebuild Dynamic Linker Cache... Starting Create Volatile Files and Directories... Starting Mark the need to relabel after reboot... [ OK ] Started Load/Save Random Seed. [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Create Volatile Files and Directories. Starting Update UTMP about System Boot/Shutdown... Starting RPC Bind... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ 42.362500] hrtimer: interrupt took 6007107 ns [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Started dnf makecache --timer. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Reached target Timers. [ OK ] Reached target Basic System. [ OK ] Started D-Bus System Message Bus. Starting Network Manager... [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting Restore /run/initramfs on shutdown... Starting Login Service... [ OK ] Started irqbalance daemon. [ OK ] Reached target sshd-keygen.target. [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Network Manager. [ OK ] Reached target Network. Starting Dynamic System Tuning Daemon... Starting OpenSSH server daemon... Starting GSSAPI Proxy Daemon... Starting Network Manager Wait Online... [ OK ] Started OpenSSH server daemon. Starting Hostname Service... [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Started Login Service. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... [ OK ] Started Permit User Sessions. [ OK ] Started Getty on tty1. [ OK ] Started Command Scheduler. [ OK ] Started Serial Getty on ttyS1. [ OK ] Started Serial Getty on ttyS0. [ OK ] Reached target Login Prompts. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting System Logging Service... Starting Notify NFS peers of a restart... Starting Crash recovery kernel arming... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg315-server login: [ 111.784769] libcfs: loading out-of-tree module taints kernel. [ 111.812919] Key type ._llcrypt registered [ 111.814573] Key type .llcrypt registered [ 111.918152] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_hostid [ 127.121086] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing load_modules_local [ 128.527795] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 128.546444] alg: No test for adler32 (adler32-zlib) [ 129.877324] Lustre: Lustre: Build Version: 2.17.53_3_gb43cd8a [ 130.576828] LNet: Added LNI 192.168.203.115@tcp [8/256/0/180] [ 132.314631] Key type lgssc registered [ 133.667596] Lustre: Echo OBD driver; http://www.lustre.org/ [ 146.726076] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 178.220585] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing load_modules_local [ 189.440786] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 189.494122] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 190.711704] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 190.741202] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 190.803338] Lustre: lustre-MDT0000: new disk, initializing [ 190.876235] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 190.892943] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 194.545840] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 205.486495] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 205.584549] Lustre: 6509: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 [ 205.616584] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 205.624242] Lustre: Skipped 1 previous similar message [ 205.693568] Lustre: lustre-MDT0001: new disk, initializing [ 205.747906] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 205.780156] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 205.794253] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 209.176821] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 213.518177] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 221.393909] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 221.566538] Lustre: lustre-OST0000: new disk, initializing [ 221.573762] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 221.580281] Lustre: 8412:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 221.637680] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 224.589882] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 224.597319] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 224.678758] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 226.922722] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 239.735693] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 239.816169] Lustre: lustre-OST0001: new disk, initializing [ 239.819386] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 239.823499] Lustre: 9467:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 239.879271] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 244.983831] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 245.790638] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 245.805649] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 245.850739] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 255.146296] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 259.856699] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 265.077377] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing check_logdir /tmp/testlogs/ [ 268.961513] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing yml_node [ 273.176044] Lustre: DEBUG MARKER: Client: 2.17.53.3 [ 275.755079] Lustre: DEBUG MARKER: MDS: 2.17.53.3 [ 278.179074] Lustre: DEBUG MARKER: OSS: 2.17.53.3 [ 279.473441] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity-quota ============----- Wed May 13 02:06:32 EDT 2026 [ 294.289400] Lustre: DEBUG MARKER: excepting tests: 2 4a 63 65 [ 295.663897] Lustre: DEBUG MARKER: skipping tests SLOW=no: 61 [ 298.348204] Lustre: DEBUG MARKER: === sanity-quota: start setup 02:06:51 (1778652411) === [ 301.629864] Lustre: DEBUG MARKER: oleg315-client.virtnet: executing check_config_client /mnt/lustre [ 316.435579] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 319.039556] Lustre: 13275:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 322.124171] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 326.653316] Lustre: DEBUG MARKER: === sanity-quota: finish setup 02:07:19 (1778652439) === [ 374.538818] Lustre: DEBUG MARKER: == sanity-quota test 0: Test basic quota performance ===== 02:08:07 (1778652487) [ 407.273866] Lustre: DEBUG MARKER: == sanity-quota test 1a: Block hard limit (normal use and out of quota) ========================================================== 02:08:40 (1778652520) [ 415.188745] Lustre: DEBUG MARKER: User quota (block hardlimit:10 MB) [ 419.606675] Lustre: DEBUG MARKER: Write... [ 420.842312] Lustre: DEBUG MARKER: Write out of block quota ... [ 444.525954] Lustre: DEBUG MARKER: -------------------------------------- [ 445.435695] Lustre: DEBUG MARKER: Group quota (block hardlimit:10 MB) [ 450.057880] Lustre: DEBUG MARKER: Write... [ 451.478560] Lustre: DEBUG MARKER: Write out of block quota ... [ 483.747497] Lustre: DEBUG MARKER: -------------------------------------- [ 484.741664] Lustre: DEBUG MARKER: Project quota (block hardlimit:10 mb) [ 486.380088] Lustre: DEBUG MARKER: Write... [ 487.743770] Lustre: DEBUG MARKER: Write out of block quota ... [ 526.458191] Lustre: DEBUG MARKER: == sanity-quota test 1b: Quota pools: Block hard limit (normal use and out of quota) ========================================================== 02:10:39 (1778652639) [ 535.775773] Lustre: DEBUG MARKER: User quota (block hardlimit:20 MB) [ 551.601890] Lustre: DEBUG MARKER: Write... [ 553.038831] Lustre: DEBUG MARKER: Write out of block quota ... [ 576.726128] Lustre: DEBUG MARKER: -------------------------------------- [ 577.823352] Lustre: DEBUG MARKER: Group quota (block hardlimit:20 MB) [ 582.569311] Lustre: DEBUG MARKER: Write... [ 584.209112] Lustre: DEBUG MARKER: Write out of block quota ... [ 617.697920] Lustre: DEBUG MARKER: -------------------------------------- [ 618.768191] Lustre: DEBUG MARKER: Project quota (block hardlimit:20 mb) [ 620.815504] Lustre: DEBUG MARKER: Write... [ 622.339913] Lustre: DEBUG MARKER: Write out of block quota ... [ 668.498309] Lustre: DEBUG MARKER: == sanity-quota test 1c: Quota pools: check 3 pools with hardlimit only for global ========================================================== 02:13:01 (1778652781) [ 675.785533] Lustre: DEBUG MARKER: User quota (block hardlimit:20 MB) [ 697.374174] Lustre: DEBUG MARKER: Write... [ 699.090239] Lustre: DEBUG MARKER: Write out of block quota ... [ 760.131627] Lustre: DEBUG MARKER: == sanity-quota test 1d: Quota pools: check block hardlimit on different pools ========================================================== 02:14:33 (1778652873) [ 766.451554] Lustre: DEBUG MARKER: User quota (block hardlimit:20 MB) [ 784.476403] Lustre: DEBUG MARKER: Write... [ 785.916895] Lustre: DEBUG MARKER: Write out of block quota ... [ 844.294091] Lustre: DEBUG MARKER: == sanity-quota test 1e: Quota pools: global pool high block limit vs quota pool with small ========================================================== 02:15:57 (1778652957) [ 852.587673] Lustre: DEBUG MARKER: User quota (block hardlimit:53000000 MB) [ 872.049731] Lustre: DEBUG MARKER: Write... [ 875.479248] Lustre: DEBUG MARKER: Write out of block quota ... [ 891.126360] Lustre: DEBUG MARKER: Write... [ 958.840944] Lustre: DEBUG MARKER: == sanity-quota test 1f: Quota pools: correct qunit after removing/adding OST ========================================================== 02:17:50 (1778653070) [ 973.827314] Lustre: DEBUG MARKER: User quota (block hardlimit:200 MB) [ 990.129191] Lustre: DEBUG MARKER: Write... [ 993.046229] Lustre: DEBUG MARKER: Write out of block quota ... [ 1030.489839] Lustre: DEBUG MARKER: Write... [ 1033.172626] Lustre: DEBUG MARKER: Write out of block quota ... [ 1087.424213] Lustre: DEBUG MARKER: == sanity-quota test 1g: Quota pools: Block hard limit with wide striping ========================================================== 02:19:59 (1778653199) [ 1100.115549] Lustre: DEBUG MARKER: User quota (block hardlimit:40 MB) [ 1114.173223] Lustre: 6516:0:(osd_handler.c:2191:osd_trans_start()) lustre-MDT0000: credits 6570 > trans_max 3200 [ 1114.185058] Lustre: 6516:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 4/16/0, destroy: 0/0/0 [ 1114.192480] Lustre: 6516:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 401/401/0, xattr_set: 602/5615/0 [ 1114.208312] Lustre: 6516:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 20/142/0, punch: 0/0/0, quota 8/328/0 [ 1114.221763] Lustre: 6516:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/68/0, delete: 0/0/0 [ 1114.234123] Lustre: 6516:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 1114.241962] CPU: 2 PID: 6516 Comm: mdt00_001 Kdump: loaded Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 1114.256170] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.17.0-8.fc42 06/10/2025 [ 1114.263997] Call Trace: [ 1114.265756] ? dump_stack+0xbb/0x10e [ 1114.270057] ? osd_trans_start+0x8db/0x9d0 [osd_ldiskfs] [ 1114.273705] ? top_trans_start+0x599/0xd80 [ptlrpc] [ 1114.276782] ? lod_ref_add+0x30/0x30 [lod] [ 1114.280885] ? lod_trans_start+0x109/0x4c0 [lod] [ 1114.282719] ? mdd_declare_attr_set+0x190/0x690 [mdd] [ 1114.285892] ? mdd_env_info+0x25/0xc0 [mdd] [ 1114.289866] ? mdd_trans_start+0x18/0x30 [mdd] [ 1114.292262] ? mdd_attr_set+0xa5a/0x1240 [mdd] [ 1114.295459] ? mdt_reint_setattr+0x14aa/0x2030 [mdt] [ 1114.300214] ? mdt_reint_setattr+0x14aa/0x2030 [mdt] [ 1114.302865] ? mdt_reint_rec+0x139/0x2b0 [mdt] [ 1114.305529] ? mdt_reint_internal+0x693/0xdc0 [mdt] [ 1114.310184] ? mdt_reint+0x163/0x190 [mdt] [ 1114.311877] ? tgt_handle_request0+0x137/0xaf0 [ptlrpc] [ 1114.315567] ? tgt_request_handle+0x575/0x1f70 [ptlrpc] [ 1114.320532] ? ptlrpc_server_handle_request+0x443/0x13b0 [ptlrpc] [ 1114.325369] ? lprocfs_counter_add+0x15b/0x210 [obdclass] [ 1114.332339] ? ptlrpc_main+0xce8/0x1400 [ptlrpc] [ 1114.334327] ? ptlrpc_wait_event+0x690/0x690 [ptlrpc] [ 1114.348784] ? kthread+0x1d1/0x200 [ 1114.355343] ? set_kthread_struct+0x70/0x70 [ 1114.361846] ? ret_from_fork+0x1f/0x30 [ 1116.031966] Lustre: DEBUG MARKER: Write... [ 1130.006269] Lustre: DEBUG MARKER: Write out of block quota ... [ 1206.480504] Lustre: DEBUG MARKER: == sanity-quota test 1h: Block hard limit test using fallocate ========================================================== 02:21:59 (1778653319) [ 1221.318305] Lustre: DEBUG MARKER: User quota (block hardlimit:10 MB) [ 1229.398389] Lustre: DEBUG MARKER: Write 5MiB Using Fallocate [ 1237.984619] Lustre: DEBUG MARKER: Write 11MiB Using Fallocate [ 1325.140717] Lustre: DEBUG MARKER: == sanity-quota test 1i: Quota pools: different limit and usage relations ========================================================== 02:23:58 (1778653438) [ 1334.740294] Lustre: DEBUG MARKER: User quota (block hardlimit:200 MB) [ 1348.898140] Lustre: DEBUG MARKER: Write... [ 1350.845499] Lustre: DEBUG MARKER: Write out of block quota ... [ 1379.203253] Lustre: DEBUG MARKER: Write... [ 1381.148920] Lustre: DEBUG MARKER: Write out of block quota ... [ 1391.994876] LustreError: 6516: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 [ 1425.127819] Lustre: DEBUG MARKER: == sanity-quota test 1j: Enable project quota enforcement for root ========================================================== 02:25:38 (1778653538) [ 1437.302851] Lustre: DEBUG MARKER: -------------------------------------- [ 1438.442914] Lustre: DEBUG MARKER: Project quota (hardlimit: 40 mb, 2048 files) [ 1686.843390] Lustre: DEBUG MARKER: == sanity-quota test 1k: LQA: Block hard limit (normal use and out of quota) ========================================================== 02:30:00 (1778653800) [ 1695.801192] Lustre: DEBUG MARKER: Write... [ 1697.401614] Lustre: DEBUG MARKER: Write out of block quota ... [ 1722.117209] Lustre: DEBUG MARKER: Write... [ 1723.670649] Lustre: DEBUG MARKER: Write out of block quota ... [ 1745.295331] Lustre: DEBUG MARKER: Write... [ 1746.790226] Lustre: DEBUG MARKER: Write out of block quota ... [ 1767.489910] Lustre: DEBUG MARKER: == sanity-quota test 1l: Async writes should not be rejected by quota with root_prj_enable ========================================================== 02:31:20 (1778653880) [ 1788.784277] Lustre: DEBUG MARKER: SKIP: sanity-quota test_2 skipping excluded test 2 [ 1789.823897] Lustre: DEBUG MARKER: == sanity-quota test 3a: Block soft limit (start timer, timer goes off, stop timer) ========================================================== 02:31:43 (1778653903) [ 1824.105919] Lustre: DEBUG MARKER: Write after timer goes off [ 1825.013564] Lustre: DEBUG MARKER: Write after cancel lru locks [ 1884.058986] Lustre: DEBUG MARKER: Write after timer goes off [ 1884.940471] Lustre: DEBUG MARKER: Write after cancel lru locks [ 1941.151654] Lustre: DEBUG MARKER: Write after timer goes off [ 1941.906593] Lustre: DEBUG MARKER: Write after cancel lru locks [ 1987.252482] Lustre: DEBUG MARKER: == sanity-quota test 3b: Quota pools: Block soft limit (start timer, expires, stop timer) ========================================================== 02:35:00 (1778654100) [ 2027.678293] Lustre: DEBUG MARKER: Write after timer goes off [ 2030.469902] Lustre: DEBUG MARKER: Write after cancel lru locks [ 2128.688192] Lustre: DEBUG MARKER: Write after timer goes off [ 2132.384867] Lustre: DEBUG MARKER: Write after cancel lru locks [ 2173.395985] LustreError: 3665:0:(qsd_reint.c:627:qqi_reint_delayed()) lustre-OST0001: Delaying reintegration for qtype:1 until pending updates are flushed. [ 2213.808381] Lustre: DEBUG MARKER: Write after timer goes off [ 2216.740349] Lustre: DEBUG MARKER: Write after cancel lru locks [ 2295.469803] Lustre: DEBUG MARKER: == sanity-quota test 3c: Quota pools: check block soft limit on different pools ========================================================== 02:40:07 (1778654407) [ 2360.843578] Lustre: DEBUG MARKER: Write after timer goes off [ 2364.060174] Lustre: DEBUG MARKER: Write after cancel lru locks [ 2440.917659] Lustre: DEBUG MARKER: SKIP: sanity-quota test_4a skipping excluded test 4a [ 2443.076127] Lustre: DEBUG MARKER: == sanity-quota test 4b: Grace time strings handling ===== 02:42:35 (1778654555) [ 2455.787834] Lustre: DEBUG MARKER: == sanity-quota test 5: Chown [ 2573.302922] Lustre: DEBUG MARKER: == sanity-quota test 6: Test dropping acquire request on master ========================================================== 02:44:46 (1778654686) [ 2611.167523] Lustre: *** cfs_fail_loc=513, val=601*** [ 2611.867556] Lustre: *** cfs_fail_loc=513, val=601*** [ 2611.877832] Lustre: Skipped 18 previous similar messages [ 2612.760326] LustreError: 16376:0:(service.c:2344:ptlrpc_server_handle_req_in()) drop incoming rpc opc 601, x1865052058183936 [ 2614.756042] Lustre: *** cfs_fail_loc=513, val=601*** [ 2614.762254] Lustre: Skipped 19 previous similar messages [ 2616.989327] Lustre: *** cfs_fail_loc=513, val=601*** [ 2616.995103] Lustre: Skipped 18 previous similar messages [ 2621.410402] Lustre: *** cfs_fail_loc=513, val=601*** [ 2621.418618] Lustre: Skipped 10 previous similar messages [ 2628.064029] Lustre: 42723:0:(service.c:1615:ptlrpc_at_send_early_reply()) @@@ Could not add any time (5/5), not sending early reply req@ffff93fed7940a80 x1865052046833536/t0(0) o4->d3a82b31-166d-4586-a35b-f5eb886e28a2@192.168.203.15@tcp:76/0 lens 488/448 e 1 to 0 dl 1778654746 ref 2 fl Interpret:/600/0 rc 0/0 job:'dd.60000' uid:60000 gid:60000 projid:0 [ 2629.088784] Lustre: 8403:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1778654726/real 1778654726] req@ffff93fee78b1f80 x1865052058183936/t0(0) o601->lustre-MDT0000-lwp-OST0000@0@lo:23/10 lens 336/336 e 0 to 1 dl 1778654742 ref 2 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'ll_ost_io00_002.0' uid:0 gid:0 projid:4294967295 [ 2629.160964] 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 [ 2629.186217] Lustre: lustre-MDT0000: Client lustre-MDT0000-lwp-OST0000_UUID (at 0@lo) reconnecting [ 2629.200146] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 2629.243499] LustreError: 16370:0:(service.c:2344:ptlrpc_server_handle_req_in()) drop incoming rpc opc 601, x1865052058192640 [ 2630.111812] Lustre: *** cfs_fail_loc=513, val=601*** [ 2630.115094] Lustre: Skipped 43 previous similar messages [ 2644.447155] Lustre: 3662:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1778654742/real 1778654742] req@ffff93feff194700 x1865052058192640/t0(0) o601->lustre-MDT0000-lwp-OST0000@0@lo:23/10 lens 336/336 e 0 to 1 dl 1778654758 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'ll_ost_io00_003.0' uid:0 gid:0 projid:4294967295 [ 2644.486388] 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 [ 2644.499589] Lustre: lustre-MDT0000: Client lustre-MDT0000-lwp-OST0000_UUID (at 0@lo) reconnecting [ 2644.508881] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 2647.015520] Lustre: *** cfs_fail_loc=513, val=601*** [ 2647.023586] Lustre: Skipped 75 previous similar messages [ 2647.554435] LustreError: 6519:0:(service.c:2344:ptlrpc_server_handle_req_in()) drop incoming rpc opc 601, x1865052058201088 [ 2651.104481] LustreError: 16378:0:(service.c:2344:ptlrpc_server_handle_req_in()) drop incoming rpc opc 601, x1865052058203264 [ 2651.125248] LustreError: 16378:0:(service.c:2344:ptlrpc_server_handle_req_in()) Skipped 5 previous similar messages [ 2663.903129] Lustre: 42724:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1778654761/real 1778654761] req@ffff93fdc992e680 x1865052058201088/t0(0) o601->lustre-MDT0000-lwp-OST0000@0@lo:23/10 lens 336/336 e 0 to 1 dl 1778654777 ref 2 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'ll_ost_io00_005.0' uid:0 gid:0 projid:4294967295 [ 2663.923095] 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 [ 2663.935624] Lustre: lustre-MDT0000: Client lustre-MDT0000-lwp-OST0000_UUID (at 0@lo) reconnecting [ 2663.948874] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 2666.975134] Lustre: 3662:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1778654764/real 1778654764] req@ffff93fee7970700 x1865052058203776/t0(0) o601->lustre-MDT0000-lwp-MDT0001@0@lo:23/10 lens 336/336 e 0 to 1 dl 1778654780 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'lquota_wb_lustr.0' uid:0 gid:0 projid:4294967295 [ 2667.010105] 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 [ 2667.030133] Lustre: lustre-MDT0000: Received new LWP connection from 0@lo, keep former export from same NID [ 2667.031989] Lustre: lustre-MDT0000: Client lustre-MDT0000-lwp-OST0001_UUID (at 0@lo) reconnecting [ 2667.042959] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 2696.455773] Lustre: DEBUG MARKER: == sanity-quota test 7a: Quota reintegration (global index) ========================================================== 02:46:49 (1778654809) [ 2721.031901] Lustre: Failing over lustre-OST0000 [ 2721.207893] Lustre: server umount lustre-OST0000 complete [ 2723.296960] 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 [ 2723.318054] Lustre: Skipped 2 previous similar messages [ 2728.419253] LustreError: 42722:0:(ldlm_lib.c:1180: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. [ 2728.452378] LustreError: 42722:0:(ldlm_lib.c:1180:target_handle_connect()) Skipped 5 previous similar messages [ 2729.641616] LustreError: 11143:0:(ldlm_lib.c:1180:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.203.15@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 2732.757929] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2733.131061] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [ 2733.159792] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 2734.592302] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 2735.045545] Lustre: lustre-OST0000: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [ 2735.049077] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 2735.073573] Lustre: Skipped 1 previous similar message [ 2739.603715] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2747.225233] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 2752.324938] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 2757.581348] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 2764.106140] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 2770.734946] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 2777.548754] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 2800.878980] Lustre: Failing over lustre-OST0000 [ 2801.007727] Lustre: server umount lustre-OST0000 complete [ 2801.383994] LustreError: 8397:0:(ldlm_lib.c:1180:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.203.15@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 2801.636170] LustreError: lustre-OST0000-osc-MDT0001: operation ost_statfs to node 0@lo failed: rc = -107 [ 2801.638578] 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 [ 2801.662936] LustreError: Skipped 1 previous similar message [ 2804.707741] LustreError: 43051:0:(ldlm_lib.c:1180: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. [ 2804.714237] LustreError: 43051:0:(ldlm_lib.c:1180:target_handle_connect()) Skipped 3 previous similar messages [ 2809.847306] LustreError: 42722:0:(ldlm_lib.c:1180: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. [ 2809.868849] LustreError: 42722:0:(ldlm_lib.c:1180:target_handle_connect()) Skipped 2 previous similar messages [ 2812.063828] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2812.287509] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [ 2812.304394] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 2813.953969] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 2814.373891] Lustre: lustre-OST0000: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [ 2814.397220] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 2814.411607] Lustre: Skipped 1 previous similar message [ 2818.889676] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2826.905395] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 2833.329190] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 2839.496140] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 2845.569870] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 2851.413138] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 2856.975056] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 2884.915614] Lustre: DEBUG MARKER: == sanity-quota test 7b: Quota reintegration (slave index) ========================================================== 02:49:57 (1778654997) [ 2918.025836] Lustre: *** cfs_fail_loc=a02, val=0*** [ 2926.223940] LustreError: 3664:0:(qsd_handler.c:298:qsd_req_completion()) $$$ DQACQ failed with -5, flags:0x8 qsd:lustre-OST0000 qtype:usr lqe: ffff93fdc35ede00 id:60000 enforced:1 granted: 1024 pending:0 waiting:0 req:1 usage: 2048 qunit:0 qtune:0 edquot:0 default:no revoke:0 [ 2926.252594] Lustre: Failing over lustre-OST0000 [ 2926.326728] Lustre: server umount lustre-OST0000 complete [ 2927.073406] LustreError: lustre-OST0000-osc-MDT0001: operation ost_statfs to node 0@lo failed: rc = -107 [ 2927.074549] 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 [ 2927.092957] LustreError: Skipped 1 previous similar message [ 2927.095351] LustreError: 43050:0:(ldlm_lib.c:1180: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. [ 2927.108221] Lustre: Skipped 2 previous similar messages [ 2927.139675] LustreError: 43050:0:(ldlm_lib.c:1180:target_handle_connect()) Skipped 2 previous similar messages [ 2935.109970] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2935.344799] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [ 2935.380603] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 2936.742722] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 2937.489535] Lustre: lustre-OST0000: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [ 2937.490132] Lustre: lustre-OST0000-osc-MDT0001: Connection restored to 0@lo (at 0@lo) [ 2937.506453] Lustre: Skipped 1 previous similar message [ 2941.339660] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2949.242815] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 2954.541517] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 2959.444903] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 2964.161832] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 2970.048793] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 2975.445594] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3009.818365] Lustre: DEBUG MARKER: == sanity-quota test 7c: Quota reintegration (restart mds during reintegration) ========================================================== 02:52:02 (1778655122) [ 3030.646805] LustreError: 99421:0:(qsd_reint.c:482:qsd_reint_main()) cfs_fail_timeout id a03 sleeping for 10000ms [ 3030.655454] LustreError: 99421:0:(qsd_reint.c:482:qsd_reint_main()) Skipped 5 previous similar messages [ 3032.389514] Lustre: Failing over lustre-MDT0000 [ 3032.554891] 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 [ 3032.555853] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3032.563187] Lustre: Skipped 1 previous similar message [ 3032.572687] Lustre: Skipped 2 previous similar messages [ 3032.798203] Lustre: server umount lustre-MDT0000 complete [ 3035.504321] LustreError: 99426:0:(qsd_reint.c:482:qsd_reint_main()) cfs_fail_timeout interrupted [ 3035.511321] LustreError: 99426:0:(qsd_reint.c:482:qsd_reint_main()) Skipped 4 previous similar messages [ 3036.867820] LustreError: 6516:0:(ldlm_lib.c:1180:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.203.15@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3036.883249] LustreError: 6516:0:(ldlm_lib.c:1180:target_handle_connect()) Skipped 4 previous similar messages [ 3037.153054] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3041.473022] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3041.623838] LustreError: MGC192.168.203.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3041.998165] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3042.062247] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 3043.198034] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 3046.254758] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3047.400975] LustreError: 3661:0:(ldlm_resource.c:1180:ldlm_resource_complain()) lustre-MDT0000-lwp-OST0001: namespace resource [0x200000006:0x2020000:0x0].0x0 (ffff93fed898e300) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 3047.453375] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 3047.461371] Lustre: Skipped 1 previous similar message [ 3047.555356] Lustre: lustre-MDT0000: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 3047.577153] Lustre: 99426: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) [ 3047.610187] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:165 to 0x280000401:193) [ 3047.618242] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:99 to 0x2c0000401:129) [ 3053.733145] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3150.664236] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3155.926499] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3160.960505] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3166.098239] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3170.853172] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3201.704478] Lustre: DEBUG MARKER: == sanity-quota test 7d: Quota reintegration (Transfer index in multiple bulks) ========================================================== 02:55:14 (1778655314) [ 3221.923938] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3227.202207] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3264.513939] Lustre: DEBUG MARKER: == sanity-quota test 7e: Quota reintegration (inode limits) ========================================================== 02:56:16 (1778655376) [ 3293.075435] Lustre: Failing over lustre-MDT0001 [ 3293.173928] 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 [ 3293.188767] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 3293.213013] Lustre: Skipped 4 previous similar messages [ 3293.214540] Lustre: Skipped 1 previous similar message [ 3293.453112] Lustre: server umount lustre-MDT0001 complete [ 3293.914744] LustreError: 10668:0:(ldlm_lib.c:1180:target_handle_connect()) lustre-MDT0001: not available for connect from 192.168.203.15@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3293.946320] LustreError: 10668:0:(ldlm_lib.c:1180:target_handle_connect()) Skipped 4 previous similar messages [ 3307.771783] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3308.288129] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 3308.384596] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 3309.216671] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 3313.641388] Lustre: lustre-MDT0001-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 3313.648691] Lustre: Skipped 3 previous similar messages [ 3313.681954] Lustre: lustre-MDT0001: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 3313.747441] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:33) [ 3314.058167] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3322.769660] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 3330.184926] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0001.recovery_status 1475 [ 3337.374447] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 3344.380701] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0001.recovery_status 1475 [ 3349.971743] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 3355.171362] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0001.recovery_status 1475 [ 3431.759677] Lustre: Failing over lustre-MDT0001 [ 3432.039922] Lustre: server umount lustre-MDT0001 complete [ 3432.121983] LustreError: 6515:0:(ldlm_lib.c:1180:target_handle_connect()) lustre-MDT0001: not available for connect from 192.168.203.15@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3432.155627] LustreError: 6515:0:(ldlm_lib.c:1180:target_handle_connect()) Skipped 8 previous similar messages [ 3434.470254] Lustre: lustre-MDT0001-lwp-OST0001: Connection to lustre-MDT0001 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 3434.483019] Lustre: Skipped 2 previous similar messages [ 3439.932362] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3440.461919] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 3440.527510] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 3441.803576] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 3445.600205] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3445.759374] Lustre: lustre-MDT0001-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 3445.770912] Lustre: Skipped 2 previous similar messages [ 3445.805919] Lustre: lustre-MDT0001: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 3445.874839] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:65) [ 3454.328611] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 3459.210510] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0001.recovery_status 1475 [ 3464.042382] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 3468.577883] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0001.recovery_status 1475 [ 3474.361601] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 3479.329380] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0001.recovery_status 1475 [ 3566.018855] Lustre: DEBUG MARKER: == sanity-quota test 7f: Quota reintegration automatically ========================================================== 03:01:18 (1778655678) [ 3579.453202] Lustre: *** cfs_fail_loc=a11, val=0*** [ 3579.464390] Lustre: Skipped 3 previous similar messages [ 3585.972602] Lustre: *** cfs_fail_loc=a11, val=0*** [ 3638.247886] Lustre: *** cfs_fail_loc=a11, val=0*** [ 3638.253095] Lustre: Skipped 1 previous similar message [ 3638.322310] Lustre: 115965: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) [ 3675.788964] Lustre: DEBUG MARKER: == sanity-quota test 8: Run dbench with quota enabled ==== 03:03:08 (1778655788) [ 3860.301914] Lustre: DEBUG MARKER: == sanity-quota test 9: Block limit larger than 4GB (b10707) ========================================================== 03:06:13 (1778655973) [ 3861.608312] Lustre: DEBUG MARKER: OST0_SIZE: 3604220 required: 4900000 [ 3867.318354] Lustre: DEBUG MARKER: == sanity-quota test 10: Test quota for root user ======== 03:06:20 (1778655980) [ 3908.700052] Lustre: DEBUG MARKER: == sanity-quota test 11: Chown/chgrp ignores quota ======= 03:07:01 (1778656021) [ 3947.383150] Lustre: DEBUG MARKER: == sanity-quota test 12a: Block quota rebalancing ======== 03:07:40 (1778656060) [ 4015.017945] Lustre: DEBUG MARKER: == sanity-quota test 12b: Inode quota rebalancing ======== 03:08:47 (1778656127) [ 4153.318527] Lustre: DEBUG MARKER: == sanity-quota test 13: Cancel per-ID lock in the LRU list ========================================================== 03:11:05 (1778656265) [ 4210.269957] Lustre: DEBUG MARKER: == sanity-quota test 14: check panic in qmt_site_recalc_cb ========================================================== 03:12:02 (1778656322) [ 4235.228370] Lustre: Failing over lustre-OST0000 [ 4235.763177] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 4235.786586] 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 [ 4235.818820] LustreError: 8397:0:(ldlm_lib.c:1180: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. [ 4235.851466] Lustre: server umount lustre-OST0000 complete [ 4235.863674] LustreError: 8397:0:(ldlm_lib.c:1180:target_handle_connect()) Skipped 7 previous similar messages [ 4254.696762] LustreError: 8395:0:(ldlm_lib.c:1180: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. [ 4254.712862] LustreError: 8395:0:(ldlm_lib.c:1180:target_handle_connect()) Skipped 11 previous similar messages [ 4257.926688] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4258.400225] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [ 4258.425819] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 4260.068740] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 4260.171062] Lustre: lustre-OST0000: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [ 4260.173587] Lustre: lustre-OST0000-osc-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4260.206517] Lustre: Skipped 2 previous similar messages [ 4264.380375] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4300.064652] Lustre: DEBUG MARKER: == sanity-quota test 15: Set over 4T block quota ========= 03:13:32 (1778656412) [ 4323.785234] Lustre: DEBUG MARKER: == sanity-quota test 16a: lfs quota should skip the inactive MDT/OST ========================================================== 03:13:56 (1778656436) [ 4342.706765] Lustre: lustre-MDT0001: Client d3a82b31-166d-4586-a35b-f5eb886e28a2 (at 192.168.203.15@tcp) reconnecting [ 4360.038405] Lustre: DEBUG MARKER: == sanity-quota test 16b: lfs quota should skip the nonexistent MDT/OST ========================================================== 03:14:33 (1778656473) [ 4361.867089] Lustre: DEBUG MARKER: SKIP: sanity-quota test_16b needs >= 3 MDTs [ 4364.059784] Lustre: DEBUG MARKER: == sanity-quota test 17: DQACQ return recoverable error == 03:14:36 (1778656476) [ 4384.066569] Lustre: *** cfs_fail_loc=a04, val=37*** [ 4384.082737] LustreError: 117580:0:(qsd_handler.c:298:qsd_req_completion()) $$$ DQACQ failed with -37, flags:0x1 qsd:lustre-OST0001 qtype:usr lqe: ffff93fdc36e6300 id:60000 enforced:1 granted: 0 pending:0 waiting:1056 req:1 usage: 0 qunit:0 qtune:0 edquot:0 default:no revoke:0 [ 4385.145209] Lustre: *** cfs_fail_loc=a04, val=37*** [ 4385.154691] LustreError: 42723:0:(qsd_handler.c:298:qsd_req_completion()) $$$ DQACQ failed with -37, flags:0x1 qsd:lustre-OST0001 qtype:usr lqe: ffff93fdc36e6300 id:60000 enforced:1 granted: 0 pending:0 waiting:1056 req:1 usage: 0 qunit:0 qtune:0 edquot:0 default:no revoke:0 [ 4443.587680] Lustre: *** cfs_fail_loc=a04, val=11*** [ 4445.925763] Lustre: *** cfs_fail_loc=a04, val=11*** [ 4445.927694] Lustre: Skipped 1 previous similar message [ 4503.035060] Lustre: *** cfs_fail_loc=a04, val=110*** [ 4557.450401] Lustre: *** cfs_fail_loc=a04, val=107*** [ 4557.454542] Lustre: Skipped 2 previous similar messages [ 4635.966336] Lustre: DEBUG MARKER: == sanity-quota test 18: MDS failover while writing, no watchdog triggered (b14840) ========================================================== 03:19:08 (1778656748) [ 4649.311953] Lustre: DEBUG MARKER: User quota (limit: 200) [ 4655.456739] Lustre: DEBUG MARKER: Write 100M (buffered) ... [ 4668.864562] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4672.139339] Lustre: DEBUG MARKER: Fail mds for 40 seconds [ 4675.714982] Lustre: Failing over lustre-MDT0000 [ 4676.758590] Lustre: server umount lustre-MDT0000 complete [ 4678.120841] LustreError: 6516:0:(ldlm_lib.c:1180: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. [ 4678.176613] LustreError: 6516:0:(ldlm_lib.c:1180:target_handle_connect()) Skipped 4 previous similar messages [ 4693.472562] Lustre: 3663:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1778656791/real 1778656791] req@ffff93fee786b480 x1865052060642048/t0(0) o400->MGC192.168.203.115@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1778656807 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4693.502618] Lustre: 3663:0:(client.c:2479:ptlrpc_expire_one_request()) Skipped 5 previous similar messages [ 4693.512242] LustreError: MGC192.168.203.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4699.119627] LDISKFS-fs (dm-0): 7 truncates cleaned up [ 4699.124199] LDISKFS-fs (dm-0): recovery complete [ 4699.146377] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4703.717258] LustreError: 3661:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff93fed7a80380 x1865052060650624/t0(0) o250->MGC192.168.203.115@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 0 ref 1 fl Rpc:NQU/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4704.343585] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4704.437406] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4705.950249] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4709.400241] Lustre: lustre-MDT0000: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 4709.483097] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:615 to 0x2c0000401:641) [ 4709.483877] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:683 to 0x280000401:705) [ 4710.661594] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4719.982901] Lustre: DEBUG MARKER: oleg315-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4722.186320] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4727.717740] Lustre: DEBUG MARKER: (dd_pid=129261, time=0, timeout=600) [ 4757.353226] Lustre: DEBUG MARKER: User quota (limit: 200) [ 4763.661339] Lustre: DEBUG MARKER: Write 100M (directio) ... [ 4774.654643] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4776.954566] Lustre: DEBUG MARKER: Fail mds for 40 seconds [ 4779.127283] Lustre: Failing over lustre-MDT0000 [ 4779.620248] Lustre: server umount lustre-MDT0000 complete [ 4781.030361] 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 [ 4781.034204] LustreError: 6520:0:(ldlm_lib.c:1180: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. [ 4781.046935] Lustre: Skipped 7 previous similar messages [ 4781.065272] LustreError: 6520:0:(ldlm_lib.c:1180:target_handle_connect()) Skipped 29 previous similar messages [ 4796.879129] Lustre: 3663:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1778656894/real 1778656894] req@ffff93fed7f07800 x1865052060708736/t0(0) o400->MGC192.168.203.115@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1778656910 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4796.897341] LustreError: MGC192.168.203.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4799.661979] LDISKFS-fs (dm-0): 3 truncates cleaned up [ 4799.666430] LDISKFS-fs (dm-0): recovery complete [ 4799.674403] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4807.437059] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4807.490066] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4809.371832] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4812.439645] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4812.777189] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 4812.785789] Lustre: Skipped 5 previous similar messages [ 4812.796618] LustreError: 3661:0:(ldlm_resource.c:1180:ldlm_resource_complain()) lustre-MDT0000-lwp-MDT0001: namespace resource [0x200000006:0x10000:0x0].0x0 (ffff93fdc4061300) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 4812.828158] LustreError: 3661:0:(ldlm_resource.c:1180:ldlm_resource_complain()) Skipped 5 previous similar messages [ 4812.859157] Lustre: lustre-MDT0000: Recovery over after 0:03, of 2 clients 2 recovered and 0 were evicted. [ 4812.920919] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:707 to 0x280000401:737) [ 4812.923248] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:615 to 0x2c0000401:673) [ 4820.571485] Lustre: DEBUG MARKER: oleg315-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4822.449954] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4828.229140] Lustre: DEBUG MARKER: (dd_pid=131685, time=0, timeout=600) [ 4871.694797] Lustre: DEBUG MARKER: == sanity-quota test 19: Updating admin limits doesn't zero operational limits(b14790) ========================================================== 03:23:04 (1778656984) [ 4926.003754] Lustre: DEBUG MARKER: == sanity-quota test 20: Test if setquota specifiers work properly (b15754) ========================================================== 03:23:58 (1778657038) [ 4952.826228] Lustre: DEBUG MARKER: == sanity-quota test 21: Setquota while writing [ 4965.421961] Lustre: DEBUG MARKER: Set limit(block:10G; file:1000000) for user: quota_usr [ 4967.351401] Lustre: DEBUG MARKER: Set limit(block:10G; file:1000000) for group: quota_usr [ 4969.769827] Lustre: DEBUG MARKER: Set limit(block:10G; file:) for project: 1000 [ 4971.899075] Lustre: DEBUG MARKER: Set quota for 1 times [ 4975.999920] Lustre: DEBUG MARKER: Set quota for 2 times [ 4980.293752] Lustre: DEBUG MARKER: Set quota for 3 times [ 4983.187889] Lustre: DEBUG MARKER: Set quota for 4 times [ 4987.029957] Lustre: DEBUG MARKER: Set quota for 5 times [ 4989.915932] Lustre: DEBUG MARKER: Set quota for 6 times [ 4992.985289] Lustre: DEBUG MARKER: Set quota for 7 times [ 4996.485023] Lustre: DEBUG MARKER: Set quota for 8 times [ 5000.387882] Lustre: DEBUG MARKER: Set quota for 9 times [ 5037.941095] Lustre: DEBUG MARKER: == sanity-quota test 22: enable/disable quota by 'lctl conf_param/set_param -P' ========================================================== 03:25:50 (1778657150) [ 5053.415440] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5053.421358] Lustre: Skipped 3 previous similar messages [ 5057.486862] Lustre: server umount lustre-MDT0000 complete [ 5058.532791] LustreError: 10668:0:(ldlm_lib.c:1180: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. [ 5058.554464] LustreError: 10668:0:(ldlm_lib.c:1180:target_handle_connect()) Skipped 29 previous similar messages [ 5061.235816] LustreError: 27375:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1778657174 with bad export cookie 3583037248419395108 [ 5061.237102] LustreError: MGC192.168.203.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5061.275954] LustreError: 27375:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 5061.747864] Lustre: server umount lustre-MDT0001 complete [ 5075.972056] Lustre: server umount lustre-OST0000 complete [ 5088.789595] Lustre: server umount lustre-OST0001 complete [ 5105.915729] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing load_modules_local [ 5118.186828] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5118.978835] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 5123.826241] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5132.676928] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5133.178371] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 5137.738561] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5140.897921] Lustre: 155414:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 5147.316306] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5147.610901] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 5154.582200] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5164.004624] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5164.543911] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 5165.546352] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:739 to 0x280000401:769) [ 5165.554805] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:676 to 0x2c0000401:705) [ 5165.595417] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:97) [ 5170.566625] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5178.439242] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5182.379684] Lustre: 157256:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 5201.408743] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5201.424888] Lustre: Skipped 3 previous similar messages [ 5206.497651] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5206.508470] Lustre: Skipped 3 previous similar messages [ 5208.491739] Lustre: server umount lustre-MDT0000 complete [ 5213.646855] LustreError: 154274:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1778657327 with bad export cookie 3583037248419402227 [ 5213.663780] LustreError: MGC192.168.203.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5213.665664] LustreError: 154274:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 5214.438277] Lustre: server umount lustre-MDT0001 complete [ 5229.881558] Lustre: server umount lustre-OST0000 complete [ 5232.607153] Lustre: 3665:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1778657330/real 1778657330] req@ffff93fdc299ed80 x1865052060987648/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1778657346 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5235.122714] Lustre: server umount lustre-OST0001 complete [ 5252.893219] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing load_modules_local [ 5264.701658] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5265.300308] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 5270.251794] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5278.987372] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5283.284181] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5285.953674] Lustre: 160944:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 5292.631637] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5299.881945] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5308.493177] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5308.774440] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 5308.778784] Lustre: Skipped 2 previous similar messages [ 5309.816450] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:739 to 0x280000401:801) [ 5309.825211] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:676 to 0x2c0000401:737) [ 5309.933688] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:129) [ 5314.806314] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5322.138573] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5325.557369] Lustre: 162781:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 5336.984548] Lustre: DEBUG MARKER: == sanity-quota test 23: Quota should be honored with directIO (b16125) ========================================================== 03:30:49 (1778657449) [ 5339.112615] Lustre: DEBUG MARKER: OST0_SIZE: 3605396 required: 6144 [ 5341.355635] Lustre: DEBUG MARKER: run for 4MB test file [ 5353.685980] Lustre: DEBUG MARKER: User quota (limit: 4 MB) [ 5359.468799] Lustre: DEBUG MARKER: Step1: trigger EDQUOT with O_DIRECT [ 5361.046636] Lustre: DEBUG MARKER: Write half of file [ 5363.098210] Lustre: DEBUG MARKER: Write out of block quota ... [ 5364.860977] Lustre: DEBUG MARKER: Step1: done [ 5366.459378] Lustre: DEBUG MARKER: Step2: rewrite should succeed [ 5368.605332] Lustre: DEBUG MARKER: Step2: done [ 5395.229283] Lustre: DEBUG MARKER: OST0_SIZE: 3605396 required: 61440 [ 5396.518991] Lustre: DEBUG MARKER: run for 40MB test file [ 5409.435630] Lustre: DEBUG MARKER: User quota (limit: 40 MB) [ 5417.267337] Lustre: DEBUG MARKER: Step1: trigger EDQUOT with O_DIRECT [ 5418.932590] Lustre: DEBUG MARKER: Write half of file [ 5422.643301] Lustre: DEBUG MARKER: Write out of block quota ... [ 5426.382298] Lustre: DEBUG MARKER: Step1: done [ 5428.121653] Lustre: DEBUG MARKER: Step2: rewrite should succeed [ 5430.112725] Lustre: DEBUG MARKER: Step2: done [ 5485.584187] Lustre: DEBUG MARKER: == sanity-quota test 24: lfs draws an asterix when limit is reached (b16646) ========================================================== 03:33:18 (1778657598) [ 5532.043589] Lustre: DEBUG MARKER: == sanity-quota test 25: check indexes versions ========== 03:34:04 (1778657644) [ 5575.629598] Lustre: DEBUG MARKER: Write... [ 5577.826643] Lustre: DEBUG MARKER: Write out of block quota ... [ 5627.366879] Lustre: DEBUG MARKER: == sanity-quota test 27a: lfs quota/setquota should handle wrong arguments (b19612) ========================================================== 03:35:39 (1778657739) [ 5635.391710] Lustre: DEBUG MARKER: == sanity-quota test 27b: lfs quota/setquota should handle user/group/project ID (b20200) ========================================================== 03:35:47 (1778657747) [ 5645.968807] Lustre: DEBUG MARKER: == sanity-quota test 27c: lfs quota should support human-readable output ========================================================== 03:35:58 (1778657758) [ 5655.323781] Lustre: DEBUG MARKER: == sanity-quota test 27d: lfs setquota should support fraction block limit ========================================================== 03:36:08 (1778657768) [ 5662.861803] Lustre: DEBUG MARKER: == sanity-quota test 30: Hard limit updates should not reset grace times ========================================================== 03:36:15 (1778657775) [ 5712.693118] Lustre: DEBUG MARKER: == sanity-quota test 33: Basic usage tracking for user [ 5832.931364] Lustre: DEBUG MARKER: == sanity-quota test 34: Usage transfer for user [ 5970.792817] Lustre: DEBUG MARKER: == sanity-quota test 35: Usage is still accessible across reboot ========================================================== 03:41:23 (1778658083) [ 6017.466202] Lustre: DEBUG MARKER: Restart... [ 6021.600211] 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 [ 6021.605197] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 6021.605781] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 6021.619983] Lustre: Skipped 13 previous similar messages [ 6021.645188] Lustre: Skipped 3 previous similar messages [ 6026.721377] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 6026.735417] Lustre: Skipped 3 previous similar messages [ 6027.691499] Lustre: server umount lustre-MDT0000 complete [ 6031.321284] LustreError: 163519:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1778658144 with bad export cookie 3583037248419404530 [ 6031.326118] LustreError: MGC192.168.203.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 6031.334354] LustreError: 163519:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 6031.581079] Lustre: server umount lustre-MDT0001 complete [ 6046.004937] Lustre: server umount lustre-OST0000 complete [ 6048.226829] Lustre: 3664:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1778658145/real 1778658145] req@ffff93fee559ce00 x1865052061436800/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1778658161 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6049.842628] Lustre: server umount lustre-OST0001 complete [ 6066.022819] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing load_modules_local [ 6077.597899] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 6078.231859] LustreError: 186355:0:(ldlm_lib.c:1180: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. [ 6078.257128] LustreError: 186355:0:(ldlm_lib.c:1180:target_handle_connect()) Skipped 14 previous similar messages [ 6078.397077] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 6083.123364] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6091.499340] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 6091.937108] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 6096.533813] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6099.998396] Lustre: 187464:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 6106.853087] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 6114.113616] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6116.514957] LustreError: 187819:0:(ldlm_lib.c:1180:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 6116.546149] LustreError: 187819:0:(ldlm_lib.c:1180:target_handle_connect()) Skipped 2 previous similar messages [ 6122.302443] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 6122.617639] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 6122.625016] Lustre: Skipped 1 previous similar message [ 6123.624292] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:813 to 0x280000401:833) [ 6123.645017] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:745 to 0x2c0000401:769) [ 6123.651355] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:161) [ 6128.349819] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6135.267845] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 6138.612279] Lustre: 189305:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 6195.458812] Lustre: DEBUG MARKER: == sanity-quota test 37: Quota accounted properly for file created by 'lfs setstripe' ========================================================== 03:45:08 (1778658308) [ 6252.310986] Lustre: DEBUG MARKER: == sanity-quota test 38: Quota accounting iterator doesn't skip id entries ========================================================== 03:46:05 (1778658365) [ 7804.907311] Lustre: DEBUG MARKER: == sanity-quota test 39: Project ID interface works correctly ========================================================== 04:11:57 (1778659917) [ 7815.049143] Lustre: server umount lustre-MDT0000 complete [ 7816.672757] 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 [ 7816.684433] LustreError: 187828:0:(ldlm_lib.c:1180: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. [ 7816.687817] Lustre: Skipped 4 previous similar messages [ 7816.722506] LustreError: 187828:0:(ldlm_lib.c:1180:target_handle_connect()) Skipped 4 previous similar messages [ 7818.427899] LustreError: 186337:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1778659932 with bad export cookie 3583037248419413644 [ 7818.444744] LustreError: MGC192.168.203.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 7818.932488] Lustre: server umount lustre-MDT0001 complete [ 7828.447515] LustreError: 3665:0:(client.c:1380:ptlrpc_import_delay_req()) @@@ IMP_CLOSED req@ffff93fefeea4380 x1865052064859136/t0(0) o601->lustre-MDT0000-lwp-OST0000@0@lo:23/10 lens 336/336 e 0 to 0 dl 0 ref 1 fl Rpc:NQU/200/ffffffff rc 0/-1 job:'lquota_wb_lustr.0' uid:0 gid:0 projid:4294967295 [ 7828.495261] LustreError: 3665:0:(qsd_handler.c:298:qsd_req_completion()) $$$ DQACQ failed with -5, flags:0x8 qsd:lustre-OST0000 qtype:usr lqe: ffff93fdcdb92780 id:0 enforced:0 granted: 0 pending:0 waiting:0 req:1 usage: 1596 qunit:0 qtune:0 edquot:0 default:no revoke:0 [ 7832.911453] Lustre: server umount lustre-OST0000 complete [ 7844.831400] LustreError: 3662:0:(client.c:1380:ptlrpc_import_delay_req()) @@@ IMP_CLOSED req@ffff93fefeea5f80 x1865052064859904/t0(0) o601->lustre-MDT0000-lwp-OST0001@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 [ 7844.844168] LustreError: 3662:0:(qsd_handler.c:298:qsd_req_completion()) $$$ DQACQ failed with -5, flags:0x8 qsd:lustre-OST0001 qtype:usr lqe: ffff93fdce516600 id:0 enforced:0 granted: 0 pending:0 waiting:0 req:1 usage: 1596 qunit:0 qtune:0 edquot:0 default:no revoke:0 [ 7846.455283] Lustre: server umount lustre-OST0001 complete [ 7862.993288] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing load_modules_local [ 7873.252244] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 7873.776207] LustreError: 196988:0:(ldlm_lib.c:1180: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. [ 7873.896910] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 7877.169418] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7886.561402] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 7887.439189] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 7892.170522] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7894.866728] Lustre: 198098:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 7901.185235] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 7901.553237] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 7907.701050] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7911.778262] LustreError: 198451:0:(ldlm_lib.c:1180:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 7911.812462] LustreError: 198451:0:(ldlm_lib.c:1180:target_handle_connect()) Skipped 2 previous similar messages [ 7915.958322] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 7919.336288] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:5835 to 0x280000401:5857) [ 7919.347744] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:5771 to 0x2c0000401:5793) [ 7919.357730] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:193) [ 7922.788093] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7930.554152] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 7933.967888] Lustre: 199937:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 7959.249930] Lustre: DEBUG MARKER: == sanity-quota test 40a: Hard link across different project ID ========================================================== 04:14:32 (1778660072) [ 7985.230565] Lustre: DEBUG MARKER: == sanity-quota test 40b: Mv across different project ID ========================================================== 04:14:58 (1778660098) [ 8017.576981] Lustre: DEBUG MARKER: == sanity-quota test 40c: Remote child Dir inherit project quota properly ========================================================== 04:15:30 (1778660130) [ 8049.343291] Lustre: DEBUG MARKER: == sanity-quota test 40d: Stripe Directory inherit project quota properly ========================================================== 04:16:02 (1778660162) [ 8088.524191] Lustre: DEBUG MARKER: == sanity-quota test 41: df should return projid-specific values ========================================================== 04:16:41 (1778660201) [ 8166.099589] Lustre: DEBUG MARKER: == sanity-quota test 42: lfs quota should include default quota info ========================================================== 04:17:58 (1778660278) [ 8196.543626] Lustre: DEBUG MARKER: == sanity-quota test 48: lfs quota --delete should delete quota project ID ========================================================== 04:18:29 (1778660309) [ 8256.791701] Lustre: DEBUG MARKER: == sanity-quota test 49a: lfs quota -a prints the quota usage for all quota IDs ========================================================== 04:19:29 (1778660369) [ 8262.944985] Lustre: *** cfs_fail_loc=a09, val=0*** [ 8262.947557] Lustre: Skipped 2 previous similar messages [ 8264.999634] Lustre: *** cfs_fail_loc=a09, val=0*** [ 8265.003115] Lustre: Skipped 91 previous similar messages [ 8269.000328] Lustre: *** cfs_fail_loc=a09, val=0*** [ 8269.002843] Lustre: Skipped 191 previous similar messages [ 8277.036294] Lustre: *** cfs_fail_loc=a09, val=0*** [ 8277.042202] Lustre: Skipped 379 previous similar messages [ 8293.079281] Lustre: *** cfs_fail_loc=a09, val=0*** [ 8293.082762] Lustre: Skipped 743 previous similar messages [ 8325.100685] Lustre: *** cfs_fail_loc=a09, val=0*** [ 8325.103504] Lustre: Skipped 1619 previous similar messages [ 8389.156919] Lustre: *** cfs_fail_loc=a09, val=0*** [ 8389.163249] Lustre: Skipped 2805 previous similar messages [ 8713.510454] Lustre: *** cfs_fail_loc=a08, val=0*** [ 8713.513990] Lustre: Skipped 2165 previous similar messages [ 8713.522108] Lustre: *** cfs_fail_loc=a08, val=0*** [ 8713.525596] Lustre: Skipped 2 previous similar messages [ 8798.689073] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 8798.699334] 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 [ 8798.715847] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 8800.228724] 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 [ 8800.229711] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 8800.260773] Lustre: Skipped 1 previous similar message [ 8800.273641] Lustre: Skipped 3 previous similar messages [ 8804.914025] Lustre: server umount lustre-MDT0000 complete [ 8805.347372] LustreError: 196983:0:(ldlm_lib.c:1180: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. [ 8805.367784] LustreError: 196983:0:(ldlm_lib.c:1180:target_handle_connect()) Skipped 3 previous similar messages [ 8808.149364] LustreError: 196968:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1778660921 with bad export cookie 3583037248421190209 [ 8808.154680] LustreError: MGC192.168.203.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 8808.172493] LustreError: 196968:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 5 previous similar messages [ 8810.467244] 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 [ 8810.470825] LustreError: 206281:0:(ldlm_lib.c:1180: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. [ 8810.474486] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 8810.479898] Lustre: Skipped 2 previous similar messages [ 8810.511316] LustreError: 206281:0:(ldlm_lib.c:1180:target_handle_connect()) Skipped 1 previous similar message [ 8813.473943] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 8813.489026] Lustre: Skipped 2 previous similar messages [ 8814.642978] Lustre: server umount lustre-MDT0001 complete [ 8818.919169] Lustre: server umount lustre-OST0000 complete [ 8822.235777] Lustre: server umount lustre-OST0001 complete [ 8828.175591] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_hostid [ 8835.540206] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing load_modules_local [ 8877.564815] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing load_modules_local [ 8885.745409] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 8886.103098] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 8886.159978] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 8886.252267] Lustre: lustre-MDT0000: new disk, initializing [ 8886.343775] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 8886.347776] Lustre: Skipped 1 previous similar message [ 8886.359509] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 8890.906446] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 8902.349195] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 8902.476221] Lustre: 216855: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 [ 8902.499589] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 8902.504078] Lustre: Skipped 1 previous similar message [ 8902.562162] Lustre: lustre-MDT0001: new disk, initializing [ 8902.614200] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 8902.631272] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 8902.641995] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 8908.018701] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 8912.629262] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 8917.793316] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 8917.951857] Lustre: lustre-OST0000: new disk, initializing [ 8917.955478] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 8917.961279] Lustre: 218452:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 8918.018793] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 8919.117677] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 8919.124893] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 8919.189325] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 8923.097941] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 8932.906930] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 8933.032245] Lustre: lustre-OST0001: new disk, initializing [ 8933.044048] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 8933.049773] Lustre: 219307:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 8933.126253] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 8934.945775] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 8934.955659] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 8935.056172] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 8939.642483] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 8949.184813] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 8952.872323] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 8977.710470] Lustre: DEBUG MARKER: == sanity-quota test 49b: lfs quota -a --blocks has a delimiter ========================================================== 04:31:29 (1778661089) [ 8986.247684] Lustre: DEBUG MARKER: == sanity-quota test 50: Test if lfs find --projid works ========================================================== 04:31:38 (1778661098) [ 9014.597866] Lustre: DEBUG MARKER: == sanity-quota test 51: Test project accounting with mv/cp ========================================================== 04:32:07 (1778661127) [ 9066.117408] Lustre: DEBUG MARKER: == sanity-quota test 52: Rename normal file across project ID ========================================================== 04:32:59 (1778661179) [ 9091.226576] Lustre: DEBUG MARKER: rename directory return 255 [ 9127.646939] Lustre: DEBUG MARKER: == sanity-quota test 53: Project inherit attribute could be cleared ========================================================== 04:34:00 (1778661240) [ 9149.192880] Lustre: DEBUG MARKER: == sanity-quota test 54: basic lfs project interface test ========================================================== 04:34:21 (1778661261) [ 9186.905275] Lustre: DEBUG MARKER: == sanity-quota test 55: Chgrp should be affected by group quota ========================================================== 04:34:59 (1778661299) [ 9263.985124] LustreError: 227821: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 [ 9291.700063] Lustre: DEBUG MARKER: == sanity-quota test 56: lfs quota -t should work well === 04:36:44 (1778661404) [ 9317.001430] Lustre: DEBUG MARKER: == sanity-quota test 57: lfs project could tolerate errors ========================================================== 04:37:09 (1778661429) [ 9344.136646] Lustre: DEBUG MARKER: == sanity-quota test 58: project ID should be kept for new mirrors created by FID ========================================================== 04:37:37 (1778661457) [ 9466.052946] Lustre: DEBUG MARKER: == sanity-quota test 59: lfs project dosen't crash kernel with project disabled ========================================================== 04:39:38 (1778661578) [ 9470.944269] LustreError: lustre-MDT0000-lwp-MDT0001: operation quota_acquire to node 0@lo failed: rc = -107 [ 9470.948591] 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 [ 9470.950637] LustreError: Skipped 1 previous similar message [ 9470.969358] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 9470.973372] Lustre: Skipped 1 previous similar message [ 9472.486779] 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 [ 9472.488805] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 9472.513427] Lustre: Skipped 2 previous similar messages [ 9472.517331] Lustre: Skipped 2 previous similar messages [ 9475.777300] Lustre: server umount lustre-MDT0000 complete [ 9477.601559] LustreError: 216863:0:(ldlm_lib.c:1180: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. [ 9477.634715] LustreError: 216863:0:(ldlm_lib.c:1180:target_handle_connect()) Skipped 5 previous similar messages [ 9480.451301] LustreError: 216847:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1778661594 with bad export cookie 3583037248421562406 [ 9480.453889] LustreError: MGC192.168.203.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 9480.471327] LustreError: 216847:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 9481.307250] Lustre: server umount lustre-MDT0001 complete [ 9495.702907] Lustre: server umount lustre-OST0000 complete [ 9498.400120] Lustre: 3662:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1778661596/real 1778661596] req@ffff93fdc4ab8000 x1865052071905536/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1778661612 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 9498.427973] Lustre: lustre-MDT0001-lwp-OST0001: Connection to lustre-MDT0001 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 9499.578387] Lustre: server umount lustre-OST0001 complete [ 9516.914145] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing load_modules_local [ 9526.439410] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 9526.772221] LustreError: 236574:0:(ldlm_lib.c:1180: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. [ 9526.858311] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 9526.882855] 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 [ 9530.182654] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 9531.872465] LustreError: 236575:0:(ldlm_lib.c:1180: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. [ 9536.857249] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 9536.996444] LustreError: 236574:0:(ldlm_lib.c:1180: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. [ 9537.154990] 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 [ 9540.987573] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 9543.373992] Lustre: 237685:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 9549.115628] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 9549.634498] 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 [ 9551.718885] LustreError: 238039:0:(ldlm_lib.c:1180:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 9551.768028] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:20 to 0x280000401:65) [ 9556.362361] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 9564.454426] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 9564.652809] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 9564.656037] Lustre: Skipped 2 previous similar messages [ 9564.670389] 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 [ 9569.802190] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:20 to 0x2c0000401:65) [ 9571.236523] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 9577.625340] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 9580.348261] Lustre: 239527:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 9586.169854] LustreError: 236569:0:(osd_handler.c:3426:osd_quota_transfer()) lustre-MDT0000: quota transfer failed. Is project enforcement enabled on the ldiskfs filesystem? rc = -95 [ 9590.247782] 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 [ 9590.251715] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 9590.267649] Lustre: Skipped 2 previous similar messages [ 9590.280471] Lustre: Skipped 4 previous similar messages [ 9595.365772] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 9595.380290] Lustre: Skipped 3 previous similar messages [ 9595.623442] Lustre: server umount lustre-MDT0000 complete [ 9598.905894] LustreError: 239529:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1778661712 with bad export cookie 3583037248421611322 [ 9598.909197] LustreError: MGC192.168.203.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 9598.913242] LustreError: 239529:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 9599.246489] Lustre: server umount lustre-MDT0001 complete [ 9610.207523] LustreError: 3663:0:(client.c:1380:ptlrpc_import_delay_req()) @@@ IMP_CLOSED req@ffff93fdcd5ace00 x1865052071956736/t0(0) o601->lustre-MDT0000-lwp-OST0000@0@lo:23/10 lens 336/336 e 0 to 0 dl 0 ref 1 fl Rpc:NQU/200/ffffffff rc 0/-1 job:'lquota_wb_lustr.0' uid:0 gid:0 projid:4294967295 [ 9610.232598] LustreError: 3663:0:(qsd_handler.c:298:qsd_req_completion()) $$$ DQACQ failed with -5, flags:0x8 qsd:lustre-OST0000 qtype:grp lqe: ffff93fdc14f8000 id:0 enforced:0 granted: 0 pending:0 waiting:0 req:1 usage: 1516 qunit:0 qtune:0 edquot:0 default:no revoke:0 [ 9610.254614] LustreError: 3663:0:(qsd_handler.c:298:qsd_req_completion()) Skipped 1 previous similar message [ 9612.817492] Lustre: server umount lustre-OST0000 complete [ 9626.464228] Lustre: server umount lustre-OST0001 complete [ 9642.937874] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing load_modules_local [ 9651.285359] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 9651.757688] LustreError: 241898:0:(ldlm_lib.c:1180: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. [ 9651.779588] LustreError: 241898:0:(ldlm_lib.c:1180:target_handle_connect()) Skipped 3 previous similar messages [ 9651.844523] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 9655.746621] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 9663.878991] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 9667.503575] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 9670.082645] Lustre: 243010:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 9676.040853] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 9677.382260] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:20 to 0x280000401:97) [ 9682.081114] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 9687.521683] LustreError: 243364:0:(ldlm_lib.c:1180:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 9687.545246] LustreError: 243364:0:(ldlm_lib.c:1180:target_handle_connect()) Skipped 4 previous similar messages [ 9690.739784] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 9696.239094] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:67 to 0x2c0000401:97) [ 9696.519467] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 9703.375750] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 9707.152396] Lustre: 244851:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 9731.598770] Lustre: DEBUG MARKER: == sanity-quota test 60: Test quota for root with setgid ========================================================== 04:44:04 (1778661844) [ 9773.396474] Lustre: DEBUG MARKER: SKIP: sanity-quota test_61 skipping SLOW test 61 [ 9774.910949] Lustre: DEBUG MARKER: == sanity-quota test 62: Project inherit should be only changed by root ========================================================== 04:44:47 (1778661887) [ 9793.746821] Lustre: DEBUG MARKER: SKIP: sanity-quota test_63 skipping excluded test 63 [ 9795.084691] Lustre: DEBUG MARKER: == sanity-quota test 64: lfs project on non-dir/files should succeed ========================================================== 04:45:08 (1778661908) [ 9833.494394] Lustre: DEBUG MARKER: SKIP: sanity-quota test_65 skipping excluded test 65 [ 9835.063682] Lustre: DEBUG MARKER: == sanity-quota test 66: nonroot user can not change project state in default ========================================================== 04:45:48 (1778661948) [ 9865.343578] Lustre: DEBUG MARKER: == sanity-quota test 67: quota pools recalculation ======= 04:46:18 (1778661978) [ 9875.841777] Lustre: DEBUG MARKER: User quota (block hardlimit:20 MB) [ 9880.892041] Lustre: 251407: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) [ 9880.908375] Lustre: 251407:0:(qsd_reint.c:245:qsd_reint_index()) Skipped 1 previous similar message [ 9884.804945] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 9888.934552] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 9892.438503] Lustre: DEBUG MARKER: Write... [ 9911.716860] LustreError: 252718:0:(mgs_handler.c:1140:mgs_iocontrol_pool()) OBD_IOC_POOL err -17, cmd CE021 for pool lustre.qpool1 [ 9917.132354] Lustre: DEBUG MARKER: Write... [ 9931.756878] Lustre: DEBUG MARKER: Write... [10009.017942] Lustre: DEBUG MARKER: == sanity-quota test 68: slave number in quota pool changed after each add/remove OST ========================================================== 04:48:41 (1778662121) [10034.361802] LustreError: 256783:0:(mgs_handler.c:1140:mgs_iocontrol_pool()) OBD_IOC_POOL err -17, cmd CE021 for pool lustre.qpool1 [10077.725347] Lustre: DEBUG MARKER: == sanity-quota test 69: EDQUOT at one of pools shouldn't affect DOM ========================================================== 04:49:50 (1778662190) [10103.000784] Lustre: DEBUG MARKER: User quota (block hardlimit:200 MB) [10106.055545] Lustre: DEBUG MARKER: User quota (block hardlimit:10 MB) [10193.436512] Lustre: DEBUG MARKER: == sanity-quota test 70a: check lfs setquota/quota with a pool option ========================================================== 04:51:46 (1778662306) [10233.254849] Lustre: DEBUG MARKER: == sanity-quota test 70b: lfs setquota pool works properly ========================================================== 04:52:26 (1778662346) [10274.984029] Lustre: DEBUG MARKER: == sanity-quota test 71a: Check PFL with quota pools ===== 04:53:07 (1778662387) [10287.332689] Lustre: DEBUG MARKER: User quota (block hardlimit:100 MB) [10308.023968] Lustre: DEBUG MARKER: Write... [10309.715963] Lustre: DEBUG MARKER: Write out of block quota ... [10389.927584] Lustre: DEBUG MARKER: == sanity-quota test 71b: Check SEL with quota pools ===== 04:55:02 (1778662502) [10402.126700] Lustre: DEBUG MARKER: User quota (block hardlimit:1000 MB) [10479.060642] Lustre: DEBUG MARKER: == sanity-quota test 72: lfs quota --pool prints only pool's OSTs ========================================================== 04:56:31 (1778662591) [10489.515688] Lustre: DEBUG MARKER: User quota (block hardlimit:50 MB) [10506.897506] Lustre: DEBUG MARKER: Write... [10508.846717] Lustre: DEBUG MARKER: Write out of block quota ... [10509.194885] LustreError: 243391: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 [10563.734745] Lustre: DEBUG MARKER: == sanity-quota test 73a: default limits at OST Pool Quotas ========================================================== 04:57:56 (1778662676) [10588.283695] Lustre: DEBUG MARKER: set to use default quota [10589.804348] Lustre: DEBUG MARKER: set default quota [10591.089511] Lustre: DEBUG MARKER: get default quota [10596.417429] Lustre: DEBUG MARKER: Test not out of quota [10599.931205] Lustre: DEBUG MARKER: Test out of quota [10609.715661] Lustre: DEBUG MARKER: Increase default quota [10629.700318] Lustre: DEBUG MARKER: Set quota to override default quota [10629.742751] LustreError: 252691: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:1779267543 qunit: 1024 edquot:0 may_rel:0 revoke:0 default:no [10640.420729] Lustre: DEBUG MARKER: Set to use default quota again [10659.046133] Lustre: DEBUG MARKER: Cleanup [10713.663692] Lustre: DEBUG MARKER: == sanity-quota test 73b: default OST Pool Quotas limit for new user ========================================================== 05:00:26 (1778662826) [10734.866334] Lustre: DEBUG MARKER: set default quota for qpool1 [10736.366616] Lustre: DEBUG MARKER: Write from user that hasn't lqe [10783.163283] Lustre: DEBUG MARKER: == sanity-quota test 74: check quota pools per user ====== 05:01:35 (1778662895) [10855.201865] Lustre: DEBUG MARKER: == sanity-quota test 75: nodemap squashed root respects quota enforcement ========================================================== 05:02:48 (1778662968) [10914.997660] Lustre: DEBUG MARKER: Write... [10917.609586] Lustre: DEBUG MARKER: Write out of block quota ... [11010.568227] Lustre: DEBUG MARKER: == sanity-quota test 76: project ID 4294967295 should be not allowed ========================================================== 05:05:23 (1778663123) [11043.805633] Lustre: DEBUG MARKER: == sanity-quota test 77: lfs setquota should fail in Lustre mount with 'ro' ========================================================== 05:05:56 (1778663156) [11051.478290] Lustre: DEBUG MARKER: == sanity-quota test 78A: Check fallocate increase quota usage ========================================================== 05:06:04 (1778663164) [11089.336829] Lustre: DEBUG MARKER: == sanity-quota test 78a: Check fallocate increase projectid usage ========================================================== 05:06:41 (1778663201) [11136.035406] Lustre: DEBUG MARKER: == sanity-quota test 79: access to non-existed dt-pool/info doesn't cause a panic ========================================================== 05:07:28 (1778663248) [11157.292949] Lustre: DEBUG MARKER: == sanity-quota test 80: check for EDQUOT after OST failover ========================================================== 05:07:50 (1778663270) [11184.341661] Lustre: *** cfs_fail_loc=a06, val=0*** [11184.346912] Lustre: Skipped 15 previous similar messages [11184.763880] LustreError: 241912:0:(qmt_lock.c:476:qmt_lvbo_update()) $$$ failed to release quota space on glimpse 0!=2048 : rc = -11 [11184.763880] qmt:lustre-QMT0000 pool:dt-0x0 id:60000 enforced:1 hard:102400 soft:0 granted:25600 time:0 qunit: 16384 edquot:0 may_rel:0 revoke:0 default:no [11189.865902] Lustre: Failing over lustre-OST0001 [11190.061050] LustreError: lustre-OST0001-osc-MDT0000: operation ost_destroy to node 0@lo failed: rc = -107 [11190.078660] LustreError: Skipped 2 previous similar messages [11190.083306] 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 [11190.094334] Lustre: Skipped 1 previous similar message [11190.100967] Lustre: lustre-OST0001: Not available for connect from 0@lo (stopping) [11191.266071] Lustre: lustre-OST0001: Not available for connect from 0@lo (stopping) [11191.270395] Lustre: lustre-OST0001-osc-MDT0001: Connection to lustre-OST0001 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [11192.323464] Lustre: server umount lustre-OST0001 complete [11194.042373] LustreError: 243364:0:(ldlm_lib.c:1180:target_handle_connect()) lustre-OST0001: not available for connect from 192.168.203.15@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [11194.065666] LustreError: 243364:0:(ldlm_lib.c:1180:target_handle_connect()) Skipped 2 previous similar messages [11200.891409] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [11201.213216] Lustre: lustre-OST0001: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [11201.255136] Lustre: lustre-OST0001: in recovery but waiting for the first client to connect [11202.984672] Lustre: lustre-OST0001: Will be in recovery for at least 1:00, or until 3 clients reconnect [11203.193544] Lustre: lustre-OST0001: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [11203.198233] Lustre: lustre-OST0001-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [11203.213801] Lustre: Skipped 3 previous similar messages [11206.746349] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [11248.926607] Lustre: DEBUG MARKER: == sanity-quota test 81: Race qmt_start_pool_recalc with qmt_pool_free ========================================================== 05:09:21 (1778663361) [11259.875773] Lustre: DEBUG MARKER: User quota (block hardlimit:20 MB) [11266.553911] LustreError: 296003:0:(qmt_pool.c:1399:qmt_pool_recalc()) cfs_fail_timeout id a07 sleeping for 10000ms [11270.850972] Lustre: lustre-MDT0000: Not available for connect from 192.168.203.15@tcp (stopping) [11270.862646] Lustre: Skipped 1 previous similar message [11271.648328] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [11271.656548] 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 [11273.184181] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [11273.194379] Lustre: Skipped 4 previous similar messages [11276.583128] LustreError: 296003:0:(qmt_pool.c:1399:qmt_pool_recalc()) cfs_fail_timeout id a07 awake [11276.777869] Lustre: server umount lustre-MDT0000 complete [11278.308663] LustreError: 241895:0:(ldlm_lib.c:1180: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. [11278.324237] LustreError: 241895:0:(ldlm_lib.c:1180:target_handle_connect()) Skipped 6 previous similar messages [11283.759458] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [11283.876677] LustreError: MGC192.168.203.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [11284.117091] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [11284.121469] Lustre: Skipped 3 previous similar messages [11284.182242] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:112 to 0x280000401:129) [11284.190401] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:113 to 0x2c0000401:129) [11288.063138] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [11289.577373] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [11289.581948] Lustre: Skipped 1 previous similar message [11315.141855] Lustre: DEBUG MARKER: == sanity-quota test 82: verify more than 8 qids for single operation ========================================================== 05:10:28 (1778663428) [11340.160853] Lustre: DEBUG MARKER: == sanity-quota test 83: Setting default quota shouldn't affect grace time ========================================================== 05:10:53 (1778663453) [11359.254089] Lustre: DEBUG MARKER: == sanity-quota test 84: Reset quota should fix the insane granted quota ========================================================== 05:11:12 (1778663472) [11403.091995] Lustre: *** cfs_fail_loc=a08, val=0*** [11403.101796] Lustre: Skipped 3232 previous similar messages [11403.107904] Lustre: *** cfs_fail_loc=a08, val=0*** [11403.109719] Lustre: Skipped 14 previous similar messages [11482.288796] Lustre: DEBUG MARKER: == sanity-quota test 85: do not hung at write with the least_qunit ========================================================== 05:13:15 (1778663595) [11505.228644] LustreError: 241897: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 [11548.537872] Lustre: DEBUG MARKER: == sanity-quota test 86: Pre-acquired quota should be released if quota is over limit ========================================================== 05:14:21 (1778663661) [11607.181229] LustreError: 243385: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:1779268520 qunit: 1024 edquot:0 may_rel:0 revoke:0 default:no [11745.439889] LustreError: 241894: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:1779268659 qunit: 1024 edquot:0 may_rel:0 revoke:0 default:no [11887.561264] LustreError: 252691: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:16384 time:1779268801 qunit: 1024 edquot:0 may_rel:0 revoke:0 default:no [11992.901712] Lustre: DEBUG MARKER: == sanity-quota test 87: lfs quota -a should print default quota setting ========================================================== 05:21:45 (1778664105) [11999.559560] Lustre: *** cfs_fail_loc=a09, val=0*** [11999.561398] Lustre: Skipped 1 previous similar message [12057.568574] 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 [12057.570092] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [12057.586346] Lustre: Skipped 5 previous similar messages [12057.611370] Lustre: Skipped 4 previous similar messages [12058.298524] Lustre: lustre-MDT0000: Not available for connect from 192.168.203.15@tcp (stopping) [12061.760921] Lustre: server umount lustre-MDT0000 complete [12062.691074] LustreError: 241894:0:(ldlm_lib.c:1180: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. [12062.721542] LustreError: 241894:0:(ldlm_lib.c:1180:target_handle_connect()) Skipped 8 previous similar messages [12067.821838] LustreError: 241894:0:(ldlm_lib.c:1180: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. [12067.851405] LustreError: 241894:0:(ldlm_lib.c:1180:target_handle_connect()) Skipped 4 previous similar messages [12070.087048] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [12070.260099] LustreError: MGC192.168.203.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [12070.633285] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [12070.731895] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:132 to 0x280000401:161) [12070.733261] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:113 to 0x2c0000401:161) [12075.013867] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [12076.002091] LustreError: lustre-MDT0000-osp-MDT0001: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [12076.027169] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [12076.039758] Lustre: Skipped 3 previous similar messages [12090.760169] Lustre: DEBUG MARKER: == sanity-quota test 88: Writing over quota should not hang ========================================================== 05:23:23 (1778664203) [12092.309428] Lustre: DEBUG MARKER: SKIP: sanity-quota test_88 require client with >4k pages [12094.010538] Lustre: DEBUG MARKER: == sanity-quota test 89: Show default quota with squash_uid ========================================================== 05:23:26 (1778664206) [12113.720037] Lustre: DEBUG MARKER: == sanity-quota test 90a: lfs quota should work without mount point ========================================================== 05:23:46 (1778664226) [12128.652330] Lustre: DEBUG MARKER: == sanity-quota test 90b: lfs quota should work with multiple mount points ========================================================== 05:24:01 (1778664241) [12146.955751] Lustre: DEBUG MARKER: == sanity-quota test 91: new quota index files in quota_master ========================================================== 05:24:19 (1778664259) [12163.041209] 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 [12163.048161] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [12163.048449] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [12163.055868] Lustre: Skipped 2 previous similar messages [12166.111431] LustreError: 3665:0:(client.c:1380:ptlrpc_import_delay_req()) @@@ IMP_CLOSED req@ffff93fdc2f4ea00 x1865052075640064/t0(0) o601->lustre-MDT0000-lwp-MDT0000@0@lo:23/10 lens 336/336 e 0 to 0 dl 0 ref 1 fl Rpc:NQU/200/ffffffff rc 0/-1 job:'lquota_wb_lustr.0' uid:0 gid:0 projid:4294967295 [12166.133612] LustreError: 3665:0:(client.c:1380:ptlrpc_import_delay_req()) Skipped 1 previous similar message [12166.143573] LustreError: 3665:0:(qsd_handler.c:298:qsd_req_completion()) $$$ DQACQ failed with -5, flags:0x8 qsd:lustre-MDT0000 qtype:prj lqe: ffff93fdd4f0b800 id:0 enforced:0 granted: 0 pending:0 waiting:0 req:1 usage: 322 qunit:0 qtune:0 edquot:0 default:no revoke:0 [12166.161303] LustreError: 3665:0:(qsd_handler.c:298:qsd_req_completion()) Skipped 5 previous similar messages [12168.164382] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [12168.174649] Lustre: Skipped 6 previous similar messages [12173.292118] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [12173.307837] Lustre: Skipped 3 previous similar messages [12176.351164] Lustre: lustre-MDT0000 is waiting for obd_unlinked_exports more than 8 seconds. The obd refcount = 3. Is it stuck? [12178.406028] LustreError: 243385:0:(ldlm_lib.c:1180: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. [12178.423523] LustreError: 243385:0:(ldlm_lib.c:1180:target_handle_connect()) Skipped 4 previous similar messages [12178.530263] Lustre: server umount lustre-MDT0000 complete [12182.016937] LustreError: 241878:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1778664295 with bad export cookie 3583037248422715796 [12182.020760] LustreError: MGC192.168.203.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [12182.032960] LustreError: 241878:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [12183.520470] Lustre: lustre-MDT0001-lwp-OST0001: Connection to lustre-MDT0001 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [12183.523231] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [12183.540304] Lustre: Skipped 3 previous similar messages [12183.555567] Lustre: Skipped 1 previous similar message [12187.560978] LustreError: 243385:0:(ldlm_lib.c:1180: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. [12187.579802] LustreError: 243385:0:(ldlm_lib.c:1180:target_handle_connect()) Skipped 3 previous similar messages [12188.626951] Lustre: server umount lustre-MDT0001 complete [12198.855142] Lustre: server umount lustre-OST0000 complete [12208.407657] Lustre: server umount lustre-OST0001 complete [12216.837684] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_hostid [12224.724720] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing load_modules_local [12260.486843] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [12260.786532] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [12260.818756] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [12260.894757] Lustre: lustre-MDT0000: new disk, initializing [12261.012087] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [12261.030069] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [12266.035618] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [12272.902938] Lustre: DEBUG MARKER: oleg315-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0000-mdc-*.mds_server_uuid [12279.476986] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [12279.661799] Lustre: lustre-OST0000: new disk, initializing [12279.666389] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [12279.671552] Lustre: Skipped 1 previous similar message [12279.676350] Lustre: 314411:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [12279.730137] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [12281.189541] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:0:ost [12281.198084] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:0:ost] [12281.232264] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x240000400 [12285.558229] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [12292.175789] Lustre: DEBUG MARKER: oleg315-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [12298.558168] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [12298.679580] Lustre: lustre-OST0001: new disk, initializing [12298.682723] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [12298.687894] Lustre: 315356:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [12298.732435] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [12300.352185] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:1:ost [12300.357593] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:1:ost] [12300.407227] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x280000400 [12304.038406] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [12311.127934] Lustre: DEBUG MARKER: oleg315-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0001-osc-[-0-9a-f]*.ost_server_uuid [12321.962199] Lustre: lustre-MDT0000: Not available for connect from 192.168.203.15@tcp (stopping) [12321.967897] Lustre: Skipped 2 previous similar messages [12324.281751] Lustre: server umount lustre-MDT0000 complete [12335.011812] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [12335.123422] LustreError: MGC192.168.203.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [12335.335176] 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 [12335.348332] Lustre: Skipped 1 previous similar message [12335.409393] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [12339.488358] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [12340.706785] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [12340.716245] Lustre: Skipped 2 previous similar messages [12341.727343] Lustre: 3664:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1778664439/real 1778664439] req@ffff93fdc4279880 x1865052075687808/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1778664455 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [12344.073097] Lustre: DEBUG MARKER: oleg315-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0000-mdc-*.mds_server_uuid [12345.511342] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [12346.670353] LustreError: 316919:0:(qmt_entry.c:1166:qmt_map_lge_idx()) qmt: cannot map ostidx 0, num_used 1: rc = -22 [12347.615453] Lustre: 3663:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1778664444/real 1778664444] req@ffff93fdc2f4f100 x1865052075688064/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1778664460 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [12347.641427] Lustre: 3663:0:(client.c:2479:ptlrpc_expire_one_request()) Skipped 1 previous similar message [12349.503291] LustreError: 316919:0:(qmt_entry.c:1166:qmt_map_lge_idx()) qmt: cannot map ostidx 0, num_used 1: rc = -22 [12352.234774] Lustre: server umount lustre-MDT0000 complete [12359.969265] LustreError: 313519:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1778664473 with bad export cookie 3583037248422718407 [12359.980757] LustreError: MGC192.168.203.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [12369.481175] Lustre: server umount lustre-OST0000 complete [12371.425593] Lustre: 3664:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1778664469/real 1778664469] req@ffff93fec7571f80 x1865052075702528/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1778664485 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [12371.452450] Lustre: 3664:0:(client.c:2479:ptlrpc_expire_one_request()) Skipped 1 previous similar message [12371.459351] 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 [12373.250441] Lustre: server umount lustre-OST0001 complete [12390.080879] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_hostid [12397.514555] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing load_modules_local [12443.092903] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing load_modules_local [12453.523937] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [12453.805836] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [12453.832372] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [12453.922755] Lustre: lustre-MDT0000: new disk, initializing [12454.013330] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [12454.043761] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [12459.127795] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [12469.935966] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [12470.020403] Lustre: 321570: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 [12470.039618] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [12470.043203] Lustre: Skipped 1 previous similar message [12470.091722] Lustre: lustre-MDT0001: new disk, initializing [12470.139129] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [12470.145630] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [12474.338661] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [12479.705234] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [12486.520056] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [12486.729137] Lustre: lustre-OST0000: new disk, initializing [12486.732305] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [12486.737114] Lustre: 323170:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [12488.053549] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [12488.065103] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [12488.271939] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [12492.726625] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [12503.770518] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [12503.969074] Lustre: lustre-OST0001: new disk, initializing [12503.976700] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [12503.989708] Lustre: 324023:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [12505.695786] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [12505.708044] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [12505.813058] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [12510.687980] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [12520.866265] Lustre: DEBUG MARKER: Using TIMEOUT=20 [12524.354986] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [12532.667090] Lustre: DEBUG MARKER: == sanity-quota test 92: Cannot set inode limit with Quota Pools ========================================================== 05:30:45 (1778664645) [12550.572964] Lustre: DEBUG MARKER: == sanity-quota test 93: update projid while client write to OST ========================================================== 05:31:03 (1778664663) [12572.831797] Lustre: *** cfs_fail_loc=170c, val=0*** [12627.824587] Lustre: DEBUG MARKER: == sanity-quota test 94: lfs quota all respects nodemap offset ========================================================== 05:32:20 (1778664740) [12659.697856] 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 [12659.705024] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [12659.730945] Lustre: Skipped 1 previous similar message [12659.739436] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [12659.785778] Lustre: Skipped 3 previous similar messages [12666.139995] Lustre: server umount lustre-MDT0000 complete [12669.098047] LustreError: 321580:0:(ldlm_lib.c:1180:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.203.15@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [12674.969586] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [12675.116445] LustreError: MGC192.168.203.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [12675.446635] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [12675.456598] Lustre: Skipped 3 previous similar messages [12675.499727] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3 to 0x280000401:33) [12680.682725] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [12680.686709] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [12680.691720] Lustre: Skipped 1 previous similar message [12680.724619] LustreError: lustre-MDT0000-osp-MDT0001: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [12690.917041] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [12690.927074] 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 [12690.945671] Lustre: Skipped 5 previous similar messages [12695.140336] LustreError: 329844:0:(ldlm_resource.c:1180:ldlm_resource_complain()) MGS: namespace resource [0x65727473756c:0x0:0x0].0x0 (ffff93fee11cf600) refcount nonzero (2) after lock cleanup; forcing cleanup. [12697.264920] Lustre: server umount lustre-MDT0000 complete [12701.154637] LustreError: 321579:0:(ldlm_lib.c:1180: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. [12701.176621] LustreError: 321579:0:(ldlm_lib.c:1180:target_handle_connect()) Skipped 17 previous similar messages [12705.003421] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [12705.158502] LustreError: MGC192.168.203.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [12705.557303] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3 to 0x280000401:65) [12709.469863] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [12710.882903] LustreError: lustre-MDT0000-osp-MDT0001: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [12715.977707] Lustre: DEBUG MARKER: == sanity-quota test 95a: Correct limits for squashed root ========================================================== 05:33:48 (1778664828) [12742.615289] Lustre: DEBUG MARKER: == sanity-quota test 95b: df respects squashed project id ========================================================== 05:34:15 (1778664855) [12777.112892] Lustre: DEBUG MARKER: == sanity-quota test 96: quota grant should be released when big files are deleted ========================================================== 05:34:49 (1778664889) [12778.985092] Lustre: DEBUG MARKER: SKIP: sanity-quota test_96 OST is too small, skip the test [12780.707055] Lustre: DEBUG MARKER: == sanity-quota test 97a: LQA control commands =========== 05:34:53 (1778664893) [12805.371705] LustreError: 334789:0:(qmt_lqa.c:79:qmt_lqa_destroy()) lustre-QMT0000: cannot destroy lqa-dt-lqa1: rc = -2 [12805.389594] LustreError: 334789:0:(qmt_lqa.c:84:qmt_lqa_destroy()) lustre-QMT0000: cannot destroy lqa-md-lqa1: rc = -2 [12807.414858] Lustre: DEBUG MARKER: == sanity-quota test 97b: Check LQA internals ============ 05:35:19 (1778664919) [12829.310900] LustreError: 335683:0:(qmt_lqa.c:250:qmt_lqa_insert_range()) lustre-QMT0000: LQA range 15-31 partially overlaps with existing range 10-19: rc = -34 [12829.335235] LustreError: 335683:0:(qmt_lqa.c:669:qmt_lqa_add()) lustre-QMT0000: lqa:lqa1 can't add range 15:31: rc = -17 [12834.534802] LustreError: 335880:0:(qmt_lqa.c:825:qmt_lqa_remove()) lustre-QMT0000: lqa-md-lqa1 cannot remove range 10:19: rc = -2 [12847.189431] Lustre: DEBUG MARKER: adding 50 LQA ranges took 2s [12853.173092] Lustre: DEBUG MARKER: Removing 50 LQA ranges took 2s [12861.634456] Lustre: DEBUG MARKER: == sanity-quota test 97c: LQA lfs quota commands and MDS restart consistency ========================================================== 05:36:14 (1778664974) [12865.920227] Lustre: Failing over lustre-MDT0000 [12866.254583] Lustre: server umount lustre-MDT0000 complete [12868.787311] LustreError: 321579:0:(ldlm_lib.c:1180:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.203.15@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [12868.804231] LustreError: 321579:0:(ldlm_lib.c:1180:target_handle_connect()) Skipped 1 previous similar message [12869.602733] 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 [12869.630643] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [12874.769156] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [12874.922891] LustreError: MGC192.168.203.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [12875.198583] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [12875.207465] Lustre: Skipped 1 previous similar message [12875.247443] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [12879.006734] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [12879.366204] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [12880.375201] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [12880.387943] Lustre: Skipped 7 previous similar messages [12880.416376] Lustre: lustre-MDT0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [12880.473415] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3 to 0x280000401:97) [12884.415683] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [12891.459511] Lustre: DEBUG MARKER: == sanity-quota test 97d: LQA disk persistence using standard commands ========================================================== 05:36:44 (1778665004) [12904.943357] Lustre: Failing over lustre-MDT0000 [12905.259291] Lustre: server umount lustre-MDT0000 complete [12905.951750] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [12913.285402] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [12913.456383] LustreError: MGC192.168.203.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [12913.817279] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [12914.847122] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [12918.251356] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [12918.806725] Lustre: lustre-MDT0000: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [12918.834201] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3 to 0x280000401:129) [12923.782050] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [12955.549647] Lustre: DEBUG MARKER: == sanity-quota test 98: Verify MDT retry on -EDQUOT during mkdir ========================================================== 05:37:47 (1778665067) [12959.449368] Lustre: DEBUG MARKER: oleg315-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0000-mdc-*.mds_server_uuid [12961.256303] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [12965.200547] Lustre: DEBUG MARKER: oleg315-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0001-mdc-*.mds_server_uuid [12967.069606] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [12973.145163] Lustre: *** cfs_fail_loc=a02, val=0*** [12983.869886] Lustre: DEBUG MARKER: == sanity-quota test complete, duration 12703 sec ======== 05:38:16 (1778665096) [12986.065636] Lustre: DEBUG MARKER: === sanity-quota: start cleanup 05:38:18 (1778665098) === [12989.972886] Lustre: DEBUG MARKER: === sanity-quota: finish cleanup 05:38:22 (1778665102) === [12995.553693] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [12995.553840] 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 [12995.554141] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [12995.554146] Lustre: Skipped 11 previous similar messages [12995.604580] Lustre: Skipped 10 previous similar messages [13001.494373] Lustre: server umount lustre-MDT0000 complete [13005.796194] LustreError: 321583:0:(ldlm_lib.c:1180: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. [13005.829894] LustreError: 321583:0:(ldlm_lib.c:1180:target_handle_connect()) Skipped 21 previous similar messages [13008.644927] LustreError: 321563:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1778665122 with bad export cookie 3583037248422724966 [13008.647727] LustreError: MGC192.168.203.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [13008.654032] LustreError: 321563:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [13008.893185] Lustre: server umount lustre-MDT0001 complete [13025.627238] Lustre: server umount lustre-OST0000 complete [13026.783215] Lustre: 3664:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1778665124/real 1778665124] req@ffff93fdcc3f3480 x1865052076049280/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1778665140 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [13029.855106] Lustre: 3662:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1778665127/real 1778665127] req@ffff93fedfd29f80 x1865052076049536/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1778665143 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [13031.967189] Lustre: 3662:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1778665129/real 1778665129] req@ffff93fdc90fdc00 x1865052076050048/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1778665145 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [13033.115796] Lustre: server umount lustre-OST0001 complete [13047.096616] Lustre: DEBUG MARKER: oleg315-server.virtnet: executing unload_modules_local [13050.076989] Key type lgssc unregistered [13050.419885] LNet: 344432:0:(lib-ptl.c:967:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [13050.431925] LNetError: 344432:0:(acceptor.c:246:lnet_acceptor_remove_socket()) Interface ens2 not found [13050.463229] LNet: Removed LNI 192.168.203.115@tcp [13051.421168] Key type .llcrypt unregistered [13051.425930] Key type ._llcrypt unregistered