[ 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 540706699 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.001012] APIC: Switch to symmetric I/O mode setup [ 0.003373] x2apic enabled [ 0.004009] Switched APIC routing to physical x2apic. [ 0.005014] kvm-guest: setup PV IPIs [ 0.008590] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.009000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.009021] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.010012] pid_max: default: 32768 minimum: 301 [ 0.012138] LSM: Security Framework initializing [ 0.013057] Yama: becoming mindful. [ 0.014035] SELinux: Initializing. [ 0.015081] *** VALIDATE selinux *** [ 0.023285] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.028400] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.029162] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.030114] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.032117] *** VALIDATE tmpfs *** [ 0.034096] *** VALIDATE proc *** [ 0.035258] *** VALIDATE cgroup *** [ 0.036010] *** VALIDATE cgroup2 *** [ 0.037266] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.038163] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.039009] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.040032] Spectre V2 : User space: Vulnerable [ 0.041007] Speculative Store Bypass: Vulnerable [ 0.044281] debug: unmapping init [mem 0xffffffff85059000-0xffffffff85060fff] [ 0.046272] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.047728] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.048027] ... version: 2 [ 0.049010] ... bit width: 48 [ 0.050011] ... generic registers: 4 [ 0.051015] ... value mask: 0000ffffffffffff [ 0.052013] ... max period: 00007fffffffffff [ 0.053014] ... fixed-purpose events: 3 [ 0.054011] ... event mask: 000000070000000f [ 0.055297] rcu: Hierarchical SRCU implementation. [ 0.057763] smp: Bringing up secondary CPUs ... [ 0.058695] x86: Booting SMP configuration: [ 0.059038] .... node #0, CPUs: #1 #2 #3 [ 0.072075] smp: Brought up 1 node, 4 CPUs [ 0.074012] smpboot: Max logical packages: 1 [ 0.075012] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.114722] node 0 deferred pages initialised in 36ms [ 0.117233] devtmpfs: initialized [ 0.118273] x86/mm: Memory block size: 128MB [ 0.122505] gcov: version magic: 0x41383552 [ 0.126426] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.130089] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.133432] pinctrl core: initialized pinctrl subsystem [ 0.135197] [ 0.135820] ************************************************************* [ 0.138014] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.140012] ** ** [ 0.142012] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.145014] ** ** [ 0.147017] ** This means that this kernel is built to expose internal ** [ 0.149013] ** IOMMU data structures, which may compromise security on ** [ 0.152020] ** your system. ** [ 0.154018] ** ** [ 0.156024] ** If you see this message and you are not debugging the ** [ 0.158023] ** kernel, report this immediately to your vendor! ** [ 0.161013] ** ** [ 0.163013] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.165011] ************************************************************* [ 0.168734] NET: Registered protocol family 16 [ 0.170469] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.175068] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.179104] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.183522] cpuidle: using governor menu [ 0.184976] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.185539] PCI: Using configuration type 1 for base access [ 0.187151] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.198251] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.201097] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.207042] cryptd: max_cpu_qlen set to 1000 [ 0.212277] ACPI: Added _OSI(Module Device) [ 0.214017] ACPI: Added _OSI(Processor Device) [ 0.216011] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.217014] ACPI: Added _OSI(Processor Aggregator Device) [ 0.221000] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.229615] ACPI: Interpreter enabled [ 0.231055] ACPI: PM: (supports S0 S3 S4 S5) [ 0.233028] ACPI: Using IOAPIC for interrupt routing [ 0.234121] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.239069] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.251906] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.256049] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.261036] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.267076] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.271000] acpiphp: Slot [2] registered [ 0.271000] acpiphp: Slot [5] registered [ 0.273075] acpiphp: Slot [6] registered [ 0.274141] acpiphp: Slot [7] registered [ 0.275120] acpiphp: Slot [8] registered [ 0.276069] acpiphp: Slot [9] registered [ 0.276970] acpiphp: Slot [10] registered [ 0.278082] acpiphp: Slot [3] registered [ 0.280088] acpiphp: Slot [4] registered [ 0.281091] acpiphp: Slot [11] registered [ 0.283200] acpiphp: Slot [12] registered [ 0.284106] acpiphp: Slot [13] registered [ 0.286112] acpiphp: Slot [14] registered [ 0.288104] acpiphp: Slot [15] registered [ 0.289104] acpiphp: Slot [16] registered [ 0.291091] acpiphp: Slot [17] registered [ 0.292093] acpiphp: Slot [18] registered [ 0.293012] acpiphp: Slot [19] registered [ 0.294070] acpiphp: Slot [20] registered [ 0.295178] acpiphp: Slot [21] registered [ 0.297110] acpiphp: Slot [22] registered [ 0.298089] acpiphp: Slot [23] registered [ 0.300119] acpiphp: Slot [24] registered [ 0.303130] acpiphp: Slot [25] registered [ 0.305128] acpiphp: Slot [26] registered [ 0.306126] acpiphp: Slot [27] registered [ 0.308100] acpiphp: Slot [28] registered [ 0.309091] acpiphp: Slot [29] registered [ 0.311093] acpiphp: Slot [30] registered [ 0.313141] acpiphp: Slot [31] registered [ 0.315067] PCI host bridge to bus 0000:00 [ 0.317018] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.320023] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.322018] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.324027] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.328023] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.332033] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.335193] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.339203] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.341547] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.351886] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.358061] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.360014] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.363019] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.365013] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.367363] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.370867] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.374045] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.379009] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.386018] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.400016] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.406089] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.413042] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.421018] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.428020] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.447017] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.458156] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.479016] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.488015] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.507030] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.515174] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.521016] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.536017] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.560017] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.571431] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.579867] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.591021] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.603014] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.611629] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.623014] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.629015] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.649018] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 0.662382] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.670015] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.676016] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.689017] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 0.698681] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.705169] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.708369] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.711374] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.714226] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.719084] iommu: Default domain type: Passthrough [ 0.721293] SCSI subsystem initialized [ 0.722114] ACPI: bus type USB registered [ 0.723079] usbcore: registered new interface driver usbfs [ 0.724098] usbcore: registered new interface driver hub [ 0.726078] usbcore: registered new device driver usb [ 0.729176] pps_core: LinuxPPS API ver. 1 registered [ 0.730007] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.733077] PTP clock support registered [ 0.735106] EDAC MC: Ver: 3.0.0 [ 0.737124] PCI: Using ACPI for IRQ routing [ 0.739527] NetLabel: Initializing [ 0.741010] NetLabel: domain hash size = 128 [ 0.742007] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.744101] NetLabel: unlabeled traffic allowed by default [ 0.747065] vgaarb: loaded [ 0.749304] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.750014] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.755540] clocksource: Switched to clocksource kvm-clock [ 0.881071] VFS: Disk quotas dquot_6.6.0 [ 0.883075] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.886306] *** VALIDATE ramfs *** [ 0.887820] *** VALIDATE hugetlbfs *** [ 0.889602] pnp: PnP ACPI init [ 0.892331] pnp: PnP ACPI: found 6 devices [ 0.908409] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.912322] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.914700] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.917394] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.920227] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.922890] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.925979] NET: Registered protocol family 2 [ 0.928235] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.933100] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.936146] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.940926] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.943326] TCP: Hash tables configured (established 65536 bind 65536) [ 0.945134] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.947093] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.949287] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.951140] NET: Registered protocol family 1 [ 0.952725] RPC: Registered named UNIX socket transport module. [ 0.954340] RPC: Registered udp transport module. [ 0.955285] RPC: Registered tcp transport module. [ 0.956229] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.957734] NET: Registered protocol family 44 [ 0.958769] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.960119] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.961411] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.962772] PCI: CLS 0 bytes, default 64 [ 0.964584] Unpacking initramfs... [ 2.436580] debug: unmapping init [mem 0xffff9f1f3cc54000-0xffff9f1f3ffbffff] [ 2.440483] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.442637] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.445099] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 2.951559] Initialise system trusted keyrings [ 2.952556] Key type blacklist registered [ 2.957300] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.965174] zbud: loaded [ 2.969395] *** VALIDATE nfs *** [ 2.970646] *** VALIDATE nfs4 *** [ 2.972182] pstore: using deflate compression [ 2.974803] Platform Keyring initialized [ 3.066163] NET: Registered protocol family 38 [ 3.067785] Key type asymmetric registered [ 3.069451] Asymmetric key parser 'x509' registered [ 3.071125] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 3.074199] io scheduler mq-deadline registered [ 3.075929] io scheduler kyber registered [ 3.077248] io scheduler bfq registered [ 3.078773] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 3.081835] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 3.084485] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 3.087383] ACPI: Power Button [PWRF] [ 3.091840] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 3.099362] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 3.113430] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 3.120777] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 3.135334] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 3.164587] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.194722] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.198399] Non-volatile memory driver v1.3 [ 3.199596] Linux agpgart interface v0.103 [ 3.227197] virtio_blk virtio1: [vda] 150608 512-byte logical blocks (77.1 MB/73.5 MiB) [ 3.229337] vda: detected capacity change from 0 to 77111296 [ 3.243283] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.245398] vdb: detected capacity change from 0 to 1073741824 [ 3.258420] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.261331] vdc: detected capacity change from 0 to 2621440000 [ 3.274189] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.276653] vdd: detected capacity change from 0 to 2621440000 [ 3.291634] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.293732] vde: detected capacity change from 0 to 4294967296 [ 3.307860] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.310027] vdf: detected capacity change from 0 to 4294967296 [ 3.319029] libphy: Fixed MDIO Bus: probed [ 3.323298] usbcore: registered new interface driver usbserial_generic [ 3.325188] usbserial: USB Serial support registered for generic [ 3.326849] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.330637] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.332068] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.333931] mousedev: PS/2 mouse device common for all mice [ 3.335977] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.337496] rtc_cmos 00:05: RTC can wake from S4 [ 3.342050] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.345204] rtc_cmos 00:05: registered as rtc0 [ 3.347296] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.348543] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.354328] intel_pstate: CPU model not supported [ 3.357376] hid: raw HID events driver (C) Jiri Kosina [ 3.359552] usbcore: registered new interface driver usbhid [ 3.361558] usbhid: USB HID core driver [ 3.363204] drop_monitor: Initializing network drop monitor service [ 3.365743] Initializing XFRM netlink socket [ 3.367847] NET: Registered protocol family 10 [ 3.371796] Segment Routing with IPv6 [ 3.373232] NET: Registered protocol family 17 [ 3.375382] mpls_gso: MPLS GSO support [ 3.382482] RAS: Correctable Errors collector initialized. [ 3.384743] AVX version of gcm_enc/dec engaged. [ 3.386704] AES CTR mode by8 optimization enabled [ 3.472048] sched_clock: Marking stable (3472025647, 0)->(4370817755, -898792108) [ 3.474753] registered taskstats version 1 [ 3.476962] Loading compiled-in X.509 certificates [ 3.478454] zswap: loaded using pool lzo/zbud [ 3.502183] Key type big_key registered [ 3.517093] Key type encrypted registered [ 3.518783] ima: No TPM chip found, activating TPM-bypass! [ 3.521090] ima: Allocated hash algorithm: sha1 [ 3.522526] ima: No architecture policies found [ 3.523875] evm: Initialising EVM extended attributes: [ 3.525425] evm: security.selinux [ 3.526663] evm: security.ima [ 3.527858] evm: security.capability [ 3.528983] evm: HMAC attrs: 0x1 [ 3.531258] rtc_cmos 00:05: setting system clock to 2026-10-02 22:00:56 UTC (1790978456) [ 3.537984] debug: unmapping init [mem 0xffffffff86003000-0xffffffff861fffff] [ 3.540379] debug: unmapping init [mem 0xffffffff84d82000-0xffffffff85058fff] [ 3.548273] Write protecting the kernel read-only data: 28672k [ 3.551478] debug: unmapping init [mem 0xffffffff83403000-0xffffffff835fffff] [ 3.554243] debug: unmapping init [mem 0xffffffff83d14000-0xffffffff83dfffff] [ 3.589305] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 3.597652] systemd[1]: Detected virtualization kvm. [ 3.599533] systemd[1]: Detected architecture x86-64. [ 3.601252] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.628641] systemd[1]: No hostname configured. [ 3.630098] systemd[1]: Set hostname to . [ 3.631535] random: systemd: uninitialized urandom read (16 bytes read) [ 3.633922] systemd[1]: Initializing machine ID from random generator. [ 3.766826] random: systemd: uninitialized urandom read (16 bytes read) [ 3.769129] systemd[1]: Listening on Journal Socket. [ OK ] Listening on Journal Socket. [ 3.772944] random: systemd: uninitialized urandom read (16 bytes read) [ 3.775195] systemd[1]: Listening on udev Kernel Socket. [ OK ] Listening on udev Kernel Socket. [ 3.778524] systemd[1]: Reached target Swap. [ OK ] Reached target Swap. Starting Apply Kernel Variables... [ OK ] Listening on udev Control Socket. [ OK ] Reached target Timers. [ OK ] Reached target Slices. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. [ OK ] Started Memstrack Anylazing Service. [ OK ] Reached target Local File Systems. Starting Create Volatile Files and Directories... [ OK ] Listening on Journal Socket (/dev/log). Starting Journal Service... [ OK ] Reached target Sockets. Starting Setup Virtual Console... Starting Create list of required st…ce nodes for the current kernel... [ OK ] Reached target Initrd Root Device. [ OK ] Started Apply Kernel Variables. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Setup Virtual Console. [ OK ] Started Create list of required sta…vice nodes for the current kernel. Starting Create Static Device Nodes in /dev... Starting dracut cmdline hook... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started Journal Service. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 4.476385] device-mapper: uevent: version 1.0.3 [ 4.479092] 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 [ 5.259427] random: fast init done ] Started udev Coldplug all Devices. Starting dracut initqueue hook... [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ 5.349961] virtio_net virtio0 ens2: renamed from eth0 [ 5.881591] scsi host0: ata_piix [ 5.982747] scsi host1: ata_piix [ 5.984217] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 5.986333] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 9.935743] dracut-initqueue[583]: RTNETLINK answers: File exists [ 11.041965] random: crng init done [ 11.043390] random: 7 urandom warning(s) missed due to ratelimiting 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... [ 11.564918] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped target Timers. [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Sockets. [ OK ] Stopped target Slices. [ OK ] Stopped target System Initialization. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped target Swap. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. Stopping udev Kernel Device Manager... [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped target Paths. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Closed udev Kernel Socket. [ OK ] Closed udev Control Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 13.069778] printk: systemd: 26 output lines suppressed due to ratelimiting [ 13.335756] SELinux: Disabled at runtime. [ 13.396256] 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) [ 13.404254] systemd[1]: Detected virtualization kvm. [ 13.405946] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 13.919127] systemd[1]: initrd-switch-root.service: Succeeded. [ 13.921246] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 13.928989] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 13.932854] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 13.935464] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 13.949577] systemd[1]: Starting Journal Service... Starting Journal Service... [ 13.971165] systemd[1]: Starting Create list of required static device nodes for the current kernel... Starting Create list of required st…ce nodes for the current kernel... [ OK ] Started Dispatch Password Requests to Console Directory Watch. Starting Apply Kernel Variables... Mounting POSIX Message Queue File System... Starting Remount Root and Kernel File Systems... [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Reached target RPC Port Mapper. Activating swap /dev/disk/by-label/SWAP... [ 14.085680] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS [ OK ] Listening on Process Core Dump Socket. [ OK ] Created slice User and Session Slice. [ OK ] Reached target Slices. [ 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 rpc_pipefs.target. [ OK ] Reached target Paths. [ OK ] Listening on udev Control Socket. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd File Systems. [ OK ] Stopped target Initrd Root File System. Mounting Kernel Debug File System... [ OK ] Created slice system-getty.slice. [ OK ] Listening on udev Kernel Socket. Starting udev Coldplug all Devices... Mounting Huge Pages File System... [ OK ] Started Journal Service. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Apply Kernel Variables. [ OK ] Mounted POSIX Message Queue File System. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Mounted Kernel Debug File System. [ OK ] Mounted Huge Pages File System. [ 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. Starting udev Kernel Device Manager... [ OK ] Reached target Local File Systems (Pre). Mounting /home/green/git/lustre-release... Mounting /mnt... [ OK ] Started udev Coldplug all Devices. [ OK ] Mounted /mnt. [ 14.549459] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 15.144128] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 15.157587] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 15.248787] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 15.712519] EDAC sbridge: Ver: 1.1.2 [ 17.386779] Key type dns_resolver registered [ 17.696773] NFS: Registering the id_resolver key type [ 17.698600] Key type id_resolver registered [ 17.700150] Key type id_legacy registered [ OK ] Started Configure read-only root support. Starting Load/Save Random Seed... [ OK ] Reached target Local File Systems. Starting Mark the need to relabel after reboot... Starting Rebuild Dynamic Linker Cache... Starting Create Volatile Files and Directories... [ OK ] Started Load/Save Random Seed. [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Create Volatile Files and Directories. Starting RPC Bind... Starting Update UTMP about System Boot/Shutdown... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Started dnf makecache --timer. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Reached target Timers. [ OK ] Reached target Basic System. [ OK ] Started D-Bus System Message Bus. Starting Network Manager... Starting Login Service... Starting Restore /run/initramfs on shutdown... [ OK ] Started irqbalance daemon. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Reached target sshd-keygen.target. [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Login Service. [ OK ] Started Network Manager. Starting Network Manager Wait Online... [ OK ] Reached target Network. Starting GSSAPI Proxy Daemon... Starting Dynamic System Tuning Daemon... Starting OpenSSH server daemon... [ OK ] Started GSSAPI Proxy Daemon. Starting Hostname Service... [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... [ OK ] Started OpenSSH server daemon. [ OK ] Started Permit User Sessions. [ OK ] Started Serial Getty on ttyS1. [ OK ] Started Command Scheduler. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Getty on tty1. [ OK ] Reached target Login Prompts. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting Notify NFS peers of a restart... Starting System Logging Service... Starting Crash recovery kernel arming... [ 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 oleg252-server login: [ 28.837017] hrtimer: interrupt took 2077330 ns [ 74.510879] libcfs: loading out-of-tree module taints kernel. [ 74.570208] Key type ._llcrypt registered [ 74.575469] Key type .llcrypt registered [ 74.674475] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_hostid [ 96.200995] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing load_modules_local [ 97.291978] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 97.302269] alg: No test for adler32 (adler32-zlib) [ 98.598834] Lustre: Lustre: Build Version: 2.17.59_2_ge06ed12 [ 99.399710] LNet: Added LNI 192.168.202.152@tcp [8/256/0/180] [ 101.071184] Key type lgssc registered [ 103.137513] Lustre: Echo OBD driver; http://www.lustre.org/ [ 121.592094] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 169.618510] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing load_modules_local [ 184.934530] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' or install '{/usr}/sbin/mount.lustre_tgt' [ 184.952167] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 186.268095] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 186.303626] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 186.418934] Lustre: lustre-MDT0000: new disk, initializing [ 186.534116] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 186.561248] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 192.510229] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 207.542573] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 207.671758] Lustre: 6510: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 [ 207.701422] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 207.707191] Lustre: Skipped 1 previous similar message [ 207.785851] Lustre: lustre-MDT0001: new disk, initializing [ 207.885510] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 207.926791] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 207.933548] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 213.153454] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 218.661951] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 229.419950] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 229.774213] Lustre: lustre-OST0000: new disk, initializing [ 229.776635] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 229.779805] Lustre: 8446:0:(osd_compat.c:1354:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 229.843630] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 229.917799] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 229.934655] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 230.133912] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 238.458952] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 255.954514] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 256.067583] Lustre: lustre-OST0001: new disk, initializing [ 256.072732] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 256.077395] Lustre: 9517:0:(osd_compat.c:1354:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 256.147344] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 263.873226] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 265.233439] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 265.244094] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 265.308469] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 279.272526] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 288.396499] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 295.717996] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing check_logdir /tmp/testlogs/ [ 301.414385] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing yml_node [ 306.862731] Lustre: DEBUG MARKER: Client: 2.17.59.2 [ 310.555803] Lustre: DEBUG MARKER: MDS: 2.17.59.2 [ 313.702793] Lustre: DEBUG MARKER: OSS: 2.17.59.2 [ 315.389223] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity-lfsck ============----- Fri Oct 2 18:06:07 EDT 2026 [ 334.990720] Lustre: DEBUG MARKER: excepting tests: 18b 23b [ 346.240123] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing load_modules_local [ 356.321614] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 356.332304] 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 [ 356.348097] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 357.344402] 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 [ 357.344943] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 357.371302] Lustre: Skipped 2 previous similar messages [ 357.396660] Lustre: Skipped 3 previous similar messages [ 360.417778] Lustre: server umount lustre-MDT0000 complete [ 367.585411] LustreError: 6517:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 367.606682] LustreError: 6517:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 5 previous similar messages [ 370.764133] LustreError: 8445:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1790978823 with bad export cookie 8015691151042305402 [ 370.767637] LustreError: MGC192.168.202.152@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 370.778697] LustreError: 8445:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 371.090499] Lustre: server umount lustre-MDT0001 complete [ 389.023182] Lustre: 3640:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790978825/real 1790978825] req@ffff9f1fbf0d9500 x1877977126252160/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1790978841 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 389.063353] 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 [ 391.138984] Lustre: 3642:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790978828/real 1790978828] req@ffff9f1fa792f800 x1877977126252416/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1790978844 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 391.349931] Lustre: server umount lustre-OST0000 complete [ 393.187582] Lustre: 3640:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790978830/real 1790978830] req@ffff9f1e82a0d500 x1877977126252672/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1790978846 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 396.320811] Lustre: 3642:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790978833/real 1790978833] req@ffff9f1fbf0db480 x1877977126253056/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1790978849 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 401.504604] Lustre: 3642:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790978838/real 1790978838] req@ffff9f1fbf0d8000 x1877977126253312/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1790978854 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 401.841965] Lustre: server umount lustre-OST0001 complete [ 421.076421] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing unload_modules_local [ 424.356725] Key type lgssc unregistered [ 424.685467] LNet: 14794:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 424.692845] LNetError: 14794:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 424.714084] LNet: Removed LNI 192.168.202.152@tcp [ 425.838464] Key type .llcrypt unregistered [ 425.840898] Key type ._llcrypt unregistered [ 452.684582] Key type ._llcrypt registered [ 452.691176] Key type .llcrypt registered [ 452.846367] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_hostid [ 470.262263] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing load_modules_local [ 472.170399] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 472.345035] alg: No test for adler32 (adler32-zlib) [ 473.596120] Lustre: Lustre: Build Version: 2.17.59_2_ge06ed12 [ 473.871349] LNet: Added LNI 192.168.202.152@tcp [8/256/0/180] [ 475.551732] Key type lgssc registered [ 477.125632] Lustre: Echo OBD driver; http://www.lustre.org/ [ 529.403633] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing load_modules_local [ 544.153534] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' or install '{/usr}/sbin/mount.lustre_tgt' [ 544.207506] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 545.513747] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 545.557711] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 545.639780] Lustre: lustre-MDT0000: new disk, initializing [ 545.816066] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 545.848782] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 550.595381] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 566.168581] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 566.298693] Lustre: 19265: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 [ 566.319778] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 566.328159] Lustre: Skipped 1 previous similar message [ 566.386968] Lustre: lustre-MDT0001: new disk, initializing [ 566.443265] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 566.488424] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 566.499389] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 571.557393] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 576.381387] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 586.455364] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 586.686648] Lustre: lustre-OST0000: new disk, initializing [ 586.692055] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 586.698642] Lustre: 21202:0:(osd_compat.c:1354:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 586.805317] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 593.432847] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 593.444919] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 593.532726] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 593.735779] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 609.445476] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 609.533369] Lustre: lustre-OST0001: new disk, initializing [ 609.535930] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 609.540168] Lustre: 22225:0:(osd_compat.c:1354:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 609.601639] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 615.502898] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 615.531687] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 615.577048] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 617.880727] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 631.091197] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 642.467866] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 651.343638] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 18:11:43 (1790979103) === [ 654.285222] Lustre: DEBUG MARKER: == sanity-lfsck test 0: Control LFSCK manually =========== 18:11:46 (1790979106) [ 654.491262] Lustre: 19271:0:(osd_internal.h:1462:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 251 < left 292, rollback = 2 [ 654.501038] Lustre: 19271:0:(osd_handler.c:2097:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 654.506416] Lustre: 19271:0:(osd_handler.c:2104:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 5/292/0 [ 654.513246] Lustre: 19271:0:(osd_handler.c:2114:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 654.518336] Lustre: 19271:0:(osd_handler.c:2121:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 654.520909] Lustre: 19271:0:(osd_handler.c:2128:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 655.023931] Lustre: 19273:0:(osd_internal.h:1462:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 292, rollback = 2 [ 655.030065] Lustre: 19273:0:(osd_internal.h:1462:osd_trans_exec_op()) Skipped 20 previous similar messages [ 655.033801] Lustre: 19273:0:(osd_handler.c:2097:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 655.037675] Lustre: 19273:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 20 previous similar messages [ 655.041889] Lustre: 19273:0:(osd_handler.c:2104:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 5/292/0 [ 655.046134] Lustre: 19273:0:(osd_handler.c:2104:osd_trans_dump_creds()) Skipped 20 previous similar messages [ 655.048635] Lustre: 19273:0:(osd_handler.c:2114:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 655.052729] Lustre: 19273:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 20 previous similar messages [ 655.056943] Lustre: 19273:0:(osd_handler.c:2121:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 655.060667] Lustre: 19273:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 20 previous similar messages [ 655.063511] Lustre: 19273:0:(osd_handler.c:2128:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 655.066165] Lustre: 19273:0:(osd_handler.c:2128:osd_trans_dump_creds()) Skipped 20 previous similar messages [ 656.034664] Lustre: 19272:0:(osd_internal.h:1462:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 292, rollback = 2 [ 656.040809] Lustre: 19272:0:(osd_internal.h:1462:osd_trans_exec_op()) Skipped 74 previous similar messages [ 656.049671] Lustre: 19272:0:(osd_handler.c:2097:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 656.058932] Lustre: 19272:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 74 previous similar messages [ 656.065174] Lustre: 19272:0:(osd_handler.c:2104:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 5/292/0 [ 656.071964] Lustre: 19272:0:(osd_handler.c:2104:osd_trans_dump_creds()) Skipped 74 previous similar messages [ 656.081832] Lustre: 19272:0:(osd_handler.c:2114:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 656.088990] Lustre: 19272:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 74 previous similar messages [ 656.097620] Lustre: 19272:0:(osd_handler.c:2121:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 656.102454] Lustre: 19272:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 74 previous similar messages [ 656.110027] Lustre: 19272:0:(osd_handler.c:2128:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 656.115318] Lustre: 19272:0:(osd_handler.c:2128:osd_trans_dump_creds()) Skipped 74 previous similar messages [ 658.160653] Lustre: 19272:0:(osd_internal.h:1462:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 292, rollback = 2 [ 658.168962] Lustre: 19272:0:(osd_internal.h:1462:osd_trans_exec_op()) Skipped 116 previous similar messages [ 658.180287] Lustre: 19272:0:(osd_handler.c:2097:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 658.188181] Lustre: 19272:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 116 previous similar messages [ 658.199380] Lustre: 19272:0:(osd_handler.c:2104:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 5/292/0 [ 658.204805] Lustre: 19272:0:(osd_handler.c:2104:osd_trans_dump_creds()) Skipped 116 previous similar messages [ 658.211147] Lustre: 19272:0:(osd_handler.c:2114:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 658.220167] Lustre: 19272:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 116 previous similar messages [ 658.227599] Lustre: 19272:0:(osd_handler.c:2121:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 658.234144] Lustre: 19272:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 116 previous similar messages [ 658.240333] Lustre: 19272:0:(osd_handler.c:2128:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 658.250635] Lustre: 19272:0:(osd_handler.c:2128:osd_trans_dump_creds()) Skipped 116 previous similar messages [ 660.711533] Lustre: *** cfs_fail_loc=1600, val=3*** [ 663.775313] Lustre: *** cfs_fail_loc=1600, val=3*** [ 665.261243] Lustre: 21191:0:(osd_internal.h:1462:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 259 < left 274, rollback = 2 [ 665.284358] Lustre: 21191:0:(osd_internal.h:1462:osd_trans_exec_op()) Skipped 61 previous similar messages [ 665.287452] Lustre: 21191:0:(osd_handler.c:2097:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 665.297177] Lustre: 23718:0:(osd_handler.c:2104:osd_trans_dump_creds()) attr_set: 1/1/1, xattr_set: 2/274/0 [ 665.302555] Lustre: 21191:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 62 previous similar messages [ 665.302581] Lustre: 21191:0:(osd_handler.c:2114:osd_trans_dump_creds()) write: 0/0/0, punch: 0/0/0, quota 7/225/0 [ 665.302584] Lustre: 21191:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 61 previous similar messages [ 665.302589] Lustre: 21191:0:(osd_handler.c:2121:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 665.302593] Lustre: 21191:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 61 previous similar messages [ 665.302598] Lustre: 21191:0:(osd_handler.c:2128:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 665.302600] Lustre: 21191:0:(osd_handler.c:2128:osd_trans_dump_creds()) Skipped 61 previous similar messages [ 665.400592] Lustre: 23718:0:(osd_handler.c:2104:osd_trans_dump_creds()) Skipped 67 previous similar messages [ 666.036120] Lustre: *** cfs_fail_loc=1600, val=3*** [ 682.472838] 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 [ 682.480929] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 682.516967] Lustre: Skipped 3 previous similar messages [ 682.528565] Lustre: Skipped 2 previous similar messages [ 686.837261] Lustre: server umount lustre-MDT0000 complete [ 691.060615] LustreError: 19257:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1790979144 with bad export cookie 9541755454548573069 [ 691.080068] LustreError: MGC192.168.202.152@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 691.081836] LustreError: 19257:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 3 previous similar messages [ 691.337628] Lustre: server umount lustre-MDT0001 complete [ 705.806794] Lustre: server umount lustre-OST0000 complete [ 708.063937] Lustre: 16415:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790979145/real 1790979145] req@ffff9f1e8a0ed180 x1877977518424192/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1790979161 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 708.122797] 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 [ 710.216390] Lustre: server umount lustre-OST0001 complete [ 719.962101] Lustre: DEBUG MARKER: == sanity-lfsck test 1a: LFSCK can find out and repair crashed FID-in-dirent ========================================================== 18:12:51 (1790979171) [ 735.900292] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing load_modules_local [ 748.337527] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 748.932511] LustreError: 26239:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 748.947928] LustreError: 26239:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 5 previous similar messages [ 749.089548] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 754.150138] LustreError: 26240:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 754.189355] LustreError: 26240:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 1 previous similar message [ 755.101861] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 758.249691] LustreError: 26239:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 763.367905] LustreError: 26240:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 764.694371] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 764.914238] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 771.976462] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 776.483272] Lustre: 27380:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 785.094853] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 785.579590] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 789.729765] LustreError: 27734:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 792.854969] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 793.848255] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:40 to 0x280000401:65) [ 799.200774] LustreError: 27733:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 799.226669] LustreError: 27733:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 3 previous similar messages [ 802.347052] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 807.922260] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:41 to 0x2c0000401:65) [ 809.848833] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 817.359810] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 821.620306] Lustre: 29250:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 823.459580] Lustre: 26235:0:(osd_internal.h:1462:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 292, rollback = 2 [ 823.475857] Lustre: 26235:0:(osd_internal.h:1462:osd_trans_exec_op()) Skipped 71 previous similar messages [ 823.494337] Lustre: 26235:0:(osd_handler.c:2097:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 823.518285] Lustre: 26235:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 70 previous similar messages [ 823.544915] Lustre: 26235:0:(osd_handler.c:2104:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 5/292/0 [ 823.559624] Lustre: 26235:0:(osd_handler.c:2104:osd_trans_dump_creds()) Skipped 65 previous similar messages [ 823.575622] Lustre: 26235:0:(osd_handler.c:2114:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 823.584940] Lustre: 26235:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 71 previous similar messages [ 823.597354] Lustre: 26235:0:(osd_handler.c:2121:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 823.611836] Lustre: 26235:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 71 previous similar messages [ 823.626964] Lustre: 26235:0:(osd_handler.c:2128:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 823.637920] Lustre: 26235:0:(osd_handler.c:2128:osd_trans_dump_creds()) Skipped 71 previous similar messages [ 829.729637] Lustre: *** cfs_fail_loc=1501, val=0*** [ 839.513761] Lustre: Failing over lustre-MDT0000 [ 839.709500] Lustre: server umount lustre-MDT0000 complete [ 841.699099] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 841.702315] 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 [ 841.750438] LustreError: 26972:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 843.764403] 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 [ 843.798485] Lustre: Skipped 2 previous similar messages [ 854.423400] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 854.606040] LustreError: MGC192.168.202.152@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 854.930413] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 854.937364] Lustre: Skipped 1 previous similar message [ 854.979107] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 860.142644] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 860.152148] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 860.213907] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 860.303711] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:105 to 0x2c0000401:129) [ 860.305154] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:105 to 0x280000401:129) [ 860.748790] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 865.420683] Lustre: *** cfs_fail_loc=1505, val=0*** [ 873.107387] Lustre: DEBUG MARKER: == sanity-lfsck test 1b: LFSCK can find out and repair the missing FID-in-LMA ========================================================== 18:15:25 (1790979325) [ 874.643300] Lustre: 26235:0:(osd_internal.h:1462:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 292, rollback = 2 [ 874.659230] Lustre: 26235:0:(osd_internal.h:1462:osd_trans_exec_op()) Skipped 322 previous similar messages [ 874.666262] Lustre: 26235:0:(osd_handler.c:2097:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 874.675195] Lustre: 26235:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 874.680947] Lustre: 26235:0:(osd_handler.c:2104:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 5/292/0 [ 874.689563] Lustre: 26235:0:(osd_handler.c:2104:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 874.696049] Lustre: 26235:0:(osd_handler.c:2114:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 874.703614] Lustre: 26235:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 874.718623] Lustre: 26235:0:(osd_handler.c:2121:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 874.727987] Lustre: 26235:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 874.740345] Lustre: 26235:0:(osd_handler.c:2128:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 874.745748] Lustre: 26235:0:(osd_handler.c:2128:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 880.595308] Lustre: *** cfs_fail_loc=1502, val=0*** [ 891.696711] Lustre: Failing over lustre-MDT0000 [ 892.245298] Lustre: server umount lustre-MDT0000 complete [ 895.968363] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 895.971181] 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 [ 895.981106] LustreError: 26236:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 895.981118] LustreError: 26236:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 12 previous similar messages [ 896.016339] Lustre: Skipped 2 previous similar messages [ 904.009324] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 904.085802] LustreError: MGC192.168.202.152@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 904.321941] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 909.283246] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 909.288916] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 909.311034] Lustre: Skipped 3 previous similar messages [ 909.334055] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 909.453864] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:169 to 0x2c0000401:193) [ 909.454640] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:169 to 0x280000401:193) [ 910.112742] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 913.799604] Lustre: *** cfs_fail_loc=1505, val=0*** [ 921.206807] Lustre: DEBUG MARKER: == sanity-lfsck test 1c: LFSCK can find out and repair lost FID-in-dirent ========================================================== 18:16:13 (1790979373) [ 922.197934] Lustre: 26236:0:(osd_internal.h:1462:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 252 < left 292, rollback = 2 [ 922.215396] Lustre: 26236:0:(osd_internal.h:1462:osd_trans_exec_op()) Skipped 322 previous similar messages [ 922.221153] Lustre: 26236:0:(osd_handler.c:2097:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 922.225450] Lustre: 26236:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 922.230875] Lustre: 26236:0:(osd_handler.c:2104:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 5/292/0 [ 922.236427] Lustre: 26236:0:(osd_handler.c:2104:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 922.244118] Lustre: 26236:0:(osd_handler.c:2114:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/1 [ 922.256542] Lustre: 26236:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 922.265547] Lustre: 26236:0:(osd_handler.c:2121:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 922.279220] Lustre: 26236:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 922.290729] Lustre: 26236:0:(osd_handler.c:2128:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 922.301939] Lustre: 26236:0:(osd_handler.c:2128:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 927.023722] Lustre: *** cfs_fail_loc=1504, val=0*** [ 927.026342] Lustre: *** cfs_fail_loc=1504, val=0*** [ 927.028420] Lustre: Skipped 1 previous similar message [ 935.627620] Lustre: Failing over lustre-MDT0000 [ 935.891385] Lustre: server umount lustre-MDT0000 complete [ 940.002509] 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 [ 940.019186] Lustre: Skipped 4 previous similar messages [ 940.029422] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 949.445805] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 949.577287] LustreError: MGC192.168.202.152@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 949.928548] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 949.937322] Lustre: Skipped 1 previous similar message [ 949.985264] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 955.076332] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 955.371475] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 955.373421] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 955.391767] Lustre: Skipped 3 previous similar messages [ 955.453635] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 955.497920] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:233 to 0x2c0000401:257) [ 955.501221] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:233 to 0x280000401:257) [ 958.528395] Lustre: *** cfs_fail_loc=1505, val=0*** [ 965.697402] Lustre: DEBUG MARKER: == sanity-lfsck test 2a: LFSCK can find out and repair crashed linkEA entry ========================================================== 18:16:57 (1790979417) [ 972.369270] Lustre: *** cfs_fail_loc=1603, val=0*** [ 982.427472] Lustre: Failing over lustre-MDT0000 [ 982.760400] Lustre: server umount lustre-MDT0000 complete [ 986.086567] 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 [ 986.121945] LustreError: 26972:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 986.157113] LustreError: 26972:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 18 previous similar messages [ 994.490623] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 994.625715] LustreError: MGC192.168.202.152@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 994.944784] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 999.907051] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 999.910028] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 999.950102] Lustre: Skipped 3 previous similar messages [ 999.995031] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1000.117488] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:297 to 0x2c0000401:321) [ 1000.119678] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:297 to 0x280000401:321) [ 1001.275141] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1012.389547] Lustre: DEBUG MARKER: == sanity-lfsck test 2b: LFSCK can find out and remove invalid linkEA entry ========================================================== 18:17:44 (1790979464) [ 1014.373446] Lustre: 26236:0:(osd_internal.h:1462:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 292, rollback = 2 [ 1014.376221] Lustre: 26236:0:(osd_internal.h:1462:osd_trans_exec_op()) Skipped 644 previous similar messages [ 1014.380763] Lustre: 26236:0:(osd_handler.c:2097:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 1014.384395] Lustre: 26236:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 1014.387494] Lustre: 26236:0:(osd_handler.c:2104:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 5/292/0 [ 1014.392568] Lustre: 26236:0:(osd_handler.c:2104:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 1014.395802] Lustre: 26236:0:(osd_handler.c:2114:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 1014.405925] Lustre: 26236:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 1014.421168] Lustre: 26236:0:(osd_handler.c:2121:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 1014.427486] Lustre: 26236:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 1014.435467] Lustre: 26236:0:(osd_handler.c:2128:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 1014.443020] Lustre: 26236:0:(osd_handler.c:2128:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 1021.313086] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1031.157434] Lustre: Failing over lustre-MDT0000 [ 1031.421693] Lustre: server umount lustre-MDT0000 complete [ 1035.743463] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1035.746435] 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 [ 1035.764123] Lustre: Skipped 3 previous similar messages [ 1043.751093] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1044.061970] LustreError: MGC192.168.202.152@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1044.570283] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1049.557942] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1049.569117] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1049.586067] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 1049.592345] Lustre: Skipped 3 previous similar messages [ 1049.621879] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1049.665451] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:361 to 0x280000401:385) [ 1049.670391] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:361 to 0x2c0000401:385) [ 1060.828447] Lustre: DEBUG MARKER: == sanity-lfsck test 2c: LFSCK can find out and remove repeated linkEA entry ========================================================== 18:18:32 (1790979512) [ 1066.825596] Lustre: *** cfs_fail_loc=1605, val=0*** [ 1078.303343] Lustre: Failing over lustre-MDT0000 [ 1078.829897] Lustre: server umount lustre-MDT0000 complete [ 1080.300020] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1088.912416] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1089.118259] LustreError: MGC192.168.202.152@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1089.464834] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1089.467479] Lustre: Skipped 2 previous similar messages [ 1089.508909] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1094.629188] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1094.645967] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1094.651132] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1094.684270] Lustre: Skipped 3 previous similar messages [ 1094.724124] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1094.791060] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:425 to 0x2c0000401:449) [ 1094.793589] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:425 to 0x280000401:449) [ 1104.108720] Lustre: DEBUG MARKER: == sanity-lfsck test 2d: LFSCK can recover the missing linkEA entry ========================================================== 18:19:16 (1790979556) [ 1110.921928] Lustre: *** cfs_fail_loc=161d, val=0*** [ 1119.562325] Lustre: Failing over lustre-MDT0000 [ 1120.163727] Lustre: server umount lustre-MDT0000 complete [ 1120.223830] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1120.226616] Lustre: lustre-MDT0000-lwp-OST0001: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 1120.233573] LustreError: 26240:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1120.233584] LustreError: 26240:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 20 previous similar messages [ 1120.264346] Lustre: Skipped 10 previous similar messages [ 1131.419635] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1131.514490] LustreError: MGC192.168.202.152@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1131.722844] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1136.588767] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1137.123790] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1137.148438] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1137.161297] Lustre: Skipped 3 previous similar messages [ 1137.176856] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1137.222547] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:489 to 0x2c0000401:513) [ 1137.230657] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:489 to 0x280000401:513) [ 1147.162807] Lustre: DEBUG MARKER: == sanity-lfsck test 2e: namespace LFSCK can verify remote object linkEA ========================================================== 18:19:59 (1790979599) [ 1148.581718] Lustre: 29017:0:(osd_internal.h:1462:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 292, rollback = 2 [ 1148.589071] Lustre: 29017:0:(osd_internal.h:1462:osd_trans_exec_op()) Skipped 967 previous similar messages [ 1148.594581] Lustre: 29017:0:(osd_handler.c:2097:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 1148.600337] Lustre: 29017:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 967 previous similar messages [ 1148.605692] Lustre: 29017:0:(osd_handler.c:2104:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 5/292/0 [ 1148.609760] Lustre: 29017:0:(osd_handler.c:2104:osd_trans_dump_creds()) Skipped 967 previous similar messages [ 1148.613114] Lustre: 29017:0:(osd_handler.c:2114:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 1148.616434] Lustre: 29017:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 967 previous similar messages [ 1148.620322] Lustre: 29017:0:(osd_handler.c:2121:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 1148.623191] Lustre: 29017:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 967 previous similar messages [ 1148.626434] Lustre: 29017:0:(osd_handler.c:2128:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 1148.631417] Lustre: 29017:0:(osd_handler.c:2128:osd_trans_dump_creds()) Skipped 967 previous similar messages [ 1150.002465] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1161.435166] Lustre: DEBUG MARKER: == sanity-lfsck test 3: LFSCK can verify multiple-linked objects ========================================================== 18:20:13 (1790979613) [ 1166.578627] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1167.455493] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1177.981724] Lustre: DEBUG MARKER: == sanity-lfsck test 4: FID-in-dirent can be rebuilt after MDT file-level backup/restore ========================================================== 18:20:30 (1790979630) [ 1212.616963] Lustre: Failing over lustre-MDT0000 [ 1212.890701] Lustre: server umount lustre-MDT0000 complete [ 1213.929967] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1218.487822] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1228.662166] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1229.279580] Lustre: 16415:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790979666/real 1790979666] req@ffff9f1e84475180 x1877977519054336/t0(0) o400->MGC192.168.202.152@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1790979682 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1229.320958] LustreError: MGC192.168.202.152@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1240.611345] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1240.633053] Lustre: lustre-MDT0000: reset Object Index mappings [ 1255.312724] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1260.306693] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1260.515088] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1260.530138] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1260.538415] Lustre: Skipped 3 previous similar messages [ 1260.587129] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1260.625903] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:592 to 0x280000401:609) [ 1260.626167] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:592 to 0x2c0000401:609) [ 1264.437743] LustreError: 42907:0:(lfsck_engine.c:1018:lfsck_master_engine()) lustre-MDT0000-osd: master engine fail to verify the .lustre/lost+found/, go ahead: rc = -115 [ 1264.457276] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1268.576880] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1268.583892] Lustre: Skipped 3 previous similar messages [ 1274.953468] Lustre: Failing over lustre-MDT0000 [ 1275.872181] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1275.875298] 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 [ 1275.917013] Lustre: Skipped 6 previous similar messages [ 1277.638290] Lustre: server umount lustre-MDT0000 complete [ 1290.414785] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1295.937220] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:592 to 0x2c0000401:641) [ 1295.946283] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:592 to 0x280000401:641) [ 1296.028312] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1300.036633] Lustre: *** cfs_fail_loc=1505, val=0*** [ 1307.445604] Lustre: DEBUG MARKER: == sanity-lfsck test 5: LFSCK can handle IGIF object upgrading ========================================================== 18:22:39 (1790979759) [ 1309.617261] Lustre: *** cfs_fail_loc=1504, val=0*** [ 1320.598820] Lustre: Failing over lustre-MDT0000 [ 1320.994979] Lustre: server umount lustre-MDT0000 complete [ 1326.444626] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1336.451424] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1337.833196] Lustre: 16414:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790979774/real 1790979774] req@ffff9f1fb98f5f80 x1877977519156224/t0(0) o400->MGC192.168.202.152@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1790979790 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1347.879569] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1347.896134] Lustre: lustre-MDT0000: reset Object Index mappings [ 1363.431474] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x846b20081205d1ab [ 1363.445783] Lustre: MGC192.168.202.152@tcp: Connection restored to 0@lo (at 0@lo) [ 1363.458061] Lustre: Skipped 7 previous similar messages [ 1363.713947] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1363.721711] Lustre: Skipped 3 previous similar messages [ 1363.764348] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1363.780310] Lustre: Skipped 1 previous similar message [ 1368.231113] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1369.068868] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1369.083098] Lustre: Skipped 1 previous similar message [ 1369.102094] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1369.112690] Lustre: Skipped 1 previous similar message [ 1369.173857] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:681 to 0x2c0000401:705) [ 1369.174758] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:681 to 0x280000401:705) [ 1371.425651] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1384.164516] Lustre: Failing over lustre-MDT0000 [ 1384.343832] Lustre: server umount lustre-MDT0000 complete [ 1384.425469] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1384.436841] LustreError: 26235:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1384.458357] LustreError: 26235:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 104 previous similar messages [ 1394.399935] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1394.523450] LustreError: MGC192.168.202.152@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1394.541777] LustreError: Skipped 2 previous similar messages [ 1394.657735] Lustre: lustre-MDT0000: Not available for connect from 0@lo (not set up) [ 1394.663634] Lustre: Skipped 3 previous similar messages [ 1398.914528] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1400.355742] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:681 to 0x280000401:737) [ 1400.357910] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:681 to 0x2c0000401:737) [ 1401.889104] Lustre: *** cfs_fail_loc=1505, val=0*** [ 1401.891917] Lustre: Skipped 84 previous similar messages [ 1409.256740] Lustre: DEBUG MARKER: == sanity-lfsck test 6a: LFSCK resumes from last checkpoint (1) ========================================================== 18:24:21 (1790979861) [ 1410.883952] Lustre: 43483:0:(osd_internal.h:1462:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 292, rollback = 2 [ 1410.890093] Lustre: 43483:0:(osd_internal.h:1462:osd_trans_exec_op()) Skipped 924 previous similar messages [ 1410.894018] Lustre: 43483:0:(osd_handler.c:2097:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 1410.898832] Lustre: 43483:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 924 previous similar messages [ 1410.903395] Lustre: 43483:0:(osd_handler.c:2104:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 5/292/0 [ 1410.907530] Lustre: 43483:0:(osd_handler.c:2104:osd_trans_dump_creds()) Skipped 924 previous similar messages [ 1410.913524] Lustre: 43483:0:(osd_handler.c:2114:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 1410.920914] Lustre: 43483:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 924 previous similar messages [ 1410.925958] Lustre: 43483:0:(osd_handler.c:2121:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 1410.928746] Lustre: 43483:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 924 previous similar messages [ 1410.933594] Lustre: 43483:0:(osd_handler.c:2128:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 1410.938506] Lustre: 43483:0:(osd_handler.c:2128:osd_trans_dump_creds()) Skipped 924 previous similar messages [ 1416.807271] Lustre: *** cfs_fail_loc=1600, val=1*** [ 1416.809073] Lustre: Skipped 8 previous similar messages [ 1440.098946] Lustre: DEBUG MARKER: == sanity-lfsck test 6b: LFSCK resumes from last checkpoint (2) ========================================================== 18:24:52 (1790979892) [ 1449.055173] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1449.057093] Lustre: Skipped 11 previous similar messages [ 1472.632789] Lustre: DEBUG MARKER: == sanity-lfsck test 7a: non-stopped LFSCK should auto restarts after MDS remount (1) ========================================================== 18:25:24 (1790979924) [ 1487.619769] Lustre: Failing over lustre-MDT0000 [ 1487.895991] Lustre: server umount lustre-MDT0000 complete [ 1498.690994] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1499.222536] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1499.233908] Lustre: Skipped 1 previous similar message [ 1504.232571] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1504.242275] Lustre: Skipped 1 previous similar message [ 1504.251045] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1504.259095] Lustre: Skipped 8 previous similar messages [ 1504.292024] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1504.311222] Lustre: Skipped 1 previous similar message [ 1504.379381] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:853 to 0x280000401:897) [ 1504.381993] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:854 to 0x2c0000401:897) [ 1504.702654] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1515.780522] Lustre: DEBUG MARKER: == sanity-lfsck test 7b: non-stopped LFSCK should auto restarts after MDS remount (2) ========================================================== 18:26:07 (1790979967) [ 1529.748586] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing load_modules_local [ 1549.801128] Lustre: 53027:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 1572.317921] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1575.967670] Lustre: 54165:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 1582.035675] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1582.037478] Lustre: Skipped 81 previous similar messages [ 1584.508674] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1585.574376] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1586.591263] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1588.642152] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1588.647433] Lustre: Skipped 1 previous similar message [ 1588.954095] Lustre: Failing over lustre-MDT0000 [ 1589.456323] Lustre: server umount lustre-MDT0000 complete [ 1591.269727] 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 [ 1591.291695] Lustre: Skipped 14 previous similar messages [ 1599.616176] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1604.691607] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1605.152952] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:946 to 0x2c0000401:961) [ 1605.155096] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:947 to 0x280000401:993) [ 1614.078300] Lustre: DEBUG MARKER: == sanity-lfsck test 8: LFSCK state machine ============== 18:27:46 (1790980066) [ 1620.447980] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1620.456237] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1620.459384] LustreError: Skipped 1 previous similar message [ 1620.477160] Lustre: Skipped 3 previous similar messages [ 1625.570309] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1625.582291] Lustre: Skipped 3 previous similar messages [ 1630.175250] Lustre: lustre-MDT0000 is waiting for obd_unlinked_exports more than 8 seconds. The obd refcount = 3. Is it stuck? [ 1630.380519] Lustre: server umount lustre-MDT0000 complete [ 1634.358507] LustreError: 27382:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1790980087 with bad export cookie 9541755454548786303 [ 1634.369679] LustreError: 27382:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 1634.995956] Lustre: server umount lustre-MDT0001 complete [ 1650.065076] Lustre: server umount lustre-OST0000 complete [ 1651.180675] Lustre: 16413:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790980088/real 1790980088] req@ffff9f1fbb451180 x1877977519483776/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1790980104 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1653.840321] Lustre: server umount lustre-OST0001 complete [ 1661.031270] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_hostid [ 1671.772612] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing load_modules_local [ 1720.029569] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing load_modules_local [ 1730.992952] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1731.241531] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 1731.269306] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 1731.401662] Lustre: lustre-MDT0000: new disk, initializing [ 1731.515502] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 1735.201760] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1744.988152] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1745.094779] Lustre: 59223: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 [ 1745.119296] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 1745.126914] Lustre: Skipped 1 previous similar message [ 1745.202382] Lustre: lustre-MDT0001: new disk, initializing [ 1745.281285] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 1745.285519] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 1749.017564] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1753.654784] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 1759.425161] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 1759.719711] Lustre: lustre-OST0000: new disk, initializing [ 1759.723829] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 1759.739970] Lustre: 60858:0:(osd_compat.c:1354:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 1761.184235] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 1761.198585] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 1761.264378] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 1765.612208] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1775.906083] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 1776.124443] Lustre: lustre-OST0001: new disk, initializing [ 1776.133202] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 1776.146942] Lustre: 61729:0:(osd_compat.c:1354:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 1777.776290] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 1777.786346] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 1777.871723] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 1783.066761] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1792.967731] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1796.915730] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 1807.928489] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1809.137499] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1809.140606] Lustre: Skipped 19 previous similar messages [ 1814.233628] Lustre: *** cfs_fail_loc=1601, val=2*** [ 1814.242688] Lustre: Skipped 17 previous similar messages [ 1832.172816] Lustre: Failing over lustre-MDT0000 [ 1832.569630] Lustre: server umount lustre-MDT0000 complete [ 1842.500628] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1842.692350] LustreError: MGC192.168.202.152@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1842.713188] LustreError: Skipped 3 previous similar messages [ 1843.191270] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1843.201839] Lustre: Skipped 1 previous similar message [ 1848.290409] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1848.297887] Lustre: Skipped 1 previous similar message [ 1848.313444] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 1848.325099] Lustre: Skipped 7 previous similar messages [ 1848.368746] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1848.380728] Lustre: Skipped 1 previous similar message [ 1848.422686] Lustre: *** cfs_fail_loc=160b, val=2*** [ 1848.429763] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:65) [ 1848.432106] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:65) [ 1849.048481] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1858.214600] Lustre: Failing over lustre-MDT0000 [ 1858.557483] Lustre: server umount lustre-MDT0000 complete [ 1868.126142] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1873.451910] Lustre: *** cfs_fail_loc=160b, val=2*** [ 1873.464703] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:97) [ 1873.465574] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:97) [ 1873.510034] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1878.931142] Lustre: Failing over lustre-MDT0000 [ 1879.107411] Lustre: server umount lustre-MDT0000 complete [ 1883.618635] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1883.632443] LustreError: Skipped 2 previous similar messages [ 1887.483705] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1887.949995] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1887.964596] Lustre: Skipped 9 previous similar messages [ 1893.163513] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1893.407513] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:129) [ 1893.407615] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:129) [ 1898.344979] Lustre: *** cfs_fail_loc=1602, val=2*** [ 1910.139326] Lustre: DEBUG MARKER: == sanity-lfsck test 9a: LFSCK speed control (1) ========= 18:32:42 (1790980362) [ 1923.484288] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing load_modules_local [ 1942.535132] Lustre: 68684:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 1964.561989] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1968.815428] Lustre: 69819:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 1976.488414] Lustre: 62256:0:(osd_internal.h:1462:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 292, rollback = 2 [ 1976.494246] Lustre: 62256:0:(osd_internal.h:1462:osd_trans_exec_op()) Skipped 2759 previous similar messages [ 1976.498921] Lustre: 62256:0:(osd_handler.c:2097:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 1976.507342] Lustre: 62256:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 2759 previous similar messages [ 1976.514419] Lustre: 62256:0:(osd_handler.c:2104:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 5/292/0 [ 1976.519876] Lustre: 62256:0:(osd_handler.c:2104:osd_trans_dump_creds()) Skipped 2759 previous similar messages [ 1976.525558] Lustre: 62256:0:(osd_handler.c:2114:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 1976.532282] Lustre: 62256:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 2759 previous similar messages [ 1976.538110] Lustre: 62256:0:(osd_handler.c:2121:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 1976.542943] Lustre: 62256:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 2759 previous similar messages [ 1976.547373] Lustre: 62256:0:(osd_handler.c:2128:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 1976.553295] Lustre: 62256:0:(osd_handler.c:2128:osd_trans_dump_creds()) Skipped 2759 previous similar messages [ 2077.568793] Lustre: DEBUG MARKER: == sanity-lfsck test 9b: LFSCK speed control (2) ========= 18:35:29 (1790980529) [ 2116.531561] Lustre: *** cfs_fail_loc=1604, val=0*** [ 2116.536453] Lustre: Skipped 4 previous similar messages [ 2137.046915] Lustre: *** cfs_fail_loc=160c, val=0*** [ 2137.050972] Lustre: Skipped 7 previous similar messages [ 2172.376939] Lustre: DEBUG MARKER: == sanity-lfsck test 10: System is available during LFSCK scanning ========================================================== 18:37:04 (1790980624) [ 2210.867643] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2211.881795] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2211.885151] Lustre: Skipped 62 previous similar messages [ 2213.919742] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2213.922913] Lustre: Skipped 127 previous similar messages [ 2217.922008] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2217.923359] Lustre: Skipped 253 previous similar messages [ 2225.931940] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2225.935091] Lustre: Skipped 493 previous similar messages [ 2241.944411] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2241.948491] Lustre: Skipped 1013 previous similar messages [ 2267.463389] Lustre: *** cfs_fail_loc=1604, val=0*** [ 2267.466641] Lustre: Skipped 2599 previous similar messages [ 2486.725755] Lustre: DEBUG MARKER: == sanity-lfsck test 11a: LFSCK can rebuild lost last_id ========================================================== 18:42:19 (1790980939) [ 2610.169205] Lustre: 60390:0:(osd_internal.h:1462:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 292, rollback = 2 [ 2610.175784] Lustre: 60390:0:(osd_internal.h:1462:osd_trans_exec_op()) Skipped 36832 previous similar messages [ 2610.182612] Lustre: 60390:0:(osd_handler.c:2097:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 2610.188754] Lustre: 60390:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 36832 previous similar messages [ 2610.194157] Lustre: 60390:0:(osd_handler.c:2104:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 5/292/0 [ 2610.198859] Lustre: 60390:0:(osd_handler.c:2104:osd_trans_dump_creds()) Skipped 36832 previous similar messages [ 2610.204992] Lustre: 60390:0:(osd_handler.c:2114:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 2610.210528] Lustre: 60390:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 36832 previous similar messages [ 2610.215734] Lustre: 60390:0:(osd_handler.c:2121:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 2610.222877] Lustre: 60390:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 36832 previous similar messages [ 2610.229884] Lustre: 60390:0:(osd_handler.c:2128:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 2610.235775] Lustre: 60390:0:(osd_handler.c:2128:osd_trans_dump_creds()) Skipped 36832 previous similar messages [ 2620.383636] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 2620.384498] 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 [ 2620.385498] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2620.410539] Lustre: Skipped 22 previous similar messages [ 2622.314118] Lustre: server umount lustre-MDT0000 complete [ 2625.507047] LustreError: 70362:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 2625.530050] LustreError: 70362:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 50 previous similar messages [ 2625.944792] LustreError: 71854:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1790981078 with bad export cookie 9541755454548805406 [ 2625.953052] LustreError: MGC192.168.202.152@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2625.958263] LustreError: 71854:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 2625.967812] LustreError: Skipped 2 previous similar messages [ 2626.631148] Lustre: server umount lustre-MDT0001 complete [ 2640.255271] Lustre: server umount lustre-OST0000 complete [ 2653.311151] Lustre: server umount lustre-OST0001 complete [ 2659.901653] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: (null) [ 2669.055277] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 2684.832325] LustreError: Failed to get MGS log lustre-sptlrpc and no local copy. [ 2689.951405] LustreError: 74998:0:(mgc_request.c:233:do_config_log_add()) MGC192.168.202.152@tcp: failed processing log, type 4: rc = -110 [ 2715.615203] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 2722.588619] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2726.232582] Lustre: 75581: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. [ 2726.261609] Lustre: *** cfs_fail_loc=160e, val=3*** [ 2729.317648] Lustre: 75581:0:(ofd_dev.c:573:ofd_lfsck_out_notify()) lustre-OST0000: Rebuilt crashed LAST_ID files successfully. [ 2737.627821] Lustre: DEBUG MARKER: == sanity-lfsck test 11b: LFSCK can rebuild crashed last_id ========================================================== 18:46:30 (1790981190) [ 2752.194607] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing load_modules_local [ 2762.421322] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2762.966972] LustreError: 75023:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 2763.128376] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3271 to 0x280000401:3297) [ 2767.667348] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2775.246625] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2779.898715] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2782.942991] Lustre: 78249:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 2799.967424] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2805.761918] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3208 to 0x2c0000401:3233) [ 2807.932389] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2815.724429] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 2819.611559] Lustre: 79746:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 2823.965887] Lustre: *** cfs_fail_loc=160d, val=0*** [ 2824.512446] Lustre: *** cfs_fail_loc=160d, val=0*** [ 2824.516800] Lustre: Skipped 3 previous similar messages [ 2831.004904] Lustre: Failing over lustre-OST0000 [ 2831.094258] Lustre: server umount lustre-OST0000 complete [ 2839.326517] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2839.617724] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 2839.639059] Lustre: Skipped 2 previous similar messages [ 2841.057995] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 2841.066316] Lustre: Skipped 2 previous similar messages [ 2841.082228] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 2841.082244] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 2841.091448] Lustre: Skipped 2 previous similar messages [ 2841.098318] Lustre: *** cfs_fail_loc=215, val=0*** [ 2841.100890] Lustre: Skipped 11 previous similar messages [ 2846.060450] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2846.175851] Lustre: *** cfs_fail_loc=215, val=0*** [ 2846.180103] Lustre: Skipped 1 previous similar message [ 2850.427269] Lustre: 81144: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. [ 2850.441169] Lustre: 81144:0:(ofd_dev.c:573:ofd_lfsck_out_notify()) lustre-OST0000: Rebuilt crashed LAST_ID files successfully. [ 2851.297105] Lustre: *** cfs_fail_loc=215, val=0*** [ 2853.403086] Lustre: Failing over lustre-OST0000 [ 2853.522355] Lustre: server umount lustre-OST0000 complete [ 2863.649225] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2865.334865] Lustre: *** cfs_fail_loc=215, val=0*** [ 2865.343560] Lustre: Skipped 2 previous similar messages [ 2870.693122] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2870.752161] Lustre: *** cfs_fail_loc=215, val=0*** [ 2870.756106] Lustre: Skipped 1 previous similar message [ 2877.923106] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2877.925387] Lustre: Skipped 3 previous similar messages [ 2879.459037] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2879.463116] Lustre: Skipped 1 previous similar message [ 2883.609826] Lustre: server umount lustre-MDT0000 complete [ 2887.625982] LustreError: 75005:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1790981340 with bad export cookie 9541755454550372293 [ 2887.640638] LustreError: 75005:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 3 previous similar messages [ 2888.228827] Lustre: server umount lustre-MDT0001 complete [ 2901.339414] Lustre: server umount lustre-OST0000 complete [ 2915.590673] Lustre: server umount lustre-OST0001 complete [ 2924.710502] Lustre: DEBUG MARKER: == sanity-lfsck test 12a: single command to trigger LFSCK on all devices ========================================================== 18:49:36 (1790981376) [ 2938.470488] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing load_modules_local [ 2952.289586] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2953.517799] LustreError: 84390:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 2953.546982] LustreError: 84390:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 30 previous similar messages [ 2959.603136] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2967.695851] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2973.370633] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2976.926900] Lustre: 85530:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 2986.189517] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2994.797811] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2999.274830] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3362 to 0x280000401:3393) [ 3003.437611] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3009.016230] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3208 to 0x2c0000401:3265) [ 3010.834783] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3019.122665] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3022.862257] Lustre: 87401:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 3056.595256] Lustre: DEBUG MARKER: == sanity-lfsck test 12b: auto detect Lustre device ====== 18:51:48 (1790981508) [ 3071.540608] Lustre: DEBUG MARKER: == sanity-lfsck test 13: LFSCK can repair crashed lmm_oi ========================================================== 18:52:03 (1790981523) [ 3072.839158] Lustre: *** cfs_fail_loc=160f, val=0*** [ 3083.037549] Lustre: DEBUG MARKER: == sanity-lfsck test 14a: LFSCK can repair MDT-object with dangling LOV EA reference (1) ========================================================== 18:52:15 (1790981535) [ 3087.098742] Lustre: *** cfs_fail_loc=1610, val=0*** [ 3087.103331] Lustre: Skipped 3 previous similar messages [ 3136.996115] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3137.000772] Lustre: Skipped 3 previous similar messages [ 3141.008113] Lustre: server umount lustre-MDT0000 complete [ 3145.002328] LustreError: 84370:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1790981597 with bad export cookie 9541755454550380784 [ 3145.017393] LustreError: 84370:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 3145.297906] Lustre: server umount lustre-MDT0001 complete [ 3159.590851] Lustre: server umount lustre-OST0000 complete [ 3163.430804] Lustre: 16413:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790981600/real 1790981600] req@ffff9f1e8b4a1500 x1877977523536384/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1790981616 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3163.849521] Lustre: server umount lustre-OST0001 complete [ 3180.765342] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing load_modules_local [ 3191.358211] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3196.065914] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3204.261416] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3210.412818] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3213.706557] Lustre: 93271:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3219.821578] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3227.481233] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3229.292544] LustreError: 93627:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3229.310165] LustreError: 93627:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 13 previous similar messages [ 3229.319719] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:116 to 0x280000400:161) [ 3236.246344] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3237.557553] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:116 to 0x2c0000400:161) [ 3237.557624] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3554 to 0x280000401:3585) [ 3237.576571] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3317 to 0x2c0000401:3361) [ 3242.737665] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3250.866404] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3255.247632] Lustre: 95141:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 3262.673045] Lustre: DEBUG MARKER: == sanity-lfsck test 14b: LFSCK can repair MDT-object with dangling LOV EA reference (2) ========================================================== 18:55:15 (1790981715) [ 3264.764339] Lustre: 92126:0:(osd_internal.h:1462:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 256 < left 292, rollback = 2 [ 3264.776222] Lustre: 92126:0:(osd_internal.h:1462:osd_trans_exec_op()) Skipped 1361 previous similar messages [ 3264.786929] Lustre: 92126:0:(osd_handler.c:2097:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 3264.798579] Lustre: 92126:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1361 previous similar messages [ 3264.804407] Lustre: 92126:0:(osd_handler.c:2104:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 5/292/0 [ 3264.816109] Lustre: 92126:0:(osd_handler.c:2104:osd_trans_dump_creds()) Skipped 1361 previous similar messages [ 3264.823410] Lustre: 92126:0:(osd_handler.c:2114:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 3264.832838] Lustre: 92126:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1361 previous similar messages [ 3264.838301] Lustre: 92126:0:(osd_handler.c:2121:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 3264.842069] Lustre: 92126:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1361 previous similar messages [ 3264.849795] Lustre: 92126:0:(osd_handler.c:2128:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3264.856936] Lustre: 92126:0:(osd_handler.c:2128:osd_trans_dump_creds()) Skipped 1361 previous similar messages [ 3268.903955] Lustre: *** cfs_fail_loc=1610, val=0*** [ 3268.907555] Lustre: Skipped 63 previous similar messages [ 3292.138426] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3292.161026] LustreError: Skipped 2 previous similar messages [ 3292.165354] 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 [ 3292.174289] Lustre: Skipped 13 previous similar messages [ 3292.185514] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3292.193356] Lustre: Skipped 1 previous similar message [ 3297.621333] Lustre: server umount lustre-MDT0000 complete [ 3300.617872] LustreError: 95143:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1790981753 with bad export cookie 9541755454550409176 [ 3300.620226] LustreError: MGC192.168.202.152@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3300.626734] LustreError: 95143:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 3300.631884] LustreError: Skipped 2 previous similar messages [ 3300.866410] Lustre: server umount lustre-MDT0001 complete [ 3313.868711] Lustre: server umount lustre-OST0000 complete [ 3327.491134] Lustre: server umount lustre-OST0001 complete [ 3346.900952] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing load_modules_local [ 3358.956570] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3359.556867] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3359.566824] Lustre: Skipped 13 previous similar messages [ 3364.787355] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3373.583076] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3379.174434] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3382.151313] Lustre: 99176:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3389.336317] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3396.040168] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3398.840174] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:116 to 0x280000400:193) [ 3405.310189] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3682 to 0x280000401:3713) [ 3406.332665] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3411.979130] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3317 to 0x2c0000401:3393) [ 3411.991594] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:116 to 0x2c0000400:193) [ 3413.836810] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3422.075270] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3434.064386] Lustre: DEBUG MARKER: == sanity-lfsck test 15a: LFSCK can repair unmatched MDT-object/OST-object pairs (1) ========================================================== 18:58:06 (1790981886) [ 3437.291928] Lustre: *** cfs_fail_loc=1611, val=0*** [ 3437.297145] Lustre: Skipped 63 previous similar messages [ 3437.566588] Lustre: *** cfs_fail_loc=1611, val=0*** [ 3447.930633] Lustre: DEBUG MARKER: == sanity-lfsck test 15b: LFSCK can repair unmatched MDT-object/OST-object pairs (2) ========================================================== 18:58:20 (1790981900) [ 3449.973254] Lustre: *** cfs_fail_loc=1612, val=0*** [ 3450.033930] Lustre: *** cfs_fail_loc=1612, val=0*** [ 3450.038377] Lustre: Skipped 2 previous similar messages [ 3460.998657] Lustre: DEBUG MARKER: == sanity-lfsck test 15c: LFSCK can repair unmatched MDT-object/OST-object pairs (3) ========================================================== 18:58:33 (1790981913) [ 3462.969623] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_15c MDS newer than 2.7.55, LU-6475 [ 3464.825455] Lustre: DEBUG MARKER: == sanity-lfsck test 15d: LFSCK don't crash upon dir migration failure ========================================================== 18:58:36 (1790981916) [ 3471.518485] Lustre: *** cfs_fail_loc=1709, val=0*** [ 3471.524921] LustreError: 98043:0:(mdt_reint.c:2656:mdt_reint_migrate()) lustre-MDT0000: migrate [0x240002340:0x6c:0x0]/f21 failed: rc = -5 [ 3474.929268] Lustre: *** cfs_fail_loc=1709, val=0*** [ 3537.889487] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3537.896615] Lustre: Skipped 4 previous similar messages [ 3544.006181] Lustre: server umount lustre-MDT0000 complete [ 3551.630056] LustreError: 98017:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1790982004 with bad export cookie 9541755454550423904 [ 3551.643091] LustreError: 98017:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 3551.964616] Lustre: server umount lustre-MDT0001 complete [ 3571.556288] Lustre: server umount lustre-OST0000 complete [ 3571.679967] Lustre: 16415:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790982008/real 1790982008] req@ffff9f1e8a7c1f80 x1877977524225536/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1790982024 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3576.872296] Lustre: 16416:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790982013/real 1790982013] req@ffff9f1e8a7c1180 x1877977524226048/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1790982029 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3576.904745] Lustre: 16416:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 3581.040679] Lustre: server umount lustre-OST0001 complete [ 3599.600533] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing unload_modules_local [ 3602.206165] Key type lgssc unregistered [ 3602.503876] LNet: 104880:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 3602.519501] LNetError: 104880:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 3602.547249] LNet: Removed LNI 192.168.202.152@tcp [ 3603.731167] Key type .llcrypt unregistered [ 3603.735416] Key type ._llcrypt unregistered [ 3626.431494] Key type ._llcrypt registered [ 3626.433178] Key type .llcrypt registered [ 3626.548415] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_hostid [ 3640.598762] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing load_modules_local [ 3642.309203] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 3642.507394] alg: No test for adler32 (adler32-zlib) [ 3643.871243] Lustre: Lustre: Build Version: 2.17.59_2_ge06ed12 [ 3644.225847] LNet: Added LNI 192.168.202.152@tcp [8/256/0/180] [ 3645.895931] Key type lgssc registered [ 3647.242812] Lustre: Echo OBD driver; http://www.lustre.org/ [ 3691.791354] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing load_modules_local [ 3704.369796] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' or install '{/usr}/sbin/mount.lustre_tgt' [ 3704.393904] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3705.623759] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 3705.650223] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 3705.736356] Lustre: lustre-MDT0000: new disk, initializing [ 3705.798669] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3705.839949] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 3710.255204] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3722.489495] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3722.585061] Lustre: 109347: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 [ 3722.646177] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 3722.663130] Lustre: Skipped 1 previous similar message [ 3722.761392] Lustre: lustre-MDT0001: new disk, initializing [ 3722.839460] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 3722.868401] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 3722.890915] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 3727.340600] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3732.357169] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 3741.901425] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3742.227331] Lustre: lustre-OST0000: new disk, initializing [ 3742.232221] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 3742.242834] Lustre: 111284:0:(osd_compat.c:1354:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 3742.346886] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 3744.210181] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 3744.228262] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 3744.295769] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 3748.058897] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3762.060731] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3762.265380] Lustre: lustre-OST0001: new disk, initializing [ 3762.272767] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 3762.285960] Lustre: 112308:0:(osd_compat.c:1354:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 3762.393169] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 3768.693576] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3769.865871] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 3769.869376] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 3769.926304] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 3780.163844] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3784.855946] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 3789.882471] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 19:04:02 (1790982242) === [ 3795.978403] Lustre: DEBUG MARKER: == sanity-lfsck test 16: LFSCK can repair inconsistent MDT-object/OST-object owner ========================================================== 19:04:08 (1790982248) [ 3796.170576] Lustre: 109354:0:(osd_internal.h:1462:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 251 < left 292, rollback = 2 [ 3796.177433] Lustre: 109354:0:(osd_handler.c:2097:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 3796.183624] Lustre: 109354:0:(osd_handler.c:2104:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 5/292/0 [ 3796.186718] Lustre: 109354:0:(osd_handler.c:2114:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 3796.190213] Lustre: 109354:0:(osd_handler.c:2121:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 3796.193204] Lustre: 109354:0:(osd_handler.c:2128:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3796.674356] Lustre: 112916:0:(osd_internal.h:1462:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 292, rollback = 2 [ 3796.682442] Lustre: 112916:0:(osd_internal.h:1462:osd_trans_exec_op()) Skipped 18 previous similar messages [ 3796.687369] Lustre: 112916:0:(osd_handler.c:2097:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 3796.691376] Lustre: 112916:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 18 previous similar messages [ 3796.696628] Lustre: 112916:0:(osd_handler.c:2104:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 5/292/0 [ 3796.700602] Lustre: 112916:0:(osd_handler.c:2104:osd_trans_dump_creds()) Skipped 18 previous similar messages [ 3796.705859] Lustre: 112916:0:(osd_handler.c:2114:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 7/369/0 [ 3796.710956] Lustre: 112916:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 18 previous similar messages [ 3796.716764] Lustre: 112916:0:(osd_handler.c:2121:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 3796.720845] Lustre: 112916:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 18 previous similar messages [ 3796.725464] Lustre: 112916:0:(osd_handler.c:2128:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3796.729751] Lustre: 112916:0:(osd_handler.c:2128:osd_trans_dump_creds()) Skipped 18 previous similar messages [ 3797.691771] Lustre: 109352:0:(osd_internal.h:1462:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 292, rollback = 2 [ 3797.697759] Lustre: 109352:0:(osd_internal.h:1462:osd_trans_exec_op()) Skipped 215 previous similar messages [ 3797.702569] Lustre: 109352:0:(osd_handler.c:2097:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 3797.707316] Lustre: 109352:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 215 previous similar messages [ 3797.711563] Lustre: 109352:0:(osd_handler.c:2104:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 5/292/0 [ 3797.722192] Lustre: 109352:0:(osd_handler.c:2104:osd_trans_dump_creds()) Skipped 215 previous similar messages [ 3797.727881] Lustre: 109352:0:(osd_handler.c:2114:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 7/369/0 [ 3797.734223] Lustre: 109352:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 215 previous similar messages [ 3797.738393] Lustre: 109352:0:(osd_handler.c:2121:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 3797.743681] Lustre: 109352:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 215 previous similar messages [ 3797.768508] Lustre: 109352:0:(osd_handler.c:2128:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3797.779802] Lustre: 109352:0:(osd_handler.c:2128:osd_trans_dump_creds()) Skipped 215 previous similar messages [ 3799.037920] Lustre: *** cfs_fail_loc=1613, val=0*** [ 3810.286996] Lustre: DEBUG MARKER: == sanity-lfsck test 17: LFSCK can repair multiple references ========================================================== 19:04:22 (1790982262) [ 3811.360475] Lustre: 112916:0:(osd_internal.h:1462:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 256 < left 292, rollback = 2 [ 3811.368184] Lustre: 112916:0:(osd_internal.h:1462:osd_trans_exec_op()) Skipped 74 previous similar messages [ 3811.376664] Lustre: 112916:0:(osd_handler.c:2097:osd_trans_dump_creds()) create: 1/4/2, destroy: 0/0/0 [ 3811.383225] Lustre: 112916:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 74 previous similar messages [ 3811.388286] Lustre: 112916:0:(osd_handler.c:2104:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 5/292/0 [ 3811.397718] Lustre: 112916:0:(osd_handler.c:2104:osd_trans_dump_creds()) Skipped 74 previous similar messages [ 3811.408220] Lustre: 112916:0:(osd_handler.c:2114:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 3811.415469] Lustre: 112916:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 74 previous similar messages [ 3811.424923] Lustre: 112916:0:(osd_handler.c:2121:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 3811.432672] Lustre: 112916:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 74 previous similar messages [ 3811.441033] Lustre: 112916:0:(osd_handler.c:2128:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3811.455398] Lustre: 112916:0:(osd_handler.c:2128:osd_trans_dump_creds()) Skipped 74 previous similar messages [ 3812.646746] Lustre: *** cfs_fail_loc=1614, val=0*** [ 3817.310294] Lustre: 111274:0:(osd_internal.h:1462:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 259 < left 275, rollback = 2 [ 3817.319936] Lustre: 111274:0:(osd_internal.h:1462:osd_trans_exec_op()) Skipped 11 previous similar messages [ 3817.328288] Lustre: 111274:0:(osd_handler.c:2097:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 3817.338852] Lustre: 111274:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3817.348721] Lustre: 111274:0:(osd_handler.c:2104:osd_trans_dump_creds()) attr_set: 1/1/1, xattr_set: 3/275/0 [ 3817.361145] Lustre: 111274:0:(osd_handler.c:2104:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3817.367454] Lustre: 111274:0:(osd_handler.c:2114:osd_trans_dump_creds()) write: 1/9/0, punch: 1/4/0, quota 7/225/0 [ 3817.378278] Lustre: 111274:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3817.394257] Lustre: 111274:0:(osd_handler.c:2121:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 3817.399800] Lustre: 111274:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3817.417870] Lustre: 111274:0:(osd_handler.c:2128:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3817.429792] Lustre: 111274:0:(osd_handler.c:2128:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3824.128136] Lustre: DEBUG MARKER: == sanity-lfsck test 18a: Find out orphan OST-object and repair it (1) ========================================================== 19:04:36 (1790982276) [ 3825.864489] Lustre: *** cfs_fail_loc=1615, val=0*** [ 3825.871840] Lustre: Skipped 1 previous similar message [ 3826.876545] Lustre: *** cfs_fail_loc=1615, val=0*** [ 3826.883954] Lustre: Skipped 1 previous similar message [ 3844.699756] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_18b skipping excluded test 18b [ 3846.350949] Lustre: DEBUG MARKER: == sanity-lfsck test 18c: Find out orphan OST-object and repair it (3) ========================================================== 19:04:58 (1790982298) [ 3846.773530] Lustre: 109352:0:(osd_internal.h:1462:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 292, rollback = 2 [ 3846.782313] Lustre: 109352:0:(osd_internal.h:1462:osd_trans_exec_op()) Skipped 23 previous similar messages [ 3846.788831] Lustre: 109352:0:(osd_handler.c:2097:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 3846.795601] Lustre: 109352:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 23 previous similar messages [ 3846.802640] Lustre: 109352:0:(osd_handler.c:2104:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 5/292/0 [ 3846.810537] Lustre: 109352:0:(osd_handler.c:2104:osd_trans_dump_creds()) Skipped 23 previous similar messages [ 3846.815522] Lustre: 109352:0:(osd_handler.c:2114:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 3846.821911] Lustre: 109352:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 23 previous similar messages [ 3846.834517] Lustre: 109352:0:(osd_handler.c:2121:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 3846.842973] Lustre: 109352:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 23 previous similar messages [ 3846.848826] Lustre: 109352:0:(osd_handler.c:2128:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3846.853151] Lustre: 109352:0:(osd_handler.c:2128:osd_trans_dump_creds()) Skipped 23 previous similar messages [ 3849.103885] Lustre: *** cfs_fail_loc=1617, val=0*** [ 3849.171048] Lustre: *** cfs_fail_loc=1617, val=0*** [ 3851.582628] Lustre: *** cfs_fail_loc=1616, val=0*** [ 3851.585043] Lustre: Skipped 3 previous similar messages [ 3869.581974] Lustre: DEBUG MARKER: == sanity-lfsck test 18d: Find out orphan OST-object and repair it (4) ========================================================== 19:05:21 (1790982321) [ 3869.895434] Lustre: 109352:0:(osd_internal.h:1462:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 292, rollback = 2 [ 3869.902411] Lustre: 109352:0:(osd_internal.h:1462:osd_trans_exec_op()) Skipped 24 previous similar messages [ 3869.906498] Lustre: 109352:0:(osd_handler.c:2097:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 3869.914255] Lustre: 109352:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 24 previous similar messages [ 3869.921247] Lustre: 109352:0:(osd_handler.c:2104:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 5/292/0 [ 3869.927929] Lustre: 109352:0:(osd_handler.c:2104:osd_trans_dump_creds()) Skipped 24 previous similar messages [ 3869.935556] Lustre: 109352:0:(osd_handler.c:2114:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 3869.940896] Lustre: 109352:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 24 previous similar messages [ 3869.946408] Lustre: 109352:0:(osd_handler.c:2121:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 3869.949652] Lustre: 109352:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 24 previous similar messages [ 3869.958291] Lustre: 109352:0:(osd_handler.c:2128:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3869.964064] Lustre: 109352:0:(osd_handler.c:2128:osd_trans_dump_creds()) Skipped 24 previous similar messages [ 3871.473471] Lustre: *** cfs_fail_loc=1618, val=0*** [ 3871.480347] Lustre: Skipped 5 previous similar messages [ 3907.041210] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3907.050777] 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 [ 3907.060808] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3908.088463] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3908.091556] 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 [ 3908.115579] Lustre: Skipped 2 previous similar messages [ 3911.074780] Lustre: server umount lustre-MDT0000 complete [ 3914.419148] LustreError: 109339:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1790982367 with bad export cookie 13511660457644019529 [ 3914.420198] LustreError: MGC192.168.202.152@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3914.430597] LustreError: 109339:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 3914.704901] Lustre: server umount lustre-MDT0001 complete [ 3928.956625] Lustre: server umount lustre-OST0000 complete [ 3943.128355] Lustre: server umount lustre-OST0001 complete [ 3960.114876] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing load_modules_local [ 3969.524405] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3969.997453] LustreError: 118021:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3970.016869] LustreError: 118021:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 5 previous similar messages [ 3970.103026] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3974.824333] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3975.137373] LustreError: 118022:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3975.165789] LustreError: 118022:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 1 previous similar message [ 3979.298769] LustreError: 118021:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3983.095316] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3983.449818] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 3988.236381] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3991.103750] Lustre: 119161:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3998.154236] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4005.390825] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4008.622620] LustreError: 119516:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4008.630281] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:4 to 0x280000400:33) [ 4012.440119] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4012.592687] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 4012.599349] Lustre: Skipped 1 previous similar message [ 4014.637553] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:116 to 0x280000401:161) [ 4014.651132] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:33) [ 4014.655402] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:4 to 0x2c0000401:33) [ 4018.616388] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4025.521231] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4028.905676] Lustre: 121030:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 4042.145910] Lustre: DEBUG MARKER: == sanity-lfsck test 18e: Find out orphan OST-object and repair it (5) ========================================================== 19:08:14 (1790982494) [ 4042.459223] Lustre: 120083:0:(osd_internal.h:1462:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 292, rollback = 2 [ 4042.466624] Lustre: 120083:0:(osd_internal.h:1462:osd_trans_exec_op()) Skipped 21 previous similar messages [ 4042.474752] Lustre: 120083:0:(osd_handler.c:2097:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 4042.486708] Lustre: 120083:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4042.495016] Lustre: 120083:0:(osd_handler.c:2104:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 5/292/0 [ 4042.502857] Lustre: 120083:0:(osd_handler.c:2104:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4042.512993] Lustre: 120083:0:(osd_handler.c:2114:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 4042.520129] Lustre: 120083:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4042.527684] Lustre: 120083:0:(osd_handler.c:2121:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 4042.536746] Lustre: 120083:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4042.553863] Lustre: 120083:0:(osd_handler.c:2128:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4042.562921] Lustre: 120083:0:(osd_handler.c:2128:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4044.088421] Lustre: *** cfs_fail_loc=1618, val=0*** [ 4044.096402] Lustre: Skipped 3 previous similar messages [ 4080.608533] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4080.621977] 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 [ 4080.630586] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4080.635812] Lustre: Skipped 3 previous similar messages [ 4083.383737] Lustre: server umount lustre-MDT0000 complete [ 4086.240091] LustreError: 118022:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4086.273054] LustreError: 118022:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 3 previous similar messages [ 4086.750244] LustreError: 118002:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1790982539 with bad export cookie 13511660457644034768 [ 4086.751746] LustreError: MGC192.168.202.152@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4086.764801] LustreError: 118002:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 4087.203230] Lustre: server umount lustre-MDT0001 complete [ 4100.634691] Lustre: server umount lustre-OST0000 complete [ 4113.662087] Lustre: server umount lustre-OST0001 complete [ 4132.373296] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing load_modules_local [ 4141.673437] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4141.907920] LustreError: 123596:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4141.953777] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4148.437860] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4158.607810] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4162.987698] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4165.961343] Lustre: 124739:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 4171.780545] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4178.956044] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4183.266683] LustreError: 125092:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4183.275097] LustreError: 125092:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 3 previous similar messages [ 4183.280565] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:4 to 0x280000400:65) [ 4186.351945] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:166 to 0x280000401:193) [ 4187.091523] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4192.239825] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:65) [ 4192.332739] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:4 to 0x2c0000401:65) [ 4193.574940] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4200.905358] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4204.649968] Lustre: 126605:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 4210.312079] Lustre: *** cfs_fail_loc=1602, val=10*** [ 4210.340924] Lustre: 123596:0:(osd_internal.h:1462:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 252 < left 260, rollback = 2 [ 4210.352823] Lustre: 123596:0:(osd_internal.h:1462:osd_trans_exec_op()) Skipped 21 previous similar messages [ 4210.359742] Lustre: 123596:0:(osd_handler.c:2097:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4210.369076] Lustre: 123596:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4210.375891] Lustre: 123596:0:(osd_handler.c:2104:osd_trans_dump_creds()) attr_set: 0/0/0, xattr_set: 1/260/0 [ 4210.382796] Lustre: 123596:0:(osd_handler.c:2104:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4210.393049] Lustre: 123596:0:(osd_handler.c:2114:osd_trans_dump_creds()) write: 1/9/0, punch: 0/0/0, quota 4/150/2 [ 4210.403208] Lustre: 123596:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4210.418554] Lustre: 123596:0:(osd_handler.c:2121:osd_trans_dump_creds()) insert: 1/17/2, delete: 0/0/0 [ 4210.429276] Lustre: 123596:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4210.437093] Lustre: 123596:0:(osd_handler.c:2128:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 4210.445295] Lustre: 123596:0:(osd_handler.c:2128:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4211.381185] Lustre: *** cfs_fail_loc=1602, val=10*** [ 4211.383173] Lustre: Skipped 2 previous similar messages [ 4236.897427] Lustre: DEBUG MARKER: == sanity-lfsck test 18f: Skip the failed OST(s) when handle orphan OST-objects ========================================================== 19:11:28 (1790982688) [ 4239.956661] Lustre: *** cfs_fail_loc=1616, val=0*** [ 4239.963214] Lustre: Skipped 3 previous similar messages [ 4246.954138] Lustre: *** cfs_fail_loc=161c, val=0*** [ 4246.964788] Lustre: Skipped 1 previous similar message [ 4267.827472] Lustre: DEBUG MARKER: == sanity-lfsck test 18g: Find out orphan OST-object and repair it (7) ========================================================== 19:12:00 (1790982720) [ 4270.762064] Lustre: *** cfs_fail_loc=162e, val=0*** [ 4287.477379] Lustre: DEBUG MARKER: == sanity-lfsck test 18h: LFSCK can repair crashed PFL extent range ========================================================== 19:12:20 (1790982740) [ 4291.437847] Lustre: *** cfs_fail_loc=162f, val=0*** [ 4291.439948] Lustre: Skipped 9 previous similar messages [ 4309.966487] Lustre: DEBUG MARKER: == sanity-lfsck test 19a: OST-object inconsistency self detect ========================================================== 19:12:41 (1790982761) [ 4321.649498] Lustre: DEBUG MARKER: == sanity-lfsck test 19b: OST-object inconsistency self repair ========================================================== 19:12:54 (1790982774) [ 4324.490937] Lustre: *** cfs_fail_loc=1611, val=0*** [ 4324.523441] Lustre: *** cfs_fail_loc=1611, val=0*** [ 4324.526502] Lustre: Skipped 3 previous similar messages [ 4330.167803] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.202.52@tcp inode [0x2000013a1:0x1f:0x0] object 0x280000401:203 extent [0-4095], client returned csum 0 (type 4), server csum 703fb3ad (type 4) [ 4331.306250] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.202.52@tcp inode [0x2000013a1:0x20:0x0] object 0x280000401:204 extent [0-4095], client returned csum 0 (type 4), server csum 7cbb935c (type 4) [ 4339.097536] Lustre: DEBUG MARKER: == sanity-lfsck test 20a: Handle the orphan with dummy LOV EA slot properly ========================================================== 19:13:11 (1790982791) [ 4339.366391] Lustre: 123592:0:(osd_internal.h:1462:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 253 < left 292, rollback = 2 [ 4339.374777] Lustre: 123592:0:(osd_internal.h:1462:osd_trans_exec_op()) Skipped 104 previous similar messages [ 4339.396303] Lustre: 123592:0:(osd_handler.c:2097:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4339.419568] Lustre: 123592:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 4339.429662] Lustre: 123592:0:(osd_handler.c:2104:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 5/292/0 [ 4339.436487] Lustre: 123592:0:(osd_handler.c:2104:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 4339.446111] Lustre: 123592:0:(osd_handler.c:2114:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/1 [ 4339.459119] Lustre: 123592:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 4339.469177] Lustre: 123592:0:(osd_handler.c:2121:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 4339.487016] Lustre: 123592:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 4339.500865] Lustre: 123592:0:(osd_handler.c:2128:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4339.511324] Lustre: 123592:0:(osd_handler.c:2128:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 4364.252373] Lustre: DEBUG MARKER: == sanity-lfsck test 20b: Handle the orphan with dummy LOV EA slot properly - PFL case ========================================================== 19:13:36 (1790982816) [ 4371.846710] Lustre: DEBUG MARKER: == sanity-lfsck test 21: run all LFSCK components by default ========================================================== 19:13:43 (1790982823) [ 4385.351786] Lustre: DEBUG MARKER: == sanity-lfsck test 22a: LFSCK can repair unmatched pairs (1) ========================================================== 19:13:57 (1790982837) [ 4387.679162] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4387.688858] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4387.698393] Lustre: Skipped 1 previous similar message [ 4401.016174] Lustre: DEBUG MARKER: == sanity-lfsck test 22b: LFSCK can repair unmatched pairs (2) ========================================================== 19:14:12 (1790982852) [ 4403.162202] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4403.164873] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4417.787357] Lustre: DEBUG MARKER: == sanity-lfsck test 23a: LFSCK can repair dangling name entry (1) ========================================================== 19:14:29 (1790982869) [ 4419.353216] Lustre: *** cfs_fail_loc=1620, val=0*** [ 4434.488412] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_23b skipping excluded test 23b [ 4436.649248] Lustre: DEBUG MARKER: == sanity-lfsck test 23c: LFSCK can repair dangling name entry (3) ========================================================== 19:14:48 (1790982888) [ 4443.203814] Lustre: *** cfs_fail_loc=1621, val=127*** [ 4443.206455] Lustre: Skipped 1 previous similar message [ 4446.681662] Lustre: *** cfs_fail_loc=1602, val=10*** [ 4468.309206] Lustre: DEBUG MARKER: == sanity-lfsck test 23d: LFSCK can repair a dangling name entry to a remote object ========================================================== 19:15:20 (1790982920) [ 4471.244329] Lustre: Failing over lustre-MDT0000 [ 4471.321712] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4471.342085] 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 [ 4471.378363] Lustre: Skipped 3 previous similar messages [ 4471.397330] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4471.413522] Lustre: Skipped 4 previous similar messages [ 4471.862214] Lustre: server umount lustre-MDT0000 complete [ 4473.057071] LustreError: 123591:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.202.52@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4473.092165] LustreError: 123591:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 2 previous similar messages [ 4483.874835] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4484.030132] LustreError: MGC192.168.202.152@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4484.313484] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4484.321682] Lustre: Skipped 3 previous similar messages [ 4484.372977] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4488.376343] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4489.720797] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4489.774218] Lustre: lustre-MDT0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 4489.828512] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:130 to 0x2c0000401:161) [ 4489.843553] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:265 to 0x280000401:289) [ 4490.070165] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4493.067553] LustreError: 127037:0:(mdt_open.c:1324:mdt_cross_open()) lustre-MDT0000: [0x2000013a3:0x82:0x0] doesn't exist!: rc = -14 [ 4504.861524] Lustre: DEBUG MARKER: == sanity-lfsck test 24: LFSCK can repair multiple-referenced name entry ========================================================== 19:15:56 (1790982956) [ 4506.892681] Lustre: *** cfs_fail_loc=1622, val=0*** [ 4507.006936] Lustre: *** cfs_fail_loc=1622, val=0*** [ 4507.014192] Lustre: Skipped 1 previous similar message [ 4518.635667] Lustre: DEBUG MARKER: == sanity-lfsck test 25: LFSCK can repair bad file type in the name entry ========================================================== 19:16:10 (1790982970) [ 4520.566578] Lustre: *** cfs_fail_loc=1623, val=0*** [ 4531.758370] Lustre: DEBUG MARKER: == sanity-lfsck test 26a: LFSCK can add the missing local name entry back to the namespace ========================================================== 19:16:23 (1790982983) [ 4533.359984] Lustre: *** cfs_fail_loc=1624, val=0*** [ 4545.730536] Lustre: DEBUG MARKER: == sanity-lfsck test 26b: LFSCK can add the missing remote name entry back to the namespace ========================================================== 19:16:37 (1790982997) [ 4559.420686] Lustre: DEBUG MARKER: == sanity-lfsck test 27a: LFSCK can recreate the lost local parent directory as orphan ========================================================== 19:16:51 (1790983011) [ 4561.257933] Lustre: *** cfs_fail_loc=1624, val=0*** [ 4561.263233] Lustre: Skipped 1 previous similar message [ 4573.727286] Lustre: DEBUG MARKER: == sanity-lfsck test 27b: LFSCK can recreate the lost remote parent directory as orphan ========================================================== 19:17:05 (1790983025) [ 4588.802994] Lustre: DEBUG MARKER: == sanity-lfsck test 28: Skip the failed MDT(s) when handle orphan MDT-objects ========================================================== 19:17:21 (1790983041) [ 4596.786852] Lustre: *** cfs_fail_loc=161c, val=0*** [ 4615.429260] Lustre: DEBUG MARKER: == sanity-lfsck test 29b: LFSCK can repair bad nlink count (2) ========================================================== 19:17:47 (1790983067) [ 4616.120205] Lustre: 126866:0:(osd_internal.h:1462:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 292, rollback = 2 [ 4616.122775] Lustre: 126866:0:(osd_internal.h:1462:osd_trans_exec_op()) Skipped 518 previous similar messages [ 4616.128725] Lustre: 126866:0:(osd_handler.c:2097:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 4616.133368] Lustre: 126866:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 518 previous similar messages [ 4616.137215] Lustre: 126866:0:(osd_handler.c:2104:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 5/292/0 [ 4616.143343] Lustre: 126866:0:(osd_handler.c:2104:osd_trans_dump_creds()) Skipped 518 previous similar messages [ 4616.147295] Lustre: 126866:0:(osd_handler.c:2114:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 4616.151566] Lustre: 126866:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 518 previous similar messages [ 4616.160686] Lustre: 126866:0:(osd_handler.c:2121:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 4616.169522] Lustre: 126866:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 518 previous similar messages [ 4616.175638] Lustre: 126866:0:(osd_handler.c:2128:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4616.180196] Lustre: 126866:0:(osd_handler.c:2128:osd_trans_dump_creds()) Skipped 518 previous similar messages [ 4617.100464] Lustre: *** cfs_fail_loc=1626, val=0*** [ 4617.102476] Lustre: Skipped 4 previous similar messages [ 4628.900413] Lustre: DEBUG MARKER: == sanity-lfsck test 29c: verify linkEA size limitation == 19:18:01 (1790983081) [ 4656.069776] Lustre: DEBUG MARKER: == sanity-lfsck test 29d: accessing non-existing inode shouldn't turn fs read-only (ldiskfs) ========================================================== 19:18:27 (1790983107) [ 4659.813686] LustreError: 127037:0:(osd_handler.c:286:osd_idc_find_or_init()) lustre-MDT0000: cannot lookup FID [0x2000013a3:0x9e:0x0]: rc = -2 [ 4667.725799] Lustre: DEBUG MARKER: == sanity-lfsck test 30: LFSCK can recover the orphans from backend /lost+found ========================================================== 19:18:39 (1790983119) [ 4676.049790] Lustre: Failing over lustre-MDT0000 [ 4676.324525] Lustre: server umount lustre-MDT0000 complete [ 4679.149386] 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 [ 4679.159617] LustreError: 123596:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4679.178874] Lustre: Skipped 4 previous similar messages [ 4679.179888] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4679.218668] LustreError: 123596:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 17 previous similar messages [ 4686.857329] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 4687.046727] LustreError: MGC192.168.202.152@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4687.299249] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4687.365769] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4692.273785] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4692.454467] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4692.474996] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4692.486114] Lustre: Skipped 3 previous similar messages [ 4692.519518] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4692.597781] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:294 to 0x280000401:321) [ 4692.601818] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:167 to 0x2c0000401:193) [ 4705.769952] Lustre: DEBUG MARKER: == sanity-lfsck test 31a: The LFSCK can find/repair the name entry with bad name hash (1) ========================================================== 19:19:17 (1790983157) [ 4720.437571] Lustre: DEBUG MARKER: == sanity-lfsck test 31b: The LFSCK can find/repair the name entry with bad name hash (2) ========================================================== 19:19:32 (1790983172) [ 4735.584856] Lustre: DEBUG MARKER: == sanity-lfsck test 31c: Re-generate the lost master LMV EA for striped directory ========================================================== 19:19:48 (1790983188) [ 4736.932308] Lustre: *** cfs_fail_loc=1629, val=0*** [ 4736.934041] Lustre: Skipped 7 previous similar messages [ 4767.826656] Lustre: DEBUG MARKER: == sanity-lfsck test 31d: Set broken striped directory (modified after broken) as read-only ========================================================== 19:20:20 (1790983220) [ 4774.091049] Lustre: Failing over lustre-MDT0000 [ 4774.244666] Lustre: server umount lustre-MDT0000 complete [ 4774.370337] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4774.382123] 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 [ 4774.399349] Lustre: Skipped 5 previous similar messages [ 4782.287987] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4782.377593] LustreError: MGC192.168.202.152@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4782.714465] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4787.686393] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4787.691184] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4787.703780] Lustre: Skipped 3 previous similar messages [ 4787.740754] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4787.817613] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:294 to 0x280000401:353) [ 4787.821345] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:167 to 0x2c0000401:225) [ 4788.061865] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4799.050767] Lustre: Failing over lustre-MDT0000 [ 4799.350779] Lustre: server umount lustre-MDT0000 complete [ 4803.049656] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4803.053348] 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 [ 4803.086649] Lustre: Skipped 3 previous similar messages [ 4808.188564] LustreError: 126866:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4808.202987] LustreError: 126866:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 20 previous similar messages [ 4808.410458] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4808.608476] LustreError: MGC192.168.202.152@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4808.984539] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4811.441944] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4814.314655] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4814.324788] Lustre: Skipped 3 previous similar messages [ 4814.384984] Lustre: lustre-MDT0000: Recovery over after 0:03, of 2 clients 2 recovered and 0 were evicted. [ 4814.448383] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:227 to 0x2c0000401:257) [ 4814.448524] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:294 to 0x280000401:385) [ 4814.449935] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4824.241725] Lustre: DEBUG MARKER: == sanity-lfsck test 31e: Re-generate the lost slave LMV EA for striped directory (1) ========================================================== 19:21:16 (1790983276) [ 4837.355878] Lustre: DEBUG MARKER: == sanity-lfsck test 31f: Re-generate the lost slave LMV EA for striped directory (2) ========================================================== 19:21:29 (1790983289) [ 4850.996458] Lustre: DEBUG MARKER: == sanity-lfsck test 31g: Repair the corrupted slave LMV EA ========================================================== 19:21:43 (1790983303) [ 4890.323757] Lustre: DEBUG MARKER: == sanity-lfsck test 31h: Repair the corrupted shard's name entry ========================================================== 19:22:22 (1790983342) [ 4891.679773] Lustre: *** cfs_fail_loc=162c, val=0*** [ 4891.683617] Lustre: Skipped 13 previous similar messages [ 4907.548598] Lustre: DEBUG MARKER: == sanity-lfsck test 32a: stop LFSCK when some OST failed ========================================================== 19:22:39 (1790983359) [ 4917.761703] LustreError: 148003:0:(lfsck_layout.c:4534:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d sleeping for 3000ms [ 4920.423679] Lustre: Failing over lustre-OST0000 [ 4920.618650] Lustre: server umount lustre-OST0000 complete [ 4920.800326] LustreError: lustre-OST0000-osc-MDT0001: operation ost_statfs to node 0@lo failed: rc = -107 [ 4920.814264] 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 [ 4920.865218] LustreError: 148003:0:(lfsck_layout.c:4534:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d awake [ 4920.883696] LustreError: 148003:0:(lfsck_layout.c:4534:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d sleeping for 3000ms [ 4923.343190] LustreError: 148003:0:(lfsck_layout.c:4534:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout interrupted [ 4934.986097] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 4935.210742] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 4936.358755] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4936.385085] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 4936.386848] Lustre: lustre-OST0000-osc-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4936.398368] Lustre: Skipped 3 previous similar messages [ 4942.166455] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4950.690093] Lustre: DEBUG MARKER: == sanity-lfsck test 32b: stop LFSCK when some MDT failed ========================================================== 19:23:22 (1790983402) [ 4967.328460] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing load_modules_local [ 4985.795317] Lustre: 150806:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 5010.532202] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5013.699952] Lustre: 151940:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 5023.684587] LustreError: 152058:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d sleeping for 3000ms [ 5026.426620] Lustre: Failing over lustre-MDT0001 [ 5026.751142] LustreError: 152058:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d awake [ 5026.803082] LustreError: 152057:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d sleeping for 3000ms [ 5026.804370] LustreError: lustre-MDT0001-osp-MDT0000: operation out_update to node 0@lo failed: rc = -107 [ 5026.819030] LustreError: 152057:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) Skipped 1 previous similar message [ 5026.849351] 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 [ 5026.859055] Lustre: Skipped 1 previous similar message [ 5026.864543] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 5027.105291] Lustre: server umount lustre-MDT0001 complete [ 5029.805563] LustreError: 152057:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d awake [ 5029.828228] LustreError: 152057:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) Skipped 1 previous similar message [ 5042.078111] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 5042.416220] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 5042.420482] Lustre: Skipped 3 previous similar messages [ 5042.448982] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 5047.247553] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5047.782099] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 1 client reconnects [ 5047.793869] Lustre: lustre-MDT0001-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 5047.808071] Lustre: Skipped 1 previous similar message [ 5047.833247] Lustre: lustre-MDT0001: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 5047.914192] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:71 to 0x280000400:97) [ 5047.914917] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:68 to 0x2c0000400:97) [ 5056.271459] Lustre: DEBUG MARKER: == sanity-lfsck test 33: check LFSCK paramters =========== 19:25:08 (1790983508) [ 5070.658343] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing load_modules_local [ 5091.532938] Lustre: 154777:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 5116.113837] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5119.425490] Lustre: 155912:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 5129.914847] Lustre: 151970:0:(osd_internal.h:1462:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 259 < left 274, rollback = 2 [ 5129.919740] Lustre: 125098:0:(osd_handler.c:2097:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 5129.939064] Lustre: 151970:0:(osd_internal.h:1462:osd_trans_exec_op()) Skipped 1543 previous similar messages [ 5129.939090] Lustre: 151970:0:(osd_handler.c:2104:osd_trans_dump_creds()) attr_set: 1/1/1, xattr_set: 2/274/0 [ 5129.939094] Lustre: 151970:0:(osd_handler.c:2104:osd_trans_dump_creds()) Skipped 1542 previous similar messages [ 5129.939100] Lustre: 151970:0:(osd_handler.c:2114:osd_trans_dump_creds()) write: 0/0/0, punch: 0/0/0, quota 7/225/0 [ 5129.939103] Lustre: 151970:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1542 previous similar messages [ 5129.939109] Lustre: 151970:0:(osd_handler.c:2121:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 5129.939112] Lustre: 151970:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1542 previous similar messages [ 5129.939118] Lustre: 151970:0:(osd_handler.c:2128:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 5129.939121] Lustre: 151970:0:(osd_handler.c:2128:osd_trans_dump_creds()) Skipped 1542 previous similar messages [ 5130.034984] Lustre: 125098:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1560 previous similar messages [ 5139.445609] Lustre: DEBUG MARKER: == sanity-lfsck test 34: LFSCK can rebuild the lost agent object ========================================================== 19:26:31 (1790983591) [ 5141.428559] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_34 Only valid for ZFS backend [ 5143.209749] Lustre: DEBUG MARKER: == sanity-lfsck test 35: LFSCK can rebuild the lost agent entry ========================================================== 19:26:35 (1790983595) [ 5150.067480] Lustre: *** cfs_fail_loc=1631, val=0*** [ 5165.539140] 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 [ 5165.542241] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 5165.542782] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5165.560141] Lustre: Skipped 4 previous similar messages [ 5168.502762] Lustre: server umount lustre-MDT0000 complete [ 5170.670159] LustreError: 123591:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 5170.690686] LustreError: 123591:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 17 previous similar messages [ 5172.577417] LustreError: 140262:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1790983625 with bad export cookie 13511660457644107505 [ 5172.582600] LustreError: MGC192.168.202.152@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5172.594286] LustreError: 140262:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 3 previous similar messages [ 5173.107401] Lustre: server umount lustre-MDT0001 complete [ 5187.855069] Lustre: server umount lustre-OST0000 complete [ 5202.276443] Lustre: server umount lustre-OST0001 complete [ 5220.616393] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing load_modules_local [ 5232.095387] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5237.860427] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5246.920941] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5251.837446] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5255.297444] Lustre: 159814:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 5262.405453] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5268.800258] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5273.028665] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:71 to 0x280000400:129) [ 5277.104055] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:540 to 0x280000401:577) [ 5277.905548] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5283.306363] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:412 to 0x2c0000401:449) [ 5283.311437] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:68 to 0x2c0000400:129) [ 5285.234131] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5292.903773] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5296.883487] Lustre: 161682:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 5307.710195] Lustre: DEBUG MARKER: == sanity-lfsck test 36a: rebuild LOV EA for mirrored file (1) ========================================================== 19:29:19 (1790983759) [ 5309.316818] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36a needs >= 3 OSTs [ 5311.404133] Lustre: DEBUG MARKER: == sanity-lfsck test 36b: rebuild LOV EA for mirrored file (2) ========================================================== 19:29:23 (1790983763) [ 5313.362997] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36b needs >= 3 OSTs [ 5315.377206] Lustre: DEBUG MARKER: == sanity-lfsck test 36c: rebuild LOV EA for mirrored file (3) ========================================================== 19:29:27 (1790983767) [ 5317.138447] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36c needs >= 3 OSTs [ 5319.032529] Lustre: DEBUG MARKER: == sanity-lfsck test 37: LFSCK must skip a ORPHAN ======== 19:29:31 (1790983771) [ 5330.149763] Lustre: DEBUG MARKER: == sanity-lfsck test 38: LFSCK does not break foreign file and reverse is also true ========================================================== 19:29:42 (1790983782) [ 5345.223381] Lustre: DEBUG MARKER: == sanity-lfsck test 39: LFSCK does not break foreign dir and reverse is also true ========================================================== 19:29:57 (1790983797) [ 5359.133649] Lustre: DEBUG MARKER: == sanity-lfsck test 40a: LFSCK correctly fixes lmm_oi in composite layout ========================================================== 19:30:11 (1790983811) [ 5373.857304] Lustre: DEBUG MARKER: == sanity-lfsck test 41: SEL support in LFSCK ============ 19:30:26 (1790983826) [ 5398.073863] Lustre: DEBUG MARKER: == sanity-lfsck test 42: LFSCK repairs inconsistent MDT-object/OST-object encryption flags ========================================================== 19:30:50 (1790983850) [ 5433.370446] Lustre: *** cfs_fail_loc=1632, val=0*** [ 5454.788945] Lustre: DEBUG MARKER: == sanity-lfsck test 43: LFSCK does not loop endlessly on iget failure in scanning-phase1 ========================================================== 19:31:45 (1790983905) [ 5458.304329] Lustre: Failing over lustre-MDT0001 [ 5460.177249] Lustre: lustre-MDT0001: Not available for connect from 192.168.202.52@tcp (stopping) [ 5460.186499] Lustre: Skipped 3 previous similar messages [ 5462.518544] 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 [ 5462.544138] Lustre: Skipped 1 previous similar message [ 5462.565974] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 5464.570809] Lustre: server umount lustre-MDT0001 complete [ 5473.986099] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5474.596193] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 5474.597055] Lustre: lustre-MDT0001: Aborting client recovery [ 5474.612193] LustreError: 165533:0:(ldlm_lib.c:3038:target_stop_recovery_thread()) lustre-MDT0001: Aborting recovery [ 5474.622578] Lustre: 165557:0:(ldlm_lib.c:2438:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 5474.635451] Lustre: 165557:0:(genops.c:1600:class_disconnect_stale_exports()) lustre-MDT0001: disconnect stale client d4662a49-7b9b-4b64-9db5-cd7fd201b1aa@ [ 5474.643538] Lustre: lustre-MDT0001: disconnecting 2 stale clients [ 5474.653393] Lustre: lustre-MDT0001-osd: cancel update llog [0x240000400:0x1:0x0] [ 5474.669951] Lustre: lustre-MDT0000-osp-MDT0001: cancel update llog [0x200000401:0x1:0x0] [ 5474.742294] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:131 to 0x280000400:161) [ 5474.751043] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:68 to 0x2c0000400:161) [ 5479.918597] LustreError: lustre-MDT0001-osp-MDT0000: This client was evicted by lustre-MDT0001; in progress operations using this service will fail. [ 5479.954151] Lustre: lustre-MDT0001-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 5479.964390] Lustre: Skipped 3 previous similar messages [ 5480.618561] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5485.354754] Lustre: *** cfs_fail_loc=1e2, val=483*** [ 5491.192547] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing wait_import_state FULL osp.lustre-MDT0001-os[pc]-MDT0000.*_server_uuid [ 5491.605595] Lustre: DEBUG MARKER: osp.lustre-MDT0001-os[pc]-MDT0000.*_server_uuid in FULL state after 0 sec [ 5498.134879] Lustre: DEBUG MARKER: == sanity-lfsck test 44: umount while lfsck is stopping == 19:32:30 (1790983950) [ 5504.616839] Lustre: *** cfs_fail_loc=1600, val=3*** [ 5507.491045] Lustre: Failing over lustre-MDT0000 [ 5507.905969] Lustre: server umount lustre-MDT0000 complete [ 5518.383404] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5518.531582] LustreError: MGC192.168.202.152@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5518.873221] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 5518.891254] Lustre: Skipped 2 previous similar messages [ 5521.584696] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 5523.214889] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5523.946557] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 5523.956545] Lustre: Skipped 1 previous similar message [ 5523.998405] Lustre: lustre-MDT0000: Recovery over after 0:02, of 2 clients 2 recovered and 0 were evicted. [ 5524.067519] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:489 to 0x2c0000401:513) [ 5524.068260] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:621 to 0x280000401:641) [ 5533.795486] Lustre: DEBUG MARKER: == sanity-lfsck test 45: LFSCK should fix UID/GID/PROJID of OST object ========================================================== 19:33:05 (1790983985) [ 5578.699607] Lustre: Failing over lustre-OST0001 [ 5578.883135] Lustre: server umount lustre-OST0001 complete [ 5586.253972] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: (null) [ 5599.026148] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5599.389550] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 5599.394819] Lustre: Skipped 6 previous similar messages [ 5599.417886] Lustre: lustre-OST0001: in recovery but waiting for the first client to connect [ 5600.450943] Lustre: lustre-OST0001: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 5600.595850] Lustre: lustre-OST0001-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 5600.604619] Lustre: lustre-OST0001: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [ 5600.605751] Lustre: Skipped 3 previous similar messages [ 5605.391669] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5611.749519] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing wait_import_state (FULL|IDLE) os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid 50 [ 5612.040016] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid in FULL state after 0 sec [ 5617.199478] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing wait_import_state (FULL|IDLE) os[cp].lustre-OST0000-osc-MDT0001.ost_server_uuid 50 [ 5617.492906] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0001.ost_server_uuid in FULL state after 0 sec [ 5623.136240] Lustre: DEBUG MARKER: oleg252-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0000-osc-ffff8b4005b56000.ost_server_uuid 50 [ 5624.856930] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff8b4005b56000.ost_server_uuid in FULL state after 0 sec [ 5710.325395] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5710.332533] Lustre: Skipped 6 previous similar messages [ 5714.939823] Lustre: server umount lustre-MDT0000 complete [ 5715.443597] LustreError: 158667:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 5715.456492] LustreError: 158667:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 39 previous similar messages [ 5723.446595] LustreError: 158653:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1790984176 with bad export cookie 13511660457644190133 [ 5723.454597] LustreError: MGC192.168.202.152@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5723.483486] LustreError: 158653:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 5723.817703] Lustre: server umount lustre-MDT0001 complete [ 5741.855212] Lustre: 106495:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790984178/real 1790984178] req@ffff9f1f887ff480 x1877980845418624/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1790984194 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5744.082242] Lustre: server umount lustre-OST0000 complete [ 5744.607225] Lustre: 106493:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790984181/real 1790984181] req@ffff9f1f887fea00 x1877980845418880/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1790984197 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5747.039103] Lustre: 106495:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790984183/real 1790984183] req@ffff9f1f887fdf80 x1877980845419136/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1790984199 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5750.752896] Lustre: 106496:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790984187/real 1790984187] req@ffff9f1fa4d42680 x1877980845419520/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1790984203 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5753.461229] Lustre: server umount lustre-OST0001 complete [ 5771.601464] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing unload_modules_local [ 5774.370884] Key type lgssc unregistered [ 5774.656203] LNet: 175231:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 5774.660787] LNetError: 175231:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 5775.720816] LNet: Removed LNI 192.168.202.152@tcp [ 5776.510320] Key type .llcrypt unregistered [ 5776.513634] Key type ._llcrypt unregistered [ 5803.054398] Key type ._llcrypt registered [ 5803.057768] Key type .llcrypt registered [ 5803.197451] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_hostid [ 5823.446703] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing load_modules_local [ 5825.681695] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 5825.713742] alg: No test for adler32 (adler32-zlib) [ 5826.927141] Lustre: Lustre: Build Version: 2.17.59_2_ge06ed12 [ 5827.249173] LNet: Added LNI 192.168.202.152@tcp [8/256/0/180] [ 5828.959300] Key type lgssc registered [ 5830.791307] Lustre: Echo OBD driver; http://www.lustre.org/ [ 5893.898602] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing load_modules_local [ 5910.538133] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' or install '{/usr}/sbin/mount.lustre_tgt' [ 5910.584168] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5911.877591] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 5911.912744] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 5912.038694] Lustre: lustre-MDT0000: new disk, initializing [ 5912.169334] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 5912.220727] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 5917.533391] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5933.292185] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5933.439316] Lustre: 179709: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 [ 5933.467600] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 5933.472144] Lustre: Skipped 1 previous similar message [ 5933.581574] Lustre: lustre-MDT0001: new disk, initializing [ 5933.703469] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 5933.754079] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 5933.770455] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 5938.998064] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5944.697823] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 5955.583121] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5955.794128] Lustre: lustre-OST0000: new disk, initializing [ 5955.800357] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 5955.804961] Lustre: 181649:0:(osd_compat.c:1354:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 5955.889688] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 5962.806163] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 5962.819220] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 5964.141482] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5968.391615] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 5979.711830] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5979.876383] Lustre: lustre-OST0001: new disk, initializing [ 5979.882594] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 5979.888829] Lustre: 182674:0:(osd_compat.c:1354:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 5979.983957] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 5986.885604] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 5986.925832] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 5987.081667] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 5988.617139] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6002.227679] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 6010.721493] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 6017.708776] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 19:41:09 (1790984469) === [ 6019.674512] Lustre: DEBUG MARKER: == sanity-lfsck test complete, duration 5702 sec ========= 19:41:11 (1790984471) [ 6022.254748] Lustre: DEBUG MARKER: === sanity-lfsck: start cleanup 19:41:13 (1790984473) === [ 6026.157626] Lustre: DEBUG MARKER: === sanity-lfsck: finish cleanup 19:41:18 (1790984478) === [ 6033.377288] 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 [ 6033.379770] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 6033.392393] Lustre: Skipped 3 previous similar messages [ 6033.395295] Lustre: Skipped 2 previous similar messages [ 6039.694609] Lustre: server umount lustre-MDT0000 complete [ 6043.616915] LustreError: 179719:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 6043.646131] LustreError: 179719:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 8 previous similar messages [ 6048.741349] LustreError: 179715:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 6048.764502] LustreError: 179715:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 3 previous similar messages [ 6048.839682] LustreError: 179700:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1790984501 with bad export cookie 278168710721569427 [ 6048.842957] LustreError: MGC192.168.202.152@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 6048.848256] LustreError: 179700:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 6049.207941] Lustre: server umount lustre-MDT0001 complete [ 6068.628771] Lustre: server umount lustre-OST0000 complete [ 6069.727386] Lustre: 176855:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790984506/real 1790984506] req@ffff9f1fb1c89f80 x1877983132474624/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1790984522 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6069.770187] 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 [ 6074.335521] Lustre: 176854:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790984511/real 1790984511] req@ffff9f1fb1c8aa00 x1877983132474880/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1790984527 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6075.872221] Lustre: 176853:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1790984512/real 1790984512] req@ffff9f1fbdd82d80 x1877983132475136/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1790984528 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6080.110824] Lustre: server umount lustre-OST0001 complete [ 6099.941251] Lustre: DEBUG MARKER: oleg252-server.virtnet: executing unload_modules_local [ 6103.150326] Key type lgssc unregistered [ 6103.423112] LNet: 186154:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 6103.431860] LNetError: 186154:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 6104.492535] LNet: Removed LNI 192.168.202.152@tcp [ 6105.372140] Key type .llcrypt unregistered [ 6105.375766] Key type ._llcrypt unregistered