[ 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 609880303 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2399.998 MHz processor [ 0.000000] last_pfn = 0x146e00 max_arch_pfn = 0x400000000 [ 0.000000] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT [ 0.000000] last_pfn = 0xbffce max_arch_pfn = 0x400000000 [ 0.000000] found SMP MP-table at [mem 0x000f54b0-0x000f54bf] [ 0.000000] RAMDISK: [mem 0xbcc54000-0xbffbffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F52D0 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE247C 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE2318 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 0022D8 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE238C 000090 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE241C 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE2454 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe2318-0xbffe238b] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe2317] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe238c-0xbffe241b] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe241c-0xbffe2453] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe2454-0xbffe247b] [ 0.000000] No NUMA configuration found [ 0.000000] Faking a node at [mem 0x0000000000000000-0x0000000146dfffff] [ 0.000000] NODE_DATA(0) allocated [mem 0x1465a3000-0x1465cdfff] [ 0.000000] Reserving 256MB of memory at 2752MB for crashkernel (System RAM: 4205MB) [ 0.000000] Zone ranges: [ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.000000] DMA32 [mem 0x0000000001000000-0x00000000ffffffff] [ 0.000000] Normal [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Device empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff] [ 0.000000] node 0: [mem 0x0000000000100000-0x00000000bffcdfff] [ 0.000000] node 0: [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Zeroed struct page in unavailable ranges: 4756 pages [ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x0000000146dfffff] [ 0.000000] ACPI: PM-Timer IO Port: 0x608 [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) [ 0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) [ 0.000000] Using ACPI (MADT) for SMP configuration information [ 0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000] TSC deadline timer available [ 0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs [ 0.000000] kvm-guest: KVM setup pv remote TLB flush [ 0.000000] kvm-guest: setup PV sched yield [ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff] [ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff] [ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff] [ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff] [ 0.000000] PM: Registered nosave memory: [mem 0xbffce000-0xbfffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xc0000000-0xfeffbfff] [ 0.000000] PM: Registered nosave memory: [mem 0xfeffc000-0xfeffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xff000000-0xfffbffff] [ 0.000000] PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff] [ 0.000000] [mem 0xc0000000-0xfeffbfff] available for PCI devices [ 0.000000] Booting paravirtualized kernel on KVM [ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns [ 0.000000] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1 [ 0.000000] percpu: Embedded 63 pages/cpu s221184 r8192 d28672 u524288 [ 0.000000] kvm-guest: PV spinlocks enabled [ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1059606 [ 0.000000] Policy zone: Normal [ 0.000000] Kernel command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] Specific versions of hardware are certified with Red Hat Enterprise Linux 8. Please see the list of hardware certified with Red Hat Enterprise Linux 8 at https://catalog.redhat.com. [ 0.000000] audit: disabled (until reboot) [ 0.000000] software IO TLB: area num 4. [ 0.000000] Memory: 2829652K/4306352K available (18435K kernel code, 11221K rwdata, 7248K rodata, 2908K init, 18040K bss, 524580K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] ftrace: allocating 41240 entries in 162 pages [ 0.000000] ftrace: allocated 162 pages with 3 groups [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] rcu: RCU event tracing is enabled. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ 0.000000] rcu: RCU callback double-/use-after-free debug enabled. [ 0.000000] Rude variant of Tasks RCU enabled. [ 0.000000] Tracing variant of Tasks RCU enabled. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 0.000000] NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16 [ 0.000000] random: get_random_bytes called from start_kernel+0x622/0x9a8 with crng_init=0 [ 0.001000] Console: colour *CGA 80x25 [ 0.001000] printk: console [ttyS1] enabled [ 0.001000] ACPI: Core revision 20220331 [ 0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.001011] APIC: Switch to symmetric I/O mode setup [ 0.003198] x2apic enabled [ 0.004007] Switched APIC routing to physical x2apic. [ 0.005013] kvm-guest: setup PV IPIs [ 0.006000] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.006000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.006018] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.008006] pid_max: default: 32768 minimum: 301 [ 0.009132] LSM: Security Framework initializing [ 0.010047] Yama: becoming mindful. [ 0.011031] SELinux: Initializing. [ 0.012050] *** VALIDATE selinux *** [ 0.021007] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.026348] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.027128] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.028099] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.029097] *** VALIDATE tmpfs *** [ 0.031115] *** VALIDATE proc *** [ 0.032208] *** VALIDATE cgroup *** [ 0.033006] *** VALIDATE cgroup2 *** [ 0.034243] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.035141] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.036007] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.037026] Spectre V2 : User space: Vulnerable [ 0.038008] Speculative Store Bypass: Vulnerable [ 0.041231] debug: unmapping init [mem 0xffffffffa9459000-0xffffffffa9460fff] [ 0.043248] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.044684] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.045021] ... version: 2 [ 0.046010] ... bit width: 48 [ 0.047011] ... generic registers: 4 [ 0.048012] ... value mask: 0000ffffffffffff [ 0.049014] ... max period: 00007fffffffffff [ 0.050013] ... fixed-purpose events: 3 [ 0.051010] ... event mask: 000000070000000f [ 0.052327] rcu: Hierarchical SRCU implementation. [ 0.054363] smp: Bringing up secondary CPUs ... [ 0.055672] x86: Booting SMP configuration: [ 0.056025] .... node #0, CPUs: #1 #2 #3 [ 0.061079] smp: Brought up 1 node, 4 CPUs [ 0.063015] smpboot: Max logical packages: 1 [ 0.064009] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.112054] node 0 deferred pages initialised in 45ms [ 0.117007] devtmpfs: initialized [ 0.118604] x86/mm: Memory block size: 128MB [ 0.125022] gcov: version magic: 0x41383552 [ 0.131344] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.132202] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.133374] pinctrl core: initialized pinctrl subsystem [ 0.134173] [ 0.134828] ************************************************************* [ 0.135012] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.136014] ** ** [ 0.137013] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.138013] ** ** [ 0.139013] ** This means that this kernel is built to expose internal ** [ 0.140012] ** IOMMU data structures, which may compromise security on ** [ 0.141017] ** your system. ** [ 0.142012] ** ** [ 0.143011] ** If you see this message and you are not debugging the ** [ 0.144011] ** kernel, report this immediately to your vendor! ** [ 0.145012] ** ** [ 0.146012] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.147012] ************************************************************* [ 0.148701] NET: Registered protocol family 16 [ 0.149394] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.150106] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.155067] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.162133] cpuidle: using governor menu [ 0.164898] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.170387] PCI: Using configuration type 1 for base access [ 0.173123] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.185178] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.186019] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.188109] cryptd: max_cpu_qlen set to 1000 [ 0.192339] ACPI: Added _OSI(Module Device) [ 0.195012] ACPI: Added _OSI(Processor Device) [ 0.197013] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.199166] ACPI: Added _OSI(Processor Aggregator Device) [ 0.206257] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.215373] ACPI: Interpreter enabled [ 0.217060] ACPI: PM: (supports S0 S3 S4 S5) [ 0.219012] ACPI: Using IOAPIC for interrupt routing [ 0.222093] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.227900] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.240021] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.243036] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.246021] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.250129] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.255547] acpiphp: Slot [2] registered [ 0.258117] acpiphp: Slot [5] registered [ 0.259140] acpiphp: Slot [6] registered [ 0.261114] acpiphp: Slot [7] registered [ 0.263122] acpiphp: Slot [8] registered [ 0.265120] acpiphp: Slot [9] registered [ 0.267106] acpiphp: Slot [10] registered [ 0.269101] acpiphp: Slot [3] registered [ 0.271096] acpiphp: Slot [4] registered [ 0.272106] acpiphp: Slot [11] registered [ 0.274158] acpiphp: Slot [12] registered [ 0.276100] acpiphp: Slot [13] registered [ 0.278150] acpiphp: Slot [14] registered [ 0.280096] acpiphp: Slot [15] registered [ 0.281104] acpiphp: Slot [16] registered [ 0.283114] acpiphp: Slot [17] registered [ 0.285100] acpiphp: Slot [18] registered [ 0.287094] acpiphp: Slot [19] registered [ 0.289121] acpiphp: Slot [20] registered [ 0.290112] acpiphp: Slot [21] registered [ 0.292123] acpiphp: Slot [22] registered [ 0.293083] acpiphp: Slot [23] registered [ 0.295099] acpiphp: Slot [24] registered [ 0.297094] acpiphp: Slot [25] registered [ 0.299092] acpiphp: Slot [26] registered [ 0.300098] acpiphp: Slot [27] registered [ 0.302132] acpiphp: Slot [28] registered [ 0.304094] acpiphp: Slot [29] registered [ 0.305093] acpiphp: Slot [30] registered [ 0.307133] acpiphp: Slot [31] registered [ 0.309070] PCI host bridge to bus 0000:00 [ 0.310016] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.313017] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.315054] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.318021] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.321021] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.324024] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.326265] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.329582] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.332355] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.343864] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.348055] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.351015] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.353017] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.356016] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.361178] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.363885] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.367041] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.369888] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.375015] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.390020] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.395015] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.400624] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.409014] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.417016] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.437015] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.448000] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.455017] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.465014] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.491015] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.505000] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.517014] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.524065] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.543014] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.557170] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.564016] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.571014] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.590015] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.603113] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.615014] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.623074] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.652023] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 0.663357] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.673014] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.681015] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.704019] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 0.720331] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.724389] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.729816] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.733602] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.737243] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.743149] iommu: Default domain type: Passthrough [ 0.746530] SCSI subsystem initialized [ 0.747303] ACPI: bus type USB registered [ 0.749106] usbcore: registered new interface driver usbfs [ 0.752364] usbcore: registered new interface driver hub [ 0.755081] usbcore: registered new device driver usb [ 0.759372] pps_core: LinuxPPS API ver. 1 registered [ 0.765012] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.771055] PTP clock support registered [ 0.773074] EDAC MC: Ver: 3.0.0 [ 0.775249] PCI: Using ACPI for IRQ routing [ 0.777797] NetLabel: Initializing [ 0.780011] NetLabel: domain hash size = 128 [ 0.784013] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.787085] NetLabel: unlabeled traffic allowed by default [ 0.792087] vgaarb: loaded [ 0.794267] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.796013] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.808982] clocksource: Switched to clocksource kvm-clock [ 0.970858] VFS: Disk quotas dquot_6.6.0 [ 0.972778] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.978245] *** VALIDATE ramfs *** [ 0.982203] *** VALIDATE hugetlbfs *** [ 0.984876] pnp: PnP ACPI init [ 0.987526] pnp: PnP ACPI: found 6 devices [ 1.005785] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 1.011498] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 1.015801] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 1.018708] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 1.022295] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 1.025609] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 1.029287] NET: Registered protocol family 2 [ 1.032296] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 1.038237] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 1.042449] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 1.048596] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 1.051776] TCP: Hash tables configured (established 65536 bind 65536) [ 1.055452] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 1.058660] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 1.061898] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 1.065353] NET: Registered protocol family 1 [ 1.068219] RPC: Registered named UNIX socket transport module. [ 1.070692] RPC: Registered udp transport module. [ 1.075158] RPC: Registered tcp transport module. [ 1.077471] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 1.080515] NET: Registered protocol family 44 [ 1.082411] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 1.085262] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 1.087558] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 1.090136] PCI: CLS 0 bytes, default 64 [ 1.091896] Unpacking initramfs... [ 2.634530] debug: unmapping init [mem 0xffff8f887cc54000-0xffff8f887ffbffff] [ 2.640348] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.643230] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.646750] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 3.196923] Initialise system trusted keyrings [ 3.198752] Key type blacklist registered [ 3.200962] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 3.210135] zbud: loaded [ 3.213385] *** VALIDATE nfs *** [ 3.214760] *** VALIDATE nfs4 *** [ 3.216463] pstore: using deflate compression [ 3.221326] Platform Keyring initialized [ 3.364810] NET: Registered protocol family 38 [ 3.367122] Key type asymmetric registered [ 3.369279] Asymmetric key parser 'x509' registered [ 3.371398] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 3.375672] io scheduler mq-deadline registered [ 3.377260] io scheduler kyber registered [ 3.379631] io scheduler bfq registered [ 3.384127] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 3.389906] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 3.395435] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 3.400374] ACPI: Power Button [PWRF] [ 3.408482] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 3.418486] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 3.449849] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 3.465740] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 3.516082] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 3.552110] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.582261] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.590701] Non-volatile memory driver v1.3 [ 3.593387] Linux agpgart interface v0.103 [ 3.636527] virtio_blk virtio1: [vda] 146144 512-byte logical blocks (74.8 MB/71.4 MiB) [ 3.640063] vda: detected capacity change from 0 to 74825728 [ 3.662264] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.666568] vdb: detected capacity change from 0 to 1073741824 [ 3.688265] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.693073] vdc: detected capacity change from 0 to 2621440000 [ 3.715435] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.719461] vdd: detected capacity change from 0 to 2621440000 [ 3.740152] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.744439] vde: detected capacity change from 0 to 4294967296 [ 3.767215] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.771809] vdf: detected capacity change from 0 to 4294967296 [ 3.781357] libphy: Fixed MDIO Bus: probed [ 3.788441] usbcore: registered new interface driver usbserial_generic [ 3.792226] usbserial: USB Serial support registered for generic [ 3.795453] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.802699] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.805948] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.809629] mousedev: PS/2 mouse device common for all mice [ 3.814405] rtc_cmos 00:05: RTC can wake from S4 [ 3.818721] rtc_cmos 00:05: registered as rtc0 [ 3.821374] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.826575] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.831117] intel_pstate: CPU model not supported [ 3.841055] hid: raw HID events driver (C) Jiri Kosina [ 3.843887] usbcore: registered new interface driver usbhid [ 3.847064] usbhid: USB HID core driver [ 3.849142] drop_monitor: Initializing network drop monitor service [ 3.853314] Initializing XFRM netlink socket [ 3.855489] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.857355] NET: Registered protocol family 10 [ 3.860407] Segment Routing with IPv6 [ 3.867544] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.871673] NET: Registered protocol family 17 [ 3.872207] mpls_gso: MPLS GSO support [ 3.895311] RAS: Correctable Errors collector initialized. [ 3.898597] AVX version of gcm_enc/dec engaged. [ 3.901088] AES CTR mode by8 optimization enabled [ 3.997895] sched_clock: Marking stable (3997820471, 0)->(4943591822, -945771351) [ 4.001796] registered taskstats version 1 [ 4.008583] Loading compiled-in X.509 certificates [ 4.010748] zswap: loaded using pool lzo/zbud [ 4.038310] Key type big_key registered [ 4.050735] Key type encrypted registered [ 4.052729] ima: No TPM chip found, activating TPM-bypass! [ 4.055183] ima: Allocated hash algorithm: sha1 [ 4.057126] ima: No architecture policies found [ 4.058774] evm: Initialising EVM extended attributes: [ 4.060690] evm: security.selinux [ 4.065341] evm: security.ima [ 4.066567] evm: security.capability [ 4.067866] evm: HMAC attrs: 0x1 [ 4.070710] rtc_cmos 00:05: setting system clock to 2026-08-22 23:05:14 UTC (1787439914) [ 4.077822] debug: unmapping init [mem 0xffffffffaa403000-0xffffffffaa5fffff] [ 4.081246] debug: unmapping init [mem 0xffffffffa9182000-0xffffffffa9458fff] [ 4.091134] Write protecting the kernel read-only data: 28672k [ 4.096169] debug: unmapping init [mem 0xffffffffa7803000-0xffffffffa79fffff] [ 4.099103] debug: unmapping init [mem 0xffffffffa8114000-0xffffffffa81fffff] [ 4.137283] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 4.147161] systemd[1]: Detected virtualization kvm. [ 4.148885] systemd[1]: Detected architecture x86-64. [ 4.151098] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 4.178213] systemd[1]: No hostname configured. [ 4.180387] systemd[1]: Set hostname to . [ 4.182439] random: systemd: uninitialized urandom read (16 bytes read) [ 4.187181] systemd[1]: Initializing machine ID from random generator. [ 4.284776] random: ln: uninitialized urandom read (6 bytes read) [ 4.424127] random: systemd: uninitialized urandom read (16 bytes read) [ 4.428346] systemd[1]: Listening on Journal Socket (/dev/log). [ OK ] Listening on Journal Socket (/dev/log). [ 4.437174] systemd[1]: Started Dispatch Password Requests to Console Directory Watch. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ 4.447053] systemd[1]: Listening on Journal Socket. [ OK ] Listening on Journal Socket. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Started Memstrack Anylazing Service. Starting Journal Service... [ OK ] Reached target Swap. [ OK ] Listening on udev Control Socket. [ OK ] Reached target Slices. [ OK ] Reached target Initrd Root Device. [ OK ] Reached target Local File Systems. Starting Create Volatile Files and Directories... [ OK ] Reached target Paths. Starting Setup Virtual Console... [ OK ] Reached target Timers. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Listening on udev Kernel Socket. [ OK ] Reached target Sockets. Starting Apply Kernel Variables... [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Setup Virtual Console. [ OK ] Started Apply Kernel Variables. Starting dracut cmdline hook... Starting Create Static Device Nodes in /dev... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started Journal Service. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 5.541243] device-mapper: uevent: version 1.0.3 [ 5.543965] 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. [ 6.829882] virtio_net virtio0 ens2: renamed from eth0 [ 6.981719] random: fast init done [ 7.136184] scsi host0: ata_piix [ 7.143371] scsi host1: ata_piix [ 7.150574] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 7.158314] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 11.579855] random: crng init done [ 11.586375] random: 7 urandom warning(s) missed due to ratelimiting [ 13.538285] dracut-initqueue[589]: RTNETLINK answers: File exists Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Mounting /sysroot... [ 14.755071] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Timers. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Slices. [ OK ] Stopped target Paths. [ OK ] Stopped target Sockets. [ OK ] Stopped target System Initialization. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. [ OK ] Stopped target Local File Systems. [ OK ] Stopped Apply Kernel Variables. Stopping udev Kernel Device Manager... [ OK ] Stopped target Swap. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ 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 Control Socket. [ OK ] Closed udev Kernel Socket. Starting Cleanup udevd DB... [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 16.746587] printk: systemd: 26 output lines suppressed due to ratelimiting [ 17.382240] SELinux: Disabled at runtime. [ 17.477542] 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) [ 17.491375] systemd[1]: Detected virtualization kvm. [ 17.493430] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 18.681601] systemd[1]: initrd-switch-root.service: Succeeded. [ 18.686354] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 18.699804] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 18.705385] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 18.711462] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 18.720440] systemd[1]: Starting Journal Service... Starting Journal Service... [ 18.732925] systemd[1]: Mounting POSIX Message Queue File System... Mounting POSIX Message Queue File System... [ OK ] Created slice system-sshd\x2dkeygen.slice. Mounting Kernel Debug File System... Starting Create list of required st…ce nodes for the current kernel... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Listening on udev Control Socket. [ OK ] Created slice system-getty.slice. [ OK ] Listening on Process Core Dump Socket. Starting Apply Kernel Variables... [ OK ] Listening on initctl Compatibility Named Pipe. [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. [ OK ] Reached target rpc_pipefs.target. [ OK ] Created slice User and Session Slice. Starting Remount Root and Kernel File Systems... [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd Root File System. [ OK ] Stopped target Initrd File Systems. [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Reached target Slices. Mounting Huge Pages File System... [ OK ] Listening on RPCbind Server Activation Socket. Activating swap /dev/disk/by-label/SWAP... [ OK ] Listening on udev Kernel Socket. Starting udev Coldplug all Devices... [ OK ] Reached target RPC Port Mapper. [ 19.265892] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS [ OK ] Started Journal Service. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Mounted Kernel Debug File System. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Apply Kernel Variables. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Mounted Huge Pages File System. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Reached target Swap. Starting Configure read-only root support... Starting Create Static Device Nodes in /dev... Starting Flush Journal to Persistent Storage... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started udev Coldplug all Devices. Starting udev Kernel Device Manager... [ OK ] Reached target Local File Systems (Pre). Mounting /home/green/git/lustre-release... Mounting /mnt... [ OK ] Mounted /mnt. [ 20.193602] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 21.470982] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 21.593098] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 22.304269] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 22.581383] EDAC sbridge: Ver: 1.1.2 [* ] A start job is running for Configur…-only root support (7s / no limit)[ 26.339566] Key type dns_resolver registered [** ] A start job is running for Configur…-only root support (7s / no limit)[ 26.707374] NFS: Registering the id_resolver key type [ 26.710252] Key type id_resolver registered [ 26.712702] Key type id_legacy registered [*** ] A start job is running for Configur…-only root support (8s / no limit) [ OK ] Started Configure read-only root support. [ OK ] Reached target Local File Systems. Starting Rebuild Dynamic Linker Cache... Starting Mark the need to relabel after reboot... Starting Load/Save Random Seed... Starting Create Volatile Files and Directories... [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Load/Save Random Seed. [ OK ] Started Create Volatile Files and Directories. Starting Update UTMP about System Boot/Shutdown... Starting RPC Bind... [ 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 ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Started irqbalance daemon. Starting Restore /run/initramfs on shutdown... [ OK ] Reached target sshd-keygen.target. [ OK ] Started dnf makecache --timer. [ OK ] Reached target Timers. Starting Login Service... [ OK ] Started D-Bus System Message Bus. Starting Network Manager... [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Network Manager. Starting Network Manager Wait Online... [ OK ] Reached target Network. Starting OpenSSH server daemon... Starting GSSAPI Proxy Daemon... Starting Dynamic System Tuning Daemon... [ OK ] Started OpenSSH server daemon. [ OK ] Started Login Service. [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... Starting Hostname Service... [ OK ] Started Permit User Sessions. [ OK ] Started Serial Getty on ttyS1. [ OK ] Started Getty on tty1. [ OK ] Started Serial Getty on ttyS0. [ OK ] Reached target Login Prompts. [ OK ] Started Command Scheduler. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting Crash recovery kernel arming... Starting Notify NFS peers of a restart... Starting System Logging Service... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg655-server login: [ 41.456010] hrtimer: interrupt took 1994430 ns [ 103.690709] libcfs: loading out-of-tree module taints kernel. [ 103.819826] Key type ._llcrypt registered [ 103.821435] Key type .llcrypt registered [ 104.007264] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_hostid [ 125.980470] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing load_modules_local [ 128.004257] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 128.049348] alg: No test for adler32 (adler32-zlib) [ 129.617791] Lustre: Lustre: Build Version: 2.17.57_64_ga728441 [ 131.008687] LNet: Added LNI 192.168.206.155@tcp [8/256/0/180] [ 132.746934] Key type lgssc registered [ 135.634322] Lustre: Echo OBD driver; http://www.lustre.org/ [ 159.208560] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 197.362888] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing load_modules_local [ 210.421151] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 210.453134] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 211.788826] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 211.831146] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 211.950750] Lustre: lustre-MDT0000: new disk, initializing [ 212.060219] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 212.085356] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 216.466458] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 229.635241] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 229.728930] Lustre: 6515: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 [ 229.771867] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 229.775338] Lustre: Skipped 1 previous similar message [ 229.896309] Lustre: lustre-MDT0001: new disk, initializing [ 229.952506] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 229.970962] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 229.984751] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 234.340960] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 238.913611] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 248.337471] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 248.605562] Lustre: lustre-OST0000: new disk, initializing [ 248.610938] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 248.626092] Lustre: 8453:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 248.702600] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 255.231437] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 256.062591] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 256.075719] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 256.182105] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 269.899257] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 270.115281] Lustre: lustre-OST0001: new disk, initializing [ 270.121953] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 270.132769] Lustre: 9526:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 270.213706] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 276.019057] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 280.098737] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 280.112042] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 280.194396] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 288.198405] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 297.574786] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 302.846597] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing check_logdir /tmp/testlogs/ [ 308.690100] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing yml_node [ 313.311581] Lustre: DEBUG MARKER: Client: 2.17.57.64 [ 315.601887] Lustre: DEBUG MARKER: MDS: 2.17.57.64 [ 318.971489] Lustre: DEBUG MARKER: OSS: 2.17.57.64 [ 320.911941] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity-lfsck ============----- Sat Aug 22 19:10:29 EDT 2026 [ 340.031874] Lustre: DEBUG MARKER: excepting tests: 18b 23b [ 349.420753] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing load_modules_local [ 357.857442] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 357.869933] 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 [ 357.890576] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 361.953549] 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 [ 361.959958] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 361.969751] Lustre: Skipped 2 previous similar messages [ 363.822108] Lustre: server umount lustre-MDT0000 complete [ 372.194840] LustreError: 10102: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. [ 372.201338] LustreError: 10102:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 7 previous similar messages [ 377.313987] LustreError: 6524: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. [ 377.333944] LustreError: 6524:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 4 previous similar messages [ 378.087264] LustreError: 6509:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787440288 with bad export cookie 13225660323585647406 [ 378.089784] LustreError: MGC192.168.206.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 378.095727] LustreError: 6509:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 378.453159] Lustre: server umount lustre-MDT0001 complete [ 397.791156] Lustre: 3650:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787440292/real 1787440292] req@ffff8f87c405df80 x1874266728537472/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787440308 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 397.825787] 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 [ 397.839087] Lustre: Skipped 2 previous similar messages [ 399.065862] Lustre: server umount lustre-OST0000 complete [ 399.328728] Lustre: 3649:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787440293/real 1787440293] req@ffff8f88e7ca5180 x1874266728537728/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787440309 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 402.976175] Lustre: 3650:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787440297/real 1787440297] req@ffff8f88c1219180 x1874266728537984/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787440313 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 406.237515] Lustre: server umount lustre-OST0001 complete [ 422.159834] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing unload_modules_local [ 425.343650] Key type lgssc unregistered [ 425.730610] LNet: 14801:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 425.740237] LNetError: 14801:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 425.752233] LNet: Removed LNI 192.168.206.155@tcp [ 426.900189] Key type .llcrypt unregistered [ 426.903588] Key type ._llcrypt unregistered [ 450.512697] Key type ._llcrypt registered [ 450.515819] Key type .llcrypt registered [ 450.629992] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_hostid [ 466.450830] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing load_modules_local [ 467.268916] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 467.323201] alg: No test for adler32 (adler32-zlib) [ 468.407697] Lustre: Lustre: Build Version: 2.17.57_64_ga728441 [ 468.654788] LNet: Added LNI 192.168.206.155@tcp [8/256/0/180] [ 470.375170] Key type lgssc registered [ 471.389704] Lustre: Echo OBD driver; http://www.lustre.org/ [ 521.533861] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing load_modules_local [ 533.434175] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 533.444807] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 534.670761] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 534.728965] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 534.889772] Lustre: lustre-MDT0000: new disk, initializing [ 535.019262] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 535.039291] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 539.605786] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 552.571510] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 552.677751] Lustre: 19270: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 [ 552.708401] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 552.712225] Lustre: Skipped 1 previous similar message [ 552.792538] Lustre: lustre-MDT0001: new disk, initializing [ 552.873405] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 552.925268] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 552.935685] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 557.412149] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 562.733569] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 573.124029] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 573.389783] Lustre: lustre-OST0000: new disk, initializing [ 573.397608] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 573.403611] Lustre: 21209:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 573.474373] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 577.391344] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 577.406089] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 577.505169] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 580.130687] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 592.389977] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 592.518673] Lustre: lustre-OST0001: new disk, initializing [ 592.521914] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 592.526284] Lustre: 22231:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 592.605149] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 599.207671] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 600.639516] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 600.662408] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 600.774837] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 609.727884] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 615.832852] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 623.957958] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 19:15:32 (1787440532) === [ 626.685543] Lustre: DEBUG MARKER: == sanity-lfsck test 0: Control LFSCK manually =========== 19:15:35 (1787440535) [ 627.206849] Lustre: 23224:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 251 < left 278, rollback = 2 [ 627.217618] Lustre: 23224:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 627.230189] Lustre: 23224:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 627.236646] Lustre: 23224:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 627.247701] Lustre: 23224:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 627.254650] Lustre: 23224:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 627.725627] Lustre: 19276:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 627.736136] Lustre: 19276:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 14 previous similar messages [ 627.741095] Lustre: 19276:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 627.745835] Lustre: 19276:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 14 previous similar messages [ 627.750194] Lustre: 19276:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 627.754440] Lustre: 19276:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 14 previous similar messages [ 627.758570] Lustre: 19276:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 627.763735] Lustre: 19276:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 14 previous similar messages [ 627.769439] Lustre: 19276:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 627.773937] Lustre: 19276:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 14 previous similar messages [ 627.778236] Lustre: 19276:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 627.782433] Lustre: 19276:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 14 previous similar messages [ 628.763315] Lustre: 19278:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 628.777349] Lustre: 19278:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 68 previous similar messages [ 628.794501] Lustre: 19278:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 628.811576] Lustre: 19278:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 68 previous similar messages [ 628.835634] Lustre: 19278:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 628.854557] Lustre: 19278:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 68 previous similar messages [ 628.859964] Lustre: 19278:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 628.872878] Lustre: 19278:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 68 previous similar messages [ 628.880534] Lustre: 19278:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 628.886150] Lustre: 19278:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 68 previous similar messages [ 628.890722] Lustre: 19278:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 628.897173] Lustre: 19278:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 68 previous similar messages [ 630.789893] Lustre: 22857:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 630.802490] Lustre: 22857:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 101 previous similar messages [ 630.811357] Lustre: 22857:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 630.819881] Lustre: 22857:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 101 previous similar messages [ 630.930791] Lustre: 22857:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 630.945788] Lustre: 22857:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 630.959593] Lustre: 22857:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 630.973058] Lustre: 22857:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 630.988538] Lustre: 22857:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 630.996859] Lustre: 22857:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 631.008423] Lustre: 22857:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 631.017395] Lustre: 22857:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 634.114434] Lustre: *** cfs_fail_loc=1600, val=3*** [ 637.151459] Lustre: *** cfs_fail_loc=1600, val=3*** [ 638.267678] Lustre: 21200:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-OST0001: opcode 2: before 260 < left 274, rollback = 2 [ 638.282727] Lustre: 21200:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 99 previous similar messages [ 638.292929] Lustre: 21200:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 638.312152] Lustre: 21200:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 99 previous similar messages [ 638.332255] Lustre: 21200:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 2/274/0 [ 638.340849] Lustre: 21200:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 96 previous similar messages [ 638.358463] Lustre: 21200:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 0/0/0, punch: 0/0/0, quota 7/225/0 [ 638.376909] Lustre: 21200:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 96 previous similar messages [ 638.385970] Lustre: 21200:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 638.412585] Lustre: 21200:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 96 previous similar messages [ 638.428451] Lustre: 21200:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 638.437834] Lustre: 21200:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 96 previous similar messages [ 640.132814] Lustre: *** cfs_fail_loc=1600, val=3*** [ 653.107995] Lustre: server umount lustre-MDT0000 complete [ 655.332206] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 655.345324] 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 [ 656.870843] 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 [ 656.882253] Lustre: Skipped 1 previous similar message [ 657.070206] LustreError: 19261:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787440567 with bad export cookie 7898105016043773435 [ 657.072460] LustreError: MGC192.168.206.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 657.080377] LustreError: 19261:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 657.443760] Lustre: server umount lustre-MDT0001 complete [ 671.293227] Lustre: server umount lustre-OST0000 complete [ 685.241966] Lustre: server umount lustre-OST0001 complete [ 693.633479] Lustre: DEBUG MARKER: == sanity-lfsck test 1a: LFSCK can find out and repair crashed FID-in-dirent ========================================================== 19:16:42 (1787440602) [ 709.668652] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing load_modules_local [ 720.545942] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 720.991105] LustreError: 26240: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. [ 721.030852] LustreError: 26240:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 6 previous similar messages [ 721.111821] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 726.324511] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 726.497188] LustreError: 26241: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. [ 726.512535] LustreError: 26241:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 1 previous similar message [ 730.593966] LustreError: 26240: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. [ 735.712657] LustreError: 26241: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. [ 737.647974] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 737.931605] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 743.281601] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 746.015842] Lustre: 27381:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 753.390068] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 760.764698] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 762.958695] LustreError: 27736: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. [ 766.065845] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:40 to 0x280000401:65) [ 770.644363] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 770.831345] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 770.836763] Lustre: Skipped 1 previous similar message [ 776.173189] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:41 to 0x2c0000401:65) [ 777.046643] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 784.444843] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 787.779624] Lustre: 29250:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 789.142280] Lustre: 26237:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 789.150314] Lustre: 26237:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 60 previous similar messages [ 789.161865] Lustre: 26237:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 789.169981] Lustre: 26237:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 60 previous similar messages [ 789.176676] Lustre: 26237:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 789.187501] Lustre: 26237:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 60 previous similar messages [ 789.192641] Lustre: 26237:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 789.197664] Lustre: 26237:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 60 previous similar messages [ 789.206575] Lustre: 26237:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 789.215131] Lustre: 26237:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 60 previous similar messages [ 789.223400] Lustre: 26237:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 789.230760] Lustre: 26237:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 60 previous similar messages [ 794.372036] Lustre: *** cfs_fail_loc=1501, val=0*** [ 802.261177] Lustre: Failing over lustre-MDT0000 [ 802.583415] Lustre: server umount lustre-MDT0000 complete [ 804.319502] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 804.331040] 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 [ 804.347614] Lustre: Skipped 1 previous similar message [ 804.367458] LustreError: 26241: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. [ 804.386488] LustreError: 26241:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 2 previous similar messages [ 806.884166] 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 [ 806.906190] Lustre: Skipped 2 previous similar messages [ 813.425630] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 813.539539] LustreError: MGC192.168.206.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 813.878226] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 813.926430] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 818.357164] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 819.172572] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 819.183513] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 819.220680] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 819.265357] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:105 to 0x2c0000401:129) [ 819.266191] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:105 to 0x280000401:129) [ 822.332444] Lustre: *** cfs_fail_loc=1505, val=0*** [ 831.530820] Lustre: DEBUG MARKER: == sanity-lfsck test 1b: LFSCK can find out and repair the missing FID-in-LMA ========================================================== 19:19:00 (1787440740) [ 832.559332] Lustre: 26237:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 832.566081] Lustre: 26237:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 322 previous similar messages [ 832.571549] Lustre: 26237:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 832.578654] Lustre: 26237:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 832.583560] Lustre: 26237:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 832.588169] Lustre: 26237:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 832.593029] Lustre: 26237:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 832.598540] Lustre: 26237:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 832.602551] Lustre: 26237:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 832.607470] Lustre: 26237:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 832.612493] Lustre: 26237:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 832.616927] Lustre: 26237:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 837.611548] Lustre: *** cfs_fail_loc=1502, val=0*** [ 846.489611] Lustre: Failing over lustre-MDT0000 [ 846.846608] Lustre: server umount lustre-MDT0000 complete [ 849.891928] 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 [ 849.895648] LustreError: 26240: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. [ 849.910234] Lustre: Skipped 2 previous similar messages [ 849.930644] LustreError: 26240:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 11 previous similar messages [ 856.212857] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 856.295666] LustreError: MGC192.168.206.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 856.533587] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 860.303572] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 861.666882] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 861.671661] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 861.679311] Lustre: Skipped 3 previous similar messages [ 861.689464] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 861.719886] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:169 to 0x2c0000401:193) [ 861.721153] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:169 to 0x280000401:193) [ 863.288479] Lustre: *** cfs_fail_loc=1505, val=0*** [ 870.685706] Lustre: DEBUG MARKER: == sanity-lfsck test 1c: LFSCK can find out and repair lost FID-in-dirent ========================================================== 19:19:39 (1787440779) [ 871.892675] Lustre: 26236:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 256 < left 278, rollback = 2 [ 871.919748] Lustre: 26236:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 321 previous similar messages [ 871.935355] Lustre: 26236:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 871.942838] Lustre: 26236:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 871.951809] Lustre: 26236:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 871.963748] Lustre: 26236:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 871.970900] Lustre: 26236:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 871.977860] Lustre: 26236:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 871.988073] Lustre: 26236:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 871.992721] Lustre: 26236:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 872.000047] Lustre: 26236:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 872.007567] Lustre: 26236:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 877.413183] Lustre: *** cfs_fail_loc=1504, val=0*** [ 877.418496] Lustre: *** cfs_fail_loc=1504, val=0*** [ 877.427050] Lustre: Skipped 1 previous similar message [ 884.387984] Lustre: Failing over lustre-MDT0000 [ 884.748654] Lustre: server umount lustre-MDT0000 complete [ 887.265418] 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 [ 887.276614] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 887.278550] Lustre: Skipped 1 previous similar message [ 887.285592] LustreError: 26973: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. [ 887.315038] LustreError: 26973:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 7 previous similar messages [ 894.674396] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 894.777733] LustreError: MGC192.168.206.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 895.145759] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 895.150485] Lustre: Skipped 1 previous similar message [ 895.187551] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 899.256045] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 900.579224] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 900.580498] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 900.597959] Lustre: Skipped 3 previous similar messages [ 900.631670] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 900.690394] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:233 to 0x280000401:257) [ 900.693105] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:233 to 0x2c0000401:257) [ 902.646795] Lustre: *** cfs_fail_loc=1505, val=0*** [ 910.072621] Lustre: DEBUG MARKER: == sanity-lfsck test 2a: LFSCK can find out and repair crashed linkEA entry ========================================================== 19:20:18 (1787440818) [ 915.588085] Lustre: *** cfs_fail_loc=1603, val=0*** [ 922.830867] Lustre: Failing over lustre-MDT0000 [ 923.031155] Lustre: server umount lustre-MDT0000 complete [ 926.175630] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 926.179859] 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 [ 926.214792] Lustre: Skipped 5 previous similar messages [ 932.954780] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 933.081466] LustreError: MGC192.168.206.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 933.279338] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 937.539780] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 938.464677] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 938.481750] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 938.491684] Lustre: Skipped 3 previous similar messages [ 938.542633] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 938.595248] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:297 to 0x280000401:321) [ 938.595635] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:297 to 0x2c0000401:321) [ 945.946422] Lustre: DEBUG MARKER: == sanity-lfsck test 2b: LFSCK can find out and remove invalid linkEA entry ========================================================== 19:20:55 (1787440855) [ 947.131261] Lustre: 29016:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 947.147631] Lustre: 29016:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 644 previous similar messages [ 947.177259] Lustre: 29016:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 947.187929] Lustre: 29016:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 947.199438] Lustre: 29016:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 947.207261] Lustre: 29016:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 947.225203] Lustre: 29016:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 947.246387] Lustre: 29016:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 947.265146] Lustre: 29016:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 947.285506] Lustre: 29016:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 947.298990] Lustre: 29016:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 947.309276] Lustre: 29016:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 952.418831] Lustre: *** cfs_fail_loc=1604, val=0*** [ 960.212904] Lustre: Failing over lustre-MDT0000 [ 960.589240] Lustre: server umount lustre-MDT0000 complete [ 964.065061] 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 [ 964.066295] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 964.066613] LustreError: 26237: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. [ 964.066621] LustreError: 26237:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 12 previous similar messages [ 964.076727] Lustre: Skipped 4 previous similar messages [ 970.524337] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 970.642442] LustreError: MGC192.168.206.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 970.955353] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 974.774302] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 976.358083] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 976.378634] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 976.391651] Lustre: Skipped 3 previous similar messages [ 976.437890] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 976.518256] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:361 to 0x280000401:385) [ 976.527250] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:361 to 0x2c0000401:385) [ 985.976996] Lustre: DEBUG MARKER: == sanity-lfsck test 2c: LFSCK can find out and remove repeated linkEA entry ========================================================== 19:21:34 (1787440894) [ 992.222921] Lustre: *** cfs_fail_loc=1605, val=0*** [ 1001.574085] Lustre: Failing over lustre-MDT0000 [ 1001.837352] Lustre: server umount lustre-MDT0000 complete [ 1001.959392] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1012.825987] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1012.951495] LustreError: MGC192.168.206.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1013.252063] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1017.290410] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1018.339594] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1018.366487] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1018.379518] Lustre: Skipped 3 previous similar messages [ 1018.396551] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1018.501817] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:425 to 0x280000401:449) [ 1018.504970] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:425 to 0x2c0000401:449) [ 1025.782427] Lustre: DEBUG MARKER: == sanity-lfsck test 2d: LFSCK can recover the missing linkEA entry ========================================================== 19:22:14 (1787440934) [ 1031.990426] Lustre: *** cfs_fail_loc=161d, val=0*** [ 1039.440440] Lustre: Failing over lustre-MDT0000 [ 1039.727984] Lustre: server umount lustre-MDT0000 complete [ 1043.938738] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1043.939667] 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 [ 1043.971758] Lustre: Skipped 6 previous similar messages [ 1050.091303] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1050.193345] LustreError: MGC192.168.206.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1050.457744] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1050.468931] Lustre: Skipped 3 previous similar messages [ 1050.508270] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1054.609291] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1055.719896] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1055.725804] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1055.745536] Lustre: Skipped 3 previous similar messages [ 1055.768703] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1055.805343] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:489 to 0x2c0000401:513) [ 1055.804931] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:489 to 0x280000401:513) [ 1063.626609] Lustre: DEBUG MARKER: == sanity-lfsck test 2e: namespace LFSCK can verify remote object linkEA ========================================================== 19:22:52 (1787440972) [ 1065.707027] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1075.747530] Lustre: DEBUG MARKER: == sanity-lfsck test 3: LFSCK can verify multiple-linked objects ========================================================== 19:23:04 (1787440984) [ 1076.128882] Lustre: 26235:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 1076.136546] Lustre: 26235:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 975 previous similar messages [ 1076.141217] Lustre: 26235:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 1076.147525] Lustre: 26235:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 975 previous similar messages [ 1076.153431] Lustre: 26235:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 1076.164833] Lustre: 26235:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 976 previous similar messages [ 1076.173600] Lustre: 26235:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 1076.181466] Lustre: 26235:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 975 previous similar messages [ 1076.187227] Lustre: 26235:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 1076.196152] Lustre: 26235:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 976 previous similar messages [ 1076.203899] Lustre: 26235:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 1076.210648] Lustre: 26235:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 976 previous similar messages [ 1081.196563] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1082.063779] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1092.259720] Lustre: DEBUG MARKER: == sanity-lfsck test 4: FID-in-dirent can be rebuilt after MDT file-level backup/restore ========================================================== 19:23:20 (1787441000) [ 1126.896190] Lustre: Failing over lustre-MDT0000 [ 1127.257100] Lustre: server umount lustre-MDT0000 complete [ 1127.393693] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1127.397519] LustreError: 26236: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. [ 1127.411216] LustreError: 26236:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 30 previous similar messages [ 1132.686880] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1142.011423] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1142.751218] Lustre: 16432:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787441037/real 1787441037] req@ffff8f88f2d50e00 x1874267083589632/t0(0) o400->MGC192.168.206.155@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1787441053 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1142.796831] LustreError: MGC192.168.206.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1152.498694] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1152.524724] Lustre: lustre-MDT0000: reset Object Index mappings [ 1153.276674] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1157.105959] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1158.625244] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1158.629725] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 1158.652738] Lustre: Skipped 3 previous similar messages [ 1158.675169] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1158.708291] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:592 to 0x280000401:609) [ 1158.708615] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:592 to 0x2c0000401:609) [ 1159.936030] LustreError: 42889:0:(lfsck_engine.c:1018:lfsck_master_engine()) lustre-MDT0000-osd: master engine fail to verify the .lustre/lost+found/, go ahead: rc = -115 [ 1159.955417] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1164.077368] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1164.088283] Lustre: Skipped 3 previous similar messages [ 1170.813539] Lustre: Failing over lustre-MDT0000 [ 1171.058791] Lustre: server umount lustre-MDT0000 complete [ 1173.984170] 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 [ 1174.007848] Lustre: Skipped 5 previous similar messages [ 1180.290163] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1184.465779] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1185.838340] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:592 to 0x2c0000401:641) [ 1185.841426] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:592 to 0x280000401:641) [ 1187.177594] Lustre: *** cfs_fail_loc=1505, val=0*** [ 1194.024516] Lustre: DEBUG MARKER: == sanity-lfsck test 5: LFSCK can handle IGIF object upgrading ========================================================== 19:25:03 (1787441103) [ 1196.690490] Lustre: *** cfs_fail_loc=1504, val=0*** [ 1205.811132] Lustre: Failing over lustre-MDT0000 [ 1206.051278] Lustre: server umount lustre-MDT0000 complete [ 1210.741457] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1219.766716] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1222.627673] Lustre: 16432:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787441116/real 1787441116] req@ffff8f88fe03bb80 x1874267083679488/t0(0) o400->MGC192.168.206.155@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1787441132 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1230.347118] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1230.371835] Lustre: lustre-MDT0000: reset Object Index mappings [ 1232.869548] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x6d9bb4aa8807798a [ 1232.883828] Lustre: MGC192.168.206.155@tcp: Connection restored to 0@lo (at 0@lo) [ 1232.886492] Lustre: Skipped 7 previous similar messages [ 1233.190965] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1233.213298] Lustre: Skipped 1 previous similar message [ 1237.085289] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1238.497364] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1238.516689] Lustre: Skipped 1 previous similar message [ 1238.539254] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1238.550235] Lustre: Skipped 1 previous similar message [ 1238.576186] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:681 to 0x280000401:705) [ 1238.576606] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:681 to 0x2c0000401:705) [ 1240.446250] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1240.459721] Lustre: Skipped 1 previous similar message [ 1253.040995] Lustre: Failing over lustre-MDT0000 [ 1253.316613] Lustre: server umount lustre-MDT0000 complete [ 1253.856150] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1253.863479] LustreError: Skipped 1 previous similar message [ 1261.999187] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1266.148385] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1267.735627] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:681 to 0x280000401:737) [ 1267.748221] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:681 to 0x2c0000401:737) [ 1269.127039] Lustre: *** cfs_fail_loc=1505, val=0*** [ 1269.131458] Lustre: Skipped 84 previous similar messages [ 1275.682362] Lustre: DEBUG MARKER: == sanity-lfsck test 6a: LFSCK resumes from last checkpoint (1) ========================================================== 19:26:24 (1787441184) [ 1283.288155] Lustre: *** cfs_fail_loc=1600, val=1*** [ 1283.296481] Lustre: Skipped 8 previous similar messages [ 1301.577869] Lustre: DEBUG MARKER: == sanity-lfsck test 6b: LFSCK resumes from last checkpoint (2) ========================================================== 19:26:50 (1787441210) [ 1315.362895] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1315.365026] Lustre: Skipped 14 previous similar messages [ 1331.310523] Lustre: DEBUG MARKER: == sanity-lfsck test 7a: non-stopped LFSCK should auto restarts after MDS remount (1) ========================================================== 19:27:20 (1787441240) [ 1332.919814] Lustre: 26235:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 1332.933026] Lustre: 26235:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 1647 previous similar messages [ 1332.939966] Lustre: 26235:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 1332.947225] Lustre: 26235:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1647 previous similar messages [ 1332.957593] Lustre: 26235:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 1332.966753] Lustre: 26235:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1647 previous similar messages [ 1332.972829] Lustre: 26235:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 1332.979850] Lustre: 26235:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1647 previous similar messages [ 1332.984420] Lustre: 26235:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 1332.988641] Lustre: 26235:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1647 previous similar messages [ 1332.996093] Lustre: 26235:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 1333.002529] Lustre: 26235:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1647 previous similar messages [ 1347.007933] Lustre: Failing over lustre-MDT0000 [ 1347.303782] Lustre: server umount lustre-MDT0000 complete [ 1357.569117] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1357.747505] LustreError: MGC192.168.206.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1357.755886] LustreError: Skipped 3 previous similar messages [ 1357.936395] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1357.944883] Lustre: Skipped 4 previous similar messages [ 1362.364103] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1363.425924] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1363.444340] Lustre: Skipped 8 previous similar messages [ 1363.537410] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:854 to 0x280000401:897) [ 1363.542190] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:853 to 0x2c0000401:897) [ 1371.472871] Lustre: DEBUG MARKER: == sanity-lfsck test 7b: non-stopped LFSCK should auto restarts after MDS remount (2) ========================================================== 19:28:00 (1787441280) [ 1384.153568] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing load_modules_local [ 1400.789426] Lustre: 52949:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 1421.822985] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1425.292938] Lustre: 54085:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 1431.050020] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1431.058797] Lustre: Skipped 81 previous similar messages [ 1433.978784] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1435.039163] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1436.071352] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1438.113150] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1438.115189] Lustre: Skipped 1 previous similar message [ 1438.598618] Lustre: Failing over lustre-MDT0000 [ 1438.984781] Lustre: server umount lustre-MDT0000 complete [ 1440.225192] 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 [ 1440.225315] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1440.225754] LustreError: 26241: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. [ 1440.225761] LustreError: 26241:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 72 previous similar messages [ 1440.243701] Lustre: Skipped 17 previous similar messages [ 1447.816433] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1448.227692] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1448.242956] Lustre: Skipped 2 previous similar messages [ 1452.395502] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1453.538466] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1453.547576] Lustre: Skipped 2 previous similar messages [ 1453.570307] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1453.578713] Lustre: Skipped 2 previous similar messages [ 1453.638943] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:947 to 0x2c0000401:993) [ 1453.641400] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:946 to 0x280000401:961) [ 1463.400633] Lustre: DEBUG MARKER: == sanity-lfsck test 8: LFSCK state machine ============== 19:29:31 (1787441371) [ 1468.898199] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1468.914653] Lustre: Skipped 3 previous similar messages [ 1474.017440] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1479.135857] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1479.143586] Lustre: Skipped 3 previous similar messages [ 1480.160017] Lustre: lustre-MDT0000 is waiting for obd_unlinked_exports more than 8 seconds. The obd refcount = 3. Is it stuck? [ 1480.341270] Lustre: server umount lustre-MDT0000 complete [ 1483.969421] LustreError: 26222:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787441394 with bad export cookie 7898105016043988230 [ 1483.981580] LustreError: 26222:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 1484.296643] Lustre: server umount lustre-MDT0001 complete [ 1490.332294] Lustre: server umount lustre-OST0000 complete [ 1493.541878] Lustre: server umount lustre-OST0001 complete [ 1499.144419] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_hostid [ 1505.473750] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing load_modules_local [ 1538.532376] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing load_modules_local [ 1546.494366] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1546.674649] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 1546.701602] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 1546.791442] Lustre: lustre-MDT0000: new disk, initializing [ 1546.877426] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 1550.069418] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1559.287962] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1559.370854] Lustre: 59141: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 [ 1559.403507] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 1559.408545] Lustre: Skipped 1 previous similar message [ 1559.497204] Lustre: lustre-MDT0001: new disk, initializing [ 1559.574254] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 1559.581641] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 1563.277126] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1567.858505] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 1573.562767] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 1573.785674] Lustre: lustre-OST0000: new disk, initializing [ 1573.789904] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 1573.797617] Lustre: 60775:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 1575.574520] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 1575.584514] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 1575.660356] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 1579.250811] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1588.129776] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 1588.220351] Lustre: lustre-OST0001: new disk, initializing [ 1588.223647] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 1588.229270] Lustre: 61644:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 1589.464134] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 1589.488181] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 1589.581633] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 1593.234380] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1601.091728] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1603.836416] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 1612.136409] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1612.905221] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1612.909154] Lustre: Skipped 19 previous similar messages [ 1616.238421] Lustre: *** cfs_fail_loc=1601, val=2*** [ 1616.244154] Lustre: Skipped 13 previous similar messages [ 1631.078400] Lustre: Failing over lustre-MDT0000 [ 1631.203650] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1631.207090] Lustre: Skipped 3 previous similar messages [ 1631.254435] Lustre: server umount lustre-MDT0000 complete [ 1639.620285] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1639.715171] LustreError: MGC192.168.206.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1639.722702] LustreError: Skipped 2 previous similar messages [ 1643.585977] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1645.043919] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1645.052651] Lustre: Skipped 7 previous similar messages [ 1645.101409] Lustre: *** cfs_fail_loc=160b, val=2*** [ 1645.110416] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:65) [ 1645.118903] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:65) [ 1650.336502] Lustre: Failing over lustre-MDT0000 [ 1650.521074] Lustre: server umount lustre-MDT0000 complete [ 1657.793546] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1661.850173] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1663.503720] Lustre: *** cfs_fail_loc=160b, val=2*** [ 1663.508564] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:97) [ 1663.508564] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:97) [ 1666.418733] Lustre: Failing over lustre-MDT0000 [ 1668.628219] Lustre: server umount lustre-MDT0000 complete [ 1675.811537] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1680.274340] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1681.437381] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:129) [ 1681.439825] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:129) [ 1685.041366] Lustre: *** cfs_fail_loc=1602, val=2*** [ 1693.788530] Lustre: DEBUG MARKER: == sanity-lfsck test 9a: LFSCK speed control (1) ========= 19:33:22 (1787441602) [ 1705.850137] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing load_modules_local [ 1721.595523] Lustre: 68545:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 1739.533714] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1742.137592] Lustre: 69680:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 1844.063076] Lustre: DEBUG MARKER: == sanity-lfsck test 9b: LFSCK speed control (2) ========= 19:35:52 (1787441752) [ 1881.538416] Lustre: 62417:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 257 < left 278, rollback = 2 [ 1881.550860] Lustre: 62417:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 17060 previous similar messages [ 1881.557846] Lustre: 62417:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 1881.565842] Lustre: 62417:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 17060 previous similar messages [ 1881.575372] Lustre: 62417:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 1881.585509] Lustre: 62417:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 17060 previous similar messages [ 1881.598461] Lustre: 62417:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 1881.608852] Lustre: 62417:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 17060 previous similar messages [ 1881.617499] Lustre: 62417:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 1881.626360] Lustre: 62417:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 17060 previous similar messages [ 1881.634591] Lustre: 62417:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 1881.642900] Lustre: 62417:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 17060 previous similar messages [ 1886.110182] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1886.122029] Lustre: Skipped 4 previous similar messages [ 1906.984173] Lustre: *** cfs_fail_loc=160c, val=0*** [ 1906.986917] Lustre: Skipped 7 previous similar messages [ 1943.034920] Lustre: DEBUG MARKER: == sanity-lfsck test 10: System is available during LFSCK scanning ========================================================== 19:37:31 (1787441851) [ 1983.484691] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1991.489919] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1991.491854] Lustre: Skipped 476 previous similar messages [ 2007.493542] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2007.499435] Lustre: Skipped 957 previous similar messages [ 2039.514804] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2039.518351] Lustre: Skipped 2031 previous similar messages [ 2041.468466] Lustre: *** cfs_fail_loc=1604, val=0*** [ 2041.473737] Lustre: Skipped 2599 previous similar messages [ 2249.965515] Lustre: DEBUG MARKER: == sanity-lfsck test 11a: LFSCK can rebuild lost last_id ========================================================== 19:42:38 (1787442158) [ 2377.697893] 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 [ 2377.697966] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 2377.702375] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2377.715134] Lustre: Skipped 21 previous similar messages [ 2377.736445] LustreError: Skipped 4 previous similar messages [ 2382.837169] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2382.845698] Lustre: Skipped 6 previous similar messages [ 2383.956803] Lustre: server umount lustre-MDT0000 complete [ 2387.329207] LustreError: 62580:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787442297 with bad export cookie 7898105016044007333 [ 2387.338207] LustreError: MGC192.168.206.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2387.341839] LustreError: 62580:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 2387.346054] LustreError: Skipped 2 previous similar messages [ 2387.691617] Lustre: server umount lustre-MDT0001 complete [ 2400.715436] Lustre: server umount lustre-OST0000 complete [ 2403.808588] Lustre: 16433:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787442298/real 1787442298] req@ffff8f88fe925880 x1874267087739392/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787442314 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2404.061377] Lustre: server umount lustre-OST0001 complete [ 2409.487562] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: (null) [ 2416.711800] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 2432.287824] LustreError: Failed to get MGS log lustre-sptlrpc and no local copy. [ 2437.407472] LustreError: 75207:0:(mgc_request.c:233:do_config_log_add()) MGC192.168.206.155@tcp: failed processing log, type 4: rc = -110 [ 2463.071428] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 2463.085194] Lustre: Skipped 8 previous similar messages [ 2468.806332] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2472.153086] Lustre: 75791: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. [ 2472.162504] Lustre: *** cfs_fail_loc=160e, val=3*** [ 2475.239541] Lustre: 75791:0:(ofd_dev.c:573:ofd_lfsck_out_notify()) lustre-OST0000: Rebuilt crashed LAST_ID files successfully. [ 2482.581081] Lustre: DEBUG MARKER: == sanity-lfsck test 11b: LFSCK can rebuild crashed last_id ========================================================== 19:46:31 (1787442391) [ 2494.520827] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing load_modules_local [ 2504.589682] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2504.965593] LustreError: 75232: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. [ 2504.994179] LustreError: 75232:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 25 previous similar messages [ 2505.070499] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3272 to 0x280000401:3297) [ 2509.071994] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2516.023665] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2520.301134] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2522.835151] Lustre: 78458:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 2535.631952] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2541.041481] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3207 to 0x2c0000401:3233) [ 2542.465721] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2549.702227] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 2553.424498] Lustre: 79955:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 2554.653817] Lustre: 78737:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 256 < left 278, rollback = 2 [ 2554.663088] Lustre: 78737:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 22021 previous similar messages [ 2554.668842] Lustre: 78737:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 2554.673657] Lustre: 78737:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 22021 previous similar messages [ 2554.679442] Lustre: 78737:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 2554.687482] Lustre: 78737:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 22021 previous similar messages [ 2554.695604] Lustre: 78737:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 2554.701663] Lustre: 78737:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 22021 previous similar messages [ 2554.708582] Lustre: 78737:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 2554.714026] Lustre: 78737:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 22021 previous similar messages [ 2554.720562] Lustre: 78737:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 2554.725660] Lustre: 78737:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 22021 previous similar messages [ 2558.269989] Lustre: *** cfs_fail_loc=160d, val=0*** [ 2558.849216] Lustre: *** cfs_fail_loc=160d, val=0*** [ 2558.853082] Lustre: Skipped 3 previous similar messages [ 2565.124422] Lustre: Failing over lustre-OST0000 [ 2565.336389] Lustre: server umount lustre-OST0000 complete [ 2566.624591] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 2574.705469] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2574.932433] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 2574.949535] Lustre: Skipped 3 previous similar messages [ 2576.226324] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 2576.237191] Lustre: Skipped 3 previous similar messages [ 2576.272559] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 2576.274352] Lustre: lustre-OST0000-osc-MDT0001: Connection restored to 0@lo (at 0@lo) [ 2576.281620] Lustre: Skipped 3 previous similar messages [ 2576.288778] Lustre: *** cfs_fail_loc=215, val=0*** [ 2576.292567] Lustre: Skipped 11 previous similar messages [ 2576.308926] Lustre: Skipped 2 previous similar messages [ 2581.476470] Lustre: *** cfs_fail_loc=215, val=0*** [ 2581.479400] Lustre: Skipped 1 previous similar message [ 2581.755111] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2585.899034] Lustre: 81356: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. [ 2585.913355] Lustre: 81356:0:(ofd_dev.c:573:ofd_lfsck_out_notify()) lustre-OST0000: Rebuilt crashed LAST_ID files successfully. [ 2586.591478] Lustre: *** cfs_fail_loc=215, val=0*** [ 2586.598193] Lustre: Skipped 1 previous similar message [ 2588.725917] Lustre: Failing over lustre-OST0000 [ 2588.965519] Lustre: server umount lustre-OST0000 complete [ 2597.194180] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2599.057223] Lustre: *** cfs_fail_loc=215, val=0*** [ 2599.066671] Lustre: Skipped 1 previous similar message [ 2603.391991] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2604.518126] Lustre: *** cfs_fail_loc=215, val=0*** [ 2604.523309] Lustre: Skipped 1 previous similar message [ 2612.707970] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2612.728342] Lustre: Skipped 3 previous similar messages [ 2615.218580] Lustre: server umount lustre-MDT0000 complete [ 2620.903030] LustreError: 75213:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787442531 with bad export cookie 7898105016045569621 [ 2621.415331] Lustre: server umount lustre-MDT0001 complete [ 2636.519496] Lustre: server umount lustre-OST0000 complete [ 2639.329129] Lustre: 16430:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787442533/real 1787442533] req@ffff8f88ff9c2d80 x1874267087833856/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787442549 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2640.765031] Lustre: server umount lustre-OST0001 complete [ 2649.638749] Lustre: DEBUG MARKER: == sanity-lfsck test 12a: single command to trigger LFSCK on all devices ========================================================== 19:49:18 (1787442558) [ 2663.768305] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing load_modules_local [ 2673.782461] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2678.225501] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2686.660958] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2691.888759] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2695.502552] Lustre: 85739:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 2701.992144] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2707.478337] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2715.474336] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2718.755646] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3362 to 0x280000401:3393) [ 2718.770742] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3207 to 0x2c0000401:3265) [ 2722.201132] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2729.478243] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 2733.285757] Lustre: 87607:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 2762.575777] Lustre: DEBUG MARKER: == sanity-lfsck test 12b: auto detect Lustre device ====== 19:51:11 (1787442671) [ 2775.273751] Lustre: DEBUG MARKER: == sanity-lfsck test 13: LFSCK can repair crashed lmm_oi ========================================================== 19:51:23 (1787442683) [ 2776.717434] Lustre: *** cfs_fail_loc=160f, val=0*** [ 2789.664972] Lustre: DEBUG MARKER: == sanity-lfsck test 14a: LFSCK can repair MDT-object with dangling LOV EA reference (1) ========================================================== 19:51:37 (1787442697) [ 2794.597882] Lustre: *** cfs_fail_loc=1610, val=0*** [ 2794.600405] Lustre: Skipped 3 previous similar messages [ 2841.569636] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2841.588890] Lustre: Skipped 2 previous similar messages [ 2846.181527] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 2846.191142] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2847.398405] Lustre: server umount lustre-MDT0000 complete [ 2850.493102] LustreError: 84578:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787442760 with bad export cookie 7898105016045578084 [ 2850.514105] LustreError: 84578:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 2850.728834] Lustre: server umount lustre-MDT0001 complete [ 2864.468187] Lustre: server umount lustre-OST0000 complete [ 2876.745173] Lustre: server umount lustre-OST0001 complete [ 2891.980893] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing load_modules_local [ 2901.113562] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2905.370350] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2913.372284] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2917.556625] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2920.553041] Lustre: 93473:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 2927.308116] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2932.909404] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2938.931231] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:116 to 0x280000400:161) [ 2942.997744] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2946.346541] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3317 to 0x2c0000401:3361) [ 2946.354235] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3554 to 0x280000401:3585) [ 2946.412404] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:116 to 0x2c0000400:161) [ 2950.623953] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2959.387274] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 2963.126234] Lustre: 95345:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 2971.124910] Lustre: DEBUG MARKER: == sanity-lfsck test 14b: LFSCK can repair MDT-object with dangling LOV EA reference (2) ========================================================== 19:54:39 (1787442879) [ 2977.691581] Lustre: *** cfs_fail_loc=1610, val=0*** [ 2977.693520] Lustre: Skipped 63 previous similar messages [ 3002.848622] 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 [ 3002.854718] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3002.864228] Lustre: Skipped 18 previous similar messages [ 3002.866984] Lustre: Skipped 5 previous similar messages [ 3009.754815] Lustre: server umount lustre-MDT0000 complete [ 3013.783826] LustreError: 92314:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787442924 with bad export cookie 7898105016045606497 [ 3013.788523] LustreError: MGC192.168.206.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3013.804024] LustreError: 92314:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 3013.811456] LustreError: Skipped 2 previous similar messages [ 3014.557255] Lustre: server umount lustre-MDT0001 complete [ 3029.412581] Lustre: server umount lustre-OST0000 complete [ 3044.536181] Lustre: server umount lustre-OST0001 complete [ 3069.358243] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing load_modules_local [ 3079.651111] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3080.265221] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3080.270366] Lustre: Skipped 13 previous similar messages [ 3085.150981] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3093.804129] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3098.918017] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3102.428983] Lustre: 99396:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3109.145599] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3115.578583] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3118.629066] LustreError: 99749: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. [ 3118.643618] LustreError: 99749:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 47 previous similar messages [ 3118.644345] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:116 to 0x280000400:193) [ 3123.452542] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3124.716553] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3682 to 0x280000401:3713) [ 3124.725323] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:116 to 0x2c0000400:193) [ 3124.727572] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3317 to 0x2c0000401:3393) [ 3129.425923] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3137.661901] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3147.625158] Lustre: DEBUG MARKER: == sanity-lfsck test 15a: LFSCK can repair unmatched MDT-object/OST-object pairs (1) ========================================================== 19:57:36 (1787443056) [ 3151.004854] Lustre: *** cfs_fail_loc=1611, val=0*** [ 3151.008028] Lustre: Skipped 63 previous similar messages [ 3151.148928] Lustre: *** cfs_fail_loc=1611, val=0*** [ 3160.758199] Lustre: DEBUG MARKER: == sanity-lfsck test 15b: LFSCK can repair unmatched MDT-object/OST-object pairs (2) ========================================================== 19:57:49 (1787443069) [ 3161.295374] Lustre: 98252:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 253 < left 278, rollback = 2 [ 3161.307255] Lustre: 98252:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 1511 previous similar messages [ 3161.319499] Lustre: 98252:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 3161.333346] Lustre: 98252:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1511 previous similar messages [ 3161.343894] Lustre: 98252:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3161.360619] Lustre: 98252:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1511 previous similar messages [ 3161.370855] Lustre: 98252:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/1 [ 3161.377728] Lustre: 98252:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1511 previous similar messages [ 3161.383401] Lustre: 98252:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 3161.388842] Lustre: 98252:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1511 previous similar messages [ 3161.398337] Lustre: 98252:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3161.402747] Lustre: 98252:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1511 previous similar messages [ 3163.266533] Lustre: *** cfs_fail_loc=1612, val=0*** [ 3163.270340] Lustre: Skipped 1 previous similar message [ 3163.329295] Lustre: *** cfs_fail_loc=1612, val=0*** [ 3163.332734] Lustre: Skipped 2 previous similar messages [ 3173.825858] Lustre: DEBUG MARKER: == sanity-lfsck test 15c: LFSCK can repair unmatched MDT-object/OST-object pairs (3) ========================================================== 19:58:02 (1787443082) [ 3175.697473] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_15c MDS newer than 2.7.55, LU-6475 [ 3177.634107] Lustre: DEBUG MARKER: == sanity-lfsck test 15d: LFSCK don't crash upon dir migration failure ========================================================== 19:58:06 (1787443086) [ 3183.783374] Lustre: *** cfs_fail_loc=1709, val=0*** [ 3183.844462] LustreError: 98265:0:(osp_object.c:618:osp_attr_get()) lustre-MDT0000-osp-MDT0001: osp_attr_get update error [0x200003ab2:0x1:0x0]: rc = -5 [ 3183.862375] LustreError: 98265:0:(mdt_reint.c:2644:mdt_reint_migrate()) lustre-MDT0001: migrate [0x240002340:0x6c:0x0]/s34 failed: rc = -5 [ 3197.446422] LustreError: 98252:0:(lod_object.c:945:lod_load_lmv_shards()) lustre-MDT0001-mdtlov: the shard [0x200003ab1:0x6a:0x0]:1 for the striped directory [0x240002340:0x8b:0x0] is out of the known LMV EA range [0 - 0], failout [ 3204.129170] LustreError: 98251:0:(lod_object.c:945:lod_load_lmv_shards()) lustre-MDT0001-mdtlov: the shard [0x200003ab1:0x6a:0x0]:1 for the striped directory [0x240002340:0x8b:0x0] is out of the known LMV EA range [0 - 0], failout [ 3204.156448] LustreError: 98251:0:(mdt_handler.c:1498:mdt_getattr_internal()) lustre-MDT0001: getattr error for [0x240002340:0x8b:0x0]: rc = -5 [ 3237.346832] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3237.349789] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3237.366413] Lustre: Skipped 1 previous similar message [ 3243.795503] Lustre: server umount lustre-MDT0000 complete [ 3251.658147] LustreError: 98238:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787443162 with bad export cookie 7898105016045621232 [ 3251.678834] LustreError: 98238:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 3 previous similar messages [ 3251.849030] Lustre: server umount lustre-MDT0001 complete [ 3268.959632] Lustre: 16430:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787443163/real 1787443163] req@ffff8f87ccbf5f80 x1874267088628608/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787443179 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3270.229464] Lustre: server umount lustre-OST0000 complete [ 3273.198807] Lustre: 16432:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787443167/real 1787443167] req@ffff8f88e57eea00 x1874267088628864/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787443183 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3278.303983] Lustre: 16433:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787443172/real 1787443172] req@ffff8f87ccbf6a00 x1874267088629504/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787443188 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3278.366571] Lustre: 16433:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 3279.149301] Lustre: server umount lustre-OST0001 complete [ 3296.721706] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing unload_modules_local [ 3299.782586] Key type lgssc unregistered [ 3300.079664] LNet: 105095:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 3300.089467] LNetError: 105095:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 3301.163195] LNet: Removed LNI 192.168.206.155@tcp [ 3302.176163] Key type .llcrypt unregistered [ 3302.177791] Key type ._llcrypt unregistered [ 3325.088259] Key type ._llcrypt registered [ 3325.097262] Key type .llcrypt registered [ 3325.257181] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_hostid [ 3337.778403] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing load_modules_local [ 3338.729205] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 3338.757986] alg: No test for adler32 (adler32-zlib) [ 3339.893529] Lustre: Lustre: Build Version: 2.17.57_64_ga728441 [ 3340.184481] LNet: Added LNI 192.168.206.155@tcp [8/256/0/180] [ 3341.927244] Key type lgssc registered [ 3343.126304] Lustre: Echo OBD driver; http://www.lustre.org/ [ 3401.460160] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing load_modules_local [ 3417.089593] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 3417.140856] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3418.562817] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 3418.619079] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 3418.735856] Lustre: lustre-MDT0000: new disk, initializing [ 3418.895221] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3418.952835] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 3425.173990] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3439.404211] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3439.501818] Lustre: 109544: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 [ 3439.534926] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 3439.543955] Lustre: Skipped 1 previous similar message [ 3439.651002] Lustre: lustre-MDT0001: new disk, initializing [ 3439.769143] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 3439.823655] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 3439.846731] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 3445.075051] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3450.653563] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 3460.878159] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3461.282597] Lustre: lustre-OST0000: new disk, initializing [ 3461.301798] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 3461.324787] Lustre: 111484:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 3461.485986] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 3468.341317] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 3468.383114] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 3468.511872] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 3469.687764] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3486.313858] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3486.531740] Lustre: lustre-OST0001: new disk, initializing [ 3486.535747] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 3486.544830] Lustre: 112510:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 3486.635679] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 3493.707629] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3493.935581] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 3493.958572] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 3494.085870] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 3506.024466] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3515.423777] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 3521.364514] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 20:03:49 (1787443429) === [ 3528.827463] Lustre: DEBUG MARKER: == sanity-lfsck test 16: LFSCK can repair inconsistent MDT-object/OST-object owner ========================================================== 20:03:57 (1787443437) [ 3529.039203] Lustre: 111784:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 251 < left 278, rollback = 2 [ 3529.049917] Lustre: 111784:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 3529.056845] Lustre: 111784:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3529.067650] Lustre: 111784:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 3529.076819] Lustre: 111784:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 3529.088194] Lustre: 111784:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3529.551974] Lustre: 109552:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 3529.563291] Lustre: 109552:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 6 previous similar messages [ 3529.572488] Lustre: 109552:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 3529.583960] Lustre: 109552:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 6 previous similar messages [ 3529.593424] Lustre: 109552:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3529.602847] Lustre: 109552:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 6 previous similar messages [ 3529.610961] Lustre: 109552:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 3529.619610] Lustre: 109552:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 6 previous similar messages [ 3529.632474] Lustre: 109552:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 3529.642422] Lustre: 109552:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 6 previous similar messages [ 3529.659857] Lustre: 109552:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3529.672462] Lustre: 109552:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 6 previous similar messages [ 3530.557606] Lustre: 109551:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 3530.578652] Lustre: 109551:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 89 previous similar messages [ 3530.601841] Lustre: 109551:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 3530.608297] Lustre: 109551:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 89 previous similar messages [ 3530.613608] Lustre: 109551:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3530.619283] Lustre: 109551:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 89 previous similar messages [ 3530.623960] Lustre: 109551:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 7/369/0 [ 3530.630453] Lustre: 109551:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 89 previous similar messages [ 3530.635771] Lustre: 109551:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 3530.642650] Lustre: 109551:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 89 previous similar messages [ 3530.697684] Lustre: 109552:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3530.713382] Lustre: 109552:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 92 previous similar messages [ 3533.405901] Lustre: *** cfs_fail_loc=1613, val=0*** [ 3544.303785] Lustre: DEBUG MARKER: == sanity-lfsck test 17: LFSCK can repair multiple references ========================================================== 20:04:13 (1787443453) [ 3545.875864] Lustre: 109551:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 3545.884070] Lustre: 109551:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 212 previous similar messages [ 3545.899393] Lustre: 109551:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 3545.907555] Lustre: 109551:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 212 previous similar messages [ 3545.928639] Lustre: 109551:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3545.939210] Lustre: 109551:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 212 previous similar messages [ 3545.950853] Lustre: 109551:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 3545.955774] Lustre: 109551:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 212 previous similar messages [ 3545.963373] Lustre: 109551:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 3545.969499] Lustre: 109551:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 212 previous similar messages [ 3545.976933] Lustre: 109551:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3545.983746] Lustre: 109551:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 209 previous similar messages [ 3547.218360] Lustre: *** cfs_fail_loc=1614, val=0*** [ 3547.740067] Lustre: *** cfs_fail_loc=1614, val=103*** [ 3547.744113] Lustre: Skipped 1 previous similar message [ 3552.721363] Lustre: 111473:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 259 < left 275, rollback = 2 [ 3552.744313] Lustre: 111473:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 11 previous similar messages [ 3552.761860] Lustre: 111473:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 3552.774158] Lustre: 111473:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3552.785189] Lustre: 111473:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/1, xattr_set: 3/275/0 [ 3552.792649] Lustre: 111473:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3552.798289] Lustre: 111473:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/9/0, punch: 1/4/0, quota 7/225/0 [ 3552.802656] Lustre: 111473:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3552.806357] Lustre: 111473:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 3552.813636] Lustre: 111473:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3552.817855] Lustre: 111473:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3552.826372] Lustre: 111473:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3560.316739] Lustre: DEBUG MARKER: == sanity-lfsck test 18a: Find out orphan OST-object and repair it (1) ========================================================== 20:04:28 (1787443468) [ 3560.875436] Lustre: 109552:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 251 < left 278, rollback = 2 [ 3560.882480] Lustre: 109552:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 4 previous similar messages [ 3560.887753] Lustre: 109552:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 3560.893207] Lustre: 109552:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 4 previous similar messages [ 3560.898168] Lustre: 109552:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3560.903600] Lustre: 109552:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 4 previous similar messages [ 3560.908694] Lustre: 109552:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 3560.913938] Lustre: 109552:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 4 previous similar messages [ 3560.919472] Lustre: 109552:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 3560.924622] Lustre: 109552:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 4 previous similar messages [ 3560.930242] Lustre: 109552:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3560.941183] Lustre: 109552:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 4 previous similar messages [ 3563.104136] Lustre: *** cfs_fail_loc=1615, val=0*** [ 3563.106170] Lustre: Skipped 1 previous similar message [ 3582.382927] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_18b skipping excluded test 18b [ 3584.158836] Lustre: DEBUG MARKER: == sanity-lfsck test 18c: Find out orphan OST-object and repair it (3) ========================================================== 20:04:52 (1787443492) [ 3584.521849] Lustre: 111784:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 3584.528544] Lustre: 111784:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 18 previous similar messages [ 3584.533396] Lustre: 111784:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 3584.537459] Lustre: 111784:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 18 previous similar messages [ 3584.543711] Lustre: 111784:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3584.550631] Lustre: 111784:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 18 previous similar messages [ 3584.556179] Lustre: 111784:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 3584.562632] Lustre: 111784:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 18 previous similar messages [ 3584.567735] Lustre: 111784:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 3584.572640] Lustre: 111784:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 18 previous similar messages [ 3584.578356] Lustre: 111784:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3584.582623] Lustre: 111784:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 18 previous similar messages [ 3587.497137] Lustre: *** cfs_fail_loc=1617, val=0*** [ 3587.589614] Lustre: *** cfs_fail_loc=1617, val=0*** [ 3590.981846] Lustre: *** cfs_fail_loc=1616, val=0*** [ 3590.990013] Lustre: Skipped 5 previous similar messages [ 3616.704522] Lustre: DEBUG MARKER: == sanity-lfsck test 18d: Find out orphan OST-object and repair it (4) ========================================================== 20:05:25 (1787443525) [ 3617.166641] Lustre: 109552:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 3617.181391] Lustre: 109552:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 24 previous similar messages [ 3617.187631] Lustre: 109552:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 3617.193541] Lustre: 109552:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 24 previous similar messages [ 3617.198949] Lustre: 109552:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3617.204476] Lustre: 109552:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 24 previous similar messages [ 3617.213381] Lustre: 109552:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 3617.221253] Lustre: 109552:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 24 previous similar messages [ 3617.226960] Lustre: 109552:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 3617.232795] Lustre: 109552:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 24 previous similar messages [ 3617.239664] Lustre: 109552:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3617.254143] Lustre: 109552:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 24 previous similar messages [ 3618.760735] Lustre: *** cfs_fail_loc=1618, val=0*** [ 3618.768246] Lustre: Skipped 5 previous similar messages [ 3653.096761] 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 [ 3653.100382] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3653.112472] Lustre: Skipped 3 previous similar messages [ 3653.137500] Lustre: Skipped 3 previous similar messages [ 3658.211497] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3658.217775] Lustre: Skipped 3 previous similar messages [ 3659.276367] Lustre: server umount lustre-MDT0000 complete [ 3662.961355] LustreError: 109538:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787443573 with bad export cookie 4216357983268091455 [ 3662.967944] LustreError: MGC192.168.206.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3662.976862] LustreError: 109538:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 3663.328925] 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 [ 3663.539026] Lustre: server umount lustre-MDT0001 complete [ 3669.670979] Lustre: server umount lustre-OST0000 complete [ 3673.826698] Lustre: server umount lustre-OST0001 complete [ 3690.875911] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing load_modules_local [ 3701.979181] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3702.455592] LustreError: 118222: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. [ 3702.500863] LustreError: 118222:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 5 previous similar messages [ 3702.548726] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3707.336968] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3707.879694] LustreError: 118223: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. [ 3711.968977] LustreError: 118222: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. [ 3716.405150] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3716.677067] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 3720.869533] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3723.747806] Lustre: 119362:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3730.505065] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3738.538663] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3742.050334] LustreError: 119716: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. [ 3742.065934] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:4 to 0x280000400:33) [ 3747.169303] LustreError: 120248: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. [ 3747.189738] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:116 to 0x280000401:161) [ 3747.198041] LustreError: 120248:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 1 previous similar message [ 3747.403795] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3747.624048] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 3747.628594] Lustre: Skipped 1 previous similar message [ 3752.951478] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:33) [ 3752.966552] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:4 to 0x2c0000401:33) [ 3754.901410] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3763.250205] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3766.936892] Lustre: 121234:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 3781.351611] Lustre: DEBUG MARKER: == sanity-lfsck test 18e: Find out orphan OST-object and repair it (5) ========================================================== 20:08:10 (1787443690) [ 3781.782949] Lustre: 118217:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 251 < left 278, rollback = 2 [ 3781.791468] Lustre: 118217:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 21 previous similar messages [ 3781.797744] Lustre: 118217:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 3781.804578] Lustre: 118217:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3781.811550] Lustre: 118217:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3781.817330] Lustre: 118217:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3781.824241] Lustre: 118217:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 3781.829377] Lustre: 118217:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3781.834862] Lustre: 118217:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 3781.844721] Lustre: 118217:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3781.855959] Lustre: 118217:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3781.863702] Lustre: 118217:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3783.644793] Lustre: *** cfs_fail_loc=1618, val=0*** [ 3783.651369] Lustre: Skipped 3 previous similar messages [ 3818.979415] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3818.989829] 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 [ 3819.005961] Lustre: Skipped 1 previous similar message [ 3819.018827] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3823.718046] Lustre: server umount lustre-MDT0000 complete [ 3824.609499] LustreError: 119247: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. [ 3824.661066] LustreError: 119247:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 3 previous similar messages [ 3828.268667] LustreError: 118202:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787443738 with bad export cookie 4216357983268106694 [ 3828.278573] LustreError: MGC192.168.206.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3828.288527] LustreError: 118202:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 3828.900141] Lustre: server umount lustre-MDT0001 complete [ 3842.772048] Lustre: server umount lustre-OST0000 complete [ 3846.116174] Lustre: 106691:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787443740/real 1787443740] req@ffff8f87cab86d80 x1874270093598720/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787443756 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3846.141415] 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 [ 3846.159424] Lustre: Skipped 3 previous similar messages [ 3846.665180] Lustre: server umount lustre-OST0001 complete [ 3863.478583] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing load_modules_local [ 3873.084444] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3873.534060] LustreError: 123812: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. [ 3873.615819] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3877.704493] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3885.363053] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3889.809507] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3892.188322] Lustre: 124952:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3898.706208] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3905.682230] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3911.354349] LustreError: 125303: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. [ 3911.370034] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:4 to 0x280000400:65) [ 3911.384880] LustreError: 125303:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 2 previous similar messages [ 3913.828424] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3918.140585] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:166 to 0x280000401:193) [ 3918.153216] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:4 to 0x2c0000401:65) [ 3918.185871] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:65) [ 3921.018549] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3928.790532] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3932.300614] Lustre: 126820:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 3937.342068] Lustre: 123813:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 252 < left 260, rollback = 2 [ 3937.349532] Lustre: 123813:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 21 previous similar messages [ 3937.361091] Lustre: 123813:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 3937.377754] Lustre: 123813:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3937.388468] Lustre: 123813:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 0/0/0, xattr_set: 1/260/0 [ 3937.394319] Lustre: 123813:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3937.403913] Lustre: 123813:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/9/0, punch: 0/0/0, quota 4/150/2 [ 3937.417429] Lustre: 123813:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3937.423180] Lustre: 123813:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 1/17/2, delete: 0/0/0 [ 3937.432517] Lustre: 123813:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3937.444149] Lustre: 123813:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3937.454715] Lustre: 123813:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3937.513151] Lustre: *** cfs_fail_loc=1602, val=10*** [ 3962.652876] Lustre: DEBUG MARKER: == sanity-lfsck test 18f: Skip the failed OST(s) when handle orphan OST-objects ========================================================== 20:11:11 (1787443871) [ 3965.958072] Lustre: *** cfs_fail_loc=1616, val=0*** [ 3965.960130] Lustre: Skipped 3 previous similar messages [ 3972.476134] Lustre: *** cfs_fail_loc=161c, val=0*** [ 3990.395546] Lustre: DEBUG MARKER: == sanity-lfsck test 18g: Find out orphan OST-object and repair it (7) ========================================================== 20:11:39 (1787443899) [ 3992.268299] Lustre: *** cfs_fail_loc=162e, val=0*** [ 3992.271252] Lustre: *** cfs_fail_loc=162e, val=0*** [ 3992.274392] Lustre: Skipped 7 previous similar messages [ 4003.299804] Lustre: DEBUG MARKER: == sanity-lfsck test 18h: LFSCK can repair crashed PFL extent range ========================================================== 20:11:52 (1787443912) [ 4020.566975] Lustre: DEBUG MARKER: == sanity-lfsck test 19a: OST-object inconsistency self detect ========================================================== 20:12:09 (1787443929) [ 4030.463385] Lustre: DEBUG MARKER: == sanity-lfsck test 19b: OST-object inconsistency self repair ========================================================== 20:12:19 (1787443939) [ 4033.205240] Lustre: *** cfs_fail_loc=1611, val=0*** [ 4033.250573] Lustre: *** cfs_fail_loc=1611, val=0*** [ 4033.258975] Lustre: Skipped 3 previous similar messages [ 4037.557447] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.206.55@tcp inode [0x2000013a1:0x1f:0x0] object 0x280000401:202 extent [0-4095], client returned csum 0 (type 4), server csum 703fb3ad (type 4) [ 4038.645119] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.206.55@tcp inode [0x2000013a1:0x20:0x0] object 0x280000401:203 extent [0-4095], client returned csum 0 (type 4), server csum 7cbb935c (type 4) [ 4045.779877] Lustre: DEBUG MARKER: == sanity-lfsck test 20a: Handle the orphan with dummy LOV EA slot properly ========================================================== 20:12:34 (1787443954) [ 4047.913745] Lustre: *** cfs_fail_loc=1616, val=0*** [ 4047.919943] Lustre: Skipped 3 previous similar messages [ 4066.559573] Lustre: DEBUG MARKER: == sanity-lfsck test 20b: Handle the orphan with dummy LOV EA slot properly - PFL case ========================================================== 20:12:55 (1787443975) [ 4072.495489] Lustre: DEBUG MARKER: == sanity-lfsck test 21: run all LFSCK components by default ========================================================== 20:13:01 (1787443981) [ 4082.932261] Lustre: DEBUG MARKER: == sanity-lfsck test 22a: LFSCK can repair unmatched pairs (1) ========================================================== 20:13:11 (1787443991) [ 4084.999101] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4085.005856] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4085.012191] Lustre: Skipped 1 previous similar message [ 4095.765640] Lustre: DEBUG MARKER: == sanity-lfsck test 22b: LFSCK can repair unmatched pairs (2) ========================================================== 20:13:24 (1787444004) [ 4097.524945] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4097.534599] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4108.356248] Lustre: DEBUG MARKER: == sanity-lfsck test 23a: LFSCK can repair dangling name entry (1) ========================================================== 20:13:37 (1787444017) [ 4110.056814] Lustre: *** cfs_fail_loc=1620, val=0*** [ 4122.194691] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_23b skipping excluded test 23b [ 4123.742341] Lustre: DEBUG MARKER: == sanity-lfsck test 23c: LFSCK can repair dangling name entry (3) ========================================================== 20:13:52 (1787444032) [ 4129.202204] Lustre: *** cfs_fail_loc=1621, val=127*** [ 4129.207445] Lustre: Skipped 1 previous similar message [ 4131.540184] Lustre: *** cfs_fail_loc=1602, val=10*** [ 4150.781678] Lustre: DEBUG MARKER: == sanity-lfsck test 23d: LFSCK can repair a dangling name entry to a remote object ========================================================== 20:14:19 (1787444059) [ 4152.743487] Lustre: Failing over lustre-MDT0000 [ 4153.015337] Lustre: server umount lustre-MDT0000 complete [ 4153.831810] 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 [ 4153.839184] LustreError: 123807: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. [ 4153.843591] Lustre: Skipped 1 previous similar message [ 4153.861909] LustreError: 123807:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 3 previous similar messages [ 4161.959647] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4162.059546] LustreError: MGC192.168.206.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4162.276769] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4162.287158] Lustre: Skipped 3 previous similar messages [ 4162.321044] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4166.450811] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4166.990475] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4167.657970] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4167.675869] Lustre: lustre-MDT0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 4167.713023] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:130 to 0x2c0000401:161) [ 4167.722956] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:265 to 0x280000401:289) [ 4168.813991] LustreError: 127642:0:(mdt_open.c:1324:mdt_cross_open()) lustre-MDT0000: [0x2000013a3:0x82:0x0] doesn't exist!: rc = -14 [ 4179.332136] Lustre: DEBUG MARKER: == sanity-lfsck test 24: LFSCK can repair multiple-referenced name entry ========================================================== 20:14:47 (1787444087) [ 4181.239840] Lustre: *** cfs_fail_loc=1622, val=0*** [ 4181.425890] Lustre: *** cfs_fail_loc=1622, val=0*** [ 4181.428281] Lustre: Skipped 1 previous similar message [ 4190.881327] Lustre: DEBUG MARKER: == sanity-lfsck test 25: LFSCK can repair bad file type in the name entry ========================================================== 20:14:59 (1787444099) [ 4192.302851] Lustre: *** cfs_fail_loc=1623, val=0*** [ 4201.110870] Lustre: DEBUG MARKER: == sanity-lfsck test 26a: LFSCK can add the missing local name entry back to the namespace ========================================================== 20:15:10 (1787444110) [ 4201.458786] Lustre: 123808:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 253 < left 278, rollback = 2 [ 4201.467555] Lustre: 123808:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 560 previous similar messages [ 4201.470631] Lustre: 123808:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4201.475542] Lustre: 123808:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 560 previous similar messages [ 4201.481514] Lustre: 123808:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4201.494148] Lustre: 123808:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 560 previous similar messages [ 4201.514217] Lustre: 123808:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/1 [ 4201.522140] Lustre: 123808:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 560 previous similar messages [ 4201.539749] Lustre: 123808:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 4201.548876] Lustre: 123808:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 560 previous similar messages [ 4201.555085] Lustre: 123808:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4201.560015] Lustre: 123808:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 560 previous similar messages [ 4202.511707] Lustre: *** cfs_fail_loc=1624, val=0*** [ 4212.458463] Lustre: DEBUG MARKER: == sanity-lfsck test 26b: LFSCK can add the missing remote name entry back to the namespace ========================================================== 20:15:21 (1787444121) [ 4224.567404] Lustre: DEBUG MARKER: == sanity-lfsck test 27a: LFSCK can recreate the lost local parent directory as orphan ========================================================== 20:15:33 (1787444133) [ 4226.458268] Lustre: *** cfs_fail_loc=1624, val=0*** [ 4226.469565] Lustre: Skipped 1 previous similar message [ 4236.861505] Lustre: DEBUG MARKER: == sanity-lfsck test 27b: LFSCK can recreate the lost remote parent directory as orphan ========================================================== 20:15:45 (1787444145) [ 4247.889468] Lustre: DEBUG MARKER: == sanity-lfsck test 28: Skip the failed MDT(s) when handle orphan MDT-objects ========================================================== 20:15:56 (1787444156) [ 4254.018038] Lustre: *** cfs_fail_loc=161c, val=0*** [ 4254.024020] Lustre: Skipped 1 previous similar message [ 4271.812779] Lustre: DEBUG MARKER: == sanity-lfsck test 29b: LFSCK can repair bad nlink count (2) ========================================================== 20:16:20 (1787444180) [ 4273.421759] Lustre: *** cfs_fail_loc=1626, val=0*** [ 4273.425464] Lustre: Skipped 4 previous similar messages [ 4283.973214] Lustre: DEBUG MARKER: == sanity-lfsck test 29c: verify linkEA size limitation == 20:16:32 (1787444192) [ 4307.887544] Lustre: DEBUG MARKER: == sanity-lfsck test 29d: accessing non-existing inode shouldn't turn fs read-only (ldiskfs) ========================================================== 20:16:57 (1787444217) [ 4309.780959] LustreError: 126130:0:(osd_handler.c:284:osd_idc_find_or_init()) lustre-MDT0000: cannot lookup FID [0x2000013a3:0x9e:0x0]: rc = -2 [ 4314.662029] Lustre: DEBUG MARKER: == sanity-lfsck test 30: LFSCK can recover the orphans from backend /lost+found ========================================================== 20:17:03 (1787444223) [ 4341.103654] Lustre: Failing over lustre-MDT0000 [ 4341.366518] Lustre: server umount lustre-MDT0000 complete [ 4341.734075] 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 [ 4341.743840] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4341.743886] Lustre: Skipped 4 previous similar messages [ 4341.748801] LustreError: 127642: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. [ 4341.773530] LustreError: 127642:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 9 previous similar messages [ 4350.111561] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 4350.201827] LustreError: MGC192.168.206.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4350.351024] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4350.382802] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4353.537476] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4355.556212] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4355.558309] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4355.574355] Lustre: Skipped 3 previous similar messages [ 4355.601545] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4355.637785] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:294 to 0x280000401:321) [ 4355.638695] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:167 to 0x2c0000401:193) [ 4363.471123] Lustre: DEBUG MARKER: == sanity-lfsck test 31a: The LFSCK can find/repair the name entry with bad name hash (1) ========================================================== 20:17:52 (1787444272) [ 4373.286273] Lustre: DEBUG MARKER: == sanity-lfsck test 31b: The LFSCK can find/repair the name entry with bad name hash (2) ========================================================== 20:18:02 (1787444282) [ 4385.386371] Lustre: DEBUG MARKER: == sanity-lfsck test 31c: Re-generate the lost master LMV EA for striped directory ========================================================== 20:18:14 (1787444294) [ 4386.532163] Lustre: *** cfs_fail_loc=1629, val=0*** [ 4386.535846] Lustre: Skipped 5 previous similar messages [ 4397.656940] Lustre: DEBUG MARKER: == sanity-lfsck test 31d: Set broken striped directory (modified after broken) as read-only ========================================================== 20:18:26 (1787444306) [ 4403.286680] Lustre: Failing over lustre-MDT0000 [ 4403.571420] Lustre: server umount lustre-MDT0000 complete [ 4406.758268] 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 [ 4406.774767] Lustre: Skipped 3 previous similar messages [ 4411.217052] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4411.326496] LustreError: MGC192.168.206.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4411.586117] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4415.617525] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4417.000884] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4417.004905] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4417.024161] Lustre: Skipped 3 previous similar messages [ 4417.049463] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4417.091067] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:167 to 0x2c0000401:225) [ 4417.092916] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:294 to 0x280000401:353) [ 4425.440049] Lustre: Failing over lustre-MDT0000 [ 4425.917132] Lustre: server umount lustre-MDT0000 complete [ 4427.246492] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4434.620908] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4434.732425] LustreError: MGC192.168.206.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4435.050471] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4438.333150] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4438.793427] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4440.044142] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4440.050409] Lustre: Skipped 3 previous similar messages [ 4440.070662] Lustre: lustre-MDT0000: Recovery over after 0:02, of 2 clients 2 recovered and 0 were evicted. [ 4440.130975] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:167 to 0x2c0000401:257) [ 4440.131494] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:355 to 0x280000401:385) [ 4446.815165] Lustre: DEBUG MARKER: == sanity-lfsck test 31e: Re-generate the lost slave LMV EA for striped directory (1) ========================================================== 20:19:15 (1787444355) [ 4459.626388] Lustre: DEBUG MARKER: == sanity-lfsck test 31f: Re-generate the lost slave LMV EA for striped directory (2) ========================================================== 20:19:28 (1787444368) [ 4475.017666] Lustre: DEBUG MARKER: == sanity-lfsck test 31g: Repair the corrupted slave LMV EA ========================================================== 20:19:43 (1787444383) [ 4514.063807] Lustre: DEBUG MARKER: == sanity-lfsck test 31h: Repair the corrupted shard's name entry ========================================================== 20:20:22 (1787444422) [ 4515.421884] Lustre: *** cfs_fail_loc=162c, val=0*** [ 4515.425944] Lustre: Skipped 13 previous similar messages [ 4528.288942] Lustre: DEBUG MARKER: == sanity-lfsck test 32a: stop LFSCK when some OST failed ========================================================== 20:20:37 (1787444437) [ 4537.807519] LustreError: 148296:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d sleeping for 3000ms [ 4540.899784] Lustre: Failing over lustre-OST0000 [ 4540.908472] LustreError: 148296:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d awake [ 4540.917460] LustreError: 148296:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d sleeping for 3000ms [ 4541.233342] Lustre: server umount lustre-OST0000 complete [ 4541.407890] LustreError: lustre-OST0000-osc-MDT0001: operation ost_statfs to node 0@lo failed: rc = -107 [ 4541.424901] 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 [ 4541.442528] Lustre: Skipped 4 previous similar messages [ 4544.001732] LustreError: 148296:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d awake [ 4544.012198] LustreError: 148296:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d sleeping for 3000ms [ 4544.343317] LustreError: 148296:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout interrupted [ 4556.725160] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 4556.971280] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 4558.379946] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4558.421511] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 4558.424577] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 4558.447576] Lustre: Skipped 3 previous similar messages [ 4564.606812] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4572.476333] Lustre: DEBUG MARKER: == sanity-lfsck test 32b: stop LFSCK when some MDT failed ========================================================== 20:21:21 (1787444481) [ 4585.451136] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing load_modules_local [ 4603.021063] Lustre: 151100:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 4624.624994] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4628.146886] Lustre: 152233:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 4639.627985] LustreError: 152346:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d sleeping for 3000ms [ 4642.601945] Lustre: Failing over lustre-MDT0001 [ 4642.719167] LustreError: 152345:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d awake [ 4642.731448] LustreError: lustre-MDT0001-osp-MDT0000: operation out_update to node 0@lo failed: rc = -107 [ 4642.743727] Lustre: lustre-MDT0001-osp-MDT0000: Connection to lustre-MDT0001 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 4642.765450] Lustre: Skipped 1 previous similar message [ 4642.769242] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 4642.775975] Lustre: Skipped 4 previous similar messages [ 4643.004812] Lustre: server umount lustre-MDT0001 complete [ 4644.321234] LustreError: 123809: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. [ 4644.344085] LustreError: 123809:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 27 previous similar messages [ 4645.768617] LustreError: 152345:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d awake [ 4645.783244] LustreError: 152345:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) Skipped 1 previous similar message [ 4657.410653] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 4657.805487] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 4657.812812] Lustre: Skipped 3 previous similar messages [ 4657.843351] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 4663.269034] Lustre: lustre-MDT0001-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 4663.281742] Lustre: Skipped 1 previous similar message [ 4663.286205] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4663.344309] Lustre: lustre-MDT0001: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4663.422705] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4663.438860] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:68 to 0x2c0000400:97) [ 4663.441146] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:71 to 0x280000400:97) [ 4672.036378] Lustre: DEBUG MARKER: == sanity-lfsck test 33: check LFSCK paramters =========== 20:23:00 (1787444580) [ 4685.433435] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing load_modules_local [ 4701.943411] Lustre: 155066:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 4722.327168] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4725.352526] Lustre: 156200:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 4727.476616] Lustre: 123809:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 257 < left 278, rollback = 2 [ 4727.482436] Lustre: 123809:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 1281 previous similar messages [ 4727.487437] Lustre: 123809:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 4727.497857] Lustre: 123809:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1281 previous similar messages [ 4727.503238] Lustre: 123809:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4727.508769] Lustre: 123809:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1281 previous similar messages [ 4727.513234] Lustre: 123809:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 4727.518696] Lustre: 123809:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1282 previous similar messages [ 4727.523655] Lustre: 123809:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 4727.528015] Lustre: 123809:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1282 previous similar messages [ 4727.535720] Lustre: 123809:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4727.541657] Lustre: 123809:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1282 previous similar messages [ 4742.441730] Lustre: DEBUG MARKER: == sanity-lfsck test 34: LFSCK can rebuild the lost agent object ========================================================== 20:24:11 (1787444651) [ 4743.761914] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_34 Only valid for ZFS backend [ 4745.518782] Lustre: DEBUG MARKER: == sanity-lfsck test 35: LFSCK can rebuild the lost agent entry ========================================================== 20:24:14 (1787444654) [ 4753.070432] Lustre: *** cfs_fail_loc=1631, val=0*** [ 4765.151842] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4765.160931] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4770.491798] Lustre: server umount lustre-MDT0000 complete [ 4773.492277] LustreError: 123794:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787444683 with bad export cookie 4216357983268179466 [ 4773.492948] LustreError: MGC192.168.206.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4773.504091] LustreError: 123794:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 3 previous similar messages [ 4773.816716] Lustre: server umount lustre-MDT0001 complete [ 4787.476909] Lustre: server umount lustre-OST0000 complete [ 4799.915269] Lustre: server umount lustre-OST0001 complete [ 4813.769968] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing load_modules_local [ 4823.235337] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4827.940867] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4836.418683] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4841.234397] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4844.226862] Lustre: 160097:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 4851.268448] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4857.767385] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4861.733305] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:71 to 0x280000400:129) [ 4866.972527] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4868.268718] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:412 to 0x2c0000401:449) [ 4868.315402] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:540 to 0x280000401:577) [ 4868.397856] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:68 to 0x2c0000400:129) [ 4873.560409] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4880.597620] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4883.977762] Lustre: 161968:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 4894.670139] Lustre: DEBUG MARKER: == sanity-lfsck test 36a: rebuild LOV EA for mirrored file (1) ========================================================== 20:26:43 (1787444803) [ 4896.562110] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36a needs >= 3 OSTs [ 4898.801501] Lustre: DEBUG MARKER: == sanity-lfsck test 36b: rebuild LOV EA for mirrored file (2) ========================================================== 20:26:47 (1787444807) [ 4900.962298] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36b needs >= 3 OSTs [ 4903.187528] Lustre: DEBUG MARKER: == sanity-lfsck test 36c: rebuild LOV EA for mirrored file (3) ========================================================== 20:26:51 (1787444811) [ 4905.105097] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36c needs >= 3 OSTs [ 4906.964794] Lustre: DEBUG MARKER: == sanity-lfsck test 37: LFSCK must skip a ORPHAN ======== 20:26:55 (1787444815) [ 4918.094809] Lustre: DEBUG MARKER: == sanity-lfsck test 38: LFSCK does not break foreign file and reverse is also true ========================================================== 20:27:07 (1787444827) [ 4932.210341] Lustre: DEBUG MARKER: == sanity-lfsck test 39: LFSCK does not break foreign dir and reverse is also true ========================================================== 20:27:20 (1787444840) [ 4945.591373] Lustre: DEBUG MARKER: == sanity-lfsck test 40a: LFSCK correctly fixes lmm_oi in composite layout ========================================================== 20:27:34 (1787444854) [ 4962.360360] Lustre: DEBUG MARKER: == sanity-lfsck test 41: SEL support in LFSCK ============ 20:27:50 (1787444870) [ 4984.379954] Lustre: DEBUG MARKER: == sanity-lfsck test 42: LFSCK repairs inconsistent MDT-object/OST-object encryption flags ========================================================== 20:28:12 (1787444892) [ 5018.194801] Lustre: *** cfs_fail_loc=1632, val=0*** [ 5035.220742] Lustre: DEBUG MARKER: == sanity-lfsck test 43: LFSCK does not loop endlessly on iget failure in scanning-phase1 ========================================================== 20:29:03 (1787444943) [ 5037.852726] Lustre: Failing over lustre-MDT0001 [ 5038.076462] Lustre: server umount lustre-MDT0001 complete [ 5041.641124] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 5041.653603] Lustre: lustre-MDT0001-osp-MDT0000: Connection to lustre-MDT0001 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 5041.675315] Lustre: Skipped 6 previous similar messages [ 5046.016633] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5046.401444] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 5046.401679] Lustre: lustre-MDT0001: Aborting client recovery [ 5046.415716] LustreError: 165768:0:(ldlm_lib.c:3029:target_stop_recovery_thread()) lustre-MDT0001: Aborting recovery [ 5046.425269] Lustre: 165792:0:(ldlm_lib.c:2429:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 5046.435393] Lustre: 165792:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0001: disconnect stale client b725d7e2-de16-40f7-81c3-2e3fad5cd87e@ [ 5046.443312] Lustre: lustre-MDT0001: disconnecting 2 stale clients [ 5046.450183] Lustre: lustre-MDT0001-osd: cancel update llog [0x240000400:0x1:0x0] [ 5046.461893] Lustre: lustre-MDT0000-osp-MDT0001: cancel update llog [0x200000401:0x1:0x0] [ 5046.502415] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:131 to 0x2c0000400:161) [ 5046.508788] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:71 to 0x280000400:161) [ 5050.914715] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5051.375966] Lustre: lustre-MDT0001-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 5051.391328] Lustre: Skipped 2 previous similar messages [ 5051.396887] LustreError: lustre-MDT0001-osp-MDT0000: This client was evicted by lustre-MDT0001; in progress operations using this service will fail. [ 5059.633509] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing wait_import_state FULL osp.lustre-MDT0001-os[pc]-MDT0000.*_server_uuid [ 5059.928897] Lustre: DEBUG MARKER: osp.lustre-MDT0001-os[pc]-MDT0000.*_server_uuid in FULL state after 0 sec [ 5065.826486] Lustre: DEBUG MARKER: == sanity-lfsck test 44: umount while lfsck is stopping == 20:29:34 (1787444974) [ 5073.366268] Lustre: *** cfs_fail_loc=1600, val=3*** [ 5076.578128] Lustre: Failing over lustre-MDT0000 [ 5076.962253] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 5076.968603] Lustre: server umount lustre-MDT0000 complete [ 5085.934983] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5086.070257] LustreError: MGC192.168.206.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5086.325356] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 5086.335763] Lustre: Skipped 2 previous similar messages [ 5087.548494] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 5090.787896] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5091.314396] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 5091.334607] Lustre: Skipped 2 previous similar messages [ 5091.369499] Lustre: lustre-MDT0000: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 5091.423719] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:621 to 0x280000401:641) [ 5091.425389] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:489 to 0x2c0000401:513) [ 5100.296747] Lustre: DEBUG MARKER: == sanity-lfsck test 45: LFSCK should fix UID/GID/PROJID of OST object ========================================================== 20:30:08 (1787445008) [ 5146.608391] Lustre: Failing over lustre-OST0000 [ 5146.706800] Lustre: server umount lustre-OST0000 complete [ 5153.192539] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: (null) [ 5157.858421] LustreError: 162682: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. [ 5157.883727] LustreError: 162682:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 37 previous similar messages [ 5165.095495] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5165.376776] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 5166.918651] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 5167.302078] Lustre: lustre-OST0000: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [ 5167.305117] Lustre: lustre-OST0000-osc-MDT0001: Connection restored to 0@lo (at 0@lo) [ 5167.323115] Lustre: Skipped 3 previous similar messages [ 5172.028326] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5179.422578] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing wait_import_state (FULL|IDLE) os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid 50 [ 5179.633476] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid in FULL state after 0 sec [ 5184.375971] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing wait_import_state (FULL|IDLE) os[cp].lustre-OST0000-osc-MDT0001.ost_server_uuid 50 [ 5184.621329] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0001.ost_server_uuid in FULL state after 0 sec [ 5190.237584] Lustre: DEBUG MARKER: oleg655-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0000-osc-ffff9ba809fb8800.ost_server_uuid 50 [ 5192.460138] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9ba809fb8800.ost_server_uuid in FULL state after 0 sec [ 5275.616438] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 5275.622937] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5275.627241] Lustre: Skipped 3 previous similar messages [ 5278.177564] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5278.185741] Lustre: Skipped 2 previous similar messages [ 5280.060717] Lustre: server umount lustre-MDT0000 complete [ 5287.754456] LustreError: 158938:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787445198 with bad export cookie 4216357983268262290 [ 5287.762458] LustreError: MGC192.168.206.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5287.773319] LustreError: 158938:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 5288.091352] Lustre: server umount lustre-MDT0001 complete [ 5303.775379] Lustre: 106691:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787445198/real 1787445198] req@ffff8f88f97b1180 x1874270095344384/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787445214 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5303.801361] 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 [ 5303.819941] Lustre: Skipped 12 previous similar messages [ 5307.871167] Lustre: 106689:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787445202/real 1787445202] req@ffff8f88c5c2ed80 x1874270095344768/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787445218 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5308.045536] Lustre: server umount lustre-OST0000 complete [ 5314.016091] Lustre: 106690:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787445208/real 1787445208] req@ffff8f88d06b0000 x1874270095345408/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787445224 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5314.053642] Lustre: 106690:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 5316.981483] Lustre: server umount lustre-OST0001 complete [ 5334.014506] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing unload_modules_local [ 5336.779098] Key type lgssc unregistered [ 5337.142823] LNet: 175461:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 5337.160853] LNetError: 175461:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 5337.175886] LNet: Removed LNI 192.168.206.155@tcp [ 5338.091151] Key type .llcrypt unregistered [ 5338.093412] Key type ._llcrypt unregistered [ 5360.622089] Key type ._llcrypt registered [ 5360.624436] Key type .llcrypt registered [ 5360.706620] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_hostid [ 5376.664240] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing load_modules_local [ 5377.459974] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 5377.520830] alg: No test for adler32 (adler32-zlib) [ 5378.636919] Lustre: Lustre: Build Version: 2.17.57_64_ga728441 [ 5378.935226] LNet: Added LNI 192.168.206.155@tcp [8/256/0/180] [ 5380.651649] Key type lgssc registered [ 5382.116218] Lustre: Echo OBD driver; http://www.lustre.org/ [ 5431.149739] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing load_modules_local [ 5445.130611] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 5445.165467] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5446.455555] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 5446.515168] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 5446.650106] Lustre: lustre-MDT0000: new disk, initializing [ 5446.777540] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 5446.809225] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 5451.031976] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5464.941782] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5465.033482] Lustre: 179914: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 [ 5465.112599] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 5465.119155] Lustre: Skipped 1 previous similar message [ 5465.214352] Lustre: lustre-MDT0001: new disk, initializing [ 5465.300789] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 5465.353959] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 5465.368179] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 5469.768326] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5474.454506] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 5484.984268] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5485.229580] Lustre: lustre-OST0000: new disk, initializing [ 5485.234509] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 5485.241725] Lustre: 181852:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 5485.319757] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 5486.372077] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 5486.390281] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 5486.457575] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 5491.883261] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5505.908695] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5506.021793] Lustre: lustre-OST0001: new disk, initializing [ 5506.027597] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 5506.047812] Lustre: 182878:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 5506.137346] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 5512.251414] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 5512.271586] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 5512.289095] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5512.369528] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 5524.558369] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5535.472772] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 5540.888849] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 20:37:29 (1787445449) === [ 5542.335685] Lustre: DEBUG MARKER: == sanity-lfsck test complete, duration 5220 sec ========= 20:37:31 (1787445451) [ 5544.178387] Lustre: DEBUG MARKER: === sanity-lfsck: start cleanup 20:37:32 (1787445452) === [ 5547.316962] Lustre: DEBUG MARKER: === sanity-lfsck: finish cleanup 20:37:36 (1787445456) === [ 5552.610226] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 5552.619503] 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 [ 5552.658815] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5553.122206] 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 [ 5557.502171] Lustre: server umount lustre-MDT0000 complete [ 5563.363538] LustreError: 179928: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. [ 5563.378837] LustreError: 179928:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 8 previous similar messages [ 5564.892832] LustreError: 183645:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787445475 with bad export cookie 631629340167140475 [ 5564.895891] LustreError: MGC192.168.206.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5564.900082] LustreError: 183645:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 5565.328416] Lustre: server umount lustre-MDT0001 complete [ 5583.841296] Lustre: 177077:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787445478/real 1787445478] req@ffff8f88d0e24000 x1874272231442432/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787445494 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5583.846385] Lustre: server umount lustre-OST0000 complete [ 5583.893051] 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 [ 5583.907722] Lustre: Skipped 2 previous similar messages [ 5584.863671] Lustre: 177079:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787445479/real 1787445479] req@ffff8f88d07b4700 x1874272231442688/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787445495 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5588.960155] Lustre: 177078:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787445483/real 1787445483] req@ffff8f88d0c2ea00 x1874272231442944/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787445499 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5591.071227] Lustre: 177078:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787445485/real 1787445485] req@ffff8f88d0c2e680 x1874272231443200/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787445501 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5593.631515] Lustre: server umount lustre-OST0001 complete [ 5611.221760] Lustre: DEBUG MARKER: oleg655-server.virtnet: executing unload_modules_local [ 5614.081580] Key type lgssc unregistered [ 5614.456416] LNet: 186356:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 5614.465286] LNetError: 186356:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 5614.481906] LNet: Removed LNI 192.168.206.155@tcp [ 5615.374334] Key type .llcrypt unregistered [ 5615.378313] Key type ._llcrypt unregistered