[ 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 504213991 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2399.998 MHz processor [ 0.000000] last_pfn = 0x146e00 max_arch_pfn = 0x400000000 [ 0.000000] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT [ 0.000000] last_pfn = 0xbffce max_arch_pfn = 0x400000000 [ 0.000000] found SMP MP-table at [mem 0x000f54b0-0x000f54bf] [ 0.000000] RAMDISK: [mem 0xbcc54000-0xbffbffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F52D0 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE247C 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE2318 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 0022D8 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE238C 000090 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE241C 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE2454 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe2318-0xbffe238b] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe2317] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe238c-0xbffe241b] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe241c-0xbffe2453] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe2454-0xbffe247b] [ 0.000000] No NUMA configuration found [ 0.000000] Faking a node at [mem 0x0000000000000000-0x0000000146dfffff] [ 0.000000] NODE_DATA(0) allocated [mem 0x1465a3000-0x1465cdfff] [ 0.000000] Reserving 256MB of memory at 2752MB for crashkernel (System RAM: 4205MB) [ 0.000000] Zone ranges: [ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.000000] DMA32 [mem 0x0000000001000000-0x00000000ffffffff] [ 0.000000] Normal [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Device empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff] [ 0.000000] node 0: [mem 0x0000000000100000-0x00000000bffcdfff] [ 0.000000] node 0: [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Zeroed struct page in unavailable ranges: 4756 pages [ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x0000000146dfffff] [ 0.000000] ACPI: PM-Timer IO Port: 0x608 [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) [ 0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) [ 0.000000] Using ACPI (MADT) for SMP configuration information [ 0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000] TSC deadline timer available [ 0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs [ 0.000000] kvm-guest: KVM setup pv remote TLB flush [ 0.000000] kvm-guest: setup PV sched yield [ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff] [ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff] [ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff] [ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff] [ 0.000000] PM: Registered nosave memory: [mem 0xbffce000-0xbfffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xc0000000-0xfeffbfff] [ 0.000000] PM: Registered nosave memory: [mem 0xfeffc000-0xfeffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xff000000-0xfffbffff] [ 0.000000] PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff] [ 0.000000] [mem 0xc0000000-0xfeffbfff] available for PCI devices [ 0.000000] Booting paravirtualized kernel on KVM [ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns [ 0.000000] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1 [ 0.000000] percpu: Embedded 63 pages/cpu s221184 r8192 d28672 u524288 [ 0.000000] kvm-guest: PV spinlocks enabled [ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1059606 [ 0.000000] Policy zone: Normal [ 0.000000] Kernel command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] Specific versions of hardware are certified with Red Hat Enterprise Linux 8. Please see the list of hardware certified with Red Hat Enterprise Linux 8 at https://catalog.redhat.com. [ 0.000000] audit: disabled (until reboot) [ 0.000000] software IO TLB: area num 4. [ 0.000000] Memory: 2829652K/4306352K available (18435K kernel code, 11221K rwdata, 7248K rodata, 2908K init, 18040K bss, 524584K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] ftrace: allocating 41240 entries in 162 pages [ 0.000000] ftrace: allocated 162 pages with 3 groups [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] rcu: RCU event tracing is enabled. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ 0.000000] rcu: RCU callback double-/use-after-free debug enabled. [ 0.000000] Rude variant of Tasks RCU enabled. [ 0.000000] Tracing variant of Tasks RCU enabled. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 0.000000] NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16 [ 0.000000] random: get_random_bytes called from start_kernel+0x622/0x9a8 with crng_init=0 [ 0.001000] Console: colour *CGA 80x25 [ 0.001000] printk: console [ttyS1] enabled [ 0.001000] ACPI: Core revision 20220331 [ 0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.001011] APIC: Switch to symmetric I/O mode setup [ 0.003207] x2apic enabled [ 0.004009] Switched APIC routing to physical x2apic. [ 0.005014] 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: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.008022] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.009012] pid_max: default: 32768 minimum: 301 [ 0.010140] LSM: Security Framework initializing [ 0.011060] Yama: becoming mindful. [ 0.012039] SELinux: Initializing. [ 0.013082] *** VALIDATE selinux *** [ 0.021813] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.026209] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.027164] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.028107] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.030030] *** VALIDATE tmpfs *** [ 0.031463] *** VALIDATE proc *** [ 0.033099] *** VALIDATE cgroup *** [ 0.034011] *** VALIDATE cgroup2 *** [ 0.036269] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.037146] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.038008] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.039032] Spectre V2 : User space: Vulnerable [ 0.040009] Speculative Store Bypass: Vulnerable [ 0.042894] debug: unmapping init [mem 0xffffffffad259000-0xffffffffad260fff] [ 0.045139] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.046703] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.047028] ... version: 2 [ 0.048013] ... bit width: 48 [ 0.049013] ... generic registers: 4 [ 0.050014] ... value mask: 0000ffffffffffff [ 0.051020] ... max period: 00007fffffffffff [ 0.052011] ... fixed-purpose events: 3 [ 0.053011] ... event mask: 000000070000000f [ 0.054305] rcu: Hierarchical SRCU implementation. [ 0.056483] smp: Bringing up secondary CPUs ... [ 0.057617] x86: Booting SMP configuration: [ 0.058028] .... node #0, CPUs: #1 #2 #3 [ 0.061538] smp: Brought up 1 node, 4 CPUs [ 0.063014] smpboot: Max logical packages: 1 [ 0.064018] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.146370] node 0 deferred pages initialised in 79ms [ 0.149101] devtmpfs: initialized [ 0.151215] x86/mm: Memory block size: 128MB [ 0.154598] gcov: version magic: 0x41383552 [ 0.158222] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.164141] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.168307] pinctrl core: initialized pinctrl subsystem [ 0.171195] [ 0.171964] ************************************************************* [ 0.175027] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.178011] ** ** [ 0.181013] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.185022] ** ** [ 0.189012] ** This means that this kernel is built to expose internal ** [ 0.192013] ** IOMMU data structures, which may compromise security on ** [ 0.196014] ** your system. ** [ 0.200014] ** ** [ 0.204011] ** If you see this message and you are not debugging the ** [ 0.207020] ** kernel, report this immediately to your vendor! ** [ 0.210013] ** ** [ 0.214013] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.217012] ************************************************************* [ 0.221710] NET: Registered protocol family 16 [ 0.224619] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.227198] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.231099] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.235138] cpuidle: using governor menu [ 0.236673] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.237388] PCI: Using configuration type 1 for base access [ 0.238131] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.246124] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.250039] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.254179] cryptd: max_cpu_qlen set to 1000 [ 0.260321] ACPI: Added _OSI(Module Device) [ 0.262021] ACPI: Added _OSI(Processor Device) [ 0.264026] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.266021] ACPI: Added _OSI(Processor Aggregator Device) [ 0.271065] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.279546] ACPI: Interpreter enabled [ 0.281079] ACPI: PM: (supports S0 S3 S4 S5) [ 0.283020] ACPI: Using IOAPIC for interrupt routing [ 0.285154] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.291540] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.302554] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.305046] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.308020] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.314088] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.320577] acpiphp: Slot [2] registered [ 0.322234] acpiphp: Slot [5] registered [ 0.324195] acpiphp: Slot [6] registered [ 0.326118] acpiphp: Slot [7] registered [ 0.328133] acpiphp: Slot [8] registered [ 0.330134] acpiphp: Slot [9] registered [ 0.331121] acpiphp: Slot [10] registered [ 0.333129] acpiphp: Slot [3] registered [ 0.335126] acpiphp: Slot [4] registered [ 0.336126] acpiphp: Slot [11] registered [ 0.338193] acpiphp: Slot [12] registered [ 0.340086] acpiphp: Slot [13] registered [ 0.342102] acpiphp: Slot [14] registered [ 0.343107] acpiphp: Slot [15] registered [ 0.345114] acpiphp: Slot [16] registered [ 0.347095] acpiphp: Slot [17] registered [ 0.348099] acpiphp: Slot [18] registered [ 0.350114] acpiphp: Slot [19] registered [ 0.352131] acpiphp: Slot [20] registered [ 0.353180] acpiphp: Slot [21] registered [ 0.355126] acpiphp: Slot [22] registered [ 0.356134] acpiphp: Slot [23] registered [ 0.358170] acpiphp: Slot [24] registered [ 0.360156] acpiphp: Slot [25] registered [ 0.361185] acpiphp: Slot [26] registered [ 0.363155] acpiphp: Slot [27] registered [ 0.365138] acpiphp: Slot [28] registered [ 0.366121] acpiphp: Slot [29] registered [ 0.368112] acpiphp: Slot [30] registered [ 0.370140] acpiphp: Slot [31] registered [ 0.371063] PCI host bridge to bus 0000:00 [ 0.373018] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.377036] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.380031] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.382031] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.385031] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.388041] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.391254] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.394208] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.397490] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.407694] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.412501] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.415023] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.418032] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.420022] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.423674] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.427744] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.430051] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.435998] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.442023] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.456028] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.460020] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.467031] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.474021] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.479017] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.495017] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.507112] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.513019] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.520023] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.544020] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.554928] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.566020] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.573015] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.588017] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.603073] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.612021] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.618021] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.639026] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.652209] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.665017] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.674015] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.688017] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 0.702190] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.715020] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.731023] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.758034] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 0.770614] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.774405] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.777478] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.780395] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.783252] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.789138] iommu: Default domain type: Passthrough [ 0.792410] SCSI subsystem initialized [ 0.794184] ACPI: bus type USB registered [ 0.795122] usbcore: registered new interface driver usbfs [ 0.798190] usbcore: registered new interface driver hub [ 0.801088] usbcore: registered new device driver usb [ 0.803238] pps_core: LinuxPPS API ver. 1 registered [ 0.805011] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.809064] PTP clock support registered [ 0.811123] EDAC MC: Ver: 3.0.0 [ 0.812146] PCI: Using ACPI for IRQ routing [ 0.814974] NetLabel: Initializing [ 0.816013] NetLabel: domain hash size = 128 [ 0.818013] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.820082] NetLabel: unlabeled traffic allowed by default [ 0.822130] vgaarb: loaded [ 0.824352] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.825021] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.831000] clocksource: Switched to clocksource kvm-clock [ 0.952418] VFS: Disk quotas dquot_6.6.0 [ 0.953805] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.956356] *** VALIDATE ramfs *** [ 0.957932] *** VALIDATE hugetlbfs *** [ 0.959722] pnp: PnP ACPI init [ 0.963128] pnp: PnP ACPI: found 6 devices [ 0.981527] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.984855] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.987221] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.989603] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.992089] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.994527] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.997118] NET: Registered protocol family 2 [ 0.999622] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 1.004321] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 1.008298] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 1.014956] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 1.018964] TCP: Hash tables configured (established 65536 bind 65536) [ 1.022575] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 1.026327] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 1.029710] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 1.032646] NET: Registered protocol family 1 [ 1.035305] RPC: Registered named UNIX socket transport module. [ 1.037749] RPC: Registered udp transport module. [ 1.039620] RPC: Registered tcp transport module. [ 1.041535] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 1.044180] NET: Registered protocol family 44 [ 1.046024] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 1.048345] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 1.050759] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 1.053488] PCI: CLS 0 bytes, default 64 [ 1.055328] Unpacking initramfs... [ 2.546979] debug: unmapping init [mem 0xffff9afcfcc54000-0xffff9afcfffbffff] [ 2.553747] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.557868] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.562498] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 3.079193] Initialise system trusted keyrings [ 3.080993] Key type blacklist registered [ 3.083231] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 3.093311] zbud: loaded [ 3.097201] *** VALIDATE nfs *** [ 3.098665] *** VALIDATE nfs4 *** [ 3.101921] pstore: using deflate compression [ 3.105747] Platform Keyring initialized [ 3.216889] NET: Registered protocol family 38 [ 3.218979] Key type asymmetric registered [ 3.220589] Asymmetric key parser 'x509' registered [ 3.222316] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 3.225259] io scheduler mq-deadline registered [ 3.226885] io scheduler kyber registered [ 3.228552] io scheduler bfq registered [ 3.230751] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 3.233789] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 3.237119] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 3.239831] ACPI: Power Button [PWRF] [ 3.245294] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 3.252147] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 3.267533] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 3.274921] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 3.295883] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 3.324837] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.354310] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.359426] Non-volatile memory driver v1.3 [ 3.361095] Linux agpgart interface v0.103 [ 3.392235] virtio_blk virtio1: [vda] 146648 512-byte logical blocks (75.1 MB/71.6 MiB) [ 3.396502] vda: detected capacity change from 0 to 75083776 [ 3.410618] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.414115] vdb: detected capacity change from 0 to 1073741824 [ 3.428729] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.432454] vdc: detected capacity change from 0 to 2621440000 [ 3.452572] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.455757] vdd: detected capacity change from 0 to 2621440000 [ 3.472263] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.475813] vde: detected capacity change from 0 to 4294967296 [ 3.489535] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.492126] vdf: detected capacity change from 0 to 4294967296 [ 3.499523] libphy: Fixed MDIO Bus: probed [ 3.504836] usbcore: registered new interface driver usbserial_generic [ 3.507504] usbserial: USB Serial support registered for generic [ 3.510158] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.516273] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.518343] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.521503] mousedev: PS/2 mouse device common for all mice [ 3.524676] rtc_cmos 00:05: RTC can wake from S4 [ 3.527885] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.528092] rtc_cmos 00:05: registered as rtc0 [ 3.533181] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.534599] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.536820] intel_pstate: CPU model not supported [ 3.543050] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.546111] hid: raw HID events driver (C) Jiri Kosina [ 3.550125] usbcore: registered new interface driver usbhid [ 3.552021] usbhid: USB HID core driver [ 3.553773] drop_monitor: Initializing network drop monitor service [ 3.556173] Initializing XFRM netlink socket [ 3.558460] NET: Registered protocol family 10 [ 3.561341] Segment Routing with IPv6 [ 3.562872] NET: Registered protocol family 17 [ 3.565220] mpls_gso: MPLS GSO support [ 3.571593] RAS: Correctable Errors collector initialized. [ 3.573838] AVX version of gcm_enc/dec engaged. [ 3.575780] AES CTR mode by8 optimization enabled [ 3.656531] sched_clock: Marking stable (3656503955, 0)->(4536029263, -879525308) [ 3.660276] registered taskstats version 1 [ 3.662797] Loading compiled-in X.509 certificates [ 3.665425] zswap: loaded using pool lzo/zbud [ 3.690795] Key type big_key registered [ 3.703049] Key type encrypted registered [ 3.704640] ima: No TPM chip found, activating TPM-bypass! [ 3.706544] ima: Allocated hash algorithm: sha1 [ 3.708255] ima: No architecture policies found [ 3.710214] evm: Initialising EVM extended attributes: [ 3.712019] evm: security.selinux [ 3.713313] evm: security.ima [ 3.714627] evm: security.capability [ 3.716142] evm: HMAC attrs: 0x1 [ 3.720204] rtc_cmos 00:05: setting system clock to 2026-08-31 17:30:41 UTC (1788197441) [ 3.726717] debug: unmapping init [mem 0xffffffffae203000-0xffffffffae3fffff] [ 3.729991] debug: unmapping init [mem 0xffffffffacf82000-0xffffffffad258fff] [ 3.739113] Write protecting the kernel read-only data: 28672k [ 3.742831] debug: unmapping init [mem 0xffffffffab603000-0xffffffffab7fffff] [ 3.745825] debug: unmapping init [mem 0xffffffffabf14000-0xffffffffabffffff] [ 3.785645] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 3.792609] systemd[1]: Detected virtualization kvm. [ 3.794806] systemd[1]: Detected architecture x86-64. [ 3.797241] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.824466] systemd[1]: No hostname configured. [ 3.826140] systemd[1]: Set hostname to . [ 3.828247] random: systemd: uninitialized urandom read (16 bytes read) [ 3.830782] systemd[1]: Initializing machine ID from random generator. [ 3.966257] random: systemd: uninitialized urandom read (16 bytes read) [ 3.969238] systemd[1]: Reached target Local File Systems. [ OK ] Reached target Local File Systems. [ 3.975092] random: systemd: uninitialized urandom read (16 bytes read) [ 3.978376] systemd[1]: Listening on udev Control Socket. [ OK ] Listening on udev Control Socket. [ 3.984774] systemd[1]: Reached target Slices. [ OK ] Reached target Slices. [ OK ] Listening on Journal Socket. [ OK ] Started Memstrack Anylazing Service. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Paths. Starting Create Volatile Files and Directories... Starting Apply Kernel Variables... Starting Setup Virtual Console... [ OK ] Reached target Timers. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Reached target Initrd Root Device. [ OK ] Listening on udev Kernel Socket. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Swap. [ OK ] Listening on Journal Socket (/dev/log). Starting Journal Service... [ OK ] Reached target Sockets. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Apply Kernel Variables. [ OK ] Started Setup Virtual Console. [ OK ] Started Create list of required sta…vice nodes for the current kernel. Starting Create Static Device Nodes in /dev... Starting dracut cmdline hook... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started Journal Service. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 4.644840] device-mapper: uevent: version 1.0.3 [ 4.647790] device-mapper: ioctl: 4.46.0-ioctl (2022-02-22) initialised: dm-devel@redhat.com [ OK ] Started dracut pre-udev hook. Starting udev Kernel Device Manager... [ OK ] Started udev Kernel Device Manager. Starting dracut pre-trigger hook... [ OK ] Started dracut pre-trigger hook. Starting udev Coldplug all Devices... Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. Starting dracut initqueue hook... [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ 5.368257] random: fast init done [ 5.387615] virtio_net virtio0 ens2: renamed from eth0 [ 5.445507] scsi host0: ata_piix [ 5.452162] scsi host1: ata_piix [ 5.455471] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 5.458035] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 9.126664] dracut-initqueue[585]: RTNETLINK answers: File exists [ 10.222672] random: crng init done [ 10.224139] 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.656869] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Remote File Systems. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped target Timers. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Sockets. [ OK ] Stopped target Slices. [ OK ] Stopped target Paths. [ OK ] Stopped target System Initialization. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Swap. [ OK ] Stopped target Local File Systems. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. [ OK ] Stopped Apply Kernel Variables. Stopping udev Kernel Device Manager... [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Closed udev Kernel Socket. [ OK ] Closed udev Control Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 11.809139] printk: systemd: 26 output lines suppressed due to ratelimiting [ 12.065771] SELinux: Disabled at runtime. [ 12.126238] 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.135645] systemd[1]: Detected virtualization kvm. [ 12.138954] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 12.632320] systemd[1]: initrd-switch-root.service: Succeeded. [ 12.637924] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 12.645289] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 12.653537] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 12.657150] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 12.664284] systemd[1]: Starting Journal Service... Starting Journal Service... [ 12.671851] systemd[1]: Mounting Kernel Debug File System... Mounting Kernel Debug File System... [ OK ] Listening on udev Kernel Socket. [ OK ] Reached target rpc_pipefs.target. [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Stopped target Switch Root. [ OK ] Listening on Process Core Dump Socket. [ OK ] Stopped target Initrd File Systems. Starting Create list of required st…ce nodes for the current kernel... Activating swap /dev/disk/by-label/SWAP... [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Created slice sy[ 12.754796] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS stem-getty.slice. Starting Remount Root and Kernel File Systems... [ OK ] Reached target RPC Port Mapper. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Created slice User and Session Slice. [ OK ] Reached target Slices. [ OK ] Stopped target Initrd Root File System. [ OK ] Listening on udev Control Socket. Starting udev Coldplug all Devices... Mounting Huge Pages File System... [ OK ] Created slice system-serial\x2dgetty.slice. Mounting POSIX Message Queue File System... [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. Starting Apply Kernel Variables... [ OK ] Started Journal Service. [ OK ] Mounted Kernel Debug File System. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Activated swap /dev/disk/by-label/SWAP. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Mounted Huge Pages File System. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Started Apply Kernel Variables. Starting Configure read-only root support... [ OK ] Reached target Swap. Starting Create Static Device Nodes in /dev... Starting Flush Journal to Persistent Storage... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. Starting udev Kernel Device Manager... [ OK ] Reached target Local File Systems (Pre). Mounting /home/green/git/lustre-release... Mounting /mnt... [ 13.065460] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Started udev Coldplug all Devices. [ OK ] Mounted /mnt. [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 13.355359] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 13.408966] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 13.519196] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 13.531475] EDAC sbridge: Ver: 1.1.2 [ 15.172391] Key type dns_resolver registered [ 15.475508] NFS: Registering the id_resolver key type [ 15.477887] Key type id_resolver registered [ 15.479812] Key type id_legacy registered [ OK ] Started Configure read-only root support. [ OK ] Reached target Local File Systems. Starting Mark the need to relabel after reboot... Starting Rebuild Dynamic Linker Cache... Starting Create Volatile Files and Directories... 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 Cleanup of Temporary Directories. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Started dnf makecache --timer. [ OK ] Reached target Timers. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. [ OK ] Reached target sshd-keygen.target. [ OK ] Started irqbalance daemon. Starting Restore /run/initramfs on shutdown... [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Started D-Bus System Message Bus. Starting Login Service... Starting Network Manager... [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Login Service. [ OK ] Started Network Manager. [ OK ] Reached target Network. Starting Dynamic System Tuning Daemon... Starting GSSAPI Proxy Daemon... Starting OpenSSH server daemon... Starting Network Manager Wait Online... Starting Hostname Service... [ OK ] Started OpenSSH server daemon. [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... [ OK ] Started Permit User Sessions. [ OK ] Started Getty on tty1. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Serial Getty on ttyS1. [ OK ] Reached target Login Prompts. [ OK ] Started Command Scheduler. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting Crash recovery kernel arming... Starting Notify NFS peers of a restart... Starting System Logging Service... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Starting Authorization Manager... [ OK ] Started Authorization Manager. [ OK ] Started Dynamic System Tuning Daemon. [ OK ] Reached target Multi-User System. [ OK ] Reached target Graphical Interface. Starting Update UTMP about System Runlevel Changes... [ OK ] Started Update UTMP about System Runlevel Changes. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg318-server login: [ 51.867762] libcfs: loading out-of-tree module taints kernel. [ 51.961449] Key type ._llcrypt registered [ 51.968301] Key type .llcrypt registered [ 52.146983] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_hostid [ 71.743779] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing load_modules_local [ 73.751598] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 73.784654] alg: No test for adler32 (adler32-zlib) [ 75.729725] Lustre: Lustre: Build Version: 2.17.57_103_g9c33a22 [ 76.940068] LNet: Added LNI 192.168.203.118@tcp [8/256/0/180] [ 78.711268] Key type lgssc registered [ 80.619931] Lustre: Echo OBD driver; http://www.lustre.org/ [ 82.847857] hrtimer: interrupt took 3626628 ns [ 99.857085] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 143.464528] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing load_modules_local [ 156.874322] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 156.918364] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 158.210996] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 158.232853] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 158.318091] Lustre: lustre-MDT0000: new disk, initializing [ 158.379571] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 158.393639] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 163.034100] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 176.805433] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 176.899316] Lustre: 6512: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 [ 176.930900] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 176.938953] Lustre: Skipped 1 previous similar message [ 177.016872] Lustre: lustre-MDT0001: new disk, initializing [ 177.083555] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 177.115923] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 177.135587] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 181.765391] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 186.750343] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 196.965360] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 197.508821] Lustre: lustre-OST0000: new disk, initializing [ 197.520217] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 197.538295] Lustre: 8449:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 197.690835] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 202.787722] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 202.807031] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 202.907366] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 204.646250] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 220.405472] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 220.550557] Lustre: lustre-OST0001: new disk, initializing [ 220.558900] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 220.563694] Lustre: 9521:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 220.642461] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 227.044630] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 228.409397] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 228.427876] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 228.515586] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 239.591185] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 248.564686] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 256.119970] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing check_logdir /tmp/testlogs/ [ 260.957850] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing yml_node [ 265.418563] Lustre: DEBUG MARKER: Client: 2.17.57.103 [ 267.848184] Lustre: DEBUG MARKER: MDS: 2.17.57.103 [ 270.488623] Lustre: DEBUG MARKER: OSS: 2.17.57.103 [ 272.493868] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity-lfsck ============----- Mon Aug 31 13:35:08 EDT 2026 [ 287.835523] Lustre: DEBUG MARKER: excepting tests: 18b 23b [ 296.747195] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing load_modules_local [ 305.121827] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 305.133599] 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 [ 305.152250] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 305.637123] 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 [ 305.648350] Lustre: Skipped 1 previous similar message [ 305.653109] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 305.664748] Lustre: Skipped 2 previous similar messages [ 312.402111] Lustre: server umount lustre-MDT0000 complete [ 315.873421] LustreError: 6522:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 315.912563] LustreError: 6522:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 8 previous similar messages [ 320.992706] LustreError: 6517:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 321.027359] LustreError: 6517:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 3 previous similar messages [ 322.299812] LustreError: 6502:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788197760 with bad export cookie 15551311092682905005 [ 322.311052] LustreError: MGC192.168.203.118@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 322.335395] LustreError: 6502:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 323.008465] Lustre: server umount lustre-MDT0001 complete [ 341.471211] Lustre: 3643:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788197763/real 1788197763] req@ffff9afc48068700 x1875060996538240/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788197779 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 341.517547] 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 [ 341.532738] Lustre: Skipped 1 previous similar message [ 342.498824] Lustre: 3646:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788197764/real 1788197764] req@ffff9afc48146300 x1875060996538496/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788197780 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 343.652733] Lustre: server umount lustre-OST0000 complete [ 346.666153] Lustre: 3643:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788197768/real 1788197768] req@ffff9afc48069f80 x1875060996538752/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788197784 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 352.769973] Lustre: server umount lustre-OST0001 complete [ 369.220065] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing unload_modules_local [ 372.885656] Key type lgssc unregistered [ 373.363607] LNet: 14792:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 373.368769] LNetError: 14792:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 374.441029] LNet: Removed LNI 192.168.203.118@tcp [ 376.162181] Key type .llcrypt unregistered [ 376.165383] Key type ._llcrypt unregistered [ 401.056848] Key type ._llcrypt registered [ 401.059277] Key type .llcrypt registered [ 401.167619] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_hostid [ 416.593352] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing load_modules_local [ 417.918476] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 417.947872] alg: No test for adler32 (adler32-zlib) [ 419.134508] Lustre: Lustre: Build Version: 2.17.57_103_g9c33a22 [ 419.433164] LNet: Added LNI 192.168.203.118@tcp [8/256/0/180] [ 421.111174] Key type lgssc registered [ 422.450314] Lustre: Echo OBD driver; http://www.lustre.org/ [ 480.986315] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing load_modules_local [ 494.280172] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 494.321200] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 495.593722] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 495.671043] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 495.803595] Lustre: lustre-MDT0000: new disk, initializing [ 495.871069] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 495.891912] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 500.079190] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 513.949675] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 514.057453] Lustre: 19247: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 [ 514.089985] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 514.099786] Lustre: Skipped 1 previous similar message [ 514.171262] Lustre: lustre-MDT0001: new disk, initializing [ 514.234335] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 514.274085] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 514.291829] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 518.299867] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 522.929058] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 531.729608] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 531.928906] Lustre: lustre-OST0000: new disk, initializing [ 531.932480] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 531.942736] Lustre: 21185:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 532.001391] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 535.325113] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 535.336713] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 535.399981] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 538.058565] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 552.037425] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 552.227277] Lustre: lustre-OST0001: new disk, initializing [ 552.230080] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 552.236972] Lustre: 22209:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 552.334145] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 558.467887] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 559.215426] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 559.231254] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 559.303938] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 570.312191] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 579.926740] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 589.255652] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 13:40:24 (1788198024) === [ 592.364546] Lustre: DEBUG MARKER: == sanity-lfsck test 0: Control LFSCK manually =========== 13:40:28 (1788198028) [ 592.544831] Lustre: 19253:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 251 < left 278, rollback = 2 [ 592.559631] Lustre: 19253:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 592.569175] Lustre: 19253:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 592.581946] Lustre: 19253:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 592.595530] Lustre: 19253:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 592.611379] Lustre: 19253:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 593.153665] Lustre: 19255:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 593.168092] Lustre: 19255:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 11 previous similar messages [ 593.177704] Lustre: 19255:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 593.183704] Lustre: 19255:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 593.191862] Lustre: 19255:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 593.202524] Lustre: 19255:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 593.209582] Lustre: 19255:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 593.220252] Lustre: 19255:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 593.229027] Lustre: 19255:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 593.235276] Lustre: 19255:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 593.241457] Lustre: 19255:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 593.252246] Lustre: 19255:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 594.183324] Lustre: 19255:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 594.189814] Lustre: 19255:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 35 previous similar messages [ 594.194456] Lustre: 19255:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 594.202941] Lustre: 19255:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 35 previous similar messages [ 594.208895] Lustre: 19255:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 594.216634] Lustre: 19255:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 35 previous similar messages [ 594.230329] Lustre: 19255:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 594.239640] Lustre: 19255:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 35 previous similar messages [ 594.244867] Lustre: 19255:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 594.250770] Lustre: 19255:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 35 previous similar messages [ 594.265386] Lustre: 19255:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 594.272741] Lustre: 19255:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 35 previous similar messages [ 596.195972] Lustre: 19254:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 596.205773] Lustre: 19254:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 101 previous similar messages [ 596.210644] Lustre: 19254:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 596.215600] Lustre: 19254:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 101 previous similar messages [ 596.219669] Lustre: 19254:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 596.225219] Lustre: 19254:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 101 previous similar messages [ 596.233035] Lustre: 19254:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 596.239313] Lustre: 19254:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 101 previous similar messages [ 596.244631] Lustre: 19254:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 596.249665] Lustre: 19254:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 101 previous similar messages [ 596.310278] Lustre: 19255:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 596.319601] Lustre: 19255:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 600.443967] Lustre: *** cfs_fail_loc=1600, val=3*** [ 602.754630] Lustre: 21175:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 260 < left 274, rollback = 2 [ 602.755665] Lustre: 23398:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 602.770682] Lustre: 21175:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 126 previous similar messages [ 602.779557] Lustre: 23398:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 125 previous similar messages [ 602.779605] Lustre: 23398:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 2/274/0 [ 602.779610] Lustre: 23398:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 125 previous similar messages [ 602.779617] Lustre: 23398:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 0/0/0, punch: 0/0/0, quota 7/225/0 [ 602.779620] Lustre: 23398:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 125 previous similar messages [ 602.779625] Lustre: 23398:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 602.779628] Lustre: 23398:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 125 previous similar messages [ 602.779634] Lustre: 23398:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 602.779641] Lustre: 23398:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 122 previous similar messages [ 605.183553] Lustre: *** cfs_fail_loc=1600, val=3*** [ 616.948619] Lustre: 23398:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 259 < left 274, rollback = 2 [ 616.960419] Lustre: 23611:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 616.969544] Lustre: 23398:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 51 previous similar messages [ 616.975599] Lustre: 23611:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 62 previous similar messages [ 616.975621] Lustre: 23611:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/1, xattr_set: 2/274/0 [ 616.975625] Lustre: 23611:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 62 previous similar messages [ 616.975630] Lustre: 23611:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 0/0/0, punch: 0/0/0, quota 7/225/0 [ 616.975633] Lustre: 23611:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 62 previous similar messages [ 616.975638] Lustre: 23611:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 616.975641] Lustre: 23611:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 62 previous similar messages [ 616.975693] Lustre: 23611:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 616.975696] Lustre: 23611:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 62 previous similar messages [ 621.026827] 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 [ 621.028813] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 621.050103] Lustre: Skipped 1 previous similar message [ 621.073488] Lustre: Skipped 3 previous similar messages [ 627.864155] Lustre: server umount lustre-MDT0000 complete [ 631.181645] LustreError: 19240:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788198068 with bad export cookie 4123620106924553196 [ 631.182861] LustreError: MGC192.168.203.118@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 631.196304] LustreError: 19240:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 631.265240] LustreError: 20599:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 631.267852] Lustre: lustre-MDT0001-lwp-OST0000: Connection to lustre-MDT0001 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 631.268230] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 631.283400] LustreError: 20599:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 6 previous similar messages [ 631.324418] Lustre: Skipped 3 previous similar messages [ 631.496085] Lustre: server umount lustre-MDT0001 complete [ 640.987827] Lustre: server umount lustre-OST0000 complete [ 645.110984] Lustre: server umount lustre-OST0001 complete [ 653.973692] Lustre: DEBUG MARKER: == sanity-lfsck test 1a: LFSCK can find out and repair crashed FID-in-dirent ========================================================== 13:41:30 (1788198090) [ 668.237223] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing load_modules_local [ 677.796498] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 678.339093] LustreError: 26269:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 678.412410] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 682.537985] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 683.490879] LustreError: 26270:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 688.609975] LustreError: 26269:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 690.048539] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 690.275991] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 694.391565] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 697.117665] Lustre: 27411:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 703.926846] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 711.116236] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 715.687593] LustreError: 27763:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 720.515432] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 720.789593] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 720.806702] Lustre: Skipped 1 previous similar message [ 723.919851] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:41 to 0x280000401:65) [ 723.930795] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:40 to 0x2c0000401:65) [ 727.470552] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 736.365777] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 740.300406] Lustre: 29283:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 742.521727] Lustre: 26265:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 742.531498] Lustre: 26265:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 3 previous similar messages [ 742.536520] Lustre: 26265:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 742.548597] Lustre: 26265:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 7 previous similar messages [ 742.555090] Lustre: 26265:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 742.562052] Lustre: 26265:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 7 previous similar messages [ 742.567550] Lustre: 26265:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 742.586966] Lustre: 26265:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 7 previous similar messages [ 742.594334] Lustre: 26265:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 742.601649] Lustre: 26265:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 7 previous similar messages [ 742.610669] Lustre: 26265:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 742.613453] Lustre: 26265:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 7 previous similar messages [ 750.464789] Lustre: *** cfs_fail_loc=1501, val=0*** [ 762.080672] Lustre: Failing over lustre-MDT0000 [ 762.309527] Lustre: server umount lustre-MDT0000 complete [ 764.918834] 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 [ 764.928420] Lustre: Skipped 1 previous similar message [ 764.931823] LustreError: 26264:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 764.952778] LustreError: 26264:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 3 previous similar messages [ 774.389760] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 774.499065] LustreError: MGC192.168.203.118@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 774.749613] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 774.805786] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 779.471723] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 779.744133] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 779.754362] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 779.780873] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 779.827322] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:105 to 0x2c0000401:129) [ 779.828208] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:105 to 0x280000401:129) [ 782.713147] Lustre: *** cfs_fail_loc=1505, val=0*** [ 790.293044] Lustre: DEBUG MARKER: == sanity-lfsck test 1b: LFSCK can find out and repair the missing FID-in-LMA ========================================================== 13:43:46 (1788198226) [ 791.565589] Lustre: 26265:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 256 < left 278, rollback = 2 [ 791.572902] Lustre: 26265:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 322 previous similar messages [ 791.582911] Lustre: 26265:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 791.589458] Lustre: 26265:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 791.600057] Lustre: 26265:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 791.611958] Lustre: 26265:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 791.624520] Lustre: 26265:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 791.635744] Lustre: 26265:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 791.644220] Lustre: 26265:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 791.652960] Lustre: 26265:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 791.665072] Lustre: 26265:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 791.685876] Lustre: 26265:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 796.900874] Lustre: *** cfs_fail_loc=1502, val=0*** [ 808.439371] Lustre: Failing over lustre-MDT0000 [ 809.314343] Lustre: server umount lustre-MDT0000 complete [ 810.464251] 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 [ 810.465555] LustreError: 26270:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 810.489941] Lustre: Skipped 5 previous similar messages [ 810.523891] LustreError: 26270:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 7 previous similar messages [ 820.929131] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 821.007168] LustreError: MGC192.168.203.118@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 821.210184] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 826.039219] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 826.344524] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 826.351214] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 826.363478] Lustre: Skipped 3 previous similar messages [ 826.385380] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 826.449182] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:169 to 0x280000401:193) [ 826.449289] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:169 to 0x2c0000401:193) [ 829.369853] Lustre: *** cfs_fail_loc=1505, val=0*** [ 837.361114] Lustre: DEBUG MARKER: == sanity-lfsck test 1c: LFSCK can find out and repair lost FID-in-dirent ========================================================== 13:44:33 (1788198273) [ 843.107508] Lustre: *** cfs_fail_loc=1504, val=0*** [ 843.114787] Lustre: *** cfs_fail_loc=1504, val=0*** [ 843.119850] Lustre: Skipped 1 previous similar message [ 850.878682] Lustre: Failing over lustre-MDT0000 [ 851.169712] Lustre: server umount lustre-MDT0000 complete [ 851.942791] 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 [ 851.965382] LustreError: 26270:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 851.967445] Lustre: Skipped 2 previous similar messages [ 851.972117] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 852.005565] LustreError: 26270:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 11 previous similar messages [ 861.148438] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 861.306520] LustreError: MGC192.168.203.118@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 861.550210] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 861.561129] Lustre: Skipped 1 previous similar message [ 861.600128] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 865.524327] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 866.789599] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 866.796298] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 866.815333] Lustre: Skipped 3 previous similar messages [ 866.848376] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 866.915053] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:233 to 0x280000401:257) [ 866.915382] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:233 to 0x2c0000401:257) [ 869.432587] Lustre: *** cfs_fail_loc=1505, val=0*** [ 876.514965] Lustre: DEBUG MARKER: == sanity-lfsck test 2a: LFSCK can find out and repair crashed linkEA entry ========================================================== 13:45:12 (1788198312) [ 877.968442] Lustre: 26266:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 877.984835] Lustre: 26266:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 644 previous similar messages [ 877.998810] Lustre: 26266:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 878.012662] Lustre: 26266:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 878.029518] Lustre: 26266:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 878.044137] Lustre: 26266:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 878.049411] Lustre: 26266:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 878.066723] Lustre: 26266:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 878.080660] Lustre: 26266:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 878.089861] Lustre: 26266:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 878.102608] Lustre: 26266:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 878.109562] Lustre: 26266:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 883.628396] Lustre: *** cfs_fail_loc=1603, val=0*** [ 891.545847] Lustre: Failing over lustre-MDT0000 [ 891.873507] Lustre: server umount lustre-MDT0000 complete [ 892.385587] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 892.388536] 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 [ 892.409214] Lustre: Skipped 4 previous similar messages [ 903.177182] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 903.342277] LustreError: MGC192.168.203.118@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 903.671597] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 908.803692] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 908.806843] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 908.818123] Lustre: Skipped 3 previous similar messages [ 908.875374] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 908.974108] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:297 to 0x280000401:321) [ 908.975964] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:297 to 0x2c0000401:321) [ 910.031489] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 922.715415] Lustre: DEBUG MARKER: == sanity-lfsck test 2b: LFSCK can find out and remove invalid linkEA entry ========================================================== 13:45:58 (1788198358) [ 930.555506] Lustre: *** cfs_fail_loc=1604, val=0*** [ 939.809275] Lustre: Failing over lustre-MDT0000 [ 939.999940] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 940.010080] 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 [ 940.059141] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 940.073809] Lustre: Skipped 1 previous similar message [ 940.330908] Lustre: server umount lustre-MDT0000 complete [ 944.607518] LustreError: 26270:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 944.627324] LustreError: 26270:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 19 previous similar messages [ 950.878117] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 950.994577] LustreError: MGC192.168.203.118@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 951.342771] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 955.699321] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 956.387326] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 956.407088] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 956.425385] Lustre: Skipped 3 previous similar messages [ 956.452475] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 956.498551] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:361 to 0x280000401:385) [ 956.501429] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:361 to 0x2c0000401:385) [ 965.444188] Lustre: DEBUG MARKER: == sanity-lfsck test 2c: LFSCK can find out and remove repeated linkEA entry ========================================================== 13:46:41 (1788198401) [ 972.946192] Lustre: *** cfs_fail_loc=1605, val=0*** [ 981.023103] Lustre: Failing over lustre-MDT0000 [ 981.373859] Lustre: server umount lustre-MDT0000 complete [ 981.985704] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 981.996440] 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 [ 982.015576] Lustre: Skipped 6 previous similar messages [ 991.906347] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 992.006118] LustreError: MGC192.168.203.118@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 992.196578] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 992.208620] Lustre: Skipped 2 previous similar messages [ 992.239593] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 997.345438] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 997.359939] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 997.373428] Lustre: Skipped 3 previous similar messages [ 997.384615] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 997.429963] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:425 to 0x280000401:449) [ 997.431630] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:425 to 0x2c0000401:449) [ 997.522706] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1006.984581] Lustre: DEBUG MARKER: == sanity-lfsck test 2d: LFSCK can recover the missing linkEA entry ========================================================== 13:47:22 (1788198442) [ 1008.385969] Lustre: 35426:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 256 < left 278, rollback = 2 [ 1008.396913] Lustre: 35426:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 967 previous similar messages [ 1008.404148] Lustre: 35426:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 1008.411076] Lustre: 35426:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 968 previous similar messages [ 1008.418548] Lustre: 35426:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 1008.425352] Lustre: 35426:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 968 previous similar messages [ 1008.434799] Lustre: 35426:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 1008.443201] Lustre: 35426:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 968 previous similar messages [ 1008.451184] Lustre: 35426:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 1008.458967] Lustre: 35426:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 968 previous similar messages [ 1008.465928] Lustre: 35426:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 1008.472908] Lustre: 35426:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 968 previous similar messages [ 1013.509630] Lustre: *** cfs_fail_loc=161d, val=0*** [ 1021.450913] Lustre: Failing over lustre-MDT0000 [ 1021.746349] Lustre: server umount lustre-MDT0000 complete [ 1022.945310] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1032.421549] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1032.569075] LustreError: MGC192.168.203.118@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1032.965615] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1037.728207] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1038.305168] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1038.334221] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1038.344818] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1038.351880] Lustre: Skipped 3 previous similar messages [ 1038.419508] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:489 to 0x280000401:513) [ 1038.419748] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:489 to 0x2c0000401:513) [ 1047.669905] Lustre: DEBUG MARKER: == sanity-lfsck test 2e: namespace LFSCK can verify remote object linkEA ========================================================== 13:48:03 (1788198483) [ 1050.733398] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1061.547639] Lustre: DEBUG MARKER: == sanity-lfsck test 3: LFSCK can verify multiple-linked objects ========================================================== 13:48:17 (1788198497) [ 1068.551484] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1069.580882] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1081.304797] Lustre: DEBUG MARKER: == sanity-lfsck test 4: FID-in-dirent can be rebuilt after MDT file-level backup/restore ========================================================== 13:48:37 (1788198517) [ 1118.531561] Lustre: Failing over lustre-MDT0000 [ 1119.449374] Lustre: server umount lustre-MDT0000 complete [ 1120.223492] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1120.227254] 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 [ 1120.233448] LustreError: 28292:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1120.233458] LustreError: 28292:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 24 previous similar messages [ 1120.370089] Lustre: Skipped 7 previous similar messages [ 1128.156363] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1136.623911] Lustre: 16405:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788198558/real 1788198558] req@ffff9afd7d801880 x1875061356819712/t0(0) o400->MGC192.168.203.118@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1788198574 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1136.677772] LustreError: MGC192.168.203.118@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1142.167290] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1158.065644] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1158.086540] Lustre: lustre-MDT0000: reset Object Index mappings [ 1162.209912] LustreError: 16404:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9afd777b6a00 x1875061356832256/t0(0) o250->MGC192.168.203.118@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 [ 1162.627413] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1167.852546] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1167.862508] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1167.900380] Lustre: Skipped 3 previous similar messages [ 1167.975351] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1168.091415] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:592 to 0x2c0000401:609) [ 1168.092171] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:592 to 0x280000401:609) [ 1168.535787] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1173.866830] LustreError: 42933:0:(lfsck_engine.c:1018:lfsck_master_engine()) lustre-MDT0000-osd: master engine fail to verify the .lustre/lost+found/, go ahead: rc = -115 [ 1173.894298] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1175.968182] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1175.973612] Lustre: Skipped 1 previous similar message [ 1184.011777] Lustre: Failing over lustre-MDT0000 [ 1186.309145] Lustre: server umount lustre-MDT0000 complete [ 1197.609268] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1203.252280] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:592 to 0x2c0000401:641) [ 1203.252697] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:592 to 0x280000401:641) [ 1204.129499] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1208.365361] Lustre: *** cfs_fail_loc=1505, val=0*** [ 1218.239443] Lustre: DEBUG MARKER: == sanity-lfsck test 5: LFSCK can handle IGIF object upgrading ========================================================== 13:50:53 (1788198653) [ 1221.052932] Lustre: *** cfs_fail_loc=1504, val=0*** [ 1228.809444] LustreError: 29312:0:(client.c:1394:ptlrpc_import_delay_req()) @@@ IMP_CLOSED req@ffff9afd77a5d500 x1875061356923392/t0(0) o104->lustre-OST0001@192.168.203.18@tcp:15/16 lens 328/224 e 0 to 0 dl 0 ref 1 fl Rpc:QU/0/ffffffff rc 0/-1 job:'' uid:4294967295 gid:4294967295 projid:4294967295 [ 1230.417222] Lustre: Failing over lustre-MDT0000 [ 1230.892938] Lustre: server umount lustre-MDT0000 complete [ 1233.895434] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1236.149173] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1247.477398] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1249.247093] Lustre: 16408:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788198671/real 1788198671] req@ffff9afc450e8e00 x1875061356925312/t0(0) o400->MGC192.168.203.118@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1788198687 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1258.632554] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1258.653792] Lustre: lustre-MDT0000: reset Object Index mappings [ 1259.493785] LustreError: 16404:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9afd7e0b3800 x1875061356933760/t0(0) o250->MGC192.168.203.118@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 [ 1259.848568] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1259.859080] Lustre: Skipped 3 previous similar messages [ 1259.903724] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1259.913100] Lustre: Skipped 1 previous similar message [ 1264.323421] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1265.129607] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1265.133503] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1265.136198] Lustre: Skipped 1 previous similar message [ 1265.166148] Lustre: Skipped 7 previous similar messages [ 1265.182408] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1265.197865] Lustre: Skipped 1 previous similar message [ 1265.274056] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:681 to 0x2c0000401:705) [ 1265.274157] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:681 to 0x280000401:705) [ 1267.829556] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1267.837227] Lustre: Skipped 1 previous similar message [ 1276.064617] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1276.069794] Lustre: Skipped 7 previous similar messages [ 1280.929118] Lustre: Failing over lustre-MDT0000 [ 1281.184224] Lustre: server umount lustre-MDT0000 complete [ 1285.608656] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1285.614038] 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 [ 1285.633971] Lustre: Skipped 11 previous similar messages [ 1292.096322] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1292.300995] LustreError: MGC192.168.203.118@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1292.315818] LustreError: Skipped 2 previous similar messages [ 1297.777850] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1298.001814] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:681 to 0x280000401:737) [ 1298.002349] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:681 to 0x2c0000401:737) [ 1301.143362] Lustre: *** cfs_fail_loc=1505, val=0*** [ 1301.145304] Lustre: Skipped 84 previous similar messages [ 1309.058340] Lustre: DEBUG MARKER: == sanity-lfsck test 6a: LFSCK resumes from last checkpoint (1) ========================================================== 13:52:25 (1788198745) [ 1310.255337] Lustre: 35426:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 1310.262575] Lustre: 35426:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 1249 previous similar messages [ 1310.269553] Lustre: 35426:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 1310.276568] Lustre: 35426:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1249 previous similar messages [ 1310.284675] Lustre: 35426:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 1310.298378] Lustre: 35426:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1249 previous similar messages [ 1310.315494] Lustre: 35426:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 1310.338059] Lustre: 35426:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1249 previous similar messages [ 1310.353579] Lustre: 35426:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 1310.358649] Lustre: 35426:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1249 previous similar messages [ 1310.364779] Lustre: 35426:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 1310.369889] Lustre: 35426:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1249 previous similar messages [ 1318.545067] Lustre: *** cfs_fail_loc=1600, val=1*** [ 1339.941675] Lustre: DEBUG MARKER: == sanity-lfsck test 6b: LFSCK resumes from last checkpoint (2) ========================================================== 13:52:55 (1788198775) [ 1351.328243] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1351.333492] Lustre: Skipped 10 previous similar messages [ 1376.483649] Lustre: DEBUG MARKER: == sanity-lfsck test 7a: non-stopped LFSCK should auto restarts after MDS remount (1) ========================================================== 13:53:32 (1788198812) [ 1394.670715] Lustre: Failing over lustre-MDT0000 [ 1394.928421] Lustre: server umount lustre-MDT0000 complete [ 1395.176252] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1395.190221] LustreError: 32570:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1395.220138] LustreError: 32570:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 82 previous similar messages [ 1404.337106] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1404.884869] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1404.896030] Lustre: Skipped 1 previous similar message [ 1409.063707] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1410.024176] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1410.050205] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 1410.071486] Lustre: Skipped 7 previous similar messages [ 1410.075314] Lustre: Skipped 1 previous similar message [ 1410.146321] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1410.160831] Lustre: Skipped 1 previous similar message [ 1410.284883] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:854 to 0x280000401:897) [ 1410.290194] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:853 to 0x2c0000401:897) [ 1420.682338] Lustre: DEBUG MARKER: == sanity-lfsck test 7b: non-stopped LFSCK should auto restarts after MDS remount (2) ========================================================== 13:54:15 (1788198855) [ 1437.613464] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing load_modules_local [ 1456.349755] Lustre: 52920:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 1481.368427] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1484.858380] Lustre: 54057:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 1492.895623] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1492.901520] Lustre: Skipped 81 previous similar messages [ 1495.966307] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1496.993798] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1498.015200] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1500.063567] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1500.066172] Lustre: Skipped 1 previous similar message [ 1501.652298] Lustre: Failing over lustre-MDT0000 [ 1501.941817] Lustre: server umount lustre-MDT0000 complete [ 1512.543753] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1517.176557] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1518.143170] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:947 to 0x280000401:993) [ 1518.143511] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:946 to 0x2c0000401:961) [ 1526.701453] Lustre: DEBUG MARKER: == sanity-lfsck test 8: LFSCK state machine ============== 13:56:02 (1788198962) [ 1533.408606] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1533.410926] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1533.427491] Lustre: Skipped 3 previous similar messages [ 1536.018123] Lustre: server umount lustre-MDT0000 complete [ 1539.537535] LustreError: 29314:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788198977 with bad export cookie 4123620106924766010 [ 1539.555524] LustreError: 29314:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 1540.029227] Lustre: server umount lustre-MDT0001 complete [ 1554.256643] Lustre: server umount lustre-OST0000 complete [ 1568.397724] Lustre: server umount lustre-OST0001 complete [ 1575.095417] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_hostid [ 1583.918648] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing load_modules_local [ 1629.737550] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing load_modules_local [ 1640.971453] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1641.182910] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 1641.216982] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 1641.298422] Lustre: lustre-MDT0000: new disk, initializing [ 1641.358889] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 1646.180190] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1657.256575] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1657.394859] Lustre: 59115: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 [ 1657.423685] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 1657.428747] Lustre: Skipped 1 previous similar message [ 1657.508167] Lustre: lustre-MDT0001: new disk, initializing [ 1657.591795] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 1657.613120] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 1662.475380] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1667.658755] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 1675.272425] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 1675.638783] Lustre: lustre-OST0000: new disk, initializing [ 1675.642838] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 1675.654772] Lustre: 60746:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 1677.338319] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 1677.355122] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 1677.415412] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 1682.214535] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1693.459873] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 1693.581480] Lustre: lustre-OST0001: new disk, initializing [ 1693.586750] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 1693.593702] Lustre: 61615:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 1694.753075] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 1694.782681] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 1694.871762] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 1700.785472] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1710.577388] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1714.101653] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 1724.606967] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1725.445599] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1725.447596] Lustre: Skipped 19 previous similar messages [ 1730.294754] Lustre: *** cfs_fail_loc=1601, val=2*** [ 1730.307312] Lustre: Skipped 18 previous similar messages [ 1750.767965] Lustre: Failing over lustre-MDT0000 [ 1751.009430] 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 [ 1751.027372] Lustre: Skipped 13 previous similar messages [ 1751.060388] Lustre: server umount lustre-MDT0000 complete [ 1760.470352] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1760.619988] LustreError: MGC192.168.203.118@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1760.638332] LustreError: Skipped 3 previous similar messages [ 1760.889770] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1760.907838] Lustre: Skipped 1 previous similar message [ 1764.966838] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1765.871241] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1765.879019] Lustre: Skipped 1 previous similar message [ 1765.881562] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1765.894359] Lustre: Skipped 7 previous similar messages [ 1765.922656] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1765.932919] Lustre: Skipped 1 previous similar message [ 1765.972221] Lustre: *** cfs_fail_loc=160b, val=2*** [ 1765.977350] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:65) [ 1765.977841] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:65) [ 1773.139750] Lustre: Failing over lustre-MDT0000 [ 1773.390309] Lustre: server umount lustre-MDT0000 complete [ 1783.409677] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1783.938899] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1783.945179] Lustre: Skipped 8 previous similar messages [ 1788.736346] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1789.470977] Lustre: *** cfs_fail_loc=160b, val=2*** [ 1789.492040] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:97) [ 1789.492618] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:97) [ 1794.396329] Lustre: Failing over lustre-MDT0000 [ 1794.539643] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1794.544748] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1794.554025] LustreError: Skipped 1 previous similar message [ 1794.566752] Lustre: Skipped 3 previous similar messages [ 1794.747543] Lustre: server umount lustre-MDT0000 complete [ 1804.109224] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1808.827054] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1809.996559] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:129) [ 1809.996806] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:129) [ 1814.350296] Lustre: *** cfs_fail_loc=1602, val=2*** [ 1814.358785] Lustre: Skipped 1 previous similar message [ 1827.527331] Lustre: DEBUG MARKER: == sanity-lfsck test 9a: LFSCK speed control (1) ========= 14:01:03 (1788199263) [ 1841.202348] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing load_modules_local [ 1858.263199] Lustre: 68637:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 1881.721471] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1885.957200] Lustre: 69773:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 1896.420692] Lustre: 62901:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 252 < left 278, rollback = 2 [ 1896.435922] Lustre: 62901:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 2791 previous similar messages [ 1896.454559] Lustre: 62901:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 1896.474107] Lustre: 62901:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 2791 previous similar messages [ 1896.491091] Lustre: 62901:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 1896.501487] Lustre: 62901:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 2791 previous similar messages [ 1896.510186] Lustre: 62901:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/1 [ 1896.528474] Lustre: 62901:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 2791 previous similar messages [ 1896.540328] Lustre: 62901:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 1896.565592] Lustre: 62901:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 2791 previous similar messages [ 1896.591401] Lustre: 62901:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 1896.602214] Lustre: 62901:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 2791 previous similar messages [ 2013.524983] Lustre: DEBUG MARKER: == sanity-lfsck test 9b: LFSCK speed control (2) ========= 14:04:09 (1788199449) [ 2067.241218] Lustre: *** cfs_fail_loc=1604, val=0*** [ 2067.246079] Lustre: Skipped 4 previous similar messages [ 2093.064798] Lustre: *** cfs_fail_loc=160c, val=0*** [ 2093.072041] Lustre: Skipped 9 previous similar messages [ 2129.291394] Lustre: DEBUG MARKER: == sanity-lfsck test 10: System is available during LFSCK scanning ========================================================== 14:06:05 (1788199565) [ 2182.040208] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2183.040293] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2183.043897] Lustre: Skipped 53 previous similar messages [ 2185.050243] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2185.057199] Lustre: Skipped 101 previous similar messages [ 2189.079500] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2189.089125] Lustre: Skipped 195 previous similar messages [ 2197.108503] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2197.110547] Lustre: Skipped 405 previous similar messages [ 2213.114409] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2213.116242] Lustre: Skipped 757 previous similar messages [ 2245.119223] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2245.124192] Lustre: Skipped 1588 previous similar messages [ 2255.260204] Lustre: *** cfs_fail_loc=1604, val=0*** [ 2255.268555] Lustre: Skipped 2599 previous similar messages [ 2494.472876] Lustre: DEBUG MARKER: == sanity-lfsck test 11a: LFSCK can rebuild lost last_id ========================================================== 14:12:10 (1788199930) [ 2541.473733] Lustre: 59122:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 320, rollback = 2 [ 2541.488220] Lustre: 59122:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 36831 previous similar messages [ 2541.497339] Lustre: 59122:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 1/4/0 [ 2541.508290] Lustre: 59122:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 36831 previous similar messages [ 2541.523334] Lustre: 59122:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 5/5/0, xattr_set: 7/320/0 [ 2541.532741] Lustre: 59122:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 36831 previous similar messages [ 2541.545369] Lustre: 59122:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 6/46/0, punch: 0/0/0, quota 1/3/0 [ 2541.555687] Lustre: 59122:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 36831 previous similar messages [ 2541.568774] Lustre: 59122:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 2/5/0 [ 2541.586396] Lustre: 59122:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 36831 previous similar messages [ 2541.601898] Lustre: 59122:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 1/1/0, ref_del: 2/2/0 [ 2541.610316] Lustre: 59122:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 36831 previous similar messages [ 2670.048280] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 2670.050959] 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 [ 2670.052494] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2670.091740] Lustre: Skipped 12 previous similar messages [ 2675.168700] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2675.175803] Lustre: Skipped 6 previous similar messages [ 2676.113835] Lustre: server umount lustre-MDT0000 complete [ 2679.948816] LustreError: 59107:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788200117 with bad export cookie 4123620106924785106 [ 2679.949848] LustreError: MGC192.168.203.118@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2679.957810] LustreError: 59107:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 2679.973058] LustreError: Skipped 2 previous similar messages [ 2680.308080] Lustre: server umount lustre-MDT0001 complete [ 2694.860168] Lustre: server umount lustre-OST0000 complete [ 2696.415123] Lustre: 16407:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788200118/real 1788200118] req@ffff9afd50316300 x1875061361082624/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788200134 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2698.199133] Lustre: server umount lustre-OST0001 complete [ 2704.898989] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: (null) [ 2714.258248] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 2729.823494] LustreError: Failed to get MGS log lustre-sptlrpc and no local copy. [ 2734.944394] LustreError: 75308:0:(mgc_request.c:233:do_config_log_add()) MGC192.168.203.118@tcp: failed processing log, type 4: rc = -110 [ 2760.671848] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 2760.680620] Lustre: Skipped 1 previous similar message [ 2767.500256] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2771.213919] Lustre: 75891: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. [ 2771.241201] Lustre: *** cfs_fail_loc=160e, val=3*** [ 2774.319152] Lustre: 75891:0:(ofd_dev.c:573:ofd_lfsck_out_notify()) lustre-OST0000: Rebuilt crashed LAST_ID files successfully. [ 2783.808452] Lustre: DEBUG MARKER: == sanity-lfsck test 11b: LFSCK can rebuild crashed last_id ========================================================== 14:16:59 (1788200219) [ 2799.339336] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing load_modules_local [ 2810.441626] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2810.912473] LustreError: 75333:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 2810.933395] LustreError: 75333:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 40 previous similar messages [ 2811.068658] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3271 to 0x280000401:3297) [ 2815.693233] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2824.225636] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2828.704754] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2831.657374] Lustre: 78555:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 2846.827955] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2852.340372] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3208 to 0x2c0000401:3233) [ 2853.262862] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2860.386717] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 2863.742401] Lustre: 80053:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 2868.003139] Lustre: *** cfs_fail_loc=160d, val=0*** [ 2874.848094] Lustre: Failing over lustre-OST0000 [ 2874.939442] Lustre: server umount lustre-OST0000 complete [ 2875.886171] LustreError: 75322:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 2875.915711] LustreError: 75322:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 18 previous similar messages [ 2884.099975] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2884.305385] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 2884.318258] Lustre: Skipped 2 previous similar messages [ 2886.115033] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 2886.122882] Lustre: Skipped 2 previous similar messages [ 2886.134343] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 2886.137525] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 2886.138419] Lustre: Skipped 2 previous similar messages [ 2886.140201] Lustre: *** cfs_fail_loc=215, val=0*** [ 2886.154226] Lustre: Skipped 11 previous similar messages [ 2890.048743] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2891.232667] Lustre: *** cfs_fail_loc=215, val=0*** [ 2891.238758] Lustre: Skipped 3 previous similar messages [ 2893.389666] Lustre: 81450: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. [ 2893.408144] Lustre: 81450:0:(ofd_dev.c:573:ofd_lfsck_out_notify()) lustre-OST0000: Rebuilt crashed LAST_ID files successfully. [ 2895.613020] Lustre: Failing over lustre-OST0000 [ 2895.707477] Lustre: server umount lustre-OST0000 complete [ 2903.476527] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2905.604627] Lustre: *** cfs_fail_loc=215, val=0*** [ 2905.613339] Lustre: Skipped 1 previous similar message [ 2909.872342] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2910.687532] Lustre: *** cfs_fail_loc=215, val=0*** [ 2910.697496] Lustre: Skipped 4 previous similar messages [ 2916.837509] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2924.233170] Lustre: server umount lustre-MDT0000 complete [ 2928.763411] LustreError: 75315:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788200366 with bad export cookie 4123620106926346393 [ 2928.784374] LustreError: 75315:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 2929.842049] Lustre: server umount lustre-MDT0001 complete [ 2935.936855] Lustre: server umount lustre-OST0000 complete [ 2939.955908] Lustre: server umount lustre-OST0001 complete [ 2948.176405] Lustre: DEBUG MARKER: == sanity-lfsck test 12a: single command to trigger LFSCK on all devices ========================================================== 14:19:44 (1788200384) [ 2964.095802] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing load_modules_local [ 2974.747186] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2979.534324] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2988.515816] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2993.077955] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2995.823433] Lustre: 85834:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3002.125581] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3008.636173] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3013.672602] LustreError: 86189:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3013.699047] LustreError: 86189:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 19 previous similar messages [ 3016.732287] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3021.035522] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3362 to 0x280000401:3393) [ 3021.042976] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3208 to 0x2c0000401:3265) [ 3023.897748] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3033.075455] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3037.050740] Lustre: 87704:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 3077.103557] Lustre: DEBUG MARKER: == sanity-lfsck test 12b: auto detect Lustre device ====== 14:21:53 (1788200513) [ 3091.396736] Lustre: DEBUG MARKER: == sanity-lfsck test 13: LFSCK can repair crashed lmm_oi ========================================================== 14:22:07 (1788200527) [ 3092.421306] Lustre: *** cfs_fail_loc=160f, val=0*** [ 3101.023892] Lustre: DEBUG MARKER: == sanity-lfsck test 14a: LFSCK can repair MDT-object with dangling LOV EA reference (1) ========================================================== 14:22:17 (1788200537) [ 3104.460970] Lustre: *** cfs_fail_loc=1610, val=0*** [ 3104.464936] Lustre: Skipped 7 previous similar messages [ 3152.864627] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3152.872830] Lustre: Skipped 4 previous similar messages [ 3158.432977] Lustre: server umount lustre-MDT0000 complete [ 3161.956211] LustreError: 84674:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788200599 with bad export cookie 4123620106926354849 [ 3161.975750] LustreError: 84674:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 3162.225689] Lustre: server umount lustre-MDT0001 complete [ 3176.345422] Lustre: server umount lustre-OST0000 complete [ 3189.558235] Lustre: server umount lustre-OST0001 complete [ 3202.859838] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing load_modules_local [ 3211.767807] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3215.924842] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3223.279859] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3226.965865] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3229.297408] Lustre: 93568:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3234.582502] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3237.872847] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3554 to 0x280000401:3585) [ 3239.880423] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3247.527435] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3248.685186] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:116 to 0x280000400:161) [ 3248.688442] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3317 to 0x2c0000401:3361) [ 3248.744637] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:116 to 0x2c0000400:161) [ 3253.167852] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3260.541923] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3264.680078] Lustre: 95438:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 3271.900529] Lustre: DEBUG MARKER: == sanity-lfsck test 14b: LFSCK can repair MDT-object with dangling LOV EA reference (2) ========================================================== 14:25:08 (1788200708) [ 3273.752698] Lustre: 92425:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 256 < left 278, rollback = 2 [ 3273.760233] Lustre: 92425:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 1364 previous similar messages [ 3273.766438] Lustre: 92425:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 3273.773536] Lustre: 92425:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1364 previous similar messages [ 3273.779801] Lustre: 92425:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3273.787742] Lustre: 92425:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1364 previous similar messages [ 3273.796167] Lustre: 92425:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 3273.804202] Lustre: 92425:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1364 previous similar messages [ 3273.810695] Lustre: 92425:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 3273.817790] Lustre: 92425:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1364 previous similar messages [ 3273.824663] Lustre: 92425:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3273.835705] Lustre: 92425:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1364 previous similar messages [ 3276.360338] Lustre: *** cfs_fail_loc=1610, val=0*** [ 3276.363292] Lustre: Skipped 63 previous similar messages [ 3294.689133] 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 [ 3294.689524] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3294.697692] Lustre: Skipped 19 previous similar messages [ 3294.700683] Lustre: Skipped 6 previous similar messages [ 3300.758986] Lustre: server umount lustre-MDT0000 complete [ 3304.009052] LustreError: 92410:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788200741 with bad export cookie 4123620106926383241 [ 3304.020089] LustreError: MGC192.168.203.118@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3304.024969] LustreError: 92410:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 3304.038480] LustreError: Skipped 2 previous similar messages [ 3304.255828] Lustre: server umount lustre-MDT0001 complete [ 3317.944233] Lustre: server umount lustre-OST0000 complete [ 3320.288142] Lustre: 16406:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788200742/real 1788200742] req@ffff9afc4c8fc700 x1875061361527808/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788200758 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3321.160455] Lustre: server umount lustre-OST0001 complete [ 3334.948971] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing load_modules_local [ 3343.284323] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3343.668363] LustreError: 98332:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3343.681395] LustreError: 98332:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 9 previous similar messages [ 3347.487825] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3356.175610] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3361.869592] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3364.507292] Lustre: 99471:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3371.183230] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3371.509977] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 3371.516522] Lustre: Skipped 15 previous similar messages [ 3377.959292] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3381.772471] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:116 to 0x280000400:193) [ 3386.777920] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3389.035725] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:116 to 0x2c0000400:193) [ 3389.048438] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3682 to 0x280000401:3713) [ 3389.132649] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3317 to 0x2c0000401:3393) [ 3393.577390] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3400.828686] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3414.193626] Lustre: DEBUG MARKER: == sanity-lfsck test 15a: LFSCK can repair unmatched MDT-object/OST-object pairs (1) ========================================================== 14:27:30 (1788200850) [ 3417.919219] Lustre: *** cfs_fail_loc=1611, val=0*** [ 3417.922345] Lustre: Skipped 63 previous similar messages [ 3418.184417] Lustre: *** cfs_fail_loc=1611, val=0*** [ 3428.351603] Lustre: DEBUG MARKER: == sanity-lfsck test 15b: LFSCK can repair unmatched MDT-object/OST-object pairs (2) ========================================================== 14:27:44 (1788200864) [ 3430.151561] Lustre: *** cfs_fail_loc=1612, val=0*** [ 3430.210861] Lustre: *** cfs_fail_loc=1612, val=0*** [ 3430.217826] Lustre: Skipped 3 previous similar messages [ 3440.709728] Lustre: DEBUG MARKER: == sanity-lfsck test 15c: LFSCK can repair unmatched MDT-object/OST-object pairs (3) ========================================================== 14:27:56 (1788200876) [ 3442.324558] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_15c MDS newer than 2.7.55, LU-6475 [ 3444.141346] Lustre: DEBUG MARKER: == sanity-lfsck test 15d: LFSCK don't crash upon dir migration failure ========================================================== 14:28:00 (1788200880) [ 3450.790982] Lustre: *** cfs_fail_loc=1709, val=0*** [ 3451.193730] LustreError: 98341:0:(mdt_reint.c:2644:mdt_reint_migrate()) lustre-MDT0000: migrate [0x240002340:0x6c:0x0]/f62 failed: rc = -5 [ 3462.711041] LustreError: 98329:0:(lod_object.c:945:lod_load_lmv_shards()) lustre-MDT0001-mdtlov: the shard [0x200003ab1:0x47:0x0]:1 for the striped directory [0x240002340:0x7e:0x0] is out of the known LMV EA range [0 - 0], failout [ 3465.879528] LustreError: 98327:0:(lod_object.c:945:lod_load_lmv_shards()) lustre-MDT0001-mdtlov: the shard [0x200003ab1:0x47:0x0]:1 for the striped directory [0x240002340:0x7e:0x0] is out of the known LMV EA range [0 - 0], failout [ 3465.902677] LustreError: 98327:0:(mdt_handler.c:1498:mdt_getattr_internal()) lustre-MDT0001: getattr error for [0x240002340:0x7e:0x0]: rc = -5 [ 3505.121148] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3505.133651] LustreError: Skipped 6 previous similar messages [ 3505.154122] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3505.171527] Lustre: Skipped 5 previous similar messages [ 3510.212982] Lustre: server umount lustre-MDT0000 complete [ 3518.704895] LustreError: 98312:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788200956 with bad export cookie 4123620106926397983 [ 3518.720557] LustreError: 98312:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 3519.150914] Lustre: server umount lustre-MDT0001 complete [ 3538.892904] Lustre: server umount lustre-OST0000 complete [ 3538.912425] Lustre: 16406:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788200960/real 1788200960] req@ffff9afc42737b80 x1875061361851136/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788200976 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3544.095133] Lustre: 16406:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788200965/real 1788200965] req@ffff9afc4f6d3480 x1875061361851648/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788200981 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3544.126521] Lustre: 16406:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 3547.836987] Lustre: server umount lustre-OST0001 complete [ 3564.191608] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing unload_modules_local [ 3566.823781] Key type lgssc unregistered [ 3567.114446] LNet: 105171:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 3567.123710] LNetError: 105171:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 3567.143899] LNet: Removed LNI 192.168.203.118@tcp [ 3567.895435] Key type .llcrypt unregistered [ 3567.900328] Key type ._llcrypt unregistered [ 3589.972041] Key type ._llcrypt registered [ 3589.974454] Key type .llcrypt registered [ 3590.096532] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_hostid [ 3601.435971] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing load_modules_local [ 3602.428992] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 3602.459214] alg: No test for adler32 (adler32-zlib) [ 3603.491257] Lustre: Lustre: Build Version: 2.17.57_103_g9c33a22 [ 3603.697487] LNet: Added LNI 192.168.203.118@tcp [8/256/0/180] [ 3605.359460] Key type lgssc registered [ 3606.396278] Lustre: Echo OBD driver; http://www.lustre.org/ [ 3652.692354] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing load_modules_local [ 3665.585405] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 3665.610624] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3666.858600] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 3666.907712] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 3666.976894] Lustre: lustre-MDT0000: new disk, initializing [ 3667.048887] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3667.066046] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 3671.172946] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3685.038310] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3685.124549] Lustre: 109605: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 [ 3685.153906] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 3685.158664] Lustre: Skipped 1 previous similar message [ 3685.212372] Lustre: lustre-MDT0001: new disk, initializing [ 3685.268536] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 3685.290285] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 3685.311638] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 3689.894844] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3695.092682] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 3705.723594] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3705.970944] Lustre: lustre-OST0000: new disk, initializing [ 3705.975857] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 3705.995917] Lustre: 111543:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 3706.111123] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 3711.554574] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 3711.567660] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 3711.725804] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 3713.481640] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3727.784347] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3727.964392] Lustre: lustre-OST0001: new disk, initializing [ 3727.973330] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 3727.989547] Lustre: 112566:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 3728.058166] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 3734.279917] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3737.623510] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 3737.640092] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 3737.695618] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 3746.524931] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3753.063173] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 3759.417042] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 14:33:15 (1788201195) === [ 3767.204933] Lustre: DEBUG MARKER: == sanity-lfsck test 16: LFSCK can repair inconsistent MDT-object/OST-object owner ========================================================== 14:33:23 (1788201203) [ 3767.859073] Lustre: 109611:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 251 < left 278, rollback = 2 [ 3767.871278] Lustre: 109611:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 3767.887488] Lustre: 109611:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3767.894236] Lustre: 109611:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 3767.904369] Lustre: 109611:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 3767.914814] Lustre: 109611:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3768.417970] Lustre: 109613:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 252 < left 278, rollback = 2 [ 3768.425267] Lustre: 109613:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 9 previous similar messages [ 3768.431062] Lustre: 109613:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 3768.438137] Lustre: 109613:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3768.445375] Lustre: 109613:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3768.458274] Lustre: 109613:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3768.465230] Lustre: 109613:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/1, punch: 0/0/0, quota 7/369/2 [ 3768.471210] Lustre: 109613:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3768.475950] Lustre: 109613:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/1, delete: 0/0/0 [ 3768.481940] Lustre: 109613:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3768.487529] Lustre: 109613:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3768.494281] Lustre: 109613:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3769.423752] Lustre: 113150:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 3769.428416] Lustre: 113150:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 188 previous similar messages [ 3769.435611] Lustre: 113150:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 3769.439657] Lustre: 113150:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 188 previous similar messages [ 3769.460853] Lustre: 109611:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3769.467950] Lustre: 109611:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 191 previous similar messages [ 3769.472602] Lustre: 109611:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 7/369/0 [ 3769.480463] Lustre: 109611:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 191 previous similar messages [ 3769.486376] Lustre: 109611:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 3769.495686] Lustre: 109611:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 191 previous similar messages [ 3769.507892] Lustre: 109611:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3769.515519] Lustre: 109611:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 191 previous similar messages [ 3771.430329] Lustre: *** cfs_fail_loc=1613, val=0*** [ 3782.598127] Lustre: DEBUG MARKER: == sanity-lfsck test 17: LFSCK can repair multiple references ========================================================== 14:33:38 (1788201218) [ 3783.500684] Lustre: 109612:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 253 < left 278, rollback = 2 [ 3783.507809] Lustre: 109612:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 110 previous similar messages [ 3783.513448] Lustre: 109612:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 3783.519165] Lustre: 109612:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 110 previous similar messages [ 3783.524158] Lustre: 109612:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3783.529144] Lustre: 109612:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 107 previous similar messages [ 3783.533862] Lustre: 109612:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/1 [ 3783.539141] Lustre: 109612:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 107 previous similar messages [ 3783.545086] Lustre: 109612:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 3783.550305] Lustre: 109612:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 107 previous similar messages [ 3783.555735] Lustre: 109612:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3783.561325] Lustre: 109612:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 107 previous similar messages [ 3784.557111] Lustre: *** cfs_fail_loc=1614, val=0*** [ 3788.889534] Lustre: 111534:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 259 < left 275, rollback = 2 [ 3788.909283] Lustre: 111534:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 11 previous similar messages [ 3788.923308] Lustre: 111534:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 3788.934743] Lustre: 111534:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3788.937770] Lustre: 111534:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/1, xattr_set: 3/275/0 [ 3788.955659] Lustre: 111534:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3788.960780] Lustre: 111534:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/9/0, punch: 1/4/0, quota 7/225/0 [ 3788.969181] Lustre: 111534:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3788.976185] Lustre: 111534:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 3788.982019] Lustre: 111534:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3788.986361] Lustre: 111534:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3788.990125] Lustre: 111534:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3795.623699] Lustre: DEBUG MARKER: == sanity-lfsck test 18a: Find out orphan OST-object and repair it (1) ========================================================== 14:33:51 (1788201231) [ 3796.987254] Lustre: 109612:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 253 < left 264, rollback = 2 [ 3797.005815] Lustre: 109612:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 16 previous similar messages [ 3797.031387] Lustre: 109612:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 3797.052261] Lustre: 109612:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 16 previous similar messages [ 3797.064102] Lustre: 109612:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 3/264/0 [ 3797.074350] Lustre: 109612:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 16 previous similar messages [ 3797.085373] Lustre: 109612:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 3797.092148] Lustre: 109612:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 16 previous similar messages [ 3797.097685] Lustre: 109612:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/1, delete: 0/0/0 [ 3797.103607] Lustre: 109612:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 16 previous similar messages [ 3797.110372] Lustre: 109612:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3797.114770] Lustre: 109612:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 16 previous similar messages [ 3798.694353] Lustre: *** cfs_fail_loc=1615, val=0*** [ 3798.699494] Lustre: Skipped 1 previous similar message [ 3799.751530] Lustre: *** cfs_fail_loc=1615, val=0*** [ 3799.757877] Lustre: Skipped 1 previous similar message [ 3817.406243] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_18b skipping excluded test 18b [ 3819.200719] Lustre: DEBUG MARKER: == sanity-lfsck test 18c: Find out orphan OST-object and repair it (3) ========================================================== 14:34:15 (1788201255) [ 3819.642097] Lustre: 109612:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 3819.650226] Lustre: 109612:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 6 previous similar messages [ 3819.655207] Lustre: 109612:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 3819.659636] Lustre: 109612:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 6 previous similar messages [ 3819.664930] Lustre: 109612:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3819.670188] Lustre: 109612:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 6 previous similar messages [ 3819.675246] Lustre: 109612:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 3819.684922] Lustre: 109612:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 6 previous similar messages [ 3819.690888] Lustre: 109612:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 3819.696453] Lustre: 109612:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 6 previous similar messages [ 3819.701152] Lustre: 109612:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3819.707045] Lustre: 109612:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 6 previous similar messages [ 3821.492865] Lustre: *** cfs_fail_loc=1617, val=0*** [ 3821.582972] Lustre: *** cfs_fail_loc=1617, val=0*** [ 3824.131736] Lustre: *** cfs_fail_loc=1616, val=0*** [ 3824.147521] Lustre: Skipped 3 previous similar messages [ 3844.550371] Lustre: DEBUG MARKER: == sanity-lfsck test 18d: Find out orphan OST-object and repair it (4) ========================================================== 14:34:40 (1788201280) [ 3846.562693] Lustre: *** cfs_fail_loc=1618, val=0*** [ 3846.568257] Lustre: Skipped 5 previous similar messages [ 3879.905094] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3879.914833] 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 [ 3879.933338] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3880.931461] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3880.932410] 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 [ 3880.940788] Lustre: Skipped 2 previous similar messages [ 3880.954635] Lustre: Skipped 2 previous similar messages [ 3886.011355] Lustre: server umount lustre-MDT0000 complete [ 3889.474892] LustreError: 109597:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788201327 with bad export cookie 6056224346896391761 [ 3889.477349] LustreError: MGC192.168.203.118@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3889.488390] LustreError: 109597:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 3889.747214] Lustre: server umount lustre-MDT0001 complete [ 3902.338825] Lustre: server umount lustre-OST0000 complete [ 3915.938829] Lustre: server umount lustre-OST0001 complete [ 3933.407822] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing load_modules_local [ 3943.760767] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3944.308144] LustreError: 118280:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3944.335372] LustreError: 118280:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 5 previous similar messages [ 3944.402047] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3948.926446] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3949.536490] LustreError: 118281:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3954.656280] LustreError: 118280:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3957.318922] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3957.657719] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 3961.886463] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3964.936418] Lustre: 119420:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3971.664447] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3978.610578] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3982.253832] LustreError: 119773:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3982.261682] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:4 to 0x280000400:33) [ 3987.004315] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3987.242231] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 3987.249551] Lustre: Skipped 1 previous similar message [ 3989.318753] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:4 to 0x2c0000401:33) [ 3989.325631] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:116 to 0x280000401:161) [ 3989.340298] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:33) [ 3993.141955] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4001.333647] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4004.550919] Lustre: 121292:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 4017.409451] Lustre: DEBUG MARKER: == sanity-lfsck test 18e: Find out orphan OST-object and repair it (5) ========================================================== 14:37:33 (1788201453) [ 4017.932374] Lustre: 121620:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 252 < left 278, rollback = 2 [ 4017.946040] Lustre: 121620:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 46 previous similar messages [ 4017.957090] Lustre: 121620:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4017.970308] Lustre: 121620:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4017.977160] Lustre: 121620:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4017.985983] Lustre: 121620:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4017.995356] Lustre: 121620:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/1 [ 4018.002677] Lustre: 121620:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4018.011324] Lustre: 121620:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 4018.017603] Lustre: 121620:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4018.027581] Lustre: 121620:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4018.031414] Lustre: 121620:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4019.766957] Lustre: *** cfs_fail_loc=1618, val=0*** [ 4019.770869] Lustre: Skipped 3 previous similar messages [ 4055.011652] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4055.021845] 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 [ 4055.058513] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4059.414719] Lustre: server umount lustre-MDT0000 complete [ 4061.158060] LustreError: 118280:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4061.182959] LustreError: 118280:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 3 previous similar messages [ 4062.665405] LustreError: 118262:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788201500 with bad export cookie 6056224346896407007 [ 4062.673924] LustreError: MGC192.168.203.118@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4062.931257] Lustre: server umount lustre-MDT0001 complete [ 4077.134915] Lustre: server umount lustre-OST0000 complete [ 4091.081636] Lustre: server umount lustre-OST0001 complete [ 4106.914420] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing load_modules_local [ 4119.159554] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4119.817895] LustreError: 123859:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4119.937936] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4125.443920] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4134.611797] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4139.817643] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4142.897642] Lustre: 124999:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 4149.716107] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4156.492621] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4159.272735] LustreError: 125351:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4159.311386] LustreError: 125351:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 3 previous similar messages [ 4159.331041] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:4 to 0x280000400:65) [ 4164.389090] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:166 to 0x280000401:193) [ 4165.681631] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4171.240911] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:4 to 0x2c0000401:65) [ 4171.249493] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:65) [ 4171.851875] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4179.423311] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4182.675325] Lustre: 126871:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 4187.703164] Lustre: 123859:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 252 < left 260, rollback = 2 [ 4187.712674] Lustre: 123859:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 21 previous similar messages [ 4187.723384] Lustre: 123859:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4187.730784] Lustre: 123859:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4187.741136] Lustre: 123859:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 0/0/0, xattr_set: 1/260/0 [ 4187.759370] Lustre: 123859:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4187.765167] Lustre: 123859:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/9/0, punch: 0/0/0, quota 4/150/2 [ 4187.775857] Lustre: 123859:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4187.788222] Lustre: 123859:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 1/17/2, delete: 0/0/0 [ 4187.794975] Lustre: 123859:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4187.800026] Lustre: 123859:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 4187.811776] Lustre: 123859:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4187.863121] Lustre: *** cfs_fail_loc=1602, val=10*** [ 4187.867223] Lustre: Skipped 1 previous similar message [ 4212.867676] Lustre: DEBUG MARKER: == sanity-lfsck test 18f: Skip the failed OST(s) when handle orphan OST-objects ========================================================== 14:40:49 (1788201649) [ 4215.770052] Lustre: *** cfs_fail_loc=1616, val=0*** [ 4215.774120] Lustre: Skipped 3 previous similar messages [ 4222.939668] Lustre: *** cfs_fail_loc=161c, val=0*** [ 4242.880778] Lustre: DEBUG MARKER: == sanity-lfsck test 18g: Find out orphan OST-object and repair it (7) ========================================================== 14:41:18 (1788201678) [ 4245.012348] Lustre: *** cfs_fail_loc=162e, val=0*** [ 4259.173773] Lustre: DEBUG MARKER: == sanity-lfsck test 18h: LFSCK can repair crashed PFL extent range ========================================================== 14:41:34 (1788201694) [ 4264.848185] Lustre: *** cfs_fail_loc=162f, val=0*** [ 4264.861172] Lustre: Skipped 9 previous similar messages [ 4281.821946] Lustre: DEBUG MARKER: == sanity-lfsck test 19a: OST-object inconsistency self detect ========================================================== 14:41:57 (1788201717) [ 4293.952118] Lustre: DEBUG MARKER: == sanity-lfsck test 19b: OST-object inconsistency self repair ========================================================== 14:42:09 (1788201729) [ 4296.900205] Lustre: *** cfs_fail_loc=1611, val=0*** [ 4296.934069] Lustre: *** cfs_fail_loc=1611, val=0*** [ 4296.940864] Lustre: Skipped 3 previous similar messages [ 4301.625448] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.203.18@tcp inode [0x2000013a1:0x1f:0x0] object 0x280000401:203 extent [0-4095], client returned csum 0 (type 4), server csum 703fb3ad (type 4) [ 4302.703699] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.203.18@tcp inode [0x2000013a1:0x20:0x0] object 0x280000401:204 extent [0-4095], client returned csum 0 (type 4), server csum 7cbb935c (type 4) [ 4309.677304] Lustre: DEBUG MARKER: == sanity-lfsck test 20a: Handle the orphan with dummy LOV EA slot properly ========================================================== 14:42:25 (1788201745) [ 4320.295847] Lustre: 131428:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 253 < left 263, rollback = 2 [ 4320.304755] Lustre: 131428:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 125 previous similar messages [ 4320.317249] Lustre: 131428:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4320.326171] Lustre: 131428:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 125 previous similar messages [ 4320.333076] Lustre: 131428:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 0/0/0, xattr_set: 2/263/0 [ 4320.344223] Lustre: 131428:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 125 previous similar messages [ 4320.354964] Lustre: 131428:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 0/0/0, punch: 0/0/0, quota 1/3/2 [ 4320.361327] Lustre: 131428:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 125 previous similar messages [ 4320.369857] Lustre: 131428:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/1, delete: 0/0/0 [ 4320.387033] Lustre: 131428:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 125 previous similar messages [ 4320.405756] Lustre: 131428:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 4320.410430] Lustre: 131428:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 125 previous similar messages [ 4335.233592] Lustre: DEBUG MARKER: == sanity-lfsck test 20b: Handle the orphan with dummy LOV EA slot properly - PFL case ========================================================== 14:42:51 (1788201771) [ 4341.738924] Lustre: DEBUG MARKER: == sanity-lfsck test 21: run all LFSCK components by default ========================================================== 14:42:57 (1788201777) [ 4354.159520] Lustre: DEBUG MARKER: == sanity-lfsck test 22a: LFSCK can repair unmatched pairs (1) ========================================================== 14:43:10 (1788201790) [ 4356.482094] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4356.489240] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4356.492958] Lustre: Skipped 1 previous similar message [ 4367.589658] Lustre: DEBUG MARKER: == sanity-lfsck test 22b: LFSCK can repair unmatched pairs (2) ========================================================== 14:43:23 (1788201803) [ 4369.133195] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4369.143807] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4380.285783] Lustre: DEBUG MARKER: == sanity-lfsck test 23a: LFSCK can repair dangling name entry (1) ========================================================== 14:43:36 (1788201816) [ 4382.092510] Lustre: *** cfs_fail_loc=1620, val=0*** [ 4397.155655] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_23b skipping excluded test 23b [ 4399.204301] Lustre: DEBUG MARKER: == sanity-lfsck test 23c: LFSCK can repair dangling name entry (3) ========================================================== 14:43:55 (1788201835) [ 4405.440412] Lustre: *** cfs_fail_loc=1621, val=127*** [ 4405.447314] Lustre: Skipped 1 previous similar message [ 4408.305801] Lustre: *** cfs_fail_loc=1602, val=10*** [ 4430.980924] Lustre: DEBUG MARKER: == sanity-lfsck test 23d: LFSCK can repair a dangling name entry to a remote object ========================================================== 14:44:26 (1788201866) [ 4433.156691] Lustre: Failing over lustre-MDT0000 [ 4433.447547] Lustre: server umount lustre-MDT0000 complete [ 4436.959834] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4436.977346] LustreError: 123841:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788201874 with bad export cookie 6056224346896411011 [ 4436.979719] 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 [ 4436.979736] Lustre: Skipped 3 previous similar messages [ 4436.980036] LustreError: 123859:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4436.980043] LustreError: 123859:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 2 previous similar messages [ 4437.079137] LustreError: 123841:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 3 previous similar messages [ 4443.775509] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4444.003035] LustreError: MGC192.168.203.118@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4444.343412] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4444.350901] Lustre: Skipped 3 previous similar messages [ 4444.411557] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4447.866205] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4449.160032] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4449.770949] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4449.831892] Lustre: lustre-MDT0000: Recovery over after 0:02, of 2 clients 2 recovered and 0 were evicted. [ 4449.883535] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:130 to 0x2c0000401:161) [ 4449.884339] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:265 to 0x280000401:289) [ 4451.156948] LustreError: 123856:0:(mdt_open.c:1324:mdt_cross_open()) lustre-MDT0000: [0x2000013a3:0x82:0x0] doesn't exist!: rc = -14 [ 4461.940737] Lustre: DEBUG MARKER: == sanity-lfsck test 24: LFSCK can repair multiple-referenced name entry ========================================================== 14:44:57 (1788201897) [ 4464.542985] Lustre: *** cfs_fail_loc=1622, val=0*** [ 4464.832553] Lustre: *** cfs_fail_loc=1622, val=0*** [ 4464.836976] Lustre: Skipped 1 previous similar message [ 4477.416317] Lustre: DEBUG MARKER: == sanity-lfsck test 25: LFSCK can repair bad file type in the name entry ========================================================== 14:45:12 (1788201912) [ 4479.416978] Lustre: *** cfs_fail_loc=1623, val=0*** [ 4492.653501] Lustre: DEBUG MARKER: == sanity-lfsck test 26a: LFSCK can add the missing local name entry back to the namespace ========================================================== 14:45:28 (1788201928) [ 4494.200252] Lustre: *** cfs_fail_loc=1624, val=0*** [ 4507.610358] Lustre: DEBUG MARKER: == sanity-lfsck test 26b: LFSCK can add the missing remote name entry back to the namespace ========================================================== 14:45:43 (1788201943) [ 4521.977744] Lustre: DEBUG MARKER: == sanity-lfsck test 27a: LFSCK can recreate the lost local parent directory as orphan ========================================================== 14:45:57 (1788201957) [ 4523.701756] Lustre: *** cfs_fail_loc=1624, val=0*** [ 4523.711635] Lustre: Skipped 1 previous similar message [ 4535.423861] Lustre: DEBUG MARKER: == sanity-lfsck test 27b: LFSCK can recreate the lost remote parent directory as orphan ========================================================== 14:46:11 (1788201971) [ 4549.213309] Lustre: DEBUG MARKER: == sanity-lfsck test 28: Skip the failed MDT(s) when handle orphan MDT-objects ========================================================== 14:46:24 (1788201984) [ 4555.812042] Lustre: *** cfs_fail_loc=161c, val=0*** [ 4555.816709] Lustre: Skipped 1 previous similar message [ 4572.444824] Lustre: DEBUG MARKER: == sanity-lfsck test 29b: LFSCK can repair bad nlink count (2) ========================================================== 14:46:48 (1788202008) [ 4574.425216] Lustre: *** cfs_fail_loc=1626, val=0*** [ 4574.427266] Lustre: Skipped 4 previous similar messages [ 4585.336621] Lustre: DEBUG MARKER: == sanity-lfsck test 29c: verify linkEA size limitation == 14:47:01 (1788202021) [ 4585.811937] Lustre: 123855:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 257 < left 320, rollback = 2 [ 4585.821707] Lustre: 123855:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 508 previous similar messages [ 4585.836382] Lustre: 123855:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 1/4/0 [ 4585.846900] Lustre: 123855:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 508 previous similar messages [ 4585.853994] Lustre: 123855:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 5/5/1, xattr_set: 7/320/0 [ 4585.863721] Lustre: 123855:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 508 previous similar messages [ 4585.872656] Lustre: 123855:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 6/46/0, punch: 0/0/0, quota 1/3/0 [ 4585.883287] Lustre: 123855:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 508 previous similar messages [ 4585.896240] Lustre: 123855:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 2/5/1 [ 4585.907119] Lustre: 123855:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 508 previous similar messages [ 4585.913227] Lustre: 123855:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 1/1/0, ref_del: 2/2/1 [ 4585.919693] Lustre: 123855:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 508 previous similar messages [ 4616.183617] Lustre: DEBUG MARKER: == sanity-lfsck test 29d: accessing non-existing inode shouldn't turn fs read-only (ldiskfs) ========================================================== 14:47:31 (1788202051) [ 4618.920688] LustreError: 123855:0:(osd_handler.c:284:osd_idc_find_or_init()) lustre-MDT0000: cannot lookup FID [0x2000013a3:0x9e:0x0]: rc = -2 [ 4626.094918] Lustre: DEBUG MARKER: == sanity-lfsck test 30: LFSCK can recover the orphans from backend /lost+found ========================================================== 14:47:42 (1788202062) [ 4649.992691] Lustre: Failing over lustre-MDT0000 [ 4650.290553] Lustre: server umount lustre-MDT0000 complete [ 4652.513447] 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 [ 4652.514648] LustreError: 123854:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4652.526820] Lustre: Skipped 5 previous similar messages [ 4652.564151] LustreError: 123854:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 13 previous similar messages [ 4661.243827] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 4661.364814] LustreError: MGC192.168.203.118@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4661.650915] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4661.688330] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4666.244501] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4666.856231] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4666.860581] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4666.866035] Lustre: Skipped 3 previous similar messages [ 4666.898312] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4666.934421] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:295 to 0x280000401:321) [ 4666.940484] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:166 to 0x2c0000401:193) [ 4679.984890] Lustre: DEBUG MARKER: == sanity-lfsck test 31a: The LFSCK can find/repair the name entry with bad name hash (1) ========================================================== 14:48:35 (1788202115) [ 4692.273663] Lustre: DEBUG MARKER: == sanity-lfsck test 31b: The LFSCK can find/repair the name entry with bad name hash (2) ========================================================== 14:48:48 (1788202128) [ 4706.073948] Lustre: DEBUG MARKER: == sanity-lfsck test 31c: Re-generate the lost master LMV EA for striped directory ========================================================== 14:49:02 (1788202142) [ 4707.619438] Lustre: *** cfs_fail_loc=1629, val=0*** [ 4707.628256] Lustre: Skipped 7 previous similar messages [ 4722.189645] Lustre: DEBUG MARKER: == sanity-lfsck test 31d: Set broken striped directory (modified after broken) as read-only ========================================================== 14:49:17 (1788202157) [ 4729.230391] Lustre: Failing over lustre-MDT0000 [ 4729.574967] Lustre: server umount lustre-MDT0000 complete [ 4733.418748] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4733.426521] 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 [ 4733.443361] Lustre: Skipped 1 previous similar message [ 4738.844066] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4739.041104] LustreError: MGC192.168.203.118@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4739.340695] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4744.143669] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4744.684814] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4744.691939] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4744.711056] Lustre: Skipped 3 previous similar messages [ 4744.757928] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4744.818319] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:295 to 0x280000401:353) [ 4744.821539] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:166 to 0x2c0000401:225) [ 4756.299750] Lustre: Failing over lustre-MDT0000 [ 4756.675737] Lustre: server umount lustre-MDT0000 complete [ 4760.034340] 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 [ 4760.040161] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4760.049910] Lustre: Skipped 5 previous similar messages [ 4766.633191] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4766.778615] LustreError: MGC192.168.203.118@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4767.079465] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4767.869313] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4772.239153] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4772.332593] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4772.341715] Lustre: Skipped 3 previous similar messages [ 4772.390691] Lustre: lustre-MDT0000: Recovery over after 0:05, of 2 clients 2 recovered and 0 were evicted. [ 4772.464171] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:166 to 0x2c0000401:257) [ 4772.467954] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:355 to 0x280000401:385) [ 4782.014818] Lustre: DEBUG MARKER: == sanity-lfsck test 31e: Re-generate the lost slave LMV EA for striped directory (1) ========================================================== 14:50:17 (1788202217) [ 4794.103802] Lustre: DEBUG MARKER: == sanity-lfsck test 31f: Re-generate the lost slave LMV EA for striped directory (2) ========================================================== 14:50:30 (1788202230) [ 4806.191285] Lustre: DEBUG MARKER: == sanity-lfsck test 31g: Repair the corrupted slave LMV EA ========================================================== 14:50:42 (1788202242) [ 4846.803980] Lustre: DEBUG MARKER: == sanity-lfsck test 31h: Repair the corrupted shard's name entry ========================================================== 14:51:22 (1788202282) [ 4848.599987] Lustre: *** cfs_fail_loc=162c, val=0*** [ 4848.608356] Lustre: Skipped 13 previous similar messages [ 4865.301666] Lustre: DEBUG MARKER: == sanity-lfsck test 32a: stop LFSCK when some OST failed ========================================================== 14:51:40 (1788202300) [ 4875.609383] LustreError: 148328:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d sleeping for 3000ms [ 4878.619732] LustreError: 148328:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d awake [ 4878.639516] LustreError: 148328:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d sleeping for 3000ms [ 4878.864617] Lustre: Failing over lustre-OST0000 [ 4879.109476] Lustre: server umount lustre-OST0000 complete [ 4879.851460] 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 [ 4879.874655] Lustre: Skipped 1 previous similar message [ 4879.886116] LustreError: 125354:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4879.913857] LustreError: 125354:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 23 previous similar messages [ 4881.735671] LustreError: 148328:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d awake [ 4881.751305] LustreError: 148328:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d sleeping for 3000ms [ 4881.986418] LustreError: 148328:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout interrupted [ 4894.777771] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 4895.221495] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 4896.489311] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4896.535636] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 4896.547798] Lustre: lustre-OST0000-osc-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4896.575381] Lustre: Skipped 3 previous similar messages [ 4903.133473] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4914.786312] Lustre: DEBUG MARKER: == sanity-lfsck test 32b: stop LFSCK when some MDT failed ========================================================== 14:52:30 (1788202350) [ 4932.276499] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing load_modules_local [ 4952.048723] Lustre: 151135:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 4978.458812] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4982.593688] Lustre: 152270:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 4997.767672] LustreError: 152410:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d sleeping for 3000ms [ 5000.847837] LustreError: 152409:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d awake [ 5001.055730] Lustre: Failing over lustre-MDT0001 [ 5002.723068] 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 [ 5002.726406] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 5002.726614] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 5002.747692] Lustre: Skipped 3 previous similar messages [ 5002.756613] Lustre: Skipped 5 previous similar messages [ 5003.879380] LustreError: 152410:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d awake [ 5003.892760] LustreError: 152410:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) Skipped 1 previous similar message [ 5004.462059] Lustre: server umount lustre-MDT0001 complete [ 5020.273720] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 5020.794546] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 5020.801690] Lustre: Skipped 3 previous similar messages [ 5020.849414] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 5026.102135] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5026.277717] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 1 client reconnects [ 5026.288026] Lustre: lustre-MDT0001-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 5026.311431] Lustre: Skipped 1 previous similar message [ 5026.337205] Lustre: lustre-MDT0001: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 5026.461238] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:70 to 0x280000400:97) [ 5026.467123] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:69 to 0x2c0000400:97) [ 5035.343353] Lustre: DEBUG MARKER: == sanity-lfsck test 33: check LFSCK paramters =========== 14:54:31 (1788202471) [ 5049.992402] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing load_modules_local [ 5068.279202] Lustre: 155136:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 5090.354176] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5094.430580] Lustre: 156271:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 5097.873911] Lustre: 123854:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 5097.894469] Lustre: 123854:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 1238 previous similar messages [ 5097.909383] Lustre: 123854:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 5097.931352] Lustre: 123854:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1238 previous similar messages [ 5097.940431] Lustre: 123854:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 5097.951894] Lustre: 123854:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1238 previous similar messages [ 5097.960222] Lustre: 123854:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 5097.975120] Lustre: 123854:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1238 previous similar messages [ 5097.980038] Lustre: 123854:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 5097.986920] Lustre: 123854:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1238 previous similar messages [ 5097.993173] Lustre: 123854:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 5098.019237] Lustre: 123854:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1238 previous similar messages [ 5117.049799] Lustre: DEBUG MARKER: == sanity-lfsck test 34: LFSCK can rebuild the lost agent object ========================================================== 14:55:52 (1788202552) [ 5118.659559] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_34 Only valid for ZFS backend [ 5120.449773] Lustre: DEBUG MARKER: == sanity-lfsck test 35: LFSCK can rebuild the lost agent entry ========================================================== 14:55:56 (1788202556) [ 5128.510970] Lustre: *** cfs_fail_loc=1631, val=0*** [ 5141.987680] 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 [ 5141.988971] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5142.012388] Lustre: Skipped 3 previous similar messages [ 5142.028038] Lustre: Skipped 4 previous similar messages [ 5146.455308] Lustre: server umount lustre-MDT0000 complete [ 5147.115943] LustreError: 123854:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 5147.129176] LustreError: 123854:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 16 previous similar messages [ 5149.924346] LustreError: 123842:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788202587 with bad export cookie 6056224346896479793 [ 5149.928992] LustreError: MGC192.168.203.118@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5149.944546] LustreError: 123842:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 3 previous similar messages [ 5150.305395] Lustre: server umount lustre-MDT0001 complete [ 5164.534835] Lustre: server umount lustre-OST0000 complete [ 5178.302064] Lustre: server umount lustre-OST0001 complete [ 5195.056425] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing load_modules_local [ 5204.910824] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5209.771711] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5217.843964] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5222.073518] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5224.832933] Lustre: 160166:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 5231.444635] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5237.386745] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5243.056230] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:70 to 0x280000400:129) [ 5246.368580] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5250.741130] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:540 to 0x280000401:577) [ 5250.742046] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:412 to 0x2c0000401:449) [ 5250.760652] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:69 to 0x2c0000400:129) [ 5253.054460] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5260.241642] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5264.444455] Lustre: 162039:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 5276.730750] Lustre: DEBUG MARKER: == sanity-lfsck test 36a: rebuild LOV EA for mirrored file (1) ========================================================== 14:58:32 (1788202712) [ 5278.875613] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36a needs >= 3 OSTs [ 5280.782526] Lustre: DEBUG MARKER: == sanity-lfsck test 36b: rebuild LOV EA for mirrored file (2) ========================================================== 14:58:36 (1788202716) [ 5282.666518] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36b needs >= 3 OSTs [ 5284.487993] Lustre: DEBUG MARKER: == sanity-lfsck test 36c: rebuild LOV EA for mirrored file (3) ========================================================== 14:58:40 (1788202720) [ 5286.490162] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36c needs >= 3 OSTs [ 5288.479323] Lustre: DEBUG MARKER: == sanity-lfsck test 37: LFSCK must skip a ORPHAN ======== 14:58:44 (1788202724) [ 5299.949310] Lustre: DEBUG MARKER: == sanity-lfsck test 38: LFSCK does not break foreign file and reverse is also true ========================================================== 14:58:56 (1788202736) [ 5313.159686] Lustre: DEBUG MARKER: == sanity-lfsck test 39: LFSCK does not break foreign dir and reverse is also true ========================================================== 14:59:08 (1788202748) [ 5327.918185] Lustre: DEBUG MARKER: == sanity-lfsck test 40a: LFSCK correctly fixes lmm_oi in composite layout ========================================================== 14:59:23 (1788202763) [ 5343.001805] Lustre: DEBUG MARKER: == sanity-lfsck test 41: SEL support in LFSCK ============ 14:59:38 (1788202778) [ 5362.960244] Lustre: DEBUG MARKER: == sanity-lfsck test 42: LFSCK repairs inconsistent MDT-object/OST-object encryption flags ========================================================== 14:59:59 (1788202799) [ 5397.678861] Lustre: *** cfs_fail_loc=1632, val=0*** [ 5414.514261] Lustre: DEBUG MARKER: == sanity-lfsck test 43: LFSCK does not loop endlessly on iget failure in scanning-phase1 ========================================================== 15:00:49 (1788202849) [ 5418.364100] Lustre: Failing over lustre-MDT0001 [ 5418.723623] Lustre: server umount lustre-MDT0001 complete [ 5420.000894] 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 [ 5420.019310] Lustre: Skipped 2 previous similar messages [ 5427.162943] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5427.527967] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 5427.534401] Lustre: lustre-MDT0001: Aborting client recovery [ 5427.537900] LustreError: 165836:0:(ldlm_lib.c:3029:target_stop_recovery_thread()) lustre-MDT0001: Aborting recovery [ 5427.542306] LustreError: 165859:0:(lod_dev.c:511:lod_sub_recovery_thread()) lustre-MDT0000-osp-MDT0001: get update log duration 0, retries 0, failed: rc = -108 [ 5427.546744] Lustre: 165860:0:(ldlm_lib.c:2429:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 5427.558363] Lustre: 165860:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0001: disconnect stale client f714c7ad-9c3e-4b39-8bf9-16a34cfed6d4@ [ 5427.564623] Lustre: lustre-MDT0001: disconnecting 2 stale clients [ 5427.571184] Lustre: lustre-MDT0001-osd: cancel update llog [0x240000400:0x1:0x0] [ 5427.592771] Lustre: lustre-MDT0000-osp-MDT0001: cancel update llog [0x200000401:0x1:0x0] [ 5427.689122] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:131 to 0x280000400:161) [ 5427.691066] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:69 to 0x2c0000400:161) [ 5432.667659] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5432.806756] LustreError: lustre-MDT0001-osp-MDT0000: This client was evicted by lustre-MDT0001; in progress operations using this service will fail. [ 5432.831515] Lustre: lustre-MDT0001-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 5432.838226] Lustre: Skipped 2 previous similar messages [ 5441.969518] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing wait_import_state FULL osp.lustre-MDT0001-os[pc]-MDT0000.*_server_uuid [ 5442.364083] Lustre: DEBUG MARKER: osp.lustre-MDT0001-os[pc]-MDT0000.*_server_uuid in FULL state after 0 sec [ 5450.557374] Lustre: DEBUG MARKER: == sanity-lfsck test 44: umount while lfsck is stopping == 15:01:26 (1788202886) [ 5460.398558] Lustre: *** cfs_fail_loc=1600, val=3*** [ 5463.310729] Lustre: Failing over lustre-MDT0000 [ 5463.521721] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5463.524938] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 5463.528259] Lustre: Skipped 1 previous similar message [ 5463.734415] Lustre: server umount lustre-MDT0000 complete [ 5473.066324] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5473.181293] LustreError: MGC192.168.203.118@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5473.451702] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 5473.463519] Lustre: Skipped 2 previous similar messages [ 5476.990366] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 5478.147361] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5478.887785] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 5478.900369] Lustre: Skipped 1 previous similar message [ 5478.947864] Lustre: lustre-MDT0000: Recovery over after 0:02, of 2 clients 2 recovered and 0 were evicted. [ 5478.976096] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:621 to 0x280000401:641) [ 5478.980268] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:489 to 0x2c0000401:513) [ 5487.856826] Lustre: DEBUG MARKER: == sanity-lfsck test 45: LFSCK should fix UID/GID/PROJID of OST object ========================================================== 15:02:03 (1788202923) [ 5535.145723] Lustre: Failing over lustre-OST0001 [ 5535.199538] LustreError: lustre-OST0001-osc-MDT0001: operation ost_statfs to node 0@lo failed: rc = -107 [ 5535.310686] Lustre: server umount lustre-OST0001 complete [ 5541.308392] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: (null) [ 5552.540787] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5552.717250] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 5552.723845] Lustre: Skipped 6 previous similar messages [ 5552.733257] Lustre: lustre-OST0001: in recovery but waiting for the first client to connect [ 5553.806859] Lustre: lustre-OST0001: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 5554.542887] Lustre: lustre-OST0001: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [ 5554.543514] Lustre: lustre-OST0001-osc-MDT0001: Connection restored to 0@lo (at 0@lo) [ 5554.567360] Lustre: Skipped 3 previous similar messages [ 5558.445715] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5565.442329] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing wait_import_state (FULL|IDLE) os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid 50 [ 5565.642221] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid in FULL state after 0 sec [ 5570.611941] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing wait_import_state (FULL|IDLE) os[cp].lustre-OST0000-osc-MDT0001.ost_server_uuid 50 [ 5570.839195] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0001.ost_server_uuid in FULL state after 0 sec [ 5576.092386] Lustre: DEBUG MARKER: oleg318-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0000-osc-ffff9b9fd82c0800.ost_server_uuid 50 [ 5577.792443] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9b9fd82c0800.ost_server_uuid in FULL state after 0 sec [ 5655.016898] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5655.025708] Lustre: Skipped 4 previous similar messages [ 5660.138426] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5660.149811] Lustre: Skipped 3 previous similar messages [ 5661.106429] Lustre: server umount lustre-MDT0000 complete [ 5665.252252] LustreError: 159022:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 5665.266224] LustreError: 159022:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 33 previous similar messages [ 5668.881956] LustreError: 159007:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788203106 with bad export cookie 6056224346896562505 [ 5668.885454] LustreError: MGC192.168.203.118@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5668.891830] LustreError: 159007:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 5669.274675] Lustre: server umount lustre-MDT0001 complete [ 5686.560094] Lustre: 106761:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788203108/real 1788203108] req@ffff9afd51bc8380 x1875064696846720/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788203124 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5687.741441] Lustre: server umount lustre-OST0000 complete [ 5689.823143] Lustre: 106759:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788203111/real 1788203111] req@ffff9afc454afb80 x1875064696846976/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788203127 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5691.871081] Lustre: 106762:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788203113/real 1788203113] req@ffff9afc45e0c700 x1875064696847232/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788203129 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5694.943270] Lustre: 106760:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788203116/real 1788203116] req@ffff9afc45e0c380 x1875064696847616/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788203132 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5695.944398] Lustre: server umount lustre-OST0001 complete [ 5712.506844] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing unload_modules_local [ 5715.265691] Key type lgssc unregistered [ 5715.647665] LNet: 175527:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 5715.663405] LNetError: 175527:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 5715.681970] LNet: Removed LNI 192.168.203.118@tcp [ 5716.455147] Key type .llcrypt unregistered [ 5716.457433] Key type ._llcrypt unregistered [ 5743.513645] Key type ._llcrypt registered [ 5743.519604] Key type .llcrypt registered [ 5743.642462] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_hostid [ 5761.154706] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing load_modules_local [ 5762.292612] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 5762.325898] alg: No test for adler32 (adler32-zlib) [ 5763.362825] Lustre: Lustre: Build Version: 2.17.57_103_g9c33a22 [ 5763.647185] LNet: Added LNI 192.168.203.118@tcp [8/256/0/180] [ 5765.335204] Key type lgssc registered [ 5766.659484] Lustre: Echo OBD driver; http://www.lustre.org/ [ 5817.332528] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing load_modules_local [ 5832.758911] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 5832.821623] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5834.168826] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 5834.203745] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 5834.312290] Lustre: lustre-MDT0000: new disk, initializing [ 5834.399288] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 5834.419389] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 5839.042789] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5851.973408] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5852.138090] Lustre: 179983: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 [ 5852.216424] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 5852.223811] Lustre: Skipped 1 previous similar message [ 5852.395267] Lustre: lustre-MDT0001: new disk, initializing [ 5852.515469] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 5852.572938] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 5852.592406] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 5856.770754] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5861.672671] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 5872.093366] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5872.407202] Lustre: lustre-OST0000: new disk, initializing [ 5872.411440] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 5872.416833] Lustre: 181919:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 5872.505354] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 5875.407065] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 5875.419650] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 5875.559171] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 5878.836976] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5893.683810] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5893.830259] Lustre: lustre-OST0001: new disk, initializing [ 5893.835262] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 5893.840846] Lustre: 182945:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 5893.894658] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 5900.194108] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5902.393715] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 5902.412617] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 5902.462341] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 5913.834820] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5923.307017] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 5930.293790] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 15:09:26 (1788203366) === [ 5932.750625] Lustre: DEBUG MARKER: == sanity-lfsck test complete, duration 5657 sec ========= 15:09:27 (1788203367) [ 5934.647738] Lustre: DEBUG MARKER: === sanity-lfsck: start cleanup 15:09:30 (1788203370) === [ 5939.413937] Lustre: DEBUG MARKER: === sanity-lfsck: finish cleanup 15:09:34 (1788203374) === [ 5944.800369] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 5944.808918] 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 [ 5944.822230] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5948.390778] 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 [ 5948.394215] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5948.404044] Lustre: Skipped 2 previous similar messages [ 5948.407835] Lustre: Skipped 2 previous similar messages [ 5950.712672] Lustre: server umount lustre-MDT0000 complete [ 5958.625236] LustreError: 179995:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 5958.653793] LustreError: 179995:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 8 previous similar messages [ 5959.373684] LustreError: 179976:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788203397 with bad export cookie 9033744317058986277 [ 5959.377722] LustreError: MGC192.168.203.118@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5959.383326] LustreError: 179976:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 5959.828747] Lustre: server umount lustre-MDT0001 complete [ 5977.615501] Lustre: server umount lustre-OST0000 complete [ 5980.127119] Lustre: 177141:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788203401/real 1788203401] req@ffff9afc4f668700 x1875066959779968/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788203417 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5980.174471] 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 [ 5980.639131] Lustre: 177144:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788203402/real 1788203402] req@ffff9afc5012e680 x1875066959780224/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788203418 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5984.735288] Lustre: 177142:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788203406/real 1788203406] req@ffff9afc4bfdf800 x1875066959780480/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788203422 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5986.357859] Lustre: server umount lustre-OST0001 complete [ 6004.995910] Lustre: DEBUG MARKER: oleg318-server.virtnet: executing unload_modules_local [ 6008.189064] Key type lgssc unregistered [ 6008.769262] LNet: 186419:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 6008.785907] LNetError: 186419:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 6008.837169] LNet: Removed LNI 192.168.203.118@tcp [ 6010.297001] Key type .llcrypt unregistered [ 6010.300063] Key type ._llcrypt unregistered