[ 0.000000] Linux version 4.18.0rh8.10-debug (green@maintenance) (gcc version 8.5.0 20210514 (Red Hat 8.5.0-26) (GCC)) #2 SMP Mon Jul 14 01:24:22 EDT 2025 [ 0.000000] Command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers' [ 0.000000] x86/fpu: xstate_offset[2]: 576, xstate_sizes[2]: 256 [ 0.000000] x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'standard' format. [ 0.000000] signal: max sigframe size: 1776 [ 0.000000] BIOS-provided physical RAM map: [ 0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable [ 0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000000100000-0x00000000bffcdfff] usable [ 0.000000] BIOS-e820: [mem 0x00000000bffce000-0x00000000bfffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000100000000-0x0000000146dfffff] usable [ 0.000000] NX (Execute Disable) protection: active [ 0.000000] SMBIOS 2.8 present. [ 0.000000] DMI: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.17.0-8.fc42 06/10/2025 [ 0.000000] Hypervisor detected: KVM [ 0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00 [ 0.000000] kvm-clock: using sched offset of 492187504 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2399.998 MHz processor [ 0.000000] last_pfn = 0x146e00 max_arch_pfn = 0x400000000 [ 0.000000] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT [ 0.000000] last_pfn = 0xbffce max_arch_pfn = 0x400000000 [ 0.000000] found SMP MP-table at [mem 0x000f54b0-0x000f54bf] [ 0.000000] RAMDISK: [mem 0xbcc54000-0xbffbffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F52D0 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE2439 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE22D5 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 002295 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE2349 000090 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE23D9 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE2411 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe22d5-0xbffe2348] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe22d4] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe2349-0xbffe23d8] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe23d9-0xbffe2410] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe2411-0xbffe2438] [ 0.000000] No NUMA configuration found [ 0.000000] Faking a node at [mem 0x0000000000000000-0x0000000146dfffff] [ 0.000000] NODE_DATA(0) allocated [mem 0x1465a3000-0x1465cdfff] [ 0.000000] Reserving 256MB of memory at 2752MB for crashkernel (System RAM: 4205MB) [ 0.000000] Zone ranges: [ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.000000] DMA32 [mem 0x0000000001000000-0x00000000ffffffff] [ 0.000000] Normal [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Device empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff] [ 0.000000] node 0: [mem 0x0000000000100000-0x00000000bffcdfff] [ 0.000000] node 0: [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Zeroed struct page in unavailable ranges: 4756 pages [ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x0000000146dfffff] [ 0.000000] ACPI: PM-Timer IO Port: 0x608 [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) [ 0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) [ 0.000000] Using ACPI (MADT) for SMP configuration information [ 0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000] TSC deadline timer available [ 0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs [ 0.000000] kvm-guest: KVM setup pv remote TLB flush [ 0.000000] kvm-guest: setup PV sched yield [ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff] [ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff] [ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff] [ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff] [ 0.000000] PM: Registered nosave memory: [mem 0xbffce000-0xbfffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xc0000000-0xfeffbfff] [ 0.000000] PM: Registered nosave memory: [mem 0xfeffc000-0xfeffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xff000000-0xfffbffff] [ 0.000000] PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff] [ 0.000000] [mem 0xc0000000-0xfeffbfff] available for PCI devices [ 0.000000] Booting paravirtualized kernel on KVM [ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns [ 0.000000] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1 [ 0.000000] percpu: Embedded 63 pages/cpu s221184 r8192 d28672 u524288 [ 0.000000] kvm-guest: PV spinlocks enabled [ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1059606 [ 0.000000] Policy zone: Normal [ 0.000000] Kernel command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] Specific versions of hardware are certified with Red Hat Enterprise Linux 8. Please see the list of hardware certified with Red Hat Enterprise Linux 8 at https://catalog.redhat.com. [ 0.000000] audit: disabled (until reboot) [ 0.000000] software IO TLB: area num 4. [ 0.000000] Memory: 2829652K/4306352K available (18435K kernel code, 11221K rwdata, 7248K rodata, 2908K init, 18040K bss, 524588K 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.001014] APIC: Switch to symmetric I/O mode setup [ 0.002408] x2apic enabled [ 0.003011] Switched APIC routing to physical x2apic. [ 0.004020] kvm-guest: setup PV IPIs [ 0.007000] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.007000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.007023] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.008015] pid_max: default: 32768 minimum: 301 [ 0.009143] LSM: Security Framework initializing [ 0.010097] Yama: becoming mindful. [ 0.011073] SELinux: Initializing. [ 0.012067] *** VALIDATE selinux *** [ 0.020771] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.025160] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.027054] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.028154] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.029111] *** VALIDATE tmpfs *** [ 0.031443] *** VALIDATE proc *** [ 0.032280] *** VALIDATE cgroup *** [ 0.033012] *** VALIDATE cgroup2 *** [ 0.035159] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.037170] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.038010] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.039030] Spectre V2 : User space: Vulnerable [ 0.040015] Speculative Store Bypass: Vulnerable [ 0.043519] debug: unmapping init [mem 0xffffffffb3859000-0xffffffffb3860fff] [ 0.045214] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.046753] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.047022] ... version: 2 [ 0.048014] ... bit width: 48 [ 0.049018] ... generic registers: 4 [ 0.050019] ... value mask: 0000ffffffffffff [ 0.051017] ... max period: 00007fffffffffff [ 0.052020] ... fixed-purpose events: 3 [ 0.053017] ... event mask: 000000070000000f [ 0.055242] rcu: Hierarchical SRCU implementation. [ 0.057633] smp: Bringing up secondary CPUs ... [ 0.058620] x86: Booting SMP configuration: [ 0.059037] .... node #0, CPUs: #1 #2 #3 [ 0.062500] smp: Brought up 1 node, 4 CPUs [ 0.064016] smpboot: Max logical packages: 1 [ 0.065029] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.227744] node 0 deferred pages initialised in 159ms [ 0.231109] devtmpfs: initialized [ 0.232441] x86/mm: Memory block size: 128MB [ 0.235927] gcov: version magic: 0x41383552 [ 0.239317] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.240084] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.241284] pinctrl core: initialized pinctrl subsystem [ 0.242191] [ 0.242629] ************************************************************* [ 0.243019] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.244016] ** ** [ 0.245021] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.246017] ** ** [ 0.247017] ** This means that this kernel is built to expose internal ** [ 0.248020] ** IOMMU data structures, which may compromise security on ** [ 0.249017] ** your system. ** [ 0.250019] ** ** [ 0.251017] ** If you see this message and you are not debugging the ** [ 0.252017] ** kernel, report this immediately to your vendor! ** [ 0.253012] ** ** [ 0.254016] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.255015] ************************************************************* [ 0.257000] NET: Registered protocol family 16 [ 0.259601] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.264092] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.267096] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.271147] cpuidle: using governor menu [ 0.273978] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.277710] PCI: Using configuration type 1 for base access [ 0.280235] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.290129] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.293095] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.296141] cryptd: max_cpu_qlen set to 1000 [ 0.299270] ACPI: Added _OSI(Module Device) [ 0.301025] ACPI: Added _OSI(Processor Device) [ 0.303020] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.305019] ACPI: Added _OSI(Processor Aggregator Device) [ 0.309111] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.315477] ACPI: Interpreter enabled [ 0.317086] ACPI: PM: (supports S0 S3 S4 S5) [ 0.319039] ACPI: Using IOAPIC for interrupt routing [ 0.321231] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.325472] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.336680] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.339064] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.343031] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.347114] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.352631] acpiphp: Slot [2] registered [ 0.355193] acpiphp: Slot [5] registered [ 0.356157] acpiphp: Slot [6] registered [ 0.358185] acpiphp: Slot [7] registered [ 0.359194] acpiphp: Slot [8] registered [ 0.361170] acpiphp: Slot [9] registered [ 0.363161] acpiphp: Slot [10] registered [ 0.364227] acpiphp: Slot [3] registered [ 0.366153] acpiphp: Slot [4] registered [ 0.368136] acpiphp: Slot [11] registered [ 0.369129] acpiphp: Slot [12] registered [ 0.371141] acpiphp: Slot [13] registered [ 0.372132] acpiphp: Slot [14] registered [ 0.374133] acpiphp: Slot [15] registered [ 0.376190] acpiphp: Slot [16] registered [ 0.377145] acpiphp: Slot [17] registered [ 0.379133] acpiphp: Slot [18] registered [ 0.381142] acpiphp: Slot [19] registered [ 0.382150] acpiphp: Slot [20] registered [ 0.384139] acpiphp: Slot [21] registered [ 0.385137] acpiphp: Slot [22] registered [ 0.387155] acpiphp: Slot [23] registered [ 0.389103] acpiphp: Slot [24] registered [ 0.390130] acpiphp: Slot [25] registered [ 0.392125] acpiphp: Slot [26] registered [ 0.394136] acpiphp: Slot [27] registered [ 0.395138] acpiphp: Slot [28] registered [ 0.397165] acpiphp: Slot [29] registered [ 0.399117] acpiphp: Slot [30] registered [ 0.401185] acpiphp: Slot [31] registered [ 0.404083] PCI host bridge to bus 0000:00 [ 0.406042] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.409036] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.412042] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.416043] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.419036] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.422044] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.424231] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.428173] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.432557] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.445015] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.449168] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.452019] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.454019] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.458022] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.460634] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.463917] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.467053] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.471677] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.477026] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.491015] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.497021] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.504662] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.515017] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.525019] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.546026] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.557011] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.565023] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.574022] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.592018] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.605000] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.613016] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.618018] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.635027] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.643000] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.651025] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.658021] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.671032] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.685810] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.692017] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.699026] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.715027] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 0.726688] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.738024] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.743020] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.760025] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 0.770291] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.773570] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.776314] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.778433] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.781251] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.785568] iommu: Default domain type: Passthrough [ 0.788544] SCSI subsystem initialized [ 0.790199] ACPI: bus type USB registered [ 0.792213] usbcore: registered new interface driver usbfs [ 0.794107] usbcore: registered new interface driver hub [ 0.796140] usbcore: registered new device driver usb [ 0.798252] pps_core: LinuxPPS API ver. 1 registered [ 0.800017] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.803115] PTP clock support registered [ 0.806057] EDAC MC: Ver: 3.0.0 [ 0.808148] PCI: Using ACPI for IRQ routing [ 0.809983] NetLabel: Initializing [ 0.811015] NetLabel: domain hash size = 128 [ 0.813012] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.814121] NetLabel: unlabeled traffic allowed by default [ 0.817052] vgaarb: loaded [ 0.819344] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.822022] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.831352] clocksource: Switched to clocksource kvm-clock [ 0.942482] VFS: Disk quotas dquot_6.6.0 [ 0.944578] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.947505] *** VALIDATE ramfs *** [ 0.949035] *** VALIDATE hugetlbfs *** [ 0.951073] pnp: PnP ACPI init [ 0.954033] pnp: PnP ACPI: found 6 devices [ 0.972189] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.976537] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.979169] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.981796] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.984672] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.989143] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.992317] NET: Registered protocol family 2 [ 0.995196] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 1.000366] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 1.004717] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 1.010856] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 1.015465] TCP: Hash tables configured (established 65536 bind 65536) [ 1.018716] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 1.022541] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 1.025737] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 1.028617] NET: Registered protocol family 1 [ 1.031517] RPC: Registered named UNIX socket transport module. [ 1.034028] RPC: Registered udp transport module. [ 1.036016] RPC: Registered tcp transport module. [ 1.037787] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 1.040770] NET: Registered protocol family 44 [ 1.042745] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 1.045188] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 1.047503] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 1.050340] PCI: CLS 0 bytes, default 64 [ 1.052896] Unpacking initramfs... [ 2.470756] debug: unmapping init [mem 0xffff89d47cc54000-0xffff89d47ffbffff] [ 2.474659] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.477086] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.480818] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 2.995612] Initialise system trusted keyrings [ 2.997610] Key type blacklist registered [ 2.999848] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 3.020082] zbud: loaded [ 3.023763] *** VALIDATE nfs *** [ 3.025262] *** VALIDATE nfs4 *** [ 3.027296] pstore: using deflate compression [ 3.031825] Platform Keyring initialized [ 3.140700] NET: Registered protocol family 38 [ 3.142629] Key type asymmetric registered [ 3.144604] Asymmetric key parser 'x509' registered [ 3.146628] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 3.150114] io scheduler mq-deadline registered [ 3.151631] io scheduler kyber registered [ 3.153175] io scheduler bfq registered [ 3.155475] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 3.158662] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 3.161935] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 3.165326] ACPI: Power Button [PWRF] [ 3.170595] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 3.178173] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 3.194569] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 3.203151] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 3.219489] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 3.247436] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.277947] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.284147] Non-volatile memory driver v1.3 [ 3.286499] Linux agpgart interface v0.103 [ 3.326313] virtio_blk virtio1: [vda] 133936 512-byte logical blocks (68.6 MB/65.4 MiB) [ 3.329698] vda: detected capacity change from 0 to 68575232 [ 3.344141] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.347763] vdb: detected capacity change from 0 to 1073741824 [ 3.362081] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.365827] vdc: detected capacity change from 0 to 2621440000 [ 3.396257] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.401025] vdd: detected capacity change from 0 to 2621440000 [ 3.449876] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.455276] vde: detected capacity change from 0 to 4294967296 [ 3.495179] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.499513] vdf: detected capacity change from 0 to 4294967296 [ 3.512904] libphy: Fixed MDIO Bus: probed [ 3.525494] usbcore: registered new interface driver usbserial_generic [ 3.529531] usbserial: USB Serial support registered for generic [ 3.534590] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.540202] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.543435] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.548079] mousedev: PS/2 mouse device common for all mice [ 3.554433] rtc_cmos 00:05: RTC can wake from S4 [ 3.558309] rtc_cmos 00:05: registered as rtc0 [ 3.561171] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.562666] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.562710] intel_pstate: CPU model not supported [ 3.573509] hid: raw HID events driver (C) Jiri Kosina [ 3.584757] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.591160] usbcore: registered new interface driver usbhid [ 3.599484] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.608651] usbhid: USB HID core driver [ 3.610867] drop_monitor: Initializing network drop monitor service [ 3.614664] Initializing XFRM netlink socket [ 3.617904] NET: Registered protocol family 10 [ 3.622724] Segment Routing with IPv6 [ 3.625803] NET: Registered protocol family 17 [ 3.628308] mpls_gso: MPLS GSO support [ 3.637563] RAS: Correctable Errors collector initialized. [ 3.641193] AVX version of gcm_enc/dec engaged. [ 3.644089] AES CTR mode by8 optimization enabled [ 3.841987] sched_clock: Marking stable (3841914518, 0)->(4770065327, -928150809) [ 3.853241] registered taskstats version 1 [ 3.857475] Loading compiled-in X.509 certificates [ 3.861127] zswap: loaded using pool lzo/zbud [ 3.946337] Key type big_key registered [ 4.009876] Key type encrypted registered [ 4.013257] ima: No TPM chip found, activating TPM-bypass! [ 4.020709] ima: Allocated hash algorithm: sha1 [ 4.025672] ima: No architecture policies found [ 4.030730] evm: Initialising EVM extended attributes: [ 4.036563] evm: security.selinux [ 4.042621] evm: security.ima [ 4.044284] evm: security.capability [ 4.046229] evm: HMAC attrs: 0x1 [ 4.067298] rtc_cmos 00:05: setting system clock to 2026-04-09 19:35:56 UTC (1775763356) [ 4.086455] debug: unmapping init [mem 0xffffffffb4803000-0xffffffffb49fffff] [ 4.097553] debug: unmapping init [mem 0xffffffffb3582000-0xffffffffb3858fff] [ 4.108419] Write protecting the kernel read-only data: 28672k [ 4.116712] debug: unmapping init [mem 0xffffffffb1c03000-0xffffffffb1dfffff] [ 4.127127] debug: unmapping init [mem 0xffffffffb2514000-0xffffffffb25fffff] [ 4.273426] 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.311429] systemd[1]: Detected virtualization kvm. [ 4.317739] systemd[1]: Detected architecture x86-64. [ 4.327899] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 4.398270] systemd[1]: No hostname configured. [ 4.400977] systemd[1]: Set hostname to . [ 4.405370] random: systemd: uninitialized urandom read (16 bytes read) [ 4.411157] systemd[1]: Initializing machine ID from random generator. [ 4.531725] random: ln: uninitialized urandom read (6 bytes read) [ 4.749925] random: systemd: uninitialized urandom read (16 bytes read) [ 4.754745] systemd[1]: Listening on Journal Socket. [ OK ] Listening on Journal Socket. [ 4.772342] systemd[1]: Started Memstrack Anylazing Service. [ OK ] Started Memstrack Anylazing Service. [ 4.808465] systemd[1]: Reached target Swap. [ OK ] Reached target Swap. [ OK ] Reached target Slices. [ OK ] Listening on udev Kernel Socket. Starting Setup Virtual Console... [ OK ] Reached target Timers. [ OK ] Listening on Journal Socket (/dev/log). Starting Journal Service... Starting Create list of required st…ce nodes for the current kernel... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. [ OK ] Reached target Local File Systems. Starting Create Volatile Files and Directories... Starting Apply Kernel Variables... [ OK ] Listening on udev Control Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Initrd Root Device. [ OK ] Started Setup Virtual Console. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Apply Kernel Variables. Starting Create Static Device Nodes in /dev... Starting dracut cmdline hook... [ OK ] Started Journal Service. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 6.598776] device-mapper: uevent: version 1.0.3 [ 6.601541] device-mapper: ioctl: 4.46.0-ioctl (2022-02-22) initialised: dm-devel@redhat.com [ OK ] Started dracut pre-udev hook. Starting udev Kernel Device Manager... [ OK ] Started udev Kernel Device Manager. Starting dracut pre-trigger hook... [ OK ] Started dracut pre-trigger hook. Starting udev Coldplug all Devices... Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. Starting dracut initqueue hook... [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ 8.794766] random: fast init done [ 8.835383] virtio_net virtio0 ens2: renamed from eth0 [ 9.050966] scsi host0: ata_piix [ 9.093193] scsi host1: ata_piix [ 9.101920] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 9.109241] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 14.601561] random: crng init done [ 14.607552] random: 7 urandom warning(s) missed due to ratelimiting [ 16.530341] dracut-initqueue[593]: RTNETLINK answers: File exists 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. [ 17.877405] 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 Timers. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Paths. [ OK ] Stopped target Sockets. [ OK ] Stopped target Slices. [ OK ] Stopped target System Initialization. [ OK ] Stopped target Swap. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. Stopping udev Kernel Device Manager... [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Closed udev Control Socket. [ OK ] Closed udev Kernel Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 20.968118] printk: systemd: 25 output lines suppressed due to ratelimiting [ 22.134533] SELinux: Disabled at runtime. [ 22.353375] 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) [ 22.391502] systemd[1]: Detected virtualization kvm. [ 22.397920] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 24.353907] systemd[1]: initrd-switch-root.service: Succeeded. [ 24.367876] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 24.406173] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 24.425565] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 24.432238] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 24.471902] systemd[1]: Starting Journal Service... Starting Journal Service... [ 24.493104] systemd[1]: Started Forward Password Requests to Wall Directory Watch. [ OK ] Started Forward Password Requests to Wall Directory Watch. Starting Remount Root and Kernel File Systems... [ OK ] Created slice system-getty.slice. [ OK ] Listening on udev Control Socket. Activating swap /dev/disk/by-label/SWAP... [ OK ] Listening on udev Kernel Socket. Starting udev Coldplug all Devices... [ 24.733681] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS [ OK ] Created slice User and Session Slice. [ OK ] Reached target Slices. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Listening on Process Core Dump Socket. Mounting POSIX Message Queue File System... Mounting Kernel Debug File System... [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Reached target Paths. [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Reached target RPC Port Mapper. [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd File Systems. [ OK ] Created slice system-serial\x2dgetty.slice. Mounting Huge Pages File System... [ OK ] Reached target rpc_pipefs.target. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Created slice system-sshd\x2dkeygen.slice. Starting Apply Kernel Variables... [ OK ] Stopped target Initrd Root File System. [ OK ] Started Journal Service. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Mounted Kernel Debug File System. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Mounted Huge Pages File System. [ OK ] Started Apply Kernel Variables. [ OK ] 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. [ 26.257344] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 27.204368] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 27.238182] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 27.807895] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 28.102861] EDAC sbridge: Ver: 1.1.2 [* ] A start job is running for Configur…-only root support (8s / no limit) [** ] A start job is running for Configur…-only root support (8s / no limit) [*** ] A start job is running for Configur…-only root support (9s / no limit)[ 33.320928] Key type dns_resolver registered [ *** ] A start job is running for Configur…-only root support (9s / no limit)[ 34.141420] NFS: Registering the id_resolver key type [ 34.143992] Key type id_resolver registered [ 34.145246] Key type id_legacy registered [ *** ] A start job is running for Configur…only root support (10s / no limit) [ ***] A start job is running for Configur…only root support (10s / no limit) [ OK ] Started Configure read-only root support. Starting Load/Save Random Seed... [ OK ] Reached target Local File Systems. Starting Mark the need to relabel after reboot... Starting Rebuild Dynamic Linker Cache... Starting Create Volatile Files and Directories... [ OK ] Started Load/Save Random Seed. [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Create Volatile Files and Directories. Starting RPC Bind... Starting Update UTMP about System Boot/Shutdown... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Started dnf makecache --timer. [ OK ] Reached target Timers. [ OK ] Reached target Basic System. [ OK ] Started D-Bus System Message Bus. Starting Network Manager... [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting Restore /run/initramfs on shutdown... [ OK ] Started irqbalance daemon. Starting Login Service... [ OK ] Reached target sshd-keygen.target. [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Network Manager. Starting Network Manager Wait Online... [ OK ] Reached target Network. Starting Dynamic System Tuning Daemon... Starting GSSAPI Proxy Daemon... Starting OpenSSH server daemon... [ OK ] Started Login Service. Starting Hostname Service... [ OK ] Started OpenSSH server daemon. [ 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 Command Scheduler. [ OK ] Started Serial Getty on ttyS1. [ OK ] Started Getty on tty1. [ OK ] Started Serial Getty on ttyS0. [ OK ] Reached target Login Prompts. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting Crash recovery kernel arming... Starting Notify NFS peers of a restart... Starting System Logging Service... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg313-server login: [ 92.086646] libcfs: loading out-of-tree module taints kernel. [ 92.119674] Key type ._llcrypt registered [ 92.122406] Key type .llcrypt registered [ 92.224415] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_hostid [ 112.116567] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing load_modules_local [ 113.717693] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 113.749941] alg: No test for adler32 (adler32-zlib) [ 115.399876] Lustre: Lustre: Build Version: 2.17.51_76_g43aed12 [ 116.924892] LNet: Added LNI 192.168.203.113@tcp [8/256/0/180] [ 118.832581] Key type lgssc registered [ 121.441633] Lustre: Echo OBD driver; http://www.lustre.org/ [ 138.580981] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 184.474779] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing load_modules_local [ 196.820182] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 196.861693] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 198.328088] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 198.416983] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 198.531356] Lustre: lustre-MDT0000: new disk, initializing [ 198.653791] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 198.681669] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 203.483925] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 217.742824] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 217.844605] Lustre: 6513:0:(mgs_llog.c:1348:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 217.874458] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 217.880157] Lustre: Skipped 1 previous similar message [ 217.974528] Lustre: lustre-MDT0001: new disk, initializing [ 218.048983] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 218.092608] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 218.119167] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 221.696554] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 226.288452] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 235.830777] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 236.140657] Lustre: lustre-OST0000: new disk, initializing [ 236.145259] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 236.192750] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 241.170280] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 241.179092] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 241.265666] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 242.247225] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 255.796917] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 256.000560] Lustre: lustre-OST0001: new disk, initializing [ 256.007375] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 256.076078] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 262.059721] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 264.727457] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 264.743517] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 264.802483] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 273.936521] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 280.407601] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 291.604689] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing check_logdir /tmp/testlogs/ [ 297.321576] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing yml_node [ 301.877122] Lustre: DEBUG MARKER: Client: 2.17.51.76 [ 304.948664] Lustre: DEBUG MARKER: MDS: 2.17.51.76 [ 308.201564] Lustre: DEBUG MARKER: OSS: 2.17.51.76 [ 310.062870] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity-quota ============----- Thu Apr 9 15:41:01 EDT 2026 [ 328.873679] Lustre: DEBUG MARKER: excepting tests: 2 4a 63 65 [ 330.325149] Lustre: DEBUG MARKER: skipping tests SLOW=no: 61 [ 333.022494] Lustre: DEBUG MARKER: === sanity-quota: start setup 15:41:24 (1775763684) === [ 336.266075] Lustre: DEBUG MARKER: oleg313-client.virtnet: executing check_config_client /mnt/lustre [ 354.302945] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 357.504566] Lustre: 13284:0:(mgs_llog.c:1348:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 361.127926] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 366.227454] Lustre: DEBUG MARKER: === sanity-quota: finish setup 15:41:57 (1775763717) === [ 420.931934] Lustre: DEBUG MARKER: == sanity-quota test 0: Test basic quota performance ===== 15:42:52 (1775763772) [ 441.318543] hrtimer: interrupt took 5827808 ns [ 465.376768] Lustre: DEBUG MARKER: == sanity-quota test 1a: Block hard limit (normal use and out of quota) ========================================================== 15:43:36 (1775763816) [ 476.469707] Lustre: DEBUG MARKER: User quota (block hardlimit:10 MB) [ 483.407533] Lustre: DEBUG MARKER: Write... [ 485.791161] Lustre: DEBUG MARKER: Write out of block quota ... [ 515.197686] Lustre: DEBUG MARKER: -------------------------------------- [ 516.786871] Lustre: DEBUG MARKER: Group quota (block hardlimit:10 MB) [ 523.417291] Lustre: DEBUG MARKER: Write... [ 525.568537] Lustre: DEBUG MARKER: Write out of block quota ... [ 562.752514] Lustre: DEBUG MARKER: -------------------------------------- [ 564.502546] Lustre: DEBUG MARKER: Project quota (block hardlimit:10 mb) [ 567.222233] Lustre: DEBUG MARKER: Write... [ 569.830434] Lustre: DEBUG MARKER: Write out of block quota ... [ 619.026759] Lustre: DEBUG MARKER: == sanity-quota test 1b: Quota pools: Block hard limit (normal use and out of quota) ========================================================== 15:46:10 (1775763970) [ 630.841929] Lustre: DEBUG MARKER: User quota (block hardlimit:20 MB) [ 650.730570] Lustre: DEBUG MARKER: Write... [ 652.640811] Lustre: DEBUG MARKER: Write out of block quota ... [ 684.255696] Lustre: DEBUG MARKER: -------------------------------------- [ 685.679970] Lustre: DEBUG MARKER: Group quota (block hardlimit:20 MB) [ 692.470754] Lustre: DEBUG MARKER: Write... [ 694.586259] Lustre: DEBUG MARKER: Write out of block quota ... [ 729.861404] Lustre: DEBUG MARKER: -------------------------------------- [ 731.390418] Lustre: DEBUG MARKER: Project quota (block hardlimit:20 mb) [ 734.073830] Lustre: DEBUG MARKER: Write... [ 736.448908] Lustre: DEBUG MARKER: Write out of block quota ... [ 798.944467] Lustre: DEBUG MARKER: == sanity-quota test 1c: Quota pools: check 3 pools with hardlimit only for global ========================================================== 15:49:10 (1775764150) [ 811.809919] Lustre: DEBUG MARKER: User quota (block hardlimit:20 MB) [ 842.317467] Lustre: DEBUG MARKER: Write... [ 845.307465] Lustre: DEBUG MARKER: Write out of block quota ... [ 937.632940] Lustre: DEBUG MARKER: == sanity-quota test 1d: Quota pools: check block hardlimit on different pools ========================================================== 15:51:28 (1775764288) [ 951.844869] Lustre: DEBUG MARKER: User quota (block hardlimit:20 MB) [ 979.080292] Lustre: DEBUG MARKER: Write... [ 981.269872] Lustre: DEBUG MARKER: Write out of block quota ... [ 1053.973791] Lustre: DEBUG MARKER: == sanity-quota test 1e: Quota pools: global pool high block limit vs quota pool with small ========================================================== 15:53:25 (1775764405) [ 1064.801795] Lustre: DEBUG MARKER: User quota (block hardlimit:53000000 MB) [ 1077.618134] Lustre: DEBUG MARKER: Write... [ 1079.611442] Lustre: DEBUG MARKER: Write out of block quota ... [ 1090.807406] Lustre: DEBUG MARKER: Write... [ 1135.300451] Lustre: DEBUG MARKER: == sanity-quota test 1f: Quota pools: correct qunit after removing/adding OST ========================================================== 15:54:46 (1775764486) [ 1148.106523] Lustre: DEBUG MARKER: User quota (block hardlimit:200 MB) [ 1163.662201] Lustre: DEBUG MARKER: Write... [ 1165.627968] Lustre: DEBUG MARKER: Write out of block quota ... [ 1195.811898] Lustre: DEBUG MARKER: Write... [ 1198.341694] Lustre: DEBUG MARKER: Write out of block quota ... [ 1249.810366] Lustre: DEBUG MARKER: == sanity-quota test 1g: Quota pools: Block hard limit with wide striping ========================================================== 15:56:41 (1775764601) [ 1262.669221] Lustre: DEBUG MARKER: User quota (block hardlimit:40 MB) [ 1275.971603] Lustre: 6522:0:(osd_handler.c:2191:osd_trans_start()) lustre-MDT0000: credits 6546 > trans_max 3200 [ 1275.981231] Lustre: 6522:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 4/16/0, destroy: 0/0/0 [ 1275.994172] Lustre: 6522:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 401/401/0, xattr_set: 602/5615/0 [ 1276.011606] Lustre: 6522:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 20/118/0, punch: 0/0/0, quota 8/328/0 [ 1276.026207] Lustre: 6522:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/68/0, delete: 0/0/0 [ 1276.038534] Lustre: 6522:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 1276.049151] CPU: 2 PID: 6522 Comm: mdt00_002 Kdump: loaded Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 1276.061239] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.17.0-8.fc42 06/10/2025 [ 1276.068949] Call Trace: [ 1276.073140] ? dump_stack+0xbb/0x10e [ 1276.076315] ? osd_trans_start+0x8db/0x9d0 [osd_ldiskfs] [ 1276.083726] ? top_trans_start+0x599/0xd80 [ptlrpc] [ 1276.089291] ? lod_ref_add+0x30/0x30 [lod] [ 1276.096595] ? lod_trans_start+0x109/0x4c0 [lod] [ 1276.106931] ? mdd_declare_attr_set+0x190/0x690 [mdd] [ 1276.108286] ? mdd_env_info+0x25/0xc0 [mdd] [ 1276.109394] ? mdd_trans_start+0x18/0x30 [mdd] [ 1276.118976] ? mdd_attr_set+0xa5a/0x1240 [mdd] [ 1276.120217] ? mdt_reint_setattr+0x1342/0x1f90 [mdt] [ 1276.130099] ? mdt_reint_setattr+0x1342/0x1f90 [mdt] [ 1276.140310] ? mdt_reint_rec+0x139/0x2b0 [mdt] [ 1276.142127] ? mdt_reint_internal+0x6a0/0xdc0 [mdt] [ 1276.151779] ? mdt_reint+0x163/0x190 [mdt] [ 1276.156776] ? tgt_handle_request0+0x137/0xaf0 [ptlrpc] [ 1276.165159] ? tgt_request_handle+0x575/0x1e70 [ptlrpc] [ 1276.168413] ? ptlrpc_server_handle_request+0x443/0x13b0 [ptlrpc] [ 1276.177204] ? lprocfs_counter_add+0x15b/0x210 [obdclass] [ 1276.186239] ? ptlrpc_main+0xce8/0x1400 [ptlrpc] [ 1276.188335] ? ptlrpc_wait_event+0x690/0x690 [ptlrpc] [ 1276.197797] ? kthread+0x1d1/0x200 [ 1276.199651] ? set_kthread_struct+0x70/0x70 [ 1276.204225] ? ret_from_fork+0x1f/0x30 [ 1277.472117] Lustre: DEBUG MARKER: Write... [ 1288.838130] Lustre: DEBUG MARKER: Write out of block quota ... [ 1361.357238] Lustre: DEBUG MARKER: == sanity-quota test 1h: Block hard limit test using fallocate ========================================================== 15:58:32 (1775764712) [ 1374.721427] Lustre: DEBUG MARKER: User quota (block hardlimit:10 MB) [ 1381.085649] Lustre: DEBUG MARKER: Write 5MiB Using Fallocate [ 1388.395873] Lustre: DEBUG MARKER: Write 11MiB Using Fallocate [ 1467.521777] Lustre: DEBUG MARKER: == sanity-quota test 1i: Quota pools: different limit and usage relations ========================================================== 16:00:18 (1775764818) [ 1478.644537] Lustre: DEBUG MARKER: User quota (block hardlimit:200 MB) [ 1492.294935] Lustre: DEBUG MARKER: Write... [ 1494.660444] Lustre: DEBUG MARKER: Write out of block quota ... [ 1526.761727] Lustre: DEBUG MARKER: Write... [ 1529.163262] Lustre: DEBUG MARKER: Write out of block quota ... [ 1540.802092] LustreError: 19870:0:(qmt_entry.c:552:qmt_adjust_edquot()) $$$ set revoke_time explicitly qmt:lustre-QMT0000 pool:dt-qpool1 id:60000 enforced:1 hard:10240 soft:0 granted:14344 time:0 qunit: 1024 edquot:0 may_rel:0 revoke:0 default:no [ 1580.991965] Lustre: DEBUG MARKER: == sanity-quota test 1j: Enable project quota enforcement for root ========================================================== 16:02:12 (1775764932) [ 1598.101889] Lustre: DEBUG MARKER: -------------------------------------- [ 1600.117485] Lustre: DEBUG MARKER: Project quota (hardlimit: 40 mb, 2048 files) [ 1914.252943] Lustre: DEBUG MARKER: == sanity-quota test 1k: LQA: Block hard limit (normal use and out of quota) ========================================================== 16:07:45 (1775765265) [ 1927.862789] Lustre: DEBUG MARKER: Write... [ 1930.573324] Lustre: DEBUG MARKER: Write out of block quota ... [ 1959.786812] Lustre: DEBUG MARKER: Write... [ 1962.869479] Lustre: DEBUG MARKER: Write out of block quota ... [ 1992.493345] Lustre: DEBUG MARKER: Write... [ 1995.377665] Lustre: DEBUG MARKER: Write out of block quota ... [ 2039.006381] Lustre: DEBUG MARKER: == sanity-quota test 1l: Async writes should not be rejected by quota with root_prj_enable ========================================================== 16:09:50 (1775765390) [ 2087.571284] Lustre: DEBUG MARKER: SKIP: sanity-quota test_2 skipping excluded test 2 [ 2090.026411] Lustre: DEBUG MARKER: == sanity-quota test 3a: Block soft limit (start timer, timer goes off, stop timer) ========================================================== 16:10:40 (1775765440) [ 2135.290324] Lustre: DEBUG MARKER: Write after timer goes off [ 2137.764515] Lustre: DEBUG MARKER: Write after cancel lru locks [ 2211.967386] Lustre: DEBUG MARKER: Write after timer goes off [ 2214.134104] Lustre: DEBUG MARKER: Write after cancel lru locks [ 2284.931526] Lustre: DEBUG MARKER: Write after timer goes off [ 2287.664719] Lustre: DEBUG MARKER: Write after cancel lru locks [ 2354.098462] Lustre: DEBUG MARKER: == sanity-quota test 3b: Quota pools: Block soft limit (start timer, expires, stop timer) ========================================================== 16:15:05 (1775765705) [ 2407.206721] Lustre: DEBUG MARKER: Write after timer goes off [ 2410.036312] Lustre: DEBUG MARKER: Write after cancel lru locks [ 2481.331373] Lustre: DEBUG MARKER: Write after timer goes off [ 2483.938535] Lustre: DEBUG MARKER: Write after cancel lru locks [ 2555.916417] Lustre: DEBUG MARKER: Write after timer goes off [ 2558.136468] Lustre: DEBUG MARKER: Write after cancel lru locks [ 2639.610392] Lustre: DEBUG MARKER: == sanity-quota test 3c: Quota pools: check block soft limit on different pools ========================================================== 16:19:51 (1775765991) [ 2699.177432] Lustre: DEBUG MARKER: Write after timer goes off [ 2703.273938] Lustre: DEBUG MARKER: Write after cancel lru locks [ 2774.964850] Lustre: DEBUG MARKER: SKIP: sanity-quota test_4a skipping excluded test 4a [ 2776.669914] Lustre: DEBUG MARKER: == sanity-quota test 4b: Grace time strings handling ===== 16:22:08 (1775766128) [ 2786.708756] Lustre: DEBUG MARKER: == sanity-quota test 5: Chown [ 2901.024983] Lustre: DEBUG MARKER: == sanity-quota test 6: Test dropping acquire request on master ========================================================== 16:24:11 (1775766251) [ 2940.756942] Lustre: *** cfs_fail_loc=513, val=601*** [ 2940.771028] Lustre: Skipped 3 previous similar messages [ 2941.922938] Lustre: *** cfs_fail_loc=513, val=601*** [ 2942.613962] LustreError: 16400:0:(service.c:2320:ptlrpc_server_handle_req_in()) drop incoming rpc opc 601, x1862022958220416 [ 2943.457107] Lustre: *** cfs_fail_loc=513, val=601*** [ 2943.459064] Lustre: Skipped 33 previous similar messages [ 2945.876775] Lustre: *** cfs_fail_loc=513, val=601*** [ 2945.883550] Lustre: Skipped 5 previous similar messages [ 2950.999292] Lustre: *** cfs_fail_loc=513, val=601*** [ 2951.001416] Lustre: Skipped 16 previous similar messages [ 2958.304215] Lustre: 20635:0:(service.c:1608:ptlrpc_at_send_early_reply()) @@@ Could not add any time (5/5), not sending early reply req@ffff89d3c4568e00 x1862022942533248/t0(0) o4->f31f0279-94cd-4e92-b13d-de1fc572846e@192.168.203.13@tcp:275/0 lens 488/448 e 1 to 0 dl 1775766315 ref 2 fl Interpret:/600/0 rc 0/0 job:'dd.60000' uid:60000 gid:60000 projid:0 [ 2958.312324] LustreError: 6523:0:(service.c:2320:ptlrpc_server_handle_req_in()) drop incoming rpc opc 601, x1862022958227200 [ 2958.356854] LustreError: 6523:0:(service.c:2320:ptlrpc_server_handle_req_in()) Skipped 2 previous similar messages [ 2958.816195] Lustre: 42083:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1775766295/real 1775766295] req@ffff89d3c2e29180 x1862022958220416/t0(0) o601->lustre-MDT0000-lwp-OST0000@0@lo:23/10 lens 336/336 e 0 to 1 dl 1775766311 ref 2 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'ll_ost_io00_005.0' uid:0 gid:0 projid:4294967295 [ 2958.850834] 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 [ 2958.864492] Lustre: lustre-MDT0000: Client lustre-MDT0000-lwp-OST0000_UUID (at 0@lo) reconnecting [ 2958.878236] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 2959.009153] Lustre: *** cfs_fail_loc=513, val=601*** [ 2959.013380] Lustre: Skipped 52 previous similar messages [ 2973.664193] Lustre: 3666:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1775766310/real 1775766310] req@ffff89d3c4453b80 x1862022958227072/t0(0) o601->lustre-MDT0000-lwp-MDT0001@0@lo:23/10 lens 336/336 e 0 to 1 dl 1775766326 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'lquota_wb_lustr.0' uid:0 gid:0 projid:4294967295 [ 2973.704152] 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 [ 2973.722905] Lustre: lustre-MDT0000: Received new LWP connection from 0@lo, keep former export from same NID [ 2973.737177] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 2974.752233] Lustre: 3665:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1775766310/real 1775766310] req@ffff89d3c4452680 x1862022958226944/t0(0) o601->lustre-MDT0000-lwp-MDT0001@0@lo:23/10 lens 336/336 e 0 to 1 dl 1775766326 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'lquota_wb_lustr.0' uid:0 gid:0 projid:4294967295 [ 2974.793252] Lustre: 3665:0:(client.c:2479:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 2975.202142] 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 [ 2975.202671] Lustre: *** cfs_fail_loc=513, val=601*** [ 2975.218561] Lustre: Skipped 68 previous similar messages [ 2975.232474] Lustre: lustre-MDT0000: Client lustre-MDT0000-lwp-OST0000_UUID (at 0@lo) reconnecting [ 2975.249444] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 2976.315380] LustreError: 6524:0:(service.c:2320:ptlrpc_server_handle_req_in()) drop incoming rpc opc 601, x1862022958238208 [ 2976.333216] LustreError: 6524:0:(service.c:2320:ptlrpc_server_handle_req_in()) Skipped 1 previous similar message [ 2982.880833] LustreError: 6523:0:(service.c:2320:ptlrpc_server_handle_req_in()) drop incoming rpc opc 601, x1862022958241024 [ 2982.898091] LustreError: 6523:0:(service.c:2320:ptlrpc_server_handle_req_in()) Skipped 5 previous similar messages [ 2991.587727] Lustre: 8404:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1775766328/real 1775766328] req@ffff89d4ffbdd880 x1862022958238208/t0(0) o601->lustre-MDT0000-lwp-OST0000@0@lo:23/10 lens 336/336 e 0 to 1 dl 1775766344 ref 2 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'ll_ost_io00_000.0' uid:0 gid:0 projid:4294967295 [ 2991.651941] Lustre: 8404:0:(client.c:2479:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 2991.661184] 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 [ 2991.695869] Lustre: lustre-MDT0000: Client lustre-MDT0000-lwp-OST0000_UUID (at 0@lo) reconnecting [ 2991.709274] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 2998.737583] Lustre: 3663:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1775766335/real 1775766335] req@ffff89d4c4156300 x1862022958240768/t0(0) o601->lustre-MDT0000-lwp-OST0001@0@lo:23/10 lens 336/336 e 0 to 1 dl 1775766351 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'lquota_wb_lustr.0' uid:0 gid:0 projid:4294967295 [ 2998.753761] 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 [ 2998.781311] Lustre: 3663:0:(client.c:2479:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 2998.818687] Lustre: lustre-MDT0000: Received new LWP connection from 0@lo, keep former export from same NID [ 2998.819858] Lustre: Skipped 1 previous similar message [ 2998.826030] Lustre: lustre-MDT0000: Client lustre-MDT0000-lwp-OST0001_UUID (at 0@lo) reconnecting [ 2998.828548] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 3024.598377] Lustre: DEBUG MARKER: == sanity-quota test 7a: Quota reintegration (global index) ========================================================== 16:26:16 (1775766376) [ 3049.699539] Lustre: Failing over lustre-OST0000 [ 3049.809783] Lustre: server umount lustre-OST0000 complete [ 3049.962612] 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 [ 3055.074613] LustreError: 8400:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3055.088657] LustreError: 8400:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 5 previous similar messages [ 3058.525066] LustreError: 42351:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.203.13@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3060.203625] LustreError: 42082:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3060.230865] LustreError: 42082:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 1 previous similar message [ 3062.256360] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3062.556797] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [ 3062.603174] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 3063.657403] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 3064.392013] Lustre: lustre-OST0000: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [ 3064.392016] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 3064.392023] Lustre: Skipped 1 previous similar message [ 3069.538255] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3077.892313] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3083.617491] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3089.286589] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3094.765193] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3099.998334] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3105.247160] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3125.745020] Lustre: Failing over lustre-OST0000 [ 3125.835651] Lustre: server umount lustre-OST0000 complete [ 3129.322695] 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 [ 3129.344733] LustreError: 42353:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3129.348091] Lustre: Skipped 2 previous similar messages [ 3129.370601] LustreError: 42353:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 1 previous similar message [ 3134.450536] LustreError: 42082:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3134.480916] LustreError: 42082:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 1 previous similar message [ 3135.699900] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3136.200210] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [ 3136.247510] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 3137.931401] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 3143.442531] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3151.323962] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3207.500394] Lustre: lustre-OST0000: recovery is timed out, evict stale exports [ 3207.522567] Lustre: 87776:0:(genops.c:1620:class_disconnect_stale_exports()) lustre-OST0000: disconnect stale client f31f0279-94cd-4e92-b13d-de1fc572846e@ [ 3207.554254] Lustre: lustre-OST0000: disconnecting 1 stale clients [ 3207.593154] Lustre: lustre-OST0000: Recovery over after 1:10, of 3 clients 2 recovered and 1 was evicted. [ 3207.593877] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 3207.620473] Lustre: Skipped 1 previous similar message [ 3218.624428] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3224.483949] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3230.253366] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3235.824603] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3241.411826] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3265.977387] Lustre: DEBUG MARKER: == sanity-quota test 7b: Quota reintegration (slave index) ========================================================== 16:30:17 (1775766617) [ 3300.905348] Lustre: *** cfs_fail_loc=a02, val=0*** [ 3308.102688] LustreError: 3663:0:(qsd_handler.c:298:qsd_req_completion()) $$$ DQACQ failed with -5, flags:0x8 qsd:lustre-OST0000 qtype:usr lqe: ffff89d3c4afe900 id:60000 enforced:1 granted: 1024 pending:0 waiting:0 req:1 usage: 2048 qunit:0 qtune:0 edquot:0 default:no revoke:0 [ 3308.129850] Lustre: Failing over lustre-OST0000 [ 3308.331777] Lustre: server umount lustre-OST0000 complete [ 3309.422488] LustreError: 8401:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.203.13@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3310.056762] LustreError: lustre-OST0000-osc-MDT0001: operation ost_statfs to node 0@lo failed: rc = -107 [ 3310.057602] 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 [ 3310.069643] LustreError: Skipped 1 previous similar message [ 3310.100884] Lustre: Skipped 1 previous similar message [ 3316.811123] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3317.182703] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [ 3317.217422] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 3319.109350] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 3319.445724] Lustre: lustre-OST0000: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [ 3319.454836] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 3319.470773] Lustre: Skipped 1 previous similar message [ 3323.307281] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3330.623517] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3335.529176] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3341.241445] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3346.994414] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3352.529240] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3357.550717] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3392.238401] Lustre: DEBUG MARKER: == sanity-quota test 7c: Quota reintegration (restart mds during reintegration) ========================================================== 16:32:24 (1775766744) [ 3416.490646] LustreError: 97266:0:(qsd_reint.c:482:qsd_reint_main()) cfs_fail_timeout id a03 sleeping for 10000ms [ 3416.497757] LustreError: 97266:0:(qsd_reint.c:482:qsd_reint_main()) Skipped 5 previous similar messages [ 3419.099076] Lustre: Failing over lustre-MDT0000 [ 3419.621465] 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 [ 3419.628815] Lustre: Skipped 1 previous similar message [ 3419.648271] LustreError: 9480:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3419.664691] LustreError: 9480:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 10 previous similar messages [ 3419.757805] Lustre: server umount lustre-MDT0000 complete [ 3423.505821] LustreError: 97266:0:(qsd_reint.c:482:qsd_reint_main()) cfs_fail_timeout interrupted [ 3431.728838] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3431.840102] LustreError: MGC192.168.203.113@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3432.118787] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3432.188071] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 3432.279566] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 3437.574668] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 3437.595643] Lustre: Skipped 1 previous similar message [ 3437.609516] LustreError: 3662:0:(ldlm_resource.c:1170:ldlm_resource_complain()) lustre-MDT0000-lwp-OST0001: namespace resource [0x200000006:0x2020000:0x0].0x0 (ffff89d4d7a69d00) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 3437.759994] Lustre: lustre-MDT0000: Recovery over after 0:05, of 2 clients 2 recovered and 0 were evicted. [ 3437.851556] Lustre: 97271:0:(qsd_reint.c:245:qsd_reint_index()) lustre-OST0001: index version for fid [0x200000005:0x100b:0x0] is 0, but index isn't empty (1) [ 3437.859613] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:111 to 0x2c0000401:129) [ 3437.861359] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:153 to 0x280000401:193) [ 3437.956159] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3447.032843] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3538.874525] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3545.655347] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3551.786375] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3557.546545] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3563.588567] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3591.896614] Lustre: DEBUG MARKER: == sanity-quota test 7d: Quota reintegration (Transfer index in multiple bulks) ========================================================== 16:35:43 (1775766943) [ 3612.272995] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [ 3617.902661] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [ 3658.978183] Lustre: DEBUG MARKER: == sanity-quota test 7e: Quota reintegration (inode limits) ========================================================== 16:36:50 (1775767010) [ 3685.990485] Lustre: Failing over lustre-MDT0001 [ 3686.345843] Lustre: server umount lustre-MDT0001 complete [ 3687.920060] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 3687.928471] Lustre: lustre-MDT0001-osp-MDT0000: Connection to lustre-MDT0001 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 3687.944505] Lustre: Skipped 2 previous similar messages [ 3687.955825] LustreError: 6526:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3687.980532] LustreError: 6526:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 10 previous similar messages [ 3700.913029] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3701.504224] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 3701.591559] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 3703.385717] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 3705.748987] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3706.872532] Lustre: lustre-MDT0001-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 3706.878209] Lustre: Skipped 3 previous similar messages [ 3706.906579] Lustre: lustre-MDT0001: Recovery over after 0:03, of 2 clients 2 recovered and 0 were evicted. [ 3706.973860] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:33) [ 3714.420637] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 3719.456617] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0001.recovery_status 1475 [ 3725.946947] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 3732.726579] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0001.recovery_status 1475 [ 3738.963316] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 3744.819455] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0001.recovery_status 1475 [ 3820.956966] Lustre: Failing over lustre-MDT0001 [ 3821.425048] LustreError: 9480:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0001: not available for connect from 192.168.203.13@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3821.440895] Lustre: server umount lustre-MDT0001 complete [ 3821.442157] LustreError: 9480:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 12 previous similar messages [ 3824.616073] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 3829.208564] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3829.952460] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 3830.034803] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 3831.491686] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 3833.490713] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3835.388191] Lustre: lustre-MDT0001: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 3835.437092] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:65) [ 3839.849704] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 3844.685283] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0001.recovery_status 1475 [ 3850.348770] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 3855.089657] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0001.recovery_status 1475 [ 3860.448715] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 3866.605496] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0001.recovery_status 1475 [ 3944.973581] Lustre: DEBUG MARKER: == sanity-quota test 7f: Quota reintegration automatically ========================================================== 16:41:36 (1775767296) [ 3957.487692] Lustre: *** cfs_fail_loc=a11, val=0*** [ 3957.491173] Lustre: Skipped 3 previous similar messages [ 3964.119538] Lustre: *** cfs_fail_loc=a11, val=0*** [ 4019.175976] Lustre: *** cfs_fail_loc=a11, val=0*** [ 4019.183196] Lustre: Skipped 2 previous similar messages [ 4019.224384] Lustre: 113611:0:(qsd_reint.c:245:qsd_reint_index()) lustre-MDT0001: index version for fid [0x200000005:0x1004:0x0] is 0, but index isn't empty (1) [ 4048.016642] Lustre: DEBUG MARKER: == sanity-quota test 8: Run dbench with quota enabled ==== 16:43:19 (1775767399) [ 4238.860456] Lustre: DEBUG MARKER: == sanity-quota test 9: Block limit larger than 4GB (b10707) ========================================================== 16:46:30 (1775767590) [ 4240.268497] Lustre: DEBUG MARKER: OST0_SIZE: 3605132 required: 4900000 [ 4248.526883] Lustre: DEBUG MARKER: == sanity-quota test 10: Test quota for root user ======== 16:46:40 (1775767600) [ 4293.300805] Lustre: DEBUG MARKER: == sanity-quota test 11: Chown/chgrp ignores quota ======= 16:47:23 (1775767643) [ 4335.746320] Lustre: DEBUG MARKER: == sanity-quota test 12a: Block quota rebalancing ======== 16:48:07 (1775767687) [ 4401.466823] Lustre: DEBUG MARKER: == sanity-quota test 12b: Inode quota rebalancing ======== 16:49:12 (1775767752) [ 4544.301516] Lustre: DEBUG MARKER: == sanity-quota test 13: Cancel per-ID lock in the LRU list ========================================================== 16:51:35 (1775767895) [ 4602.261935] Lustre: DEBUG MARKER: == sanity-quota test 14: check panic in qmt_site_recalc_cb ========================================================== 16:52:33 (1775767953) [ 4626.152618] Lustre: Failing over lustre-OST0000 [ 4626.319835] Lustre: server umount lustre-OST0000 complete [ 4626.916284] 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 [ 4626.927986] Lustre: Skipped 5 previous similar messages [ 4626.932757] LustreError: 115272:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4626.948156] LustreError: 115272:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 4 previous similar messages [ 4639.036389] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4639.411056] Lustre: lustre-OST0000: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [ 4639.451524] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 4640.600236] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 4640.942931] Lustre: lustre-OST0000: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [ 4640.952284] Lustre: lustre-OST0000-osc-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4640.978286] Lustre: Skipped 5 previous similar messages [ 4646.666619] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4681.707711] Lustre: DEBUG MARKER: == sanity-quota test 15: Set over 4T block quota ========= 16:53:53 (1775768033) [ 4707.474245] Lustre: DEBUG MARKER: == sanity-quota test 16a: lfs quota should skip the inactive MDT/OST ========================================================== 16:54:18 (1775768058) [ 4725.649072] Lustre: lustre-MDT0001: Client f31f0279-94cd-4e92-b13d-de1fc572846e (at 192.168.203.13@tcp) reconnecting [ 4751.623776] Lustre: DEBUG MARKER: == sanity-quota test 16b: lfs quota should skip the nonexistent MDT/OST ========================================================== 16:55:02 (1775768102) [ 4753.656828] Lustre: DEBUG MARKER: SKIP: sanity-quota test_16b needs >= 3 MDTs [ 4756.342755] Lustre: DEBUG MARKER: == sanity-quota test 17: DQACQ return recoverable error == 16:55:07 (1775768107) [ 4780.182747] Lustre: *** cfs_fail_loc=a04, val=37*** [ 4780.196936] LustreError: 115255:0:(qsd_handler.c:298:qsd_req_completion()) $$$ DQACQ failed with -37, flags:0x1 qsd:lustre-OST0001 qtype:usr lqe: ffff89d3c2d53c80 id:60000 enforced:1 granted: 0 pending:0 waiting:1056 req:1 usage: 0 qunit:0 qtune:0 edquot:0 default:no revoke:0 [ 4781.307440] Lustre: *** cfs_fail_loc=a04, val=37*** [ 4781.323323] LustreError: 20635:0:(qsd_handler.c:298:qsd_req_completion()) $$$ DQACQ failed with -37, flags:0x1 qsd:lustre-OST0001 qtype:usr lqe: ffff89d3c2d53c80 id:60000 enforced:1 granted: 0 pending:0 waiting:1056 req:1 usage: 0 qunit:0 qtune:0 edquot:0 default:no revoke:0 [ 4835.450131] Lustre: *** cfs_fail_loc=a04, val=11*** [ 4838.628796] Lustre: *** cfs_fail_loc=a04, val=11*** [ 4838.634339] Lustre: Skipped 1 previous similar message [ 4895.653240] Lustre: *** cfs_fail_loc=a04, val=110*** [ 4954.869299] Lustre: *** cfs_fail_loc=a04, val=107*** [ 4954.872675] Lustre: Skipped 2 previous similar messages [ 5039.883342] Lustre: DEBUG MARKER: == sanity-quota test 18: MDS failover while writing, no watchdog triggered (b14840) ========================================================== 16:59:51 (1775768391) [ 5050.935142] Lustre: DEBUG MARKER: User quota (limit: 200) [ 5057.358237] Lustre: DEBUG MARKER: Write 100M (buffered) ... [ 5066.131672] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5067.950306] Lustre: DEBUG MARKER: Fail mds for 40 seconds [ 5070.008223] Lustre: Failing over lustre-MDT0000 [ 5070.246634] LustreError: lustre-MDT0000-lwp-OST0000: operation quota_acquire to node 0@lo failed: rc = -107 [ 5070.253932] 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 [ 5070.267196] Lustre: Skipped 1 previous similar message [ 5070.282576] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5070.362970] Lustre: server umount lustre-MDT0000 complete [ 5073.810396] LustreError: 6521:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.203.13@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 5073.834897] LustreError: 6521:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 6 previous similar messages [ 5073.888755] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 5091.302648] Lustre: 3664:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1775768427/real 1775768427] req@ffff89d3d508c000 x1862022960797952/t0(0) o400->MGC192.168.203.113@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1775768443 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5091.328763] Lustre: 3664:0:(client.c:2479:ptlrpc_expire_one_request()) Skipped 4 previous similar messages [ 5091.333772] LustreError: MGC192.168.203.113@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5093.217984] LDISKFS-fs (dm-0): 7 truncates cleaned up [ 5093.221218] LDISKFS-fs (dm-0): recovery complete [ 5093.230827] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5101.536607] LustreError: 3662:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff89d3d523fb80 x1862022960808448/t0(0) o250->MGC192.168.203.113@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 0 ref 1 fl Rpc:NQU/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5101.964530] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 5102.032671] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 5103.867027] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 5106.811862] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5107.186322] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 5107.193953] Lustre: Skipped 1 previous similar message [ 5107.233080] Lustre: lustre-MDT0000: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 5107.284867] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:702 to 0x280000401:737) [ 5107.287342] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:634 to 0x2c0000401:673) [ 5114.473306] Lustre: DEBUG MARKER: oleg313-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 5116.210448] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5121.939233] Lustre: DEBUG MARKER: (dd_pid=126293, time=0, timeout=600) [ 5147.957565] Lustre: DEBUG MARKER: User quota (limit: 200) [ 5152.611337] Lustre: DEBUG MARKER: Write 100M (directio) ... [ 5157.994819] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5159.118462] Lustre: DEBUG MARKER: Fail mds for 40 seconds [ 5160.552930] Lustre: Failing over lustre-MDT0000 [ 5160.827107] Lustre: server umount lustre-MDT0000 complete [ 5163.490648] 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 [ 5163.492717] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 5163.493033] LustreError: 6520:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 5163.493041] LustreError: 6520:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 35 previous similar messages [ 5163.499623] Lustre: Skipped 4 previous similar messages [ 5178.850230] Lustre: 3665:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1775768515/real 1775768515] req@ffff89d3d56b1180 x1862022960857728/t0(0) o400->MGC192.168.203.113@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1775768531 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5178.866797] LustreError: MGC192.168.203.113@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5183.557964] LDISKFS-fs (dm-0): 3 truncates cleaned up [ 5183.561520] LDISKFS-fs (dm-0): recovery complete [ 5183.571872] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5189.095633] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x8e13e711d411eed5 [ 5189.101987] Lustre: MGC192.168.203.113@tcp: Connection restored to 0@lo (at 0@lo) [ 5189.107247] Lustre: Skipped 3 previous similar messages [ 5189.275321] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 5189.310512] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 5190.485512] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 5191.612588] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5194.731864] LustreError: 3662:0:(ldlm_resource.c:1170:ldlm_resource_complain()) lustre-MDT0000-lwp-MDT0001: namespace resource [0x200000006:0x10000:0x0].0x0 (ffff89d4c5142e00) refcount nonzero (1) after lock cleanup; forcing cleanup. [ 5194.741040] LustreError: 3662:0:(ldlm_resource.c:1170:ldlm_resource_complain()) Skipped 5 previous similar messages [ 5194.769574] Lustre: lustre-MDT0000: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 5194.804553] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:739 to 0x280000401:769) [ 5194.804952] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:634 to 0x2c0000401:705) [ 5197.353282] Lustre: DEBUG MARKER: oleg313-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 5198.437826] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5203.266144] Lustre: DEBUG MARKER: (dd_pid=128782, time=0, timeout=600) [ 5256.394327] Lustre: DEBUG MARKER: == sanity-quota test 19: Updating admin limits doesn't zero operational limits(b14790) ========================================================== 17:03:27 (1775768607) [ 5312.206831] Lustre: DEBUG MARKER: == sanity-quota test 20: Test if setquota specifiers work properly (b15754) ========================================================== 17:04:23 (1775768663) [ 5338.600819] Lustre: DEBUG MARKER: == sanity-quota test 21: Setquota while writing [ 5350.856483] Lustre: DEBUG MARKER: Set limit(block:10G; file:1000000) for user: quota_usr [ 5352.565740] Lustre: DEBUG MARKER: Set limit(block:10G; file:1000000) for group: quota_usr [ 5354.072561] Lustre: DEBUG MARKER: Set limit(block:10G; file:) for project: 1000 [ 5355.910109] Lustre: DEBUG MARKER: Set quota for 1 times [ 5359.035308] Lustre: DEBUG MARKER: Set quota for 2 times [ 5362.348639] Lustre: DEBUG MARKER: Set quota for 3 times [ 5365.791619] Lustre: DEBUG MARKER: Set quota for 4 times [ 5369.706353] Lustre: DEBUG MARKER: Set quota for 5 times [ 5373.522782] Lustre: DEBUG MARKER: Set quota for 6 times [ 5377.140439] Lustre: DEBUG MARKER: Set quota for 7 times [ 5380.217579] Lustre: DEBUG MARKER: Set quota for 8 times [ 5383.388672] Lustre: DEBUG MARKER: Set quota for 9 times [ 5432.864299] Lustre: DEBUG MARKER: == sanity-quota test 22: enable/disable quota by 'lctl conf_param/set_param -P' ========================================================== 17:06:24 (1775768784) [ 5450.723331] 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 [ 5450.726676] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 5450.745884] Lustre: Skipped 2 previous similar messages [ 5450.746581] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5455.507902] Lustre: server umount lustre-MDT0000 complete [ 5455.848278] LustreError: 6521:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 5455.872997] LustreError: 6521:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 31 previous similar messages [ 5459.638351] LustreError: 115285:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1775768812 with bad export cookie 10237780441701674709 [ 5459.645045] LustreError: MGC192.168.203.113@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5459.662555] LustreError: 115285:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 5460.253322] Lustre: server umount lustre-MDT0001 complete [ 5475.248073] Lustre: server umount lustre-OST0000 complete [ 5477.154202] Lustre: 3666:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1775768813/real 1775768813] req@ffff89d3c2e6d500 x1862022961052544/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1775768829 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5479.434596] Lustre: server umount lustre-OST0001 complete [ 5498.305406] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing load_modules_local [ 5510.068584] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5510.728588] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 5515.854866] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5525.481117] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5526.110350] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 5532.157931] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5537.043812] Lustre: 153434:0:(mgs_llog.c:1348:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 5547.648537] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5548.436738] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 5555.091927] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5555.628687] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:771 to 0x280000401:801) [ 5566.003400] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5566.227293] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 5568.155712] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:97) [ 5568.160574] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:708 to 0x2c0000401:737) [ 5572.707345] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5582.197953] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5586.866748] Lustre: 155283:0:(mgs_llog.c:1348:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 5612.515135] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5612.526336] Lustre: Skipped 6 previous similar messages [ 5617.644957] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5617.653472] Lustre: Skipped 3 previous similar messages [ 5618.155634] Lustre: server umount lustre-MDT0000 complete [ 5622.205106] LustreError: 155285:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1775768974 with bad export cookie 10237780441701682031 [ 5622.206159] LustreError: MGC192.168.203.113@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5622.225385] LustreError: 155285:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 5622.523890] Lustre: server umount lustre-MDT0001 complete [ 5636.984376] Lustre: server umount lustre-OST0000 complete [ 5639.136510] Lustre: 3663:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1775768975/real 1775768975] req@ffff89d4f476c380 x1862022961140864/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1775768991 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5640.866350] Lustre: server umount lustre-OST0001 complete [ 5658.303436] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing load_modules_local [ 5669.284504] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5669.771187] LustreError: 157865:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 5669.800398] LustreError: 157865:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 10 previous similar messages [ 5669.959417] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 5674.644050] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5684.765631] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5689.905340] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5692.753615] Lustre: 158971:0:(mgs_llog.c:1348:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 5700.266544] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5707.440624] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5715.950217] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:771 to 0x280000401:833) [ 5716.432627] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5716.733432] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 5716.744441] Lustre: Skipped 2 previous similar messages [ 5718.150614] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:129) [ 5718.165318] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:708 to 0x2c0000401:769) [ 5723.448069] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5731.094042] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5735.504687] Lustre: 160816:0:(mgs_llog.c:1348:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 5753.261512] Lustre: DEBUG MARKER: == sanity-quota test 23: Quota should be honored with directIO (b16125) ========================================================== 17:11:44 (1775769104) [ 5754.733481] Lustre: DEBUG MARKER: OST0_SIZE: 3605396 required: 6144 [ 5756.122373] Lustre: DEBUG MARKER: run for 4MB test file [ 5766.266422] Lustre: DEBUG MARKER: User quota (limit: 4 MB) [ 5772.056089] Lustre: DEBUG MARKER: Step1: trigger EDQUOT with O_DIRECT [ 5773.505246] Lustre: DEBUG MARKER: Write half of file [ 5775.367455] Lustre: DEBUG MARKER: Write out of block quota ... [ 5776.875653] Lustre: DEBUG MARKER: Step1: done [ 5778.392953] Lustre: DEBUG MARKER: Step2: rewrite should succeed [ 5779.726622] Lustre: DEBUG MARKER: Step2: done [ 5802.221508] Lustre: DEBUG MARKER: OST0_SIZE: 3605396 required: 61440 [ 5803.755635] Lustre: DEBUG MARKER: run for 40MB test file [ 5814.355494] Lustre: DEBUG MARKER: User quota (limit: 40 MB) [ 5820.507861] Lustre: DEBUG MARKER: Step1: trigger EDQUOT with O_DIRECT [ 5822.612905] Lustre: DEBUG MARKER: Write half of file [ 5825.812129] Lustre: DEBUG MARKER: Write out of block quota ... [ 5828.798408] Lustre: DEBUG MARKER: Step1: done [ 5830.371268] Lustre: DEBUG MARKER: Step2: rewrite should succeed [ 5832.265200] Lustre: DEBUG MARKER: Step2: done [ 5885.302415] Lustre: DEBUG MARKER: == sanity-quota test 24: lfs draws an asterix when limit is reached (b16646) ========================================================== 17:13:56 (1775769236) [ 5923.306248] Lustre: DEBUG MARKER: == sanity-quota test 25: check indexes versions ========== 17:14:34 (1775769274) [ 5962.322727] Lustre: DEBUG MARKER: Write... [ 5964.798375] Lustre: DEBUG MARKER: Write out of block quota ... [ 6013.231855] Lustre: DEBUG MARKER: == sanity-quota test 27a: lfs quota/setquota should handle wrong arguments (b19612) ========================================================== 17:16:04 (1775769364) [ 6021.614082] Lustre: DEBUG MARKER: == sanity-quota test 27b: lfs quota/setquota should handle user/group/project ID (b20200) ========================================================== 17:16:12 (1775769372) [ 6031.174418] Lustre: DEBUG MARKER: == sanity-quota test 27c: lfs quota should support human-readable output ========================================================== 17:16:22 (1775769382) [ 6040.431401] Lustre: DEBUG MARKER: == sanity-quota test 27d: lfs setquota should support fraction block limit ========================================================== 17:16:31 (1775769391) [ 6050.742525] Lustre: DEBUG MARKER: == sanity-quota test 30: Hard limit updates should not reset grace times ========================================================== 17:16:41 (1775769401) [ 6105.482744] Lustre: DEBUG MARKER: == sanity-quota test 33: Basic usage tracking for user [ 6229.186343] Lustre: DEBUG MARKER: == sanity-quota test 34: Usage transfer for user [ 6366.615300] Lustre: DEBUG MARKER: == sanity-quota test 35: Usage is still accessible across reboot ========================================================== 17:21:58 (1775769718) [ 6417.335540] Lustre: DEBUG MARKER: Restart... [ 6422.496914] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 6422.508266] 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 [ 6422.535562] Lustre: Skipped 9 previous similar messages [ 6422.546306] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 6423.522439] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 6423.532208] Lustre: Skipped 3 previous similar messages [ 6428.166757] Lustre: server umount lustre-MDT0000 complete [ 6428.661892] LustreError: 157865:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 6428.671397] LustreError: 157865:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 9 previous similar messages [ 6432.043276] LustreError: 157847:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1775769784 with bad export cookie 10237780441701684334 [ 6432.055596] LustreError: MGC192.168.203.113@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 6432.061574] LustreError: 157847:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 6432.356871] Lustre: server umount lustre-MDT0001 complete [ 6446.182923] Lustre: server umount lustre-OST0000 complete [ 6450.148792] Lustre: 3663:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1775769786/real 1775769786] req@ffff89d4fbfab800 x1862022961627264/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1775769802 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6452.103600] Lustre: server umount lustre-OST0001 complete [ 6476.511559] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing load_modules_local [ 6491.133752] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 6491.736611] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 6497.869940] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6508.144368] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 6508.710871] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 6514.204256] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6517.687047] Lustre: 184778:0:(mgs_llog.c:1348:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 6525.529831] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 6525.895895] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 6532.037401] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6536.192748] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:844 to 0x280000401:865) [ 6540.929555] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 6543.204184] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:161) [ 6543.221334] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:778 to 0x2c0000401:801) [ 6548.420027] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6556.085297] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 6560.134756] Lustre: 186624:0:(mgs_llog.c:1348:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 6622.934105] Lustre: DEBUG MARKER: == sanity-quota test 37: Quota accounted properly for file created by 'lfs setstripe' ========================================================== 17:26:14 (1775769974) [ 6669.176789] Lustre: DEBUG MARKER: == sanity-quota test 38: Quota accounting iterator doesn't skip id entries ========================================================== 17:27:00 (1775770020) [ 8182.707616] Lustre: DEBUG MARKER: == sanity-quota test 39: Project ID interface works correctly ========================================================== 17:52:14 (1775771534) [ 8191.510404] Lustre: server umount lustre-MDT0000 complete [ 8192.993166] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 8193.007513] 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 [ 8193.025932] Lustre: Skipped 4 previous similar messages [ 8193.046297] LustreError: 185143:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 8193.086511] LustreError: 185143:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 7 previous similar messages [ 8195.245733] LustreError: 186627:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1775771547 with bad export cookie 10237780441701693420 [ 8195.252720] LustreError: MGC192.168.203.113@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 8195.255550] LustreError: 186627:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 8195.599609] Lustre: server umount lustre-MDT0001 complete [ 8210.475925] Lustre: server umount lustre-OST0000 complete [ 8224.699411] Lustre: server umount lustre-OST0001 complete [ 8237.409720] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing load_modules_local [ 8246.004295] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 8246.462827] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 8246.467283] Lustre: Skipped 1 previous similar message [ 8250.107662] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 8257.262659] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 8257.536248] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 8261.421633] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 8264.059996] Lustre: 195115:0:(mgs_llog.c:1348:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 8270.034932] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 8270.371360] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 8271.394767] LustreError: 195469:0:(ldlm_lib.c:1179: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. [ 8271.402398] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:5867 to 0x280000401:5889) [ 8271.414304] LustreError: 195469:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 7 previous similar messages [ 8275.146052] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 8282.142969] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 8284.290187] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:193) [ 8284.293602] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:5803 to 0x2c0000401:5825) [ 8288.288240] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 8294.964821] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 8298.212555] Lustre: 196960:0:(mgs_llog.c:1348:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 8326.554904] Lustre: DEBUG MARKER: == sanity-quota test 40a: Hard link across different project ID ========================================================== 17:54:38 (1775771678) [ 8356.678359] Lustre: DEBUG MARKER: == sanity-quota test 40b: Mv across different project ID ========================================================== 17:55:07 (1775771707) [ 8385.083631] Lustre: DEBUG MARKER: == sanity-quota test 40c: Remote child Dir inherit project quota properly ========================================================== 17:55:36 (1775771736) [ 8424.981635] Lustre: DEBUG MARKER: == sanity-quota test 40d: Stripe Directory inherit project quota properly ========================================================== 17:56:16 (1775771776) [ 8462.114482] Lustre: DEBUG MARKER: == sanity-quota test 41: df should return projid-specific values ========================================================== 17:56:53 (1775771813) [ 8540.721895] Lustre: DEBUG MARKER: == sanity-quota test 42: lfs quota should include default quota info ========================================================== 17:58:12 (1775771892) [ 8572.522102] Lustre: DEBUG MARKER: == sanity-quota test 48: lfs quota --delete should delete quota project ID ========================================================== 17:58:43 (1775771923) [ 8586.144663] LustreError: 195476:0:(qsd_handler.c:298:qsd_req_completion()) $$$ DQACQ failed with -3, flags:0x1 qsd:lustre-OST0000 qtype:usr lqe: ffff89d3d5628c00 id:60000 enforced:1 granted: 0 pending:0 waiting:1032 req:1 usage: 0 qunit:0 qtune:0 edquot:0 default:no revoke:0 [ 8586.181026] LustreError: 195476:0:(qsd_handler.c:772:qsd_op_begin0()) $$$ ID isn't enforced on master, it probably due to a legeal race, if this message is showing up constantly, there could be some inconsistence between master & slave, and quota reintegration needs be re-triggered. qsd:lustre-OST0000 qtype:usr lqe: ffff89d3d5628c00 id:60000 enforced:1 granted: 0 pending:0 waiting:0 req:0 usage: 0 qunit:0 qtune:0 edquot:0 default:no revoke:0 [ 8641.334490] Lustre: DEBUG MARKER: == sanity-quota test 49a: lfs quota -a prints the quota usage for all quota IDs ========================================================== 17:59:52 (1775771992) [ 8647.830075] Lustre: *** cfs_fail_loc=a09, val=0*** [ 8647.833608] Lustre: Skipped 2 previous similar messages [ 8649.837185] Lustre: *** cfs_fail_loc=a09, val=0*** [ 8649.838920] Lustre: Skipped 71 previous similar messages [ 8653.855136] Lustre: *** cfs_fail_loc=a09, val=0*** [ 8653.859047] Lustre: Skipped 169 previous similar messages [ 8661.861404] Lustre: *** cfs_fail_loc=a09, val=0*** [ 8661.863474] Lustre: Skipped 345 previous similar messages [ 8677.888871] Lustre: *** cfs_fail_loc=a09, val=0*** [ 8677.890906] Lustre: Skipped 749 previous similar messages [ 8709.960560] Lustre: *** cfs_fail_loc=a09, val=0*** [ 8709.970245] Lustre: Skipped 1413 previous similar messages [ 8773.978376] Lustre: *** cfs_fail_loc=a09, val=0*** [ 8773.982986] Lustre: Skipped 2971 previous similar messages [ 9085.857889] Lustre: *** cfs_fail_loc=a08, val=0*** [ 9085.859736] Lustre: Skipped 2275 previous similar messages [ 9085.863820] Lustre: *** cfs_fail_loc=a08, val=0*** [ 9085.900059] Lustre: Skipped 4 previous similar messages [ 9184.226370] 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 [ 9184.227648] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 9184.264110] Lustre: Skipped 5 previous similar messages [ 9184.267734] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 9184.292708] Lustre: Skipped 3 previous similar messages [ 9189.350577] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 9190.480499] Lustre: server umount lustre-MDT0000 complete [ 9194.288186] LustreError: 194733:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1775772546 with bad export cookie 10237780441703469145 [ 9194.305413] LustreError: 194733:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 9194.306132] LustreError: MGC192.168.203.113@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 9194.471917] LustreError: 195266:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 9194.472842] 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 [ 9194.481753] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 9194.481766] Lustre: Skipped 3 previous similar messages [ 9194.513626] LustreError: 195266:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 4 previous similar messages [ 9194.554339] Lustre: Skipped 2 previous similar messages [ 9199.586342] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 9199.595902] Lustre: Skipped 1 previous similar message [ 9200.873290] Lustre: server umount lustre-MDT0001 complete [ 9205.514737] Lustre: server umount lustre-OST0000 complete [ 9209.422025] Lustre: server umount lustre-OST0001 complete [ 9216.051595] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_hostid [ 9224.173654] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing load_modules_local [ 9269.438422] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing load_modules_local [ 9279.193151] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 9279.403818] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 9279.424252] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 9279.487910] Lustre: lustre-MDT0000: new disk, initializing [ 9279.560298] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 9279.566452] Lustre: Skipped 1 previous similar message [ 9279.579484] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 9284.115563] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 9293.751170] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 9293.831476] Lustre: 213566:0:(mgs_llog.c:1348:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 9293.871417] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 9293.875762] Lustre: Skipped 1 previous similar message [ 9293.935676] Lustre: lustre-MDT0001: new disk, initializing [ 9293.994535] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 9294.017040] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 9294.026885] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 9298.072755] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 9302.728779] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 9308.563935] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 9308.838067] Lustre: lustre-OST0000: new disk, initializing [ 9308.842361] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 9308.927573] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 9310.482529] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 9310.493465] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 9310.582970] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 9313.933183] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 9323.040967] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 9323.141680] Lustre: lustre-OST0001: new disk, initializing [ 9323.146202] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 9323.204372] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 9325.005172] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 9325.017887] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 9325.043489] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 9328.607343] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 9338.257730] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 9342.207421] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 9374.956738] Lustre: DEBUG MARKER: == sanity-quota test 49b: lfs quota -a --blocks has a delimiter ========================================================== 18:12:05 (1775772725) [ 9382.245790] Lustre: DEBUG MARKER: == sanity-quota test 50: Test if lfs find --projid works ========================================================== 18:12:14 (1775772734) [ 9411.216995] Lustre: DEBUG MARKER: == sanity-quota test 51: Test project accounting with mv/cp ========================================================== 18:12:42 (1775772762) [ 9459.409538] Lustre: DEBUG MARKER: == sanity-quota test 52: Rename normal file across project ID ========================================================== 18:13:31 (1775772811) [ 9481.466973] Lustre: DEBUG MARKER: rename directory return 255 [ 9518.342330] Lustre: DEBUG MARKER: == sanity-quota test 53: Project inherit attribute could be cleared ========================================================== 18:14:29 (1775772869) [ 9539.664409] Lustre: DEBUG MARKER: == sanity-quota test 54: basic lfs project interface test ========================================================== 18:14:51 (1775772891) [ 9574.554986] Lustre: DEBUG MARKER: == sanity-quota test 55: Chgrp should be affected by group quota ========================================================== 18:15:26 (1775772926) [ 9699.626634] Lustre: DEBUG MARKER: == sanity-quota test 56: lfs quota -t should work well === 18:17:31 (1775773051) [ 9726.475781] Lustre: DEBUG MARKER: == sanity-quota test 57: lfs project could tolerate errors ========================================================== 18:17:58 (1775773078) [ 9759.503934] Lustre: DEBUG MARKER: == sanity-quota test 58: project ID should be kept for new mirrors created by FID ========================================================== 18:18:31 (1775773111) [ 9902.059002] Lustre: DEBUG MARKER: == sanity-quota test 59: lfs project dosen't crash kernel with project disabled ========================================================== 18:20:53 (1775773253) [ 9908.707562] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 9908.708712] 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 [ 9908.721404] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 9908.721411] Lustre: Skipped 1 previous similar message [ 9908.761714] Lustre: Skipped 3 previous similar messages [ 9913.827483] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 9913.835088] Lustre: Skipped 6 previous similar messages [ 9914.151199] Lustre: server umount lustre-MDT0000 complete [ 9918.947125] LustreError: 213572:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 9918.981975] LustreError: 213572:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 5 previous similar messages [ 9919.209680] LustreError: 213558:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1775773271 with bad export cookie 10237780441703841342 [ 9919.223448] LustreError: MGC192.168.203.113@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 9919.251264] LustreError: 213558:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 9919.975815] Lustre: server umount lustre-MDT0001 complete [ 9935.651931] Lustre: server umount lustre-OST0000 complete [ 9946.084921] LustreError: 3663:0:(client.c:1380:ptlrpc_import_delay_req()) @@@ IMP_CLOSED req@ffff89d3d8da9500 x1862022972129920/t0(0) o601->lustre-MDT0000-lwp-OST0001@0@lo:23/10 lens 336/336 e 0 to 0 dl 0 ref 1 fl Rpc:NQU/200/ffffffff rc 0/-1 job:'lquota_wb_lustr.0' uid:0 gid:0 projid:4294967295 [ 9946.112772] LustreError: 3663:0:(qsd_handler.c:298:qsd_req_completion()) $$$ DQACQ failed with -5, flags:0x8 qsd:lustre-OST0001 qtype:usr lqe: ffff89d3d14ecd80 id:0 enforced:0 granted: 0 pending:0 waiting:0 req:1 usage: 1516 qunit:0 qtune:0 edquot:0 default:no revoke:0 [ 9946.131564] LustreError: 3663:0:(qsd_handler.c:298:qsd_req_completion()) Skipped 3 previous similar messages [ 9950.694335] Lustre: server umount lustre-OST0001 complete [ 9970.425573] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing load_modules_local [ 9981.057085] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 9981.702420] LustreError: 233275:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 9981.823987] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 9981.846796] 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 [ 9985.909736] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 9987.041709] LustreError: 233276:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 9993.921793] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 9994.166129] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 9994.186834] 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 [ 9998.326214] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [10001.665192] Lustre: 234387:0:(mgs_llog.c:1348:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [10009.820740] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [10010.187846] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [10010.201887] 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 [10016.494747] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [10019.459264] LustreError: 234742:0:(ldlm_lib.c:1179: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. [10019.490332] LustreError: 234742:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 1 previous similar message [10025.178795] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [10025.428867] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [10025.438180] 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 [10027.596954] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:20 to 0x2c0000401:65) [10027.602621] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:20 to 0x280000401:65) [10032.927634] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [10041.956391] Lustre: DEBUG MARKER: Using TIMEOUT=20 [10046.183104] Lustre: 236236:0:(mgs_llog.c:1348:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [10058.349136] LustreError: 233270:0:(osd_handler.c:3428:osd_quota_transfer()) lustre-MDT0000: quota transfer failed. Is project enforcement enabled on the ldiskfs filesystem? rc = -95 [10063.329603] 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 [10063.344804] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [10063.349801] Lustre: Skipped 2 previous similar messages [10068.452829] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [10068.472037] Lustre: Skipped 4 previous similar messages [10069.419740] Lustre: server umount lustre-MDT0000 complete [10073.571863] LustreError: 235242:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [10073.603251] LustreError: 235242:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 4 previous similar messages [10074.071329] LustreError: 233257:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1775773426 with bad export cookie 10237780441703890237 [10074.072827] LustreError: MGC192.168.203.113@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [10074.090026] LustreError: 233257:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [10074.817838] Lustre: server umount lustre-MDT0001 complete [10090.410162] Lustre: server umount lustre-OST0000 complete [10105.080599] Lustre: server umount lustre-OST0001 complete [10127.598278] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing load_modules_local [10139.181995] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [10139.723562] LustreError: 238609:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [10139.826990] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [10145.317689] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [10154.979155] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [10159.730459] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [10162.690246] Lustre: 239724:0:(mgs_llog.c:1348:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [10170.146650] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [10176.377860] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [10184.607363] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [10184.774068] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [10184.780941] Lustre: Skipped 2 previous similar messages [10185.807367] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:20 to 0x2c0000401:97) [10185.821537] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:67 to 0x280000401:97) [10190.752474] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [10198.669602] Lustre: DEBUG MARKER: Using TIMEOUT=20 [10203.254401] Lustre: 241576:0:(mgs_llog.c:1348:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [10237.037599] Lustre: DEBUG MARKER: == sanity-quota test 60: Test quota for root with setgid ========================================================== 18:26:28 (1775773588) [10287.906503] Lustre: DEBUG MARKER: SKIP: sanity-quota test_61 skipping SLOW test 61 [10289.405291] Lustre: DEBUG MARKER: == sanity-quota test 62: Project inherit should be only changed by root ========================================================== 18:27:21 (1775773641) [10309.827662] Lustre: DEBUG MARKER: SKIP: sanity-quota test_63 skipping excluded test 63 [10311.401328] Lustre: DEBUG MARKER: == sanity-quota test 64: lfs project on non-dir/files should succeed ========================================================== 18:27:42 (1775773662) [10344.735846] Lustre: DEBUG MARKER: SKIP: sanity-quota test_65 skipping excluded test 65 [10346.476326] Lustre: DEBUG MARKER: == sanity-quota test 66: nonroot user can not change project state in default ========================================================== 18:28:17 (1775773697) [10374.445567] Lustre: DEBUG MARKER: == sanity-quota test 67: quota pools recalculation ======= 18:28:45 (1775773725) [10384.452265] Lustre: DEBUG MARKER: User quota (block hardlimit:20 MB) [10389.564400] Lustre: 248135:0:(qsd_reint.c:245:qsd_reint_index()) lustre-OST0000: index version for fid [0x200000005:0x1007:0x0] is 0, but index isn't empty (1) [10389.582660] Lustre: 248135:0:(qsd_reint.c:245:qsd_reint_index()) Skipped 1 previous similar message [10393.459168] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing _wait_recovery_complete *.lustre-OST0000.recovery_status 1475 [10397.876810] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing _wait_recovery_complete *.lustre-OST0001.recovery_status 1475 [10400.961578] Lustre: DEBUG MARKER: Write... [10418.898555] LustreError: 249445:0:(mgs_handler.c:1102:mgs_iocontrol_pool()) OBD_IOC_POOL err -17, cmd CE021 for pool lustre.qpool1 [10423.968558] Lustre: DEBUG MARKER: Write... [10435.483617] Lustre: DEBUG MARKER: Write... [10505.232911] Lustre: DEBUG MARKER: == sanity-quota test 68: slave number in quota pool changed after each add/remove OST ========================================================== 18:30:56 (1775773856) [10532.909740] LustreError: 253412:0:(mgs_handler.c:1102:mgs_iocontrol_pool()) OBD_IOC_POOL err -17, cmd CE021 for pool lustre.qpool1 [10578.177313] Lustre: DEBUG MARKER: == sanity-quota test 69: EDQUOT at one of pools shouldn't affect DOM ========================================================== 18:32:09 (1775773929) [10600.900415] Lustre: DEBUG MARKER: User quota (block hardlimit:200 MB) [10602.493055] Lustre: DEBUG MARKER: User quota (block hardlimit:10 MB) [10699.732550] Lustre: DEBUG MARKER: == sanity-quota test 70a: check lfs setquota/quota with a pool option ========================================================== 18:34:11 (1775774051) [10738.943944] Lustre: DEBUG MARKER: == sanity-quota test 70b: lfs setquota pool works properly ========================================================== 18:34:50 (1775774090) [10773.642932] Lustre: DEBUG MARKER: == sanity-quota test 71a: Check PFL with quota pools ===== 18:35:25 (1775774125) [10784.492986] Lustre: DEBUG MARKER: User quota (block hardlimit:100 MB) [10808.467538] Lustre: DEBUG MARKER: Write... [10810.346784] Lustre: DEBUG MARKER: Write out of block quota ... [10892.479417] Lustre: DEBUG MARKER: == sanity-quota test 71b: Check SEL with quota pools ===== 18:37:23 (1775774243) [10902.975596] Lustre: DEBUG MARKER: User quota (block hardlimit:1000 MB) [10985.704872] Lustre: DEBUG MARKER: == sanity-quota test 72: lfs quota --pool prints only pool's OSTs ========================================================== 18:38:56 (1775774336) [10996.298344] Lustre: DEBUG MARKER: User quota (block hardlimit:50 MB) [11016.293831] Lustre: DEBUG MARKER: Write... [11018.243613] Lustre: DEBUG MARKER: Write out of block quota ... [11075.937657] Lustre: DEBUG MARKER: == sanity-quota test 73a: default limits at OST Pool Quotas ========================================================== 18:40:26 (1775774426) [11108.684497] Lustre: DEBUG MARKER: set to use default quota [11110.691477] Lustre: DEBUG MARKER: set default quota [11113.420263] Lustre: DEBUG MARKER: get default quota [11122.226902] Lustre: DEBUG MARKER: Test not out of quota [11127.606744] Lustre: DEBUG MARKER: Test out of quota [11140.396704] Lustre: DEBUG MARKER: Increase default quota [11168.010385] Lustre: DEBUG MARKER: Set quota to override default quota [11168.130829] LustreError: 238605:0:(qmt_entry.c:552:qmt_adjust_edquot()) $$$ set revoke_time explicitly qmt:lustre-QMT0000 pool:dt-qpool1 id:60000 enforced:1 hard:20480 soft:20480 granted:45056 time:1776379320 qunit: 1024 edquot:0 may_rel:0 revoke:0 default:no [11185.498239] Lustre: DEBUG MARKER: Set to use default quota again [11207.354593] Lustre: DEBUG MARKER: Cleanup [11268.696450] Lustre: DEBUG MARKER: == sanity-quota test 73b: default OST Pool Quotas limit for new user ========================================================== 18:43:39 (1775774619) [11290.914247] Lustre: DEBUG MARKER: set default quota for qpool1 [11292.966659] Lustre: DEBUG MARKER: Write from user that hasn't lqe [11342.749244] Lustre: DEBUG MARKER: == sanity-quota test 74: check quota pools per user ====== 18:44:53 (1775774693) [11432.660248] Lustre: DEBUG MARKER: == sanity-quota test 75: nodemap squashed root respects quota enforcement ========================================================== 18:46:23 (1775774783) [11505.333775] Lustre: DEBUG MARKER: Write... [11508.340501] Lustre: DEBUG MARKER: Write out of block quota ... [11614.662237] Lustre: DEBUG MARKER: == sanity-quota test 76: project ID 4294967295 should be not allowed ========================================================== 18:49:25 (1775774965) [11650.090664] Lustre: DEBUG MARKER: == sanity-quota test 77: lfs setquota should fail in Lustre mount with 'ro' ========================================================== 18:50:01 (1775775001) [11659.695396] Lustre: DEBUG MARKER: == sanity-quota test 78A: Check fallocate increase quota usage ========================================================== 18:50:10 (1775775010) [11698.492964] Lustre: DEBUG MARKER: == sanity-quota test 78a: Check fallocate increase projectid usage ========================================================== 18:50:49 (1775775049) [11745.565906] Lustre: DEBUG MARKER: == sanity-quota test 79: access to non-existed dt-pool/info doesn't cause a panic ========================================================== 18:51:36 (1775775096) [11768.254895] Lustre: DEBUG MARKER: == sanity-quota test 80: check for EDQUOT after OST failover ========================================================== 18:51:59 (1775775119) [11799.820665] Lustre: *** cfs_fail_loc=a06, val=0*** [11799.822748] Lustre: Skipped 8 previous similar messages [11800.122523] LustreError: 238623:0:(qmt_lock.c:476:qmt_lvbo_update()) $$$ failed to release quota space on glimpse 0!=2048 : rc = -11 [11800.122523] 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 [11806.013190] Lustre: Failing over lustre-OST0001 [11806.347967] Lustre: server umount lustre-OST0001 complete [11808.741188] LustreError: lustre-OST0001-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [11808.747269] 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 [11808.748487] LustreError: Skipped 1 previous similar message [11808.754335] LustreError: 240938:0:(ldlm_lib.c:1179: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. [11808.765013] Lustre: Skipped 4 previous similar messages [11808.825264] LustreError: 240938:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 4 previous similar messages [11817.357525] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [11817.941996] Lustre: lustre-OST0001: Imperative Recovery enabled, recovery window shrunk from 60-180 down to 60-180 [11817.971188] Lustre: lustre-OST0001: in recovery but waiting for the first client to connect [11819.089659] Lustre: lustre-OST0001: Will be in recovery for at least 1:00, or until 3 clients reconnect [11819.824566] Lustre: lustre-OST0001-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [11819.827536] Lustre: lustre-OST0001: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [11819.834815] Lustre: Skipped 4 previous similar messages [11827.135865] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [11874.718393] Lustre: DEBUG MARKER: == sanity-quota test 81: Race qmt_start_pool_recalc with qmt_pool_free ========================================================== 18:53:46 (1775775226) [11886.635510] Lustre: DEBUG MARKER: User quota (block hardlimit:20 MB) [11894.328304] LustreError: 292198:0:(qmt_pool.c:1399:qmt_pool_recalc()) cfs_fail_timeout id a07 sleeping for 10000ms [11899.872225] LustreError: 3663:0:(client.c:1380:ptlrpc_import_delay_req()) @@@ IMP_CLOSED req@ffff89d3d4a38a80 x1862022974348928/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 [11899.873763] 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 [11899.906954] LustreError: 3663:0:(client.c:1380:ptlrpc_import_delay_req()) Skipped 2 previous similar messages [11899.908616] LustreError: 3663:0:(qsd_handler.c:298:qsd_req_completion()) $$$ DQACQ failed with -5, flags:0x8 qsd:lustre-MDT0000 qtype:grp lqe: ffff89d3d670f500 id:0 enforced:0 granted: 0 pending:0 waiting:0 req:1 usage: 318 qunit:0 qtune:0 edquot:0 default:no revoke:0 [11899.911407] LustreError: lustre-MDT0000-lwp-MDT0001: operation quota_acquire to node 0@lo failed: rc = -107 [11899.915986] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [11899.932377] Lustre: Skipped 3 previous similar messages [11899.942095] Lustre: Skipped 2 previous similar messages [11901.835743] Lustre: lustre-MDT0000: Not available for connect from 192.168.203.13@tcp (stopping) [11904.392365] LustreError: 292198:0:(qmt_pool.c:1399:qmt_pool_recalc()) cfs_fail_timeout id a07 awake [11904.733395] Lustre: server umount lustre-MDT0000 complete [11904.998474] LustreError: 238609:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [11905.025344] LustreError: 238609:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 7 previous similar messages [11913.463600] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [11913.675225] LustreError: MGC192.168.203.113@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [11914.090891] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [11914.162328] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:113 to 0x2c0000401:129) [11914.166761] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:112 to 0x280000401:129) [11918.978414] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [11919.335681] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [11919.339330] Lustre: Skipped 1 previous similar message [11950.158845] Lustre: DEBUG MARKER: == sanity-quota test 82: verify more than 8 qids for single operation ========================================================== 18:55:01 (1775775301) [11975.220461] Lustre: DEBUG MARKER: == sanity-quota test 83: Setting default quota shouldn't affect grace time ========================================================== 18:55:26 (1775775326) [12000.583845] Lustre: DEBUG MARKER: == sanity-quota test 84: Reset quota should fix the insane granted quota ========================================================== 18:55:51 (1775775351) [12047.400294] Lustre: *** cfs_fail_loc=a08, val=0*** [12047.404839] Lustre: Skipped 2430 previous similar messages [12047.418767] Lustre: *** cfs_fail_loc=a08, val=0*** [12047.422968] Lustre: Skipped 6 previous similar messages [12138.782076] Lustre: DEBUG MARKER: == sanity-quota test 85: do not hung at write with the least_qunit ========================================================== 18:58:10 (1775775490) [12167.109623] LustreError: 238607:0:(qmt_entry.c:552:qmt_adjust_edquot()) $$$ set revoke_time explicitly qmt:lustre-QMT0000 pool:dt-qpool1 id:60000 enforced:1 hard:3072 soft:0 granted:3072 time:0 qunit: 1024 edquot:0 may_rel:0 revoke:0 default:no [12225.867589] Lustre: DEBUG MARKER: == sanity-quota test 86: Pre-acquired quota should be released if quota is over limit ========================================================== 18:59:37 (1775775577) [12286.964285] LustreError: 238606:0:(qmt_entry.c:552:qmt_adjust_edquot()) $$$ set revoke_time explicitly qmt:lustre-QMT0000 pool:md-0x0 id:60000 enforced:1 hard:2048 soft:2048 granted:16384 time:1776380439 qunit: 1024 edquot:0 may_rel:0 revoke:0 default:no [12436.045936] LustreError: 245400:0:(qmt_entry.c:552:qmt_adjust_edquot()) $$$ set revoke_time explicitly qmt:lustre-QMT0000 pool:md-0x0 id:60000 enforced:1 hard:2048 soft:2048 granted:16384 time:1776380588 qunit: 1024 edquot:0 may_rel:0 revoke:0 default:no [12580.916723] LustreError: 245400:0:(qmt_entry.c:552:qmt_adjust_edquot()) $$$ set revoke_time explicitly qmt:lustre-QMT0000 pool:md-0x0 id:1000 enforced:1 hard:2048 soft:2048 granted:16384 time:1776380733 qunit: 1024 edquot:0 may_rel:0 revoke:0 default:no [12687.648965] Lustre: DEBUG MARKER: == sanity-quota test 87: lfs quota -a should print default quota setting ========================================================== 19:07:19 (1775776039) [12693.963719] Lustre: *** cfs_fail_loc=a09, val=0*** [12693.966468] Lustre: Skipped 1 previous similar message [12751.752516] Lustre: lustre-MDT0000: Not available for connect from 192.168.203.13@tcp (stopping) [12753.893789] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [12753.899867] 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 [12753.907976] LustreError: Skipped 1 previous similar message [12753.910297] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [12753.932868] Lustre: Skipped 2 previous similar messages [12753.936328] Lustre: Skipped 1 previous similar message [12756.835970] Lustre: lustre-MDT0000: Not available for connect from 192.168.203.13@tcp (stopping) [12756.843097] Lustre: Skipped 2 previous similar messages [12758.096688] Lustre: server umount lustre-MDT0000 complete [12759.015761] LustreError: 240089:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [12759.029545] LustreError: 240089:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 9 previous similar messages [12761.952968] LustreError: 253677:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.203.13@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [12766.844906] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [12767.064687] LustreError: 238605:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.203.13@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [12767.085983] LustreError: 238605:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 4 previous similar messages [12767.100649] LustreError: MGC192.168.203.113@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [12767.617175] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [12767.689176] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:131 to 0x2c0000401:161) [12767.692164] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:131 to 0x280000401:161) [12772.237401] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [12772.842235] LustreError: lustre-MDT0000-osp-MDT0001: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [12772.861927] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [12772.867565] Lustre: Skipped 3 previous similar messages [12788.291921] Lustre: DEBUG MARKER: == sanity-quota test 88: Writing over quota should not hang ========================================================== 19:08:59 (1775776139) [12789.699294] Lustre: DEBUG MARKER: SKIP: sanity-quota test_88 require client with >4k pages [12791.454530] Lustre: DEBUG MARKER: == sanity-quota test 89: Show default quota with squash_uid ========================================================== 19:09:03 (1775776143) [12812.424813] Lustre: DEBUG MARKER: == sanity-quota test 90a: lfs quota should work without mount point ========================================================== 19:09:23 (1775776163) [12829.745464] Lustre: DEBUG MARKER: == sanity-quota test 90b: lfs quota should work with multiple mount points ========================================================== 19:09:41 (1775776181) [12847.189245] Lustre: DEBUG MARKER: == sanity-quota test 91: new quota index files in quota_master ========================================================== 19:09:58 (1775776198) [12862.432564] LustreError: 3666:0:(client.c:1380:ptlrpc_import_delay_req()) @@@ IMP_CLOSED req@ffff89d3d3cc1880 x1862022975687552/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 [12862.460053] LustreError: 3666:0:(client.c:1380:ptlrpc_import_delay_req()) Skipped 2 previous similar messages [12862.474881] LustreError: 3665:0:(qsd_handler.c:298:qsd_req_completion()) $$$ DQACQ failed with -5, flags:0x8 qsd:lustre-MDT0000 qtype:grp lqe: ffff89d4c71eb800 id:0 enforced:0 granted: 0 pending:0 waiting:0 req:1 usage: 2508 qunit:0 qtune:0 edquot:0 default:no revoke:0 [12862.496072] LustreError: 3665:0:(qsd_handler.c:298:qsd_req_completion()) Skipped 7 previous similar messages [12865.001416] 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 [12865.002627] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [12865.004640] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [12865.012334] Lustre: Skipped 4 previous similar messages [12865.037139] Lustre: Skipped 3 previous similar messages [12870.116620] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [12870.121062] Lustre: Skipped 3 previous similar messages [12876.257147] Lustre: lustre-MDT0000 is waiting for obd_unlinked_exports more than 8 seconds. The obd refcount = 3. Is it stuck? [12876.542308] Lustre: server umount lustre-MDT0000 complete [12880.357715] LustreError: 245400:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [12880.398120] LustreError: 245400:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 3 previous similar messages [12881.757526] LustreError: 307272:0:(ldlm_resource.c:1170:ldlm_resource_complain()) lustre-MDT0000-lwp-MDT0001: namespace resource [0x200000006:0x2010000:0x0].0x0 (ffff89d4c9d83200) refcount nonzero (2) after lock cleanup; forcing cleanup. [12881.760130] LustreError: 247645:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1775776234 with bad export cookie 10237780441704994851 [12881.770581] LustreError: 307272:0:(ldlm_resource.c:1170:ldlm_resource_complain()) Skipped 2 previous similar messages [12881.779672] LustreError: MGC192.168.203.113@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [12881.782273] LustreError: 247645:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [12885.475457] 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 [12885.490451] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [12885.498909] Lustre: Skipped 5 previous similar messages [12896.226911] Lustre: lustre-MDT0001 is waiting for obd_unlinked_exports more than 8 seconds. The obd refcount = 3. Is it stuck? [12896.572838] Lustre: server umount lustre-MDT0001 complete [12915.168129] Lustre: lustre-OST0000 is waiting for obd_unlinked_exports more than 8 seconds. The obd refcount = 3. Is it stuck? [12915.288887] Lustre: server umount lustre-OST0000 complete [12924.730723] Lustre: server umount lustre-OST0001 complete [12931.997906] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_hostid [12942.035653] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing load_modules_local [12983.102990] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [12983.336929] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [12983.360517] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [12983.483500] Lustre: lustre-MDT0000: new disk, initializing [12983.605651] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [12983.639484] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [12987.902346] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [12995.114725] Lustre: DEBUG MARKER: oleg313-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0000-mdc-*.mds_server_uuid [13001.289568] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [13001.588183] Lustre: lustre-OST0000: new disk, initializing [13001.594640] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [13001.606923] Lustre: Skipped 1 previous similar message [13001.680409] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [13003.406919] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:0:ost [13003.426671] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:0:ost] [13003.471354] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x240000400 [13007.210322] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [13014.473965] Lustre: DEBUG MARKER: oleg313-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [13022.108904] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [13022.208653] Lustre: lustre-OST0001: new disk, initializing [13022.212234] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [13022.265019] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [13023.847386] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:1:ost [13023.854312] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:1:ost] [13023.897464] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x280000400 [13028.391775] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [13036.805518] Lustre: DEBUG MARKER: oleg313-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0001-osc-[-0-9a-f]*.ost_server_uuid [13053.296729] Lustre: lustre-MDT0000: Not available for connect from 192.168.203.13@tcp (stopping) [13053.313944] Lustre: Skipped 4 previous similar messages [13054.434917] 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 [13054.462389] Lustre: Skipped 1 previous similar message [13056.230174] Lustre: server umount lustre-MDT0000 complete [13068.970664] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [13069.049807] LustreError: MGC192.168.203.113@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [13069.315908] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [13073.751697] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [13075.475489] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [13075.477592] Lustre: Skipped 2 previous similar messages [13079.466322] Lustre: DEBUG MARKER: oleg313-client.virtnet: executing wait_import_state_mount FULL mdc.lustre-MDT0000-mdc-*.mds_server_uuid [13081.160544] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [13083.016575] LustreError: 313249:0:(qmt_entry.c:1166:qmt_map_lge_idx()) qmt: cannot map ostidx 1, num_used 1: rc = -22 [13085.814188] LustreError: 313250:0:(qmt_entry.c:1166:qmt_map_lge_idx()) qmt: cannot map ostidx 1, num_used 1: rc = -22 [13088.816558] Lustre: server umount lustre-MDT0000 complete [13095.851187] LustreError: 309845:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1775776448 with bad export cookie 10237780441704997462 [13095.868783] LustreError: MGC192.168.203.113@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [13106.304575] Lustre: server umount lustre-OST0000 complete [13106.976096] Lustre: 3663:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1775776443/real 1775776443] req@ffff89d3d17a0e00 x1862022975758848/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1775776459 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [13107.015276] 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 [13107.036970] Lustre: Skipped 1 previous similar message [13110.453800] Lustre: server umount lustre-OST0001 complete [13131.937562] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_hostid [13140.921981] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing load_modules_local [13198.043676] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing load_modules_local [13208.635599] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [13208.911798] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [13208.936918] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [13208.998268] Lustre: lustre-MDT0000: new disk, initializing [13209.095527] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [13209.118508] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [13213.573767] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [13226.770472] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [13226.940916] Lustre: 317907:0:(mgs_llog.c:1348:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [13226.980110] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [13226.985412] Lustre: Skipped 1 previous similar message [13227.080157] Lustre: lustre-MDT0001: new disk, initializing [13227.148994] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [13227.161973] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [13231.131098] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [13236.605330] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [13243.497464] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [13243.743174] Lustre: lustre-OST0000: new disk, initializing [13243.754573] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [13243.815932] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [13243.820988] Lustre: Skipped 1 previous similar message [13245.279318] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [13245.293728] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [13245.382856] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [13249.736918] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [13259.545932] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [13261.131810] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [13261.167844] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [13266.037085] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [13275.519733] Lustre: DEBUG MARKER: Using TIMEOUT=20 [13279.029258] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [13292.135945] Lustre: DEBUG MARKER: == sanity-quota test 92: Cannot set inode limit with Quota Pools ========================================================== 19:17:23 (1775776643) [13310.874563] Lustre: DEBUG MARKER: == sanity-quota test 93: update projid while client write to OST ========================================================== 19:17:41 (1775776661) [13335.484218] Lustre: *** cfs_fail_loc=170c, val=0*** [13389.553097] Lustre: DEBUG MARKER: == sanity-quota test 94: lfs quota all respects nodemap offset ========================================================== 19:19:00 (1775776740) [13434.237694] Lustre: lustre-MDT0000: Not available for connect from 192.168.203.13@tcp (stopping) [13434.249533] Lustre: Skipped 2 previous similar messages [13435.362956] 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 [13435.375865] Lustre: Skipped 3 previous similar messages [13447.136204] Lustre: lustre-MDT0000 is waiting for obd_unlinked_exports more than 8 seconds. The obd refcount = 3. Is it stuck? [13447.385353] Lustre: server umount lustre-MDT0000 complete [13449.567059] LustreError: 319902:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.203.13@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [13449.587855] LustreError: 319902:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 6 previous similar messages [13457.205516] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [13457.271819] LustreError: MGC192.168.203.113@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [13457.401916] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [13457.407150] Lustre: Skipped 1 previous similar message [13457.436295] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3 to 0x280000401:33) [13461.852612] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [13462.500787] LustreError: lustre-MDT0000-osp-MDT0001: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [13462.523410] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [13462.529703] Lustre: Skipped 2 previous similar messages [13472.745430] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [13472.750544] 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 [13472.766801] Lustre: Skipped 3 previous similar messages [13475.557136] Lustre: server umount lustre-MDT0000 complete [13482.979114] LustreError: 317918:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [13483.016241] LustreError: 317918:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 17 previous similar messages [13484.208275] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [13484.406399] LustreError: MGC192.168.203.113@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [13484.773103] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3 to 0x280000401:65) [13488.498358] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [13490.150100] LustreError: lustre-MDT0000-osp-MDT0001: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [13490.160529] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [13490.162337] Lustre: Skipped 3 previous similar messages [13500.554348] Lustre: DEBUG MARKER: == sanity-quota test 95a: Correct limits for squashed root ========================================================== 19:20:52 (1775776852) [13520.549601] Lustre: DEBUG MARKER: == sanity-quota test 95b: df respects squashed project id ========================================================== 19:21:12 (1775776872) [13558.845857] Lustre: DEBUG MARKER: == sanity-quota test 96: quota grant should be released when big files are deleted ========================================================== 19:21:50 (1775776910) [13560.727809] Lustre: DEBUG MARKER: SKIP: sanity-quota test_96 OST is too small, skip the test [13569.390274] Lustre: DEBUG MARKER: == sanity-quota test 97a: LQA control commands =========== 19:22:00 (1775776920) [13588.527896] LustreError: 331166:0:(qmt_lqa.c:44:qmt_lqa_destroy()) lustre-QMT0000: cannot destroy lqa-dt-lqa1: rc = -2 [13588.531232] LustreError: 331166:0:(qmt_lqa.c:49:qmt_lqa_destroy()) lustre-QMT0000: cannot destroy lqa-md-lqa1: rc = -2 [13591.833646] Lustre: DEBUG MARKER: == sanity-quota test 97b: Check LQA internals ============ 19:22:23 (1775776943) [13609.191453] LustreError: 332062:0:(qmt_lqa.c:171:qmt_lqa_add()) lustre-QMT0000: lqa:lqa1 can't add range 15:31: rc = -34 [13611.003852] LustreError: 332258:0:(qmt_lqa.c:328:qmt_lqa_remove()) lustre-QMT0000: lqa-md-lqa1 cannot remove range 10:19: rc = -2 [13616.633049] Lustre: DEBUG MARKER: adding 50 LQA ranges took 1s [13618.994386] Lustre: DEBUG MARKER: Removing 50 LQA ranges took 1s [13623.860662] Lustre: DEBUG MARKER: == sanity-quota test 97c: LQA lfs quota commands ========= 19:22:55 (1775776975) [13632.605865] Lustre: DEBUG MARKER: == sanity-quota test complete, duration 13320 sec ======== 19:23:03 (1775776983) [13634.480343] Lustre: DEBUG MARKER: === sanity-quota: start cleanup 19:23:06 (1775776986) === [13637.654702] Lustre: DEBUG MARKER: === sanity-quota: finish cleanup 19:23:09 (1775776989) === [13643.746318] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [13643.746558] 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 [13643.751248] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [13643.751258] Lustre: Skipped 20 previous similar messages [13643.781758] Lustre: Skipped 3 previous similar messages [13648.433900] Lustre: server umount lustre-MDT0000 complete [13648.865716] LustreError: 317919:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [13658.628626] LustreError: 317898:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1775777011 with bad export cookie 10237780441705001333 [13658.642712] LustreError: MGC192.168.203.113@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [13658.649478] LustreError: 317898:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [13659.047666] Lustre: server umount lustre-MDT0001 complete [13675.296387] Lustre: 3663:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1775777011/real 1775777011] req@ffff89d3cf6ab480 x1862022976034560/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1775777027 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [13678.570258] Lustre: 3665:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1775777015/real 1775777015] req@ffff89d4fbdd7100 x1862022976034816/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1775777031 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [13678.619496] Lustre: server umount lustre-OST0000 complete [13684.704096] Lustre: 3664:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1775777021/real 1775777021] req@ffff89d3c1a00000 x1862022976035328/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1775777037 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [13684.742276] Lustre: 3664:0:(client.c:2479:ptlrpc_expire_one_request()) Skipped 1 previous similar message [13686.671583] Lustre: server umount lustre-OST0001 complete [13702.976180] Lustre: DEBUG MARKER: oleg313-server.virtnet: executing unload_modules_local [13706.025814] Key type lgssc unregistered [13706.352253] LNet: 336239:0:(lib-ptl.c:967:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [13706.365915] LNetError: 336239:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [13707.431833] LNet: Removed LNI 192.168.203.113@tcp [13708.353487] Key type .llcrypt unregistered [13708.356746] Key type ._llcrypt unregistered