[ 0.000000] Linux version 4.18.0rh8.10-debug (green@maintenance) (gcc version 8.5.0 20210514 (Red Hat 8.5.0-26) (GCC)) #2 SMP Mon Jul 14 01:24:22 EDT 2025 [ 0.000000] Command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers' [ 0.000000] x86/fpu: xstate_offset[2]: 576, xstate_sizes[2]: 256 [ 0.000000] x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'standard' format. [ 0.000000] signal: max sigframe size: 1776 [ 0.000000] BIOS-provided physical RAM map: [ 0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable [ 0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000000100000-0x00000000bffcdfff] usable [ 0.000000] BIOS-e820: [mem 0x00000000bffce000-0x00000000bfffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000100000000-0x0000000146dfffff] usable [ 0.000000] NX (Execute Disable) protection: active [ 0.000000] SMBIOS 2.8 present. [ 0.000000] DMI: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.17.0-10.fc44 06/10/2025 [ 0.000000] Hypervisor detected: KVM [ 0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00 [ 0.000000] kvm-clock: using sched offset of 524849655 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2399.998 MHz processor [ 0.000000] last_pfn = 0x146e00 max_arch_pfn = 0x400000000 [ 0.000000] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT [ 0.000000] last_pfn = 0xbffce max_arch_pfn = 0x400000000 [ 0.000000] found SMP MP-table at [mem 0x000f54b0-0x000f54bf] [ 0.000000] RAMDISK: [mem 0xbcc54000-0xbffbffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F52D0 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE247C 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE2318 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 0022D8 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE238C 000090 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE241C 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE2454 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe2318-0xbffe238b] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe2317] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe238c-0xbffe241b] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe241c-0xbffe2453] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe2454-0xbffe247b] [ 0.000000] No NUMA configuration found [ 0.000000] Faking a node at [mem 0x0000000000000000-0x0000000146dfffff] [ 0.000000] NODE_DATA(0) allocated [mem 0x1465a3000-0x1465cdfff] [ 0.000000] Reserving 256MB of memory at 2752MB for crashkernel (System RAM: 4205MB) [ 0.000000] Zone ranges: [ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.000000] DMA32 [mem 0x0000000001000000-0x00000000ffffffff] [ 0.000000] Normal [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Device empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff] [ 0.000000] node 0: [mem 0x0000000000100000-0x00000000bffcdfff] [ 0.000000] node 0: [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Zeroed struct page in unavailable ranges: 4756 pages [ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x0000000146dfffff] [ 0.000000] ACPI: PM-Timer IO Port: 0x608 [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) [ 0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) [ 0.000000] Using ACPI (MADT) for SMP configuration information [ 0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000] TSC deadline timer available [ 0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs [ 0.000000] kvm-guest: KVM setup pv remote TLB flush [ 0.000000] kvm-guest: setup PV sched yield [ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff] [ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff] [ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff] [ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff] [ 0.000000] PM: Registered nosave memory: [mem 0xbffce000-0xbfffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xc0000000-0xfeffbfff] [ 0.000000] PM: Registered nosave memory: [mem 0xfeffc000-0xfeffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xff000000-0xfffbffff] [ 0.000000] PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff] [ 0.000000] [mem 0xc0000000-0xfeffbfff] available for PCI devices [ 0.000000] Booting paravirtualized kernel on KVM [ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns [ 0.000000] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1 [ 0.000000] percpu: Embedded 63 pages/cpu s221184 r8192 d28672 u524288 [ 0.000000] kvm-guest: PV spinlocks enabled [ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1059606 [ 0.000000] Policy zone: Normal [ 0.000000] Kernel command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] Specific versions of hardware are certified with Red Hat Enterprise Linux 8. Please see the list of hardware certified with Red Hat Enterprise Linux 8 at https://catalog.redhat.com. [ 0.000000] audit: disabled (until reboot) [ 0.000000] software IO TLB: area num 4. [ 0.000000] Memory: 2829652K/4306352K available (18435K kernel code, 11221K rwdata, 7248K rodata, 2908K init, 18040K bss, 524580K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] ftrace: allocating 41240 entries in 162 pages [ 0.000000] ftrace: allocated 162 pages with 3 groups [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] rcu: RCU event tracing is enabled. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ 0.000000] rcu: RCU callback double-/use-after-free debug enabled. [ 0.000000] Rude variant of Tasks RCU enabled. [ 0.000000] Tracing variant of Tasks RCU enabled. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 0.000000] NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16 [ 0.000000] random: get_random_bytes called from start_kernel+0x622/0x9a8 with crng_init=0 [ 0.001000] Console: colour *CGA 80x25 [ 0.001000] printk: console [ttyS1] enabled [ 0.001000] ACPI: Core revision 20220331 [ 0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.001011] APIC: Switch to symmetric I/O mode setup [ 0.003265] x2apic enabled [ 0.004008] Switched APIC routing to physical x2apic. [ 0.005016] kvm-guest: setup PV IPIs [ 0.008479] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.009000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.009022] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.010012] pid_max: default: 32768 minimum: 301 [ 0.011141] LSM: Security Framework initializing [ 0.012054] Yama: becoming mindful. [ 0.013038] SELinux: Initializing. [ 0.014079] *** VALIDATE selinux *** [ 0.021850] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.027012] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.028149] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.030113] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.031104] *** VALIDATE tmpfs *** [ 0.033128] *** VALIDATE proc *** [ 0.034237] *** VALIDATE cgroup *** [ 0.035009] *** VALIDATE cgroup2 *** [ 0.037041] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.038147] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.039008] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.040027] Spectre V2 : User space: Vulnerable [ 0.041009] Speculative Store Bypass: Vulnerable [ 0.044081] debug: unmapping init [mem 0xffffffffa4459000-0xffffffffa4460fff] [ 0.047151] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.048646] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.049025] ... version: 2 [ 0.050015] ... bit width: 48 [ 0.051016] ... generic registers: 4 [ 0.052015] ... value mask: 0000ffffffffffff [ 0.053016] ... max period: 00007fffffffffff [ 0.054016] ... fixed-purpose events: 3 [ 0.055013] ... event mask: 000000070000000f [ 0.056307] rcu: Hierarchical SRCU implementation. [ 0.058448] smp: Bringing up secondary CPUs ... [ 0.059574] x86: Booting SMP configuration: [ 0.060031] .... node #0, CPUs: #1 #2 #3 [ 0.066507] smp: Brought up 1 node, 4 CPUs [ 0.068013] smpboot: Max logical packages: 1 [ 0.069024] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.292111] node 0 deferred pages initialised in 220ms [ 0.295090] devtmpfs: initialized [ 0.296264] x86/mm: Memory block size: 128MB [ 0.300085] gcov: version magic: 0x41383552 [ 0.303303] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.306095] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.308410] pinctrl core: initialized pinctrl subsystem [ 0.311185] [ 0.311715] ************************************************************* [ 0.314015] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.316015] ** ** [ 0.319013] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.321013] ** ** [ 0.324014] ** This means that this kernel is built to expose internal ** [ 0.326011] ** IOMMU data structures, which may compromise security on ** [ 0.329014] ** your system. ** [ 0.332032] ** ** [ 0.334012] ** If you see this message and you are not debugging the ** [ 0.337014] ** kernel, report this immediately to your vendor! ** [ 0.339011] ** ** [ 0.342013] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.344012] ************************************************************* [ 0.347866] NET: Registered protocol family 16 [ 0.349514] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.352058] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.355062] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.359029] cpuidle: using governor menu [ 0.360903] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.363531] PCI: Using configuration type 1 for base access [ 0.366136] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.377122] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.380025] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.385060] cryptd: max_cpu_qlen set to 1000 [ 0.390338] ACPI: Added _OSI(Module Device) [ 0.392018] ACPI: Added _OSI(Processor Device) [ 0.393014] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.395014] ACPI: Added _OSI(Processor Aggregator Device) [ 0.400420] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.406521] ACPI: Interpreter enabled [ 0.408049] ACPI: PM: (supports S0 S3 S4 S5) [ 0.410026] ACPI: Using IOAPIC for interrupt routing [ 0.412100] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.416416] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.425581] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.428037] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.430016] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.433091] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.438290] acpiphp: Slot [2] registered [ 0.440136] acpiphp: Slot [5] registered [ 0.442091] acpiphp: Slot [6] registered [ 0.443139] acpiphp: Slot [7] registered [ 0.445157] acpiphp: Slot [8] registered [ 0.446109] acpiphp: Slot [9] registered [ 0.447117] acpiphp: Slot [10] registered [ 0.449114] acpiphp: Slot [3] registered [ 0.450101] acpiphp: Slot [4] registered [ 0.452106] acpiphp: Slot [11] registered [ 0.453112] acpiphp: Slot [12] registered [ 0.455099] acpiphp: Slot [13] registered [ 0.456220] acpiphp: Slot [14] registered [ 0.458095] acpiphp: Slot [15] registered [ 0.460159] acpiphp: Slot [16] registered [ 0.461092] acpiphp: Slot [17] registered [ 0.463124] acpiphp: Slot [18] registered [ 0.464106] acpiphp: Slot [19] registered [ 0.466110] acpiphp: Slot [20] registered [ 0.467108] acpiphp: Slot [21] registered [ 0.469109] acpiphp: Slot [22] registered [ 0.470168] acpiphp: Slot [23] registered [ 0.471079] acpiphp: Slot [24] registered [ 0.473136] acpiphp: Slot [25] registered [ 0.474092] acpiphp: Slot [26] registered [ 0.475091] acpiphp: Slot [27] registered [ 0.477091] acpiphp: Slot [28] registered [ 0.478132] acpiphp: Slot [29] registered [ 0.480083] acpiphp: Slot [30] registered [ 0.481119] acpiphp: Slot [31] registered [ 0.482076] PCI host bridge to bus 0000:00 [ 0.484021] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.486021] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.488023] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.491023] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.493021] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.496024] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.498180] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.501026] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.504312] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.513826] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.520043] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.522020] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.524018] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.527301] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.530387] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.532749] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.535052] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.538806] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.543015] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.556872] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.561946] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.568439] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.610023] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.653017] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.716015] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.730036] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.755021] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.784019] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.829026] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.854038] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.861036] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.867025] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.893017] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.909145] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.917016] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.932017] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.954023] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.971445] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.986016] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.997028] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 1.031019] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 1.048845] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 1.071018] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 1.086017] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 1.147024] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 1.165653] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 1.168377] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 1.171404] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 1.174820] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 1.177252] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 1.182095] iommu: Default domain type: Passthrough [ 1.184446] SCSI subsystem initialized [ 1.186135] ACPI: bus type USB registered [ 1.188128] usbcore: registered new interface driver usbfs [ 1.190084] usbcore: registered new interface driver hub [ 1.192086] usbcore: registered new device driver usb [ 1.194181] pps_core: LinuxPPS API ver. 1 registered [ 1.196013] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 1.199084] PTP clock support registered [ 1.201121] EDAC MC: Ver: 3.0.0 [ 1.203146] PCI: Using ACPI for IRQ routing [ 1.205165] NetLabel: Initializing [ 1.206011] NetLabel: domain hash size = 128 [ 1.208016] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 1.210099] NetLabel: unlabeled traffic allowed by default [ 1.214048] vgaarb: loaded [ 1.216358] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 1.217017] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 1.222000] clocksource: Switched to clocksource kvm-clock [ 1.335301] VFS: Disk quotas dquot_6.6.0 [ 1.336893] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 1.339590] *** VALIDATE ramfs *** [ 1.340916] *** VALIDATE hugetlbfs *** [ 1.342540] pnp: PnP ACPI init [ 1.344842] pnp: PnP ACPI: found 6 devices [ 1.379095] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 1.382717] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 1.385101] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 1.387564] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 1.390040] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 1.392659] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 1.395690] NET: Registered protocol family 2 [ 1.398298] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 1.403660] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 1.407289] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 1.412507] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 1.415923] TCP: Hash tables configured (established 65536 bind 65536) [ 1.418917] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 1.422060] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 1.425105] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 1.428451] NET: Registered protocol family 1 [ 1.432221] RPC: Registered named UNIX socket transport module. [ 1.434542] RPC: Registered udp transport module. [ 1.436498] RPC: Registered tcp transport module. [ 1.438342] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 1.440729] NET: Registered protocol family 44 [ 1.442247] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 1.444291] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 1.446283] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 1.448658] PCI: CLS 0 bytes, default 64 [ 1.450297] Unpacking initramfs... [ 2.849440] debug: unmapping init [mem 0xffff8cd7bcc54000-0xffff8cd7bffbffff] [ 2.853822] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.856937] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.860693] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 3.378213] Initialise system trusted keyrings [ 3.379494] Key type blacklist registered [ 3.380901] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 3.389866] zbud: loaded [ 3.392736] *** VALIDATE nfs *** [ 3.393796] *** VALIDATE nfs4 *** [ 3.395343] pstore: using deflate compression [ 3.399444] Platform Keyring initialized [ 3.508434] NET: Registered protocol family 38 [ 3.510558] Key type asymmetric registered [ 3.512022] Asymmetric key parser 'x509' registered [ 3.513810] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 3.517311] io scheduler mq-deadline registered [ 3.519143] io scheduler kyber registered [ 3.520649] io scheduler bfq registered [ 3.523418] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 3.526374] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 3.529320] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 3.532025] ACPI: Power Button [PWRF] [ 3.537476] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 3.543678] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 3.570250] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 3.578117] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 3.597055] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 3.624115] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.652119] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.656938] Non-volatile memory driver v1.3 [ 3.659142] Linux agpgart interface v0.103 [ 3.696803] virtio_blk virtio1: [vda] 146672 512-byte logical blocks (75.1 MB/71.6 MiB) [ 3.699717] vda: detected capacity change from 0 to 75096064 [ 3.716544] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.719665] vdb: detected capacity change from 0 to 1073741824 [ 3.734492] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.737473] vdc: detected capacity change from 0 to 2621440000 [ 3.756396] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.759323] vdd: detected capacity change from 0 to 2621440000 [ 3.776711] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.780018] vde: detected capacity change from 0 to 4294967296 [ 3.804644] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.808482] vdf: detected capacity change from 0 to 4294967296 [ 3.826645] libphy: Fixed MDIO Bus: probed [ 3.839267] usbcore: registered new interface driver usbserial_generic [ 3.841918] usbserial: USB Serial support registered for generic [ 3.844279] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.848930] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.850963] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.853773] mousedev: PS/2 mouse device common for all mice [ 3.857390] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.857523] rtc_cmos 00:05: RTC can wake from S4 [ 3.864292] rtc_cmos 00:05: registered as rtc0 [ 3.865791] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.868800] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.869584] intel_pstate: CPU model not supported [ 3.873054] hid: raw HID events driver (C) Jiri Kosina [ 3.879316] usbcore: registered new interface driver usbhid [ 3.881185] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.882308] usbhid: USB HID core driver [ 3.882449] drop_monitor: Initializing network drop monitor service [ 3.882574] Initializing XFRM netlink socket [ 3.883982] NET: Registered protocol family 10 [ 3.893969] Segment Routing with IPv6 [ 3.895670] NET: Registered protocol family 17 [ 3.897933] mpls_gso: MPLS GSO support [ 3.904928] RAS: Correctable Errors collector initialized. [ 3.907196] AVX version of gcm_enc/dec engaged. [ 3.908850] AES CTR mode by8 optimization enabled [ 3.994359] sched_clock: Marking stable (3994333719, 0)->(4909720312, -915386593) [ 3.997913] registered taskstats version 1 [ 3.999756] Loading compiled-in X.509 certificates [ 4.001743] zswap: loaded using pool lzo/zbud [ 4.029923] Key type big_key registered [ 4.044000] Key type encrypted registered [ 4.045360] ima: No TPM chip found, activating TPM-bypass! [ 4.047254] ima: Allocated hash algorithm: sha1 [ 4.048934] ima: No architecture policies found [ 4.050652] evm: Initialising EVM extended attributes: [ 4.052606] evm: security.selinux [ 4.053810] evm: security.ima [ 4.054898] evm: security.capability [ 4.056355] evm: HMAC attrs: 0x1 [ 4.058767] rtc_cmos 00:05: setting system clock to 2026-08-27 14:22:25 UTC (1787840545) [ 4.064672] debug: unmapping init [mem 0xffffffffa5403000-0xffffffffa55fffff] [ 4.067718] debug: unmapping init [mem 0xffffffffa4182000-0xffffffffa4458fff] [ 4.075109] Write protecting the kernel read-only data: 28672k [ 4.078488] debug: unmapping init [mem 0xffffffffa2803000-0xffffffffa29fffff] [ 4.081584] debug: unmapping init [mem 0xffffffffa3114000-0xffffffffa31fffff] [ 4.118759] 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) [ 4.127179] systemd[1]: Detected virtualization kvm. [ 4.129322] systemd[1]: Detected architecture x86-64. [ 4.131417] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 4.159850] systemd[1]: No hostname configured. [ 4.161392] systemd[1]: Set hostname to . [ 4.163284] random: systemd: uninitialized urandom read (16 bytes read) [ 4.165301] systemd[1]: Initializing machine ID from random generator. [ 4.211438] random: ln: uninitialized urandom read (6 bytes read) [ 4.308690] random: systemd: uninitialized urandom read (16 bytes read) [ 4.311112] systemd[1]: Listening on udev Kernel Socket. [ OK ] Listening on udev Kernel Socket. [ 4.315898] systemd[1]: Reached target Timers. [ OK ] Reached target Timers. [ 4.320533] systemd[1]: Reached target Initrd Root Device. [ OK ] Reached target Initrd Root Device. [ OK ] Listening on Journal Socket. Starting Setup Virtual Console... Starting Apply Kernel Variables... Starting Create list of required st…ce nodes for the current kernel... [ OK ] Started Memstrack Anylazing Service. [ OK ] Reached target Slices. [ OK ] Reached target Local File Systems. Starting Create Volatile Files and Directories... [ OK ] Listening on udev Control Socket. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Paths. [ OK ] Reached target Swap. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Listening on Journal Socket (/dev/log). [ OK ] Reached target Sockets. Starting Journal Service... [ OK ] Started Setup Virtual Console. [ OK ] Started Apply Kernel Variables. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Create Volatile Files and Directories. Starting Create Static Device Nodes in /dev... Starting dracut cmdline hook... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started Journal Service. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 4.910726] device-mapper: uevent: version 1.0.3 [ 4.912883] 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... [ 5.264747] random: fast init done Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting dracut initqueue hook... [ 5.594809] virtio_net virtio0 ens2: renamed from eth0 [ 5.620492] scsi host0: ata_piix [ 5.635502] scsi host1: ata_piix [ 5.637208] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 5.639762] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 10.100852] dracut-initqueue[580]: RTNETLINK answers: File exists [ 10.560665] random: crng init done [ 10.561933] random: 7 urandom warning(s) missed due to ratelimiting Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. Mounting /sysroot... [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. [ 11.498831] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped target Timers. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Slices. [ OK ] Stopped target Sockets. [ OK ] Stopped target Paths. [ OK ] Stopped target System Initialization. [ OK ] Stopped target Swap. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. Stopping udev Kernel Device Manager... [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Closed udev Kernel Socket. [ OK ] Closed udev Control Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 13.202071] printk: systemd: 26 output lines suppressed due to ratelimiting [ 13.450313] SELinux: Disabled at runtime. [ 13.511981] 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) [ 13.518926] systemd[1]: Detected virtualization kvm. [ 13.520429] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 14.001294] systemd[1]: initrd-switch-root.service: Succeeded. [ 14.004176] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 14.008772] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 14.014277] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 14.017438] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 14.031808] systemd[1]: Starting Journal Service... Starting Journal Service... [ 14.039887] systemd[1]: Listening on initctl Compatibility Named Pipe. [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Listening on Process Core Dump Socket. Mounting Kernel Debug File System... [ OK ] Created slice system-getty.slice. [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Created slice User and Session Slice. [ OK ] Reached target Slices. Starting Create list of required st…ce nodes for the current kernel... Mounting POSIX Message Queue File System... Starting Remount Root and Kernel File Systems... [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Reached target rpc_pipefs.target. Starting Apply Kernel Variables... [ OK ] Listening on udev Control Socket. [ OK ] Started Dispatch Password Requests to Console Directory Watch. Activating swap /dev/disk/by-label/SWAP... Mounting Huge Pages File System... [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd File Systems. [ OK ] Stopped target Initrd Root File System. [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ 14.238566] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS [ OK ] Reached target Paths. [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Reached target RPC Port Mapper. [ OK ] Listening on udev Kernel Socket. Starting udev Coldplug all Devices... [ OK ] Started Journal Service. [ OK ] Mounted Kernel Debug 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 ] Started Apply Kernel Variables. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Mounted Huge Pages File System. [ OK ] Reached target Swap. Starting Configure read-only root support... Starting Create Static Device Nodes in /dev... Starting Flush Journal to Persistent Storage... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started udev Coldplug all Devices. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Reached target Local File Systems (Pre). Mounting /mnt... Mounting /home/green/git/lustre-release... Starting udev Kernel Device Manager... [ OK ] Mounted /mnt. [ 14.601342] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 14.945324] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 14.987970] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 15.053432] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 15.110372] EDAC sbridge: Ver: 1.1.2 [ 17.558942] Key type dns_resolver registered [ 17.872387] NFS: Registering the id_resolver key type [ 17.874246] Key type id_resolver registered [ 17.875674] Key type id_legacy registered [ OK ] Started Configure read-only root support. [ OK ] Reached target Local File Systems. Starting Rebuild Dynamic Linker Cache... Starting Mark the need to relabel after reboot... Starting Create Volatile Files and Directories... Starting Load/Save Random Seed... [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Load/Save Random Seed. Starting RPC Bind... Starting Update UTMP about System Boot/Shutdown... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Started dnf makecache --timer. [ OK ] Reached target Timers. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. [ OK ] Started irqbalance daemon. [ OK ] Started D-Bus System Message Bus. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting Restore /run/initramfs on shutdown... Starting Network Manager... Starting Login Service... [ OK ] Reached target sshd-keygen.target. [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Network Manager. [ OK ] Reached target Network. Starting OpenSSH server daemon... Starting Dynamic System Tuning Daemon... Starting GSSAPI Proxy Daemon... Starting Network Manager Wait Online... [ OK ] Started Login Service. [ OK ] Started OpenSSH server daemon. Starting Hostname Service... [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... [ OK ] Started Permit User Sessions. [ OK ] Started Getty on tty1. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Serial Getty on ttyS1. [ OK ] Reached target Login Prompts. [ OK ] Started Command Scheduler. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting Notify NFS peers of a restart... Starting Crash recovery kernel arming... Starting System Logging Service... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Starting Authorization Manager... [ OK ] Started Authorization Manager. [ OK ] Started Dynamic System Tuning Daemon. [ OK ] Reached target Multi-User System. [ OK ] Reached target Graphical Interface. Starting Update UTMP about System Runlevel Changes... [ OK ] Started Update UTMP about System Runlevel Changes. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg127-server login: [ 46.063728] libcfs: loading out-of-tree module taints kernel. [ 46.083049] Key type ._llcrypt registered [ 46.084780] Key type .llcrypt registered [ 46.137125] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_hostid [ 55.062787] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing load_modules_local [ 55.749932] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 55.757472] alg: No test for adler32 (adler32-zlib) [ 56.801072] Lustre: Lustre: Build Version: 2.17.57_65_g89f8e4a [ 57.145433] LNet: Added LNI 192.168.201.127@tcp [8/256/0/180] [ 58.793397] Key type lgssc registered [ 61.380200] Lustre: Echo OBD driver; http://www.lustre.org/ [ 80.383008] hrtimer: interrupt took 4999271 ns [ 81.390990] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 123.537862] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing load_modules_local [ 135.730493] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 135.788432] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 137.060683] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 137.084167] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 137.151316] Lustre: lustre-MDT0000: new disk, initializing [ 137.207142] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 137.220578] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 141.785818] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 155.534731] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 155.677600] Lustre: 6489:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 155.718912] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 155.723531] Lustre: Skipped 1 previous similar message [ 155.902547] Lustre: lustre-MDT0001: new disk, initializing [ 155.986961] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 156.051161] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 156.065460] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 160.347314] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 165.678736] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 175.620096] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 175.868603] Lustre: lustre-OST0000: new disk, initializing [ 175.875577] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 175.885902] Lustre: 8425:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 175.982874] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 178.084634] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 178.093753] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 178.204353] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 182.055868] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 195.458885] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 195.611558] Lustre: lustre-OST0001: new disk, initializing [ 195.616343] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 195.621311] Lustre: 9497:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 195.693086] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 202.112177] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 205.374167] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 205.388893] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 205.453588] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 214.383578] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 220.059681] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 225.483439] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing check_logdir /tmp/testlogs/ [ 229.822633] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing yml_node [ 234.167869] Lustre: DEBUG MARKER: Client: 2.17.57.65 [ 237.008915] Lustre: DEBUG MARKER: MDS: 2.17.57.65 [ 239.605605] Lustre: DEBUG MARKER: OSS: 2.17.57.65 [ 241.430363] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity-quota ============----- Thu Aug 27 10:26:20 EDT 2026 [ 261.370061] Lustre: DEBUG MARKER: excepting tests: 2 4a 63 65 [ 263.299487] Lustre: DEBUG MARKER: skipping tests SLOW=no: 61 [ 266.906426] Lustre: DEBUG MARKER: === sanity-quota: start setup 10:26:45 (1787840805) === [ 275.953912] Lustre: DEBUG MARKER: oleg127-client.virtnet: executing check_config_client /mnt/lustre [ 305.763606] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 310.933971] Lustre: 13406:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 315.555581] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 323.382682] Lustre: DEBUG MARKER: === sanity-quota: finish setup 10:27:42 (1787840862) === [ 394.196959] Lustre: DEBUG MARKER: == sanity-quota test 0: Test basic quota performance ===== 10:28:53 (1787840933) [ 442.512549] Lustre: DEBUG MARKER: == sanity-quota test 1a: Block hard limit (normal use and out of quota) ========================================================== 10:29:41 (1787840981) [ 455.634849] Lustre: DEBUG MARKER: User quota (block hardlimit:10 MB) [ 464.159730] Lustre: DEBUG MARKER: Write... [ 467.692804] Lustre: DEBUG MARKER: Write out of block quota ... [ 511.162619] Lustre: DEBUG MARKER: -------------------------------------- [ 515.762539] Lustre: DEBUG MARKER: Group quota (block hardlimit:10 MB) [ 529.354880] Lustre: DEBUG MARKER: Write... [ 533.377559] Lustre: DEBUG MARKER: Write out of block quota ... [ 591.918312] Lustre: DEBUG MARKER: -------------------------------------- [ 594.415094] Lustre: DEBUG MARKER: Project quota (block hardlimit:10 mb) [ 599.859991] Lustre: DEBUG MARKER: Write... [ 603.044608] Lustre: DEBUG MARKER: Write out of block quota ... [ 660.771622] Lustre: DEBUG MARKER: == sanity-quota test 1b: Quota pools: Block hard limit (normal use and out of quota) ========================================================== 10:33:19 (1787841199) [ 673.478393] Lustre: DEBUG MARKER: User quota (block hardlimit:20 MB) [ 698.932833] Lustre: DEBUG MARKER: Write... [ 702.189068] Lustre: DEBUG MARKER: Write out of block quota ... [ 738.010911] Lustre: DEBUG MARKER: -------------------------------------- [ 739.809801] Lustre: DEBUG MARKER: Group quota (block hardlimit:20 MB) [ 748.242478] Lustre: DEBUG MARKER: Write... [ 750.467831] Lustre: DEBUG MARKER: Write out of block quota ... [ 788.189385] Lustre: DEBUG MARKER: -------------------------------------- [ 790.044195] Lustre: DEBUG MARKER: Project quota (block hardlimit:20 mb) [ 793.321341] Lustre: DEBUG MARKER: Write... [ 795.935916] Lustre: DEBUG MARKER: Write out of block quota ... [ 855.660925] Lustre: DEBUG MARKER: == sanity-quota test 1c: Quota pools: check 3 pools with hardlimit only for global ========================================================== 10:36:34 (1787841394) [ 866.079498] Lustre: DEBUG MARKER: User quota (block hardlimit:20 MB) [ 898.780425] Lustre: DEBUG MARKER: Write... [ 904.478644] Lustre: DEBUG MARKER: Write out of block quota ... [ 1010.485107] Lustre: DEBUG MARKER: == sanity-quota test 1d: Quota pools: check block hardlimit on different pools ========================================================== 10:39:08 (1787841548) [ 1025.658717] Lustre: DEBUG MARKER: User quota (block hardlimit:20 MB) [ 1054.137407] Lustre: DEBUG MARKER: Write... [ 1056.796693] Lustre: DEBUG MARKER: Write out of block quota ... [ 1152.865580] Lustre: DEBUG MARKER: == sanity-quota test 1e: Quota pools: global pool high block limit vs quota pool with small ========================================================== 10:41:32 (1787841692) [ 1168.345562] Lustre: DEBUG MARKER: User quota (block hardlimit:53000000 MB) [ 1185.243474] Lustre: DEBUG MARKER: Write... [ 1188.827838] Lustre: DEBUG MARKER: Write out of block quota ... [ 1206.072571] Lustre: DEBUG MARKER: Write... [ 1262.198644] Lustre: DEBUG MARKER: == sanity-quota test 1f: Quota pools: correct qunit after removing/adding OST ========================================================== 10:43:21 (1787841801) [ 1275.116626] Lustre: DEBUG MARKER: User quota (block hardlimit:200 MB) [ 1294.546793] Lustre: DEBUG MARKER: Write... [ 1297.508174] Lustre: DEBUG MARKER: Write out of block quota ... [ 1339.252189] Lustre: DEBUG MARKER: Write... [ 1341.829243] Lustre: DEBUG MARKER: Write out of block quota ... [ 1394.283306] Lustre: DEBUG MARKER: == sanity-quota test 1g: Quota pools: Block hard limit with wide striping ========================================================== 10:45:33 (1787841933) [ 1408.516964] Lustre: DEBUG MARKER: User quota (block hardlimit:40 MB) [ 1424.906613] Lustre: 33093:0:(osd_handler.c:2191:osd_trans_start()) lustre-MDT0000: credits 6570 > trans_max 3200 [ 1424.912625] Lustre: 33093:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 4/16/0, destroy: 0/0/0 [ 1424.917918] Lustre: 33093:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 401/401/0, xattr_set: 602/5615/0 [ 1424.922747] Lustre: 33093:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 20/142/0, punch: 0/0/0, quota 8/328/0 [ 1424.928140] Lustre: 33093:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/68/0, delete: 0/0/0 [ 1424.932737] Lustre: 33093:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 1424.937471] CPU: 3 PID: 33093 Comm: mdt00_005 Kdump: loaded Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 1424.941497] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.17.0-10.fc44 06/10/2025 [ 1424.945480] Call Trace: [ 1424.946608] ? dump_stack+0xbb/0x10e [ 1424.947892] ? osd_trans_start+0x8db/0x9d0 [osd_ldiskfs] [ 1424.950128] ? dt_trans_start+0x1c/0x70 [obdclass] [ 1424.952672] ? top_trans_start+0x4fd/0xd00 [ptlrpc] [ 1424.955476] ? lod_xattr_list+0x30/0x30 [lod] [ 1424.957440] ? lod_trans_start+0x109/0x4c0 [lod] [ 1424.959663] ? mdd_declare_attr_set+0x91/0x880 [mdd] [ 1424.962219] ? mdd_env_info+0x25/0xc0 [mdd] [ 1424.964594] ? mdd_trans_start+0x18/0x30 [mdd] [ 1424.966596] ? mdd_attr_set+0xa5a/0x1330 [mdd] [ 1424.968715] ? mdt_reint_setattr+0x14aa/0x2030 [mdt] [ 1424.971475] ? mdt_reint_setattr+0x14aa/0x2030 [mdt] [ 1424.973741] ? mdt_reint_rec+0x139/0x2b0 [mdt] [ 1424.975560] ? mdt_reint_internal+0x693/0xdc0 [mdt] [ 1424.978492] ? mdt_reint+0x163/0x190 [mdt] [ 1424.980696] ? tgt_handle_request0+0x137/0xaf0 [ptlrpc] [ 1424.983492] ? tgt_request_handle+0x575/0x1f70 [ptlrpc] [ 1424.985946] ? ptlrpc_server_handle_request+0x443/0x13b0 [ptlrpc] [ 1424.989546] ? lprocfs_counter_add+0x15b/0x210 [obdclass] [ 1424.991814] ? ptlrpc_main+0xce8/0x1400 [ptlrpc] [ 1424.998644] ? ptlrpc_wait_event+0x690/0x690 [ptlrpc] [ 1425.001935] ? kthread+0x1d1/0x200 [ 1425.003105] ? set_kthread_struct+0x70/0x70 [ 1425.004923] ? ret_from_fork+0x1f/0x30 [ 1426.809327] Lustre: DEBUG MARKER: Write... [ 1442.137704] Lustre: DEBUG MARKER: Write out of block quota ... [ 1518.272378] Lustre: DEBUG MARKER: == sanity-quota test 1h: Block hard limit test using fallocate ========================================================== 10:47:37 (1787842057) [ 1533.938908] Lustre: DEBUG MARKER: User quota (block hardlimit:10 MB) [ 1541.070500] Lustre: DEBUG MARKER: Write 5MiB Using Fallocate [ 1549.811796] Lustre: DEBUG MARKER: Write 11MiB Using Fallocate [ 1639.823697] Lustre: DEBUG MARKER: == sanity-quota test 1i: Quota pools: different limit and usage relations ========================================================== 10:49:38 (1787842178) [ 1652.466800] Lustre: DEBUG MARKER: User quota (block hardlimit:200 MB) [ 1668.679940] Lustre: DEBUG MARKER: Write... [ 1671.006581] Lustre: DEBUG MARKER: Write out of block quota ... [ 1706.382844] Lustre: DEBUG MARKER: Write... [ 1709.571668] Lustre: DEBUG MARKER: Write out of block quota ... [ 1722.469297] LustreError: 6496:0:(qmt_entry.c:558:qmt_adjust_edquot()) $$$ set revoke_time explicitly qmt:lustre-QMT0000 pool:dt-qpool1 id:60000 enforced:1 hard:10240 soft:0 granted:14344 time:0 qunit: 1024 edquot:0 may_rel:0 revoke:0 default:no [ 1763.919517] Lustre: DEBUG MARKER: == sanity-quota test 1j: Enable project quota enforcement for root ========================================================== 10:51:43 (1787842303) [ 1780.346718] Lustre: DEBUG MARKER: -------------------------------------- [ 1782.184219] Lustre: DEBUG MARKER: Project quota (hardlimit: 40 mb, 2048 files) [ 2141.953494] Lustre: DEBUG MARKER: == sanity-quota test 1k: LQA: Block hard limit (normal use and out of quota) ========================================================== 10:58:00 (1787842680) [ 2156.500717] Lustre: DEBUG MARKER: Write... [ 2159.484794] Lustre: DEBUG MARKER: Write out of block quota ... [ 2188.422845] Lustre: DEBUG MARKER: Write... [ 2191.569600] Lustre: DEBUG MARKER: Write out of block quota ... [ 2223.679756] Lustre: DEBUG MARKER: Write... [ 2226.497944] Lustre: DEBUG MARKER: Write out of block quota ... [ 2263.301979] Lustre: DEBUG MARKER: == sanity-quota test 1l: Async writes should not be rejected by quota with root_prj_enable ========================================================== 11:00:03 (1787842803) [ 2306.133754] Lustre: DEBUG MARKER: SKIP: sanity-quota test_2 skipping excluded test 2 [ 2307.855984] Lustre: DEBUG MARKER: == sanity-quota test 3a: Block soft limit (start timer, timer goes off, stop timer) ========================================================== 11:00:47 (1787842847) [ 2353.318633] Lustre: DEBUG MARKER: Write after timer goes off [ 2356.209811] Lustre: DEBUG MARKER: Write after cancel lru locks [ 2437.026259] Lustre: DEBUG MARKER: Write after timer goes off [ 2439.282732] Lustre: DEBUG MARKER: Write after cancel lru locks [ 2524.406545] Lustre: DEBUG MARKER: Write after timer goes off [ 2527.076933] Lustre: DEBUG MARKER: Write after cancel lru locks [ 2604.469842] Lustre: DEBUG MARKER: == sanity-quota test 3b: Quota pools: Block soft limit (start timer, expires, stop timer) ========================================================== 11:05:43 (1787843143) [ 2662.003919] Lustre: DEBUG MARKER: Write after timer goes off [ 2664.498984] Lustre: DEBUG MARKER: Write after cancel lru locks [ 2743.018370] Lustre: DEBUG MARKER: Write after timer goes off [ 2745.246931] Lustre: DEBUG MARKER: Write after cancel lru locks [ 2826.812561] Lustre: DEBUG MARKER: Write after timer goes off [ 2830.813146] Lustre: DEBUG MARKER: Write after cancel lru locks [ 2916.642384] Lustre: DEBUG MARKER: == sanity-quota test 3c: Quota pools: check block soft limit on different pools ========================================================== 11:10:55 (1787843455) [ 2980.598460] Lustre: DEBUG MARKER: Write after timer goes off [ 2983.647614] Lustre: DEBUG MARKER: Write after cancel lru locks [ 3062.185653] Lustre: DEBUG MARKER: SKIP: sanity-quota test_4a skipping excluded test 4a [ 3064.230390] Lustre: DEBUG MARKER: == sanity-quota test 4b: Grace time strings handling ===== 11:13:23 (1787843603) [ 3077.065807] Lustre: DEBUG MARKER: == sanity-quota test 5: Chown [ 3199.258241] Lustre: DEBUG MARKER: == sanity-quota test 6: Test dropping acquire request on master ========================================================== 11:15:38 (1787843738) [ 3236.640382] Lustre: *** cfs_fail_loc=513, val=601*** [ 3236.645627] Lustre: Skipped 3 previous similar messages [ 3237.346588] Lustre: *** cfs_fail_loc=513, val=601*** [ 3237.350032] Lustre: Skipped 2 previous similar messages [ 3237.956685] LustreError: 16520:0:(service.c:2341:ptlrpc_server_handle_req_in()) drop incoming rpc opc 601, x1874686746066688 [ 3238.367952] Lustre: *** cfs_fail_loc=513, val=601*** [ 3238.371963] Lustre: Skipped 18 previous similar messages [ 3240.417292] Lustre: *** cfs_fail_loc=513, val=601*** [ 3240.429938] Lustre: Skipped 6 previous similar messages [ 3245.538281] Lustre: *** cfs_fail_loc=513, val=601*** [ 3245.540208] Lustre: Skipped 8 previous similar messages [ 3253.217217] Lustre: 19431:0:(service.c:1612:ptlrpc_at_send_early_reply()) @@@ Could not add any time (5/5), not sending early reply req@ffff8cd827da52c0 x1874686740665216/t0(0) o4->756038f4-56c6-4d0a-8e2e-17932d4b3cfd@192.168.201.27@tcp:24/0 lens 488/448 e 1 to 0 dl 1787843799 ref 2 fl Interpret:/600/0 rc 0/0 job:'dd.60000' uid:60000 gid:60000 projid:0 [ 3253.727987] Lustre: *** cfs_fail_loc=513, val=601*** [ 3253.729986] Lustre: Skipped 33 previous similar messages [ 3254.239142] Lustre: 8414:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787843779/real 1787843779] req@ffff8cd705684000 x1874686746066688/t0(0) o601->lustre-MDT0000-lwp-OST0000@0@lo:23/10 lens 336/336 e 0 to 1 dl 1787843795 ref 2 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'ll_ost_io00_000.0' uid:0 gid:0 projid:4294967295 [ 3254.299760] 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 [ 3254.310717] Lustre: lustre-MDT0000: Client lustre-MDT0000-lwp-OST0000_UUID (at 0@lo) reconnecting [ 3254.334872] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 3254.434607] LustreError: 16512:0:(service.c:2341:ptlrpc_server_handle_req_in()) drop incoming rpc opc 601, x1874686746075776 [ 3257.319628] LustreError: 6498:0:(service.c:2341:ptlrpc_server_handle_req_in()) drop incoming rpc opc 601, x1874686746076288 [ 3257.341610] LustreError: 6498:0:(service.c:2341:ptlrpc_server_handle_req_in()) Skipped 2 previous similar messages [ 3269.599198] Lustre: 3622:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787843795/real 1787843795] req@ffff8cd7072bb480 x1874686746075776/t0(0) o601->lustre-MDT0000-lwp-OST0000@0@lo:23/10 lens 336/336 e 0 to 1 dl 1787843811 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'ll_ost_io00_001.0' uid:0 gid:0 projid:4294967295 [ 3269.622535] 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 [ 3269.632243] Lustre: lustre-MDT0000: Client lustre-MDT0000-lwp-OST0000_UUID (at 0@lo) reconnecting [ 3269.651864] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 3271.138741] Lustre: *** cfs_fail_loc=513, val=601*** [ 3271.142489] Lustre: Skipped 91 previous similar messages [ 3272.671201] Lustre: 3621:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787843798/real 1787843798] req@ffff8cd70d80ed00 x1874686746076288/t0(0) o601->lustre-MDT0000-lwp-MDT0001@0@lo:23/10 lens 336/336 e 0 to 1 dl 1787843814 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'lquota_wb_lustr.0' uid:0 gid:0 projid:4294967295 [ 3272.707135] LustreError: 16515:0:(service.c:2341:ptlrpc_server_handle_req_in()) drop incoming rpc opc 601, x1874686746084352 [ 3272.718180] 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 [ 3272.728387] Lustre: lustre-MDT0000: Received new LWP connection from 0@lo, keep former export from same NID [ 3272.769534] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 3277.796757] LustreError: 16512:0:(service.c:2341:ptlrpc_server_handle_req_in()) drop incoming rpc opc 601, x1874686746086272 [ 3277.811944] LustreError: 16512:0:(service.c:2341:ptlrpc_server_handle_req_in()) Skipped 5 previous similar messages [ 3289.056291] Lustre: 8416:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787843814/real 1787843814] req@ffff8cd705686940 x1874686746084352/t0(0) o601->lustre-MDT0000-lwp-OST0000@0@lo:23/10 lens 336/336 e 0 to 1 dl 1787843830 ref 2 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'ll_ost_io00_002.0' uid:0 gid:0 projid:4294967295 [ 3289.095789] Lustre: 8416:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 3289.101347] 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 [ 3289.118724] Lustre: lustre-MDT0000: Client lustre-MDT0000-lwp-OST0000_UUID (at 0@lo) reconnecting [ 3289.137311] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 3293.664282] Lustre: 3619:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787843819/real 1787843819] req@ffff8cd827ca2d00 x1874686746086400/t0(0) o601->lustre-MDT0000-lwp-OST0001@0@lo:23/10 lens 336/336 e 0 to 1 dl 1787843835 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'lquota_wb_lustr.0' uid:0 gid:0 projid:4294967295 [ 3293.688701] 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 [ 3293.707504] Lustre: lustre-MDT0000: Client lustre-MDT0000-lwp-OST0001_UUID (at 0@lo) reconnecting [ 3293.720379] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 3294.755429] Lustre: lustre-MDT0000: Received new LWP connection from 0@lo, keep former export from same NID [ 3326.769323] Lustre: DEBUG MARKER: == sanity-quota test 7a: Quota reintegration (global index) ========================================================== 11:17:45 (1787843865) [ 3353.348613] Lustre: Failing over lustre-OST0000 [ 3353.553356] Lustre: server umount lustre-OST0000 complete [ 3356.133750] 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 [ 3356.141117] Lustre: Skipped 1 previous similar message [ 3359.518948] LustreError: 8408:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.201.27@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3359.538622] LustreError: 8408:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 4 previous similar messages [ 3361.258758] LustreError: 41820:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3361.282193] LustreError: 41820:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 1 previous similar message [ 3364.643593] LustreError: 41871:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.201.27@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3367.705780] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3368.051965] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [ 3368.076621] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 3369.403031] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 3369.663912] Lustre: lustre-OST0000: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [ 3369.667592] Lustre: lustre-OST0000-osc-MDT0001: Connection restored to 0@lo (at 0@lo) [ 3369.684351] Lustre: Skipped 1 previous similar message [ 3375.296413] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3384.155646] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3391.608318] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3398.122778] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3405.221712] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3413.530441] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3421.584865] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3444.914818] Lustre: Failing over lustre-OST0000 [ 3445.191317] Lustre: server umount lustre-OST0000 complete [ 3445.227546] 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 [ 3445.246078] LustreError: 42200:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3445.252659] Lustre: Skipped 2 previous similar messages [ 3445.290470] LustreError: 42200:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 3 previous similar messages [ 3450.347312] LustreError: 8410:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3450.358093] LustreError: 8410:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 1 previous similar message [ 3456.134674] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3456.524632] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [ 3456.570965] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 3457.657147] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 3464.960954] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3475.631378] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3527.502297] Lustre: lustre-OST0000: recovery is timed out, evict stale exports [ 3527.506944] Lustre: 88180:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-OST0000: disconnect stale client 756038f4-56c6-4d0a-8e2e-17932d4b3cfd@ [ 3527.519989] Lustre: lustre-OST0000: disconnecting 1 stale clients [ 3527.544127] Lustre: lustre-OST0000: Recovery over after 1:10, of 3 clients 2 recovered and 1 was evicted. [ 3527.544279] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 3527.561084] Lustre: Skipped 1 previous similar message [ 3538.053481] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3544.959369] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3550.605258] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3556.366467] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3563.030765] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3590.854599] Lustre: DEBUG MARKER: == sanity-quota test 7b: Quota reintegration (slave index) ========================================================== 11:22:10 (1787844130) [ 3622.855990] Lustre: *** cfs_fail_loc=a02, val=0*** [ 3630.792125] LustreError: 3620:0:(qsd_handler.c:298:qsd_req_completion()) $$$ DQACQ failed with -5, flags:0x8 qsd:lustre-OST0000 qtype:usr lqe: ffff8cd705b73e00 id:60000 enforced:1 granted: 1024 pending:0 waiting:0 req:1 usage: 2048 qunit:0 qtune:0 edquot:0 default:no revoke:0 [ 3630.821801] Lustre: Failing over lustre-OST0000 [ 3630.883917] Lustre: server umount lustre-OST0000 complete [ 3630.926344] LustreError: 8410:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.201.27@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3630.940986] LustreError: 8410:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 2 previous similar messages [ 3631.596150] Lustre: lustre-OST0000-osc-MDT0001: Connection to lustre-OST0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 3641.200466] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3641.579963] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [ 3641.648150] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 3643.140411] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 3643.575956] Lustre: lustre-OST0000: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [ 3643.576593] Lustre: lustre-OST0000-osc-MDT0001: Connection restored to 0@lo (at 0@lo) [ 3643.599963] Lustre: Skipped 1 previous similar message [ 3649.100700] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3658.585767] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3664.916316] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3670.846683] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3677.396189] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3684.018974] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3690.377381] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3734.700883] Lustre: DEBUG MARKER: == sanity-quota test 7c: Quota reintegration (restart mds during reintegration) ========================================================== 11:24:33 (1787844273) [ 3758.420200] LustreError: 97850:0:(qsd_reint.c:488:qsd_reint_main()) cfs_fail_timeout id a03 sleeping for 10000ms [ 3758.431569] LustreError: 97850:0:(qsd_reint.c:488:qsd_reint_main()) Skipped 5 previous similar messages [ 3760.212268] Lustre: Failing over lustre-MDT0000 [ 3760.610836] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3760.618351] 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 [ 3760.634851] Lustre: Skipped 1 previous similar message [ 3760.642840] LustreError: 6500:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3760.661748] Lustre: server umount lustre-MDT0000 complete [ 3760.663088] LustreError: 6500:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 6 previous similar messages [ 3764.119376] LustreError: 97854:0:(qsd_reint.c:488:qsd_reint_main()) cfs_fail_timeout interrupted [ 3764.139488] LustreError: 97854:0:(qsd_reint.c:488:qsd_reint_main()) Skipped 1 previous similar message [ 3764.154163] LustreError: lustre-MDT0000-lwp-OST0001: operation dt_index_read to node 0@lo failed: rc = -107 [ 3764.164186] LustreError: Skipped 1 previous similar message [ 3770.658766] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3770.819834] LustreError: MGC192.168.201.127@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3771.226703] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3771.281403] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 3774.247168] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 3776.568471] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 3776.575199] Lustre: Skipped 1 previous similar message [ 3776.577779] LustreError: 3618:0:(ldlm_resource.c:1207:ldlm_resource_complain()) lustre-MDT0000-lwp-OST0001: namespace resource [0x200000006:0x2020000:0x0].0x0 (ffff8cd8039a7200) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 3776.722237] Lustre: lustre-MDT0000: Recovery over after 0:02, of 2 clients 2 recovered and 0 were evicted. [ 3776.780733] Lustre: 97855:0:(qsd_reint.c:249:qsd_reint_index()) lustre-OST0001: index version for fid [0x200000005:0x100c:0x0] is 0, but index isn't empty (1) [ 3776.819682] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:104 to 0x2c0000401:129) [ 3776.826430] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:160 to 0x280000401:193) [ 3777.249502] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3787.424175] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3882.617903] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3889.295804] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3895.303565] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3902.439611] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3908.645452] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3937.368692] Lustre: DEBUG MARKER: == sanity-quota test 7d: Quota reintegration (Transfer index in multiple bulks) ========================================================== 11:27:56 (1787844476) [ 3961.761905] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3969.845780] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 4019.246447] Lustre: DEBUG MARKER: == sanity-quota test 7e: Quota reintegration (inode limits) ========================================================== 11:29:18 (1787844558) [ 4047.014510] Lustre: Failing over lustre-MDT0001 [ 4047.336683] Lustre: server umount lustre-MDT0001 complete [ 4047.840373] 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 [ 4047.846770] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 4047.847171] LustreError: 18124:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4047.847179] LustreError: 18124:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 10 previous similar messages [ 4047.861830] Lustre: Skipped 4 previous similar messages [ 4062.016219] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4062.656872] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 4062.743252] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 4064.381172] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4067.820774] Lustre: lustre-MDT0001-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 4067.827387] Lustre: Skipped 3 previous similar messages [ 4067.863592] Lustre: lustre-MDT0001: Recovery over after 0:03, of 2 clients 2 recovered and 0 were evicted. [ 4067.911272] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:33) [ 4068.665227] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4078.336116] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 4085.592504] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0001.recovery_status 1475 [ 4092.295334] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 4098.034817] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0001.recovery_status 1475 [ 4105.625776] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 4113.078938] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0001.recovery_status 1475 [ 4193.143818] Lustre: Failing over lustre-MDT0001 [ 4193.464602] Lustre: server umount lustre-MDT0001 complete [ 4195.819093] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 4195.830057] LustreError: 18124:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4195.851364] LustreError: 18124:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 13 previous similar messages [ 4204.023452] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4204.598219] Lustre: lustre-MDT0001: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [ 4204.675032] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 4206.473984] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4209.663484] Lustre: lustre-MDT0001: Recovery over after 0:03, of 2 clients 2 recovered and 0 were evicted. [ 4209.738692] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:65) [ 4210.133785] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4219.022679] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 4225.511829] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0001.recovery_status 1475 [ 4231.681181] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 4237.985992] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0001.recovery_status 1475 [ 4244.274888] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 4251.055147] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0001.recovery_status 1475 [ 4355.598731] Lustre: DEBUG MARKER: == sanity-quota test 7f: Quota reintegration automatically ========================================================== 11:34:54 (1787844894) [ 4369.824755] Lustre: *** cfs_fail_loc=a11, val=0*** [ 4369.829848] Lustre: Skipped 3 previous similar messages [ 4376.554657] Lustre: *** cfs_fail_loc=a11, val=0*** [ 4428.773151] Lustre: *** cfs_fail_loc=a11, val=0*** [ 4428.795519] Lustre: Skipped 2 previous similar messages [ 4428.874501] Lustre: 114269:0:(qsd_reint.c:249:qsd_reint_index()) lustre-MDT0001: index version for fid [0x200000005:0x100a:0x0] is 0, but index isn't empty (1) [ 4486.296661] Lustre: DEBUG MARKER: == sanity-quota test 8: Run dbench with quota enabled ==== 11:37:05 (1787845025) [ 4681.602965] Lustre: DEBUG MARKER: == sanity-quota test 9: Block limit larger than 4GB (b10707) ========================================================== 11:40:20 (1787845220) [ 4683.479934] Lustre: DEBUG MARKER: OST0_SIZE: 3599412 required: 4900000 [ 4691.266581] Lustre: DEBUG MARKER: == sanity-quota test 10: Test quota for root user ======== 11:40:30 (1787845230) [ 4736.949610] Lustre: DEBUG MARKER: == sanity-quota test 11: Chown/chgrp ignores quota ======= 11:41:16 (1787845276) [ 4789.058711] Lustre: DEBUG MARKER: == sanity-quota test 12a: Block quota rebalancing ======== 11:42:08 (1787845328) [ 4859.246456] Lustre: DEBUG MARKER: == sanity-quota test 12b: Inode quota rebalancing ======== 11:43:18 (1787845398) [ 5020.248987] Lustre: DEBUG MARKER: == sanity-quota test 13: Cancel per-ID lock in the LRU list ========================================================== 11:45:59 (1787845559) [ 5084.769404] Lustre: DEBUG MARKER: == sanity-quota test 14: check panic in qmt_site_recalc_cb ========================================================== 11:47:03 (1787845623) [ 5109.582264] Lustre: Failing over lustre-OST0000 [ 5109.756762] Lustre: server umount lustre-OST0000 complete [ 5110.755684] 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 [ 5110.771149] Lustre: Skipped 4 previous similar messages [ 5110.777061] LustreError: 115893:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 5110.791357] LustreError: 115893:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 6 previous similar messages [ 5124.110070] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5124.476623] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [ 5124.498465] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 5125.668889] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 5126.168371] Lustre: lustre-OST0000: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [ 5126.171520] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 5126.196889] Lustre: Skipped 5 previous similar messages [ 5131.554499] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5169.659718] Lustre: DEBUG MARKER: == sanity-quota test 15: Set over 4T block quota ========= 11:48:28 (1787845708) [ 5202.136354] Lustre: DEBUG MARKER: == sanity-quota test 16a: lfs quota should skip the inactive MDT/OST ========================================================== 11:49:01 (1787845741) [ 5226.327857] Lustre: lustre-MDT0001: Client 756038f4-56c6-4d0a-8e2e-17932d4b3cfd (at 192.168.201.27@tcp) reconnecting [ 5252.658597] Lustre: DEBUG MARKER: == sanity-quota test 16b: lfs quota should skip the nonexistent MDT/OST ========================================================== 11:49:51 (1787845791) [ 5255.417702] Lustre: DEBUG MARKER: SKIP: sanity-quota test_16b needs >= 3 MDTs [ 5257.890180] Lustre: DEBUG MARKER: == sanity-quota test 17: DQACQ return recoverable error == 11:49:56 (1787845796) [ 5283.927728] Lustre: *** cfs_fail_loc=a04, val=37*** [ 5283.937926] LustreError: 41872:0:(qsd_handler.c:298:qsd_req_completion()) $$$ DQACQ failed with -37, flags:0x1 qsd:lustre-OST0001 qtype:usr lqe: ffff8cd70374c300 id:60000 enforced:1 granted: 0 pending:0 waiting:1056 req:1 usage: 0 qunit:0 qtune:0 edquot:0 default:no revoke:0 [ 5285.050119] Lustre: *** cfs_fail_loc=a04, val=37*** [ 5285.062305] LustreError: 42111:0:(qsd_handler.c:298:qsd_req_completion()) $$$ DQACQ failed with -37, flags:0x1 qsd:lustre-OST0001 qtype:usr lqe: ffff8cd70374c300 id:60000 enforced:1 granted: 0 pending:0 waiting:1056 req:1 usage: 0 qunit:0 qtune:0 edquot:0 default:no revoke:0 [ 5287.226975] Lustre: *** cfs_fail_loc=a04, val=37*** [ 5287.234452] LustreError: 115868:0:(qsd_handler.c:298:qsd_req_completion()) $$$ DQACQ failed with -37, flags:0x1 qsd:lustre-OST0001 qtype:usr lqe: ffff8cd70374c300 id:60000 enforced:1 granted: 0 pending:0 waiting:1056 req:1 usage: 0 qunit:0 qtune:0 edquot:0 default:no revoke:0 [ 5349.440226] Lustre: *** cfs_fail_loc=a04, val=11*** [ 5411.134083] Lustre: *** cfs_fail_loc=a04, val=110*** [ 5411.140531] Lustre: Skipped 2 previous similar messages [ 5474.992668] Lustre: *** cfs_fail_loc=a04, val=107*** [ 5474.995793] Lustre: Skipped 2 previous similar messages [ 5561.505427] Lustre: DEBUG MARKER: == sanity-quota test 18: MDS failover while writing, no watchdog triggered (b14840) ========================================================== 11:55:00 (1787846100) [ 5575.831459] Lustre: DEBUG MARKER: User quota (limit: 200) [ 5583.399652] Lustre: DEBUG MARKER: Write 100M (buffered) ... [ 5593.633842] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5596.045198] Lustre: DEBUG MARKER: Fail mds for 40 seconds [ 5598.183185] Lustre: Failing over lustre-MDT0000 [ 5598.560616] Lustre: server umount lustre-MDT0000 complete [ 5600.740579] 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 [ 5600.747744] LustreError: 6499:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 5600.756556] Lustre: Skipped 4 previous similar messages [ 5600.800789] LustreError: 6499:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 10 previous similar messages [ 5617.119166] Lustre: 3622:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787846142/real 1787846142] req@ffff8cd7049c8f00 x1874686748541696/t0(0) o400->MGC192.168.201.127@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1787846158 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5617.148266] Lustre: 3622:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 5 previous similar messages [ 5617.153419] LustreError: MGC192.168.201.127@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5621.907968] LDISKFS-fs (dm-0): 7 truncates cleaned up [ 5621.915854] LDISKFS-fs (dm-0): recovery complete [ 5621.930542] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5627.406404] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xfbce82a13e75ba22 [ 5627.421283] Lustre: MGC192.168.201.127@tcp: Connection restored to 0@lo (at 0@lo) [ 5627.439397] Lustre: Skipped 1 previous similar message [ 5627.867726] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 5627.920451] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 5629.749639] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 5632.913379] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5633.111373] Lustre: lustre-MDT0000: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 5633.166252] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:571 to 0x280000401:609) [ 5633.191857] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:503 to 0x2c0000401:545) [ 5644.977394] Lustre: DEBUG MARKER: oleg127-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5647.812222] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5655.494685] Lustre: DEBUG MARKER: (dd_pid=127370, time=0, timeout=600) [ 5688.969463] Lustre: DEBUG MARKER: User quota (limit: 200) [ 5696.233266] Lustre: DEBUG MARKER: Write 100M (directio) ... [ 5705.770861] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5707.753517] Lustre: DEBUG MARKER: Fail mds for 40 seconds [ 5710.221679] Lustre: Failing over lustre-MDT0000 [ 5710.333987] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 5710.340214] 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 [ 5710.350145] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5710.588635] Lustre: server umount lustre-MDT0000 complete [ 5711.695056] LustreError: 9506:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.201.27@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 5711.719207] LustreError: 9506:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 30 previous similar messages [ 5731.296653] Lustre: 3619:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787846256/real 1787846256] req@ffff8cd71036fc00 x1874686748613376/t0(0) o400->MGC192.168.201.127@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1787846272 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5731.342870] LustreError: MGC192.168.201.127@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5737.026585] LDISKFS-fs (dm-0): 3 truncates cleaned up [ 5737.028913] LDISKFS-fs (dm-0): recovery complete [ 5737.035906] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5741.937747] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 5742.031563] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 5743.325931] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 5747.172932] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 5747.189755] Lustre: Skipped 4 previous similar messages [ 5747.201956] LustreError: 3618:0:(ldlm_resource.c:1207:ldlm_resource_complain()) lustre-MDT0000-lwp-MDT0001: namespace resource [0x200000006:0x10000:0x0].0x0 (ffff8cd81e267200) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 5747.227063] LustreError: 3618:0:(ldlm_resource.c:1207:ldlm_resource_complain()) Skipped 5 previous similar messages [ 5747.275500] Lustre: lustre-MDT0000: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 5747.358218] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:611 to 0x280000401:641) [ 5747.360137] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:503 to 0x2c0000401:577) [ 5747.682151] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5758.880159] Lustre: DEBUG MARKER: oleg127-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5760.886313] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5767.282475] Lustre: DEBUG MARKER: (dd_pid=129812, time=0, timeout=600) [ 5814.809329] Lustre: DEBUG MARKER: == sanity-quota test 19: Updating admin limits doesn't zero operational limits(b14790) ========================================================== 11:59:14 (1787846354) [ 5879.290725] Lustre: DEBUG MARKER: == sanity-quota test 20: Test if setquota specifiers work properly (b15754) ========================================================== 12:00:18 (1787846418) [ 5912.843669] Lustre: DEBUG MARKER: == sanity-quota test 21: Setquota while writing [ 5929.196557] Lustre: DEBUG MARKER: Set limit(block:10G; file:1000000) for user: quota_usr [ 5931.375802] Lustre: DEBUG MARKER: Set limit(block:10G; file:1000000) for group: quota_usr [ 5934.128962] Lustre: DEBUG MARKER: Set limit(block:10G; file:) for project: 1000 [ 5937.350915] Lustre: DEBUG MARKER: Set quota for 1 times [ 5941.582945] Lustre: DEBUG MARKER: Set quota for 2 times [ 5945.650163] Lustre: DEBUG MARKER: Set quota for 3 times [ 5949.655658] Lustre: DEBUG MARKER: Set quota for 4 times [ 5953.586383] Lustre: DEBUG MARKER: Set quota for 5 times [ 5958.200541] Lustre: DEBUG MARKER: Set quota for 6 times [ 5962.450470] Lustre: DEBUG MARKER: Set quota for 7 times [ 5965.982986] Lustre: DEBUG MARKER: Set quota for 8 times [ 6020.166220] Lustre: DEBUG MARKER: == sanity-quota test 22: enable/disable quota by 'lctl conf_param/set_param -P' ========================================================== 12:02:39 (1787846559) [ 6039.016088] 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 [ 6039.016980] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 6039.032026] Lustre: Skipped 4 previous similar messages [ 6044.035036] Lustre: server umount lustre-MDT0000 complete [ 6044.129534] LustreError: 6496:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 6044.149593] LustreError: 6496:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 37 previous similar messages [ 6049.067263] LustreError: 26568:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787846590 with bad export cookie 18144583577771558183 [ 6049.084598] LustreError: MGC192.168.201.127@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 6049.087558] LustreError: 26568:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 6049.271601] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 6049.282950] Lustre: Skipped 4 previous similar messages [ 6050.096132] Lustre: server umount lustre-MDT0001 complete [ 6055.111725] Lustre: server umount lustre-OST0000 complete [ 6059.563136] Lustre: server umount lustre-OST0001 complete [ 6079.040869] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing load_modules_local [ 6091.055617] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 6091.559738] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 6097.313466] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6106.459709] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 6107.093703] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 6112.131994] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6115.429726] Lustre: 153617:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 6123.703112] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 6124.479380] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 6133.281630] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6135.728181] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:643 to 0x280000401:673) [ 6144.969828] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 6145.581057] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 6150.679237] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:97) [ 6150.686951] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:580 to 0x2c0000401:609) [ 6155.048060] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6165.455669] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 6171.089340] Lustre: 155498:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 6199.266494] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 6199.294505] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 6204.553881] Lustre: server umount lustre-MDT0000 complete [ 6206.948057] LustreError: 152464:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 6206.984399] LustreError: 152464:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 14 previous similar messages [ 6209.505107] LustreError: 152445:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787846750 with bad export cookie 18144583577771564644 [ 6209.517496] LustreError: MGC192.168.201.127@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 6209.977920] Lustre: server umount lustre-MDT0001 complete [ 6225.062331] Lustre: server umount lustre-OST0000 complete [ 6228.447118] Lustre: 3622:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787846753/real 1787846753] req@ffff8cd7073703c0 x1874686748927360/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787846769 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6229.816806] Lustre: server umount lustre-OST0001 complete [ 6250.262519] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing load_modules_local [ 6263.314035] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 6263.867424] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 6269.517782] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6280.351080] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 6288.005966] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6291.687818] Lustre: 159242:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 6299.466278] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 6299.817570] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 6299.820521] Lustre: Skipped 1 previous similar message [ 6307.801238] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6309.030686] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:643 to 0x280000401:705) [ 6318.606391] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 6324.223212] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:580 to 0x2c0000401:641) [ 6324.238677] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:129) [ 6327.123970] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6337.202764] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 6341.626900] Lustre: 161113:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 6355.169277] Lustre: DEBUG MARKER: == sanity-quota test 23: Quota should be honored with directIO (b16125) ========================================================== 12:08:14 (1787846894) [ 6357.502183] Lustre: DEBUG MARKER: OST0_SIZE: 3605396 required: 6144 [ 6359.613158] Lustre: DEBUG MARKER: run for 4MB test file [ 6372.599743] Lustre: DEBUG MARKER: User quota (limit: 4 MB) [ 6379.898930] Lustre: DEBUG MARKER: Step1: trigger EDQUOT with O_DIRECT [ 6381.909540] Lustre: DEBUG MARKER: Write half of file [ 6384.157714] Lustre: DEBUG MARKER: Write out of block quota ... [ 6386.035284] Lustre: DEBUG MARKER: Step1: done [ 6388.064744] Lustre: DEBUG MARKER: Step2: rewrite should succeed [ 6390.028406] Lustre: DEBUG MARKER: Step2: done [ 6418.443594] Lustre: DEBUG MARKER: OST0_SIZE: 3605396 required: 61440 [ 6420.205737] Lustre: DEBUG MARKER: run for 40MB test file [ 6433.956244] Lustre: DEBUG MARKER: User quota (limit: 40 MB) [ 6441.043088] Lustre: DEBUG MARKER: Step1: trigger EDQUOT with O_DIRECT [ 6443.135274] Lustre: DEBUG MARKER: Write half of file [ 6447.035784] Lustre: DEBUG MARKER: Write out of block quota ... [ 6449.917636] Lustre: DEBUG MARKER: Step1: done [ 6451.414086] Lustre: DEBUG MARKER: Step2: rewrite should succeed [ 6453.283508] Lustre: DEBUG MARKER: Step2: done [ 6503.909498] Lustre: DEBUG MARKER: == sanity-quota test 24: lfs draws an asterix when limit is reached (b16646) ========================================================== 12:10:43 (1787847043) [ 6559.478305] Lustre: DEBUG MARKER: == sanity-quota test 25: check indexes versions ========== 12:11:38 (1787847098) [ 6603.990639] Lustre: DEBUG MARKER: Write... [ 6606.248522] Lustre: DEBUG MARKER: Write out of block quota ... [ 6658.383507] Lustre: DEBUG MARKER: == sanity-quota test 27a: lfs quota/setquota should handle wrong arguments (b19612) ========================================================== 12:13:17 (1787847197) [ 6665.050179] Lustre: DEBUG MARKER: == sanity-quota test 27b: lfs quota/setquota should handle user/group/project ID (b20200) ========================================================== 12:13:24 (1787847204) [ 6674.917939] Lustre: DEBUG MARKER: == sanity-quota test 27c: lfs quota should support human-readable output ========================================================== 12:13:34 (1787847214) [ 6683.619205] Lustre: DEBUG MARKER: == sanity-quota test 27d: lfs setquota should support fraction block limit ========================================================== 12:13:42 (1787847222) [ 6692.029353] Lustre: DEBUG MARKER: == sanity-quota test 30: Hard limit updates should not reset grace times ========================================================== 12:13:51 (1787847231) [ 6746.123722] Lustre: DEBUG MARKER: == sanity-quota test 33: Basic usage tracking for user [ 6875.733757] Lustre: DEBUG MARKER: == sanity-quota test 34: Usage transfer for user [ 7010.852475] Lustre: DEBUG MARKER: == sanity-quota test 35: Usage is still accessible across reboot ========================================================== 12:19:10 (1787847550) [ 7058.514113] Lustre: DEBUG MARKER: Restart... [ 7064.033289] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 7064.043717] 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 [ 7064.052182] Lustre: Skipped 9 previous similar messages [ 7064.055749] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 7064.058127] Lustre: Skipped 4 previous similar messages [ 7066.598683] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 7066.605271] Lustre: Skipped 2 previous similar messages [ 7068.910127] Lustre: server umount lustre-MDT0000 complete [ 7071.715354] LustreError: 160230:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 7071.731979] LustreError: 160230:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 12 previous similar messages [ 7073.285519] LustreError: 158080:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787847614 with bad export cookie 18144583577771566947 [ 7073.286390] LustreError: MGC192.168.201.127@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 7073.292467] LustreError: 158080:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 5 previous similar messages [ 7073.750080] Lustre: server umount lustre-MDT0001 complete [ 7088.200513] Lustre: server umount lustre-OST0000 complete [ 7103.667733] Lustre: server umount lustre-OST0001 complete [ 7119.389691] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing load_modules_local [ 7128.710717] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 7129.062584] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 7129.065397] Lustre: Skipped 1 previous similar message [ 7132.473931] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7139.398507] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 7139.738307] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 7144.141519] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7147.248491] Lustre: 185221:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 7155.317767] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 7160.399367] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7169.295648] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 7169.485232] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 7169.490833] Lustre: Skipped 1 previous similar message [ 7174.570545] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:716 to 0x280000401:737) [ 7174.581479] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:161) [ 7174.594288] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:650 to 0x2c0000401:673) [ 7175.896373] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7183.814445] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 7187.654342] Lustre: 187094:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 7249.678500] Lustre: DEBUG MARKER: == sanity-quota test 37: Quota accounted properly for file created by 'lfs setstripe' ========================================================== 12:23:08 (1787847788) [ 7303.392435] Lustre: DEBUG MARKER: == sanity-quota test 38: Quota accounting iterator doesn't skip id entries ========================================================== 12:24:02 (1787847842) [ 9127.295560] Lustre: DEBUG MARKER: == sanity-quota test 39: Project ID interface works correctly ========================================================== 12:54:26 (1787849666) [ 9140.707307] 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 [ 9140.715625] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 9140.742638] Lustre: Skipped 5 previous similar messages [ 9140.757867] Lustre: Skipped 1 previous similar message [ 9145.826294] LustreError: 186861:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 9145.857578] LustreError: 186861:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 8 previous similar messages [ 9146.937761] Lustre: server umount lustre-MDT0000 complete [ 9150.867018] LustreError: 184059:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787849692 with bad export cookie 18144583577771576054 [ 9150.868428] LustreError: MGC192.168.201.127@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 9150.878269] LustreError: 184059:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 9150.944895] 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 [ 9150.949448] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 9150.964925] Lustre: Skipped 2 previous similar messages [ 9150.988833] Lustre: Skipped 3 previous similar messages [ 9151.222831] Lustre: server umount lustre-MDT0001 complete [ 9158.161244] Lustre: server umount lustre-OST0000 complete [ 9162.385440] Lustre: server umount lustre-OST0001 complete [ 9181.620228] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing load_modules_local [ 9193.031308] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 9193.607805] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 9199.303344] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 9208.295391] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 9208.982752] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 9213.784924] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 9216.799732] Lustre: 195642:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 9223.743825] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 9224.054474] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 9229.873823] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 9234.278966] LustreError: 195994:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 9234.306599] LustreError: 195994:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 6 previous similar messages [ 9237.937524] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 9239.224973] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:5674 to 0x2c0000401:5697) [ 9239.245402] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:5740 to 0x280000401:5761) [ 9239.253611] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:193) [ 9244.962754] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 9253.558429] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 9257.716247] Lustre: 197517:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 9287.003673] Lustre: DEBUG MARKER: == sanity-quota test 40a: Hard link across different project ID ========================================================== 12:57:06 (1787849826) [ 9317.549369] Lustre: DEBUG MARKER: == sanity-quota test 40b: Mv across different project ID ========================================================== 12:57:36 (1787849856) [ 9364.531338] Lustre: DEBUG MARKER: == sanity-quota test 40c: Remote child Dir inherit project quota properly ========================================================== 12:58:23 (1787849903) [ 9405.159422] Lustre: DEBUG MARKER: == sanity-quota test 40d: Stripe Directory inherit project quota properly ========================================================== 12:59:04 (1787849944) [ 9445.872491] Lustre: DEBUG MARKER: == sanity-quota test 41: df should return projid-specific values ========================================================== 12:59:45 (1787849985) [ 9527.295771] Lustre: DEBUG MARKER: == sanity-quota test 42: lfs quota should include default quota info ========================================================== 13:01:06 (1787850066) [ 9563.166567] Lustre: DEBUG MARKER: == sanity-quota test 48: lfs quota --delete should delete quota project ID ========================================================== 13:01:42 (1787850102) [ 9636.013109] Lustre: DEBUG MARKER: == sanity-quota test 49a: lfs quota -a prints the quota usage for all quota IDs ========================================================== 13:02:55 (1787850175) [ 9643.222082] Lustre: *** cfs_fail_loc=a09, val=0*** [ 9643.228188] Lustre: Skipped 1 previous similar message [ 9645.269565] Lustre: *** cfs_fail_loc=a09, val=0*** [ 9645.271419] Lustre: Skipped 107 previous similar messages [ 9649.276435] Lustre: *** cfs_fail_loc=a09, val=0*** [ 9649.278406] Lustre: Skipped 165 previous similar messages [ 9657.307073] Lustre: *** cfs_fail_loc=a09, val=0*** [ 9657.317044] Lustre: Skipped 245 previous similar messages [ 9673.342362] Lustre: *** cfs_fail_loc=a09, val=0*** [ 9673.344682] Lustre: Skipped 633 previous similar messages [ 9705.355588] Lustre: *** cfs_fail_loc=a09, val=0*** [ 9705.360030] Lustre: Skipped 1251 previous similar messages [ 9769.362077] Lustre: *** cfs_fail_loc=a09, val=0*** [ 9769.373442] Lustre: Skipped 2461 previous similar messages [10243.042376] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [10243.051271] 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 [10243.066406] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [10243.104572] Lustre: Skipped 2 previous similar messages [10247.940660] Lustre: server umount lustre-MDT0000 complete [10248.162793] LustreError: 196820:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [10248.180160] LustreError: 196820:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 3 previous similar messages [10252.248111] LustreError: 194481:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787850793 with bad export cookie 18144583577773355881 [10252.251909] LustreError: MGC192.168.201.127@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [10252.253842] LustreError: 194481:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [10253.280370] 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 [10253.288754] Lustre: Skipped 1 previous similar message [10253.294668] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [10253.297315] Lustre: Skipped 3 previous similar messages [10257.313206] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [10257.316191] Lustre: Skipped 1 previous similar message [10258.789915] Lustre: server umount lustre-MDT0001 complete [10265.091702] Lustre: server umount lustre-OST0000 complete [10272.024412] Lustre: server umount lustre-OST0001 complete [10280.451664] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_hostid [10295.798542] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing load_modules_local [10361.424282] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing load_modules_local [10373.425820] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [10373.772132] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [10373.830532] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [10373.921733] Lustre: lustre-MDT0000: new disk, initializing [10373.994675] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [10374.000878] Lustre: Skipped 1 previous similar message [10374.012361] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [10379.420899] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [10390.280816] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [10390.383740] Lustre: 214298:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [10390.408762] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [10390.412989] Lustre: Skipped 1 previous similar message [10390.472958] Lustre: lustre-MDT0001: new disk, initializing [10390.534942] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [10390.563604] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [10390.581286] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [10395.125976] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [10400.445724] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [10406.989653] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [10407.228607] Lustre: lustre-OST0000: new disk, initializing [10407.232257] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [10407.241968] Lustre: 215929:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [10407.313561] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [10408.665372] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [10408.682773] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [10408.784182] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [10415.065801] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [10426.511137] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [10426.732150] Lustre: lustre-OST0001: new disk, initializing [10426.738614] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [10426.748636] Lustre: 216798:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [10426.833741] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [10428.716187] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [10428.723264] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [10428.812365] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [10434.281325] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [10444.255978] Lustre: DEBUG MARKER: Using TIMEOUT=20 [10448.070958] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [10477.559154] Lustre: DEBUG MARKER: == sanity-quota test 49b: lfs quota -a --blocks has a delimiter ========================================================== 13:16:56 (1787851016) [10484.723985] Lustre: DEBUG MARKER: == sanity-quota test 50: Test if lfs find --projid works ========================================================== 13:17:04 (1787851024) [10518.739438] Lustre: DEBUG MARKER: == sanity-quota test 51: Test project accounting with mv/cp ========================================================== 13:17:37 (1787851057) [10573.133460] Lustre: DEBUG MARKER: == sanity-quota test 52: Rename normal file across project ID ========================================================== 13:18:32 (1787851112) [10605.125200] Lustre: DEBUG MARKER: rename directory return 255 [10650.636837] Lustre: DEBUG MARKER: == sanity-quota test 53: Project inherit attribute could be cleared ========================================================== 13:19:49 (1787851189) [10675.133945] Lustre: DEBUG MARKER: == sanity-quota test 54: basic lfs project interface test ========================================================== 13:20:13 (1787851213) [10715.991530] Lustre: DEBUG MARKER: == sanity-quota test 55: Chgrp should be affected by group quota ========================================================== 13:20:54 (1787851254) [10829.265673] LustreError: 218889:0:(qmt_entry.c:558:qmt_adjust_edquot()) $$$ set revoke_time explicitly qmt:lustre-QMT0000 pool:dt-0x0 id:60001 enforced:1 hard:51200 soft:0 granted:51200 time:0 qunit: 1024 edquot:0 may_rel:0 revoke:0 default:no [10861.519395] Lustre: DEBUG MARKER: == sanity-quota test 56: lfs quota -t should work well === 13:23:20 (1787851400) [10890.869766] Lustre: DEBUG MARKER: == sanity-quota test 57: lfs project could tolerate errors ========================================================== 13:23:49 (1787851429) [10926.573927] Lustre: DEBUG MARKER: == sanity-quota test 58: project ID should be kept for new mirrors created by FID ========================================================== 13:24:25 (1787851465) [11089.418196] Lustre: DEBUG MARKER: == sanity-quota test 59: lfs project dosen't crash kernel with project disabled ========================================================== 13:27:08 (1787851628) [11097.056380] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [11097.066306] 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 [11097.091643] Lustre: Skipped 1 previous similar message [11097.095133] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [11099.620014] 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 [11099.620812] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [11099.652487] Lustre: Skipped 3 previous similar messages [11101.953363] Lustre: server umount lustre-MDT0000 complete [11104.739594] LustreError: 214309:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [11104.779540] LustreError: 214309:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 7 previous similar messages [11107.009397] LustreError: 214289:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787851648 with bad export cookie 18144583577773728281 [11107.012641] LustreError: MGC192.168.201.127@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [11107.024937] LustreError: 214289:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [11107.549180] Lustre: server umount lustre-MDT0001 complete [11122.332479] Lustre: server umount lustre-OST0000 complete [11126.367678] Lustre: 3622:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787851651/real 1787851651] req@ffff8cd71a95fc00 x1874686760068608/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787851667 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [11126.394410] 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 [11126.409705] Lustre: Skipped 2 previous similar messages [11126.988091] Lustre: server umount lustre-OST0001 complete [11154.551986] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing load_modules_local [11169.470294] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [11170.322460] LustreError: 233912:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [11170.476267] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [11170.499575] 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 [11175.904106] LustreError: 233913:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [11177.270960] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [11185.122537] LustreError: 233912:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [11185.137673] LustreError: 233912:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 1 previous similar message [11188.120516] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [11188.712600] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [11188.728173] 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 [11194.839597] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [11199.027846] Lustre: 235059:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [11208.891655] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [11209.489560] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [11209.508574] 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 [11213.605180] LustreError: 235413:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [11214.648336] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:20 to 0x280000401:65) [11218.030038] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [11229.874575] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [11230.328286] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [11230.349443] 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 [11235.341730] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:20 to 0x2c0000401:65) [11239.147466] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [11248.068844] Lustre: DEBUG MARKER: Using TIMEOUT=20 [11252.962278] Lustre: 236934:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [11263.590482] LustreError: 233909:0:(osd_handler.c:3425:osd_quota_transfer()) lustre-MDT0000: quota transfer failed. Is project enforcement enabled on the ldiskfs filesystem? rc = -95 [11271.148319] 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 [11271.173803] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [11271.198692] Lustre: Skipped 2 previous similar messages [11271.225640] Lustre: Skipped 3 previous similar messages [11276.256684] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [11276.291592] Lustre: Skipped 3 previous similar messages [11277.779669] Lustre: server umount lustre-MDT0000 complete [11281.382763] LustreError: 233909:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [11281.400571] LustreError: 233909:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 8 previous similar messages [11283.684801] LustreError: 233893:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787851825 with bad export cookie 18144583577773777162 [11283.686266] LustreError: MGC192.168.201.127@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [11283.700645] LustreError: 233893:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [11284.481412] Lustre: server umount lustre-MDT0001 complete [11299.911822] Lustre: server umount lustre-OST0000 complete [11301.856184] Lustre: 3622:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787851827/real 1787851827] req@ffff8cd70dee7480 x1874686760130048/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787851843 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [11301.892929] 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 [11301.907993] Lustre: Skipped 1 previous similar message [11304.148417] Lustre: server umount lustre-OST0001 complete [11330.007469] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing load_modules_local [11341.759791] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [11342.098431] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [11347.431754] LustreError: 239325:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [11347.453463] LustreError: 239325:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 1 previous similar message [11347.514454] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [11357.335354] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [11362.191589] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [11365.266056] Lustre: 240474:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [11374.164897] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [11374.576781] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [11374.596927] Lustre: Skipped 1 previous similar message [11381.337073] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [11386.874937] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:20 to 0x280000401:97) [11390.011556] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [11395.603055] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:67 to 0x2c0000401:97) [11396.066721] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [11403.546760] Lustre: DEBUG MARKER: Using TIMEOUT=20 [11406.940249] Lustre: 242349:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [11432.825579] Lustre: DEBUG MARKER: == sanity-quota test 60: Test quota for root with setgid ========================================================== 13:32:52 (1787851972) [11489.222340] Lustre: DEBUG MARKER: SKIP: sanity-quota test_61 skipping SLOW test 61 [11491.085128] Lustre: DEBUG MARKER: == sanity-quota test 62: Project inherit should be only changed by root ========================================================== 13:33:50 (1787852030) [11512.395690] Lustre: DEBUG MARKER: SKIP: sanity-quota test_63 skipping excluded test 63 [11514.078746] Lustre: DEBUG MARKER: == sanity-quota test 64: lfs project on non-dir/files should succeed ========================================================== 13:34:13 (1787852053) [11556.560484] Lustre: DEBUG MARKER: SKIP: sanity-quota test_65 skipping excluded test 65 [11558.396830] Lustre: DEBUG MARKER: == sanity-quota test 66: nonroot user can not change project state in default ========================================================== 13:34:57 (1787852097) [11599.639269] Lustre: DEBUG MARKER: == sanity-quota test 67: quota pools recalculation ======= 13:35:38 (1787852138) [11612.345983] Lustre: DEBUG MARKER: User quota (block hardlimit:20 MB) [11619.293525] Lustre: 248963:0:(qsd_reint.c:249:qsd_reint_index()) lustre-OST0000: index version for fid [0x200000005:0x1007:0x0] is 0, but index isn't empty (1) [11619.317946] Lustre: 248963:0:(qsd_reint.c:249:qsd_reint_index()) Skipped 1 previous similar message [11624.192600] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [11631.336913] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [11635.292824] Lustre: DEBUG MARKER: Write... [11660.698510] LustreError: 250308:0:(mgs_handler.c:1144:mgs_iocontrol_pool()) OBD_IOC_POOL err -17, cmd CE021 for pool lustre.qpool1 [11665.824345] Lustre: DEBUG MARKER: Write... [11681.760331] Lustre: DEBUG MARKER: Write... [11765.636782] Lustre: DEBUG MARKER: == sanity-quota test 68: slave number in quota pool changed after each add/remove OST ========================================================== 13:38:24 (1787852304) [11793.498298] LustreError: 254178:0:(mgs_handler.c:1144:mgs_iocontrol_pool()) OBD_IOC_POOL err -17, cmd CE021 for pool lustre.qpool1 [11849.023368] Lustre: DEBUG MARKER: == sanity-quota test 69: EDQUOT at one of pools shouldn't affect DOM ========================================================== 13:39:48 (1787852388) [11873.866765] Lustre: DEBUG MARKER: User quota (block hardlimit:200 MB) [11875.678547] Lustre: DEBUG MARKER: User quota (block hardlimit:10 MB) [11957.864903] Lustre: DEBUG MARKER: == sanity-quota test 70a: check lfs setquota/quota with a pool option ========================================================== 13:41:37 (1787852497) [12006.828971] Lustre: DEBUG MARKER: == sanity-quota test 70b: lfs setquota pool works properly ========================================================== 13:42:25 (1787852545) [12052.032325] Lustre: DEBUG MARKER: == sanity-quota test 71a: Check PFL with quota pools ===== 13:43:10 (1787852590) [12066.914095] Lustre: DEBUG MARKER: User quota (block hardlimit:100 MB) [12096.132423] Lustre: DEBUG MARKER: Write... [12098.147406] Lustre: DEBUG MARKER: Write out of block quota ... [12195.845569] Lustre: DEBUG MARKER: == sanity-quota test 71b: Check SEL with quota pools ===== 13:45:34 (1787852734) [12209.449778] Lustre: DEBUG MARKER: User quota (block hardlimit:1000 MB) [12301.410040] Lustre: DEBUG MARKER: == sanity-quota test 72: lfs quota --pool prints only pool's OSTs ========================================================== 13:47:20 (1787852840) [12315.952172] Lustre: DEBUG MARKER: User quota (block hardlimit:50 MB) [12335.436299] Lustre: DEBUG MARKER: Write... [12337.216296] Lustre: DEBUG MARKER: Write out of block quota ... [12337.590868] LustreError: 243497:0:(qmt_entry.c:558:qmt_adjust_edquot()) $$$ set revoke_time explicitly qmt:lustre-QMT0000 pool:dt-qpool1 id:60000 enforced:1 hard:10240 soft:0 granted:10240 time:0 qunit: 1024 edquot:0 may_rel:0 revoke:0 default:no [12397.549552] Lustre: DEBUG MARKER: == sanity-quota test 73a: default limits at OST Pool Quotas ========================================================== 13:48:56 (1787852936) [12427.103914] Lustre: DEBUG MARKER: set to use default quota [12429.454305] Lustre: DEBUG MARKER: set default quota [12431.108592] Lustre: DEBUG MARKER: get default quota [12437.753655] Lustre: DEBUG MARKER: Test not out of quota [12441.846699] Lustre: DEBUG MARKER: Test out of quota [12453.499256] Lustre: DEBUG MARKER: Increase default quota [12481.916694] Lustre: DEBUG MARKER: Set quota to override default quota [12481.999738] LustreError: 247228:0:(qmt_entry.c:558:qmt_adjust_edquot()) $$$ set revoke_time explicitly qmt:lustre-QMT0000 pool:dt-qpool1 id:60000 enforced:1 hard:20480 soft:20480 granted:45056 time:1788457823 qunit: 1024 edquot:0 may_rel:0 revoke:0 default:no [12494.415902] Lustre: DEBUG MARKER: Set to use default quota again [12514.895192] Lustre: DEBUG MARKER: Cleanup [12582.422099] Lustre: DEBUG MARKER: == sanity-quota test 73b: default OST Pool Quotas limit for new user ========================================================== 13:52:01 (1787853121) [12607.534499] Lustre: DEBUG MARKER: set default quota for qpool1 [12610.495855] Lustre: DEBUG MARKER: Write from user that hasn't lqe [12662.813508] Lustre: DEBUG MARKER: == sanity-quota test 74: check quota pools per user ====== 13:53:22 (1787853202) [12756.657192] Lustre: DEBUG MARKER: == sanity-quota test 75: nodemap squashed root respects quota enforcement ========================================================== 13:54:55 (1787853295) [12824.164469] Lustre: DEBUG MARKER: Write... [12828.060235] Lustre: DEBUG MARKER: Write out of block quota ... [12939.307390] Lustre: DEBUG MARKER: == sanity-quota test 76: project ID 4294967295 should be not allowed ========================================================== 13:57:58 (1787853478) [12974.014984] Lustre: DEBUG MARKER: == sanity-quota test 77: lfs setquota should fail in Lustre mount with 'ro' ========================================================== 13:58:33 (1787853513) [12981.972988] Lustre: DEBUG MARKER: == sanity-quota test 78A: Check fallocate increase quota usage ========================================================== 13:58:41 (1787853521) [13029.163943] Lustre: DEBUG MARKER: == sanity-quota test 78a: Check fallocate increase projectid usage ========================================================== 13:59:27 (1787853567) [13076.682307] Lustre: DEBUG MARKER: == sanity-quota test 79: access to non-existed dt-pool/info doesn't cause a panic ========================================================== 14:00:15 (1787853615) [13099.918108] Lustre: DEBUG MARKER: == sanity-quota test 80: check for EDQUOT after OST failover ========================================================== 14:00:39 (1787853639) [13129.140626] Lustre: *** cfs_fail_loc=a06, val=0*** [13129.146494] Lustre: Skipped 3131 previous similar messages [13129.551268] LustreError: 239340:0:(qmt_lock.c:479:qmt_lvbo_update()) $$$ failed to release quota space on glimpse 0!=2048 : rc = -11 [13129.551268] 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 [13135.102623] Lustre: Failing over lustre-OST0001 [13135.390965] Lustre: server umount lustre-OST0001 complete [13136.351578] LustreError: lustre-OST0001-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [13136.355178] 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 [13136.356455] LustreError: Skipped 1 previous similar message [13136.372879] LustreError: 240827:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [13136.400895] LustreError: 240827:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 5 previous similar messages [13146.552756] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [13147.095420] Lustre: lustre-OST0001: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [13147.120110] Lustre: lustre-OST0001: in recovery but waiting for the first client to connect [13148.515489] Lustre: lustre-OST0001: Will be in recovery for at least 1:00, or until 3 clients reconnect [13149.087789] Lustre: lustre-OST0001: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [13149.091248] Lustre: lustre-OST0001-osc-MDT0001: Connection restored to 0@lo (at 0@lo) [13149.101329] Lustre: Skipped 3 previous similar messages [13153.968165] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [13198.339367] Lustre: DEBUG MARKER: == sanity-quota test 81: Race qmt_start_pool_recalc with qmt_pool_free ========================================================== 14:02:17 (1787853737) [13211.507704] Lustre: DEBUG MARKER: User quota (block hardlimit:20 MB) [13219.941807] LustreError: 292884:0:(qmt_pool.c:1407:qmt_pool_recalc()) cfs_fail_timeout id a07 sleeping for 10000ms [13226.464749] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [13226.478233] 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 [13226.492233] Lustre: Skipped 1 previous similar message [13226.499774] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [13229.030784] 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 [13229.032931] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [13229.044363] Lustre: Skipped 2 previous similar messages [13229.057969] Lustre: Skipped 4 previous similar messages [13230.001043] LustreError: 292884:0:(qmt_pool.c:1407:qmt_pool_recalc()) cfs_fail_timeout id a07 awake [13231.911050] Lustre: lustre-MDT0000: Not available for connect from 192.168.201.27@tcp (stopping) [13232.362590] Lustre: server umount lustre-MDT0000 complete [13234.144350] LustreError: 239325:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [13234.155769] LustreError: 239325:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 7 previous similar messages [13241.094392] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [13241.243644] LustreError: MGC192.168.201.127@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [13241.580325] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [13241.596934] Lustre: Skipped 1 previous similar message [13241.645728] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:113 to 0x2c0000401:129) [13241.648823] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:112 to 0x280000401:129) [13246.194083] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [13246.958632] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [13246.967027] Lustre: Skipped 1 previous similar message [13282.947940] Lustre: DEBUG MARKER: == sanity-quota test 82: verify more than 8 qids for single operation ========================================================== 14:03:42 (1787853822) [13309.321152] Lustre: DEBUG MARKER: == sanity-quota test 83: Setting default quota shouldn't affect grace time ========================================================== 14:04:08 (1787853848) [13334.677782] Lustre: DEBUG MARKER: == sanity-quota test 84: Reset quota should fix the insane granted quota ========================================================== 14:04:34 (1787853874) [13377.818483] Lustre: *** cfs_fail_loc=a08, val=0*** [13377.820877] Lustre: Skipped 2496 previous similar messages [13377.830290] Lustre: *** cfs_fail_loc=a08, val=0*** [13377.833240] Lustre: Skipped 1 previous similar message [13470.741090] Lustre: DEBUG MARKER: == sanity-quota test 85: do not hung at write with the least_qunit ========================================================== 14:06:49 (1787854009) [13556.462300] Lustre: DEBUG MARKER: == sanity-quota test 86: Pre-acquired quota should be released if quota is over limit ========================================================== 14:08:15 (1787854095) [13619.376726] LustreError: 239321:0:(qmt_entry.c:558:qmt_adjust_edquot()) $$$ set revoke_time explicitly qmt:lustre-QMT0000 pool:md-0x0 id:60000 enforced:1 hard:2048 soft:2048 granted:16384 time:1788458960 qunit: 1024 edquot:0 may_rel:0 revoke:0 default:no [13775.032080] LustreError: 241657:0:(qmt_entry.c:558:qmt_adjust_edquot()) $$$ set revoke_time explicitly qmt:lustre-QMT0000 pool:md-0x0 id:60000 enforced:1 hard:2048 soft:2048 granted:16384 time:1788459116 qunit: 1024 edquot:0 may_rel:0 revoke:0 default:no [13921.390824] LustreError: 239322:0:(qmt_entry.c:558:qmt_adjust_edquot()) $$$ set revoke_time explicitly qmt:lustre-QMT0000 pool:md-0x0 id:1000 enforced:1 hard:2048 soft:2048 granted:16384 time:1788459262 qunit: 1024 edquot:0 may_rel:0 revoke:0 default:no [14031.926702] Lustre: DEBUG MARKER: == sanity-quota test 87: lfs quota -a should print default quota setting ========================================================== 14:16:11 (1787854571) [14038.568816] Lustre: *** cfs_fail_loc=a09, val=0*** [14038.573311] Lustre: Skipped 1 previous similar message [14042.590889] Lustre: *** cfs_fail_loc=a09, val=0*** [14042.596550] Lustre: Skipped 169 previous similar messages [14050.611055] Lustre: *** cfs_fail_loc=a09, val=0*** [14050.616699] Lustre: Skipped 349 previous similar messages [14096.868637] 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 [14096.870438] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [14096.872529] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [14096.882518] Lustre: Skipped 3 previous similar messages [14096.892211] Lustre: Skipped 3 previous similar messages [14100.272351] Lustre: lustre-MDT0000: Not available for connect from 192.168.201.27@tcp (stopping) [14101.999191] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [14102.001720] Lustre: Skipped 1 previous similar message [14102.924904] Lustre: server umount lustre-MDT0000 complete [14105.377429] LustreError: 247228:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.201.27@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [14105.396053] LustreError: 247228:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 5 previous similar messages [14110.496867] LustreError: 239320:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.201.27@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [14110.525271] LustreError: 239320:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 4 previous similar messages [14112.424043] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [14112.774049] LustreError: MGC192.168.201.127@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [14113.341586] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [14113.476180] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:131 to 0x280000401:161) [14113.486606] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:131 to 0x2c0000401:161) [14118.380090] LustreError: lustre-MDT0000-osp-MDT0001: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [14118.390832] Lustre: lustre-MDT0000-osp-MDT0001: Connection restored to 0@lo (at 0@lo) [14118.394420] Lustre: Skipped 3 previous similar messages [14118.992522] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [14136.074360] Lustre: DEBUG MARKER: == sanity-quota test 88: Writing over quota should not hang ========================================================== 14:17:55 (1787854675) [14137.496867] Lustre: DEBUG MARKER: SKIP: sanity-quota test_88 require client with >4k pages [14139.012721] Lustre: DEBUG MARKER: == sanity-quota test 89: Show default quota with squash_uid ========================================================== 14:17:58 (1787854678) [14160.768496] Lustre: DEBUG MARKER: == sanity-quota test 90a: lfs quota should work without mount point ========================================================== 14:18:20 (1787854700) [14176.830909] Lustre: DEBUG MARKER: == sanity-quota test 90b: lfs quota should work with multiple mount points ========================================================== 14:18:36 (1787854716) [14193.472095] Lustre: DEBUG MARKER: == sanity-quota test 91: new quota index files in quota_master ========================================================== 14:18:53 (1787854733) [14210.015499] LustreError: 3622:0:(client.c:1394:ptlrpc_import_delay_req()) @@@ IMP_CLOSED req@ffff8cd7037f7c00 x1874686763751552/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 [14210.039560] LustreError: 3622:0:(qsd_handler.c:298:qsd_req_completion()) $$$ DQACQ failed with -5, flags:0x8 qsd:lustre-MDT0000 qtype:usr lqe: ffff8cd70dfb5680 id:0 enforced:0 granted: 0 pending:0 waiting:0 req:1 usage: 2508 qunit:0 qtune:0 edquot:0 default:no revoke:0 [14210.067019] LustreError: 3622:0:(qsd_handler.c:298:qsd_req_completion()) Skipped 5 previous similar messages [14210.536023] 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 [14210.544327] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [14210.551546] Lustre: Skipped 2 previous similar messages [14210.567918] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [14210.571164] Lustre: Skipped 3 previous similar messages [14214.978713] Lustre: server umount lustre-MDT0000 complete [14215.649569] LustreError: 239320:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [14215.659462] LustreError: 239320:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 7 previous similar messages [14218.110965] LustreError: 239305:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787854759 with bad export cookie 18144583577774881608 [14218.120174] LustreError: MGC192.168.201.127@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [14218.120911] LustreError: 239305:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 3 previous similar messages [14218.210606] LustreError: 307970:0:(client.c:1394:ptlrpc_import_delay_req()) @@@ IMP_CLOSED req@ffff8cd7037f43c0 x1874686763756544/t0(0) o101->lustre-MDT0000-lwp-MDT0001@0@lo:23/10 lens 456/496 e 0 to 0 dl 0 ref 2 fl Rpc:QU/200/ffffffff rc 0/-1 job:'qsd_reint_0.lus.0' uid:0 gid:0 projid:4294967295 [14218.240681] LustreError: 307970:0:(client.c:1394:ptlrpc_import_delay_req()) Skipped 5 previous similar messages [14220.769881] 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 [14220.770460] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [14220.778441] Lustre: Skipped 2 previous similar messages [14220.800930] Lustre: Skipped 1 previous similar message [14224.570384] Lustre: server umount lustre-MDT0001 complete [14234.382371] Lustre: server umount lustre-OST0000 complete [14244.075110] Lustre: server umount lustre-OST0001 complete [14250.536815] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_hostid [14259.152180] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing load_modules_local [14299.725751] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [14300.026911] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [14300.060227] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [14300.118698] Lustre: lustre-MDT0000: new disk, initializing [14300.179106] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [14300.196492] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [14305.307132] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [14315.951289] Lustre: DEBUG MARKER: oleg127-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [14322.432863] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [14322.595123] Lustre: lustre-OST0000: new disk, initializing [14322.598450] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [14322.601899] Lustre: Skipped 1 previous similar message [14322.605744] Lustre: 311585:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [14322.654607] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [14323.750231] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:0:ost [14323.757247] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:0:ost] [14323.785711] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x240000400 [14328.945290] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [14340.406679] Lustre: DEBUG MARKER: oleg127-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [14349.491329] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [14349.818027] Lustre: lustre-OST0001: new disk, initializing [14349.831787] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [14349.849106] Lustre: 312640:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [14349.975833] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [14351.425953] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:1:ost [14351.445362] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:1:ost] [14351.495552] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x280000400 [14359.464713] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [14372.694948] Lustre: DEBUG MARKER: oleg127-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0001-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [14387.171204] 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 [14387.183854] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [14387.185809] Lustre: Skipped 2 previous similar messages [14387.946773] Lustre: server umount lustre-MDT0000 complete [14398.442026] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [14398.534179] LustreError: MGC192.168.201.127@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [14398.813368] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [14402.898576] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [14407.140744] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [14407.148051] Lustre: Skipped 1 previous similar message [14410.643978] Lustre: DEBUG MARKER: oleg127-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [14412.071769] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [14413.514989] LustreError: 314330:0:(qmt_entry.c:1150:qmt_map_lge_idx()) qmt: cannot map ostidx 0, num_used 1: rc = -22 [14415.354192] LustreError: 314971:0:(qmt_entry.c:1150:qmt_map_lge_idx()) qmt: cannot map ostidx 0, num_used 1: rc = -22 [14419.782677] Lustre: server umount lustre-MDT0000 complete [14427.501627] LustreError: 310580:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787854968 with bad export cookie 18144583577774884373 [14427.522040] LustreError: MGC192.168.201.127@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [14437.045921] Lustre: server umount lustre-OST0000 complete [14437.855265] Lustre: 3621:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787854963/real 1787854963] req@ffff8cd703312d00 x1874686763822208/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787854979 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [14437.883327] 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 [14437.893893] Lustre: Skipped 1 previous similar message [14441.958895] Lustre: server umount lustre-OST0001 complete [14459.669567] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_hostid [14466.891846] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing load_modules_local [14510.557404] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing load_modules_local [14519.851810] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [14520.222460] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [14520.271887] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [14520.344908] Lustre: lustre-MDT0000: new disk, initializing [14520.396866] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [14520.410541] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [14524.857947] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [14535.881601] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [14535.962776] Lustre: 319143:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [14535.986705] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [14535.994777] Lustre: Skipped 1 previous similar message [14536.061985] Lustre: lustre-MDT0001: new disk, initializing [14536.182341] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [14536.199322] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [14540.779320] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [14545.649853] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [14551.588650] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [14551.752977] Lustre: lustre-OST0000: new disk, initializing [14551.755916] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [14551.759639] Lustre: 320776:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [14553.108323] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [14553.127106] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [14553.210508] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [14558.266741] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [14570.672334] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [14570.909448] Lustre: lustre-OST0001: new disk, initializing [14570.911994] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [14570.917229] Lustre: 321645:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [14570.978810] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [14570.987652] Lustre: Skipped 2 previous similar messages [14572.291562] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [14572.299101] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [14572.462726] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [14577.753657] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [14587.030461] Lustre: DEBUG MARKER: Using TIMEOUT=20 [14590.646760] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [14598.751656] Lustre: DEBUG MARKER: == sanity-quota test 92: Cannot set inode limit with Quota Pools ========================================================== 14:25:38 (1787855138) [14617.672538] Lustre: DEBUG MARKER: == sanity-quota test 93: update projid while client write to OST ========================================================== 14:25:56 (1787855156) [14640.843305] Lustre: *** cfs_fail_loc=170c, val=0*** [14701.836573] Lustre: DEBUG MARKER: == sanity-quota test 94: lfs quota all respects nodemap offset ========================================================== 14:27:20 (1787855240) [14746.083367] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [14746.103000] 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 [14746.127435] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [14746.138092] Lustre: Skipped 1 previous similar message [14749.570322] Lustre: server umount lustre-MDT0000 complete [14751.519687] LustreError: 319151:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.201.27@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [14751.531068] LustreError: 319151:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 4 previous similar messages [14758.236685] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [14758.324555] LustreError: MGC192.168.201.127@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [14758.592910] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [14758.651417] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3 to 0x280000401:33) [14763.535355] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [14764.020579] LustreError: lustre-MDT0000-osp-MDT0001: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [14764.037810] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [14764.046155] Lustre: Skipped 2 previous similar messages [14774.241854] 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 [14774.246455] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [14774.261267] Lustre: Skipped 4 previous similar messages [14778.530321] Lustre: server umount lustre-MDT0000 complete [14784.485044] LustreError: 319150:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [14784.512042] LustreError: 319150:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 17 previous similar messages [14786.915692] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [14787.083444] LustreError: MGC192.168.201.127@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [14787.363796] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3 to 0x280000401:65) [14791.416257] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [14792.701974] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [14792.714027] Lustre: Skipped 2 previous similar messages [14792.723201] LustreError: lustre-MDT0000-osp-MDT0001: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [14799.491848] Lustre: DEBUG MARKER: == sanity-quota test 95a: Correct limits for squashed root ========================================================== 14:28:58 (1787855338) [14832.086272] Lustre: DEBUG MARKER: == sanity-quota test 95b: df respects squashed project id ========================================================== 14:29:31 (1787855371) [14873.119086] Lustre: DEBUG MARKER: == sanity-quota test 96: quota grant should be released when big files are deleted ========================================================== 14:30:12 (1787855412) [14875.180567] Lustre: DEBUG MARKER: SKIP: sanity-quota test_96 OST is too small, skip the test [14877.239650] Lustre: DEBUG MARKER: == sanity-quota test 97a: LQA control commands =========== 14:30:16 (1787855416) [14914.891056] LustreError: 332470:0:(qmt_lqa.c:79:qmt_lqa_destroy()) lustre-QMT0000: cannot destroy lqa-dt-lqa1: rc = -2 [14914.897595] LustreError: 332470:0:(qmt_lqa.c:84:qmt_lqa_destroy()) lustre-QMT0000: cannot destroy lqa-md-lqa1: rc = -2 [14918.249875] Lustre: DEBUG MARKER: == sanity-quota test 97b: Check LQA internals ============ 14:30:56 (1787855456) [14941.820134] LustreError: 333367:0:(qmt_lqa.c:250:qmt_lqa_insert_range()) lustre-QMT0000: LQA range 15-31 partially overlaps with existing range 10-19: rc = -34 [14941.831667] LustreError: 333367:0:(qmt_lqa.c:669:qmt_lqa_add()) lustre-QMT0000: lqa:lqa1 can't add range 15:31: rc = -17 [14945.594463] LustreError: 333565:0:(qmt_lqa.c:825:qmt_lqa_remove()) lustre-QMT0000: lqa-md-lqa1 cannot remove range 10:19: rc = -2 [14958.191310] Lustre: DEBUG MARKER: adding 50 LQA ranges took 2s [14965.046300] Lustre: DEBUG MARKER: Removing 50 LQA ranges took 2s [14976.041931] Lustre: DEBUG MARKER: == sanity-quota test 97c: LQA lfs quota commands and MDS restart consistency ========================================================== 14:31:54 (1787855514) [14980.339913] Lustre: Failing over lustre-MDT0000 [14980.641327] Lustre: server umount lustre-MDT0000 complete [14982.022714] LustreError: 322477:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.201.27@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [14982.123535] 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 [14982.171043] Lustre: Skipped 3 previous similar messages [14990.519399] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [14990.652941] LustreError: MGC192.168.201.127@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [14990.966602] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [14990.970562] Lustre: Skipped 1 previous similar message [14991.014895] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [14992.169616] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [14995.248482] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [14996.489381] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [14996.501954] Lustre: Skipped 3 previous similar messages [14996.560232] Lustre: lustre-MDT0000: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [14996.612797] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3 to 0x280000401:97) [15001.629947] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [15010.468132] Lustre: DEBUG MARKER: == sanity-quota test 97d: LQA disk persistence using standard commands ========================================================== 14:32:29 (1787855549) [15024.617488] Lustre: Failing over lustre-MDT0000 [15024.892900] Lustre: server umount lustre-MDT0000 complete [15027.173651] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [15034.679529] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [15034.841679] LustreError: MGC192.168.201.127@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [15035.191480] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [15038.236555] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [15040.134939] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [15040.531427] Lustre: lustre-MDT0000: Recovery over after 0:02, of 2 clients 2 recovered and 0 were evicted. [15040.591389] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3 to 0x280000401:129) [15046.388212] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [15084.686145] Lustre: DEBUG MARKER: == sanity-quota test 97e: LQA add/remove should reject invalid ranges ========================================================== 14:33:43 (1787855623) [15100.619312] LustreError: 339711:0:(qmt_lqa.c:79:qmt_lqa_destroy()) lustre-QMT0000: cannot destroy lqa-dt-lqa1: rc = -2 [15100.624743] LustreError: 339711:0:(qmt_lqa.c:84:qmt_lqa_destroy()) lustre-QMT0000: cannot destroy lqa-md-lqa1: rc = -2 [15103.389649] Lustre: DEBUG MARKER: == sanity-quota test 98: Verify MDT retry on -EDQUOT during mkdir ========================================================== 14:34:01 (1787855641) [15110.408496] Lustre: DEBUG MARKER: oleg127-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [15111.754417] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [15117.304200] Lustre: DEBUG MARKER: oleg127-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0001-mdc-*.mds_server_uuid 1475 0 [15119.166432] Lustre: DEBUG MARKER: mdc.lustre-MDT0001-mdc-*.mds_server_uuid in FULL state after 0 sec [15125.529911] Lustre: *** cfs_fail_loc=a02, val=1*** [15125.540100] LustreError: 319150:0:(lod_object.c:6315:lod_declare_create()) lustre-MDT0000-mdtlov: Injecting -EDQUOT for directory create on MDT0000 (fail_val=1): rc = -122 [15134.420118] Lustre: DEBUG MARKER: == sanity-quota test 300: inode quota with MDT directory migration at 80% limit ========================================================== 14:34:33 (1787855673) [15152.024224] Lustre: DEBUG MARKER: Creating 819 files as quota_usr ... [15167.018942] Lustre: DEBUG MARKER: Migrating directory from MDT0 to MDT1 ... [15224.567408] Lustre: DEBUG MARKER: Migration completed successfully [15264.980608] Lustre: DEBUG MARKER: == sanity-quota test complete, duration 15021 sec ======== 14:36:43 (1787855803) [15266.945543] Lustre: DEBUG MARKER: === sanity-quota: start cleanup 14:36:46 (1787855806) === [15271.499987] Lustre: DEBUG MARKER: === sanity-quota: finish cleanup 14:36:50 (1787855810) === [15280.108392] LustreError: lustre-MDT0000-osp-MDT0001: operation out_update to node 0@lo failed: rc = -107 [15280.119553] 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 [15280.135613] Lustre: Skipped 6 previous similar messages [15280.149869] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [15280.157643] Lustre: Skipped 9 previous similar messages [15283.446619] Lustre: server umount lustre-MDT0000 complete [15286.249514] LustreError: 319152:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [15286.278516] LustreError: 319152:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 22 previous similar messages [15292.481425] LustreError: 319135:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787855833 with bad export cookie 18144583577774890946 [15292.486449] LustreError: MGC192.168.201.127@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [15292.500654] LustreError: 319135:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [15293.070197] Lustre: server umount lustre-MDT0001 complete [15311.839285] Lustre: 3620:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787855837/real 1787855837] req@ffff8cd703015a40 x1874686765950592/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787855853 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [15313.124129] Lustre: server umount lustre-OST0000 complete [15313.381469] Lustre: 3621:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787855838/real 1787855838] req@ffff8cd837cdf0c0 x1874686765950848/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787855854 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [15317.024231] Lustre: 3620:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787855842/real 1787855842] req@ffff8cd70dd2d2c0 x1874686765951104/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787855858 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [15323.156805] Lustre: server umount lustre-OST0001 complete [15344.815658] Lustre: DEBUG MARKER: oleg127-server.virtnet: executing unload_modules_local [15348.016659] Key type lgssc unregistered [15348.425050] LNet: 344750:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [15348.435946] LNetError: 344750:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [15349.498672] LNet: Removed LNI 192.168.201.127@tcp [15350.712158] Key type .llcrypt unregistered [15350.714767] Key type ._llcrypt unregistered