[ 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 558493531 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2400.000 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.001016] APIC: Switch to symmetric I/O mode setup [ 0.003328] x2apic enabled [ 0.004012] Switched APIC routing to physical x2apic. [ 0.005026] kvm-guest: setup PV IPIs [ 0.008000] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.008000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x22983777dd9, max_idle_ns: 440795300422 ns [ 0.008037] Calibrating delay loop (skipped) preset value.. 4800.00 BogoMIPS (lpj=2400000) [ 0.009021] pid_max: default: 32768 minimum: 301 [ 0.010181] LSM: Security Framework initializing [ 0.011078] Yama: becoming mindful. [ 0.012046] SELinux: Initializing. [ 0.013079] *** VALIDATE selinux *** [ 0.022053] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.027385] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.028185] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.030016] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.031176] *** VALIDATE tmpfs *** [ 0.033538] *** VALIDATE proc *** [ 0.034400] *** VALIDATE cgroup *** [ 0.035019] *** VALIDATE cgroup2 *** [ 0.037295] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.038188] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.039017] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.040041] Spectre V2 : User space: Vulnerable [ 0.041015] Speculative Store Bypass: Vulnerable [ 0.044285] debug: unmapping init [mem 0xffffffffa3059000-0xffffffffa3060fff] [ 0.046228] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.047801] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.048031] ... version: 2 [ 0.049020] ... bit width: 48 [ 0.050015] ... generic registers: 4 [ 0.051021] ... value mask: 0000ffffffffffff [ 0.052022] ... max period: 00007fffffffffff [ 0.053023] ... fixed-purpose events: 3 [ 0.054016] ... event mask: 000000070000000f [ 0.056306] rcu: Hierarchical SRCU implementation. [ 0.058554] smp: Bringing up secondary CPUs ... [ 0.059716] x86: Booting SMP configuration: [ 0.060041] .... node #0, CPUs: #1 #2 #3 [ 0.065517] smp: Brought up 1 node, 4 CPUs [ 0.067025] smpboot: Max logical packages: 1 [ 0.068020] smpboot: Total of 4 processors activated (19200.00 BogoMIPS) [ 0.231022] node 0 deferred pages initialised in 160ms [ 0.234123] devtmpfs: initialized [ 0.236442] x86/mm: Memory block size: 128MB [ 0.240199] gcov: version magic: 0x41383552 [ 0.242366] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.247086] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.250335] pinctrl core: initialized pinctrl subsystem [ 0.252170] [ 0.252766] ************************************************************* [ 0.255016] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.258015] ** ** [ 0.261021] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.264015] ** ** [ 0.266014] ** This means that this kernel is built to expose internal ** [ 0.269016] ** IOMMU data structures, which may compromise security on ** [ 0.271012] ** your system. ** [ 0.274013] ** ** [ 0.276013] ** If you see this message and you are not debugging the ** [ 0.278015] ** kernel, report this immediately to your vendor! ** [ 0.281013] ** ** [ 0.283011] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.285015] ************************************************************* [ 0.288969] NET: Registered protocol family 16 [ 0.290471] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.293067] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.296088] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.300011] cpuidle: using governor menu [ 0.301795] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.305555] PCI: Using configuration type 1 for base access [ 0.307129] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.317133] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.320058] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.324063] cryptd: max_cpu_qlen set to 1000 [ 0.327256] ACPI: Added _OSI(Module Device) [ 0.329018] ACPI: Added _OSI(Processor Device) [ 0.331009] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.332011] ACPI: Added _OSI(Processor Aggregator Device) [ 0.337217] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.343322] ACPI: Interpreter enabled [ 0.345065] ACPI: PM: (supports S0 S3 S4 S5) [ 0.346012] ACPI: Using IOAPIC for interrupt routing [ 0.348215] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.352458] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.364137] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.367039] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.370020] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.375099] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.384436] acpiphp: Slot [2] registered [ 0.387204] acpiphp: Slot [5] registered [ 0.389186] acpiphp: Slot [6] registered [ 0.391147] acpiphp: Slot [7] registered [ 0.392128] acpiphp: Slot [8] registered [ 0.394120] acpiphp: Slot [9] registered [ 0.397135] acpiphp: Slot [10] registered [ 0.398129] acpiphp: Slot [3] registered [ 0.400116] acpiphp: Slot [4] registered [ 0.401102] acpiphp: Slot [11] registered [ 0.403096] acpiphp: Slot [12] registered [ 0.404104] acpiphp: Slot [13] registered [ 0.406140] acpiphp: Slot [14] registered [ 0.407099] acpiphp: Slot [15] registered [ 0.409096] acpiphp: Slot [16] registered [ 0.410099] acpiphp: Slot [17] registered [ 0.411093] acpiphp: Slot [18] registered [ 0.413090] acpiphp: Slot [19] registered [ 0.414137] acpiphp: Slot [20] registered [ 0.416121] acpiphp: Slot [21] registered [ 0.417111] acpiphp: Slot [22] registered [ 0.419318] acpiphp: Slot [23] registered [ 0.421107] acpiphp: Slot [24] registered [ 0.422116] acpiphp: Slot [25] registered [ 0.424105] acpiphp: Slot [26] registered [ 0.425146] acpiphp: Slot [27] registered [ 0.427133] acpiphp: Slot [28] registered [ 0.429106] acpiphp: Slot [29] registered [ 0.431107] acpiphp: Slot [30] registered [ 0.432106] acpiphp: Slot [31] registered [ 0.434064] PCI host bridge to bus 0000:00 [ 0.436020] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.438041] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.442039] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.447028] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.451028] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.455030] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.458180] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.463776] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.468563] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.484014] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.490056] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.493020] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.495017] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.497017] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.500714] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.504613] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.509071] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.514373] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.521019] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.535018] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.543017] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.549031] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.561016] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.572018] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.606017] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.626607] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.640018] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.652017] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.673023] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.683949] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.697016] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.709021] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.733022] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.743424] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.749015] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.759016] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.797021] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.812315] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.819015] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.827020] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.845038] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 0.859186] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.869069] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.878016] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.909029] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 0.920681] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.926401] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.930434] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.933367] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.935359] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.941711] iommu: Default domain type: Passthrough [ 0.944988] SCSI subsystem initialized [ 0.947183] ACPI: bus type USB registered [ 0.950175] usbcore: registered new interface driver usbfs [ 0.952116] usbcore: registered new interface driver hub [ 0.956113] usbcore: registered new device driver usb [ 0.959516] pps_core: LinuxPPS API ver. 1 registered [ 0.961011] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.965103] PTP clock support registered [ 0.967171] EDAC MC: Ver: 3.0.0 [ 0.969159] PCI: Using ACPI for IRQ routing [ 0.973269] NetLabel: Initializing [ 0.974014] NetLabel: domain hash size = 128 [ 0.976017] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.978183] NetLabel: unlabeled traffic allowed by default [ 0.980456] vgaarb: loaded [ 0.982584] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.983021] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.987234] clocksource: Switched to clocksource kvm-clock [ 1.107489] VFS: Disk quotas dquot_6.6.0 [ 1.108922] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 1.111168] *** VALIDATE ramfs *** [ 1.112360] *** VALIDATE hugetlbfs *** [ 1.113774] pnp: PnP ACPI init [ 1.116104] pnp: PnP ACPI: found 6 devices [ 1.131195] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 1.134172] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 1.136324] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 1.138313] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 1.140375] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 1.142387] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 1.144883] NET: Registered protocol family 2 [ 1.146956] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 1.151623] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 1.154685] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 1.159124] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 1.162096] TCP: Hash tables configured (established 65536 bind 65536) [ 1.164598] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 1.167163] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 1.169822] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 1.173063] NET: Registered protocol family 1 [ 1.175724] RPC: Registered named UNIX socket transport module. [ 1.177686] RPC: Registered udp transport module. [ 1.179204] RPC: Registered tcp transport module. [ 1.180585] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 1.182430] NET: Registered protocol family 44 [ 1.183648] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 1.185806] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 1.187501] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 1.189385] PCI: CLS 0 bytes, default 64 [ 1.190753] Unpacking initramfs... [ 2.721911] debug: unmapping init [mem 0xffff9ab53cc54000-0xffff9ab53ffbffff] [ 2.729534] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.732535] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.737749] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x22983777dd9, max_idle_ns: 440795300422 ns [ 3.220861] Initialise system trusted keyrings [ 3.222364] Key type blacklist registered [ 3.223956] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 3.232398] zbud: loaded [ 3.234960] *** VALIDATE nfs *** [ 3.236034] *** VALIDATE nfs4 *** [ 3.237419] pstore: using deflate compression [ 3.240281] Platform Keyring initialized [ 3.348763] NET: Registered protocol family 38 [ 3.350886] Key type asymmetric registered [ 3.352785] Asymmetric key parser 'x509' registered [ 3.354886] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 3.358487] io scheduler mq-deadline registered [ 3.362678] io scheduler kyber registered [ 3.365695] io scheduler bfq registered [ 3.367835] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 3.371538] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 3.374696] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 3.377894] ACPI: Power Button [PWRF] [ 3.383373] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 3.390479] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 3.414366] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 3.423382] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 3.454383] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 3.487628] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.520163] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.525116] Non-volatile memory driver v1.3 [ 3.526784] Linux agpgart interface v0.103 [ 3.555535] virtio_blk virtio1: [vda] 150616 512-byte logical blocks (77.1 MB/73.5 MiB) [ 3.558821] vda: detected capacity change from 0 to 77115392 [ 3.609341] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.612937] vdb: detected capacity change from 0 to 1073741824 [ 3.627933] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.631280] vdc: detected capacity change from 0 to 2621440000 [ 3.646186] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.649696] vdd: detected capacity change from 0 to 2621440000 [ 3.675630] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.679023] vde: detected capacity change from 0 to 4294967296 [ 3.693188] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.696263] vdf: detected capacity change from 0 to 4294967296 [ 3.708057] libphy: Fixed MDIO Bus: probed [ 3.751867] usbcore: registered new interface driver usbserial_generic [ 3.755611] usbserial: USB Serial support registered for generic [ 3.758930] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.765026] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.766857] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.770418] mousedev: PS/2 mouse device common for all mice [ 3.773899] rtc_cmos 00:05: RTC can wake from S4 [ 3.778966] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.780203] rtc_cmos 00:05: registered as rtc0 [ 3.784541] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.786060] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.788732] intel_pstate: CPU model not supported [ 3.796547] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.824467] hid: raw HID events driver (C) Jiri Kosina [ 3.827235] usbcore: registered new interface driver usbhid [ 3.829630] usbhid: USB HID core driver [ 3.831454] drop_monitor: Initializing network drop monitor service [ 3.834145] Initializing XFRM netlink socket [ 3.836403] NET: Registered protocol family 10 [ 3.840315] Segment Routing with IPv6 [ 3.841930] NET: Registered protocol family 17 [ 3.843863] mpls_gso: MPLS GSO support [ 3.849481] RAS: Correctable Errors collector initialized. [ 3.851182] AVX version of gcm_enc/dec engaged. [ 3.853292] AES CTR mode by8 optimization enabled [ 3.930737] sched_clock: Marking stable (3930715533, 0)->(4903875232, -973159699) [ 3.934285] registered taskstats version 1 [ 3.936332] Loading compiled-in X.509 certificates [ 3.938246] zswap: loaded using pool lzo/zbud [ 3.962092] Key type big_key registered [ 3.974732] Key type encrypted registered [ 3.976189] ima: No TPM chip found, activating TPM-bypass! [ 3.978381] ima: Allocated hash algorithm: sha1 [ 3.980406] ima: No architecture policies found [ 3.981976] evm: Initialising EVM extended attributes: [ 3.983715] evm: security.selinux [ 3.984852] evm: security.ima [ 3.985838] evm: security.capability [ 3.987024] evm: HMAC attrs: 0x1 [ 3.989574] rtc_cmos 00:05: setting system clock to 2026-10-02 12:34:14 UTC (1790944454) [ 3.995981] debug: unmapping init [mem 0xffffffffa4003000-0xffffffffa41fffff] [ 3.999500] debug: unmapping init [mem 0xffffffffa2d82000-0xffffffffa3058fff] [ 4.007168] Write protecting the kernel read-only data: 28672k [ 4.010776] debug: unmapping init [mem 0xffffffffa1403000-0xffffffffa15fffff] [ 4.013645] debug: unmapping init [mem 0xffffffffa1d14000-0xffffffffa1dfffff] [ 4.046937] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 4.055642] systemd[1]: Detected virtualization kvm. [ 4.057740] systemd[1]: Detected architecture x86-64. [ 4.059824] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 4.090935] systemd[1]: No hostname configured. [ 4.093111] systemd[1]: Set hostname to . [ 4.095388] random: systemd: uninitialized urandom read (16 bytes read) [ 4.099052] systemd[1]: Initializing machine ID from random generator. [ 4.258152] random: systemd: uninitialized urandom read (16 bytes read) [ 4.261047] systemd[1]: Reached target Timers. [ OK ] Reached target Timers. [ 4.264954] random: systemd: uninitialized urandom read (16 bytes read) [ 4.267865] systemd[1]: Reached target Local File Systems. [ OK ] Reached target Local File Systems. [ 4.273336] systemd[1]: Reached target Initrd Root Device. [ OK ] Reached target Initrd Root Device. [ OK ] Listening on Journal Socket. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Started Memstrack Anylazing Service. Starting Setup Virtual Console... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Paths. [ OK ] Listening on udev Kernel Socket. [ OK ] Reached target Slices. [ OK ] Reached target Swap. [ OK ] Listening on udev Control Socket. Starting Create Volatile Files and Directories... [ OK ] Reached target Local Encrypted Volumes. Starting Apply Kernel Variables... [ OK ] Listening on Journal Socket (/dev/log). [ OK ] Reached target Sockets. Starting Journal Service... [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Setup Virtual Console. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Apply Kernel Variables. Starting dracut cmdline hook... Starting Create Static Device Nodes in /dev... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started Journal Service. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 4.925594] device-mapper: uevent: version 1.0.3 [ 4.928211] device-mapper: ioctl: 4.46.0-ioctl (2022-02-22) initialised: dm-devel@redhat.com [ OK ] Started dracut pre-udev hook. Starting udev Kernel Device Manager... [ OK ] Started udev Kernel Device Manager. Starting dracut pre-trigger hook... [ OK ] Started dracut pre-trigger hook. Starting udev Coldplug all Devices... Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ 5.592399] random: fast init done [ 5.592847] virtio_net virtio0 ens2: renamed from eth0 Starting dracut initqueue hook... [ 5.683258] scsi host0: ata_piix [ 5.705948] scsi host1: ata_piix [ 5.708724] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 5.710762] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 9.221695] dracut-initqueue[577]: RTNETLINK answers: File exists [ 10.506554] random: crng init done [ 10.507817] 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.854720] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped target Timers. [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped target Initrd Default Target. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Paths. [ OK ] Stopped target Slices. [ OK ] Stopped target Sockets. [ OK ] Stopped target System Initialization. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped Apply Kernel Variables. Stopping udev Kernel Device Manager... [ OK ] Stopped target Local File Systems. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped target Swap. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Closed udev Kernel Socket. [ OK ] Closed udev Control Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 12.069850] printk: systemd: 26 output lines suppressed due to ratelimiting [ 12.337856] SELinux: Disabled at runtime. [ 12.406860] 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.418059] systemd[1]: Detected virtualization kvm. [ 12.419428] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 12.947061] systemd[1]: initrd-switch-root.service: Succeeded. [ 12.950431] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 12.956155] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 12.960893] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 12.965211] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 12.975188] systemd[1]: Starting Journal Service... Starting Journal Service... [ 12.987769] systemd[1]: Activating swap /dev/disk/by-label/SWAP... Activating swap /dev/disk/by-label/SWAP... [ OK ] Reached target rpc_pipefs.target. [ OK ] Listening on initctl Compatibility Named Pipe. Mounting Huge Pages File System... [ OK ] Created slice system-getty.slice. [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd File Systems. [ OK ] Listening on udev Kernel Socket. [FAILED] Failed to set up[ 13.018947] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Listening on Process Core Dump Socket. Mounting POSIX Message Queue File System... [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Started Dispatch Password Requests to Console Directory Watch. Starting Create list of required st…ce nodes for the current kernel... Starting Apply Kernel Variables... Starting Remount Root and Kernel File Systems... [ OK ] Created slice User and Session Slice. Mounting Kernel Debug File System... [ OK ] Listening on udev Control Socket. Starting udev Coldplug all Devices... [ OK ] Stopped target Initrd Root File System. [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Reached target RPC Port Mapper. [ OK ] Reached target Slices. [ OK ] Started Journal Service. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Mounted Huge Pages File System. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Apply Kernel Variables. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Mounted Kernel Debug File System. Starting Configure read-only root support... Starting Create Static Device Nodes in /dev... [ OK ] Reached target Swap. Starting Flush Journal to Persistent Storage... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. Starting udev Kernel Device Manager... [ OK ] Reached target Local File Systems (Pre). Mounting /home/green/git/lustre-release... Mounting /mnt... [ OK ] Started udev Coldplug all Devices. [ 13.445765] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /mnt. [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 13.961300] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 13.968979] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 14.124357] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 14.147936] EDAC sbridge: Ver: 1.1.2 [ 15.986751] Key type dns_resolver registered [ 16.396970] NFS: Registering the id_resolver key type [ 16.399182] Key type id_resolver registered [ 16.401109] 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 Create Volatile Files and Directories... Starting Rebuild Dynamic Linker Cache... Starting Load/Save Random Seed... [ 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 ] Reached target sshd-keygen.target. [ OK ] Started irqbalance daemon. Starting Login Service... [ 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 OpenSSH server daemon... Starting Dynamic System Tuning Daemon... Starting GSSAPI Proxy Daemon... Starting Network Manager Wait Online... [ OK ] Started OpenSSH server daemon. [ OK ] Started GSSAPI Proxy Daemon. Starting Hostname Service... [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... [ OK ] Started Permit User Sessions. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Getty on tty1. [ OK ] Started Serial Getty on ttyS1. [ OK ] Reached target Login Prompts. [ OK ] Started Command Scheduler. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting System Logging Service... Starting Crash recovery kernel arming... Starting Notify NFS peers of a restart... [ 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 oleg332-server login: [ 44.474042] hrtimer: interrupt took 2137432 ns [ 62.739688] libcfs: loading out-of-tree module taints kernel. [ 62.823680] Key type ._llcrypt registered [ 62.828143] Key type .llcrypt registered [ 62.984353] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_hostid [ 84.565513] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing load_modules_local [ 85.753469] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 85.772559] alg: No test for adler32 (adler32-zlib) [ 87.264241] Lustre: Lustre: Build Version: 2.17.59_2_gbfaf0e7 [ 88.274399] LNet: Added LNI 192.168.203.132@tcp [8/256/0/180] [ 89.991478] Key type lgssc registered [ 91.753659] Lustre: Echo OBD driver; http://www.lustre.org/ [ 108.846953] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 152.584126] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing load_modules_local [ 165.996946] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' or install '{/usr}/sbin/mount.lustre_tgt' [ 166.039045] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 167.413112] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 167.457792] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 167.633360] Lustre: lustre-MDT0000: new disk, initializing [ 167.765766] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 167.793913] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 173.660395] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 189.401085] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 189.509774] Lustre: 6508: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 [ 189.544493] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 189.552889] Lustre: Skipped 1 previous similar message [ 189.665765] Lustre: lustre-MDT0001: new disk, initializing [ 189.771079] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 189.802799] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 189.820575] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 195.012390] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 201.353462] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 211.084698] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 211.459214] Lustre: lustre-OST0000: new disk, initializing [ 211.467609] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 211.479409] Lustre: 8447:0:(osd_compat.c:1354:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 211.545952] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 217.680810] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 217.696144] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 217.752527] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 217.799462] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 231.407065] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 231.525498] Lustre: lustre-OST0001: new disk, initializing [ 231.528864] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 231.533211] Lustre: 9518:0:(osd_compat.c:1354:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 231.595235] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 240.094063] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 241.191948] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 241.201940] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 241.335843] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 253.613536] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 260.998715] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 267.846758] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing check_logdir /tmp/testlogs/ [ 274.771112] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing yml_node [ 279.225660] Lustre: DEBUG MARKER: Client: 2.17.59.2 [ 281.515904] Lustre: DEBUG MARKER: MDS: 2.17.59.2 [ 284.120216] Lustre: DEBUG MARKER: OSS: 2.17.59.2 [ 285.911491] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity-lfsck ============----- Fri Oct 2 08:38:54 EDT 2026 [ 301.569808] Lustre: DEBUG MARKER: excepting tests: 18b 23b [ 310.530616] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing load_modules_local [ 317.923275] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 317.933761] 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 [ 317.952523] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 323.728977] Lustre: server umount lustre-MDT0000 complete [ 328.673690] LustreError: 6519:0:(ldlm_lib.c:1199: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. [ 328.690908] LustreError: 6519:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 8 previous similar messages [ 332.354440] LustreError: 6499:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1790944782 with bad export cookie 4443568444732439115 [ 332.362875] LustreError: MGC192.168.203.132@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 332.363749] LustreError: 6499:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 332.727430] Lustre: server umount lustre-MDT0001 complete [ 350.047258] Lustre: 3637:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790944784/real 1790944784] req@ffff9ab487d34700 x1877941459978752/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1790944800 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 350.076133] 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 [ 350.087655] Lustre: Skipped 3 previous similar messages [ 351.251151] Lustre: server umount lustre-OST0000 complete [ 353.762335] Lustre: 3639:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790944788/real 1790944788] req@ffff9ab487d36680 x1877941459979008/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1790944804 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 355.232251] Lustre: 3637:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790944789/real 1790944789] req@ffff9ab5b6c4b480 x1877941459979264/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1790944805 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 357.857343] Lustre: 3640:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790944792/real 1790944792] req@ffff9ab5b1526680 x1877941459979648/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1790944808 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 360.131686] Lustre: server umount lustre-OST0001 complete [ 373.381891] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing unload_modules_local [ 376.513250] Key type lgssc unregistered [ 376.803520] LNet: 14790:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 376.811948] LNetError: 14790:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 376.847443] LNet: Removed LNI 192.168.203.132@tcp [ 377.725133] Key type .llcrypt unregistered [ 377.729169] Key type ._llcrypt unregistered [ 399.641541] Key type ._llcrypt registered [ 399.643012] Key type .llcrypt registered [ 399.724576] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_hostid [ 417.966883] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing load_modules_local [ 418.913450] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 418.955339] alg: No test for adler32 (adler32-zlib) [ 420.045504] Lustre: Lustre: Build Version: 2.17.59_2_gbfaf0e7 [ 420.376173] LNet: Added LNI 192.168.203.132@tcp [8/256/0/180] [ 422.111344] Key type lgssc registered [ 423.276280] Lustre: Echo OBD driver; http://www.lustre.org/ [ 466.694416] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing load_modules_local [ 478.193441] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' or install '{/usr}/sbin/mount.lustre_tgt' [ 478.228123] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 479.524396] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 479.553744] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 479.663111] Lustre: lustre-MDT0000: new disk, initializing [ 479.768244] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 479.787448] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 483.329286] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 494.269726] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 494.390992] Lustre: 19258: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 [ 494.461139] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 494.483470] Lustre: Skipped 1 previous similar message [ 494.599749] Lustre: lustre-MDT0001: new disk, initializing [ 494.685480] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 494.718116] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 494.729989] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 498.350276] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 502.725373] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 511.339895] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 511.658851] Lustre: lustre-OST0000: new disk, initializing [ 511.662365] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 511.667985] Lustre: 21198:0:(osd_compat.c:1354:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 511.720850] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 517.158713] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 518.681388] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 518.703459] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 518.773352] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 529.387721] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 529.492271] Lustre: lustre-OST0001: new disk, initializing [ 529.495484] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 529.500987] Lustre: 22220:0:(osd_compat.c:1354:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 529.550239] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 535.317605] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 537.091360] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 537.101154] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 537.164066] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 545.940712] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 550.859310] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 558.147635] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 08:43:27 (1790945007) === [ 560.726499] Lustre: DEBUG MARKER: == sanity-lfsck test 0: Control LFSCK manually =========== 08:43:29 (1790945009) [ 560.894422] Lustre: 19265:0:(osd_internal.h:1462:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 251 < left 292, rollback = 2 [ 560.904720] Lustre: 19265:0:(osd_handler.c:2097:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 560.914818] Lustre: 19265:0:(osd_handler.c:2104:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 5/292/0 [ 560.927691] Lustre: 19265:0:(osd_handler.c:2114:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 560.933880] Lustre: 19265:0:(osd_handler.c:2121:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 560.938234] Lustre: 19265:0:(osd_handler.c:2128:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 561.395395] Lustre: 20615:0:(osd_internal.h:1462:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 292, rollback = 2 [ 561.413268] Lustre: 20615:0:(osd_internal.h:1462:osd_trans_exec_op()) Skipped 20 previous similar messages [ 561.418249] Lustre: 20615:0:(osd_handler.c:2097:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 561.423308] Lustre: 20615:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 20 previous similar messages [ 561.429253] Lustre: 20615:0:(osd_handler.c:2104:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 5/292/0 [ 561.436454] Lustre: 20615:0:(osd_handler.c:2104:osd_trans_dump_creds()) Skipped 20 previous similar messages [ 561.442335] Lustre: 20615:0:(osd_handler.c:2114:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 561.448854] Lustre: 20615:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 20 previous similar messages [ 561.454332] Lustre: 20615:0:(osd_handler.c:2121:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 561.459328] Lustre: 20615:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 20 previous similar messages [ 561.465639] Lustre: 20615:0:(osd_handler.c:2128:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 561.472017] Lustre: 20615:0:(osd_handler.c:2128:osd_trans_dump_creds()) Skipped 20 previous similar messages [ 562.416716] Lustre: 20615:0:(osd_internal.h:1462:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 292, rollback = 2 [ 562.431712] Lustre: 20615:0:(osd_internal.h:1462:osd_trans_exec_op()) Skipped 53 previous similar messages [ 562.439479] Lustre: 20615:0:(osd_handler.c:2097:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 562.451303] Lustre: 20615:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 53 previous similar messages [ 562.464644] Lustre: 20615:0:(osd_handler.c:2104:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 5/292/0 [ 562.471120] Lustre: 20615:0:(osd_handler.c:2104:osd_trans_dump_creds()) Skipped 53 previous similar messages [ 562.478106] Lustre: 20615:0:(osd_handler.c:2114:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 562.483210] Lustre: 20615:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 53 previous similar messages [ 562.495542] Lustre: 20615:0:(osd_handler.c:2121:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 562.501501] Lustre: 20615:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 53 previous similar messages [ 562.509113] Lustre: 20615:0:(osd_handler.c:2128:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 562.515800] Lustre: 20615:0:(osd_handler.c:2128:osd_trans_dump_creds()) Skipped 53 previous similar messages [ 564.444420] Lustre: 19265:0:(osd_internal.h:1462:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 292, rollback = 2 [ 564.453458] Lustre: 19265:0:(osd_internal.h:1462:osd_trans_exec_op()) Skipped 116 previous similar messages [ 564.459807] Lustre: 19265:0:(osd_handler.c:2097:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 564.464693] Lustre: 19265:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 116 previous similar messages [ 564.472864] Lustre: 19265:0:(osd_handler.c:2104:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 5/292/0 [ 564.478130] Lustre: 19265:0:(osd_handler.c:2104:osd_trans_dump_creds()) Skipped 116 previous similar messages [ 564.487134] Lustre: 19265:0:(osd_handler.c:2114:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 564.492128] Lustre: 19265:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 116 previous similar messages [ 564.499830] Lustre: 19265:0:(osd_handler.c:2121:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 564.505250] Lustre: 19265:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 116 previous similar messages [ 564.552793] Lustre: 19266:0:(osd_handler.c:2128:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 564.557133] Lustre: 19266:0:(osd_handler.c:2128:osd_trans_dump_creds()) Skipped 119 previous similar messages [ 566.795635] Lustre: *** cfs_fail_loc=1600, val=3*** [ 570.490272] Lustre: *** cfs_fail_loc=1600, val=3*** [ 571.325879] Lustre: 21187:0:(osd_internal.h:1462:osd_trans_exec_op()) lustre-OST0001: opcode 2: before 260 < left 274, rollback = 2 [ 571.333542] Lustre: 23800:0:(osd_handler.c:2097:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 571.338436] Lustre: 21187:0:(osd_internal.h:1462:osd_trans_exec_op()) Skipped 89 previous similar messages [ 571.338461] Lustre: 21187:0:(osd_handler.c:2104:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 2/274/0 [ 571.338464] Lustre: 21187:0:(osd_handler.c:2104:osd_trans_dump_creds()) Skipped 88 previous similar messages [ 571.338470] Lustre: 21187:0:(osd_handler.c:2114:osd_trans_dump_creds()) write: 0/0/0, punch: 0/0/0, quota 7/225/0 [ 571.338474] Lustre: 21187:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 88 previous similar messages [ 571.338480] Lustre: 21187:0:(osd_handler.c:2121:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 571.338483] Lustre: 21187:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 88 previous similar messages [ 571.338489] Lustre: 21187:0:(osd_handler.c:2128:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 571.338492] Lustre: 21187:0:(osd_handler.c:2128:osd_trans_dump_creds()) Skipped 85 previous similar messages [ 571.404877] Lustre: 23800:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 97 previous similar messages [ 581.603086] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 581.611128] 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 [ 581.624988] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 582.947223] Lustre: server umount lustre-MDT0000 complete [ 583.145815] 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 [ 583.158745] Lustre: Skipped 2 previous similar messages [ 585.713064] LustreError: 19251:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1790945036 with bad export cookie 4295120569075953292 [ 585.714168] LustreError: MGC192.168.203.132@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 585.720594] LustreError: 19251:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 586.045757] Lustre: server umount lustre-MDT0001 complete [ 599.398443] Lustre: server umount lustre-OST0000 complete [ 612.501245] Lustre: server umount lustre-OST0001 complete [ 618.407795] Lustre: DEBUG MARKER: == sanity-lfsck test 1a: LFSCK can find out and repair crashed FID-in-dirent ========================================================== 08:44:27 (1790945067) [ 628.146130] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing load_modules_local [ 635.150530] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 635.471980] LustreError: 26275:0:(ldlm_lib.c:1199: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. [ 635.489831] LustreError: 26275:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 5 previous similar messages [ 635.517620] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 638.316827] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 640.994377] LustreError: 26276:0:(ldlm_lib.c:1199: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. [ 643.736773] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 643.930761] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 646.905336] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 648.949573] Lustre: 27413:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 653.424720] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 654.625191] LustreError: 27766:0:(ldlm_lib.c:1199: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. [ 658.009846] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 659.746907] LustreError: 27868:0:(ldlm_lib.c:1199: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. [ 659.762225] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:40 to 0x280000401:65) [ 664.097986] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 664.218020] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 664.223361] Lustre: Skipped 1 previous similar message [ 668.198557] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 669.672439] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:41 to 0x2c0000401:65) [ 673.360791] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 675.338605] Lustre: 29282:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 676.272217] Lustre: 29041:0:(osd_internal.h:1462:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 292, rollback = 2 [ 676.277263] Lustre: 29041:0:(osd_internal.h:1462:osd_trans_exec_op()) Skipped 64 previous similar messages [ 676.281614] Lustre: 29041:0:(osd_handler.c:2097:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 676.285406] Lustre: 29041:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 56 previous similar messages [ 676.290780] Lustre: 29041:0:(osd_handler.c:2104:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 5/292/0 [ 676.295513] Lustre: 29041:0:(osd_handler.c:2104:osd_trans_dump_creds()) Skipped 65 previous similar messages [ 676.300212] Lustre: 29041:0:(osd_handler.c:2114:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 676.304936] Lustre: 29041:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 65 previous similar messages [ 676.309398] Lustre: 29041:0:(osd_handler.c:2121:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 676.314446] Lustre: 29041:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 65 previous similar messages [ 676.319572] Lustre: 29041:0:(osd_handler.c:2128:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 676.324210] Lustre: 29041:0:(osd_handler.c:2128:osd_trans_dump_creds()) Skipped 65 previous similar messages [ 680.018593] Lustre: *** cfs_fail_loc=1501, val=0*** [ 685.225948] Lustre: Failing over lustre-MDT0000 [ 685.401637] Lustre: server umount lustre-MDT0000 complete [ 690.144817] 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 [ 690.148360] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 690.153447] LustreError: 29041:0:(ldlm_lib.c:1199: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. [ 690.153460] LustreError: 29041:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 2 previous similar messages [ 690.154322] Lustre: Skipped 2 previous similar messages [ 692.455687] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 692.559645] LustreError: MGC192.168.203.132@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 692.731263] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 695.650171] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 697.363709] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 697.375606] Lustre: lustre-MDT0000: Denying connection for new client 4fb973fb-171a-4376-9302-6d8060d1a10c (at 192.168.203.32@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 1:00 [ 697.831904] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 697.845457] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 697.872747] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:105 to 0x2c0000401:129) [ 697.877625] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:105 to 0x280000401:129) [ 703.268859] Lustre: *** cfs_fail_loc=1505, val=0*** [ 709.120370] Lustre: DEBUG MARKER: == sanity-lfsck test 1b: LFSCK can find out and repair the missing FID-in-LMA ========================================================== 08:45:58 (1790945158) [ 710.095760] Lustre: 29041:0:(osd_internal.h:1462:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 292, rollback = 2 [ 710.103378] Lustre: 29041:0:(osd_internal.h:1462:osd_trans_exec_op()) Skipped 322 previous similar messages [ 710.108347] Lustre: 29041:0:(osd_handler.c:2097:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 710.113347] Lustre: 29041:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 710.121063] Lustre: 29041:0:(osd_handler.c:2104:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 5/292/0 [ 710.133656] Lustre: 29041:0:(osd_handler.c:2104:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 710.140744] Lustre: 29041:0:(osd_handler.c:2114:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 710.147957] Lustre: 29041:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 710.161508] Lustre: 29041:0:(osd_handler.c:2121:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 710.166389] Lustre: 29041:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 710.171413] Lustre: 29041:0:(osd_handler.c:2128:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 710.178312] Lustre: 29041:0:(osd_handler.c:2128:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 714.574922] Lustre: *** cfs_fail_loc=1502, val=0*** [ 721.428104] Lustre: Failing over lustre-MDT0000 [ 721.616822] Lustre: server umount lustre-MDT0000 complete [ 723.423421] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 723.425696] 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 [ 723.430216] LustreError: 29041:0:(ldlm_lib.c:1199: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.430225] LustreError: 29041:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 3 previous similar messages [ 723.488276] Lustre: Skipped 3 previous similar messages [ 729.146899] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 729.313549] LustreError: MGC192.168.203.132@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 729.551163] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 729.554494] Lustre: Skipped 1 previous similar message [ 729.594574] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 732.739340] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 734.678536] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 734.692757] Lustre: lustre-MDT0000: Denying connection for new client 7b6363f8-62e9-40e2-aa69-d879441b0b40 (at 192.168.203.32@tcp), waiting for 1 known clients (0 recovered, 1 in progress, and 0 evicted) to recover in 1:09 [ 734.710450] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 734.718535] Lustre: Skipped 3 previous similar messages [ 734.735796] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 734.779456] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:169 to 0x2c0000401:193) [ 734.786576] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:169 to 0x280000401:193) [ 740.835710] Lustre: *** cfs_fail_loc=1505, val=0*** [ 747.244774] Lustre: DEBUG MARKER: == sanity-lfsck test 1c: LFSCK can find out and repair lost FID-in-dirent ========================================================== 08:46:36 (1790945196) [ 748.817663] Lustre: 29041:0:(osd_internal.h:1462:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 256 < left 292, rollback = 2 [ 748.824329] Lustre: 29041:0:(osd_internal.h:1462:osd_trans_exec_op()) Skipped 321 previous similar messages [ 748.829105] Lustre: 29041:0:(osd_handler.c:2097:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 748.835753] Lustre: 29041:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 748.843785] Lustre: 29041:0:(osd_handler.c:2104:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 5/292/0 [ 748.851346] Lustre: 29041:0:(osd_handler.c:2104:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 748.859025] Lustre: 29041:0:(osd_handler.c:2114:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 748.868381] Lustre: 29041:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 748.876492] Lustre: 29041:0:(osd_handler.c:2121:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 748.887880] Lustre: 29041:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 748.894513] Lustre: 29041:0:(osd_handler.c:2128:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 748.901407] Lustre: 29041:0:(osd_handler.c:2128:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 753.043407] Lustre: *** cfs_fail_loc=1504, val=0*** [ 753.048626] Lustre: *** cfs_fail_loc=1504, val=0*** [ 753.056569] Lustre: Skipped 1 previous similar message [ 759.329820] Lustre: Failing over lustre-MDT0000 [ 759.527540] Lustre: server umount lustre-MDT0000 complete [ 760.287963] 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 [ 760.292341] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 760.301462] Lustre: Skipped 1 previous similar message [ 760.303612] LustreError: 26270:0:(ldlm_lib.c:1199: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. [ 760.303623] LustreError: 26270:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 7 previous similar messages [ 768.307965] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 768.412667] LustreError: MGC192.168.203.132@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 768.684781] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 772.488889] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 774.120571] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 774.147375] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 774.151222] Lustre: Skipped 3 previous similar messages [ 774.185554] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 774.230818] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:233 to 0x2c0000401:257) [ 774.238311] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:233 to 0x280000401:257) [ 775.277828] Lustre: *** cfs_fail_loc=1505, val=0*** [ 781.581065] Lustre: DEBUG MARKER: == sanity-lfsck test 2a: LFSCK can find out and repair crashed linkEA entry ========================================================== 08:47:10 (1790945230) [ 786.954792] Lustre: *** cfs_fail_loc=1603, val=0*** [ 793.407646] Lustre: Failing over lustre-MDT0000 [ 793.594783] Lustre: server umount lustre-MDT0000 complete [ 794.591917] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 794.592759] 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 [ 794.602313] LustreError: 26276:0:(ldlm_lib.c:1199: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. [ 794.602323] LustreError: 26276:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 7 previous similar messages [ 794.633856] Lustre: Skipped 6 previous similar messages [ 802.358626] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 802.435696] LustreError: MGC192.168.203.132@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 802.573228] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 802.576400] Lustre: Skipped 1 previous similar message [ 802.598703] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 806.370912] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 807.907288] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 807.918296] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 807.930766] Lustre: Skipped 3 previous similar messages [ 807.954178] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 808.015632] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:297 to 0x2c0000401:321) [ 808.018350] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:297 to 0x280000401:321) [ 815.141807] Lustre: DEBUG MARKER: == sanity-lfsck test 2b: LFSCK can find out and remove invalid linkEA entry ========================================================== 08:47:44 (1790945264) [ 816.334731] Lustre: 26270:0:(osd_internal.h:1462:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 292, rollback = 2 [ 816.342101] Lustre: 26270:0:(osd_internal.h:1462:osd_trans_exec_op()) Skipped 644 previous similar messages [ 816.349377] Lustre: 26270:0:(osd_handler.c:2097:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 816.358609] Lustre: 26270:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 816.364385] Lustre: 26270:0:(osd_handler.c:2104:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 5/292/0 [ 816.369702] Lustre: 26270:0:(osd_handler.c:2104:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 816.375852] Lustre: 26270:0:(osd_handler.c:2114:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 816.386682] Lustre: 26270:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 816.393891] Lustre: 26270:0:(osd_handler.c:2121:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 816.405119] Lustre: 26270:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 816.414554] Lustre: 26270:0:(osd_handler.c:2128:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 816.424174] Lustre: 26270:0:(osd_handler.c:2128:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 820.807396] Lustre: *** cfs_fail_loc=1604, val=0*** [ 828.328098] Lustre: Failing over lustre-MDT0000 [ 828.384503] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 828.386320] 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 [ 828.399790] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 828.408455] Lustre: Skipped 3 previous similar messages [ 828.418294] Lustre: Skipped 3 previous similar messages [ 828.715661] Lustre: server umount lustre-MDT0000 complete [ 839.207742] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 839.389782] LustreError: MGC192.168.203.132@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 839.781729] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 844.550674] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 844.770459] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 844.783356] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 844.787706] Lustre: Skipped 3 previous similar messages [ 844.805297] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 844.855535] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:361 to 0x2c0000401:385) [ 844.857125] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:361 to 0x280000401:385) [ 855.280274] Lustre: DEBUG MARKER: == sanity-lfsck test 2c: LFSCK can find out and remove repeated linkEA entry ========================================================== 08:48:24 (1790945304) [ 861.257472] Lustre: *** cfs_fail_loc=1605, val=0*** [ 869.378045] Lustre: Failing over lustre-MDT0000 [ 869.928717] Lustre: server umount lustre-MDT0000 complete [ 870.378017] 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 [ 870.378442] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 870.392601] LustreError: 34135:0:(ldlm_lib.c:1199: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. [ 870.392612] LustreError: 34135:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 15 previous similar messages [ 870.394630] Lustre: Skipped 3 previous similar messages [ 881.108627] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 881.261492] LustreError: MGC192.168.203.132@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 881.616175] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 885.860474] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 886.757475] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 886.761183] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 886.785652] Lustre: Skipped 3 previous similar messages [ 886.823490] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 886.879200] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:425 to 0x2c0000401:449) [ 886.891677] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:425 to 0x280000401:449) [ 894.054970] Lustre: DEBUG MARKER: == sanity-lfsck test 2d: LFSCK can recover the missing linkEA entry ========================================================== 08:49:03 (1790945343) [ 900.019818] Lustre: *** cfs_fail_loc=161d, val=0*** [ 908.741435] Lustre: Failing over lustre-MDT0000 [ 909.031052] Lustre: server umount lustre-MDT0000 complete [ 912.353298] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 920.392847] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 920.548383] LustreError: MGC192.168.203.132@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 920.733965] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 924.451955] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 926.176623] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 926.188313] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 926.218273] Lustre: Skipped 3 previous similar messages [ 926.251556] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 926.306351] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:489 to 0x2c0000401:513) [ 926.308331] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:489 to 0x280000401:513) [ 933.959329] Lustre: DEBUG MARKER: == sanity-lfsck test 2e: namespace LFSCK can verify remote object linkEA ========================================================== 08:49:42 (1790945382) [ 936.275457] Lustre: *** cfs_fail_loc=1603, val=0*** [ 946.546323] Lustre: DEBUG MARKER: == sanity-lfsck test 3: LFSCK can verify multiple-linked objects ========================================================== 08:49:55 (1790945395) [ 946.888300] Lustre: 33830:0:(osd_internal.h:1462:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 292, rollback = 2 [ 946.892937] Lustre: 33830:0:(osd_internal.h:1462:osd_trans_exec_op()) Skipped 976 previous similar messages [ 946.900649] Lustre: 33830:0:(osd_handler.c:2097:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 946.907300] Lustre: 33830:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 976 previous similar messages [ 946.915567] Lustre: 33830:0:(osd_handler.c:2104:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 5/292/0 [ 946.922456] Lustre: 33830:0:(osd_handler.c:2104:osd_trans_dump_creds()) Skipped 976 previous similar messages [ 946.932878] Lustre: 33830:0:(osd_handler.c:2114:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 946.945018] Lustre: 33830:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 976 previous similar messages [ 946.953881] Lustre: 33830:0:(osd_handler.c:2121:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 946.964421] Lustre: 33830:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 976 previous similar messages [ 946.976877] Lustre: 33830:0:(osd_handler.c:2128:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 946.989259] Lustre: 33830:0:(osd_handler.c:2128:osd_trans_dump_creds()) Skipped 976 previous similar messages [ 951.702127] Lustre: *** cfs_fail_loc=1603, val=0*** [ 952.617302] Lustre: *** cfs_fail_loc=1604, val=0*** [ 962.827074] Lustre: DEBUG MARKER: == sanity-lfsck test 4: FID-in-dirent can be rebuilt after MDT file-level backup/restore ========================================================== 08:50:11 (1790945411) [ 997.868891] Lustre: Failing over lustre-MDT0000 [ 998.223209] Lustre: server umount lustre-MDT0000 complete [ 1002.975642] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1002.981146] 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 [ 1002.983435] LustreError: 26272:0:(ldlm_lib.c:1199: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. [ 1002.998265] Lustre: Skipped 7 previous similar messages [ 1003.017555] LustreError: 26272:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 21 previous similar messages [ 1003.789837] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1011.676859] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1018.842037] Lustre: 16412:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790945453/real 1790945453] req@ffff9ab48e2e4a80 x1877941808726912/t0(0) o400->MGC192.168.203.132@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1790945469 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1018.878632] LustreError: MGC192.168.203.132@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1021.473274] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1021.498337] Lustre: lustre-MDT0000: reset Object Index mappings [ 1029.308353] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1029.310813] Lustre: Skipped 3 previous similar messages [ 1029.337878] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1033.497423] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1034.725189] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1034.732724] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1034.760713] Lustre: Skipped 3 previous similar messages [ 1034.790561] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1034.829962] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:592 to 0x280000401:609) [ 1034.832224] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:592 to 0x2c0000401:609) [ 1036.501963] LustreError: 42918:0:(lfsck_engine.c:1018:lfsck_master_engine()) lustre-MDT0000-osd: master engine fail to verify the .lustre/lost+found/, go ahead: rc = -115 [ 1036.516376] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1038.562274] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1038.568755] Lustre: Skipped 1 previous similar message [ 1045.713649] Lustre: Failing over lustre-MDT0000 [ 1046.165776] Lustre: server umount lustre-MDT0000 complete [ 1056.779819] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1061.324374] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1062.421811] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:592 to 0x2c0000401:641) [ 1062.423952] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:592 to 0x280000401:641) [ 1063.835893] Lustre: *** cfs_fail_loc=1505, val=0*** [ 1069.379739] Lustre: DEBUG MARKER: == sanity-lfsck test 5: LFSCK can handle IGIF object upgrading ========================================================== 08:51:58 (1790945518) [ 1071.555062] Lustre: *** cfs_fail_loc=1504, val=0*** [ 1079.062261] Lustre: Failing over lustre-MDT0000 [ 1079.233928] Lustre: server umount lustre-MDT0000 complete [ 1083.413789] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1091.391676] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1099.232686] Lustre: 16413:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790945533/real 1790945533] req@ffff9ab5b7297480 x1877941808818176/t0(0) o400->MGC192.168.203.132@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1790945549 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1100.396282] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1100.430762] Lustre: lustre-MDT0000: reset Object Index mappings [ 1109.476499] LustreError: 16410:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9ab5a0832d80 x1877941808827648/t0(0) o250->MGC192.168.203.132@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 0 ref 1 fl Rpc:NQU/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1109.786090] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1109.792087] Lustre: Skipped 1 previous similar message [ 1112.987195] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1115.106917] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1115.108732] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1115.118049] Lustre: Skipped 1 previous similar message [ 1115.123318] Lustre: Skipped 7 previous similar messages [ 1115.137612] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1115.147172] Lustre: Skipped 1 previous similar message [ 1115.213473] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:681 to 0x2c0000401:705) [ 1115.218353] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:681 to 0x280000401:705) [ 1115.962911] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1115.973924] Lustre: Skipped 2 previous similar messages [ 1128.768982] Lustre: Failing over lustre-MDT0000 [ 1129.027828] Lustre: server umount lustre-MDT0000 complete [ 1137.171629] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1141.808056] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1142.804198] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:681 to 0x280000401:737) [ 1142.817565] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:681 to 0x2c0000401:737) [ 1144.739618] Lustre: *** cfs_fail_loc=1505, val=0*** [ 1144.743368] Lustre: Skipped 84 previous similar messages [ 1150.471880] Lustre: DEBUG MARKER: == sanity-lfsck test 6a: LFSCK resumes from last checkpoint (1) ========================================================== 08:53:19 (1790945599) [ 1156.632431] Lustre: *** cfs_fail_loc=1600, val=1*** [ 1156.633983] Lustre: Skipped 7 previous similar messages [ 1173.096726] Lustre: DEBUG MARKER: == sanity-lfsck test 6b: LFSCK resumes from last checkpoint (2) ========================================================== 08:53:42 (1790945622) [ 1180.882702] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1180.887127] Lustre: Skipped 8 previous similar messages [ 1206.198176] Lustre: 29420:0:(osd_internal.h:1462:osd_trans_exec_op()) lustre-OST0001: opcode 2: before 259 < left 274, rollback = 2 [ 1206.198245] Lustre: 29418:0:(osd_handler.c:2097:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 1206.205047] Lustre: 29420:0:(osd_internal.h:1462:osd_trans_exec_op()) Skipped 1670 previous similar messages [ 1206.205068] Lustre: 29420:0:(osd_handler.c:2104:osd_trans_dump_creds()) attr_set: 1/1/1, xattr_set: 2/274/0 [ 1206.205072] Lustre: 29420:0:(osd_handler.c:2104:osd_trans_dump_creds()) Skipped 1669 previous similar messages [ 1206.205077] Lustre: 29420:0:(osd_handler.c:2114:osd_trans_dump_creds()) write: 0/0/0, punch: 0/0/0, quota 7/225/0 [ 1206.205081] Lustre: 29420:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1669 previous similar messages [ 1206.205087] Lustre: 29420:0:(osd_handler.c:2121:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 1206.205090] Lustre: 29420:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1669 previous similar messages [ 1206.205267] Lustre: 29420:0:(osd_handler.c:2128:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 1206.205272] Lustre: 29420:0:(osd_handler.c:2128:osd_trans_dump_creds()) Skipped 1669 previous similar messages [ 1206.237533] Lustre: DEBUG MARKER: == sanity-lfsck test 7a: non-stopped LFSCK should auto restarts after MDS remount (1) ========================================================== 08:54:14 (1790945654) [ 1206.247485] Lustre: 29418:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1679 previous similar messages [ 1215.921291] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1215.934423] Lustre: Skipped 12 previous similar messages [ 1221.478719] Lustre: Failing over lustre-MDT0000 [ 1221.791954] Lustre: server umount lustre-MDT0000 complete [ 1224.681815] 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 [ 1224.699492] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1224.700865] Lustre: Skipped 15 previous similar messages [ 1224.732124] LustreError: Skipped 2 previous similar messages [ 1231.002909] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1231.105593] LustreError: MGC192.168.203.132@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1231.113333] LustreError: Skipped 3 previous similar messages [ 1235.782299] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1236.559273] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:853 to 0x280000401:897) [ 1236.573977] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:854 to 0x2c0000401:897) [ 1246.134379] Lustre: DEBUG MARKER: == sanity-lfsck test 7b: non-stopped LFSCK should auto restarts after MDS remount (2) ========================================================== 08:54:55 (1790945695) [ 1259.006358] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing load_modules_local [ 1275.534670] Lustre: 53027:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 1295.236106] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1298.165645] Lustre: 54163:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 1304.202119] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1304.208941] Lustre: Skipped 81 previous similar messages [ 1306.513279] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1307.556096] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1308.576335] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1310.395678] Lustre: Failing over lustre-MDT0000 [ 1310.688063] Lustre: server umount lustre-MDT0000 complete [ 1313.248791] LustreError: 29297:0:(ldlm_lib.c:1199: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. [ 1313.266424] LustreError: 29297:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 76 previous similar messages [ 1318.644214] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1318.943979] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1318.947213] Lustre: Skipped 4 previous similar messages [ 1318.983452] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1318.994453] Lustre: Skipped 2 previous similar messages [ 1322.842822] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1324.011135] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1324.016725] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1324.024134] Lustre: Skipped 2 previous similar messages [ 1324.041445] Lustre: Skipped 11 previous similar messages [ 1324.058680] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1324.064234] Lustre: Skipped 2 previous similar messages [ 1324.135778] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:946 to 0x2c0000401:961) [ 1324.139464] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:947 to 0x280000401:993) [ 1330.844492] Lustre: DEBUG MARKER: == sanity-lfsck test 8: LFSCK state machine ============== 08:56:19 (1790945779) [ 1334.242147] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1334.256472] Lustre: Skipped 3 previous similar messages [ 1339.360354] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1339.366383] Lustre: Skipped 3 previous similar messages [ 1344.484331] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1344.488811] Lustre: Skipped 3 previous similar messages [ 1347.039261] Lustre: lustre-MDT0000 is waiting for obd_unlinked_exports more than 8 seconds. The obd refcount = 3. Is it stuck? [ 1347.322206] Lustre: server umount lustre-MDT0000 complete [ 1350.767679] LustreError: 30941:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1790945801 with bad export cookie 4295120569076167114 [ 1350.781519] LustreError: 30941:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 1351.092514] Lustre: server umount lustre-MDT0001 complete [ 1365.304320] Lustre: server umount lustre-OST0000 complete [ 1379.808967] Lustre: server umount lustre-OST0001 complete [ 1387.014459] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_hostid [ 1395.905464] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing load_modules_local [ 1442.804420] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing load_modules_local [ 1452.847652] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1453.079566] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 1453.107639] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 1453.183462] Lustre: lustre-MDT0000: new disk, initializing [ 1453.300814] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 1457.695564] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1468.203828] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1468.313802] Lustre: 59226: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 [ 1468.372809] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 1468.378262] Lustre: Skipped 1 previous similar message [ 1468.465602] Lustre: lustre-MDT0001: new disk, initializing [ 1468.570064] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 1468.587700] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 1472.543577] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1476.909621] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 1483.134911] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 1483.338693] Lustre: lustre-OST0000: new disk, initializing [ 1483.341595] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 1483.347570] Lustre: 60857:0:(osd_compat.c:1354:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 1484.634403] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 1484.656450] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 1484.750653] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 1489.191040] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1499.048491] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 1499.193382] Lustre: lustre-OST0001: new disk, initializing [ 1499.204454] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 1499.217064] Lustre: 61726:0:(osd_compat.c:1354:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 1501.186297] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 1501.217401] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 1501.273967] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 1505.239749] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1515.289036] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1519.663803] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 1530.531031] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1531.650817] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1531.652885] Lustre: Skipped 19 previous similar messages [ 1535.966367] Lustre: *** cfs_fail_loc=1601, val=2*** [ 1535.969367] Lustre: Skipped 5 previous similar messages [ 1553.422796] Lustre: Failing over lustre-MDT0000 [ 1553.823036] Lustre: server umount lustre-MDT0000 complete [ 1555.935884] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1555.948891] LustreError: Skipped 1 previous similar message [ 1555.954691] 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 [ 1555.984386] Lustre: Skipped 8 previous similar messages [ 1562.371028] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1562.482964] LustreError: MGC192.168.203.132@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1562.491930] LustreError: Skipped 2 previous similar messages [ 1562.597509] Lustre: lustre-MDT0000: Not available for connect from 0@lo (not set up) [ 1562.604394] Lustre: Skipped 3 previous similar messages [ 1566.512356] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1568.299566] Lustre: *** cfs_fail_loc=160b, val=2*** [ 1568.308747] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:65) [ 1568.311258] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:65) [ 1574.593961] Lustre: Failing over lustre-MDT0000 [ 1574.849469] Lustre: server umount lustre-MDT0000 complete [ 1583.402259] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1583.865666] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1583.881446] Lustre: Skipped 1 previous similar message [ 1589.059569] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1589.225076] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1589.232192] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1589.234029] Lustre: Skipped 1 previous similar message [ 1589.237825] Lustre: Skipped 7 previous similar messages [ 1589.259317] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1589.270095] Lustre: Skipped 1 previous similar message [ 1589.304389] Lustre: *** cfs_fail_loc=160b, val=2*** [ 1589.327724] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:97) [ 1589.333041] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:97) [ 1594.665841] Lustre: Failing over lustre-MDT0000 [ 1595.518361] Lustre: server umount lustre-MDT0000 complete [ 1603.061741] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1607.653240] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1608.730579] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:129) [ 1608.730685] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:129) [ 1613.781217] Lustre: *** cfs_fail_loc=1602, val=2*** [ 1613.783381] Lustre: Skipped 1 previous similar message [ 1625.078930] Lustre: DEBUG MARKER: == sanity-lfsck test 9a: LFSCK speed control (1) ========= 09:01:14 (1790946074) [ 1638.518701] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing load_modules_local [ 1653.617877] Lustre: 68700:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 1673.081814] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1718.203791] Lustre: 59232:0:(osd_internal.h:1462:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 292, rollback = 2 [ 1718.210246] Lustre: 59232:0:(osd_internal.h:1462:osd_trans_exec_op()) Skipped 10330 previous similar messages [ 1718.217042] Lustre: 59232:0:(osd_handler.c:2097:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 1718.222858] Lustre: 59232:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 10322 previous similar messages [ 1718.227444] Lustre: 59232:0:(osd_handler.c:2104:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 5/292/0 [ 1718.232125] Lustre: 59232:0:(osd_handler.c:2104:osd_trans_dump_creds()) Skipped 10332 previous similar messages [ 1718.237132] Lustre: 59232:0:(osd_handler.c:2114:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 1718.245162] Lustre: 59232:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 10332 previous similar messages [ 1718.251325] Lustre: 59232:0:(osd_handler.c:2121:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 1718.255670] Lustre: 59232:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 10332 previous similar messages [ 1718.268725] Lustre: 59232:0:(osd_handler.c:2128:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 1718.274276] Lustre: 59232:0:(osd_handler.c:2128:osd_trans_dump_creds()) Skipped 10332 previous similar messages [ 1777.862539] Lustre: DEBUG MARKER: == sanity-lfsck test 9b: LFSCK speed control (2) ========= 09:03:47 (1790946227) [ 1819.571715] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1819.573298] Lustre: Skipped 4 previous similar messages [ 1839.992322] Lustre: *** cfs_fail_loc=160c, val=0*** [ 1839.998280] Lustre: Skipped 8 previous similar messages [ 1873.925290] Lustre: DEBUG MARKER: == sanity-lfsck test 10: System is available during LFSCK scanning ========================================================== 09:05:23 (1790946323) [ 1917.811138] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1925.831080] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1925.836198] Lustre: Skipped 462 previous similar messages [ 1941.844648] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1941.848119] Lustre: Skipped 936 previous similar messages [ 1973.847245] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1973.850492] Lustre: Skipped 1807 previous similar messages [ 1979.662195] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1979.664231] Lustre: Skipped 2599 previous similar messages [ 2205.815700] Lustre: DEBUG MARKER: == sanity-lfsck test 11a: LFSCK can rebuild lost last_id ========================================================== 09:10:54 (1790946654) [ 2342.505589] Lustre: 61861:0:(osd_internal.h:1462:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 292, rollback = 2 [ 2342.515742] Lustre: 61861:0:(osd_internal.h:1462:osd_trans_exec_op()) Skipped 28585 previous similar messages [ 2342.526557] Lustre: 61861:0:(osd_handler.c:2097:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 2342.534527] Lustre: 61861:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 28585 previous similar messages [ 2342.540846] Lustre: 61861:0:(osd_handler.c:2104:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 5/292/0 [ 2342.553223] Lustre: 61861:0:(osd_handler.c:2104:osd_trans_dump_creds()) Skipped 28585 previous similar messages [ 2342.561227] Lustre: 61861:0:(osd_handler.c:2114:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 2342.567631] Lustre: 61861:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 28585 previous similar messages [ 2342.573037] Lustre: 61861:0:(osd_handler.c:2121:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 2342.579225] Lustre: 61861:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 28585 previous similar messages [ 2342.585614] Lustre: 61861:0:(osd_handler.c:2128:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 2342.591127] Lustre: 61861:0:(osd_handler.c:2128:osd_trans_dump_creds()) Skipped 28585 previous similar messages [ 2351.077416] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 2351.089112] 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 [ 2351.093798] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2351.112555] Lustre: Skipped 12 previous similar messages [ 2351.131352] Lustre: Skipped 3 previous similar messages [ 2354.483196] Lustre: server umount lustre-MDT0000 complete [ 2356.193068] LustreError: 60852:0:(ldlm_lib.c:1199: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. [ 2356.218100] LustreError: 60852:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 28 previous similar messages [ 2357.830724] LustreError: MGC192.168.203.132@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2357.830242] LustreError: 59217:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1790946808 with bad export cookie 4295120569076186217 [ 2357.837709] LustreError: Skipped 2 previous similar messages [ 2357.851684] LustreError: 59217:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 2358.245231] Lustre: server umount lustre-MDT0001 complete [ 2372.133395] Lustre: server umount lustre-OST0000 complete [ 2386.528593] Lustre: server umount lustre-OST0001 complete [ 2392.353119] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: (null) [ 2400.199253] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 2415.776622] LustreError: Failed to get MGS log lustre-sptlrpc and no local copy. [ 2420.896192] LustreError: 75461:0:(mgc_request.c:233:do_config_log_add()) MGC192.168.203.132@tcp: failed processing log, type 4: rc = -110 [ 2446.495513] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 2446.511928] Lustre: Skipped 7 previous similar messages [ 2453.931961] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2457.921552] Lustre: 76044: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. [ 2457.941396] Lustre: *** cfs_fail_loc=160e, val=3*** [ 2460.964619] Lustre: 76044:0:(ofd_dev.c:573:ofd_lfsck_out_notify()) lustre-OST0000: Rebuilt crashed LAST_ID files successfully. [ 2468.447889] Lustre: DEBUG MARKER: == sanity-lfsck test 11b: LFSCK can rebuild crashed last_id ========================================================== 09:15:17 (1790946917) [ 2482.194894] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing load_modules_local [ 2492.485951] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2492.613384] LustreError: 16410:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9ab5abeb5500 x1877941812874496/t0(0) o250->MGC192.168.203.132@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 0 ref 1 fl Rpc:NQU/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2493.109623] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3271 to 0x280000401:3297) [ 2497.423841] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2505.706625] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2510.799823] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2513.662319] Lustre: 78707:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 2513.669287] Lustre: 78707:0:(mgs_llog.c:1450:mgs_modify_param()) Skipped 1 previous similar message [ 2528.916666] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2529.098664] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 2529.106150] Lustre: Skipped 2 previous similar messages [ 2534.379158] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3208 to 0x2c0000401:3233) [ 2534.889626] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2542.435984] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 2545.506747] Lustre: 80208:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 2549.766489] Lustre: *** cfs_fail_loc=160d, val=0*** [ 2556.347670] Lustre: Failing over lustre-OST0000 [ 2556.510358] Lustre: server umount lustre-OST0000 complete [ 2565.618634] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2565.826388] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 2565.843657] Lustre: Skipped 1 previous similar message [ 2567.264499] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 2567.273377] Lustre: Skipped 1 previous similar message [ 2567.286236] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 2567.286728] Lustre: lustre-OST0000-osc-MDT0001: Connection restored to 0@lo (at 0@lo) [ 2567.289049] Lustre: *** cfs_fail_loc=215, val=0*** [ 2567.296434] Lustre: Skipped 1 previous similar message [ 2567.324518] Lustre: Skipped 7 previous similar messages [ 2572.592239] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2572.771187] Lustre: *** cfs_fail_loc=215, val=0*** [ 2572.787167] Lustre: Skipped 4 previous similar messages [ 2576.732347] Lustre: 81619: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. [ 2576.752636] Lustre: 81619:0:(ofd_dev.c:573:ofd_lfsck_out_notify()) lustre-OST0000: Rebuilt crashed LAST_ID files successfully. [ 2577.892624] Lustre: *** cfs_fail_loc=215, val=0*** [ 2577.897876] Lustre: Skipped 1 previous similar message [ 2579.782479] Lustre: Failing over lustre-OST0000 [ 2579.963791] Lustre: server umount lustre-OST0000 complete [ 2588.897469] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2590.918907] Lustre: *** cfs_fail_loc=215, val=0*** [ 2590.923523] Lustre: Skipped 1 previous similar message [ 2595.756529] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2596.319950] Lustre: *** cfs_fail_loc=215, val=0*** [ 2596.326203] Lustre: Skipped 1 previous similar message [ 2603.488477] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2607.964686] Lustre: server umount lustre-MDT0000 complete [ 2611.981201] LustreError: 75468:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1790947062 with bad export cookie 4295120569077745439 [ 2612.002833] LustreError: 75468:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 2612.379717] Lustre: server umount lustre-MDT0001 complete [ 2625.583835] Lustre: server umount lustre-OST0000 complete [ 2639.600115] Lustre: server umount lustre-OST0001 complete [ 2648.140134] Lustre: DEBUG MARKER: == sanity-lfsck test 12a: single command to trigger LFSCK on all devices ========================================================== 09:18:17 (1790947097) [ 2663.354994] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing load_modules_local [ 2674.265853] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2674.770775] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 2674.779607] Lustre: Skipped 2 previous similar messages [ 2678.633794] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2687.817139] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2693.312288] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2696.172907] Lustre: 86001:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 2703.009630] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2709.605569] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2717.625310] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2719.865727] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3208 to 0x2c0000401:3265) [ 2719.891791] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3362 to 0x280000401:3393) [ 2724.872698] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2732.175876] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 2735.864325] Lustre: 87871:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 2770.292492] Lustre: DEBUG MARKER: == sanity-lfsck test 12b: auto detect Lustre device ====== 09:20:19 (1790947219) [ 2783.638129] Lustre: DEBUG MARKER: == sanity-lfsck test 13: LFSCK can repair crashed lmm_oi ========================================================== 09:20:32 (1790947232) [ 2784.882443] Lustre: *** cfs_fail_loc=160f, val=0*** [ 2795.875200] Lustre: DEBUG MARKER: == sanity-lfsck test 14a: LFSCK can repair MDT-object with dangling LOV EA reference (1) ========================================================== 09:20:44 (1790947244) [ 2799.858497] Lustre: *** cfs_fail_loc=1610, val=0*** [ 2799.865711] Lustre: Skipped 7 previous similar messages [ 2852.329643] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2852.348640] Lustre: Skipped 4 previous similar messages [ 2854.630360] Lustre: server umount lustre-MDT0000 complete [ 2858.949209] LustreError: 84842:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1790947309 with bad export cookie 4295120569077753895 [ 2858.979945] LustreError: 84842:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 2859.637042] Lustre: server umount lustre-MDT0001 complete [ 2874.154269] Lustre: server umount lustre-OST0000 complete [ 2887.775781] Lustre: server umount lustre-OST0001 complete [ 2903.348315] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing load_modules_local [ 2913.645699] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2918.650096] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2928.378025] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2932.688316] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2935.202384] Lustre: 93736:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 2941.453845] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2941.703906] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 2941.712752] Lustre: Skipped 5 previous similar messages [ 2947.244821] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2953.962107] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:116 to 0x280000400:161) [ 2955.455101] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2959.761064] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3554 to 0x280000401:3585) [ 2959.783058] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3317 to 0x2c0000401:3361) [ 2959.831351] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:116 to 0x2c0000400:161) [ 2961.563859] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2968.192772] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 2978.751141] Lustre: DEBUG MARKER: == sanity-lfsck test 14b: LFSCK can repair MDT-object with dangling LOV EA reference (2) ========================================================== 09:23:47 (1790947427) [ 2980.158239] Lustre: 92591:0:(osd_internal.h:1462:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 256 < left 292, rollback = 2 [ 2980.165427] Lustre: 92591:0:(osd_internal.h:1462:osd_trans_exec_op()) Skipped 1361 previous similar messages [ 2980.171138] Lustre: 92591:0:(osd_handler.c:2097:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 2980.175826] Lustre: 92591:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1361 previous similar messages [ 2980.182343] Lustre: 92591:0:(osd_handler.c:2104:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 5/292/0 [ 2980.188140] Lustre: 92591:0:(osd_handler.c:2104:osd_trans_dump_creds()) Skipped 1361 previous similar messages [ 2980.194036] Lustre: 92591:0:(osd_handler.c:2114:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 2980.199516] Lustre: 92591:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1361 previous similar messages [ 2980.210891] Lustre: 92591:0:(osd_handler.c:2121:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 2980.218926] Lustre: 92591:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1361 previous similar messages [ 2980.231145] Lustre: 92591:0:(osd_handler.c:2128:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 2980.238218] Lustre: 92591:0:(osd_handler.c:2128:osd_trans_dump_creds()) Skipped 1361 previous similar messages [ 2983.351538] Lustre: *** cfs_fail_loc=1610, val=0*** [ 2983.356038] Lustre: Skipped 63 previous similar messages [ 3005.407904] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3005.418305] LustreError: Skipped 4 previous similar messages [ 3005.427211] 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 [ 3005.446243] Lustre: Skipped 14 previous similar messages [ 3005.453895] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3005.458087] Lustre: Skipped 4 previous similar messages [ 3011.597491] Lustre: server umount lustre-MDT0000 complete [ 3015.546331] LustreError: 92578:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1790947466 with bad export cookie 4295120569077782308 [ 3015.552032] LustreError: MGC192.168.203.132@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3015.558891] LustreError: 92578:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 3 previous similar messages [ 3015.572390] LustreError: Skipped 2 previous similar messages [ 3015.812294] Lustre: server umount lustre-MDT0001 complete [ 3030.627667] Lustre: server umount lustre-OST0000 complete [ 3031.519451] Lustre: 16411:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790947466/real 1790947466] req@ffff9ab48fa08000 x1877941813315968/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1790947482 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3034.966292] Lustre: server umount lustre-OST0001 complete [ 3051.239977] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing load_modules_local [ 3061.384100] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3061.969091] LustreError: 98500:0:(ldlm_lib.c:1199: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. [ 3062.004802] LustreError: 98500:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 44 previous similar messages [ 3066.927868] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3076.485979] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3081.555484] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3085.159752] Lustre: 99639:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3085.167540] Lustre: 99639:0:(mgs_llog.c:1450:mgs_modify_param()) Skipped 1 previous similar message [ 3091.977282] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3099.768880] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3102.515582] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:116 to 0x280000400:193) [ 3106.610336] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3682 to 0x280000401:3713) [ 3108.741767] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3113.979631] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3317 to 0x2c0000401:3393) [ 3114.081390] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:116 to 0x2c0000400:193) [ 3115.794571] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3123.424227] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3133.222890] Lustre: DEBUG MARKER: == sanity-lfsck test 15a: LFSCK can repair unmatched MDT-object/OST-object pairs (1) ========================================================== 09:26:22 (1790947582) [ 3136.497466] Lustre: *** cfs_fail_loc=1611, val=0*** [ 3136.504173] Lustre: Skipped 63 previous similar messages [ 3136.737760] Lustre: *** cfs_fail_loc=1611, val=0*** [ 3147.158532] Lustre: DEBUG MARKER: == sanity-lfsck test 15b: LFSCK can repair unmatched MDT-object/OST-object pairs (2) ========================================================== 09:26:35 (1790947595) [ 3149.176546] Lustre: *** cfs_fail_loc=1612, val=0*** [ 3149.258084] Lustre: *** cfs_fail_loc=1612, val=0*** [ 3149.261771] Lustre: Skipped 2 previous similar messages [ 3160.868462] Lustre: DEBUG MARKER: == sanity-lfsck test 15c: LFSCK can repair unmatched MDT-object/OST-object pairs (3) ========================================================== 09:26:49 (1790947609) [ 3162.538548] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_15c MDS newer than 2.7.55, LU-6475 [ 3164.536451] Lustre: DEBUG MARKER: == sanity-lfsck test 15d: LFSCK don't crash upon dir migration failure ========================================================== 09:26:53 (1790947613) [ 3170.331344] Lustre: *** cfs_fail_loc=1709, val=0*** [ 3170.395286] LustreError: 98507:0:(osp_object.c:618:osp_attr_get()) lustre-MDT0000-osp-MDT0001: osp_attr_get update error [0x200003ab2:0x1:0x0]: rc = -5 [ 3170.423943] LustreError: 98507:0:(mdt_reint.c:2656:mdt_reint_migrate()) lustre-MDT0001: migrate [0x240002340:0x6c:0x0]/s10 failed: rc = -5 [ 3194.096443] LustreError: 98494:0:(lod_object.c:945:lod_load_lmv_shards()) lustre-MDT0001-mdtlov: the shard [0x200003ab1:0x52:0x0]:1 for the striped directory [0x240002340:0x81:0x0] is out of the known LMV EA range [0 - 0], failout [ 3199.742607] LustreError: 98496:0:(lod_object.c:945:lod_load_lmv_shards()) lustre-MDT0001-mdtlov: the shard [0x200003ab1:0x52:0x0]:1 for the striped directory [0x240002340:0x81:0x0] is out of the known LMV EA range [0 - 0], failout [ 3199.765834] LustreError: 98496:0:(mdt_handler.c:1499:mdt_getattr_internal()) lustre-MDT0001: getattr error for [0x240002340:0x81:0x0]: rc = -5 [ 3210.221024] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3210.229412] Lustre: Skipped 7 previous similar messages [ 3212.398616] Lustre: server umount lustre-MDT0000 complete [ 3222.821806] LustreError: 98480:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1790947673 with bad export cookie 4295120569077797050 [ 3222.833435] LustreError: 98480:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 3223.074894] Lustre: server umount lustre-MDT0001 complete [ 3241.738333] Lustre: server umount lustre-OST0000 complete [ 3242.528097] Lustre: 16411:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790947677/real 1790947677] req@ffff9ab488436680 x1877941813923328/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1790947693 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3244.000160] Lustre: 16413:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790947678/real 1790947678] req@ffff9ab48fa09500 x1877941813923584/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1790947694 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3247.716482] Lustre: 16411:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790947682/real 1790947682] req@ffff9ab48fa0ad80 x1877941813923840/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1790947698 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3250.971146] Lustre: server umount lustre-OST0001 complete [ 3270.292202] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing unload_modules_local [ 3273.301348] Key type lgssc unregistered [ 3273.571714] LNet: 105340:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 3273.586609] LNetError: 105340:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 3274.597725] LNet: Removed LNI 192.168.203.132@tcp [ 3275.709196] Key type .llcrypt unregistered [ 3275.717195] Key type ._llcrypt unregistered [ 3301.765662] Key type ._llcrypt registered [ 3301.772466] Key type .llcrypt registered [ 3301.936952] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_hostid [ 3316.759490] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing load_modules_local [ 3318.034616] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 3318.207785] alg: No test for adler32 (adler32-zlib) [ 3319.583975] Lustre: Lustre: Build Version: 2.17.59_2_gbfaf0e7 [ 3319.873927] LNet: Added LNI 192.168.203.132@tcp [8/256/0/180] [ 3321.639277] Key type lgssc registered [ 3322.984422] Lustre: Echo OBD driver; http://www.lustre.org/ [ 3378.616598] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing load_modules_local [ 3392.656903] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' or install '{/usr}/sbin/mount.lustre_tgt' [ 3392.703514] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3394.057712] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 3394.120172] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 3394.226621] Lustre: lustre-MDT0000: new disk, initializing [ 3394.352088] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3394.382585] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 3399.435577] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3414.203504] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3414.381406] Lustre: 109812: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 [ 3414.440811] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 3414.453277] Lustre: Skipped 1 previous similar message [ 3414.583767] Lustre: lustre-MDT0001: new disk, initializing [ 3414.717838] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 3414.754109] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 3414.767992] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 3420.701433] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3425.881852] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 3436.829940] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3437.102626] Lustre: lustre-OST0000: new disk, initializing [ 3437.107909] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 3437.119759] Lustre: 111749:0:(osd_compat.c:1354:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 3437.199851] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 3437.427697] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 3437.450328] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 3437.595285] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 3443.924460] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3457.087320] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3457.256166] Lustre: lustre-OST0001: new disk, initializing [ 3457.261130] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 3457.266578] Lustre: 112775:0:(osd_compat.c:1354:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 3457.314972] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 3463.845976] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3466.339772] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 3466.367403] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 3466.447670] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 3474.388946] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3484.406597] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 3491.178844] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 09:32:19 (1790947939) === [ 3497.535492] Lustre: DEBUG MARKER: == sanity-lfsck test 16: LFSCK can repair inconsistent MDT-object/OST-object owner ========================================================== 09:32:26 (1790947946) [ 3497.708068] Lustre: 109818:0:(osd_internal.h:1462:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 251 < left 292, rollback = 2 [ 3497.714831] Lustre: 109818:0:(osd_handler.c:2097:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 3497.725848] Lustre: 109818:0:(osd_handler.c:2104:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 5/292/0 [ 3497.730777] Lustre: 109818:0:(osd_handler.c:2114:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 3497.737745] Lustre: 109818:0:(osd_handler.c:2121:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 3497.742444] Lustre: 109818:0:(osd_handler.c:2128:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3498.209030] Lustre: 109820:0:(osd_internal.h:1462:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 292, rollback = 2 [ 3498.215468] Lustre: 109820:0:(osd_internal.h:1462:osd_trans_exec_op()) Skipped 12 previous similar messages [ 3498.221838] Lustre: 109820:0:(osd_handler.c:2097:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 3498.227800] Lustre: 109820:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 12 previous similar messages [ 3498.233529] Lustre: 109820:0:(osd_handler.c:2104:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 5/292/0 [ 3498.248107] Lustre: 109820:0:(osd_handler.c:2104:osd_trans_dump_creds()) Skipped 12 previous similar messages [ 3498.254454] Lustre: 109820:0:(osd_handler.c:2114:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 7/369/0 [ 3498.262824] Lustre: 109820:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 12 previous similar messages [ 3498.280191] Lustre: 109820:0:(osd_handler.c:2121:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 3498.291082] Lustre: 109820:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 12 previous similar messages [ 3498.306114] Lustre: 109820:0:(osd_handler.c:2128:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3498.316324] Lustre: 109820:0:(osd_handler.c:2128:osd_trans_dump_creds()) Skipped 12 previous similar messages [ 3499.221252] Lustre: 109820:0:(osd_internal.h:1462:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 292, rollback = 2 [ 3499.229720] Lustre: 109820:0:(osd_internal.h:1462:osd_trans_exec_op()) Skipped 194 previous similar messages [ 3499.236934] Lustre: 109820:0:(osd_handler.c:2097:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 3499.250134] Lustre: 109820:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 194 previous similar messages [ 3499.256674] Lustre: 109820:0:(osd_handler.c:2104:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 5/292/0 [ 3499.267078] Lustre: 109820:0:(osd_handler.c:2104:osd_trans_dump_creds()) Skipped 194 previous similar messages [ 3499.275648] Lustre: 109820:0:(osd_handler.c:2114:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 7/369/0 [ 3499.282945] Lustre: 109820:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 194 previous similar messages [ 3499.296217] Lustre: 109820:0:(osd_handler.c:2121:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 3499.303254] Lustre: 109820:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 194 previous similar messages [ 3499.309703] Lustre: 109820:0:(osd_handler.c:2128:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3499.316672] Lustre: 109820:0:(osd_handler.c:2128:osd_trans_dump_creds()) Skipped 194 previous similar messages [ 3501.013247] Lustre: *** cfs_fail_loc=1613, val=0*** [ 3511.238615] Lustre: DEBUG MARKER: == sanity-lfsck test 17: LFSCK can repair multiple references ========================================================== 09:32:40 (1790947960) [ 3512.317135] Lustre: 109820:0:(osd_internal.h:1462:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 257 < left 292, rollback = 2 [ 3512.324811] Lustre: 109820:0:(osd_internal.h:1462:osd_trans_exec_op()) Skipped 101 previous similar messages [ 3512.331378] Lustre: 109820:0:(osd_handler.c:2097:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 3512.339824] Lustre: 109820:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 101 previous similar messages [ 3512.345176] Lustre: 109820:0:(osd_handler.c:2104:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 5/292/0 [ 3512.352865] Lustre: 109820:0:(osd_handler.c:2104:osd_trans_dump_creds()) Skipped 101 previous similar messages [ 3512.359692] Lustre: 109820:0:(osd_handler.c:2114:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 3512.366363] Lustre: 109820:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 101 previous similar messages [ 3512.372492] Lustre: 109820:0:(osd_handler.c:2121:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 3512.378356] Lustre: 109820:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 101 previous similar messages [ 3512.385122] Lustre: 109820:0:(osd_handler.c:2128:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3512.391054] Lustre: 109820:0:(osd_handler.c:2128:osd_trans_dump_creds()) Skipped 101 previous similar messages [ 3513.285606] Lustre: *** cfs_fail_loc=1614, val=0*** [ 3513.789549] Lustre: *** cfs_fail_loc=1614, val=103*** [ 3513.800177] Lustre: Skipped 1 previous similar message [ 3518.523635] Lustre: 111740:0:(osd_internal.h:1462:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 259 < left 275, rollback = 2 [ 3518.541611] Lustre: 111740:0:(osd_internal.h:1462:osd_trans_exec_op()) Skipped 11 previous similar messages [ 3518.550960] Lustre: 111740:0:(osd_handler.c:2097:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 3518.580301] Lustre: 111740:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3518.596877] Lustre: 111740:0:(osd_handler.c:2104:osd_trans_dump_creds()) attr_set: 1/1/1, xattr_set: 3/275/0 [ 3518.618014] Lustre: 111740:0:(osd_handler.c:2104:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3518.628628] Lustre: 111740:0:(osd_handler.c:2114:osd_trans_dump_creds()) write: 1/9/0, punch: 1/4/0, quota 7/225/0 [ 3518.642642] Lustre: 111740:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3518.655651] Lustre: 111740:0:(osd_handler.c:2121:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 3518.670913] Lustre: 111740:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3518.683862] Lustre: 111740:0:(osd_handler.c:2128:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3518.697832] Lustre: 111740:0:(osd_handler.c:2128:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3526.013678] Lustre: DEBUG MARKER: == sanity-lfsck test 18a: Find out orphan OST-object and repair it (1) ========================================================== 09:32:54 (1790947974) [ 3526.540945] Lustre: 109820:0:(osd_internal.h:1462:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 292, rollback = 2 [ 3526.549759] Lustre: 109820:0:(osd_internal.h:1462:osd_trans_exec_op()) Skipped 7 previous similar messages [ 3526.556317] Lustre: 109820:0:(osd_handler.c:2097:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 3526.562937] Lustre: 109820:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 7 previous similar messages [ 3526.853036] Lustre: 112783:0:(osd_handler.c:2104:osd_trans_dump_creds()) attr_set: 3/3/0, xattr_set: 7/320/0 [ 3526.863992] Lustre: 112783:0:(osd_handler.c:2104:osd_trans_dump_creds()) Skipped 10 previous similar messages [ 3526.872448] Lustre: 112783:0:(osd_handler.c:2114:osd_trans_dump_creds()) write: 7/145/0, punch: 0/0/0, quota 1/3/0 [ 3526.878202] Lustre: 112783:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 10 previous similar messages [ 3526.883582] Lustre: 112783:0:(osd_handler.c:2121:osd_trans_dump_creds()) insert: 7/135/3, delete: 0/0/0 [ 3526.889540] Lustre: 112783:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 10 previous similar messages [ 3526.896710] Lustre: 112783:0:(osd_handler.c:2128:osd_trans_dump_creds()) ref_add: 1/1/0, ref_del: 0/0/0 [ 3526.901969] Lustre: 112783:0:(osd_handler.c:2128:osd_trans_dump_creds()) Skipped 10 previous similar messages [ 3528.629747] Lustre: *** cfs_fail_loc=1615, val=0*** [ 3528.631718] Lustre: Skipped 1 previous similar message [ 3529.722693] Lustre: *** cfs_fail_loc=1615, val=0*** [ 3529.724684] Lustre: Skipped 3 previous similar messages [ 3548.921739] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_18b skipping excluded test 18b [ 3551.665239] Lustre: DEBUG MARKER: == sanity-lfsck test 18c: Find out orphan OST-object and repair it (3) ========================================================== 09:33:19 (1790947999) [ 3552.643746] Lustre: 112783:0:(osd_internal.h:1462:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 292, rollback = 2 [ 3552.681453] Lustre: 112783:0:(osd_internal.h:1462:osd_trans_exec_op()) Skipped 15 previous similar messages [ 3552.709797] Lustre: 112783:0:(osd_handler.c:2097:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 3552.724996] Lustre: 112783:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 15 previous similar messages [ 3552.732797] Lustre: 112783:0:(osd_handler.c:2104:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 5/292/0 [ 3552.745143] Lustre: 112783:0:(osd_handler.c:2104:osd_trans_dump_creds()) Skipped 12 previous similar messages [ 3552.755805] Lustre: 112783:0:(osd_handler.c:2114:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 3552.768336] Lustre: 112783:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 12 previous similar messages [ 3552.779320] Lustre: 112783:0:(osd_handler.c:2121:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 3552.791319] Lustre: 112783:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 12 previous similar messages [ 3552.800486] Lustre: 112783:0:(osd_handler.c:2128:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3552.815453] Lustre: 112783:0:(osd_handler.c:2128:osd_trans_dump_creds()) Skipped 12 previous similar messages [ 3556.331281] Lustre: *** cfs_fail_loc=1617, val=0*** [ 3556.468829] Lustre: *** cfs_fail_loc=1617, val=0*** [ 3559.852660] Lustre: *** cfs_fail_loc=1616, val=0*** [ 3559.870793] Lustre: Skipped 1 previous similar message [ 3582.020611] Lustre: DEBUG MARKER: == sanity-lfsck test 18d: Find out orphan OST-object and repair it (4) ========================================================== 09:33:50 (1790948030) [ 3584.435040] Lustre: *** cfs_fail_loc=1618, val=0*** [ 3584.437055] Lustre: Skipped 5 previous similar messages [ 3619.808037] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3619.810909] 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 [ 3619.838730] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3620.322709] 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 [ 3620.336737] Lustre: Skipped 1 previous similar message [ 3620.347282] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3620.356932] Lustre: Skipped 3 previous similar messages [ 3624.782176] Lustre: server umount lustre-MDT0000 complete [ 3628.690210] LustreError: 109804:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1790948079 with bad export cookie 13397111647055740298 [ 3628.690620] LustreError: MGC192.168.203.132@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3628.706891] LustreError: 109804:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 3629.233807] Lustre: server umount lustre-MDT0001 complete [ 3644.082758] Lustre: server umount lustre-OST0000 complete [ 3646.751132] Lustre: 106961:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790948081/real 1790948081] req@ffff9ab48ca4e300 x1877944849084800/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1790948097 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3646.809349] 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 [ 3646.839796] Lustre: Skipped 1 previous similar message [ 3649.632817] Lustre: server umount lustre-OST0001 complete [ 3671.214615] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing load_modules_local [ 3684.977688] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3685.777678] LustreError: 118491:0:(ldlm_lib.c:1199: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. [ 3685.808364] LustreError: 118491:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 5 previous similar messages [ 3685.931716] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3690.975770] LustreError: 118492:0:(ldlm_lib.c:1199: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. [ 3692.517468] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3696.116483] LustreError: 118491:0:(ldlm_lib.c:1199: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. [ 3701.218805] LustreError: 118492:0:(ldlm_lib.c:1199: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. [ 3703.507554] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3703.770250] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 3710.426177] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3714.293156] Lustre: 119633:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3721.542079] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3721.859800] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 3729.061707] LustreError: 119985:0:(ldlm_lib.c:1199: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. [ 3729.079620] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:4 to 0x280000400:33) [ 3729.559985] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3731.112585] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:116 to 0x280000401:161) [ 3739.632840] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3745.282553] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:33) [ 3745.307534] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:4 to 0x2c0000401:33) [ 3747.594608] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3755.387856] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3759.024742] Lustre: 121503:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 3775.977084] Lustre: DEBUG MARKER: == sanity-lfsck test 18e: Find out orphan OST-object and repair it (5) ========================================================== 09:37:04 (1790948224) [ 3776.672704] Lustre: 118486:0:(osd_internal.h:1462:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 252 < left 292, rollback = 2 [ 3776.686159] Lustre: 118486:0:(osd_internal.h:1462:osd_trans_exec_op()) Skipped 46 previous similar messages [ 3776.693478] Lustre: 118486:0:(osd_handler.c:2097:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 3776.707873] Lustre: 118486:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 3776.720034] Lustre: 118486:0:(osd_handler.c:2104:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 5/292/0 [ 3776.731333] Lustre: 118486:0:(osd_handler.c:2104:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 3776.748947] Lustre: 118486:0:(osd_handler.c:2114:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/1 [ 3776.762066] Lustre: 118486:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 3776.769710] Lustre: 118486:0:(osd_handler.c:2121:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 3776.777719] Lustre: 118486:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 3776.792630] Lustre: 118486:0:(osd_handler.c:2128:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3776.812524] Lustre: 118486:0:(osd_handler.c:2128:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 3779.445566] Lustre: *** cfs_fail_loc=1618, val=0*** [ 3779.453912] Lustre: Skipped 3 previous similar messages [ 3816.415513] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3816.441865] 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 [ 3816.487849] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3820.336301] Lustre: server umount lustre-MDT0000 complete [ 3822.054431] LustreError: 118492:0:(ldlm_lib.c:1199: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. [ 3822.088990] LustreError: 118492:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 7 previous similar messages [ 3825.133440] LustreError: 118473:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1790948275 with bad export cookie 13397111647055755551 [ 3825.146509] LustreError: MGC192.168.203.132@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3825.150447] LustreError: 118473:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 3825.836381] Lustre: server umount lustre-MDT0001 complete [ 3841.185427] Lustre: server umount lustre-OST0000 complete [ 3843.362895] Lustre: 106961:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790948277/real 1790948277] req@ffff9ab48ca4f100 x1877944849163264/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1790948293 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3843.430757] 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 [ 3843.442884] Lustre: Skipped 3 previous similar messages [ 3845.162593] Lustre: server umount lustre-OST0001 complete [ 3861.242088] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing load_modules_local [ 3872.305607] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3872.912061] LustreError: 124073:0:(ldlm_lib.c:1199: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. [ 3873.025226] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3873.031577] Lustre: Skipped 1 previous similar message [ 3878.016304] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3887.207120] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3892.512607] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3895.783634] Lustre: 125213:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3904.512505] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3911.871834] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3912.935220] LustreError: 125569:0:(ldlm_lib.c:1199: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. [ 3912.956339] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:4 to 0x280000400:65) [ 3912.983450] LustreError: 125569:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 3 previous similar messages [ 3919.351811] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:166 to 0x280000401:193) [ 3922.352949] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3928.035788] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:4 to 0x2c0000401:65) [ 3928.072572] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:65) [ 3930.679218] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3938.662942] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3942.813147] Lustre: 127083:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 3948.531027] Lustre: *** cfs_fail_loc=1602, val=10*** [ 3948.559493] Lustre: 124073:0:(osd_internal.h:1462:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 252 < left 260, rollback = 2 [ 3948.586057] Lustre: 124073:0:(osd_internal.h:1462:osd_trans_exec_op()) Skipped 21 previous similar messages [ 3948.616544] Lustre: 124073:0:(osd_handler.c:2097:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 3948.645160] Lustre: 124073:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3948.661348] Lustre: 124073:0:(osd_handler.c:2104:osd_trans_dump_creds()) attr_set: 0/0/0, xattr_set: 1/260/0 [ 3948.669706] Lustre: 124073:0:(osd_handler.c:2104:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3948.680850] Lustre: 124073:0:(osd_handler.c:2114:osd_trans_dump_creds()) write: 1/9/0, punch: 0/0/0, quota 4/150/2 [ 3948.692088] Lustre: 124073:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3948.701099] Lustre: 124073:0:(osd_handler.c:2121:osd_trans_dump_creds()) insert: 1/17/2, delete: 0/0/0 [ 3948.709562] Lustre: 124073:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3948.717309] Lustre: 124073:0:(osd_handler.c:2128:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3948.735559] Lustre: 124073:0:(osd_handler.c:2128:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3973.408707] Lustre: DEBUG MARKER: == sanity-lfsck test 18f: Skip the failed OST(s) when handle orphan OST-objects ========================================================== 09:40:22 (1790948422) [ 3976.478719] Lustre: *** cfs_fail_loc=1616, val=0*** [ 3976.482483] Lustre: Skipped 3 previous similar messages [ 3982.519836] Lustre: *** cfs_fail_loc=161c, val=0*** [ 3982.525429] Lustre: Skipped 1 previous similar message [ 4001.660593] Lustre: DEBUG MARKER: == sanity-lfsck test 18g: Find out orphan OST-object and repair it (7) ========================================================== 09:40:50 (1790948450) [ 4003.619276] Lustre: *** cfs_fail_loc=162e, val=0*** [ 4016.741864] Lustre: DEBUG MARKER: == sanity-lfsck test 18h: LFSCK can repair crashed PFL extent range ========================================================== 09:41:05 (1790948465) [ 4021.170079] Lustre: *** cfs_fail_loc=162f, val=0*** [ 4021.175743] Lustre: Skipped 9 previous similar messages [ 4036.679251] Lustre: DEBUG MARKER: == sanity-lfsck test 19a: OST-object inconsistency self detect ========================================================== 09:41:25 (1790948485) [ 4048.696543] Lustre: DEBUG MARKER: == sanity-lfsck test 19b: OST-object inconsistency self repair ========================================================== 09:41:37 (1790948497) [ 4051.909770] Lustre: *** cfs_fail_loc=1611, val=0*** [ 4051.950285] Lustre: *** cfs_fail_loc=1611, val=0*** [ 4051.957632] Lustre: Skipped 3 previous similar messages [ 4057.000147] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.203.32@tcp inode [0x2000013a1:0x1f:0x0] object 0x280000401:203 extent [0-4095], client returned csum 0 (type 4), server csum 703fb3ad (type 4) [ 4058.090147] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.203.32@tcp inode [0x2000013a1:0x20:0x0] object 0x280000401:204 extent [0-4095], client returned csum 0 (type 4), server csum 7cbb935c (type 4) [ 4064.465919] Lustre: DEBUG MARKER: == sanity-lfsck test 20a: Handle the orphan with dummy LOV EA slot properly ========================================================== 09:41:53 (1790948513) [ 4079.288895] Lustre: 124068:0:(osd_internal.h:1462:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 255 < left 292, rollback = 2 [ 4079.300208] Lustre: 124068:0:(osd_internal.h:1462:osd_trans_exec_op()) Skipped 131 previous similar messages [ 4079.307120] Lustre: 124068:0:(osd_handler.c:2097:osd_trans_dump_creds()) create: 1/4/3, destroy: 0/0/0 [ 4079.312574] Lustre: 124068:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 131 previous similar messages [ 4079.319554] Lustre: 124068:0:(osd_handler.c:2104:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 5/292/0 [ 4079.326606] Lustre: 124068:0:(osd_handler.c:2104:osd_trans_dump_creds()) Skipped 131 previous similar messages [ 4079.331128] Lustre: 124068:0:(osd_handler.c:2114:osd_trans_dump_creds()) write: 2/20/1, punch: 0/0/0, quota 1/3/0 [ 4079.338251] Lustre: 124068:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 131 previous similar messages [ 4079.349409] Lustre: 124068:0:(osd_handler.c:2121:osd_trans_dump_creds()) insert: 2/33/1, delete: 0/0/0 [ 4079.359287] Lustre: 124068:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 131 previous similar messages [ 4079.373655] Lustre: 124068:0:(osd_handler.c:2128:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 4079.381576] Lustre: 124068:0:(osd_handler.c:2128:osd_trans_dump_creds()) Skipped 131 previous similar messages [ 4088.707690] Lustre: DEBUG MARKER: == sanity-lfsck test 20b: Handle the orphan with dummy LOV EA slot properly - PFL case ========================================================== 09:42:17 (1790948537) [ 4095.913252] Lustre: DEBUG MARKER: == sanity-lfsck test 21: run all LFSCK components by default ========================================================== 09:42:25 (1790948545) [ 4109.056669] Lustre: DEBUG MARKER: == sanity-lfsck test 22a: LFSCK can repair unmatched pairs (1) ========================================================== 09:42:37 (1790948557) [ 4111.354870] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4111.376088] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4111.381470] Lustre: Skipped 1 previous similar message [ 4122.421408] Lustre: DEBUG MARKER: == sanity-lfsck test 22b: LFSCK can repair unmatched pairs (2) ========================================================== 09:42:51 (1790948571) [ 4124.070334] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4124.075559] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4134.318663] Lustre: DEBUG MARKER: == sanity-lfsck test 23a: LFSCK can repair dangling name entry (1) ========================================================== 09:43:03 (1790948583) [ 4135.798456] Lustre: *** cfs_fail_loc=1620, val=0*** [ 4148.827844] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_23b skipping excluded test 23b [ 4150.880604] Lustre: DEBUG MARKER: == sanity-lfsck test 23c: LFSCK can repair dangling name entry (3) ========================================================== 09:43:19 (1790948599) [ 4156.730104] Lustre: *** cfs_fail_loc=1621, val=127*** [ 4156.741577] Lustre: Skipped 1 previous similar message [ 4159.660257] Lustre: *** cfs_fail_loc=1602, val=10*** [ 4180.593308] Lustre: DEBUG MARKER: == sanity-lfsck test 23d: LFSCK can repair a dangling name entry to a remote object ========================================================== 09:43:49 (1790948629) [ 4183.039922] Lustre: Failing over lustre-MDT0000 [ 4183.477094] Lustre: server umount lustre-MDT0000 complete [ 4184.040522] 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 [ 4184.051187] LustreError: 127344:0:(ldlm_lib.c:1199: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. [ 4184.054982] Lustre: Skipped 3 previous similar messages [ 4184.107679] LustreError: 127344:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 6 previous similar messages [ 4192.130975] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4192.253901] LustreError: MGC192.168.203.132@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4192.474395] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4192.478875] Lustre: Skipped 3 previous similar messages [ 4192.516758] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4196.270219] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4196.359401] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4197.876260] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4197.916514] Lustre: lustre-MDT0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 4197.963704] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:130 to 0x2c0000401:161) [ 4197.975818] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:265 to 0x280000401:289) [ 4198.220263] LustreError: 127505:0:(mdt_open.c:1324:mdt_cross_open()) lustre-MDT0000: [0x2000013a3:0x82:0x0] doesn't exist!: rc = -14 [ 4207.657345] Lustre: DEBUG MARKER: == sanity-lfsck test 24: LFSCK can repair multiple-referenced name entry ========================================================== 09:44:16 (1790948656) [ 4209.492612] Lustre: *** cfs_fail_loc=1622, val=0*** [ 4209.619884] Lustre: *** cfs_fail_loc=1622, val=0*** [ 4209.621907] Lustre: Skipped 1 previous similar message [ 4220.853641] Lustre: DEBUG MARKER: == sanity-lfsck test 25: LFSCK can repair bad file type in the name entry ========================================================== 09:44:29 (1790948669) [ 4222.406254] Lustre: *** cfs_fail_loc=1623, val=0*** [ 4232.239462] Lustre: DEBUG MARKER: == sanity-lfsck test 26a: LFSCK can add the missing local name entry back to the namespace ========================================================== 09:44:41 (1790948681) [ 4233.835541] Lustre: *** cfs_fail_loc=1624, val=0*** [ 4244.371097] Lustre: DEBUG MARKER: == sanity-lfsck test 26b: LFSCK can add the missing remote name entry back to the namespace ========================================================== 09:44:53 (1790948693) [ 4257.921743] Lustre: DEBUG MARKER: == sanity-lfsck test 27a: LFSCK can recreate the lost local parent directory as orphan ========================================================== 09:45:06 (1790948706) [ 4259.569356] Lustre: *** cfs_fail_loc=1624, val=0*** [ 4259.573723] Lustre: Skipped 1 previous similar message [ 4270.496027] Lustre: DEBUG MARKER: == sanity-lfsck test 27b: LFSCK can recreate the lost remote parent directory as orphan ========================================================== 09:45:19 (1790948719) [ 4284.913453] Lustre: DEBUG MARKER: == sanity-lfsck test 28: Skip the failed MDT(s) when handle orphan MDT-objects ========================================================== 09:45:33 (1790948733) [ 4292.487507] Lustre: *** cfs_fail_loc=161c, val=0*** [ 4309.846857] Lustre: DEBUG MARKER: == sanity-lfsck test 29b: LFSCK can repair bad nlink count (2) ========================================================== 09:45:58 (1790948758) [ 4311.920730] Lustre: *** cfs_fail_loc=1626, val=0*** [ 4311.923987] Lustre: Skipped 4 previous similar messages [ 4325.668267] Lustre: DEBUG MARKER: == sanity-lfsck test 29c: verify linkEA size limitation == 09:46:14 (1790948774) [ 4335.373091] Lustre: 124070:0:(osd_internal.h:1462:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 334, rollback = 2 [ 4335.381257] Lustre: 124070:0:(osd_internal.h:1462:osd_trans_exec_op()) Skipped 539 previous similar messages [ 4335.385599] Lustre: 124070:0:(osd_handler.c:2097:osd_trans_dump_creds()) create: 2/8/0, destroy: 1/4/0 [ 4335.397473] Lustre: 124070:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 539 previous similar messages [ 4335.402655] Lustre: 124070:0:(osd_handler.c:2104:osd_trans_dump_creds()) attr_set: 6/6/0, xattr_set: 8/334/0 [ 4335.407470] Lustre: 124070:0:(osd_handler.c:2104:osd_trans_dump_creds()) Skipped 539 previous similar messages [ 4335.414637] Lustre: 124070:0:(osd_handler.c:2114:osd_trans_dump_creds()) write: 10/119/0, punch: 0/0/0, quota 1/3/0 [ 4335.420683] Lustre: 124070:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 539 previous similar messages [ 4335.426561] Lustre: 124070:0:(osd_handler.c:2121:osd_trans_dump_creds()) insert: 4/66/0, delete: 1/4/0 [ 4335.431844] Lustre: 124070:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 539 previous similar messages [ 4335.436269] Lustre: 124070:0:(osd_handler.c:2128:osd_trans_dump_creds()) ref_add: 1/1/0, ref_del: 2/2/1 [ 4335.440304] Lustre: 124070:0:(osd_handler.c:2128:osd_trans_dump_creds()) Skipped 539 previous similar messages [ 4354.678081] Lustre: DEBUG MARKER: == sanity-lfsck test 29d: accessing non-existing inode shouldn't turn fs read-only (ldiskfs) ========================================================== 09:46:43 (1790948803) [ 4357.586730] LustreError: 125339:0:(osd_handler.c:286:osd_idc_find_or_init()) lustre-MDT0000: cannot lookup FID [0x2000013a3:0x9e:0x0]: rc = -2 [ 4364.863085] Lustre: DEBUG MARKER: == sanity-lfsck test 30: LFSCK can recover the orphans from backend /lost+found ========================================================== 09:46:53 (1790948813) [ 4374.618459] Lustre: Failing over lustre-MDT0000 [ 4375.490178] Lustre: server umount lustre-MDT0000 complete [ 4377.058304] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4377.061972] 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 [ 4377.094697] Lustre: Skipped 2 previous similar messages [ 4377.106301] LustreError: 124805:0:(ldlm_lib.c:1199: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. [ 4377.129888] LustreError: 124805:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 7 previous similar messages [ 4387.944818] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 4388.114858] LustreError: MGC192.168.203.132@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4388.461058] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4388.531091] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4393.240450] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4393.445167] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4393.445864] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4393.449740] Lustre: Skipped 3 previous similar messages [ 4393.516240] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4393.575784] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:295 to 0x280000401:321) [ 4393.577293] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:166 to 0x2c0000401:193) [ 4407.207356] Lustre: DEBUG MARKER: == sanity-lfsck test 31a: The LFSCK can find/repair the name entry with bad name hash (1) ========================================================== 09:47:35 (1790948855) [ 4422.166395] Lustre: DEBUG MARKER: == sanity-lfsck test 31b: The LFSCK can find/repair the name entry with bad name hash (2) ========================================================== 09:47:50 (1790948870) [ 4436.844642] Lustre: DEBUG MARKER: == sanity-lfsck test 31c: Re-generate the lost master LMV EA for striped directory ========================================================== 09:48:05 (1790948885) [ 4438.044335] Lustre: *** cfs_fail_loc=1629, val=0*** [ 4438.051351] Lustre: Skipped 7 previous similar messages [ 4451.354269] Lustre: DEBUG MARKER: == sanity-lfsck test 31d: Set broken striped directory (modified after broken) as read-only ========================================================== 09:48:20 (1790948900) [ 4457.616442] Lustre: Failing over lustre-MDT0000 [ 4458.055712] Lustre: server umount lustre-MDT0000 complete [ 4460.003271] 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 [ 4460.021970] Lustre: Skipped 3 previous similar messages [ 4467.813460] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4467.899772] LustreError: MGC192.168.203.132@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4468.190631] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4473.323360] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4473.340399] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4473.348246] Lustre: Skipped 3 previous similar messages [ 4473.359900] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4473.441243] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:166 to 0x2c0000401:225) [ 4473.443478] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:295 to 0x280000401:353) [ 4473.910081] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4484.162939] Lustre: Failing over lustre-MDT0000 [ 4484.657817] Lustre: server umount lustre-MDT0000 complete [ 4488.684431] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4493.476314] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4493.549728] LustreError: MGC192.168.203.132@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4493.781657] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4496.818093] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4498.318807] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4498.919226] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4498.926726] Lustre: Skipped 3 previous similar messages [ 4498.952557] Lustre: lustre-MDT0000: Recovery over after 0:02, of 2 clients 2 recovered and 0 were evicted. [ 4498.990492] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:227 to 0x2c0000401:257) [ 4498.991105] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:295 to 0x280000401:385) [ 4506.379493] Lustre: DEBUG MARKER: == sanity-lfsck test 31e: Re-generate the lost slave LMV EA for striped directory (1) ========================================================== 09:49:15 (1790948955) [ 4517.628088] Lustre: DEBUG MARKER: == sanity-lfsck test 31f: Re-generate the lost slave LMV EA for striped directory (2) ========================================================== 09:49:26 (1790948966) [ 4530.278696] Lustre: DEBUG MARKER: == sanity-lfsck test 31g: Repair the corrupted slave LMV EA ========================================================== 09:49:39 (1790948979) [ 4569.975482] Lustre: DEBUG MARKER: == sanity-lfsck test 31h: Repair the corrupted shard's name entry ========================================================== 09:50:18 (1790949018) [ 4571.414466] Lustre: *** cfs_fail_loc=162c, val=0*** [ 4571.421195] Lustre: Skipped 13 previous similar messages [ 4584.495768] Lustre: DEBUG MARKER: == sanity-lfsck test 32a: stop LFSCK when some OST failed ========================================================== 09:50:33 (1790949033) [ 4593.615598] LustreError: 148455:0:(lfsck_layout.c:4534:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d sleeping for 3000ms [ 4596.357658] Lustre: Failing over lustre-OST0000 [ 4596.455710] Lustre: server umount lustre-OST0000 complete [ 4596.711060] LustreError: 148455:0:(lfsck_layout.c:4534:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d awake [ 4596.722137] LustreError: 148455:0:(lfsck_layout.c:4534:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d sleeping for 3000ms [ 4599.267017] LustreError: lustre-OST0000-osc-MDT0001: operation ost_statfs to node 0@lo failed: rc = -107 [ 4599.274243] 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 [ 4599.290525] Lustre: Skipped 5 previous similar messages [ 4599.495488] LustreError: 148455:0:(lfsck_layout.c:4534:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout interrupted [ 4612.165772] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 4612.391285] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 4613.482924] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4613.523725] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 4613.525943] Lustre: lustre-OST0000-osc-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4613.544883] Lustre: Skipped 3 previous similar messages [ 4619.289992] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4628.193882] Lustre: DEBUG MARKER: == sanity-lfsck test 32b: stop LFSCK when some MDT failed ========================================================== 09:51:17 (1790949077) [ 4641.535682] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing load_modules_local [ 4660.097251] Lustre: 151259:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 4685.293564] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4690.026212] Lustre: 152393:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 4700.860571] LustreError: 152511:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d sleeping for 3000ms [ 4700.891722] LustreError: 152511:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) Skipped 1 previous similar message [ 4703.895124] LustreError: 152511:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d awake [ 4703.912929] LustreError: 152511:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d sleeping for 3000ms [ 4703.967123] Lustre: Failing over lustre-MDT0001 [ 4704.738606] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 4704.746538] Lustre: Skipped 5 previous similar messages [ 4706.951175] LustreError: 152510:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d awake [ 4706.957230] LustreError: 152510:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) Skipped 1 previous similar message [ 4707.562906] Lustre: server umount lustre-MDT0001 complete [ 4709.865435] LustreError: 124070:0:(ldlm_lib.c:1199: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. [ 4709.893239] LustreError: 124070:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 32 previous similar messages [ 4722.495695] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 4722.717306] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 4722.726410] Lustre: Skipped 3 previous similar messages [ 4722.742728] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 4727.157095] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4727.794367] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4727.796951] Lustre: lustre-MDT0001-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 4727.817438] Lustre: Skipped 1 previous similar message [ 4727.846863] Lustre: lustre-MDT0001: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4727.938688] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:70 to 0x280000400:97) [ 4727.940936] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:69 to 0x2c0000400:97) [ 4736.421192] Lustre: DEBUG MARKER: == sanity-lfsck test 33: check LFSCK paramters =========== 09:53:05 (1790949185) [ 4752.404620] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing load_modules_local [ 4774.323531] Lustre: 155230:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 4800.369373] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4804.141108] Lustre: 156366:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 4826.734031] Lustre: DEBUG MARKER: == sanity-lfsck test 34: LFSCK can rebuild the lost agent object ========================================================== 09:54:35 (1790949275) [ 4828.313207] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_34 Only valid for ZFS backend [ 4830.394097] Lustre: DEBUG MARKER: == sanity-lfsck test 35: LFSCK can rebuild the lost agent entry ========================================================== 09:54:39 (1790949279) [ 4837.273596] Lustre: *** cfs_fail_loc=1631, val=0*** [ 4850.659835] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4850.672791] 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 [ 4850.679879] LustreError: Skipped 1 previous similar message [ 4850.684261] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4850.699332] Lustre: Skipped 7 previous similar messages [ 4850.722528] Lustre: Skipped 3 previous similar messages [ 4855.776257] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4855.786567] Lustre: Skipped 3 previous similar messages [ 4855.975481] Lustre: server umount lustre-MDT0000 complete [ 4859.504112] LustreError: 131499:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1790949310 with bad export cookie 13397111647055828274 [ 4859.504356] LustreError: MGC192.168.203.132@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4859.515701] LustreError: 131499:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 4859.761967] Lustre: server umount lustre-MDT0001 complete [ 4874.161698] Lustre: server umount lustre-OST0000 complete [ 4889.168350] Lustre: server umount lustre-OST0001 complete [ 4909.691499] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing load_modules_local [ 4920.800521] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4925.748569] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4934.759426] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4940.003262] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4943.028224] Lustre: 160264:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 4949.762424] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4956.583204] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4960.366147] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:70 to 0x280000400:129) [ 4966.904538] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:540 to 0x280000401:577) [ 4967.240655] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4973.034094] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:412 to 0x2c0000401:449) [ 4973.037108] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:69 to 0x2c0000400:129) [ 4975.060885] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4983.729954] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4987.569861] Lustre: 162135:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 4998.649156] Lustre: DEBUG MARKER: == sanity-lfsck test 36a: rebuild LOV EA for mirrored file (1) ========================================================== 09:57:27 (1790949447) [ 5000.433851] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36a needs >= 3 OSTs [ 5002.412349] Lustre: DEBUG MARKER: == sanity-lfsck test 36b: rebuild LOV EA for mirrored file (2) ========================================================== 09:57:31 (1790949451) [ 5004.050501] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36b needs >= 3 OSTs [ 5005.744544] Lustre: DEBUG MARKER: == sanity-lfsck test 36c: rebuild LOV EA for mirrored file (3) ========================================================== 09:57:34 (1790949454) [ 5007.517253] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36c needs >= 3 OSTs [ 5009.417689] Lustre: DEBUG MARKER: == sanity-lfsck test 37: LFSCK must skip a ORPHAN ======== 09:57:38 (1790949458) [ 5010.990032] Lustre: 159117:0:(osd_internal.h:1462:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 292, rollback = 2 [ 5011.012280] Lustre: 159117:0:(osd_internal.h:1462:osd_trans_exec_op()) Skipped 1875 previous similar messages [ 5011.025741] Lustre: 159117:0:(osd_handler.c:2097:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 5011.035060] Lustre: 159117:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1875 previous similar messages [ 5011.042987] Lustre: 159117:0:(osd_handler.c:2104:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 5/292/0 [ 5011.061784] Lustre: 159117:0:(osd_handler.c:2104:osd_trans_dump_creds()) Skipped 1875 previous similar messages [ 5011.071642] Lustre: 159117:0:(osd_handler.c:2114:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 5011.080361] Lustre: 159117:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1875 previous similar messages [ 5011.088418] Lustre: 159117:0:(osd_handler.c:2121:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 5011.095308] Lustre: 159117:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1875 previous similar messages [ 5011.101371] Lustre: 159117:0:(osd_handler.c:2128:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 5011.106491] Lustre: 159117:0:(osd_handler.c:2128:osd_trans_dump_creds()) Skipped 1875 previous similar messages [ 5020.777739] Lustre: DEBUG MARKER: == sanity-lfsck test 38: LFSCK does not break foreign file and reverse is also true ========================================================== 09:57:49 (1790949469) [ 5035.369855] Lustre: DEBUG MARKER: == sanity-lfsck test 39: LFSCK does not break foreign dir and reverse is also true ========================================================== 09:58:04 (1790949484) [ 5050.474222] Lustre: DEBUG MARKER: == sanity-lfsck test 40a: LFSCK correctly fixes lmm_oi in composite layout ========================================================== 09:58:18 (1790949498) [ 5065.842964] Lustre: DEBUG MARKER: == sanity-lfsck test 41: SEL support in LFSCK ============ 09:58:34 (1790949514) [ 5090.881634] Lustre: DEBUG MARKER: == sanity-lfsck test 42: LFSCK repairs inconsistent MDT-object/OST-object encryption flags ========================================================== 09:58:59 (1790949539) [ 5125.341370] Lustre: *** cfs_fail_loc=1632, val=0*** [ 5144.120389] Lustre: DEBUG MARKER: == sanity-lfsck test 43: LFSCK does not loop endlessly on iget failure in scanning-phase1 ========================================================== 09:59:52 (1790949592) [ 5147.730326] Lustre: Failing over lustre-MDT0001 [ 5147.749676] LustreError: 159103:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1790949598 with bad export cookie 13397111647055887487 [ 5147.983589] Lustre: server umount lustre-MDT0001 complete [ 5150.181361] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 5150.191747] 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 [ 5157.362027] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5157.872226] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 5157.873787] Lustre: lustre-MDT0001: Aborting client recovery [ 5157.888813] LustreError: 165971:0:(ldlm_lib.c:3038:target_stop_recovery_thread()) lustre-MDT0001: Aborting recovery [ 5157.896285] Lustre: 165995:0:(ldlm_lib.c:2438:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 5157.902236] Lustre: 165995:0:(genops.c:1600:class_disconnect_stale_exports()) lustre-MDT0001: disconnect stale client 757fe556-cf8a-423f-9907-1548ccbe686b@ [ 5157.910469] Lustre: lustre-MDT0001: disconnecting 2 stale clients [ 5157.917423] Lustre: lustre-MDT0001-osd: cancel update llog [0x240000400:0x1:0x0] [ 5157.930695] Lustre: lustre-MDT0000-osp-MDT0001: cancel update llog [0x200000401:0x1:0x0] [ 5157.992183] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:131 to 0x2c0000400:161) [ 5157.998141] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:70 to 0x280000400:161) [ 5162.989875] Lustre: lustre-MDT0001-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 5163.008732] Lustre: Skipped 2 previous similar messages [ 5163.021582] LustreError: lustre-MDT0001-osp-MDT0000: This client was evicted by lustre-MDT0001; in progress operations using this service will fail. [ 5163.481626] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5172.740755] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing wait_import_state FULL osp.lustre-MDT0001-os[pc]-MDT0000.*_server_uuid [ 5173.045968] Lustre: DEBUG MARKER: osp.lustre-MDT0001-os[pc]-MDT0000.*_server_uuid in FULL state after 0 sec [ 5180.375929] Lustre: DEBUG MARKER: == sanity-lfsck test 44: umount while lfsck is stopping == 10:00:28 (1790949628) [ 5190.779268] Lustre: *** cfs_fail_loc=1600, val=3*** [ 5194.098424] Lustre: Failing over lustre-MDT0000 [ 5194.137551] LustreError: lustre-MDT0000-osp-MDT0001: operation out_update to node 0@lo failed: rc = -107 [ 5194.151496] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5194.465359] Lustre: server umount lustre-MDT0000 complete [ 5206.148298] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5206.308410] LustreError: MGC192.168.203.132@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5206.617442] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 5206.634935] Lustre: Skipped 2 previous similar messages [ 5211.072102] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 5211.562800] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5211.637112] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 5211.641286] Lustre: Skipped 2 previous similar messages [ 5211.669615] Lustre: lustre-MDT0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 5211.712094] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:621 to 0x280000401:641) [ 5211.714579] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:489 to 0x2c0000401:513) [ 5223.493910] Lustre: DEBUG MARKER: == sanity-lfsck test 45: LFSCK should fix UID/GID/PROJID of OST object ========================================================== 10:01:12 (1790949672) [ 5270.506632] Lustre: Failing over lustre-OST0000 [ 5270.683184] Lustre: server umount lustre-OST0000 complete [ 5272.593594] LustreError: 168413:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.203.32@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 5272.624290] LustreError: 168413:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 33 previous similar messages [ 5278.895465] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: (null) [ 5292.900657] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5293.260415] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 5293.264842] Lustre: Skipped 6 previous similar messages [ 5293.280039] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 5294.771461] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 5294.858454] Lustre: lustre-OST0000: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [ 5294.868900] Lustre: lustre-OST0000-osc-MDT0001: Connection restored to 0@lo (at 0@lo) [ 5294.883324] Lustre: Skipped 3 previous similar messages [ 5299.867618] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5306.862268] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing wait_import_state (FULL|IDLE) os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid 50 [ 5307.120208] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid in FULL state after 0 sec [ 5311.826925] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing wait_import_state (FULL|IDLE) os[cp].lustre-OST0000-osc-MDT0001.ost_server_uuid 50 [ 5312.021232] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0001.ost_server_uuid in FULL state after 0 sec [ 5317.978758] Lustre: DEBUG MARKER: oleg332-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0000-osc-ffff90c3946a5000.ost_server_uuid 50 [ 5319.423608] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff90c3946a5000.ost_server_uuid in FULL state after 0 sec [ 5406.176540] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5406.191781] Lustre: Skipped 3 previous similar messages [ 5408.375768] Lustre: server umount lustre-MDT0000 complete [ 5416.698457] LustreError: 159103:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1790949867 with bad export cookie 13397111647055911049 [ 5416.701549] LustreError: MGC192.168.203.132@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5416.707472] LustreError: 159103:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 5417.303542] Lustre: server umount lustre-MDT0001 complete [ 5436.080279] Lustre: server umount lustre-OST0000 complete [ 5437.919160] Lustre: 106960:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790949872/real 1790949872] req@ffff9ab492579880 x1877944850966272/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1790949888 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5443.048124] Lustre: 106961:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790949877/real 1790949877] req@ffff9ab49257e300 x1877944850966784/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1790949893 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5444.771775] Lustre: server umount lustre-OST0001 complete [ 5462.091081] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing unload_modules_local [ 5465.707253] Key type lgssc unregistered [ 5466.199314] LNet: 175729:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 5466.208341] LNetError: 175729:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 5466.245966] LNet: Removed LNI 192.168.203.132@tcp [ 5467.432874] Key type .llcrypt unregistered [ 5467.445054] Key type ._llcrypt unregistered [ 5492.288364] Key type ._llcrypt registered [ 5492.291592] Key type .llcrypt registered [ 5492.428796] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_hostid [ 5508.609636] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing load_modules_local [ 5510.016730] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 5510.103274] alg: No test for adler32 (adler32-zlib) [ 5511.239577] Lustre: Lustre: Build Version: 2.17.59_2_gbfaf0e7 [ 5511.520341] LNet: Added LNI 192.168.203.132@tcp [8/256/0/180] [ 5513.271369] Key type lgssc registered [ 5514.482436] Lustre: Echo OBD driver; http://www.lustre.org/ [ 5565.553653] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing load_modules_local [ 5580.708963] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' or install '{/usr}/sbin/mount.lustre_tgt' [ 5580.750173] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5582.070730] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 5582.104679] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 5582.152498] Lustre: lustre-MDT0000: new disk, initializing [ 5582.200624] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 5582.213104] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 5588.159303] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5602.562891] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5602.689951] Lustre: 180203: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 [ 5602.724731] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 5602.730122] Lustre: Skipped 1 previous similar message [ 5602.799901] Lustre: lustre-MDT0001: new disk, initializing [ 5602.896745] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 5602.954733] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 5602.976794] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 5607.810406] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5612.517758] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 5622.627484] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5622.905907] Lustre: lustre-OST0000: new disk, initializing [ 5622.909961] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 5622.918202] Lustre: 182143:0:(osd_compat.c:1354:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 5622.987758] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 5625.130151] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 5625.139150] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 5625.185432] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 5629.233416] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5643.352507] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5643.499883] Lustre: lustre-OST0001: new disk, initializing [ 5643.503355] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 5643.507866] Lustre: 183167:0:(osd_compat.c:1354:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 5643.582397] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 5649.549833] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5651.992766] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 5652.011437] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 5652.097861] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 5660.349595] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5671.315790] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 5677.953921] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 10:08:46 (1790950126) === [ 5679.644722] Lustre: DEBUG MARKER: == sanity-lfsck test complete, duration 5392 sec ========= 10:08:48 (1790950128) [ 5681.153962] Lustre: DEBUG MARKER: === sanity-lfsck: start cleanup 10:08:50 (1790950130) === [ 5684.634414] Lustre: DEBUG MARKER: === sanity-lfsck: finish cleanup 10:08:53 (1790950133) === [ 5689.824308] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 5689.846551] 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 [ 5689.858323] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5692.901674] 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 [ 5692.902895] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5692.913889] Lustre: Skipped 1 previous similar message [ 5692.930725] Lustre: Skipped 3 previous similar messages [ 5695.158760] Lustre: server umount lustre-MDT0000 complete [ 5702.853502] LustreError: 180197:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1790950153 with bad export cookie 17732800255020531156 [ 5702.856461] LustreError: MGC192.168.203.132@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5702.864587] LustreError: 180197:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 5703.140231] LustreError: 180211:0:(ldlm_lib.c:1199: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. [ 5703.141684] 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 [ 5703.152965] LustreError: 180211:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 6 previous similar messages [ 5703.164795] Lustre: Skipped 1 previous similar message [ 5703.298545] Lustre: server umount lustre-MDT0001 complete [ 5711.466704] Lustre: server umount lustre-OST0000 complete [ 5720.702759] Lustre: server umount lustre-OST0001 complete [ 5736.735974] Lustre: DEBUG MARKER: oleg332-server.virtnet: executing unload_modules_local [ 5739.453979] Key type lgssc unregistered [ 5739.750122] LNet: 186638:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 5739.757629] LNetError: 186638:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 5739.778244] LNet: Removed LNI 192.168.203.132@tcp [ 5740.596327] Key type .llcrypt unregistered [ 5740.600520] Key type ._llcrypt unregistered