[ 0.000000] Linux version 4.18.0rh8.10-debug (green@maintenance) (gcc version 8.5.0 20210514 (Red Hat 8.5.0-26) (GCC)) #2 SMP Mon Jul 14 01:24:22 EDT 2025 [ 0.000000] Command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers' [ 0.000000] x86/fpu: xstate_offset[2]: 576, xstate_sizes[2]: 256 [ 0.000000] x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'standard' format. [ 0.000000] signal: max sigframe size: 1776 [ 0.000000] BIOS-provided physical RAM map: [ 0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable [ 0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000000100000-0x00000000bffcdfff] usable [ 0.000000] BIOS-e820: [mem 0x00000000bffce000-0x00000000bfffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000100000000-0x0000000146dfffff] usable [ 0.000000] NX (Execute Disable) protection: active [ 0.000000] SMBIOS 2.8 present. [ 0.000000] DMI: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.17.0-10.fc44 06/10/2025 [ 0.000000] Hypervisor detected: KVM [ 0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00 [ 0.000000] kvm-clock: using sched offset of 472782247 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2399.998 MHz processor [ 0.000000] last_pfn = 0x146e00 max_arch_pfn = 0x400000000 [ 0.000000] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT [ 0.000000] last_pfn = 0xbffce max_arch_pfn = 0x400000000 [ 0.000000] found SMP MP-table at [mem 0x000f54b0-0x000f54bf] [ 0.000000] RAMDISK: [mem 0xbcc54000-0xbffbffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F52D0 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE247C 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE2318 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 0022D8 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE238C 000090 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE241C 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE2454 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe2318-0xbffe238b] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe2317] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe238c-0xbffe241b] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe241c-0xbffe2453] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe2454-0xbffe247b] [ 0.000000] No NUMA configuration found [ 0.000000] Faking a node at [mem 0x0000000000000000-0x0000000146dfffff] [ 0.000000] NODE_DATA(0) allocated [mem 0x1465a3000-0x1465cdfff] [ 0.000000] Reserving 256MB of memory at 2752MB for crashkernel (System RAM: 4205MB) [ 0.000000] Zone ranges: [ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.000000] DMA32 [mem 0x0000000001000000-0x00000000ffffffff] [ 0.000000] Normal [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Device empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff] [ 0.000000] node 0: [mem 0x0000000000100000-0x00000000bffcdfff] [ 0.000000] node 0: [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Zeroed struct page in unavailable ranges: 4756 pages [ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x0000000146dfffff] [ 0.000000] ACPI: PM-Timer IO Port: 0x608 [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) [ 0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) [ 0.000000] Using ACPI (MADT) for SMP configuration information [ 0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000] TSC deadline timer available [ 0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs [ 0.000000] kvm-guest: KVM setup pv remote TLB flush [ 0.000000] kvm-guest: setup PV sched yield [ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff] [ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff] [ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff] [ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff] [ 0.000000] PM: Registered nosave memory: [mem 0xbffce000-0xbfffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xc0000000-0xfeffbfff] [ 0.000000] PM: Registered nosave memory: [mem 0xfeffc000-0xfeffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xff000000-0xfffbffff] [ 0.000000] PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff] [ 0.000000] [mem 0xc0000000-0xfeffbfff] available for PCI devices [ 0.000000] Booting paravirtualized kernel on KVM [ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns [ 0.000000] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1 [ 0.000000] percpu: Embedded 63 pages/cpu s221184 r8192 d28672 u524288 [ 0.000000] kvm-guest: PV spinlocks enabled [ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1059606 [ 0.000000] Policy zone: Normal [ 0.000000] Kernel command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] Specific versions of hardware are certified with Red Hat Enterprise Linux 8. Please see the list of hardware certified with Red Hat Enterprise Linux 8 at https://catalog.redhat.com. [ 0.000000] audit: disabled (until reboot) [ 0.000000] software IO TLB: area num 4. [ 0.000000] Memory: 2829652K/4306352K available (18435K kernel code, 11221K rwdata, 7248K rodata, 2908K init, 18040K bss, 524584K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] ftrace: allocating 41240 entries in 162 pages [ 0.000000] ftrace: allocated 162 pages with 3 groups [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] rcu: RCU event tracing is enabled. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ 0.000000] rcu: RCU callback double-/use-after-free debug enabled. [ 0.000000] Rude variant of Tasks RCU enabled. [ 0.000000] Tracing variant of Tasks RCU enabled. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 0.000000] NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16 [ 0.000000] random: get_random_bytes called from start_kernel+0x622/0x9a8 with crng_init=0 [ 0.001000] Console: colour *CGA 80x25 [ 0.001000] printk: console [ttyS1] enabled [ 0.001000] ACPI: Core revision 20220331 [ 0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.001011] APIC: Switch to symmetric I/O mode setup [ 0.003318] x2apic enabled [ 0.004009] Switched APIC routing to physical x2apic. [ 0.005013] kvm-guest: setup PV IPIs [ 0.007747] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.008000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.008022] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.009013] pid_max: default: 32768 minimum: 301 [ 0.011060] LSM: Security Framework initializing [ 0.012059] Yama: becoming mindful. [ 0.013028] SELinux: Initializing. [ 0.014083] *** VALIDATE selinux *** [ 0.022474] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.027422] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.028119] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.030004] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.031106] *** VALIDATE tmpfs *** [ 0.032457] *** VALIDATE proc *** [ 0.034123] *** VALIDATE cgroup *** [ 0.035010] *** VALIDATE cgroup2 *** [ 0.037104] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.038152] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.039009] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.040028] Spectre V2 : User space: Vulnerable [ 0.041011] Speculative Store Bypass: Vulnerable [ 0.043757] debug: unmapping init [mem 0xffffffff95e59000-0xffffffff95e60fff] [ 0.045974] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.046703] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.047025] ... version: 2 [ 0.048015] ... bit width: 48 [ 0.049012] ... generic registers: 4 [ 0.050015] ... value mask: 0000ffffffffffff [ 0.051014] ... max period: 00007fffffffffff [ 0.052015] ... fixed-purpose events: 3 [ 0.053030] ... event mask: 000000070000000f [ 0.055224] rcu: Hierarchical SRCU implementation. [ 0.057401] smp: Bringing up secondary CPUs ... [ 0.058424] x86: Booting SMP configuration: [ 0.059036] .... node #0, CPUs: #1 #2 #3 [ 0.063467] smp: Brought up 1 node, 4 CPUs [ 0.065018] smpboot: Max logical packages: 1 [ 0.066023] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.221028] node 0 deferred pages initialised in 153ms [ 0.224267] devtmpfs: initialized [ 0.225233] x86/mm: Memory block size: 128MB [ 0.227568] gcov: version magic: 0x41383552 [ 0.231211] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.232083] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.235431] pinctrl core: initialized pinctrl subsystem [ 0.238243] [ 0.238870] ************************************************************* [ 0.241018] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.243014] ** ** [ 0.245013] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.247015] ** ** [ 0.250017] ** This means that this kernel is built to expose internal ** [ 0.252013] ** IOMMU data structures, which may compromise security on ** [ 0.254018] ** your system. ** [ 0.256015] ** ** [ 0.258015] ** If you see this message and you are not debugging the ** [ 0.261018] ** kernel, report this immediately to your vendor! ** [ 0.263030] ** ** [ 0.266020] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.269018] ************************************************************* [ 0.271537] NET: Registered protocol family 16 [ 0.273595] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.276068] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.278077] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.282082] cpuidle: using governor menu [ 0.285716] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.288481] PCI: Using configuration type 1 for base access [ 0.289157] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.298146] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.299050] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.302039] cryptd: max_cpu_qlen set to 1000 [ 0.304232] ACPI: Added _OSI(Module Device) [ 0.305020] ACPI: Added _OSI(Processor Device) [ 0.306029] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.307020] ACPI: Added _OSI(Processor Aggregator Device) [ 0.311000] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.318651] ACPI: Interpreter enabled [ 0.320095] ACPI: PM: (supports S0 S3 S4 S5) [ 0.321018] ACPI: Using IOAPIC for interrupt routing [ 0.323170] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.327551] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.337687] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.340053] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.342026] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.345112] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.351807] acpiphp: Slot [2] registered [ 0.353133] acpiphp: Slot [5] registered [ 0.354130] acpiphp: Slot [6] registered [ 0.356136] acpiphp: Slot [7] registered [ 0.357169] acpiphp: Slot [8] registered [ 0.359124] acpiphp: Slot [9] registered [ 0.360000] acpiphp: Slot [10] registered [ 0.360000] acpiphp: Slot [3] registered [ 0.362128] acpiphp: Slot [4] registered [ 0.363149] acpiphp: Slot [11] registered [ 0.365117] acpiphp: Slot [12] registered [ 0.366130] acpiphp: Slot [13] registered [ 0.367099] acpiphp: Slot [14] registered [ 0.368129] acpiphp: Slot [15] registered [ 0.370106] acpiphp: Slot [16] registered [ 0.371116] acpiphp: Slot [17] registered [ 0.372097] acpiphp: Slot [18] registered [ 0.373123] acpiphp: Slot [19] registered [ 0.375125] acpiphp: Slot [20] registered [ 0.376100] acpiphp: Slot [21] registered [ 0.377097] acpiphp: Slot [22] registered [ 0.378099] acpiphp: Slot [23] registered [ 0.380115] acpiphp: Slot [24] registered [ 0.381149] acpiphp: Slot [25] registered [ 0.382102] acpiphp: Slot [26] registered [ 0.383102] acpiphp: Slot [27] registered [ 0.385114] acpiphp: Slot [28] registered [ 0.386099] acpiphp: Slot [29] registered [ 0.387127] acpiphp: Slot [30] registered [ 0.389136] acpiphp: Slot [31] registered [ 0.391107] PCI host bridge to bus 0000:00 [ 0.393040] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.396037] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.398031] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.401036] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.404028] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.406029] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.408205] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.411121] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.415303] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.424018] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.430922] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.433037] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.436024] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.438022] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.442391] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.444711] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.447044] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.449982] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.455018] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.467025] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.471025] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.476762] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.482017] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.488015] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.501020] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.512000] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.524021] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.530020] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.549021] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.559824] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.565014] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.571017] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.583016] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.592976] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.598016] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.604016] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.616013] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.624355] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.630020] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.637020] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.653022] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 0.664881] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.671013] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.677016] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.690017] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 0.701704] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.703435] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.706427] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.709401] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.711216] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.715199] iommu: Default domain type: Passthrough [ 0.717610] SCSI subsystem initialized [ 0.720222] ACPI: bus type USB registered [ 0.722171] usbcore: registered new interface driver usbfs [ 0.725154] usbcore: registered new interface driver hub [ 0.727119] usbcore: registered new device driver usb [ 0.729230] pps_core: LinuxPPS API ver. 1 registered [ 0.732018] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.735093] PTP clock support registered [ 0.738057] EDAC MC: Ver: 3.0.0 [ 0.740156] PCI: Using ACPI for IRQ routing [ 0.742988] NetLabel: Initializing [ 0.745019] NetLabel: domain hash size = 128 [ 0.746018] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.749110] NetLabel: unlabeled traffic allowed by default [ 0.751174] vgaarb: loaded [ 0.753311] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.755011] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.759326] clocksource: Switched to clocksource kvm-clock [ 0.864190] VFS: Disk quotas dquot_6.6.0 [ 0.865862] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.868276] *** VALIDATE ramfs *** [ 0.869504] *** VALIDATE hugetlbfs *** [ 0.871588] pnp: PnP ACPI init [ 0.874058] pnp: PnP ACPI: found 6 devices [ 0.893556] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.897143] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.899129] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.901308] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.903988] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.906328] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.908816] NET: Registered protocol family 2 [ 0.911227] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.916063] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.919682] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.924623] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.927924] TCP: Hash tables configured (established 65536 bind 65536) [ 0.931038] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.934325] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.937222] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.939802] NET: Registered protocol family 1 [ 0.943144] RPC: Registered named UNIX socket transport module. [ 0.945460] RPC: Registered udp transport module. [ 0.947014] RPC: Registered tcp transport module. [ 0.948724] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.951380] NET: Registered protocol family 44 [ 0.953254] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.955651] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.957903] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.960292] PCI: CLS 0 bytes, default 64 [ 0.962194] Unpacking initramfs... [ 2.365356] debug: unmapping init [mem 0xffff97afbcc54000-0xffff97afbffbffff] [ 2.369036] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.371225] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.374315] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 2.868203] Initialise system trusted keyrings [ 2.870074] Key type blacklist registered [ 2.872061] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.881925] zbud: loaded [ 2.885265] *** VALIDATE nfs *** [ 2.886536] *** VALIDATE nfs4 *** [ 2.888256] pstore: using deflate compression [ 2.891983] Platform Keyring initialized [ 3.002645] NET: Registered protocol family 38 [ 3.005436] Key type asymmetric registered [ 3.006936] Asymmetric key parser 'x509' registered [ 3.009770] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 3.013301] io scheduler mq-deadline registered [ 3.015361] io scheduler kyber registered [ 3.017247] io scheduler bfq registered [ 3.019376] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 3.023055] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 3.026117] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 3.029358] ACPI: Power Button [PWRF] [ 3.047409] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 3.056460] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 3.073620] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 3.082647] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 3.102022] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 3.132421] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.163042] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.168500] Non-volatile memory driver v1.3 [ 3.170502] Linux agpgart interface v0.103 [ 3.214331] virtio_blk virtio1: [vda] 145944 512-byte logical blocks (74.7 MB/71.3 MiB) [ 3.219222] vda: detected capacity change from 0 to 74723328 [ 3.232571] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.235090] vdb: detected capacity change from 0 to 1073741824 [ 3.250186] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.253284] vdc: detected capacity change from 0 to 2621440000 [ 3.273686] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.276958] vdd: detected capacity change from 0 to 2621440000 [ 3.292995] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.295794] vde: detected capacity change from 0 to 4294967296 [ 3.313494] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.316396] vdf: detected capacity change from 0 to 4294967296 [ 3.322321] libphy: Fixed MDIO Bus: probed [ 3.327479] usbcore: registered new interface driver usbserial_generic [ 3.329821] usbserial: USB Serial support registered for generic [ 3.331899] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.335483] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.337085] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.339447] mousedev: PS/2 mouse device common for all mice [ 3.342335] rtc_cmos 00:05: RTC can wake from S4 [ 3.342573] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.346357] rtc_cmos 00:05: registered as rtc0 [ 3.349131] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.351285] intel_pstate: CPU model not supported [ 3.354750] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.358425] hid: raw HID events driver (C) Jiri Kosina [ 3.359178] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.360488] usbcore: registered new interface driver usbhid [ 3.364248] usbhid: USB HID core driver [ 3.365994] drop_monitor: Initializing network drop monitor service [ 3.367977] Initializing XFRM netlink socket [ 3.369768] NET: Registered protocol family 10 [ 3.372419] Segment Routing with IPv6 [ 3.373647] NET: Registered protocol family 17 [ 3.375880] mpls_gso: MPLS GSO support [ 3.379862] RAS: Correctable Errors collector initialized. [ 3.381211] AVX version of gcm_enc/dec engaged. [ 3.382146] AES CTR mode by8 optimization enabled [ 3.466234] sched_clock: Marking stable (3466193864, 0)->(4378107462, -911913598) [ 3.469872] registered taskstats version 1 [ 3.471968] Loading compiled-in X.509 certificates [ 3.474035] zswap: loaded using pool lzo/zbud [ 3.500609] Key type big_key registered [ 3.514405] Key type encrypted registered [ 3.515909] ima: No TPM chip found, activating TPM-bypass! [ 3.517353] ima: Allocated hash algorithm: sha1 [ 3.518582] ima: No architecture policies found [ 3.521455] evm: Initialising EVM extended attributes: [ 3.523404] evm: security.selinux [ 3.524668] evm: security.ima [ 3.525881] evm: security.capability [ 3.527261] evm: HMAC attrs: 0x1 [ 3.530947] rtc_cmos 00:05: setting system clock to 2026-08-14 23:32:18 UTC (1786750338) [ 3.537390] debug: unmapping init [mem 0xffffffff96e03000-0xffffffff96ffffff] [ 3.540148] debug: unmapping init [mem 0xffffffff95b82000-0xffffffff95e58fff] [ 3.548121] Write protecting the kernel read-only data: 28672k [ 3.551611] debug: unmapping init [mem 0xffffffff94203000-0xffffffff943fffff] [ 3.554522] debug: unmapping init [mem 0xffffffff94b14000-0xffffffff94bfffff] [ 3.589297] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 3.598973] systemd[1]: Detected virtualization kvm. [ 3.601064] systemd[1]: Detected architecture x86-64. [ 3.603236] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.630065] systemd[1]: No hostname configured. [ 3.632222] systemd[1]: Set hostname to . [ 3.634639] random: systemd: uninitialized urandom read (16 bytes read) [ 3.637534] systemd[1]: Initializing machine ID from random generator. [ 3.694376] random: ln: uninitialized urandom read (6 bytes read) [ 3.785754] random: systemd: uninitialized urandom read (16 bytes read) [ 3.787798] systemd[1]: Reached target Local File Systems. [ OK ] Reached target Local File Systems. [ 3.792597] systemd[1]: Reached target Swap. [ OK ] Reached target Swap. [ 3.796648] systemd[1]: Listening on Journal Socket (/dev/log). [ OK ] Listening on Journal Socket (/dev/log). [ OK ] Reached target Slices. [ OK ] Listening on Journal Socket. Starting Create Volatile Files and Directories... Starting Create list of required st…ce nodes for the current kernel... Starting Setup Virtual Console... Starting Journal Service... [ OK ] Reached target Timers. [ OK ] Reached target Initrd Root Device. [ OK ] Listening on udev Control Socket. [ OK ] Listening on udev Kernel Socket. [ OK ] Reached target Sockets. Starting Apply Kernel Variables... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. [ OK ] Started Memstrack Anylazing Service. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Setup Virtual Console. [ OK ] Started Apply Kernel Variables. Starting dracut cmdline hook... Starting Create Static Device Nodes in /dev... [ OK ] Started Journal Service. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 4.460954] device-mapper: uevent: version 1.0.3 [ 4.463325] 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... [[ 5.044195] random: fast init done  OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting dracut initqueue hook... [ 5.247929] virtio_net virtio0 ens2: renamed from eth0 [ 5.278417] scsi host0: ata_piix [ 5.321221] scsi host1: ata_piix [ 5.324203] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 5.328154] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 9.859932] dracut-initqueue[606]: RTNETLINK answers: File exists [ 10.035619] random: crng init done [ 10.036765] random: 7 urandom warning(s) missed due to ratelimiting Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. Mounting /sysroot... [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. [ 10.549898] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Initrd Default Target. [ 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 Root Device. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Sockets. [ OK ] Stopped target Slices. [ OK ] Stopped target System Initialization. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. [ OK ] Stopped target Swap. Stopping udev Kernel Device Manager... [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. [ OK ] Stopped target Paths. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Closed udev Control Socket. [ OK ] Closed udev Kernel Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 11.791773] printk: systemd: 25 output lines suppressed due to ratelimiting [ 12.090127] SELinux: Disabled at runtime. [ 12.156386] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 12.165397] systemd[1]: Detected virtualization kvm. [ 12.167486] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 12.708133] systemd[1]: initrd-switch-root.service: Succeeded. [ 12.711220] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 12.715939] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 12.722118] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 12.725461] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 12.734498] systemd[1]: Starting Journal Service... Starting Journal Service... [ 12.743949] systemd[1]: Mounting Huge Pages File System... Mounting Huge Pages File System... [ OK ] Created slice system-getty.slice. [ OK ] Created slice User and Session Slice. [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Listening on udev Kernel Socket. [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Reached target Slices. [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. Mounting Kernel Debug File System... [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd File Systems. [ OK ] Stopped target Initrd Root File System. Mounting POSIX Message Queue File System... Starting Create list of required st…ce nodes for the current kernel... Starting Remount Root and Kernel File Systems... [ OK ] Reached target rpc_pipefs.target. Starting Apply Kernel Variables... [ OK ] Listening on Process Core Dump Socket. [ OK ] Listening on udev Control Socket. Starting udev Coldplug all Devices... [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Listening on initctl Compatibility Named Pipe. Activating swap /dev/disk/by-label/SWAP... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Paths. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target RPC Port Mapper. [ 12.944483] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS [ OK ] Started Journal Service. [ OK ] Mounted Huge Pages File System. [ OK ] Mounted Kernel Debug File System. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Started Apply Kernel Variables. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Reached target Swap. Starting Configure read-only root support... Starting Create Static Device Nodes in /dev... Starting Flush Journal to Persistent Storage... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Reached target Local File Systems (Pre). Mounting /home/green/git/lustre-release... Mounting /mnt... Starting udev Kernel Device Manager... [ OK ] Started udev Coldplug all Devices. [ OK ] Mounted /mnt. [ 13.230442] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 13.636710] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 13.670619] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 13.852647] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 13.863695] EDAC sbridge: Ver: 1.1.2 [ 15.483187] Key type dns_resolver registered [ 15.781705] NFS: Registering the id_resolver key type [ 15.783758] Key type id_resolver registered [ 15.785195] Key type id_legacy registered [ OK ] Started Configure read-only root support. [ OK ] Reached target Local File Systems. Starting Mark the need to relabel after reboot... Starting Rebuild Dynamic Linker Cache... Starting Load/Save Random Seed... Starting Create Volatile Files and Directories... [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Load/Save Random Seed. [ OK ] Started Create Volatile Files and Directories. Starting RPC Bind... Starting Update UTMP about System Boot/Shutdown... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Started dnf makecache --timer. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Reached target Timers. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. Starting Restore /run/initramfs on shutdown... [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Started irqbalance daemon. Starting Login Service... [ OK ] Reached target sshd-keygen.target. [ OK ] Started D-Bus System Message Bus. Starting Network Manager... [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Login Service. [ OK ] Started Network Manager. [ OK ] Reached target Network. Starting GSSAPI Proxy Daemon... Starting OpenSSH server daemon... Starting Dynamic System Tuning Daemon... Starting Network Manager Wait Online... [ 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... Starting Hostname Service... [ OK ] Started Permit User Sessions. [ OK ] Started Serial Getty on ttyS1. [ OK ] Started Getty on tty1. [ OK ] Started Serial Getty on ttyS0. [ OK ] Reached target Login Prompts. [ OK ] Started Command Scheduler. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting 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. Starting Authorization Manager... [ OK ] Started Authorization Manager. [ OK ] Started Dynamic System Tuning Daemon. [ OK ] Reached target Multi-User System. [ OK ] Reached target Graphical Interface. Starting Update UTMP about System Runlevel Changes... [ OK ] Started Update UTMP about System Runlevel Changes. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg355-server login: [ 42.048871] libcfs: loading out-of-tree module taints kernel. [ 42.069192] Key type ._llcrypt registered [ 42.070807] Key type .llcrypt registered [ 42.120767] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_hostid [ 50.659543] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing load_modules_local [ 51.301506] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 51.309602] alg: No test for adler32 (adler32-zlib) [ 52.358405] Lustre: Lustre: Build Version: 2.17.57_4_gb324e6e [ 52.707970] LNet: Added LNI 192.168.203.155@tcp [8/256/0/180] [ 54.335186] Key type lgssc registered [ 55.045659] Lustre: Echo OBD driver; http://www.lustre.org/ [ 66.995764] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 101.038830] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing load_modules_local [ 112.253614] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 112.302419] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 113.584620] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 113.675278] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 113.791785] Lustre: lustre-MDT0000: new disk, initializing [ 113.880300] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 113.904305] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 117.865631] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 129.488357] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 129.572695] Lustre: 6498:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 129.611559] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 129.615432] Lustre: Skipped 1 previous similar message [ 129.712861] Lustre: lustre-MDT0001: new disk, initializing [ 129.789552] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 129.835682] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 129.855529] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 133.470246] hrtimer: interrupt took 6973138 ns [ 133.948496] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 139.092341] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 148.630433] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 148.914458] Lustre: lustre-OST0000: new disk, initializing [ 148.917727] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 148.925665] Lustre: 8434:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 148.994073] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 155.016362] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 157.218884] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 157.227862] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 157.295975] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 168.284095] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 168.429232] Lustre: lustre-OST0001: new disk, initializing [ 168.433081] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 168.443740] Lustre: 9506:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 168.522735] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 174.473792] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 178.719332] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 178.737817] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 178.871161] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 186.402975] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 192.602708] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 199.476815] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing check_logdir /tmp/testlogs/ [ 205.850635] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing yml_node [ 210.256881] Lustre: DEBUG MARKER: Client: 2.17.57.4 [ 212.696657] Lustre: DEBUG MARKER: MDS: 2.17.57.4 [ 215.164587] Lustre: DEBUG MARKER: OSS: 2.17.57.4 [ 216.652937] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity-lfsck ============----- Fri Aug 14 19:35:50 EDT 2026 [ 230.958130] Lustre: DEBUG MARKER: excepting tests: 18b 23b [ 239.294190] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing load_modules_local [ 245.732303] 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 [ 245.735096] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 245.746438] Lustre: Skipped 3 previous similar messages [ 245.757636] Lustre: Skipped 3 previous similar messages [ 250.850106] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 250.854883] Lustre: Skipped 3 previous similar messages [ 252.029948] Lustre: server umount lustre-MDT0000 complete [ 260.396580] LustreError: 6490:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1786750595 with bad export cookie 13195088412826044008 [ 260.399352] LustreError: MGC192.168.203.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 260.405084] LustreError: 6490:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 260.814386] Lustre: server umount lustre-MDT0001 complete [ 277.919892] Lustre: 3632:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786750596/real 1786750596] req@ffff97af034f8a80 x1873543573894016/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786750612 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 277.949076] 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 [ 278.049347] Lustre: server umount lustre-OST0000 complete [ 281.507203] Lustre: 3634:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786750600/real 1786750600] req@ffff97b03fc0e300 x1873543573894272/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786750616 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 282.592104] Lustre: 3633:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786750601/real 1786750601] req@ffff97af034f9180 x1873543573894528/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786750617 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 285.553581] Lustre: server umount lustre-OST0001 complete [ 300.813971] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing unload_modules_local [ 303.469403] Key type lgssc unregistered [ 303.759058] LNet: 14777:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 303.767553] LNetError: 14777:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 303.784824] LNet: Removed LNI 192.168.203.155@tcp [ 304.614796] Key type .llcrypt unregistered [ 304.627708] Key type ._llcrypt unregistered [ 328.214385] Key type ._llcrypt registered [ 328.216580] Key type .llcrypt registered [ 328.296808] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_hostid [ 344.366531] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing load_modules_local [ 345.654465] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 345.733419] alg: No test for adler32 (adler32-zlib) [ 346.905608] Lustre: Lustre: Build Version: 2.17.57_4_gb324e6e [ 347.250569] LNet: Added LNI 192.168.203.155@tcp [8/256/0/180] [ 349.033706] Key type lgssc registered [ 350.947422] Lustre: Echo OBD driver; http://www.lustre.org/ [ 396.554394] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing load_modules_local [ 409.285864] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 409.313176] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 410.563759] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 410.613969] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 410.727300] Lustre: lustre-MDT0000: new disk, initializing [ 410.809884] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 410.840848] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 415.444782] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 428.786565] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 428.899928] Lustre: 19234:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 428.935673] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 428.939597] Lustre: Skipped 1 previous similar message [ 429.059872] Lustre: lustre-MDT0001: new disk, initializing [ 429.149686] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 429.200021] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 429.225812] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 434.598589] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 439.919501] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 451.490874] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 451.793880] Lustre: lustre-OST0000: new disk, initializing [ 451.798596] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 451.806481] Lustre: 21172:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 451.920286] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 457.273515] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 457.286138] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 457.330239] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 458.640525] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 472.026593] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 472.147815] Lustre: lustre-OST0001: new disk, initializing [ 472.153188] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 472.158857] Lustre: 22196:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 472.231611] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 478.728294] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 478.775790] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 478.787485] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 478.836777] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 489.148809] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 498.792440] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 506.960685] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 19:40:40 (1786750840) === [ 510.055724] Lustre: DEBUG MARKER: == sanity-lfsck test 0: Control LFSCK manually =========== 19:40:44 (1786750844) [ 510.278970] Lustre: 19239:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 251 < left 278, rollback = 2 [ 510.291541] Lustre: 19239:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 510.300373] Lustre: 19239:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 510.314708] Lustre: 19239:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 510.324635] Lustre: 19239:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 510.335869] Lustre: 19239:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 510.792616] Lustre: 19239:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 510.802994] Lustre: 19239:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 11 previous similar messages [ 510.811825] Lustre: 19239:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 510.818540] Lustre: 19239:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 510.824461] Lustre: 19239:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 510.829487] Lustre: 19239:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 510.838363] Lustre: 19239:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 510.844516] Lustre: 19239:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 510.851298] Lustre: 19239:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 510.857533] Lustre: 19239:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 510.861915] Lustre: 19239:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 510.866849] Lustre: 19239:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 511.805264] Lustre: 19239:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 511.812067] Lustre: 19239:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 44 previous similar messages [ 511.822863] Lustre: 19239:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 511.829539] Lustre: 19239:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 44 previous similar messages [ 511.835273] Lustre: 19239:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 511.840638] Lustre: 19239:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 44 previous similar messages [ 511.844185] Lustre: 19239:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 511.853383] Lustre: 19239:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 44 previous similar messages [ 511.861938] Lustre: 19239:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 511.866268] Lustre: 19239:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 44 previous similar messages [ 511.872285] Lustre: 19239:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 511.877930] Lustre: 19239:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 44 previous similar messages [ 513.857752] Lustre: 19241:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 513.864439] Lustre: 19241:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 95 previous similar messages [ 513.869414] Lustre: 19241:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 513.874574] Lustre: 19241:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 95 previous similar messages [ 513.879520] Lustre: 19241:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 513.884263] Lustre: 19241:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 95 previous similar messages [ 513.888551] Lustre: 19241:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 513.894372] Lustre: 19241:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 95 previous similar messages [ 513.899952] Lustre: 19241:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 513.908289] Lustre: 19241:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 95 previous similar messages [ 513.920429] Lustre: 19241:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 513.933539] Lustre: 19241:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 95 previous similar messages [ 517.772529] Lustre: *** cfs_fail_loc=1600, val=3*** [ 520.355698] Lustre: 23385:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 260 < left 274, rollback = 2 [ 520.356444] Lustre: 23386:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 520.360668] Lustre: 23385:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 124 previous similar messages [ 520.360692] Lustre: 23385:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 2/274/0 [ 520.360697] Lustre: 23385:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 123 previous similar messages [ 520.360703] Lustre: 23385:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 0/0/0, punch: 0/0/0, quota 7/225/0 [ 520.360707] Lustre: 23385:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 123 previous similar messages [ 520.360713] Lustre: 23385:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 520.360717] Lustre: 23385:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 123 previous similar messages [ 520.360723] Lustre: 23385:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 520.360726] Lustre: 23385:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 123 previous similar messages [ 520.463099] Lustre: 23386:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 130 previous similar messages [ 521.804489] Lustre: *** cfs_fail_loc=1600, val=3*** [ 531.373659] Lustre: 23637:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 259 < left 274, rollback = 2 [ 531.374709] Lustre: 23645:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 531.390659] Lustre: 23637:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 61 previous similar messages [ 531.390688] Lustre: 23637:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/1, xattr_set: 2/274/0 [ 531.390692] Lustre: 23637:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 61 previous similar messages [ 531.390698] Lustre: 23637:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 0/0/0, punch: 0/0/0, quota 7/225/0 [ 531.390701] Lustre: 23637:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 61 previous similar messages [ 531.390707] Lustre: 23637:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 531.390710] Lustre: 23637:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 61 previous similar messages [ 531.390715] Lustre: 23637:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 531.390718] Lustre: 23637:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 61 previous similar messages [ 531.464060] Lustre: 23645:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 58 previous similar messages [ 535.009223] 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 [ 535.017304] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 535.032175] Lustre: Skipped 3 previous similar messages [ 535.044839] Lustre: Skipped 3 previous similar messages [ 539.642411] Lustre: server umount lustre-MDT0000 complete [ 543.049613] LustreError: 19226:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1786750878 with bad export cookie 11607402660536757253 [ 543.051625] LustreError: MGC192.168.203.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 543.062083] LustreError: 19226:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 543.382188] Lustre: server umount lustre-MDT0001 complete [ 556.954566] Lustre: server umount lustre-OST0000 complete [ 570.531624] Lustre: server umount lustre-OST0001 complete [ 580.201749] Lustre: DEBUG MARKER: == sanity-lfsck test 1a: LFSCK can find out and repair crashed FID-in-dirent ========================================================== 19:41:54 (1786750914) [ 596.761530] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing load_modules_local [ 604.778532] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 605.145522] LustreError: 26256:0:(ldlm_lib.c:1192: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. [ 605.163746] LustreError: 26256:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 5 previous similar messages [ 605.198918] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 609.138185] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 610.272399] LustreError: 26257:0:(ldlm_lib.c:1192: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. [ 615.394816] LustreError: 26256:0:(ldlm_lib.c:1192: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. [ 616.843191] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 617.213185] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 621.488717] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 624.538098] Lustre: 27396:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 631.080154] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 638.769228] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 642.701350] LustreError: 27751:0:(ldlm_lib.c:1192: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. [ 648.160727] LustreError: 27752:0:(ldlm_lib.c:1192: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. [ 648.719178] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 649.036581] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 649.048673] Lustre: Skipped 1 previous similar message [ 651.058395] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:41 to 0x280000401:65) [ 651.071724] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:40 to 0x2c0000401:65) [ 656.089306] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 663.591096] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 666.790829] Lustre: 29267:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 668.262606] Lustre: 26252:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 668.285173] Lustre: 26252:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 6 previous similar messages [ 668.292295] Lustre: 26252:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 668.303423] Lustre: 26252:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 3 previous similar messages [ 668.319150] Lustre: 26252:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 668.331755] Lustre: 26252:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 7 previous similar messages [ 668.339669] Lustre: 26252:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 668.350604] Lustre: 26252:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 7 previous similar messages [ 668.356825] Lustre: 26252:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 668.374527] Lustre: 26252:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 7 previous similar messages [ 668.383256] Lustre: 26252:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 668.394036] Lustre: 26252:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 7 previous similar messages [ 674.430533] Lustre: *** cfs_fail_loc=1501, val=0*** [ 681.880182] Lustre: Failing over lustre-MDT0000 [ 681.957756] 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 [ 681.976279] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 681.980664] Lustre: Skipped 3 previous similar messages [ 682.116605] Lustre: server umount lustre-MDT0000 complete [ 687.074962] LustreError: 29282:0:(ldlm_lib.c:1192: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. [ 687.092759] LustreError: 29282:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 3 previous similar messages [ 692.861821] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 693.025218] LustreError: MGC192.168.203.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 693.332342] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 693.410925] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 697.853528] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 698.338988] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 698.345169] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 698.368183] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 698.409766] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:105 to 0x280000401:129) [ 698.412187] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:105 to 0x2c0000401:129) [ 701.521457] Lustre: *** cfs_fail_loc=1505, val=0*** [ 708.140506] Lustre: DEBUG MARKER: == sanity-lfsck test 1b: LFSCK can find out and repair the missing FID-in-LMA ========================================================== 19:44:02 (1786751042) [ 709.429698] Lustre: 26251:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 256 < left 278, rollback = 2 [ 709.436119] Lustre: 26251:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 322 previous similar messages [ 709.441169] Lustre: 26251:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 709.446885] Lustre: 26251:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 709.451644] Lustre: 26251:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 709.458207] Lustre: 26251:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 709.464082] Lustre: 26251:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 709.473359] Lustre: 26251:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 709.486941] Lustre: 26251:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 709.495841] Lustre: 26251:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 709.502363] Lustre: 26251:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 709.511439] Lustre: 26251:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 714.336689] Lustre: *** cfs_fail_loc=1502, val=0*** [ 723.548985] Lustre: Failing over lustre-MDT0000 [ 723.937983] 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 [ 723.949218] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 723.954049] Lustre: Skipped 3 previous similar messages [ 723.954491] LustreError: 26252:0:(ldlm_lib.c:1192: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. [ 723.954499] LustreError: 26252:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 4 previous similar messages [ 724.125202] Lustre: server umount lustre-MDT0000 complete [ 734.119727] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 734.255910] LustreError: MGC192.168.203.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 734.628463] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 739.552956] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 739.823541] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 739.824893] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 739.834469] Lustre: Skipped 3 previous similar messages [ 739.873544] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 739.937950] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:169 to 0x2c0000401:193) [ 739.938245] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:169 to 0x280000401:193) [ 743.042823] Lustre: *** cfs_fail_loc=1505, val=0*** [ 749.915551] Lustre: DEBUG MARKER: == sanity-lfsck test 1c: LFSCK can find out and repair lost FID-in-dirent ========================================================== 19:44:43 (1786751083) [ 756.643157] Lustre: *** cfs_fail_loc=1504, val=0*** [ 756.644831] Lustre: *** cfs_fail_loc=1504, val=0*** [ 756.648300] Lustre: Skipped 1 previous similar message [ 764.093993] Lustre: Failing over lustre-MDT0000 [ 765.408823] 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 [ 765.414060] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 765.415497] LustreError: 27311:0:(ldlm_lib.c:1192: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. [ 765.415506] LustreError: 27311:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 11 previous similar messages [ 765.427162] Lustre: Skipped 4 previous similar messages [ 766.399281] Lustre: server umount lustre-MDT0000 complete [ 776.652951] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 776.753699] LustreError: MGC192.168.203.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 776.931925] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 776.939366] Lustre: Skipped 1 previous similar message [ 776.966354] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 781.394174] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 782.305554] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 782.307088] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 782.324258] Lustre: Skipped 3 previous similar messages [ 782.339574] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 782.401555] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:233 to 0x280000401:257) [ 782.406548] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:233 to 0x2c0000401:257) [ 784.527734] Lustre: *** cfs_fail_loc=1505, val=0*** [ 790.914829] Lustre: DEBUG MARKER: == sanity-lfsck test 2a: LFSCK can find out and repair crashed linkEA entry ========================================================== 19:45:25 (1786751125) [ 792.336297] Lustre: 26253:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 792.345548] Lustre: 26253:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 644 previous similar messages [ 792.358148] Lustre: 26253:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 792.369612] Lustre: 26253:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 792.378887] Lustre: 26253:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 792.389914] Lustre: 26253:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 792.402555] Lustre: 26253:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 792.414656] Lustre: 26253:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 792.424971] Lustre: 26253:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 792.440929] Lustre: 26253:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 792.449817] Lustre: 26253:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 792.459874] Lustre: 26253:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 797.592902] Lustre: *** cfs_fail_loc=1603, val=0*** [ 805.447955] Lustre: Failing over lustre-MDT0000 [ 805.677157] Lustre: server umount lustre-MDT0000 complete [ 807.910856] 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 [ 807.917977] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 807.944057] Lustre: Skipped 4 previous similar messages [ 816.287723] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 816.458376] LustreError: MGC192.168.203.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 816.726926] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 820.542939] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 821.736692] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 821.752466] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 821.760713] Lustre: Skipped 3 previous similar messages [ 821.798574] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 821.848721] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:297 to 0x2c0000401:321) [ 821.849571] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:297 to 0x280000401:321) [ 830.273080] Lustre: DEBUG MARKER: == sanity-lfsck test 2b: LFSCK can find out and remove invalid linkEA entry ========================================================== 19:46:04 (1786751164) [ 836.731381] Lustre: *** cfs_fail_loc=1604, val=0*** [ 846.143555] Lustre: Failing over lustre-MDT0000 [ 846.360150] Lustre: server umount lustre-MDT0000 complete [ 847.328193] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 847.335650] 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 [ 847.337875] LustreError: 27311:0:(ldlm_lib.c:1192: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. [ 847.347920] Lustre: Skipped 2 previous similar messages [ 847.384919] LustreError: 27311:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 22 previous similar messages [ 856.557893] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 856.712476] LustreError: MGC192.168.203.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 856.964406] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 861.152759] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 862.187671] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 862.193720] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 862.214509] Lustre: Skipped 3 previous similar messages [ 862.245547] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 862.311360] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:361 to 0x280000401:385) [ 862.314398] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:361 to 0x2c0000401:385) [ 870.950598] Lustre: DEBUG MARKER: == sanity-lfsck test 2c: LFSCK can find out and remove repeated linkEA entry ========================================================== 19:46:45 (1786751205) [ 878.037067] Lustre: *** cfs_fail_loc=1605, val=0*** [ 886.166199] Lustre: Failing over lustre-MDT0000 [ 886.459495] Lustre: server umount lustre-MDT0000 complete [ 887.776516] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 887.780106] 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 [ 887.807173] Lustre: Skipped 4 previous similar messages [ 896.477152] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 896.675719] LustreError: MGC192.168.203.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 896.889561] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 900.838824] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 902.121151] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 902.134135] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 902.145749] Lustre: Skipped 3 previous similar messages [ 902.207778] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 902.292120] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:425 to 0x2c0000401:449) [ 902.292917] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:425 to 0x280000401:449) [ 910.215710] Lustre: DEBUG MARKER: == sanity-lfsck test 2d: LFSCK can recover the missing linkEA entry ========================================================== 19:47:24 (1786751244) [ 917.319369] Lustre: *** cfs_fail_loc=161d, val=0*** [ 925.346361] Lustre: Failing over lustre-MDT0000 [ 925.611855] Lustre: server umount lustre-MDT0000 complete [ 927.712831] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 927.717623] 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 [ 927.742203] Lustre: Skipped 4 previous similar messages [ 936.229079] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 936.386755] LustreError: MGC192.168.203.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 936.669325] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 936.672840] Lustre: Skipped 3 previous similar messages [ 936.716864] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 941.088075] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 942.055505] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 942.060357] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 942.079286] Lustre: Skipped 3 previous similar messages [ 942.129290] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 942.187978] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:489 to 0x280000401:513) [ 942.188623] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:489 to 0x2c0000401:513) [ 952.287825] Lustre: DEBUG MARKER: == sanity-lfsck test 2e: namespace LFSCK can verify remote object linkEA ========================================================== 19:48:06 (1786751286) [ 953.780486] Lustre: 26253:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 256 < left 278, rollback = 2 [ 953.788475] Lustre: 26253:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 1290 previous similar messages [ 953.796508] Lustre: 26253:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 953.805405] Lustre: 26253:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1290 previous similar messages [ 953.811836] Lustre: 26253:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 953.822886] Lustre: 26253:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1290 previous similar messages [ 953.832520] Lustre: 26253:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 953.839615] Lustre: 26253:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1290 previous similar messages [ 953.846706] Lustre: 26253:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 953.852925] Lustre: 26253:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1290 previous similar messages [ 953.861629] Lustre: 26253:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 953.870599] Lustre: 26253:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1290 previous similar messages [ 955.272126] Lustre: *** cfs_fail_loc=1603, val=0*** [ 966.520898] Lustre: DEBUG MARKER: == sanity-lfsck test 3: LFSCK can verify multiple-linked objects ========================================================== 19:48:20 (1786751300) [ 972.826693] Lustre: *** cfs_fail_loc=1603, val=0*** [ 973.693459] Lustre: *** cfs_fail_loc=1604, val=0*** [ 983.941598] Lustre: DEBUG MARKER: == sanity-lfsck test 4: FID-in-dirent can be rebuilt after MDT file-level backup/restore ========================================================== 19:48:38 (1786751318) [ 1018.543825] Lustre: Failing over lustre-MDT0000 [ 1018.837970] Lustre: server umount lustre-MDT0000 complete [ 1018.859233] 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 [ 1018.861028] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1018.868415] Lustre: Skipped 1 previous similar message [ 1018.875960] LustreError: 26257:0:(ldlm_lib.c:1192: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. [ 1018.911179] LustreError: 26257:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 23 previous similar messages [ 1023.988346] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1033.202194] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1039.327134] Lustre: 16396:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786751358/real 1786751358] req@ffff97af041dd180 x1873543883862912/t0(0) o400->MGC192.168.203.155@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1786751374 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1039.350948] LustreError: MGC192.168.203.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1046.288754] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1046.318229] Lustre: lustre-MDT0000: reset Object Index mappings [ 1049.587926] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xa115c7389a39c633 [ 1049.613310] Lustre: MGC192.168.203.155@tcp: Connection restored to 0@lo (at 0@lo) [ 1049.626512] Lustre: Skipped 3 previous similar messages [ 1050.008721] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1055.210111] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1055.242948] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1055.299237] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:592 to 0x2c0000401:609) [ 1055.299245] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:592 to 0x280000401:609) [ 1055.376329] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1059.591623] LustreError: 42910:0:(lfsck_engine.c:1018:lfsck_master_engine()) lustre-MDT0000-osd: master engine fail to verify the .lustre/lost+found/, go ahead: rc = -115 [ 1059.610165] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1061.663613] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1061.669530] Lustre: Skipped 1 previous similar message [ 1070.586679] Lustre: Failing over lustre-MDT0000 [ 1070.756364] Lustre: server umount lustre-MDT0000 complete [ 1081.577162] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1086.004313] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1087.007245] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:592 to 0x280000401:641) [ 1087.008415] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:592 to 0x2c0000401:641) [ 1089.533521] Lustre: *** cfs_fail_loc=1505, val=0*** [ 1097.506427] Lustre: DEBUG MARKER: == sanity-lfsck test 5: LFSCK can handle IGIF object upgrading ========================================================== 19:50:31 (1786751431) [ 1100.342178] Lustre: *** cfs_fail_loc=1504, val=0*** [ 1110.545521] Lustre: Failing over lustre-MDT0000 [ 1110.958926] Lustre: server umount lustre-MDT0000 complete [ 1116.381534] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1126.359203] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1128.928312] Lustre: 16395:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786751447/real 1786751447] req@ffff97b02a22ad80 x1873543883959168/t0(0) o400->MGC192.168.203.155@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1786751463 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1137.136869] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1137.157346] Lustre: lustre-MDT0000: reset Object Index mappings [ 1138.415508] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1138.425591] Lustre: Skipped 1 previous similar message [ 1142.251188] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1143.777487] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1143.781761] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1143.783424] Lustre: Skipped 1 previous similar message [ 1143.792079] Lustre: Skipped 8 previous similar messages [ 1143.809534] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1143.817320] Lustre: Skipped 1 previous similar message [ 1143.860693] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:681 to 0x2c0000401:705) [ 1143.861382] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:681 to 0x280000401:705) [ 1145.738847] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1145.746411] Lustre: Skipped 3 previous similar messages [ 1158.059926] Lustre: Failing over lustre-MDT0000 [ 1159.137718] 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 [ 1159.157897] Lustre: Skipped 12 previous similar messages [ 1160.275732] Lustre: server umount lustre-MDT0000 complete [ 1171.336487] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1171.531958] LustreError: MGC192.168.203.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1171.544134] LustreError: Skipped 2 previous similar messages [ 1176.561689] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1177.132043] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:681 to 0x2c0000401:737) [ 1177.138405] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:681 to 0x280000401:737) [ 1179.564923] Lustre: *** cfs_fail_loc=1505, val=0*** [ 1179.569791] Lustre: Skipped 84 previous similar messages [ 1185.290309] Lustre: DEBUG MARKER: == sanity-lfsck test 6a: LFSCK resumes from last checkpoint (1) ========================================================== 19:51:59 (1786751519) [ 1192.778234] Lustre: *** cfs_fail_loc=1600, val=1*** [ 1192.786730] Lustre: Skipped 7 previous similar messages [ 1211.754668] Lustre: DEBUG MARKER: == sanity-lfsck test 6b: LFSCK resumes from last checkpoint (2) ========================================================== 19:52:25 (1786751545) [ 1213.614231] Lustre: 26253:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 1213.626123] Lustre: 26253:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 1300 previous similar messages [ 1213.631601] Lustre: 26253:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 1213.643394] Lustre: 26253:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1300 previous similar messages [ 1213.657462] Lustre: 26253:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 1213.665752] Lustre: 26253:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1300 previous similar messages [ 1213.679153] Lustre: 26253:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 1213.690774] Lustre: 26253:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1300 previous similar messages [ 1213.701738] Lustre: 26253:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 1213.710954] Lustre: 26253:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1300 previous similar messages [ 1213.723728] Lustre: 26253:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 1213.736205] Lustre: 26253:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1300 previous similar messages [ 1220.405707] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1220.412866] Lustre: Skipped 8 previous similar messages [ 1243.704233] Lustre: DEBUG MARKER: == sanity-lfsck test 7a: non-stopped LFSCK should auto restarts after MDS remount (1) ========================================================== 19:52:57 (1786751577) [ 1257.581834] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1257.584634] Lustre: Skipped 12 previous similar messages [ 1263.255185] Lustre: Failing over lustre-MDT0000 [ 1263.457193] Lustre: server umount lustre-MDT0000 complete [ 1264.097339] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1270.995537] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1271.350281] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1271.357776] Lustre: Skipped 4 previous similar messages [ 1271.392168] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1271.399874] Lustre: Skipped 1 previous similar message [ 1275.461785] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1276.392981] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1276.398473] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1276.402555] Lustre: Skipped 1 previous similar message [ 1276.412850] Lustre: Skipped 7 previous similar messages [ 1276.435210] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1276.449823] Lustre: Skipped 1 previous similar message [ 1276.530569] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:854 to 0x2c0000401:897) [ 1276.532276] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:853 to 0x280000401:897) [ 1283.536739] Lustre: DEBUG MARKER: == sanity-lfsck test 7b: non-stopped LFSCK should auto restarts after MDS remount (2) ========================================================== 19:53:37 (1786751617) [ 1296.074683] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing load_modules_local [ 1312.849327] Lustre: 52992:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 1336.382652] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1339.817380] Lustre: 54129:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 1347.590154] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1347.593315] Lustre: Skipped 81 previous similar messages [ 1350.448123] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1351.455138] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1352.479326] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1354.527079] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1354.529611] Lustre: Skipped 1 previous similar message [ 1355.058098] Lustre: Failing over lustre-MDT0000 [ 1355.434269] Lustre: server umount lustre-MDT0000 complete [ 1358.305185] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1358.321747] LustreError: 37074:0:(ldlm_lib.c:1192: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. [ 1358.349679] LustreError: 37074:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 83 previous similar messages [ 1364.749904] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1369.364288] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1370.163941] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:947 to 0x280000401:993) [ 1370.164681] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:946 to 0x2c0000401:961) [ 1378.284396] Lustre: DEBUG MARKER: == sanity-lfsck test 8: LFSCK state machine ============== 19:55:12 (1786751712) [ 1380.320219] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1380.326537] Lustre: Skipped 3 previous similar messages [ 1385.451214] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1385.459602] Lustre: Skipped 3 previous similar messages [ 1386.602461] Lustre: server umount lustre-MDT0000 complete [ 1390.196179] LustreError: 26237:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1786751725 with bad export cookie 11607402660536971425 [ 1390.204877] LustreError: 26237:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 1390.453612] Lustre: server umount lustre-MDT0001 complete [ 1403.252522] Lustre: server umount lustre-OST0000 complete [ 1416.734699] Lustre: server umount lustre-OST0001 complete [ 1424.290075] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_hostid [ 1434.676303] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing load_modules_local [ 1481.318642] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing load_modules_local [ 1491.899303] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1492.237888] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 1492.277648] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 1492.347523] Lustre: lustre-MDT0000: new disk, initializing [ 1492.453948] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 1496.837671] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1508.172433] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1508.310858] Lustre: 59188:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 1508.347362] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 1508.354921] Lustre: Skipped 1 previous similar message [ 1508.470366] Lustre: lustre-MDT0001: new disk, initializing [ 1508.560475] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 1508.564197] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 1512.474654] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1516.915933] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 1522.772962] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 1522.940501] Lustre: lustre-OST0000: new disk, initializing [ 1522.943717] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 1522.947106] Lustre: 60818:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 1524.458463] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 1524.474858] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 1524.524668] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 1528.541661] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1537.558608] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 1537.661185] Lustre: lustre-OST0001: new disk, initializing [ 1537.663927] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 1537.668116] Lustre: 61689:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 1539.154134] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 1539.170485] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 1539.276372] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 1543.585389] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1551.534432] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1554.960649] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 1564.826432] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1565.691246] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1565.693350] Lustre: Skipped 19 previous similar messages [ 1569.001547] Lustre: *** cfs_fail_loc=1601, val=2*** [ 1569.011219] Lustre: Skipped 5 previous similar messages [ 1584.493271] Lustre: Failing over lustre-MDT0000 [ 1585.632671] 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 [ 1585.648666] Lustre: Skipped 14 previous similar messages [ 1585.652626] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1585.659118] LustreError: Skipped 1 previous similar message [ 1586.708404] Lustre: server umount lustre-MDT0000 complete [ 1595.247367] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1595.369106] LustreError: MGC192.168.203.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1595.382258] LustreError: Skipped 3 previous similar messages [ 1595.651749] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1595.661758] Lustre: Skipped 1 previous similar message [ 1600.043976] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1600.997454] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1600.998575] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1601.003577] Lustre: Skipped 7 previous similar messages [ 1601.020792] Lustre: Skipped 1 previous similar message [ 1601.043464] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1601.054043] Lustre: Skipped 1 previous similar message [ 1601.087178] Lustre: *** cfs_fail_loc=160b, val=2*** [ 1601.097576] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:65) [ 1601.108386] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:65) [ 1608.786903] Lustre: Failing over lustre-MDT0000 [ 1609.105032] Lustre: server umount lustre-MDT0000 complete [ 1620.062142] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1624.573734] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1625.647732] Lustre: *** cfs_fail_loc=160b, val=2*** [ 1625.654933] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:97) [ 1625.654983] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:97) [ 1630.475230] Lustre: Failing over lustre-MDT0000 [ 1630.844563] Lustre: server umount lustre-MDT0000 complete [ 1638.894610] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1644.416527] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1644.613465] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:129) [ 1644.615467] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:129) [ 1649.768870] Lustre: *** cfs_fail_loc=1602, val=2*** [ 1661.488797] Lustre: DEBUG MARKER: == sanity-lfsck test 9a: LFSCK speed control (1) ========= 19:59:55 (1786751995) [ 1675.228367] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing load_modules_local [ 1690.151260] Lustre: 68641:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 1711.556403] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1714.881266] Lustre: 69776:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 1726.712248] Lustre: 59192:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 252 < left 278, rollback = 2 [ 1726.725049] Lustre: 59192:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 2374 previous similar messages [ 1726.745653] Lustre: 59192:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 1726.755981] Lustre: 59192:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 2374 previous similar messages [ 1726.769594] Lustre: 59192:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 1726.774466] Lustre: 59192:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 2374 previous similar messages [ 1726.790071] Lustre: 59192:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/1, punch: 0/0/0, quota 1/3/2 [ 1726.801353] Lustre: 59192:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 2374 previous similar messages [ 1726.816588] Lustre: 59192:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/1, delete: 0/0/0 [ 1726.824080] Lustre: 59192:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 2374 previous similar messages [ 1726.832558] Lustre: 59192:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 1726.839615] Lustre: 59192:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 2374 previous similar messages [ 1829.940444] Lustre: DEBUG MARKER: == sanity-lfsck test 9b: LFSCK speed control (2) ========= 20:02:44 (1786752164) [ 1881.147041] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1881.153368] Lustre: Skipped 4 previous similar messages [ 1904.034055] Lustre: *** cfs_fail_loc=160c, val=0*** [ 1904.039448] Lustre: Skipped 7 previous similar messages [ 1938.431754] Lustre: DEBUG MARKER: == sanity-lfsck test 10: System is available during LFSCK scanning ========================================================== 20:04:32 (1786752272) [ 1990.011688] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1998.044135] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1998.046024] Lustre: Skipped 386 previous similar messages [ 2014.046536] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2014.057055] Lustre: Skipped 812 previous similar messages [ 2046.068808] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2046.071880] Lustre: Skipped 1363 previous similar messages [ 2066.345348] Lustre: *** cfs_fail_loc=1604, val=0*** [ 2066.350892] Lustre: Skipped 2599 previous similar messages [ 2306.476634] Lustre: DEBUG MARKER: == sanity-lfsck test 11a: LFSCK can rebuild lost last_id ========================================================== 20:10:40 (1786752640) [ 2395.630326] Lustre: 59192:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 320, rollback = 2 [ 2395.645241] Lustre: 59192:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 36825 previous similar messages [ 2395.652946] Lustre: 59192:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 1/4/0 [ 2395.660040] Lustre: 59192:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 36825 previous similar messages [ 2395.666085] Lustre: 59192:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 5/5/0, xattr_set: 7/320/0 [ 2395.673944] Lustre: 59192:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 36825 previous similar messages [ 2395.679266] Lustre: 59192:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 6/46/0, punch: 0/0/0, quota 1/3/0 [ 2395.684020] Lustre: 59192:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 36825 previous similar messages [ 2395.689666] Lustre: 59192:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 2/5/0 [ 2395.695926] Lustre: 59192:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 36825 previous similar messages [ 2395.701221] Lustre: 59192:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 1/1/0, ref_del: 2/2/1 [ 2395.706922] Lustre: 59192:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 36825 previous similar messages [ 2468.834374] 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 [ 2468.839951] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2468.852945] Lustre: Skipped 11 previous similar messages [ 2471.234203] Lustre: server umount lustre-MDT0000 complete [ 2473.956170] LustreError: 70218:0:(ldlm_lib.c:1192: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. [ 2473.972357] LustreError: 70218:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 31 previous similar messages [ 2475.423853] LustreError: 71456:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1786752810 with bad export cookie 11607402660536990528 [ 2475.426482] LustreError: MGC192.168.203.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2475.438256] LustreError: 71456:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 2475.461712] LustreError: Skipped 2 previous similar messages [ 2475.998183] Lustre: server umount lustre-MDT0001 complete [ 2490.787297] Lustre: server umount lustre-OST0000 complete [ 2504.771931] Lustre: server umount lustre-OST0001 complete [ 2512.927450] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: (null) [ 2520.734632] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 2536.287601] LustreError: Failed to get MGS log lustre-sptlrpc and no local copy. [ 2541.408428] LustreError: 75039:0:(mgc_request.c:233:do_config_log_add()) MGC192.168.203.155@tcp: failed processing log, type 4: rc = -110 [ 2567.071204] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 2567.080836] Lustre: Skipped 8 previous similar messages [ 2572.250125] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2575.499036] Lustre: 75621:0:(ofd_dev.c:561:ofd_lfsck_out_notify()) lustre-OST0000: Found crashed LAST_ID, deny creating new OST-object on the device until the LAST_ID rebuilt successfully. [ 2575.524790] Lustre: *** cfs_fail_loc=160e, val=3*** [ 2578.593716] Lustre: 75621:0:(ofd_dev.c:573:ofd_lfsck_out_notify()) lustre-OST0000: Rebuilt crashed LAST_ID files successfully. [ 2586.321468] Lustre: DEBUG MARKER: == sanity-lfsck test 11b: LFSCK can rebuild crashed last_id ========================================================== 20:15:20 (1786752920) [ 2599.289729] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing load_modules_local [ 2607.228770] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2607.593907] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3271 to 0x280000401:3297) [ 2611.030392] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2617.941995] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2621.720534] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2624.060573] Lustre: 78286:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 2638.061345] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2638.187575] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 2638.192718] Lustre: Skipped 2 previous similar messages [ 2643.438391] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3208 to 0x2c0000401:3233) [ 2643.815476] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2650.532789] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 2653.591243] Lustre: 79784:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 2657.733830] Lustre: *** cfs_fail_loc=160d, val=0*** [ 2658.261123] Lustre: *** cfs_fail_loc=160d, val=0*** [ 2658.263213] Lustre: Skipped 3 previous similar messages [ 2664.671554] Lustre: Failing over lustre-OST0000 [ 2664.760829] Lustre: server umount lustre-OST0000 complete [ 2669.024969] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 2669.037707] LustreError: Skipped 2 previous similar messages [ 2673.175762] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2673.455466] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 2673.475382] Lustre: Skipped 2 previous similar messages [ 2674.850551] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 2674.868478] Lustre: Skipped 2 previous similar messages [ 2674.912481] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 2674.920399] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 2674.920928] Lustre: *** cfs_fail_loc=215, val=0*** [ 2674.925079] Lustre: Skipped 2 previous similar messages [ 2674.947029] Lustre: Skipped 11 previous similar messages [ 2679.409472] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2680.287440] Lustre: *** cfs_fail_loc=215, val=0*** [ 2680.294761] Lustre: Skipped 2 previous similar messages [ 2682.447920] Lustre: 81183:0:(ofd_dev.c:561:ofd_lfsck_out_notify()) lustre-OST0000: Found crashed LAST_ID, deny creating new OST-object on the device until the LAST_ID rebuilt successfully. [ 2682.468612] Lustre: 81183:0:(ofd_dev.c:573:ofd_lfsck_out_notify()) lustre-OST0000: Rebuilt crashed LAST_ID files successfully. [ 2684.701567] Lustre: Failing over lustre-OST0000 [ 2684.821977] Lustre: server umount lustre-OST0000 complete [ 2692.859816] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2694.224267] Lustre: *** cfs_fail_loc=215, val=0*** [ 2694.237682] Lustre: Skipped 2 previous similar messages [ 2699.748626] Lustre: *** cfs_fail_loc=215, val=0*** [ 2699.756038] Lustre: Skipped 1 previous similar message [ 2699.794849] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2705.381469] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 2705.392512] LustreError: Skipped 2 previous similar messages [ 2705.406893] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2705.418096] Lustre: Skipped 3 previous similar messages [ 2708.450759] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2708.458669] Lustre: Skipped 3 previous similar messages [ 2713.568503] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2718.689125] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2718.692623] Lustre: Skipped 6 previous similar messages [ 2719.199404] Lustre: lustre-MDT0000 is waiting for obd_unlinked_exports more than 8 seconds. The obd refcount = 3. Is it stuck? [ 2719.587236] Lustre: server umount lustre-MDT0000 complete [ 2723.319210] LustreError: 75047:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1786753058 with bad export cookie 11607402660538565906 [ 2723.338478] LustreError: 75047:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 2723.790438] Lustre: server umount lustre-MDT0001 complete [ 2737.873110] Lustre: server umount lustre-OST0000 complete [ 2739.167193] Lustre: 16395:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786753058/real 1786753058] req@ffff97b007110000 x1873543888182400/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786753074 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2741.754577] Lustre: server umount lustre-OST0001 complete [ 2750.845278] Lustre: DEBUG MARKER: == sanity-lfsck test 12a: single command to trigger LFSCK on all devices ========================================================== 20:18:04 (1786753084) [ 2765.063202] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing load_modules_local [ 2775.252788] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2775.769429] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 2775.780207] Lustre: Skipped 2 previous similar messages [ 2780.014858] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2789.039969] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2794.259755] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2796.974455] Lustre: 85566:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 2803.674470] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2809.580093] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2818.211602] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2820.466698] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3208 to 0x2c0000401:3265) [ 2820.484702] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3362 to 0x280000401:3393) [ 2824.380637] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2831.055293] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 2834.073922] Lustre: 87436:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 2862.461688] Lustre: DEBUG MARKER: == sanity-lfsck test 12b: auto detect Lustre device ====== 20:19:56 (1786753196) [ 2875.061519] Lustre: DEBUG MARKER: == sanity-lfsck test 13: LFSCK can repair crashed lmm_oi ========================================================== 20:20:09 (1786753209) [ 2876.150693] Lustre: *** cfs_fail_loc=160f, val=0*** [ 2885.488306] Lustre: DEBUG MARKER: == sanity-lfsck test 14a: LFSCK can repair MDT-object with dangling LOV EA reference (1) ========================================================== 20:20:19 (1786753219) [ 2888.675416] Lustre: *** cfs_fail_loc=1610, val=0*** [ 2888.681687] Lustre: Skipped 3 previous similar messages [ 2937.828598] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 2937.852187] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2941.662688] Lustre: server umount lustre-MDT0000 complete [ 2945.723162] LustreError: 84407:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1786753280 with bad export cookie 11607402660538574425 [ 2945.738148] LustreError: 84407:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 2946.058728] Lustre: server umount lustre-MDT0001 complete [ 2960.530398] Lustre: server umount lustre-OST0000 complete [ 2974.622515] Lustre: server umount lustre-OST0001 complete [ 2990.289615] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing load_modules_local [ 3002.086945] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3007.061866] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3016.385175] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3021.699745] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3024.771607] Lustre: 93301:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3031.337513] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3037.498667] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3041.909864] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:116 to 0x280000400:161) [ 3045.501922] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3045.674862] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 3045.679509] Lustre: Skipped 6 previous similar messages [ 3047.731285] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:116 to 0x2c0000400:161) [ 3047.815832] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3554 to 0x280000401:3585) [ 3047.816834] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3317 to 0x2c0000401:3361) [ 3051.750809] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3058.787107] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3062.112262] Lustre: 95170:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 3067.970819] Lustre: DEBUG MARKER: == sanity-lfsck test 14b: LFSCK can repair MDT-object with dangling LOV EA reference (2) ========================================================== 20:23:22 (1786753402) [ 3069.810389] Lustre: 92157:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 256 < left 278, rollback = 2 [ 3069.817381] Lustre: 92157:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 1361 previous similar messages [ 3069.821488] Lustre: 92157:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 3069.829421] Lustre: 92157:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1361 previous similar messages [ 3069.838399] Lustre: 92157:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3069.844400] Lustre: 92157:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1361 previous similar messages [ 3069.851678] Lustre: 92157:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 3069.860942] Lustre: 92157:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1361 previous similar messages [ 3069.874462] Lustre: 92157:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 3069.882715] Lustre: 92157:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1361 previous similar messages [ 3069.895170] Lustre: 92157:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3069.908046] Lustre: 92157:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1361 previous similar messages [ 3073.058210] Lustre: *** cfs_fail_loc=1610, val=0*** [ 3073.062392] Lustre: Skipped 63 previous similar messages [ 3093.985711] 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 [ 3093.986059] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3093.990157] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3094.004801] Lustre: Skipped 17 previous similar messages [ 3094.016846] Lustre: Skipped 5 previous similar messages [ 3099.381321] Lustre: server umount lustre-MDT0000 complete [ 3102.722593] LustreError: 96036:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1786753437 with bad export cookie 11607402660538602852 [ 3102.729146] LustreError: MGC192.168.203.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3102.735134] LustreError: 96036:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 3102.758447] LustreError: Skipped 2 previous similar messages [ 3103.127465] Lustre: server umount lustre-MDT0001 complete [ 3117.697675] Lustre: server umount lustre-OST0000 complete [ 3120.608698] Lustre: 16394:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786753439/real 1786753439] req@ffff97b004a99f80 x1873543888522112/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786753455 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3121.954572] Lustre: server umount lustre-OST0001 complete [ 3141.984212] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing load_modules_local [ 3152.996313] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3153.307609] LustreError: 98065:0:(ldlm_lib.c:1192: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. [ 3153.325803] LustreError: 98065:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 36 previous similar messages [ 3158.400245] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3167.092697] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3171.390860] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3173.906818] Lustre: 99206:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3179.809586] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3185.049800] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3192.312989] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:116 to 0x280000400:193) [ 3193.284070] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3198.442576] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:116 to 0x2c0000400:193) [ 3199.484655] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3682 to 0x280000401:3713) [ 3199.500581] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3317 to 0x2c0000401:3393) [ 3199.848491] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3206.851833] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3216.457214] Lustre: DEBUG MARKER: == sanity-lfsck test 15a: LFSCK can repair unmatched MDT-object/OST-object pairs (1) ========================================================== 20:25:50 (1786753550) [ 3220.804808] Lustre: *** cfs_fail_loc=1611, val=0*** [ 3220.809612] Lustre: Skipped 63 previous similar messages [ 3221.242685] Lustre: *** cfs_fail_loc=1611, val=0*** [ 3231.171564] Lustre: DEBUG MARKER: == sanity-lfsck test 15b: LFSCK can repair unmatched MDT-object/OST-object pairs (2) ========================================================== 20:26:05 (1786753565) [ 3233.386331] Lustre: *** cfs_fail_loc=1612, val=0*** [ 3233.390227] Lustre: Skipped 1 previous similar message [ 3233.472271] Lustre: *** cfs_fail_loc=1612, val=0*** [ 3233.479916] Lustre: Skipped 2 previous similar messages [ 3242.973947] Lustre: DEBUG MARKER: == sanity-lfsck test 15c: LFSCK can repair unmatched MDT-object/OST-object pairs (3) ========================================================== 20:26:17 (1786753577) [ 3244.442396] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_15c MDS newer than 2.7.55, LU-6475 [ 3246.314876] Lustre: DEBUG MARKER: == sanity-lfsck test 15d: LFSCK don't crash upon dir migration failure ========================================================== 20:26:20 (1786753580) [ 3252.792964] Lustre: *** cfs_fail_loc=1709, val=0*** [ 3252.797833] LustreError: 98073:0:(osp_object.c:618:osp_attr_get()) lustre-MDT0000-osp-MDT0001: osp_attr_get update error [0x200003ab2:0x1:0x0]: rc = -5 [ 3252.807835] LustreError: 98073:0:(mdt_reint.c:2644:mdt_reint_migrate()) lustre-MDT0001: migrate [0x240002340:0x6c:0x0]/s6 failed: rc = -5 [ 3321.317328] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3321.334334] Lustre: Skipped 6 previous similar messages [ 3326.664815] Lustre: server umount lustre-MDT0000 complete [ 3335.432455] LustreError: 98046:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1786753670 with bad export cookie 11607402660538617587 [ 3335.458470] LustreError: 98046:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 3335.819587] Lustre: server umount lustre-MDT0001 complete [ 3353.256047] Lustre: 16393:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786753672/real 1786753672] req@ffff97af0361f100 x1873543889154816/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786753688 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3354.526929] Lustre: server umount lustre-OST0000 complete [ 3356.647540] Lustre: 16395:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786753675/real 1786753675] req@ffff97b03c765c00 x1873543889155072/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786753691 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3360.799350] Lustre: 16395:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786753679/real 1786753679] req@ffff97b03c777b80 x1873543889155584/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786753695 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3360.818142] Lustre: 16395:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 3362.773315] Lustre: server umount lustre-OST0001 complete [ 3379.343061] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing unload_modules_local [ 3382.736602] Key type lgssc unregistered [ 3383.083587] LNet: 104914:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 3383.092844] LNetError: 104914:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 3383.120197] LNet: Removed LNI 192.168.203.155@tcp [ 3384.042925] Key type .llcrypt unregistered [ 3384.049298] Key type ._llcrypt unregistered [ 3407.347561] Key type ._llcrypt registered [ 3407.351820] Key type .llcrypt registered [ 3407.438900] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_hostid [ 3419.010996] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing load_modules_local [ 3420.147239] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 3420.174575] alg: No test for adler32 (adler32-zlib) [ 3421.267465] Lustre: Lustre: Build Version: 2.17.57_4_gb324e6e [ 3421.545765] LNet: Added LNI 192.168.203.155@tcp [8/256/0/180] [ 3423.360563] Key type lgssc registered [ 3424.683204] Lustre: Echo OBD driver; http://www.lustre.org/ [ 3470.592670] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing load_modules_local [ 3482.164818] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 3482.180299] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3483.411801] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 3483.434125] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 3483.505174] Lustre: lustre-MDT0000: new disk, initializing [ 3483.630929] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3483.661599] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 3487.546994] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3499.636975] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3499.716407] Lustre: 109350:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 3499.738355] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 3499.742245] Lustre: Skipped 1 previous similar message [ 3499.814947] Lustre: lustre-MDT0001: new disk, initializing [ 3499.882677] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 3499.911833] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 3499.921109] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 3503.707135] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3508.040817] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 3516.857631] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3517.072919] Lustre: lustre-OST0000: new disk, initializing [ 3517.076613] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 3517.087853] Lustre: 111288:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 3517.159659] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 3521.556511] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 3521.570179] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 3521.664292] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 3523.170683] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3534.845487] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3534.960513] Lustre: lustre-OST0001: new disk, initializing [ 3534.967292] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 3534.974577] Lustre: 112310:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 3535.036880] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 3540.752532] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3545.174777] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 3545.188436] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 3545.234968] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 3552.530350] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3564.164988] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 3569.874955] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 20:31:43 (1786753903) === [ 3575.912465] Lustre: DEBUG MARKER: == sanity-lfsck test 16: LFSCK can repair inconsistent MDT-object/OST-object owner ========================================================== 20:31:50 (1786753910) [ 3576.422289] Lustre: 112878:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 251 < left 278, rollback = 2 [ 3576.437834] Lustre: 112878:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 3576.456975] Lustre: 112878:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3576.470648] Lustre: 112878:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 3576.484514] Lustre: 112878:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 3576.500432] Lustre: 112878:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3576.994294] Lustre: 112318:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 3577.018780] Lustre: 112318:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 6 previous similar messages [ 3577.024940] Lustre: 112318:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 3577.034917] Lustre: 112318:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 6 previous similar messages [ 3577.046868] Lustre: 112318:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3577.060941] Lustre: 112318:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 6 previous similar messages [ 3577.064800] Lustre: 112318:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 3577.069518] Lustre: 112318:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 6 previous similar messages [ 3577.075620] Lustre: 112318:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 3577.081557] Lustre: 112318:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 6 previous similar messages [ 3577.099206] Lustre: 112318:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3577.116254] Lustre: 112318:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 6 previous similar messages [ 3578.003524] Lustre: 109357:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 3578.019827] Lustre: 109357:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 119 previous similar messages [ 3578.027476] Lustre: 109357:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 3578.033809] Lustre: 109357:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 119 previous similar messages [ 3578.065464] Lustre: 112318:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3578.071607] Lustre: 112318:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 122 previous similar messages [ 3578.077220] Lustre: 112318:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 7/369/0 [ 3578.084976] Lustre: 112318:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 122 previous similar messages [ 3578.099572] Lustre: 112318:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 3578.113408] Lustre: 112318:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 122 previous similar messages [ 3578.126913] Lustre: 112318:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3578.133963] Lustre: 112318:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 122 previous similar messages [ 3580.062504] Lustre: *** cfs_fail_loc=1613, val=0*** [ 3590.070542] Lustre: DEBUG MARKER: == sanity-lfsck test 17: LFSCK can repair multiple references ========================================================== 20:32:04 (1786753924) [ 3591.238925] Lustre: 109358:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 253 < left 278, rollback = 2 [ 3591.254060] Lustre: 109358:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 182 previous similar messages [ 3591.259601] Lustre: 109358:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 3591.266797] Lustre: 109358:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 182 previous similar messages [ 3591.277417] Lustre: 109358:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3591.285477] Lustre: 109358:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 179 previous similar messages [ 3591.291068] Lustre: 109358:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/1 [ 3591.294782] Lustre: 109358:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 179 previous similar messages [ 3591.298938] Lustre: 109358:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 3591.304473] Lustre: 109358:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 179 previous similar messages [ 3591.309406] Lustre: 109358:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3591.317757] Lustre: 109358:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 179 previous similar messages [ 3592.238462] Lustre: *** cfs_fail_loc=1614, val=0*** [ 3596.463427] Lustre: 111279:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 259 < left 275, rollback = 2 [ 3596.471065] Lustre: 111279:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 11 previous similar messages [ 3596.477646] Lustre: 111279:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 3596.483978] Lustre: 111279:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3596.488971] Lustre: 111279:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/1, xattr_set: 3/275/0 [ 3596.494162] Lustre: 111279:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3596.499609] Lustre: 111279:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/9/0, punch: 1/4/0, quota 7/225/0 [ 3596.521784] Lustre: 111279:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3596.534230] Lustre: 111279:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 3596.539433] Lustre: 111279:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3596.545688] Lustre: 111279:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3596.551812] Lustre: 111279:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3603.938759] Lustre: DEBUG MARKER: == sanity-lfsck test 18a: Find out orphan OST-object and repair it (1) ========================================================== 20:32:17 (1786753937) [ 3604.534365] Lustre: 109358:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 3604.548822] Lustre: 109358:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 4 previous similar messages [ 3604.563211] Lustre: 109358:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 3604.569772] Lustre: 109358:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 4 previous similar messages [ 3604.582347] Lustre: 109358:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3604.587520] Lustre: 109358:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 4 previous similar messages [ 3604.593356] Lustre: 109358:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 3604.603431] Lustre: 109358:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 4 previous similar messages [ 3604.608569] Lustre: 109358:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 3604.614341] Lustre: 109358:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 4 previous similar messages [ 3604.623912] Lustre: 109358:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3604.629452] Lustre: 109358:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 4 previous similar messages [ 3607.033438] Lustre: *** cfs_fail_loc=1615, val=0*** [ 3607.043310] Lustre: Skipped 1 previous similar message [ 3608.161198] Lustre: *** cfs_fail_loc=1615, val=0*** [ 3608.163273] Lustre: Skipped 1 previous similar message [ 3626.158404] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_18b skipping excluded test 18b [ 3628.100862] Lustre: DEBUG MARKER: == sanity-lfsck test 18c: Find out orphan OST-object and repair it (3) ========================================================== 20:32:42 (1786753962) [ 3628.502890] Lustre: 109357:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 3628.517935] Lustre: 109357:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 18 previous similar messages [ 3628.522524] Lustre: 109357:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 3628.527569] Lustre: 109357:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 18 previous similar messages [ 3628.532263] Lustre: 109357:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3628.536981] Lustre: 109357:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 18 previous similar messages [ 3628.541328] Lustre: 109357:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 3628.545961] Lustre: 109357:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 18 previous similar messages [ 3628.550568] Lustre: 109357:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 3628.555247] Lustre: 109357:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 18 previous similar messages [ 3628.561876] Lustre: 109357:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3628.567263] Lustre: 109357:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 18 previous similar messages [ 3631.343232] Lustre: *** cfs_fail_loc=1617, val=0*** [ 3631.438569] Lustre: *** cfs_fail_loc=1617, val=0*** [ 3634.161100] Lustre: *** cfs_fail_loc=1616, val=0*** [ 3634.170513] Lustre: Skipped 3 previous similar messages [ 3653.919171] Lustre: DEBUG MARKER: == sanity-lfsck test 18d: Find out orphan OST-object and repair it (4) ========================================================== 20:33:07 (1786753987) [ 3656.933472] Lustre: *** cfs_fail_loc=1618, val=0*** [ 3656.937752] Lustre: Skipped 5 previous similar messages [ 3694.050821] 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 [ 3694.056820] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3694.065933] Lustre: Skipped 3 previous similar messages [ 3694.084456] Lustre: Skipped 3 previous similar messages [ 3696.857529] Lustre: server umount lustre-MDT0000 complete [ 3700.893412] LustreError: 109344:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1786754035 with bad export cookie 5547759022737784862 [ 3700.900514] LustreError: MGC192.168.203.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3700.903771] LustreError: 109344:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 3701.356414] Lustre: server umount lustre-MDT0001 complete [ 3715.596840] Lustre: server umount lustre-OST0000 complete [ 3728.337978] Lustre: server umount lustre-OST0001 complete [ 3745.350586] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing load_modules_local [ 3754.786707] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3755.348709] LustreError: 118027:0:(ldlm_lib.c:1192: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. [ 3755.376445] LustreError: 118027:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 5 previous similar messages [ 3755.440697] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3760.149409] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3760.613871] LustreError: 118028:0:(ldlm_lib.c:1192: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. [ 3765.739911] LustreError: 118027:0:(ldlm_lib.c:1192: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. [ 3770.209642] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3770.830711] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 3775.435494] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3778.462257] Lustre: 119168:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3785.116211] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3791.227893] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3795.683227] LustreError: 119521:0:(ldlm_lib.c:1192: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. [ 3795.704929] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:4 to 0x280000400:33) [ 3798.542343] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3798.684971] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 3798.690795] Lustre: Skipped 1 previous similar message [ 3800.751588] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:116 to 0x280000401:161) [ 3800.756757] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:33) [ 3800.779696] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:4 to 0x2c0000401:33) [ 3804.751727] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3812.126738] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3815.613977] Lustre: 121038:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 3830.038787] Lustre: DEBUG MARKER: == sanity-lfsck test 18e: Find out orphan OST-object and repair it (5) ========================================================== 20:36:03 (1786754163) [ 3830.428478] Lustre: 119039:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 252 < left 278, rollback = 2 [ 3830.441349] Lustre: 119039:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 46 previous similar messages [ 3830.447226] Lustre: 119039:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 3830.459469] Lustre: 119039:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 3830.468917] Lustre: 119039:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3830.479648] Lustre: 119039:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 3830.489737] Lustre: 119039:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/1 [ 3830.499693] Lustre: 119039:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 3830.506518] Lustre: 119039:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 3830.516566] Lustre: 119039:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 3830.526443] Lustre: 119039:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3830.534987] Lustre: 119039:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 3832.489980] Lustre: *** cfs_fail_loc=1618, val=0*** [ 3832.496399] Lustre: Skipped 3 previous similar messages [ 3867.641473] 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 [ 3867.654297] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3867.666943] Lustre: Skipped 3 previous similar messages [ 3867.690544] Lustre: Skipped 3 previous similar messages [ 3872.266917] Lustre: server umount lustre-MDT0000 complete [ 3872.739548] LustreError: 118023:0:(ldlm_lib.c:1192: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. [ 3872.758159] LustreError: 118023:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 3 previous similar messages [ 3876.081050] LustreError: 119170:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1786754211 with bad export cookie 5547759022737800101 [ 3876.093192] LustreError: MGC192.168.203.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3876.094131] LustreError: 119170:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 3876.343955] Lustre: server umount lustre-MDT0001 complete [ 3890.715278] Lustre: server umount lustre-OST0000 complete [ 3894.048234] Lustre: 106507:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786754212/real 1786754212] req@ffff97af0b49b100 x1873547106732160/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786754228 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3894.082038] 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 [ 3894.612131] Lustre: server umount lustre-OST0001 complete [ 3911.847833] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing load_modules_local [ 3923.056043] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3923.414564] LustreError: 123607:0:(ldlm_lib.c:1192: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. [ 3923.521494] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3928.035311] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3936.669589] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3941.491077] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3944.241358] Lustre: 124747:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3951.210397] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3958.599240] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3961.769322] LustreError: 125101:0:(ldlm_lib.c:1192: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. [ 3961.784292] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:4 to 0x280000400:65) [ 3961.787653] LustreError: 125101:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 2 previous similar messages [ 3967.129315] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3968.380630] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:166 to 0x280000401:193) [ 3968.385985] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:65) [ 3968.401477] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:4 to 0x2c0000401:65) [ 3972.995463] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3981.414469] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3985.118157] Lustre: 126617:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 3991.268202] Lustre: 126384:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 252 < left 260, rollback = 2 [ 3991.275787] Lustre: 126384:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 21 previous similar messages [ 3991.280657] Lustre: 126384:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 3991.284520] Lustre: 126384:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3991.288977] Lustre: 126384:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 0/0/0, xattr_set: 1/260/0 [ 3991.293191] Lustre: 126384:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3991.297698] Lustre: 126384:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/9/0, punch: 0/0/0, quota 4/150/2 [ 3991.302548] Lustre: 126384:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3991.307491] Lustre: 126384:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 1/17/2, delete: 0/0/0 [ 3991.311978] Lustre: 126384:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3991.316248] Lustre: 126384:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3991.320520] Lustre: 126384:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3991.368188] Lustre: *** cfs_fail_loc=1602, val=10*** [ 3991.371921] Lustre: Skipped 1 previous similar message [ 4016.815730] Lustre: DEBUG MARKER: == sanity-lfsck test 18f: Skip the failed OST(s) when handle orphan OST-objects ========================================================== 20:39:10 (1786754350) [ 4020.342396] Lustre: *** cfs_fail_loc=1616, val=0*** [ 4020.349973] Lustre: Skipped 3 previous similar messages [ 4028.638578] Lustre: *** cfs_fail_loc=161c, val=0*** [ 4028.644310] Lustre: Skipped 1 previous similar message [ 4050.351801] Lustre: DEBUG MARKER: == sanity-lfsck test 18g: Find out orphan OST-object and repair it (7) ========================================================== 20:39:44 (1786754384) [ 4052.591224] Lustre: *** cfs_fail_loc=162e, val=0*** [ 4052.593314] Lustre: *** cfs_fail_loc=162e, val=0*** [ 4052.598634] Lustre: Skipped 7 previous similar messages [ 4065.829969] Lustre: DEBUG MARKER: == sanity-lfsck test 18h: LFSCK can repair crashed PFL extent range ========================================================== 20:39:59 (1786754399) [ 4085.265905] Lustre: DEBUG MARKER: == sanity-lfsck test 19a: OST-object inconsistency self detect ========================================================== 20:40:19 (1786754419) [ 4097.658512] Lustre: DEBUG MARKER: == sanity-lfsck test 19b: OST-object inconsistency self repair ========================================================== 20:40:31 (1786754431) [ 4100.667864] Lustre: *** cfs_fail_loc=1611, val=0*** [ 4100.716706] Lustre: *** cfs_fail_loc=1611, val=0*** [ 4100.722555] Lustre: Skipped 3 previous similar messages [ 4105.816740] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.203.55@tcp inode [0x2000013a1:0x1f:0x0] object 0x280000401:203 extent [0-4095], client returned csum 0 (type 4), server csum 703fb3ad (type 4) [ 4106.904913] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.203.55@tcp inode [0x2000013a1:0x20:0x0] object 0x280000401:204 extent [0-4095], client returned csum 0 (type 4), server csum 7cbb935c (type 4) [ 4114.773517] Lustre: DEBUG MARKER: == sanity-lfsck test 20a: Handle the orphan with dummy LOV EA slot properly ========================================================== 20:40:48 (1786754448) [ 4117.874384] Lustre: *** cfs_fail_loc=1616, val=0*** [ 4117.877267] Lustre: Skipped 3 previous similar messages [ 4125.197902] Lustre: 131126:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 253 < left 263, rollback = 2 [ 4125.212664] Lustre: 131126:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 125 previous similar messages [ 4125.218074] Lustre: 131126:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4125.222638] Lustre: 131126:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 125 previous similar messages [ 4125.227711] Lustre: 131126:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 0/0/0, xattr_set: 2/263/0 [ 4125.232334] Lustre: 131126:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 125 previous similar messages [ 4125.236411] Lustre: 131126:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 0/0/0, punch: 0/0/0, quota 1/3/2 [ 4125.240857] Lustre: 131126:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 125 previous similar messages [ 4125.245803] Lustre: 131126:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/1, delete: 0/0/0 [ 4125.250641] Lustre: 131126:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 125 previous similar messages [ 4125.255493] Lustre: 131126:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 4125.262802] Lustre: 131126:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 125 previous similar messages [ 4142.595914] Lustre: DEBUG MARKER: == sanity-lfsck test 20b: Handle the orphan with dummy LOV EA slot properly - PFL case ========================================================== 20:41:15 (1786754475) [ 4151.551079] Lustre: DEBUG MARKER: == sanity-lfsck test 21: run all LFSCK components by default ========================================================== 20:41:25 (1786754485) [ 4164.680301] Lustre: DEBUG MARKER: == sanity-lfsck test 22a: LFSCK can repair unmatched pairs (1) ========================================================== 20:41:38 (1786754498) [ 4167.348372] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4167.354077] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4167.357272] Lustre: Skipped 1 previous similar message [ 4180.023680] Lustre: DEBUG MARKER: == sanity-lfsck test 22b: LFSCK can repair unmatched pairs (2) ========================================================== 20:41:53 (1786754513) [ 4181.633246] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4181.640111] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4192.262150] Lustre: DEBUG MARKER: == sanity-lfsck test 23a: LFSCK can repair dangling name entry (1) ========================================================== 20:42:06 (1786754526) [ 4193.944720] Lustre: *** cfs_fail_loc=1620, val=0*** [ 4208.286782] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_23b skipping excluded test 23b [ 4209.897816] Lustre: DEBUG MARKER: == sanity-lfsck test 23c: LFSCK can repair dangling name entry (3) ========================================================== 20:42:24 (1786754544) [ 4215.357486] Lustre: *** cfs_fail_loc=1621, val=127*** [ 4215.359574] Lustre: Skipped 1 previous similar message [ 4218.458408] Lustre: *** cfs_fail_loc=1602, val=10*** [ 4239.514259] Lustre: DEBUG MARKER: == sanity-lfsck test 23d: LFSCK can repair a dangling name entry to a remote object ========================================================== 20:42:53 (1786754573) [ 4241.683492] Lustre: Failing over lustre-MDT0000 [ 4242.008963] Lustre: server umount lustre-MDT0000 complete [ 4242.657709] LustreError: 125121:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.203.55@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4242.681619] LustreError: 125121:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 1 previous similar message [ 4242.916908] 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 [ 4252.289110] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4252.489910] LustreError: MGC192.168.203.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4252.817893] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4252.832995] Lustre: Skipped 3 previous similar messages [ 4252.883415] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4254.282767] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4257.512936] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4258.296733] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4258.341618] Lustre: lustre-MDT0000: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 4258.398309] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:130 to 0x2c0000401:161) [ 4258.399701] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:265 to 0x280000401:289) [ 4259.861812] LustreError: 123603:0:(mdt_open.c:1324:mdt_cross_open()) lustre-MDT0000: [0x2000013a3:0x82:0x0] doesn't exist!: rc = -14 [ 4271.591070] Lustre: DEBUG MARKER: == sanity-lfsck test 24: LFSCK can repair multiple-referenced name entry ========================================================== 20:43:25 (1786754605) [ 4273.766885] Lustre: *** cfs_fail_loc=1622, val=0*** [ 4273.915373] Lustre: *** cfs_fail_loc=1622, val=0*** [ 4273.920463] Lustre: Skipped 1 previous similar message [ 4286.183210] Lustre: DEBUG MARKER: == sanity-lfsck test 25: LFSCK can repair bad file type in the name entry ========================================================== 20:43:40 (1786754620) [ 4287.604968] Lustre: *** cfs_fail_loc=1623, val=0*** [ 4298.928959] Lustre: DEBUG MARKER: == sanity-lfsck test 26a: LFSCK can add the missing local name entry back to the namespace ========================================================== 20:43:52 (1786754632) [ 4300.840929] Lustre: *** cfs_fail_loc=1624, val=0*** [ 4312.556426] Lustre: DEBUG MARKER: == sanity-lfsck test 26b: LFSCK can add the missing remote name entry back to the namespace ========================================================== 20:44:06 (1786754646) [ 4325.806728] Lustre: DEBUG MARKER: == sanity-lfsck test 27a: LFSCK can recreate the lost local parent directory as orphan ========================================================== 20:44:19 (1786754659) [ 4327.405820] Lustre: *** cfs_fail_loc=1624, val=0*** [ 4327.409058] Lustre: Skipped 1 previous similar message [ 4340.418873] Lustre: DEBUG MARKER: == sanity-lfsck test 27b: LFSCK can recreate the lost remote parent directory as orphan ========================================================== 20:44:33 (1786754673) [ 4356.896687] Lustre: DEBUG MARKER: == sanity-lfsck test 28: Skip the failed MDT(s) when handle orphan MDT-objects ========================================================== 20:44:50 (1786754690) [ 4359.869909] Lustre: *** cfs_fail_loc=1624, val=0*** [ 4359.873024] Lustre: Skipped 2 previous similar messages [ 4364.282516] Lustre: *** cfs_fail_loc=161c, val=0*** [ 4382.140360] Lustre: DEBUG MARKER: == sanity-lfsck test 29b: LFSCK can repair bad nlink count (2) ========================================================== 20:45:16 (1786754716) [ 4383.073861] Lustre: 123603:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 4383.090801] Lustre: 123603:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 497 previous similar messages [ 4383.107375] Lustre: 123603:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 4383.120348] Lustre: 123603:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 497 previous similar messages [ 4383.129946] Lustre: 123603:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4383.138069] Lustre: 123603:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 497 previous similar messages [ 4383.142944] Lustre: 123603:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 4383.150032] Lustre: 123603:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 497 previous similar messages [ 4383.156239] Lustre: 123603:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 4383.161805] Lustre: 123603:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 497 previous similar messages [ 4383.171853] Lustre: 123603:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4383.183246] Lustre: 123603:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 497 previous similar messages [ 4397.105904] Lustre: DEBUG MARKER: == sanity-lfsck test 29c: verify linkEA size limitation == 20:45:30 (1786754730) [ 4428.595531] Lustre: DEBUG MARKER: == sanity-lfsck test 29d: accessing non-existing inode shouldn't turn fs read-only (ldiskfs) ========================================================== 20:46:02 (1786754762) [ 4430.719783] Lustre: *** cfs_fail_loc=1626, val=0*** [ 4430.721654] Lustre: Skipped 2 previous similar messages [ 4432.042717] LustreError: 123603:0:(osd_handler.c:284:osd_idc_find_or_init()) lustre-MDT0000: cannot lookup FID [0x2000013a3:0x9e:0x0]: rc = -2 [ 4439.677475] Lustre: DEBUG MARKER: == sanity-lfsck test 30: LFSCK can recover the orphans from backend /lost+found ========================================================== 20:46:13 (1786754773) [ 4463.263887] Lustre: Failing over lustre-MDT0000 [ 4463.645692] Lustre: server umount lustre-MDT0000 complete [ 4468.192365] 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 [ 4468.196204] LustreError: 123603:0:(ldlm_lib.c:1192: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. [ 4468.214102] Lustre: Skipped 4 previous similar messages [ 4468.242616] LustreError: 123603:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 12 previous similar messages [ 4474.672677] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 4474.909487] LustreError: MGC192.168.203.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4475.264382] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4475.309542] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4479.874304] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4480.480924] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4480.492953] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4480.500190] Lustre: Skipped 3 previous similar messages [ 4480.521748] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4480.578290] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:294 to 0x280000401:321) [ 4480.585242] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:167 to 0x2c0000401:193) [ 4492.676684] Lustre: DEBUG MARKER: == sanity-lfsck test 31a: The LFSCK can find/repair the name entry with bad name hash (1) ========================================================== 20:47:06 (1786754826) [ 4505.747814] Lustre: DEBUG MARKER: == sanity-lfsck test 31b: The LFSCK can find/repair the name entry with bad name hash (2) ========================================================== 20:47:19 (1786754839) [ 4519.540383] Lustre: DEBUG MARKER: == sanity-lfsck test 31c: Re-generate the lost master LMV EA for striped directory ========================================================== 20:47:33 (1786754853) [ 4520.928291] Lustre: *** cfs_fail_loc=1629, val=0*** [ 4520.935835] Lustre: Skipped 5 previous similar messages [ 4553.081071] Lustre: DEBUG MARKER: == sanity-lfsck test 31d: Set broken striped directory (modified after broken) as read-only ========================================================== 20:48:06 (1786754886) [ 4559.177827] Lustre: Failing over lustre-MDT0000 [ 4559.611515] Lustre: server umount lustre-MDT0000 complete [ 4562.402122] 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 [ 4562.414574] Lustre: Skipped 4 previous similar messages [ 4562.417738] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4568.079278] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4568.254785] LustreError: MGC192.168.203.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4568.597948] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4572.124513] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4573.676091] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4573.704622] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4573.724460] Lustre: Skipped 3 previous similar messages [ 4573.766206] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4573.845508] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:294 to 0x280000401:353) [ 4573.849557] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:167 to 0x2c0000401:225) [ 4582.900691] Lustre: Failing over lustre-MDT0000 [ 4583.315267] Lustre: server umount lustre-MDT0000 complete [ 4583.906354] 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 [ 4583.917789] Lustre: Skipped 3 previous similar messages [ 4583.926125] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4592.602622] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4592.708752] LustreError: MGC192.168.203.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4592.924193] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4595.359709] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4597.952325] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4598.245443] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4598.268407] Lustre: Skipped 3 previous similar messages [ 4598.298098] Lustre: lustre-MDT0000: Recovery over after 0:03, of 2 clients 2 recovered and 0 were evicted. [ 4598.348777] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:167 to 0x2c0000401:257) [ 4598.355959] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:355 to 0x280000401:385) [ 4607.488344] Lustre: DEBUG MARKER: == sanity-lfsck test 31e: Re-generate the lost slave LMV EA for striped directory (1) ========================================================== 20:49:01 (1786754941) [ 4622.357297] Lustre: DEBUG MARKER: == sanity-lfsck test 31f: Re-generate the lost slave LMV EA for striped directory (2) ========================================================== 20:49:16 (1786754956) [ 4640.412651] Lustre: DEBUG MARKER: == sanity-lfsck test 31g: Repair the corrupted slave LMV EA ========================================================== 20:49:33 (1786754973) [ 4680.115734] Lustre: DEBUG MARKER: == sanity-lfsck test 31h: Repair the corrupted shard's name entry ========================================================== 20:50:13 (1786755013) [ 4696.055765] Lustre: DEBUG MARKER: == sanity-lfsck test 32a: stop LFSCK when some OST failed ========================================================== 20:50:30 (1786755030) [ 4706.540767] LustreError: 148045:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d sleeping for 3000ms [ 4709.214714] Lustre: Failing over lustre-OST0000 [ 4709.347076] LustreError: lustre-OST0000-osc-MDT0001: operation ost_statfs to node 0@lo failed: rc = -107 [ 4709.350077] 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 [ 4709.367682] Lustre: Skipped 1 previous similar message [ 4709.376442] LustreError: 125101:0:(ldlm_lib.c:1192: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. [ 4709.385638] LustreError: 125101:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 22 previous similar messages [ 4709.412662] Lustre: server umount lustre-OST0000 complete [ 4709.624451] LustreError: 148045:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d awake [ 4709.631161] LustreError: 148045:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d sleeping for 3000ms [ 4712.163888] LustreError: 148045:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout interrupted [ 4723.238504] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 4723.460445] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 4724.779203] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4724.803094] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 4724.804930] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 4724.824276] Lustre: Skipped 3 previous similar messages [ 4729.814512] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4738.015919] Lustre: DEBUG MARKER: == sanity-lfsck test 32b: stop LFSCK when some MDT failed ========================================================== 20:51:12 (1786755072) [ 4753.519254] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing load_modules_local [ 4774.431621] Lustre: 150849:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 4797.445549] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4800.807423] Lustre: 151985:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 4813.916680] LustreError: 152121:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d sleeping for 3000ms [ 4813.935241] LustreError: 152121:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) Skipped 1 previous similar message [ 4816.554154] Lustre: Failing over lustre-MDT0001 [ 4816.967114] LustreError: 152120:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d awake [ 4816.978648] LustreError: 152120:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d sleeping for 3000ms [ 4816.981422] LustreError: lustre-MDT0001-osp-MDT0000: operation out_update to node 0@lo failed: rc = -107 [ 4816.996778] 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 [ 4817.010599] Lustre: Skipped 1 previous similar message [ 4817.015402] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 4817.196883] Lustre: server umount lustre-MDT0001 complete [ 4820.031451] LustreError: 152120:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d awake [ 4820.044639] LustreError: 152120:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) Skipped 1 previous similar message [ 4833.598750] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 4834.029648] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 4834.036208] Lustre: Skipped 3 previous similar messages [ 4834.070777] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 4838.737716] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4839.404988] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4839.410269] Lustre: lustre-MDT0001-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 4839.425934] Lustre: Skipped 1 previous similar message [ 4839.450727] Lustre: lustre-MDT0001: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4839.515910] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:70 to 0x280000400:97) [ 4839.518184] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:69 to 0x2c0000400:97) [ 4848.698335] Lustre: DEBUG MARKER: == sanity-lfsck test 33: check LFSCK paramters =========== 20:53:02 (1786755182) [ 4863.513449] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing load_modules_local [ 4882.324937] Lustre: 154840:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 4905.607672] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4909.143964] Lustre: 155975:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 4911.438949] Lustre: 127296:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 4911.449258] Lustre: 127296:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 1222 previous similar messages [ 4911.462440] Lustre: 127296:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 4911.472681] Lustre: 127296:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1222 previous similar messages [ 4911.479162] Lustre: 127296:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4911.494973] Lustre: 127296:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1222 previous similar messages [ 4911.502357] Lustre: 127296:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 4911.509583] Lustre: 127296:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1222 previous similar messages [ 4911.518862] Lustre: 127296:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 4911.526190] Lustre: 127296:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1222 previous similar messages [ 4911.536139] Lustre: 127296:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4911.542460] Lustre: 127296:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1222 previous similar messages [ 4930.226151] Lustre: DEBUG MARKER: == sanity-lfsck test 34: LFSCK can rebuild the lost agent object ========================================================== 20:54:24 (1786755264) [ 4931.915965] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_34 Only valid for ZFS backend [ 4933.920758] Lustre: DEBUG MARKER: == sanity-lfsck test 35: LFSCK can rebuild the lost agent entry ========================================================== 20:54:27 (1786755267) [ 4942.199899] Lustre: *** cfs_fail_loc=1631, val=0*** [ 4953.167939] Lustre: server umount lustre-MDT0000 complete [ 4956.700069] LustreError: 156601:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1786755291 with bad export cookie 5547759022737872992 [ 4956.718142] LustreError: MGC192.168.203.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4956.720775] LustreError: 156601:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 4957.063970] Lustre: server umount lustre-MDT0001 complete [ 4973.345578] Lustre: 106507:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786755292/real 1786755292] req@ffff97b01fceb800 x1873547108141824/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786755308 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4973.372542] 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 [ 4973.390500] Lustre: Skipped 2 previous similar messages [ 4974.047561] Lustre: 106509:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786755292/real 1786755292] req@ffff97b01fce8000 x1873547108141696/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786755308 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4977.183231] Lustre: 106509:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786755296/real 1786755296] req@ffff97b01fce8700 x1873547108142336/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786755312 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4981.515904] Lustre: server umount lustre-OST0000 complete [ 4982.367123] Lustre: 106509:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786755301/real 1786755301] req@ffff97b02e39df80 x1873547108142720/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786755317 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4982.414509] Lustre: 106509:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 4985.935812] Lustre: server umount lustre-OST0001 complete [ 5003.760737] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing load_modules_local [ 5013.829044] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5014.198532] LustreError: 158730:0:(ldlm_lib.c:1192: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. [ 5014.233355] LustreError: 158730:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 15 previous similar messages [ 5019.048924] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5027.192485] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5031.260489] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5033.797889] Lustre: 159870:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 5040.295269] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5047.755818] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5053.869206] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:70 to 0x280000400:129) [ 5056.010250] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5059.305953] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:540 to 0x280000401:577) [ 5059.309432] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:69 to 0x2c0000400:129) [ 5059.309523] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:412 to 0x2c0000401:449) [ 5062.875778] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5070.274493] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5073.456306] Lustre: 161741:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 5082.810535] Lustre: DEBUG MARKER: == sanity-lfsck test 36a: rebuild LOV EA for mirrored file (1) ========================================================== 20:56:56 (1786755416) [ 5084.292550] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36a needs >= 3 OSTs [ 5086.540588] Lustre: DEBUG MARKER: == sanity-lfsck test 36b: rebuild LOV EA for mirrored file (2) ========================================================== 20:57:00 (1786755420) [ 5088.450685] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36b needs >= 3 OSTs [ 5090.145671] Lustre: DEBUG MARKER: == sanity-lfsck test 36c: rebuild LOV EA for mirrored file (3) ========================================================== 20:57:04 (1786755424) [ 5091.695867] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36c needs >= 3 OSTs [ 5093.895559] Lustre: DEBUG MARKER: == sanity-lfsck test 37: LFSCK must skip a ORPHAN ======== 20:57:07 (1786755427) [ 5108.294323] Lustre: DEBUG MARKER: == sanity-lfsck test 38: LFSCK does not break foreign file and reverse is also true ========================================================== 20:57:21 (1786755441) [ 5153.847584] Lustre: DEBUG MARKER: == sanity-lfsck test 39: LFSCK does not break foreign dir and reverse is also true ========================================================== 20:58:07 (1786755487) [ 5168.600195] Lustre: DEBUG MARKER: == sanity-lfsck test 40a: LFSCK correctly fixes lmm_oi in composite layout ========================================================== 20:58:22 (1786755502) [ 5183.265785] Lustre: DEBUG MARKER: == sanity-lfsck test 41: SEL support in LFSCK ============ 20:58:37 (1786755517) [ 5202.210788] Lustre: DEBUG MARKER: == sanity-lfsck test 42: LFSCK repairs inconsistent MDT-object/OST-object encryption flags ========================================================== 20:58:56 (1786755536) [ 5237.548073] Lustre: *** cfs_fail_loc=1632, val=0*** [ 5255.431981] Lustre: DEBUG MARKER: == sanity-lfsck test 43: LFSCK does not loop endlessly on iget failure in scanning-phase1 ========================================================== 20:59:48 (1786755588) [ 5258.590849] Lustre: Failing over lustre-MDT0001 [ 5258.795824] Lustre: server umount lustre-MDT0001 complete [ 5259.236505] 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 [ 5259.257855] Lustre: Skipped 2 previous similar messages [ 5265.774450] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5266.163882] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 5266.167711] Lustre: lustre-MDT0001: Aborting client recovery [ 5266.170064] LustreError: 166342:0:(ldlm_lib.c:3004:target_stop_recovery_thread()) lustre-MDT0001: Aborting recovery [ 5266.175731] Lustre: 166366:0:(ldlm_lib.c:2404:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 5266.180803] LustreError: 166364:0:(lod_dev.c:511:lod_sub_recovery_thread()) lustre-MDT0001-osd: get update log duration 0, retries 0, failed: rc = -108 [ 5266.195611] LustreError: 166364:0:(lod_dev.c:511:lod_sub_recovery_thread()) Skipped 1 previous similar message [ 5266.200792] Lustre: 166366:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0001: disconnect stale client 1bbd082f-312d-484d-adea-a17e0c2b5892@ [ 5266.207367] Lustre: lustre-MDT0001: disconnecting 2 stale clients [ 5266.213322] Lustre: lustre-MDT0001-osd: cancel update llog [0x240000400:0x1:0x0] [ 5266.224116] Lustre: lustre-MDT0000-osp-MDT0001: cancel update llog [0x200000401:0x1:0x0] [ 5266.290247] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:131 to 0x2c0000400:161) [ 5266.292877] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:70 to 0x280000400:161) [ 5270.430526] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5271.529089] Lustre: lustre-MDT0001-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 5271.543755] Lustre: Skipped 2 previous similar messages [ 5271.550901] LustreError: lustre-MDT0001-osp-MDT0000: This client was evicted by lustre-MDT0001; in progress operations using this service will fail. [ 5273.911166] Lustre: *** cfs_fail_loc=1e2, val=483*** [ 5278.225280] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing wait_import_state FULL osp.lustre-MDT0001-os[pc]-MDT0000.*_server_uuid [ 5278.560028] Lustre: DEBUG MARKER: osp.lustre-MDT0001-os[pc]-MDT0000.*_server_uuid in FULL state after 0 sec [ 5285.410601] Lustre: DEBUG MARKER: == sanity-lfsck test 44: umount while lfsck is stopping == 21:00:19 (1786755619) [ 5294.780253] Lustre: *** cfs_fail_loc=1600, val=3*** [ 5297.798341] Lustre: Failing over lustre-MDT0000 [ 5297.826720] LustreError: lustre-MDT0000-osp-MDT0001: operation out_update to node 0@lo failed: rc = -107 [ 5297.838725] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5298.261801] Lustre: server umount lustre-MDT0000 complete [ 5307.612247] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5307.748368] LustreError: MGC192.168.203.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5308.036252] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 5308.050798] Lustre: Skipped 2 previous similar messages [ 5312.587370] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5312.675693] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 5313.023696] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 5313.028480] Lustre: Skipped 2 previous similar messages [ 5313.072780] Lustre: lustre-MDT0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 5313.133806] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:489 to 0x2c0000401:513) [ 5313.134786] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:621 to 0x280000401:641) [ 5321.818620] Lustre: DEBUG MARKER: == sanity-lfsck test 45: LFSCK should fix UID/GID/PROJID of OST object ========================================================== 21:00:56 (1786755656) [ 5348.165020] Lustre: Failing over lustre-OST0000 [ 5348.319536] LustreError: lustre-OST0000-osc-MDT0001: operation ost_statfs to node 0@lo failed: rc = -107 [ 5348.330793] Lustre: server umount lustre-OST0000 complete [ 5354.497571] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: (null) [ 5365.285248] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5365.414865] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 5365.423422] Lustre: Skipped 6 previous similar messages [ 5366.569561] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 5367.189758] Lustre: lustre-OST0000: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [ 5371.105813] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5378.184765] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing wait_import_state (FULL|IDLE) os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid 50 [ 5378.409264] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid in FULL state after 0 sec [ 5383.407227] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing wait_import_state (FULL|IDLE) os[cp].lustre-OST0000-osc-MDT0001.ost_server_uuid 50 [ 5383.697540] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0001.ost_server_uuid in FULL state after 0 sec [ 5390.618295] Lustre: DEBUG MARKER: oleg355-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0000-osc-ffff976fc423f800.ost_server_uuid 50 [ 5392.220353] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff976fc423f800.ost_server_uuid in FULL state after 0 sec [ 5443.786502] Lustre: server umount lustre-MDT0000 complete [ 5446.114668] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 5446.129351] LustreError: Skipped 1 previous similar message [ 5454.046567] LustreError: 160248:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1786755789 with bad export cookie 5547759022737955781 [ 5454.048079] LustreError: MGC192.168.203.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5454.057672] LustreError: 160248:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 5454.465321] Lustre: server umount lustre-MDT0001 complete [ 5473.247206] Lustre: 106510:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786755792/real 1786755792] req@ffff97b03c777100 x1873547108534016/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786755808 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5473.281359] Lustre: 106510:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 5474.431321] Lustre: server umount lustre-OST0000 complete [ 5482.158835] Lustre: server umount lustre-OST0001 complete [ 5498.906208] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing unload_modules_local [ 5501.546294] Key type lgssc unregistered [ 5501.825281] LNet: 175490:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 5501.832237] LNetError: 175490:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 5501.847080] LNet: Removed LNI 192.168.203.155@tcp [ 5502.835238] Key type .llcrypt unregistered [ 5502.837360] Key type ._llcrypt unregistered [ 5526.255664] Key type ._llcrypt registered [ 5526.257230] Key type .llcrypt registered [ 5526.365912] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_hostid [ 5542.823946] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing load_modules_local [ 5544.046617] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 5544.091677] alg: No test for adler32 (adler32-zlib) [ 5545.187540] Lustre: Lustre: Build Version: 2.17.57_4_gb324e6e [ 5545.400614] LNet: Added LNI 192.168.203.155@tcp [8/256/0/180] [ 5547.063663] Key type lgssc registered [ 5548.215522] Lustre: Echo OBD driver; http://www.lustre.org/ [ 5601.347531] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing load_modules_local [ 5614.550269] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 5614.577811] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5615.826620] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 5615.856208] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 5615.924621] Lustre: lustre-MDT0000: new disk, initializing [ 5615.988992] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 5616.021673] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 5619.893404] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5631.330354] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5631.493183] Lustre: 179945:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 5631.524585] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 5631.531729] Lustre: Skipped 1 previous similar message [ 5631.594336] Lustre: lustre-MDT0001: new disk, initializing [ 5631.650670] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 5631.675590] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 5631.682690] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 5636.136420] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5640.830897] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 5649.607947] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5649.902988] Lustre: lustre-OST0000: new disk, initializing [ 5649.908945] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 5649.916565] Lustre: lustre-OST0000: Not available for connect from 0@lo (not set up) [ 5649.923365] Lustre: 181885:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 5649.991632] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 5655.039051] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 5655.061489] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 5655.102707] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000400 [ 5656.069987] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5669.111028] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5669.243625] Lustre: lustre-OST0001: new disk, initializing [ 5669.247951] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 5669.254058] Lustre: 182907:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 5669.326314] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 5675.630273] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5678.641061] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 5678.648890] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 5678.700728] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 5685.992738] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5693.840609] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 5699.252958] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 21:07:13 (1786756033) === [ 5700.984686] Lustre: DEBUG MARKER: == sanity-lfsck test complete, duration 5482 sec ========= 21:07:14 (1786756034) [ 5702.663499] Lustre: DEBUG MARKER: === sanity-lfsck: start cleanup 21:07:16 (1786756036) === [ 5706.216972] Lustre: DEBUG MARKER: === sanity-lfsck: finish cleanup 21:07:20 (1786756040) === [ 5713.892358] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 5713.911429] 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 [ 5713.936351] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5714.412695] 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 [ 5716.655427] Lustre: server umount lustre-MDT0000 complete [ 5724.640563] LustreError: 179958:0:(ldlm_lib.c:1192: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. [ 5724.687854] LustreError: 179958:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 8 previous similar messages [ 5725.562914] LustreError: 179937:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1786756060 with bad export cookie 13905439601593046744 [ 5725.564974] LustreError: MGC192.168.203.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5725.571118] LustreError: 179937:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 5725.884506] Lustre: server umount lustre-MDT0001 complete [ 5745.120282] Lustre: 177106:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786756064/real 1786756064] req@ffff97af036a0000 x1873549333709056/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786756080 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5745.150837] 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 [ 5745.160827] Lustre: Skipped 2 previous similar messages [ 5746.318477] Lustre: server umount lustre-OST0000 complete [ 5746.655457] Lustre: 177108:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786756065/real 1786756065] req@ffff97b037368700 x1873549333709312/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786756081 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5750.239163] Lustre: 177107:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786756069/real 1786756069] req@ffff97b02eb7aa00 x1873549333709568/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786756085 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5752.864847] Lustre: 177108:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786756071/real 1786756071] req@ffff97af036a1880 x1873549333709952/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786756087 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5754.372460] Lustre: server umount lustre-OST0001 complete [ 5771.657689] Lustre: DEBUG MARKER: oleg355-server.virtnet: executing unload_modules_local [ 5774.343447] Key type lgssc unregistered [ 5774.697739] LNet: 186381:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 5774.709280] LNetError: 186381:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 5774.742984] LNet: Removed LNI 192.168.203.155@tcp [ 5775.671918] Key type .llcrypt unregistered [ 5775.682842] Key type ._llcrypt unregistered