[ 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 489700623 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 2576MB 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.001014] APIC: Switch to symmetric I/O mode setup [ 0.003342] x2apic enabled [ 0.004013] Switched APIC routing to physical x2apic. [ 0.005023] kvm-guest: setup PV IPIs [ 0.008000] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.008000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.008032] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.009019] pid_max: default: 32768 minimum: 301 [ 0.011150] LSM: Security Framework initializing [ 0.012071] Yama: becoming mindful. [ 0.013061] SELinux: Initializing. [ 0.015084] *** VALIDATE selinux *** [ 0.023808] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.027837] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.028202] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.029135] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.030151] *** VALIDATE tmpfs *** [ 0.031523] *** VALIDATE proc *** [ 0.032320] *** VALIDATE cgroup *** [ 0.033017] *** VALIDATE cgroup2 *** [ 0.034307] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.035184] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.036014] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.038035] Spectre V2 : User space: Vulnerable [ 0.039014] Speculative Store Bypass: Vulnerable [ 0.042191] debug: unmapping init [mem 0xffffffff98e59000-0xffffffff98e60fff] [ 0.045227] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.046692] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.047032] ... version: 2 [ 0.048019] ... bit width: 48 [ 0.049019] ... generic registers: 4 [ 0.050017] ... value mask: 0000ffffffffffff [ 0.051021] ... max period: 00007fffffffffff [ 0.052022] ... fixed-purpose events: 3 [ 0.053019] ... event mask: 000000070000000f [ 0.054372] rcu: Hierarchical SRCU implementation. [ 0.056707] smp: Bringing up secondary CPUs ... [ 0.057664] x86: Booting SMP configuration: [ 0.058045] .... node #0, CPUs: #1 #2 #3 [ 0.062466] smp: Brought up 1 node, 4 CPUs [ 0.064025] smpboot: Max logical packages: 1 [ 0.065022] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.226250] node 0 deferred pages initialised in 158ms [ 0.229174] devtmpfs: initialized [ 0.230401] x86/mm: Memory block size: 128MB [ 0.233220] gcov: version magic: 0x41383552 [ 0.235287] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.236082] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.237287] pinctrl core: initialized pinctrl subsystem [ 0.238204] [ 0.238836] ************************************************************* [ 0.239016] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.240014] ** ** [ 0.241016] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.242014] ** ** [ 0.243015] ** This means that this kernel is built to expose internal ** [ 0.244015] ** IOMMU data structures, which may compromise security on ** [ 0.245014] ** your system. ** [ 0.246014] ** ** [ 0.247015] ** If you see this message and you are not debugging the ** [ 0.248018] ** kernel, report this immediately to your vendor! ** [ 0.249014] ** ** [ 0.250013] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.251017] ************************************************************* [ 0.252684] NET: Registered protocol family 16 [ 0.253333] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.254051] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.255063] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.256499] cpuidle: using governor menu [ 0.258741] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.261618] PCI: Using configuration type 1 for base access [ 0.265167] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.275046] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.276018] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.278164] cryptd: max_cpu_qlen set to 1000 [ 0.280128] ACPI: Added _OSI(Module Device) [ 0.281014] ACPI: Added _OSI(Processor Device) [ 0.282013] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.283015] ACPI: Added _OSI(Processor Aggregator Device) [ 0.287196] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.289424] ACPI: Interpreter enabled [ 0.290000] ACPI: PM: (supports S0 S3 S4 S5) [ 0.293018] ACPI: Using IOAPIC for interrupt routing [ 0.295895] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.299406] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.311150] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.313045] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.315019] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.319089] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.324394] acpiphp: Slot [2] registered [ 0.326183] acpiphp: Slot [5] registered [ 0.328172] acpiphp: Slot [6] registered [ 0.330121] acpiphp: Slot [7] registered [ 0.332167] acpiphp: Slot [8] registered [ 0.334020] acpiphp: Slot [9] registered [ 0.335232] acpiphp: Slot [10] registered [ 0.337174] acpiphp: Slot [3] registered [ 0.338136] acpiphp: Slot [4] registered [ 0.340137] acpiphp: Slot [11] registered [ 0.341126] acpiphp: Slot [12] registered [ 0.343137] acpiphp: Slot [13] registered [ 0.344162] acpiphp: Slot [14] registered [ 0.346142] acpiphp: Slot [15] registered [ 0.347136] acpiphp: Slot [16] registered [ 0.349135] acpiphp: Slot [17] registered [ 0.350138] acpiphp: Slot [18] registered [ 0.352142] acpiphp: Slot [19] registered [ 0.353157] acpiphp: Slot [20] registered [ 0.355176] acpiphp: Slot [21] registered [ 0.356133] acpiphp: Slot [22] registered [ 0.358142] acpiphp: Slot [23] registered [ 0.359115] acpiphp: Slot [24] registered [ 0.361140] acpiphp: Slot [25] registered [ 0.362127] acpiphp: Slot [26] registered [ 0.364180] acpiphp: Slot [27] registered [ 0.365112] acpiphp: Slot [28] registered [ 0.367633] acpiphp: Slot [29] registered [ 0.369130] acpiphp: Slot [30] registered [ 0.371105] acpiphp: Slot [31] registered [ 0.372046] PCI host bridge to bus 0000:00 [ 0.372923] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.375024] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.377024] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.379031] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.382025] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.385026] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.387250] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.390011] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.393398] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.402807] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.408037] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.411018] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.413021] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.415019] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.418640] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.421874] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.425061] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.429030] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.435030] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.448012] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.454026] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.460678] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.470016] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.476017] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.498017] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.510147] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.519017] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.525016] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.546014] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.555825] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.561014] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.570015] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.590020] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.599080] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.607017] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.614024] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.631016] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.642039] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.652015] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.662018] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.680017] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 0.691014] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.697014] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.704014] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.729013] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 0.740578] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.742364] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.745375] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.748479] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.751238] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.755185] iommu: Default domain type: Passthrough [ 0.757565] SCSI subsystem initialized [ 0.759130] ACPI: bus type USB registered [ 0.761096] usbcore: registered new interface driver usbfs [ 0.763088] usbcore: registered new interface driver hub [ 0.765080] usbcore: registered new device driver usb [ 0.767160] pps_core: LinuxPPS API ver. 1 registered [ 0.768009] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.771063] PTP clock support registered [ 0.773084] EDAC MC: Ver: 3.0.0 [ 0.775146] PCI: Using ACPI for IRQ routing [ 0.776887] NetLabel: Initializing [ 0.777011] NetLabel: domain hash size = 128 [ 0.778010] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.779097] NetLabel: unlabeled traffic allowed by default [ 0.781155] vgaarb: loaded [ 0.782268] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.784011] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.790251] clocksource: Switched to clocksource kvm-clock [ 0.898098] VFS: Disk quotas dquot_6.6.0 [ 0.899558] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.902259] *** VALIDATE ramfs *** [ 0.903664] *** VALIDATE hugetlbfs *** [ 0.905409] pnp: PnP ACPI init [ 0.907930] pnp: PnP ACPI: found 6 devices [ 0.924670] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.929408] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.931599] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.934017] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.936262] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.938903] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.941727] NET: Registered protocol family 2 [ 0.944282] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.949227] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.953143] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.958398] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.962088] TCP: Hash tables configured (established 65536 bind 65536) [ 0.965123] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.968338] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.971393] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.974470] NET: Registered protocol family 1 [ 0.977247] RPC: Registered named UNIX socket transport module. [ 0.979555] RPC: Registered udp transport module. [ 0.981305] RPC: Registered tcp transport module. [ 0.983016] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.985218] NET: Registered protocol family 44 [ 0.986941] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.989063] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.991206] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.993440] PCI: CLS 0 bytes, default 64 [ 0.995771] Unpacking initramfs... [ 2.428321] debug: unmapping init [mem 0xffff8e043cc54000-0xffff8e043ffbffff] [ 2.433956] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.436325] software IO TLB: mapped [mem 0x00000000b8c54000-0x00000000bcc54000] (64MB) [ 2.439278] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 2.945263] Initialise system trusted keyrings [ 2.947178] Key type blacklist registered [ 2.949108] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.958306] zbud: loaded [ 2.961270] *** VALIDATE nfs *** [ 2.962746] *** VALIDATE nfs4 *** [ 2.964519] pstore: using deflate compression [ 2.968256] Platform Keyring initialized [ 3.070882] NET: Registered protocol family 38 [ 3.072882] Key type asymmetric registered [ 3.074318] Asymmetric key parser 'x509' registered [ 3.076270] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 3.079684] io scheduler mq-deadline registered [ 3.081405] io scheduler kyber registered [ 3.083305] io scheduler bfq registered [ 3.085102] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 3.088041] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 3.090606] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 3.093197] ACPI: Power Button [PWRF] [ 3.097832] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 3.104111] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 3.118194] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 3.129617] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 3.148461] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 3.178340] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.206393] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.210888] Non-volatile memory driver v1.3 [ 3.212476] Linux agpgart interface v0.103 [ 3.252364] virtio_blk virtio1: [vda] 149784 512-byte logical blocks (76.7 MB/73.1 MiB) [ 3.255523] vda: detected capacity change from 0 to 76689408 [ 3.277111] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.280390] vdb: detected capacity change from 0 to 1073741824 [ 3.305670] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.308767] vdc: detected capacity change from 0 to 2621440000 [ 3.330428] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.333797] vdd: detected capacity change from 0 to 2621440000 [ 3.349253] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.351822] vde: detected capacity change from 0 to 4294967296 [ 3.368755] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.371927] vdf: detected capacity change from 0 to 4294967296 [ 3.388327] libphy: Fixed MDIO Bus: probed [ 3.393695] usbcore: registered new interface driver usbserial_generic [ 3.396906] usbserial: USB Serial support registered for generic [ 3.399438] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.404049] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.406067] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.408950] mousedev: PS/2 mouse device common for all mice [ 3.411943] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.416534] rtc_cmos 00:05: RTC can wake from S4 [ 3.422199] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.424068] rtc_cmos 00:05: registered as rtc0 [ 3.428201] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.428278] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.434776] intel_pstate: CPU model not supported [ 3.438141] hid: raw HID events driver (C) Jiri Kosina [ 3.440566] usbcore: registered new interface driver usbhid [ 3.442775] usbhid: USB HID core driver [ 3.444234] drop_monitor: Initializing network drop monitor service [ 3.446398] Initializing XFRM netlink socket [ 3.448401] NET: Registered protocol family 10 [ 3.451235] Segment Routing with IPv6 [ 3.452739] NET: Registered protocol family 17 [ 3.454960] mpls_gso: MPLS GSO support [ 3.462592] RAS: Correctable Errors collector initialized. [ 3.464961] AVX version of gcm_enc/dec engaged. [ 3.466542] AES CTR mode by8 optimization enabled [ 3.542971] sched_clock: Marking stable (3542950412, 0)->(4562167335, -1019216923) [ 3.545962] registered taskstats version 1 [ 3.547654] Loading compiled-in X.509 certificates [ 3.549607] zswap: loaded using pool lzo/zbud [ 3.572505] Key type big_key registered [ 3.582635] Key type encrypted registered [ 3.584029] ima: No TPM chip found, activating TPM-bypass! [ 3.585725] ima: Allocated hash algorithm: sha1 [ 3.587110] ima: No architecture policies found [ 3.588665] evm: Initialising EVM extended attributes: [ 3.590285] evm: security.selinux [ 3.591286] evm: security.ima [ 3.592170] evm: security.capability [ 3.593184] evm: HMAC attrs: 0x1 [ 3.595977] rtc_cmos 00:05: setting system clock to 2026-09-06 03:07:13 UTC (1788664033) [ 3.601932] debug: unmapping init [mem 0xffffffff99e03000-0xffffffff99ffffff] [ 3.604836] debug: unmapping init [mem 0xffffffff98b82000-0xffffffff98e58fff] [ 3.613092] Write protecting the kernel read-only data: 28672k [ 3.616792] debug: unmapping init [mem 0xffffffff97203000-0xffffffff973fffff] [ 3.619946] debug: unmapping init [mem 0xffffffff97b14000-0xffffffff97bfffff] [ 3.653798] 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.662827] systemd[1]: Detected virtualization kvm. [ 3.664918] systemd[1]: Detected architecture x86-64. [ 3.667087] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.693751] systemd[1]: No hostname configured. [ 3.695478] systemd[1]: Set hostname to . [ 3.697544] random: systemd: uninitialized urandom read (16 bytes read) [ 3.700136] systemd[1]: Initializing machine ID from random generator. [ 3.738921] random: ln: uninitialized urandom read (6 bytes read) [ 3.851585] random: systemd: uninitialized urandom read (16 bytes read) [ 3.855356] systemd[1]: Listening on udev Control Socket. [ OK ] Listening on udev Control Socket. [ 3.860643] systemd[1]: Listening on Journal Socket (/dev/log). [ OK ] Listening on Journal Socket (/dev/log). [ 3.865803] systemd[1]: Listening on udev Kernel Socket. [ OK ] Listening on udev Kernel Socket. [ OK ] Reached target Local File Systems. [ OK ] Reached target Timers. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Swap. [ OK ] Reached target Slices. [ OK ] Reached target Paths. [ OK ] Listening on Journal Socket. [ OK ] Reached target Sockets. Starting Setup Virtual Console... Starting Journal Service... Starting Create Volatile Files and Directories... Starting Apply Kernel Variables... [ OK ] Started Memstrack Anylazing Service. [ OK ] Reached target Initrd Root Device. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Started Setup Virtual Console. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Apply Kernel Variables. [ 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.548880] device-mapper: uevent: version 1.0.3 [ 4.551570] device-mapper: ioctl: 4.46.0-ioctl (2022-02-22) initialised: dm-devel@redhat.com [ OK ] Started dracut pre-udev hook. Starting udev Kernel Device Manager... [ OK ] Started udev Kernel Device Manager. Starting dracut pre-trigger hook... [ OK ] Started dracut pre-trigger hook. Starting udev Coldplug all Devices... Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting dracut initqueue hook... [ 5.340047] random: fast init done [ 5.360822] virtio_net virtio0 ens2: renamed from eth0 [ 5.391303] scsi host0: ata_piix [ 5.403181] scsi host1: ata_piix [ 5.405138] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 5.407984] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 9.986196] dracut-initqueue[594]: RTNETLINK answers: File exists [ 10.099514] random: crng init done [ 10.100848] random: 7 urandom warning(s) missed due to ratelimiting Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. Mounting /sysroot... [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. [ 10.657073] 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. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Paths. [ OK ] Stopped target Slices. [ OK ] Stopped target Sockets. [ OK ] Stopped target System Initialization. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped target Swap. [ OK ] Stopped Apply Kernel Variables. Stopping udev Kernel Device Manager... [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Stopped 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... [ 11.855565] printk: systemd: 26 output lines suppressed due to ratelimiting [ 12.113889] SELinux: Disabled at runtime. [ 12.173877] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 12.183586] systemd[1]: Detected virtualization kvm. [ 12.185569] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 12.713550] systemd[1]: initrd-switch-root.service: Succeeded. [ 12.716560] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 12.720921] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 12.724366] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 12.727228] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 12.738612] systemd[1]: Starting Journal Service... Starting Journal Service... [ 12.748856] systemd[1]: Mounting Huge Pages File System... Mounting Huge Pages File System... [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Reached target rpc_pipefs.target. [ OK ] Listening on Process Core Dump Socket. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Listening on udev Kernel Socket. [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Stopped target Switch Root. [ OK ] Created slice User and Session Slice. [ OK ] Reached target Slices. [ OK ] Stopped target Initrd File Systems. Starting Remount Root and Kernel File Systems... Starting Apply Kernel Variables... [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. Mounting POSIX Message Queue File System... Activating swap /dev/disk/by-label/SWAP... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Listening on udev Control Socket. Starting udev Coldplug all Devices... [ OK ] Reached target Paths. [ OK ] Listening on RPCbind Server Activation Socket.[ 12.895697] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS [ OK ] Created slice system-getty.slice. [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Reached target RPC Port Mapper. [ OK ] Stopped target Initrd Root File System. Mounting Kernel Debug File System... [ OK ] Started Journal Service. [ OK ] Mounted Huge Pages File System. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Started Apply Kernel Variables. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Mounted Kernel Debug 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. [ OK ] Reached target Local File Systems (Pre). Mounting /home/green/git/lustre-release... Mounting /mnt... Starting udev Kernel Device Manager... [ OK ] Started udev Coldplug all Devices. [ OK ] Mounted /mnt. [ 13.186079] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 13.482356] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 13.497031] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 13.635372] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 13.656850] EDAC sbridge: Ver: 1.1.2 [ 15.263147] Key type dns_resolver registered [ 15.566462] NFS: Registering the id_resolver key type [ 15.568920] Key type id_resolver registered [ 15.570570] 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 Update UTMP about System Boot/Shutdown... Starting RPC Bind... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Started dnf makecache --timer. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. [ OK ] Started D-Bus System Message Bus. Starting Login Service... [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting Network Manager... [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Reached target Timers. [ OK ] Started irqbalance daemon. [ OK ] Reached target sshd-keygen.target. Starting Restore /run/initramfs on shutdown... [ 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 Dynamic System Tuning Daemon... Starting GSSAPI Proxy Daemon... Starting OpenSSH server daemon... Starting Hostname Service... [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Started OpenSSH server daemon. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... [ OK ] Started Permit User Sessions. [ OK ] Started Serial Getty on ttyS1. [ OK ] Started Command Scheduler. [ OK ] Started Getty on tty1. [ OK ] Started Serial Getty on ttyS0. [ 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 System Logging Service... Starting Crash recovery kernel arming... Starting Notify NFS peers of a restart... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Starting Authorization Manager... [ OK ] Started Authorization Manager. [ OK ] Started Dynamic System Tuning Daemon. [ OK ] Reached target Multi-User System. [ OK ] Reached target Graphical Interface. Starting Update UTMP about System Runlevel Changes... [ OK ] Started Update UTMP about System Runlevel Changes. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg605-server login: [ 41.694437] libcfs: loading out-of-tree module taints kernel. [ 41.714673] Key type ._llcrypt registered [ 41.716438] Key type .llcrypt registered [ 41.770722] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_hostid [ 53.409270] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing load_modules_local [ 55.375735] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 55.390389] alg: No test for adler32 (adler32-zlib) [ 57.050716] Lustre: Lustre: Build Version: 2.17.58_4_g3b30273 [ 57.986175] LNet: Added LNI 192.168.206.105@tcp [8/256/0/180] [ 59.840434] Key type lgssc registered [ 61.716461] Lustre: Echo OBD driver; http://www.lustre.org/ [ 80.759040] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 123.600608] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing load_modules_local [ 135.598368] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 135.621477] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 136.842419] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 136.871524] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 136.952402] Lustre: lustre-MDT0000: new disk, initializing [ 137.052749] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 137.077121] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 141.759645] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 153.676486] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 153.820113] Lustre: 6492: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 [ 153.870814] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 153.880237] Lustre: Skipped 1 previous similar message [ 153.998507] Lustre: lustre-MDT0001: new disk, initializing [ 154.079848] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 154.106872] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 154.123533] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 154.862993] hrtimer: interrupt took 6107208 ns [ 158.114959] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 162.700272] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 171.858562] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 172.108429] Lustre: lustre-OST0000: new disk, initializing [ 172.117571] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 172.124488] Lustre: 8428:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 172.196853] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 177.868967] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 180.292089] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 180.298990] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 180.388765] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 192.059880] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 192.170896] Lustre: lustre-OST0001: new disk, initializing [ 192.175905] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 192.186123] Lustre: 9499:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 192.247123] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 197.749052] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 197.759029] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 197.841858] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 199.185988] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 211.159660] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 223.969766] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 230.843744] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing check_logdir /tmp/testlogs/ [ 236.738807] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing yml_node [ 242.097699] Lustre: DEBUG MARKER: Client: 2.17.58.4 [ 244.847913] Lustre: DEBUG MARKER: MDS: 2.17.58.4 [ 247.385337] Lustre: DEBUG MARKER: OSS: 2.17.58.4 [ 248.816990] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity-lfsck ============----- Sat Sep 5 23:11:17 EDT 2026 [ 267.771516] Lustre: DEBUG MARKER: excepting tests: 18b 23b [ 278.514708] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing load_modules_local [ 287.201411] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 287.213834] 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 [ 287.239844] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 290.273737] 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 [ 290.275568] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 290.320729] Lustre: Skipped 3 previous similar messages [ 293.204247] Lustre: server umount lustre-MDT0000 complete [ 300.513184] LustreError: 6500:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 300.539487] LustreError: 6500:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 8 previous similar messages [ 302.426633] LustreError: 10315:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788664332 with bad export cookie 16805369081489959519 [ 302.427356] LustreError: MGC192.168.206.105@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 302.453879] LustreError: 10315:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 3 previous similar messages [ 302.854532] Lustre: server umount lustre-MDT0001 complete [ 320.248484] Lustre: server umount lustre-OST0000 complete [ 321.761794] Lustre: 3622:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788664335/real 1788664335] req@ffff8e04bfa61500 x1875550233796608/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788664351 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 321.785593] 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 [ 321.799318] Lustre: Skipped 2 previous similar messages [ 323.552461] Lustre: 3625:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788664337/real 1788664337] req@ffff8e0382681500 x1875550233796864/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788664353 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 326.116615] Lustre: 3623:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788664340/real 1788664340] req@ffff8e04bfa63100 x1875550233797120/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788664356 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 328.224147] Lustre: 3623:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788664342/real 1788664342] req@ffff8e0382680380 x1875550233797504/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788664358 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 328.480657] Lustre: server umount lustre-OST0001 complete [ 343.575381] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing unload_modules_local [ 346.648552] Key type lgssc unregistered [ 346.958306] LNet: 14772:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 346.966866] LNetError: 14772:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 346.982907] LNet: Removed LNI 192.168.206.105@tcp [ 347.812256] Key type .llcrypt unregistered [ 347.820244] Key type ._llcrypt unregistered [ 372.074650] Key type ._llcrypt registered [ 372.079672] Key type .llcrypt registered [ 372.219969] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_hostid [ 386.569734] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing load_modules_local [ 387.244841] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 387.266820] alg: No test for adler32 (adler32-zlib) [ 388.312916] Lustre: Lustre: Build Version: 2.17.58_4_g3b30273 [ 388.538895] LNet: Added LNI 192.168.206.105@tcp [8/256/0/180] [ 390.161521] Key type lgssc registered [ 391.202881] Lustre: Echo OBD driver; http://www.lustre.org/ [ 436.723665] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing load_modules_local [ 447.814425] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 447.851686] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 449.062841] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 449.106931] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 449.203341] Lustre: lustre-MDT0000: new disk, initializing [ 449.263974] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 449.277539] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 452.710914] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 464.118408] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 464.225579] Lustre: 19222: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 [ 464.253525] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 464.257293] Lustre: Skipped 1 previous similar message [ 464.344329] Lustre: lustre-MDT0001: new disk, initializing [ 464.416922] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 464.453402] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 464.461980] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 468.369766] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 473.598723] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 482.163221] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 482.330717] Lustre: lustre-OST0000: new disk, initializing [ 482.335410] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 482.339424] Lustre: 21162:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 482.391763] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 486.362028] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 486.369071] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 486.451333] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 488.232463] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 501.000046] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 501.204407] Lustre: lustre-OST0001: new disk, initializing [ 501.213644] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 501.225243] Lustre: 22186:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 501.312543] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 507.646105] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 511.061395] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 511.072639] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 511.129337] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 521.064522] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 530.250297] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 537.108178] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 23:16:05 (1788664565) === [ 539.461749] Lustre: DEBUG MARKER: == sanity-lfsck test 0: Control LFSCK manually =========== 23:16:07 (1788664567) [ 539.585049] Lustre: 19231:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 251 < left 278, rollback = 2 [ 539.592636] Lustre: 19231:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 539.604517] Lustre: 19231:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 539.616628] Lustre: 19231:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 539.629251] Lustre: 19231:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 539.635831] Lustre: 19231:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 540.090190] Lustre: 19232:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 540.097884] Lustre: 19232:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 11 previous similar messages [ 540.104264] Lustre: 19232:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 540.115486] Lustre: 19232:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 540.121499] Lustre: 19232:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 540.130132] Lustre: 19232:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 540.136617] Lustre: 19232:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 540.149624] Lustre: 19232:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 540.157851] Lustre: 19232:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 540.175369] Lustre: 19232:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 540.181463] Lustre: 19232:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 540.193201] Lustre: 19232:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 541.110807] Lustre: 19230:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 541.121024] Lustre: 19230:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 44 previous similar messages [ 541.127621] Lustre: 19230:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 541.133091] Lustre: 19230:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 44 previous similar messages [ 541.139774] Lustre: 19230:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 541.148441] Lustre: 19230:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 44 previous similar messages [ 541.156922] Lustre: 19230:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 541.165942] Lustre: 19230:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 44 previous similar messages [ 541.171552] Lustre: 19230:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 541.182593] Lustre: 19230:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 44 previous similar messages [ 541.189071] Lustre: 19230:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 541.193034] Lustre: 19230:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 44 previous similar messages [ 543.131294] Lustre: 19232:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 543.143320] Lustre: 19232:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 101 previous similar messages [ 543.152907] Lustre: 19232:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 543.161330] Lustre: 19232:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 101 previous similar messages [ 543.174598] Lustre: 19232:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 543.180100] Lustre: 19232:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 101 previous similar messages [ 543.188730] Lustre: 19232:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 543.193970] Lustre: 19232:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 101 previous similar messages [ 543.203713] Lustre: 19232:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 543.213346] Lustre: 19232:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 101 previous similar messages [ 543.219564] Lustre: 19232:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 543.225416] Lustre: 19232:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 101 previous similar messages [ 547.084050] Lustre: *** cfs_fail_loc=1600, val=3*** [ 549.918440] Lustre: 23375:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 259 < left 274, rollback = 2 [ 549.933909] Lustre: 23375:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 120 previous similar messages [ 549.938759] Lustre: 21151:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 549.942716] Lustre: 23375:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/1, xattr_set: 2/274/0 [ 549.942726] Lustre: 23375:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 120 previous similar messages [ 549.942733] Lustre: 23375:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 0/0/0, punch: 0/0/0, quota 7/225/0 [ 549.942736] Lustre: 23375:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 120 previous similar messages [ 549.942741] Lustre: 23375:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 549.942745] Lustre: 23375:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 120 previous similar messages [ 549.942750] Lustre: 23375:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 549.942753] Lustre: 23375:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 120 previous similar messages [ 550.027724] Lustre: 21151:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 127 previous similar messages [ 551.030452] Lustre: *** cfs_fail_loc=1600, val=3*** [ 561.790609] Lustre: 21152:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 259 < left 274, rollback = 2 [ 561.794037] Lustre: 23638:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 561.804654] Lustre: 21152:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 59 previous similar messages [ 561.811645] Lustre: 23638:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 52 previous similar messages [ 561.811669] Lustre: 23638:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/1, xattr_set: 2/274/0 [ 561.811672] Lustre: 23638:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 59 previous similar messages [ 561.811679] Lustre: 23638:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 0/0/0, punch: 0/0/0, quota 7/225/0 [ 561.811682] Lustre: 23638:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 59 previous similar messages [ 561.811687] Lustre: 23638:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 561.811690] Lustre: 23638:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 59 previous similar messages [ 561.811694] Lustre: 23638:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 561.811697] Lustre: 23638:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 59 previous similar messages [ 564.021422] Lustre: server umount lustre-MDT0000 complete [ 566.762456] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 566.766566] 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 [ 567.420413] LustreError: 21161:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788664597 with bad export cookie 17171417915440852410 [ 567.431269] LustreError: MGC192.168.206.105@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 567.434027] LustreError: 21161:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 567.790436] Lustre: lustre-MDT0001-lwp-OST0000: Connection to lustre-MDT0001 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 567.792609] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 567.801157] Lustre: Skipped 3 previous similar messages [ 567.807914] Lustre: Skipped 1 previous similar message [ 569.817696] Lustre: server umount lustre-MDT0001 complete [ 573.574545] Lustre: server umount lustre-OST0000 complete [ 577.515276] Lustre: server umount lustre-OST0001 complete [ 585.528331] Lustre: DEBUG MARKER: == sanity-lfsck test 1a: LFSCK can find out and repair crashed FID-in-dirent ========================================================== 23:16:54 (1788664614) [ 598.812170] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing load_modules_local [ 608.155496] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 608.433568] LustreError: 26241:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 608.448171] LustreError: 26241:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 4 previous similar messages [ 608.499837] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 612.391259] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 613.857367] LustreError: 26242:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 618.977593] LustreError: 26241:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 620.112356] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 620.379250] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 624.633187] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 627.414080] Lustre: 27382:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 634.439870] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 641.096286] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 646.075845] LustreError: 27737:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 649.711185] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 649.874572] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 649.880449] Lustre: Skipped 1 previous similar message [ 654.008947] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:40 to 0x280000401:65) [ 654.026486] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:41 to 0x2c0000401:65) [ 656.237113] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 663.421581] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 666.770777] Lustre: 29253:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 668.414370] Lustre: 26237:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 668.427644] Lustre: 26237:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 2 previous similar messages [ 668.437168] Lustre: 26237:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 668.446821] Lustre: 26237:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 6 previous similar messages [ 668.456810] Lustre: 26237:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 668.467291] Lustre: 26237:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 6 previous similar messages [ 668.474302] Lustre: 26237:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 668.483461] Lustre: 26237:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 6 previous similar messages [ 668.493837] Lustre: 26237:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 668.509575] Lustre: 26237:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 6 previous similar messages [ 668.522670] Lustre: 26237:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 668.528672] Lustre: 26237:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 6 previous similar messages [ 674.176599] Lustre: *** cfs_fail_loc=1501, val=0*** [ 681.170448] Lustre: Failing over lustre-MDT0000 [ 681.504611] Lustre: server umount lustre-MDT0000 complete [ 681.954529] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 681.963567] 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 [ 681.981489] LustreError: 26241:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 685.030695] 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 [ 685.051988] Lustre: Skipped 1 previous similar message [ 690.150907] LustreError: 26973:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 690.175155] LustreError: 26973:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 7 previous similar messages [ 691.104277] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 691.163410] LustreError: MGC192.168.206.105@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 691.468418] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 691.530567] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 695.728922] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 696.802926] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 696.807231] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 696.862533] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 696.912183] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:105 to 0x280000401:129) [ 696.914693] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:105 to 0x2c0000401:129) [ 698.668265] Lustre: *** cfs_fail_loc=1505, val=0*** [ 705.076948] Lustre: DEBUG MARKER: == sanity-lfsck test 1b: LFSCK can find out and repair the missing FID-in-LMA ========================================================== 23:18:53 (1788664733) [ 706.035229] Lustre: 29302:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 706.042159] Lustre: 29302:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 322 previous similar messages [ 706.047414] Lustre: 29302:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 706.050930] Lustre: 29302:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 706.054057] Lustre: 29302:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 706.058016] Lustre: 29302:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 706.061587] Lustre: 29302:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 706.067964] Lustre: 29302:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 706.072451] Lustre: 29302:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 706.076304] Lustre: 29302:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 706.080626] Lustre: 29302:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 706.083577] Lustre: 29302:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 711.022752] Lustre: *** cfs_fail_loc=1502, val=0*** [ 720.480148] Lustre: Failing over lustre-MDT0000 [ 720.759812] Lustre: server umount lustre-MDT0000 complete [ 722.402571] 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 [ 722.421991] Lustre: Skipped 1 previous similar message [ 722.430507] LustreError: 26236:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 722.452959] LustreError: 26236:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 3 previous similar messages [ 730.476324] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 730.627769] LustreError: MGC192.168.206.105@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 730.897489] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 735.137196] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 736.234036] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 736.244797] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 736.259618] Lustre: Skipped 3 previous similar messages [ 736.283298] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 736.364428] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:169 to 0x2c0000401:193) [ 736.371413] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:169 to 0x280000401:193) [ 738.705909] Lustre: *** cfs_fail_loc=1505, val=0*** [ 746.826203] Lustre: DEBUG MARKER: == sanity-lfsck test 1c: LFSCK can find out and repair lost FID-in-dirent ========================================================== 23:19:34 (1788664774) [ 753.382418] Lustre: *** cfs_fail_loc=1504, val=0*** [ 753.386328] Lustre: *** cfs_fail_loc=1504, val=0*** [ 753.390268] Lustre: Skipped 1 previous similar message [ 760.190378] Lustre: Failing over lustre-MDT0000 [ 760.471947] Lustre: server umount lustre-MDT0000 complete [ 761.824472] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 761.825641] 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 [ 761.826736] LustreError: 26238:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 761.826744] LustreError: 26238:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 4 previous similar messages [ 761.865403] Lustre: Skipped 6 previous similar messages [ 770.777910] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 770.917663] LustreError: MGC192.168.206.105@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 771.147343] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 771.156675] Lustre: Skipped 1 previous similar message [ 771.192852] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 775.419225] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 776.163173] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 776.166799] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 776.185407] Lustre: Skipped 3 previous similar messages [ 776.215802] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 776.313311] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:233 to 0x2c0000401:257) [ 776.315218] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:233 to 0x280000401:257) [ 779.015939] Lustre: *** cfs_fail_loc=1505, val=0*** [ 785.967572] Lustre: DEBUG MARKER: == sanity-lfsck test 2a: LFSCK can find out and repair crashed linkEA entry ========================================================== 23:20:14 (1788664814) [ 787.140272] Lustre: 26236:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 787.157206] Lustre: 26236:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 644 previous similar messages [ 787.165443] Lustre: 26236:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 787.170583] Lustre: 26236:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 787.178220] Lustre: 26236:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 787.186226] Lustre: 26236:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 787.191362] Lustre: 26236:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 787.197718] Lustre: 26236:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 787.204354] Lustre: 26236:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 787.208496] Lustre: 26236:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 787.221130] Lustre: 26236:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 787.227799] Lustre: 26236:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 792.372804] Lustre: *** cfs_fail_loc=1603, val=0*** [ 801.276113] Lustre: Failing over lustre-MDT0000 [ 801.649758] Lustre: server umount lustre-MDT0000 complete [ 801.764992] 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 [ 801.780117] Lustre: Skipped 2 previous similar messages [ 801.788552] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 812.224490] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 812.380086] LustreError: MGC192.168.206.105@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 812.800349] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 816.939220] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 818.152481] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 818.154996] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 818.173471] Lustre: Skipped 3 previous similar messages [ 818.206154] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 818.234167] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:297 to 0x280000401:321) [ 818.234421] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:297 to 0x2c0000401:321) [ 825.781922] Lustre: DEBUG MARKER: == sanity-lfsck test 2b: LFSCK can find out and remove invalid linkEA entry ========================================================== 23:20:53 (1788664853) [ 832.574434] Lustre: *** cfs_fail_loc=1604, val=0*** [ 840.477882] Lustre: Failing over lustre-MDT0000 [ 840.808095] Lustre: server umount lustre-MDT0000 complete [ 843.749759] 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 [ 843.757254] LustreError: 26236:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 843.761591] Lustre: Skipped 2 previous similar messages [ 843.762306] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 843.779327] LustreError: 26236:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 21 previous similar messages [ 850.489937] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 850.691509] LustreError: MGC192.168.206.105@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 851.047796] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 854.782291] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 856.034147] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 856.041846] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 856.054476] Lustre: Skipped 3 previous similar messages [ 856.088732] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 856.137580] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:361 to 0x280000401:385) [ 856.138669] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:361 to 0x2c0000401:385) [ 864.338755] Lustre: DEBUG MARKER: == sanity-lfsck test 2c: LFSCK can find out and remove repeated linkEA entry ========================================================== 23:21:32 (1788664892) [ 871.294465] Lustre: *** cfs_fail_loc=1605, val=0*** [ 878.210039] Lustre: Failing over lustre-MDT0000 [ 878.738704] Lustre: server umount lustre-MDT0000 complete [ 881.632416] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 889.990337] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 890.107192] LustreError: MGC192.168.206.105@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 890.466914] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 895.478679] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 895.480868] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 895.490097] Lustre: Skipped 3 previous similar messages [ 895.514742] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 895.559921] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:425 to 0x2c0000401:449) [ 895.563696] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:425 to 0x280000401:449) [ 896.101564] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 905.367122] Lustre: DEBUG MARKER: == sanity-lfsck test 2d: LFSCK can recover the missing linkEA entry ========================================================== 23:22:13 (1788664933) [ 911.991857] Lustre: *** cfs_fail_loc=161d, val=0*** [ 919.780828] Lustre: Failing over lustre-MDT0000 [ 920.044418] Lustre: server umount lustre-MDT0000 complete [ 921.064102] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 921.065336] 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 [ 921.090367] Lustre: Skipped 7 previous similar messages [ 931.347832] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 931.478581] LustreError: MGC192.168.206.105@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 931.734865] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 931.739723] Lustre: Skipped 3 previous similar messages [ 931.774619] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 936.021637] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 936.931780] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 936.941478] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 936.960138] Lustre: Skipped 3 previous similar messages [ 936.980747] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 937.049247] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:489 to 0x2c0000401:513) [ 937.051771] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:489 to 0x280000401:513) [ 944.658088] Lustre: DEBUG MARKER: == sanity-lfsck test 2e: namespace LFSCK can verify remote object linkEA ========================================================== 23:22:53 (1788664973) [ 945.670050] Lustre: 29302:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 945.674780] Lustre: 29302:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 1290 previous similar messages [ 945.681470] Lustre: 29302:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 945.688679] Lustre: 29302:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1290 previous similar messages [ 945.695417] Lustre: 29302:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 945.700642] Lustre: 29302:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1290 previous similar messages [ 945.704537] Lustre: 29302:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 945.711451] Lustre: 29302:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1290 previous similar messages [ 945.716456] Lustre: 29302:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 945.720597] Lustre: 29302:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1290 previous similar messages [ 945.725886] Lustre: 29302:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 945.730663] Lustre: 29302:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1290 previous similar messages [ 946.955420] Lustre: *** cfs_fail_loc=1603, val=0*** [ 958.074941] Lustre: DEBUG MARKER: == sanity-lfsck test 3: LFSCK can verify multiple-linked objects ========================================================== 23:23:06 (1788664986) [ 963.682403] Lustre: *** cfs_fail_loc=1603, val=0*** [ 964.493497] Lustre: *** cfs_fail_loc=1604, val=0*** [ 973.926845] Lustre: DEBUG MARKER: == sanity-lfsck test 4: FID-in-dirent can be rebuilt after MDT file-level backup/restore ========================================================== 23:23:22 (1788665002) [ 1008.509941] Lustre: Failing over lustre-MDT0000 [ 1008.610362] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1008.611200] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1008.614027] Lustre: Skipped 2 previous similar messages [ 1008.697976] Lustre: server umount lustre-MDT0000 complete [ 1013.732247] LustreError: 26241:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1013.764797] LustreError: 26241:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 27 previous similar messages [ 1015.497986] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1025.563494] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1030.114455] Lustre: 16384:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788665043/real 1788665043] req@ffff8e04bcce0700 x1875550581504896/t0(0) o400->MGC192.168.206.105@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1788665059 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1030.140075] LustreError: MGC192.168.206.105@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1037.142417] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1037.167298] Lustre: lustre-MDT0000: reset Object Index mappings [ 1040.698263] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1045.132462] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1045.991110] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1045.994040] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1046.021084] Lustre: Skipped 3 previous similar messages [ 1046.040977] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1046.076197] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:592 to 0x2c0000401:609) [ 1046.081172] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:592 to 0x280000401:609) [ 1048.241653] LustreError: 42887:0:(lfsck_engine.c:1018:lfsck_master_engine()) lustre-MDT0000-osd: master engine fail to verify the .lustre/lost+found/, go ahead: rc = -115 [ 1048.259945] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1050.337237] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1050.338822] Lustre: Skipped 1 previous similar message [ 1057.554141] Lustre: Failing over lustre-MDT0000 [ 1057.752218] Lustre: server umount lustre-MDT0000 complete [ 1061.349566] 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 [ 1061.361427] Lustre: Skipped 5 previous similar messages [ 1068.938291] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1073.708363] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1074.715772] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:592 to 0x2c0000401:641) [ 1074.744217] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:592 to 0x280000401:641) [ 1077.281499] Lustre: *** cfs_fail_loc=1505, val=0*** [ 1084.227417] Lustre: DEBUG MARKER: == sanity-lfsck test 5: LFSCK can handle IGIF object upgrading ========================================================== 23:25:12 (1788665112) [ 1086.767714] Lustre: *** cfs_fail_loc=1504, val=0*** [ 1095.322989] Lustre: Failing over lustre-MDT0000 [ 1095.576499] Lustre: server umount lustre-MDT0000 complete [ 1100.257713] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1100.272424] LustreError: Skipped 1 previous similar message [ 1100.390938] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1110.174393] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1116.640409] Lustre: 16384:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788665130/real 1788665130] req@ffff8e04bfb75880 x1875550581597824/t0(0) o400->MGC192.168.206.105@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1788665146 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1119.892108] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1119.914216] Lustre: lustre-MDT0000: reset Object Index mappings [ 1126.880944] LustreError: 16382:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8e0388f4ca80 x1875550581607168/t0(0) o250->MGC192.168.206.105@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 0 ref 1 fl Rpc:NQU/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1127.335675] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1127.367445] Lustre: Skipped 1 previous similar message [ 1132.120060] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1132.518201] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1132.529155] Lustre: Skipped 1 previous similar message [ 1132.530600] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1132.538673] Lustre: Skipped 7 previous similar messages [ 1132.550830] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1132.556849] Lustre: Skipped 1 previous similar message [ 1132.587316] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:681 to 0x2c0000401:705) [ 1132.588144] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:681 to 0x280000401:705) [ 1136.350490] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1136.351757] Lustre: Skipped 2 previous similar messages [ 1148.883712] Lustre: Failing over lustre-MDT0000 [ 1149.240618] Lustre: server umount lustre-MDT0000 complete [ 1159.833441] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1159.973153] LustreError: MGC192.168.206.105@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1159.978442] LustreError: Skipped 2 previous similar messages [ 1164.471531] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1165.354359] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:681 to 0x2c0000401:737) [ 1165.361310] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:681 to 0x280000401:737) [ 1167.702619] Lustre: *** cfs_fail_loc=1505, val=0*** [ 1167.716067] Lustre: Skipped 84 previous similar messages [ 1174.761974] Lustre: DEBUG MARKER: == sanity-lfsck test 6a: LFSCK resumes from last checkpoint (1) ========================================================== 23:26:43 (1788665203) [ 1181.964622] Lustre: *** cfs_fail_loc=1600, val=1*** [ 1181.968191] Lustre: Skipped 7 previous similar messages [ 1198.293753] Lustre: DEBUG MARKER: == sanity-lfsck test 6b: LFSCK resumes from last checkpoint (2) ========================================================== 23:27:06 (1788665226) [ 1201.679623] Lustre: 44735:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 1201.690823] Lustre: 44735:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 1399 previous similar messages [ 1201.697043] Lustre: 44735:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 1201.702791] Lustre: 44735:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1399 previous similar messages [ 1201.708874] Lustre: 44735:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 1201.714779] Lustre: 44735:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1399 previous similar messages [ 1201.722327] Lustre: 44735:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 1201.728280] Lustre: 44735:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1399 previous similar messages [ 1201.733634] Lustre: 44735:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 1201.739676] Lustre: 44735:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1399 previous similar messages [ 1201.746039] Lustre: 44735:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 1201.751394] Lustre: 44735:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1399 previous similar messages [ 1206.764303] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1206.766840] Lustre: Skipped 7 previous similar messages [ 1230.364903] Lustre: DEBUG MARKER: == sanity-lfsck test 7a: non-stopped LFSCK should auto restarts after MDS remount (1) ========================================================== 23:27:38 (1788665258) [ 1240.710818] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1240.715345] Lustre: Skipped 12 previous similar messages [ 1246.218896] Lustre: Failing over lustre-MDT0000 [ 1246.458867] Lustre: server umount lustre-MDT0000 complete [ 1247.211053] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1247.222341] LustreError: Skipped 1 previous similar message [ 1255.342644] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1255.681641] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1255.689522] Lustre: Skipped 4 previous similar messages [ 1255.711812] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1255.731912] Lustre: Skipped 1 previous similar message [ 1259.617071] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1261.028456] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1261.033076] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1261.034700] Lustre: Skipped 1 previous similar message [ 1261.046259] Lustre: Skipped 7 previous similar messages [ 1261.067549] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1261.079760] Lustre: Skipped 1 previous similar message [ 1261.148357] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:854 to 0x2c0000401:897) [ 1261.150210] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:853 to 0x280000401:897) [ 1267.567415] Lustre: DEBUG MARKER: == sanity-lfsck test 7b: non-stopped LFSCK should auto restarts after MDS remount (2) ========================================================== 23:28:15 (1788665295) [ 1279.794297] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing load_modules_local [ 1295.785497] Lustre: 52902:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 1319.047533] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1322.264300] Lustre: 54039:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 1330.429267] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1330.435368] Lustre: Skipped 81 previous similar messages [ 1333.200335] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1334.240172] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1335.264258] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1337.157430] Lustre: Failing over lustre-MDT0000 [ 1337.377649] Lustre: server umount lustre-MDT0000 complete [ 1337.824515] 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 [ 1337.835428] Lustre: Skipped 14 previous similar messages [ 1337.843249] LustreError: 26242:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1337.853557] LustreError: 26242:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 79 previous similar messages [ 1346.533561] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1351.686931] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1352.251316] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:946 to 0x2c0000401:961) [ 1352.251320] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:947 to 0x280000401:993) [ 1360.560667] Lustre: DEBUG MARKER: == sanity-lfsck test 8: LFSCK state machine ============== 23:29:49 (1788665389) [ 1362.419810] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1362.427892] Lustre: Skipped 4 previous similar messages [ 1367.524319] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1367.529836] Lustre: Skipped 3 previous similar messages [ 1368.680939] Lustre: server umount lustre-MDT0000 complete [ 1372.083388] LustreError: 37054:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788665401 with bad export cookie 17171417915441067338 [ 1372.095596] LustreError: 37054:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 1372.502478] Lustre: server umount lustre-MDT0001 complete [ 1386.915658] Lustre: server umount lustre-OST0000 complete [ 1389.025098] Lustre: 16385:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788665402/real 1788665402] req@ffff8e0487468a80 x1875550581911552/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788665418 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1391.252762] Lustre: server umount lustre-OST0001 complete [ 1400.032834] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_hostid [ 1409.979137] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing load_modules_local [ 1458.689797] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing load_modules_local [ 1469.996910] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1470.319789] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 1470.353476] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 1470.444466] Lustre: lustre-MDT0000: new disk, initializing [ 1470.577074] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 1474.944134] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1485.969989] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1486.056927] Lustre: 59099: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 [ 1486.086086] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 1486.089988] Lustre: Skipped 1 previous similar message [ 1486.149063] Lustre: lustre-MDT0001: new disk, initializing [ 1486.276934] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 1486.301432] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 1490.305128] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1494.945418] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 1500.960916] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 1501.199495] Lustre: lustre-OST0000: new disk, initializing [ 1501.203919] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 1501.218131] Lustre: 60730:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 1503.249793] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 1503.259028] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 1503.330561] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 1507.801729] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1518.922159] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 1519.068615] Lustre: lustre-OST0001: new disk, initializing [ 1519.075308] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 1519.082862] Lustre: 61602:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 1521.140442] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 1521.160941] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 1521.262798] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 1525.552424] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1535.615137] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1539.357548] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 1548.060445] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1549.092629] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1549.098566] Lustre: Skipped 19 previous similar messages [ 1553.279748] Lustre: *** cfs_fail_loc=1601, val=2*** [ 1553.282041] Lustre: Skipped 5 previous similar messages [ 1572.385803] Lustre: Failing over lustre-MDT0000 [ 1572.618925] Lustre: server umount lustre-MDT0000 complete [ 1573.349985] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1573.361333] LustreError: Skipped 2 previous similar messages [ 1581.292190] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1581.362616] LustreError: MGC192.168.206.105@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1581.371878] LustreError: Skipped 3 previous similar messages [ 1581.643827] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1581.661722] Lustre: Skipped 1 previous similar message [ 1585.992660] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1586.658669] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1586.663601] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1586.669770] Lustre: Skipped 1 previous similar message [ 1586.685613] Lustre: Skipped 7 previous similar messages [ 1586.719646] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1586.725939] Lustre: Skipped 1 previous similar message [ 1586.764806] Lustre: *** cfs_fail_loc=160b, val=2*** [ 1586.773942] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:65) [ 1586.781817] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:65) [ 1593.113982] Lustre: Failing over lustre-MDT0000 [ 1595.365702] Lustre: server umount lustre-MDT0000 complete [ 1603.043783] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1608.013453] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1608.735557] Lustre: *** cfs_fail_loc=160b, val=2*** [ 1608.746446] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:97) [ 1608.746736] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:97) [ 1613.193384] Lustre: Failing over lustre-MDT0000 [ 1615.430230] Lustre: server umount lustre-MDT0000 complete [ 1623.820324] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1624.032768] Lustre: lustre-MDT0000: Not available for connect from 0@lo (not set up) [ 1624.039614] Lustre: Skipped 3 previous similar messages [ 1628.764349] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1629.738477] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:129) [ 1629.742277] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:129) [ 1634.014589] Lustre: *** cfs_fail_loc=1602, val=2*** [ 1634.021304] Lustre: Skipped 1 previous similar message [ 1646.084996] Lustre: DEBUG MARKER: == sanity-lfsck test 9a: LFSCK speed control (1) ========= 23:34:34 (1788665674) [ 1659.472415] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing load_modules_local [ 1674.690186] Lustre: 68605:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 1698.305727] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1702.373114] Lustre: 69742:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 1714.054937] Lustre: 61112:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 252 < left 278, rollback = 2 [ 1714.067141] Lustre: 61112:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 2351 previous similar messages [ 1714.073765] Lustre: 61112:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 1714.080270] Lustre: 61112:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 2352 previous similar messages [ 1714.092887] Lustre: 61112:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 1714.097558] Lustre: 61112:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 2352 previous similar messages [ 1714.102295] Lustre: 61112:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/1, punch: 0/0/0, quota 1/3/2 [ 1714.108016] Lustre: 61112:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 2352 previous similar messages [ 1714.113108] Lustre: 61112:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/1, delete: 0/0/0 [ 1714.120234] Lustre: 61112:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 2352 previous similar messages [ 1714.124862] Lustre: 61112:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 1714.129155] Lustre: 61112:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 2352 previous similar messages [ 1817.701628] Lustre: DEBUG MARKER: == sanity-lfsck test 9b: LFSCK speed control (2) ========= 23:37:25 (1788665845) [ 1866.035510] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1866.041053] Lustre: Skipped 4 previous similar messages [ 1889.028355] Lustre: *** cfs_fail_loc=160c, val=0*** [ 1889.031636] Lustre: Skipped 8 previous similar messages [ 1924.318202] Lustre: DEBUG MARKER: == sanity-lfsck test 10: System is available during LFSCK scanning ========================================================== 23:39:12 (1788665952) [ 1971.327948] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1979.327733] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1979.332718] Lustre: Skipped 452 previous similar messages [ 1995.329665] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1995.334088] Lustre: Skipped 863 previous similar messages [ 2027.399991] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2027.412508] Lustre: Skipped 1715 previous similar messages [ 2036.849215] Lustre: *** cfs_fail_loc=1604, val=0*** [ 2036.851327] Lustre: Skipped 2599 previous similar messages [ 2277.270242] Lustre: DEBUG MARKER: == sanity-lfsck test 11a: LFSCK can rebuild lost last_id ========================================================== 23:45:05 (1788666305) [ 2315.165578] Lustre: 59107:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 320, rollback = 2 [ 2315.173870] Lustre: 59107:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 36825 previous similar messages [ 2315.182732] Lustre: 59107:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 1/4/0 [ 2315.186861] Lustre: 59107:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 36825 previous similar messages [ 2315.193301] Lustre: 59107:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 5/5/0, xattr_set: 7/320/0 [ 2315.200502] Lustre: 59107:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 36825 previous similar messages [ 2315.206439] Lustre: 59107:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 6/46/0, punch: 0/0/0, quota 1/3/0 [ 2315.213546] Lustre: 59107:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 36825 previous similar messages [ 2315.218825] Lustre: 59107:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 2/5/0 [ 2315.223376] Lustre: 59107:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 36825 previous similar messages [ 2315.229153] Lustre: 59107:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 1/1/0, ref_del: 2/2/1 [ 2315.233368] Lustre: 59107:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 36825 previous similar messages [ 2441.697026] 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 [ 2441.709149] Lustre: Skipped 20 previous similar messages [ 2441.717552] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2441.732307] Lustre: Skipped 3 previous similar messages [ 2446.314342] Lustre: server umount lustre-MDT0000 complete [ 2446.817544] LustreError: 70168:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 2446.846390] LustreError: 70168:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 27 previous similar messages [ 2451.008779] LustreError: 69745:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788666480 with bad export cookie 17171417915441086441 [ 2451.025554] LustreError: MGC192.168.206.105@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2451.031553] LustreError: 69745:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 2451.065913] LustreError: Skipped 2 previous similar messages [ 2451.302412] Lustre: server umount lustre-MDT0001 complete [ 2465.977806] Lustre: server umount lustre-OST0000 complete [ 2467.297142] Lustre: 16384:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788666481/real 1788666481] req@ffff8e038ca45180 x1875550585721728/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788666497 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2469.824500] Lustre: server umount lustre-OST0001 complete [ 2476.919799] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: (null) [ 2489.113134] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 2504.992580] LustreError: Failed to get MGS log lustre-sptlrpc and no local copy. [ 2510.112758] LustreError: 75035:0:(mgc_request.c:233:do_config_log_add()) MGC192.168.206.105@tcp: failed processing log, type 4: rc = -110 [ 2535.840311] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 2535.850033] Lustre: Skipped 8 previous similar messages [ 2542.105854] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2545.926616] Lustre: 75618: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. [ 2545.938388] Lustre: *** cfs_fail_loc=160e, val=3*** [ 2548.973470] Lustre: 75618:0:(ofd_dev.c:573:ofd_lfsck_out_notify()) lustre-OST0000: Rebuilt crashed LAST_ID files successfully. [ 2558.500960] Lustre: DEBUG MARKER: == sanity-lfsck test 11b: LFSCK can rebuild crashed last_id ========================================================== 23:49:46 (1788666586) [ 2574.785366] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing load_modules_local [ 2585.037857] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2585.667034] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3271 to 0x280000401:3297) [ 2590.536147] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2599.132888] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2603.911757] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2606.660609] Lustre: 78286:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 2619.244782] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2619.429846] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 2619.435929] Lustre: Skipped 2 previous similar messages [ 2624.505498] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3208 to 0x2c0000401:3233) [ 2624.652433] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2630.803839] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 2634.017762] Lustre: 79781:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 2638.386102] Lustre: *** cfs_fail_loc=160d, val=0*** [ 2645.510227] Lustre: Failing over lustre-OST0000 [ 2645.785537] Lustre: server umount lustre-OST0000 complete [ 2647.011404] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 2647.019724] LustreError: Skipped 2 previous similar messages [ 2655.745589] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2656.012706] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 2656.026142] Lustre: Skipped 2 previous similar messages [ 2657.573451] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 2657.580533] Lustre: Skipped 2 previous similar messages [ 2657.594441] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 2657.594909] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 2657.598676] Lustre: *** cfs_fail_loc=215, val=0*** [ 2657.599186] Lustre: Skipped 11 previous similar messages [ 2657.605792] Lustre: Skipped 2 previous similar messages [ 2661.238290] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2662.880548] Lustre: *** cfs_fail_loc=215, val=0*** [ 2662.889838] Lustre: Skipped 3 previous similar messages [ 2664.641041] Lustre: 81181: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. [ 2664.684820] Lustre: 81181:0:(ofd_dev.c:573:ofd_lfsck_out_notify()) lustre-OST0000: Rebuilt crashed LAST_ID files successfully. [ 2667.223578] Lustre: Failing over lustre-OST0000 [ 2667.377972] Lustre: server umount lustre-OST0000 complete [ 2675.178064] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2676.662232] Lustre: *** cfs_fail_loc=215, val=0*** [ 2676.665329] Lustre: Skipped 2 previous similar messages [ 2681.433244] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2681.824733] Lustre: *** cfs_fail_loc=215, val=0*** [ 2681.831677] Lustre: Skipped 1 previous similar message [ 2691.049174] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2691.054550] Lustre: Skipped 2 previous similar messages [ 2693.377712] Lustre: server umount lustre-MDT0000 complete [ 2696.853092] LustreError: 75043:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788666726 with bad export cookie 17171417915442660797 [ 2696.884966] LustreError: 75043:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 3 previous similar messages [ 2697.175575] Lustre: server umount lustre-MDT0001 complete [ 2710.619977] Lustre: server umount lustre-OST0000 complete [ 2724.614076] Lustre: server umount lustre-OST0001 complete [ 2732.935268] Lustre: DEBUG MARKER: == sanity-lfsck test 12a: single command to trigger LFSCK on all devices ========================================================== 23:52:41 (1788666761) [ 2746.586936] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing load_modules_local [ 2755.497126] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2755.890398] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 2755.895525] Lustre: Skipped 2 previous similar messages [ 2759.563694] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2767.228115] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2771.357395] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2774.213172] Lustre: 85568:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 2779.788485] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2781.112612] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3362 to 0x280000401:3393) [ 2786.064484] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2793.874949] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2799.089026] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3208 to 0x2c0000401:3265) [ 2799.803229] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2807.236619] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 2810.292990] Lustre: 87435:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 2838.789726] Lustre: DEBUG MARKER: == sanity-lfsck test 12b: auto detect Lustre device ====== 23:54:27 (1788666867) [ 2853.314835] Lustre: DEBUG MARKER: == sanity-lfsck test 13: LFSCK can repair crashed lmm_oi ========================================================== 23:54:41 (1788666881) [ 2854.414081] Lustre: *** cfs_fail_loc=160f, val=0*** [ 2864.623757] Lustre: DEBUG MARKER: == sanity-lfsck test 14a: LFSCK can repair MDT-object with dangling LOV EA reference (1) ========================================================== 23:54:52 (1788666892) [ 2868.731567] Lustre: *** cfs_fail_loc=1610, val=0*** [ 2868.734681] Lustre: Skipped 7 previous similar messages [ 2916.323065] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2921.723055] Lustre: server umount lustre-MDT0000 complete [ 2924.790765] LustreError: 84405:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788666954 with bad export cookie 17171417915442669281 [ 2924.802091] LustreError: 84405:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 2925.050282] Lustre: server umount lustre-MDT0001 complete [ 2938.613420] Lustre: server umount lustre-OST0000 complete [ 2952.070071] Lustre: server umount lustre-OST0001 complete [ 2965.879977] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing load_modules_local [ 2974.304704] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2977.957464] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2985.648825] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2990.308342] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2992.840474] Lustre: 93298:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 2999.298535] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3004.925528] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3010.867176] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:116 to 0x280000400:161) [ 3013.077986] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3013.235433] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 3013.239538] Lustre: Skipped 6 previous similar messages [ 3018.727641] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:116 to 0x2c0000400:161) [ 3019.130166] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3019.763088] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3554 to 0x280000401:3585) [ 3019.775491] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3317 to 0x2c0000401:3361) [ 3025.587833] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3028.290942] Lustre: 95167:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 3033.554187] Lustre: DEBUG MARKER: == sanity-lfsck test 14b: LFSCK can repair MDT-object with dangling LOV EA reference (2) ========================================================== 23:57:42 (1788667062) [ 3035.463956] Lustre: 94849:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 256 < left 278, rollback = 2 [ 3035.473740] Lustre: 94849:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 1360 previous similar messages [ 3035.479692] Lustre: 94849:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 3035.483782] Lustre: 94849:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1360 previous similar messages [ 3035.489946] Lustre: 94849:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3035.498014] Lustre: 94849:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1360 previous similar messages [ 3035.506264] Lustre: 94849:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 3035.515358] Lustre: 94849:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1360 previous similar messages [ 3035.530179] Lustre: 94849:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 3035.538842] Lustre: 94849:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1360 previous similar messages [ 3035.545057] Lustre: 94849:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3035.552588] Lustre: 94849:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1360 previous similar messages [ 3038.433149] Lustre: *** cfs_fail_loc=1610, val=0*** [ 3038.438504] Lustre: Skipped 63 previous similar messages [ 3060.714191] 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 [ 3060.716368] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3060.728728] Lustre: Skipped 19 previous similar messages [ 3060.740342] Lustre: Skipped 6 previous similar messages [ 3064.810933] Lustre: server umount lustre-MDT0000 complete [ 3065.831351] LustreError: 94934:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3065.844902] LustreError: 94934:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 44 previous similar messages [ 3068.097453] LustreError: 92140:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788667098 with bad export cookie 17171417915442697673 [ 3068.103791] LustreError: MGC192.168.206.105@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3068.108778] LustreError: 92140:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 3 previous similar messages [ 3068.133124] LustreError: Skipped 2 previous similar messages [ 3068.410626] Lustre: server umount lustre-MDT0001 complete [ 3081.252683] Lustre: server umount lustre-OST0000 complete [ 3094.858673] Lustre: server umount lustre-OST0001 complete [ 3110.632136] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing load_modules_local [ 3119.537057] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3123.698161] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3131.930054] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3136.294342] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3139.091411] Lustre: 99202:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3146.005473] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3152.404768] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3157.549684] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:116 to 0x280000400:193) [ 3159.635500] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3165.007055] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3682 to 0x280000401:3713) [ 3165.014768] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:116 to 0x2c0000400:193) [ 3165.019138] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3317 to 0x2c0000401:3393) [ 3165.941898] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3172.305797] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3181.934538] Lustre: DEBUG MARKER: == sanity-lfsck test 15a: LFSCK can repair unmatched MDT-object/OST-object pairs (1) ========================================================== 00:00:10 (1788667210) [ 3185.120465] Lustre: *** cfs_fail_loc=1611, val=0*** [ 3185.123387] Lustre: Skipped 63 previous similar messages [ 3185.338570] Lustre: *** cfs_fail_loc=1611, val=0*** [ 3195.048426] Lustre: DEBUG MARKER: == sanity-lfsck test 15b: LFSCK can repair unmatched MDT-object/OST-object pairs (2) ========================================================== 00:00:23 (1788667223) [ 3197.177285] Lustre: *** cfs_fail_loc=1612, val=0*** [ 3197.231031] Lustre: *** cfs_fail_loc=1612, val=0*** [ 3197.233819] Lustre: Skipped 2 previous similar messages [ 3207.949810] Lustre: DEBUG MARKER: == sanity-lfsck test 15c: LFSCK can repair unmatched MDT-object/OST-object pairs (3) ========================================================== 00:00:36 (1788667236) [ 3209.313355] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_15c MDS newer than 2.7.55, LU-6475 [ 3210.779846] Lustre: DEBUG MARKER: == sanity-lfsck test 15d: LFSCK don't crash upon dir migration failure ========================================================== 00:00:39 (1788667239) [ 3216.846309] Lustre: *** cfs_fail_loc=1709, val=0*** [ 3216.923784] LustreError: 98072:0:(osp_object.c:618:osp_attr_get()) lustre-MDT0000-osp-MDT0001: osp_attr_get update error [0x200003ab2:0x1:0x0]: rc = -5 [ 3216.933903] LustreError: 98072:0:(mdt_reint.c:2644:mdt_reint_migrate()) lustre-MDT0001: migrate [0x240002340:0x6c:0x0]/s88 failed: rc = -5 [ 3233.254926] LustreError: 98057:0:(lod_object.c:945:lod_load_lmv_shards()) lustre-MDT0001-mdtlov: the shard [0x200003ab1:0x60:0x0]:1 for the striped directory [0x240002340:0x84:0x0] is out of the known LMV EA range [0 - 0], failout [ 3240.597474] LustreError: 100382:0:(lod_object.c:945:lod_load_lmv_shards()) lustre-MDT0001-mdtlov: the shard [0x200003ab1:0x60:0x0]:1 for the striped directory [0x240002340:0x84:0x0] is out of the known LMV EA range [0 - 0], failout [ 3240.616179] LustreError: 100382:0:(mdt_handler.c:1498:mdt_getattr_internal()) lustre-MDT0001: getattr error for [0x240002340:0x84:0x0]: rc = -5 [ 3275.745238] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3275.754042] LustreError: Skipped 3 previous similar messages [ 3275.771763] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3281.043474] Lustre: server umount lustre-MDT0000 complete [ 3288.349442] LustreError: 98043:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788667318 with bad export cookie 17171417915442712401 [ 3288.359033] LustreError: 98043:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 3 previous similar messages [ 3288.610402] Lustre: server umount lustre-MDT0001 complete [ 3306.840726] Lustre: server umount lustre-OST0000 complete [ 3309.537638] Lustre: 16384:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788667323/real 1788667323] req@ffff8e04ae7caa00 x1875550586617216/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788667339 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3314.327318] Lustre: server umount lustre-OST0001 complete [ 3328.757970] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing unload_modules_local [ 3331.193289] Key type lgssc unregistered [ 3331.456649] LNet: 104918:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 3331.461532] LNetError: 104918:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 3331.473976] LNet: Removed LNI 192.168.206.105@tcp [ 3332.243320] Key type .llcrypt unregistered [ 3332.248401] Key type ._llcrypt unregistered [ 3352.653763] Key type ._llcrypt registered [ 3352.656102] Key type .llcrypt registered [ 3352.727319] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_hostid [ 3363.767676] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing load_modules_local [ 3364.523304] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 3364.541248] alg: No test for adler32 (adler32-zlib) [ 3365.568424] Lustre: Lustre: Build Version: 2.17.58_4_g3b30273 [ 3365.855131] LNet: Added LNI 192.168.206.105@tcp [8/256/0/180] [ 3367.500891] Key type lgssc registered [ 3368.562259] Lustre: Echo OBD driver; http://www.lustre.org/ [ 3410.182266] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing load_modules_local [ 3422.132113] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 3422.166493] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3423.404902] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 3423.431663] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 3423.515677] Lustre: lustre-MDT0000: new disk, initializing [ 3423.585532] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3423.601614] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 3427.477959] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3439.799544] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3439.902605] Lustre: 109346:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 3439.962325] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 3439.965916] Lustre: Skipped 1 previous similar message [ 3440.079535] Lustre: lustre-MDT0001: new disk, initializing [ 3440.177621] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 3440.202524] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 3440.213292] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 3445.257224] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3450.595029] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 3460.783827] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3461.037818] Lustre: lustre-OST0000: new disk, initializing [ 3461.040910] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 3461.044371] Lustre: 111285:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 3461.107408] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 3462.068566] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 3462.076710] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 3462.143290] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 3466.831316] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3479.585767] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3479.678611] Lustre: lustre-OST0001: new disk, initializing [ 3479.681962] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 3479.686220] Lustre: 112309:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 3479.736983] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 3486.432600] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3486.772528] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 3486.788212] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 3486.863319] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 3498.548682] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3503.603511] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 3510.414800] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 00:05:38 (1788667538) === [ 3516.834001] Lustre: DEBUG MARKER: == sanity-lfsck test 16: LFSCK can repair inconsistent MDT-object/OST-object owner ========================================================== 00:05:45 (1788667545) [ 3517.055417] Lustre: 113205:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 251 < left 278, rollback = 2 [ 3517.062455] Lustre: 113205:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 3517.079494] Lustre: 113205:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3517.092249] Lustre: 113205:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 3517.112788] Lustre: 113205:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 3517.128484] Lustre: 113205:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3517.813809] Lustre: 109351:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 252 < left 278, rollback = 2 [ 3517.833811] Lustre: 109351:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 9 previous similar messages [ 3517.846419] Lustre: 109351:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 3517.858696] Lustre: 109351:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3517.865164] Lustre: 109351:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3517.874774] Lustre: 109351:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3517.884954] Lustre: 109351:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/1, punch: 0/0/0, quota 7/369/2 [ 3517.895699] Lustre: 109351:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3517.906629] Lustre: 109351:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/1, delete: 0/0/0 [ 3517.913349] Lustre: 109351:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3517.927235] Lustre: 109351:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3517.935501] Lustre: 109351:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3518.816866] Lustre: 113205:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 3518.823491] Lustre: 113205:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 152 previous similar messages [ 3518.848839] Lustre: 112836:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 3518.854415] Lustre: 112836:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 158 previous similar messages [ 3518.868241] Lustre: 113205:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3518.873900] Lustre: 113205:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 161 previous similar messages [ 3518.890421] Lustre: 109353:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 7/369/0 [ 3518.895962] Lustre: 109353:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 164 previous similar messages [ 3518.908990] Lustre: 112836:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 3518.917329] Lustre: 112836:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 167 previous similar messages [ 3518.931881] Lustre: 113205:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3518.936863] Lustre: 113205:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 170 previous similar messages [ 3520.437730] Lustre: *** cfs_fail_loc=1613, val=0*** [ 3530.149263] Lustre: DEBUG MARKER: == sanity-lfsck test 17: LFSCK can repair multiple references ========================================================== 00:05:58 (1788667558) [ 3531.253546] Lustre: 112836:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 257 < left 278, rollback = 2 [ 3531.261778] Lustre: 112836:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 146 previous similar messages [ 3531.270083] Lustre: 112836:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 3531.275503] Lustre: 112836:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 140 previous similar messages [ 3531.287684] Lustre: 112836:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3531.296371] Lustre: 112836:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 137 previous similar messages [ 3531.304371] Lustre: 112836:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 3531.311453] Lustre: 112836:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 134 previous similar messages [ 3531.319817] Lustre: 112836:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 3531.331705] Lustre: 112836:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 131 previous similar messages [ 3531.340575] Lustre: 112836:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3531.348549] Lustre: 112836:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 128 previous similar messages [ 3532.394952] Lustre: *** cfs_fail_loc=1614, val=0*** [ 3535.745939] Lustre: 111276:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 259 < left 275, rollback = 2 [ 3535.757172] Lustre: 111276:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 11 previous similar messages [ 3535.762330] Lustre: 111276:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 3535.766344] Lustre: 111276:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3535.770381] Lustre: 111276:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/1, xattr_set: 3/275/0 [ 3535.774695] Lustre: 111276:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3535.778806] Lustre: 111276:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/9/0, punch: 1/4/0, quota 7/225/0 [ 3535.785731] Lustre: 111276:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3535.793124] Lustre: 111276:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 3535.798137] Lustre: 111276:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3535.804543] Lustre: 111276:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3535.810236] Lustre: 111276:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3542.168671] Lustre: DEBUG MARKER: == sanity-lfsck test 18a: Find out orphan OST-object and repair it (1) ========================================================== 00:06:10 (1788667570) [ 3544.551265] Lustre: *** cfs_fail_loc=1615, val=0*** [ 3544.554166] Lustre: Skipped 1 previous similar message [ 3561.883467] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_18b skipping excluded test 18b [ 3563.298592] Lustre: DEBUG MARKER: == sanity-lfsck test 18c: Find out orphan OST-object and repair it (3) ========================================================== 00:06:31 (1788667591) [ 3563.878995] Lustre: 109353:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 3563.884324] Lustre: 109353:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 23 previous similar messages [ 3563.887879] Lustre: 109353:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 3563.891721] Lustre: 109353:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 23 previous similar messages [ 3563.895817] Lustre: 109353:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3563.900396] Lustre: 109353:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 23 previous similar messages [ 3563.905618] Lustre: 109353:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 3563.910747] Lustre: 109353:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 23 previous similar messages [ 3563.915228] Lustre: 109353:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 3563.920120] Lustre: 109353:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 23 previous similar messages [ 3563.930910] Lustre: 109353:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3563.935227] Lustre: 109353:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 23 previous similar messages [ 3566.179314] Lustre: *** cfs_fail_loc=1617, val=0*** [ 3566.250146] Lustre: *** cfs_fail_loc=1617, val=0*** [ 3568.419972] Lustre: *** cfs_fail_loc=1616, val=0*** [ 3568.422701] Lustre: Skipped 5 previous similar messages [ 3587.579200] Lustre: DEBUG MARKER: == sanity-lfsck test 18d: Find out orphan OST-object and repair it (4) ========================================================== 00:06:55 (1788667615) [ 3587.989359] Lustre: 113205:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 3587.997902] Lustre: 113205:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 24 previous similar messages [ 3588.003967] Lustre: 113205:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 3588.009645] Lustre: 113205:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 24 previous similar messages [ 3588.020512] Lustre: 113205:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3588.027025] Lustre: 113205:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 24 previous similar messages [ 3588.032732] Lustre: 113205:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 3588.040942] Lustre: 113205:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 24 previous similar messages [ 3588.046183] Lustre: 113205:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 3588.054586] Lustre: 113205:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 24 previous similar messages [ 3588.060271] Lustre: 113205:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3588.065498] Lustre: 113205:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 24 previous similar messages [ 3589.676537] Lustre: *** cfs_fail_loc=1618, val=0*** [ 3589.681774] Lustre: Skipped 5 previous similar messages [ 3624.417614] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3624.436332] 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 [ 3624.452790] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3628.996709] Lustre: server umount lustre-MDT0000 complete [ 3632.826661] LustreError: 109338:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788667662 with bad export cookie 14884967291984942240 [ 3632.827575] LustreError: MGC192.168.206.105@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3632.840563] LustreError: 109338:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 3633.259106] Lustre: server umount lustre-MDT0001 complete [ 3648.011237] Lustre: server umount lustre-OST0000 complete [ 3651.429799] Lustre: 106508:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788667665/real 1788667665] req@ffff8e038ba33b80 x1875553702584704/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788667681 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3651.476425] 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 [ 3651.488115] Lustre: Skipped 3 previous similar messages [ 3652.372743] Lustre: server umount lustre-OST0001 complete [ 3666.320653] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing load_modules_local [ 3675.428915] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3675.797571] LustreError: 118023:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3675.822636] LustreError: 118023:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 5 previous similar messages [ 3675.862980] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3679.545773] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3681.249477] LustreError: 118024:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3685.347793] LustreError: 118023:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3686.373534] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3686.554311] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 3689.881654] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3692.147912] Lustre: 119162:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3697.338187] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3700.647075] LustreError: 119515:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3700.659762] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:116 to 0x280000401:161) [ 3702.469937] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3705.828867] LustreError: 119515:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3709.932540] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3710.075506] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 3710.080987] Lustre: Skipped 1 previous similar message [ 3712.106967] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:4 to 0x2c0000401:33) [ 3712.109337] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:33) [ 3712.111902] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:4 to 0x280000400:33) [ 3715.395908] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3721.871709] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3724.770639] Lustre: 121033:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 3736.643425] Lustre: DEBUG MARKER: == sanity-lfsck test 18e: Find out orphan OST-object and repair it (5) ========================================================== 00:09:25 (1788667765) [ 3736.943865] Lustre: 118018:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 251 < left 278, rollback = 2 [ 3736.948684] Lustre: 118018:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 21 previous similar messages [ 3736.953832] Lustre: 118018:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 3736.970627] Lustre: 118018:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3736.982580] Lustre: 118018:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3736.988837] Lustre: 118018:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3736.995511] Lustre: 118018:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 3737.001063] Lustre: 118018:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3737.005685] Lustre: 118018:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 3737.010517] Lustre: 118018:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3737.014880] Lustre: 118018:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3737.019440] Lustre: 118018:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3738.545865] Lustre: *** cfs_fail_loc=1618, val=0*** [ 3738.548822] Lustre: Skipped 3 previous similar messages [ 3773.924734] 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 [ 3773.926833] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3773.929825] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3773.929833] Lustre: Skipped 3 previous similar messages [ 3773.941485] Lustre: Skipped 1 previous similar message [ 3777.441362] Lustre: server umount lustre-MDT0000 complete [ 3779.049095] LustreError: 118020:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3779.074239] LustreError: 118020:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 3 previous similar messages [ 3781.641212] LustreError: 118006:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788667811 with bad export cookie 14884967291984957486 [ 3781.654105] LustreError: MGC192.168.206.105@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3781.656365] LustreError: 118006:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 3782.146185] Lustre: server umount lustre-MDT0001 complete [ 3796.475945] Lustre: server umount lustre-OST0000 complete [ 3809.496698] Lustre: server umount lustre-OST0001 complete [ 3824.949960] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing load_modules_local [ 3834.994771] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3835.543102] LustreError: 123608:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3835.646925] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3839.965926] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3848.471822] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3852.987374] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3855.639393] Lustre: 124748:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3861.692725] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3868.815903] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3873.127977] LustreError: 125101:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3873.142447] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:4 to 0x280000400:65) [ 3873.159719] LustreError: 125101:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 2 previous similar messages [ 3878.191752] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3881.577100] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:166 to 0x280000401:193) [ 3881.591948] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:4 to 0x2c0000401:65) [ 3881.604517] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:65) [ 3884.806388] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3892.301716] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3895.916801] Lustre: 126618:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 3900.856617] Lustre: 125995:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 252 < left 260, rollback = 2 [ 3900.880854] Lustre: 125995:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 21 previous similar messages [ 3900.890227] Lustre: 125995:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 3900.900649] Lustre: 125995:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3900.916768] Lustre: 125995:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 0/0/0, xattr_set: 1/260/0 [ 3900.923094] Lustre: 125995:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3900.931212] Lustre: 125995:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/9/0, punch: 0/0/0, quota 4/150/2 [ 3900.937880] Lustre: 125995:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3900.944841] Lustre: 125995:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 1/17/2, delete: 0/0/0 [ 3900.948470] Lustre: *** cfs_fail_loc=1602, val=10*** [ 3900.958689] Lustre: 125995:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3900.958711] Lustre: 125995:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3900.958716] Lustre: 125995:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3925.713678] Lustre: DEBUG MARKER: == sanity-lfsck test 18f: Skip the failed OST(s) when handle orphan OST-objects ========================================================== 00:12:33 (1788667953) [ 3929.004510] Lustre: *** cfs_fail_loc=1616, val=0*** [ 3929.008418] Lustre: Skipped 3 previous similar messages [ 3935.820704] Lustre: *** cfs_fail_loc=161c, val=0*** [ 3935.827649] Lustre: Skipped 1 previous similar message [ 3953.542856] Lustre: DEBUG MARKER: == sanity-lfsck test 18g: Find out orphan OST-object and repair it (7) ========================================================== 00:13:01 (1788667981) [ 3955.372575] Lustre: *** cfs_fail_loc=162e, val=0*** [ 3955.379399] Lustre: *** cfs_fail_loc=162e, val=0*** [ 3955.385205] Lustre: Skipped 7 previous similar messages [ 3968.033868] Lustre: DEBUG MARKER: == sanity-lfsck test 18h: LFSCK can repair crashed PFL extent range ========================================================== 00:13:16 (1788667996) [ 3987.802211] Lustre: DEBUG MARKER: == sanity-lfsck test 19a: OST-object inconsistency self detect ========================================================== 00:13:35 (1788668015) [ 3999.784602] Lustre: DEBUG MARKER: == sanity-lfsck test 19b: OST-object inconsistency self repair ========================================================== 00:13:47 (1788668027) [ 4003.477647] Lustre: *** cfs_fail_loc=1611, val=0*** [ 4003.545751] Lustre: *** cfs_fail_loc=1611, val=0*** [ 4003.552788] Lustre: Skipped 3 previous similar messages [ 4009.116149] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.206.5@tcp inode [0x2000013a1:0x1f:0x0] object 0x280000401:202 extent [0-4095], client returned csum 0 (type 4), server csum 703fb3ad (type 4) [ 4010.030310] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.206.5@tcp inode [0x2000013a1:0x20:0x0] object 0x280000401:203 extent [0-4095], client returned csum 0 (type 4), server csum 7cbb935c (type 4) [ 4017.913394] Lustre: DEBUG MARKER: == sanity-lfsck test 20a: Handle the orphan with dummy LOV EA slot properly ========================================================== 00:14:06 (1788668046) [ 4020.104736] Lustre: *** cfs_fail_loc=1616, val=0*** [ 4020.109258] Lustre: Skipped 3 previous similar messages [ 4033.944933] Lustre: 123604:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 254 < left 278, rollback = 2 [ 4033.955137] Lustre: 123604:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 131 previous similar messages [ 4033.964632] Lustre: 123604:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4033.987408] Lustre: 123604:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 131 previous similar messages [ 4034.010696] Lustre: 123604:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4034.038500] Lustre: 123604:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 131 previous similar messages [ 4034.051699] Lustre: 123604:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/1, punch: 0/0/0, quota 1/3/0 [ 4034.075690] Lustre: 123604:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 131 previous similar messages [ 4034.099616] Lustre: 123604:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/1, delete: 0/0/0 [ 4034.128138] Lustre: 123604:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 131 previous similar messages [ 4034.139501] Lustre: 123604:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 4034.159942] Lustre: 123604:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 131 previous similar messages [ 4043.753813] Lustre: DEBUG MARKER: == sanity-lfsck test 20b: Handle the orphan with dummy LOV EA slot properly - PFL case ========================================================== 00:14:32 (1788668072) [ 4049.503625] Lustre: DEBUG MARKER: == sanity-lfsck test 21: run all LFSCK components by default ========================================================== 00:14:37 (1788668077) [ 4062.352954] Lustre: DEBUG MARKER: == sanity-lfsck test 22a: LFSCK can repair unmatched pairs (1) ========================================================== 00:14:50 (1788668090) [ 4065.046755] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4065.055940] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4065.063400] Lustre: Skipped 1 previous similar message [ 4077.928506] Lustre: DEBUG MARKER: == sanity-lfsck test 22b: LFSCK can repair unmatched pairs (2) ========================================================== 00:15:05 (1788668105) [ 4079.420348] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4079.427920] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4093.160782] Lustre: DEBUG MARKER: == sanity-lfsck test 23a: LFSCK can repair dangling name entry (1) ========================================================== 00:15:20 (1788668120) [ 4094.925169] Lustre: *** cfs_fail_loc=1620, val=0*** [ 4112.183679] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_23b skipping excluded test 23b [ 4114.203759] Lustre: DEBUG MARKER: == sanity-lfsck test 23c: LFSCK can repair dangling name entry (3) ========================================================== 00:15:42 (1788668142) [ 4121.424965] Lustre: *** cfs_fail_loc=1621, val=127*** [ 4121.437187] Lustre: Skipped 1 previous similar message [ 4124.575885] Lustre: *** cfs_fail_loc=1602, val=10*** [ 4145.759586] Lustre: DEBUG MARKER: == sanity-lfsck test 23d: LFSCK can repair a dangling name entry to a remote object ========================================================== 00:16:14 (1788668174) [ 4147.944356] Lustre: Failing over lustre-MDT0000 [ 4148.188586] Lustre: server umount lustre-MDT0000 complete [ 4148.197510] 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 [ 4148.210221] LustreError: 123608:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4148.215953] Lustre: Skipped 3 previous similar messages [ 4148.254677] LustreError: 123608:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 3 previous similar messages [ 4157.563641] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4157.802127] LustreError: MGC192.168.206.105@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4158.142541] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4158.159659] Lustre: Skipped 3 previous similar messages [ 4158.203803] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4160.541223] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4162.886368] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4163.561242] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4163.589589] Lustre: lustre-MDT0000: Recovery over after 0:03, of 2 clients 2 recovered and 0 were evicted. [ 4163.643605] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:265 to 0x280000401:289) [ 4163.645496] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:130 to 0x2c0000401:161) [ 4164.722782] LustreError: 126698:0:(mdt_open.c:1324:mdt_cross_open()) lustre-MDT0000: [0x2000013a3:0x82:0x0] doesn't exist!: rc = -14 [ 4175.357440] Lustre: DEBUG MARKER: == sanity-lfsck test 24: LFSCK can repair multiple-referenced name entry ========================================================== 00:16:43 (1788668203) [ 4177.934803] Lustre: *** cfs_fail_loc=1622, val=0*** [ 4178.087426] Lustre: *** cfs_fail_loc=1622, val=0*** [ 4178.093790] Lustre: Skipped 1 previous similar message [ 4189.112360] Lustre: DEBUG MARKER: == sanity-lfsck test 25: LFSCK can repair bad file type in the name entry ========================================================== 00:16:57 (1788668217) [ 4190.888616] Lustre: *** cfs_fail_loc=1623, val=0*** [ 4201.140653] Lustre: DEBUG MARKER: == sanity-lfsck test 26a: LFSCK can add the missing local name entry back to the namespace ========================================================== 00:17:09 (1788668229) [ 4202.900375] Lustre: *** cfs_fail_loc=1624, val=0*** [ 4214.657486] Lustre: DEBUG MARKER: == sanity-lfsck test 26b: LFSCK can add the missing remote name entry back to the namespace ========================================================== 00:17:22 (1788668242) [ 4227.115214] Lustre: DEBUG MARKER: == sanity-lfsck test 27a: LFSCK can recreate the lost local parent directory as orphan ========================================================== 00:17:35 (1788668255) [ 4228.844718] Lustre: *** cfs_fail_loc=1624, val=0*** [ 4228.853255] Lustre: Skipped 1 previous similar message [ 4239.418519] Lustre: DEBUG MARKER: == sanity-lfsck test 27b: LFSCK can recreate the lost remote parent directory as orphan ========================================================== 00:17:47 (1788668267) [ 4251.729413] Lustre: DEBUG MARKER: == sanity-lfsck test 28: Skip the failed MDT(s) when handle orphan MDT-objects ========================================================== 00:17:59 (1788668279) [ 4259.595028] Lustre: *** cfs_fail_loc=161c, val=0*** [ 4274.535337] Lustre: DEBUG MARKER: == sanity-lfsck test 29b: LFSCK can repair bad nlink count (2) ========================================================== 00:18:23 (1788668303) [ 4276.399554] Lustre: *** cfs_fail_loc=1626, val=0*** [ 4276.404326] Lustre: Skipped 4 previous similar messages [ 4286.304410] Lustre: DEBUG MARKER: == sanity-lfsck test 29c: verify linkEA size limitation == 00:18:34 (1788668314) [ 4290.119042] Lustre: 123609:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 264, rollback = 2 [ 4290.131027] Lustre: 123609:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 516 previous similar messages [ 4290.140167] Lustre: 123609:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 4290.153117] Lustre: 123609:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 516 previous similar messages [ 4290.166432] Lustre: 123609:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 2/264/0 [ 4290.182166] Lustre: 123609:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 516 previous similar messages [ 4290.197871] Lustre: 123609:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 5/47/0, punch: 0/0/0, quota 1/3/0 [ 4290.207175] Lustre: 123609:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 516 previous similar messages [ 4290.213267] Lustre: 123609:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 4290.220389] Lustre: 123609:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 516 previous similar messages [ 4290.232343] Lustre: 123609:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 1/1/1, ref_del: 0/0/0 [ 4290.243288] Lustre: 123609:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 516 previous similar messages [ 4315.231206] Lustre: DEBUG MARKER: == sanity-lfsck test 29d: accessing non-existing inode shouldn't turn fs read-only (ldiskfs) ========================================================== 00:19:03 (1788668343) [ 4319.175119] LustreError: 123603:0:(osd_handler.c:284:osd_idc_find_or_init()) lustre-MDT0000: cannot lookup FID [0x2000013a3:0x9e:0x0]: rc = -2 [ 4328.790716] Lustre: DEBUG MARKER: == sanity-lfsck test 30: LFSCK can recover the orphans from backend /lost+found ========================================================== 00:19:16 (1788668356) [ 4348.945769] Lustre: Failing over lustre-MDT0000 [ 4349.381629] Lustre: server umount lustre-MDT0000 complete [ 4352.993668] 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 [ 4353.008363] LustreError: 123605:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4353.014106] Lustre: Skipped 3 previous similar messages [ 4353.014859] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4353.044297] LustreError: 123605:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 10 previous similar messages [ 4360.581596] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 4360.658953] LustreError: MGC192.168.206.105@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4360.909272] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4360.940922] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4365.237949] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4366.308509] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4366.327183] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4366.332541] Lustre: Skipped 3 previous similar messages [ 4366.343390] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4366.383204] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:295 to 0x280000401:321) [ 4366.384513] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:166 to 0x2c0000401:193) [ 4378.527929] Lustre: DEBUG MARKER: == sanity-lfsck test 31a: The LFSCK can find/repair the name entry with bad name hash (1) ========================================================== 00:20:06 (1788668406) [ 4391.877965] Lustre: DEBUG MARKER: == sanity-lfsck test 31b: The LFSCK can find/repair the name entry with bad name hash (2) ========================================================== 00:20:19 (1788668419) [ 4406.130493] Lustre: DEBUG MARKER: == sanity-lfsck test 31c: Re-generate the lost master LMV EA for striped directory ========================================================== 00:20:34 (1788668434) [ 4407.596898] Lustre: *** cfs_fail_loc=1629, val=0*** [ 4407.601734] Lustre: Skipped 5 previous similar messages [ 4420.199344] Lustre: DEBUG MARKER: == sanity-lfsck test 31d: Set broken striped directory (modified after broken) as read-only ========================================================== 00:20:48 (1788668448) [ 4426.385588] Lustre: Failing over lustre-MDT0000 [ 4426.660172] Lustre: server umount lustre-MDT0000 complete [ 4427.750557] 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 [ 4427.766980] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4427.771962] Lustre: Skipped 3 previous similar messages [ 4435.786239] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4435.929298] LustreError: MGC192.168.206.105@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4436.210430] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4440.228751] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4441.570832] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4441.579925] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4441.601914] Lustre: Skipped 3 previous similar messages [ 4441.630147] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4441.687659] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:166 to 0x2c0000401:225) [ 4441.690126] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:295 to 0x280000401:353) [ 4449.761528] Lustre: Failing over lustre-MDT0000 [ 4450.064492] Lustre: server umount lustre-MDT0000 complete [ 4451.812891] 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 [ 4451.826713] Lustre: Skipped 3 previous similar messages [ 4451.834078] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4457.987515] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4458.068249] LustreError: MGC192.168.206.105@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4458.280023] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4462.372107] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4463.133507] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4463.593500] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4463.599732] Lustre: Skipped 3 previous similar messages [ 4463.632039] Lustre: lustre-MDT0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 4463.669574] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:295 to 0x280000401:385) [ 4463.669744] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:227 to 0x2c0000401:257) [ 4470.849803] Lustre: DEBUG MARKER: == sanity-lfsck test 31e: Re-generate the lost slave LMV EA for striped directory (1) ========================================================== 00:21:39 (1788668499) [ 4483.224154] Lustre: DEBUG MARKER: == sanity-lfsck test 31f: Re-generate the lost slave LMV EA for striped directory (2) ========================================================== 00:21:51 (1788668511) [ 4495.379545] Lustre: DEBUG MARKER: == sanity-lfsck test 31g: Repair the corrupted slave LMV EA ========================================================== 00:22:03 (1788668523) [ 4534.326974] Lustre: DEBUG MARKER: == sanity-lfsck test 31h: Repair the corrupted shard's name entry ========================================================== 00:22:42 (1788668562) [ 4535.891782] Lustre: *** cfs_fail_loc=162c, val=0*** [ 4535.895991] Lustre: Skipped 13 previous similar messages [ 4550.462556] Lustre: DEBUG MARKER: == sanity-lfsck test 32a: stop LFSCK when some OST failed ========================================================== 00:22:58 (1788668578) [ 4560.430217] LustreError: 148059:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d sleeping for 3000ms [ 4563.094821] Lustre: Failing over lustre-OST0000 [ 4563.233291] Lustre: server umount lustre-OST0000 complete [ 4563.485665] LustreError: 148059:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d awake [ 4563.491336] LustreError: 148059:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d sleeping for 3000ms [ 4564.454388] LustreError: lustre-OST0000-osc-MDT0001: operation ost_statfs to node 0@lo failed: rc = -107 [ 4564.459569] 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 [ 4564.475204] Lustre: Skipped 1 previous similar message [ 4565.699312] LustreError: 148059:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout interrupted [ 4576.253041] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 4576.433424] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 4578.407297] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4578.431582] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 4578.431968] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 4578.447338] Lustre: Skipped 3 previous similar messages [ 4581.808738] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4589.659590] Lustre: DEBUG MARKER: == sanity-lfsck test 32b: stop LFSCK when some MDT failed ========================================================== 00:23:38 (1788668618) [ 4602.136264] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing load_modules_local [ 4618.655617] Lustre: 150860:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 4639.666299] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4643.345640] Lustre: 151996:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 4654.932251] LustreError: 152111:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d sleeping for 3000ms [ 4657.722589] Lustre: Failing over lustre-MDT0001 [ 4657.944129] LustreError: 152111:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d awake [ 4657.969990] LustreError: 152110:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d sleeping for 3000ms [ 4657.980376] LustreError: lustre-MDT0001-osp-MDT0000: operation out_update to node 0@lo failed: rc = -107 [ 4657.987443] LustreError: 152110:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) Skipped 1 previous similar message [ 4658.013484] LustreError: Skipped 1 previous similar message [ 4658.022700] 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 [ 4658.042714] Lustre: Skipped 1 previous similar message [ 4658.065236] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 4658.075112] Lustre: Skipped 3 previous similar messages [ 4658.230243] Lustre: server umount lustre-MDT0001 complete [ 4658.658711] LustreError: 125111:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4658.684529] LustreError: 125111:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 31 previous similar messages [ 4661.056361] LustreError: 152110:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d awake [ 4661.072221] LustreError: 152110:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) Skipped 1 previous similar message [ 4671.987798] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 4672.224849] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 4672.235580] Lustre: Skipped 3 previous similar messages [ 4672.264659] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 4676.985936] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4677.607101] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4677.611035] Lustre: lustre-MDT0001-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 4677.618402] Lustre: Skipped 1 previous similar message [ 4677.640847] Lustre: lustre-MDT0001: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4677.687935] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:71 to 0x280000400:97) [ 4677.690809] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:68 to 0x2c0000400:97) [ 4685.504749] Lustre: DEBUG MARKER: == sanity-lfsck test 33: check LFSCK paramters =========== 00:25:13 (1788668713) [ 4698.402511] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing load_modules_local [ 4713.901571] Lustre: 154832:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 4731.476693] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4734.406692] Lustre: 155965:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 4753.268575] Lustre: DEBUG MARKER: == sanity-lfsck test 34: LFSCK can rebuild the lost agent object ========================================================== 00:26:21 (1788668781) [ 4754.381255] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_34 Only valid for ZFS backend [ 4755.705666] Lustre: DEBUG MARKER: == sanity-lfsck test 35: LFSCK can rebuild the lost agent entry ========================================================== 00:26:24 (1788668784) [ 4762.124628] Lustre: *** cfs_fail_loc=1631, val=0*** [ 4774.880733] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4774.882587] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4774.903187] Lustre: Skipped 3 previous similar messages [ 4778.752994] Lustre: server umount lustre-MDT0000 complete [ 4782.087537] LustreError: 123589:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788668811 with bad export cookie 14884967291985030251 [ 4782.095471] LustreError: MGC192.168.206.105@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4782.336399] Lustre: server umount lustre-MDT0001 complete [ 4796.539514] Lustre: server umount lustre-OST0000 complete [ 4809.502581] Lustre: server umount lustre-OST0001 complete [ 4823.330582] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing load_modules_local [ 4832.872860] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4837.847198] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4845.780226] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4850.035384] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4852.520876] Lustre: 159858:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 4857.555585] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4858.853665] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:540 to 0x280000401:577) [ 4862.983368] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4870.125721] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:71 to 0x280000400:129) [ 4870.976413] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4876.275658] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:68 to 0x2c0000400:129) [ 4876.276347] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:412 to 0x2c0000401:449) [ 4876.864873] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4883.167210] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4886.107383] Lustre: 161732:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 4894.593210] Lustre: DEBUG MARKER: == sanity-lfsck test 36a: rebuild LOV EA for mirrored file (1) ========================================================== 00:28:42 (1788668922) [ 4895.927979] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36a needs >= 3 OSTs [ 4897.576712] Lustre: DEBUG MARKER: == sanity-lfsck test 36b: rebuild LOV EA for mirrored file (2) ========================================================== 00:28:45 (1788668925) [ 4898.682961] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36b needs >= 3 OSTs [ 4900.282517] Lustre: DEBUG MARKER: == sanity-lfsck test 36c: rebuild LOV EA for mirrored file (3) ========================================================== 00:28:48 (1788668928) [ 4901.721429] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36c needs >= 3 OSTs [ 4903.195985] Lustre: DEBUG MARKER: == sanity-lfsck test 37: LFSCK must skip a ORPHAN ======== 00:28:51 (1788668931) [ 4904.607692] Lustre: 161040:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 4904.618530] Lustre: 161040:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 1885 previous similar messages [ 4904.624264] Lustre: 161040:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 4904.631271] Lustre: 161040:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1885 previous similar messages [ 4904.642283] Lustre: 161040:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4904.652835] Lustre: 161040:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1885 previous similar messages [ 4904.657427] Lustre: 161040:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 4904.660934] Lustre: 161040:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1885 previous similar messages [ 4904.664481] Lustre: 161040:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 4904.667817] Lustre: 161040:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1885 previous similar messages [ 4904.670808] Lustre: 161040:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4904.676072] Lustre: 161040:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1885 previous similar messages [ 4912.807032] Lustre: DEBUG MARKER: == sanity-lfsck test 38: LFSCK does not break foreign file and reverse is also true ========================================================== 00:29:01 (1788668941) [ 4925.415489] Lustre: DEBUG MARKER: == sanity-lfsck test 39: LFSCK does not break foreign dir and reverse is also true ========================================================== 00:29:13 (1788668953) [ 4939.420114] Lustre: DEBUG MARKER: == sanity-lfsck test 40a: LFSCK correctly fixes lmm_oi in composite layout ========================================================== 00:29:27 (1788668967) [ 4953.354506] Lustre: DEBUG MARKER: == sanity-lfsck test 41: SEL support in LFSCK ============ 00:29:41 (1788668981) [ 4971.615888] Lustre: DEBUG MARKER: == sanity-lfsck test 42: LFSCK repairs inconsistent MDT-object/OST-object encryption flags ========================================================== 00:29:59 (1788668999) [ 5006.013523] Lustre: *** cfs_fail_loc=1632, val=0*** [ 5020.511568] Lustre: DEBUG MARKER: == sanity-lfsck test 43: LFSCK does not loop endlessly on iget failure in scanning-phase1 ========================================================== 00:30:48 (1788669048) [ 5023.121297] Lustre: Failing over lustre-MDT0001 [ 5023.457499] Lustre: server umount lustre-MDT0001 complete [ 5024.740417] 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 [ 5024.754730] Lustre: Skipped 8 previous similar messages [ 5031.535312] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5031.945849] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 5031.949215] Lustre: lustre-MDT0001: Aborting client recovery [ 5031.955969] LustreError: 165520:0:(ldlm_lib.c:3029:target_stop_recovery_thread()) lustre-MDT0001: Aborting recovery [ 5031.961258] Lustre: 165544:0:(ldlm_lib.c:2429:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 5031.969030] Lustre: 165544:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0001: disconnect stale client 4ed30cea-6e40-41c9-8d0f-a4d5375be72d@192.168.206.5@tcp [ 5031.981401] Lustre: lustre-MDT0001: disconnecting 2 stale clients [ 5031.995407] Lustre: lustre-MDT0001: Denying connection for new client 4ed30cea-6e40-41c9-8d0f-a4d5375be72d (at 192.168.206.5@tcp), waiting for 2 known clients (0 recovered, 0 in progress, and 2 evicted) already passed deadline 83:51 [ 5032.000891] Lustre: lustre-MDT0001-osd: cancel update llog [0x240000400:0x1:0x0] [ 5032.029895] Lustre: lustre-MDT0000-osp-MDT0001: cancel update llog [0x200000401:0x1:0x0] [ 5032.081583] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:71 to 0x280000400:161) [ 5032.087272] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:131 to 0x2c0000400:161) [ 5037.044327] Lustre: lustre-MDT0001-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 5037.058610] Lustre: Skipped 2 previous similar messages [ 5037.090194] LustreError: lustre-MDT0001-osp-MDT0000: This client was evicted by lustre-MDT0001; in progress operations using this service will fail. [ 5037.510569] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5044.489303] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing wait_import_state FULL osp.lustre-MDT0001-os[pc]-MDT0000.*_server_uuid [ 5044.770981] Lustre: DEBUG MARKER: osp.lustre-MDT0001-os[pc]-MDT0000.*_server_uuid in FULL state after 0 sec [ 5051.520509] Lustre: DEBUG MARKER: == sanity-lfsck test 44: umount while lfsck is stopping == 00:31:19 (1788669079) [ 5060.530358] Lustre: *** cfs_fail_loc=1600, val=3*** [ 5063.314510] Lustre: Failing over lustre-MDT0000 [ 5063.337695] LustreError: lustre-MDT0000-osp-MDT0001: operation out_update to node 0@lo failed: rc = -107 [ 5063.351436] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5063.652190] Lustre: server umount lustre-MDT0000 complete [ 5072.698640] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5072.774979] LustreError: MGC192.168.206.105@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5072.867291] Lustre: lustre-MDT0000: Not available for connect from 0@lo (not set up) [ 5073.063716] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 5073.076363] Lustre: Skipped 2 previous similar messages [ 5074.807442] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 5077.567909] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5078.514638] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 5078.528213] Lustre: Skipped 2 previous similar messages [ 5078.575974] Lustre: lustre-MDT0000: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 5078.663782] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:489 to 0x2c0000401:513) [ 5078.667280] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:621 to 0x280000401:641) [ 5087.479788] Lustre: DEBUG MARKER: == sanity-lfsck test 45: LFSCK should fix UID/GID/PROJID of OST object ========================================================== 00:31:55 (1788669115) [ 5123.110762] Lustre: Failing over lustre-OST0000 [ 5123.222898] Lustre: server umount lustre-OST0000 complete [ 5128.691714] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: (null) [ 5139.148835] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5139.337273] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 5141.029786] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 5141.373740] Lustre: lustre-OST0000: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [ 5144.901089] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5150.705780] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing wait_import_state (FULL|IDLE) os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid 50 [ 5150.823349] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid in FULL state after 0 sec [ 5154.451746] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing wait_import_state (FULL|IDLE) os[cp].lustre-OST0000-osc-MDT0001.ost_server_uuid 50 [ 5154.706836] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0001.ost_server_uuid in FULL state after 0 sec [ 5160.284172] Lustre: DEBUG MARKER: oleg605-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0000-osc-ffff9b99c7968000.ost_server_uuid 50 [ 5162.199108] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9b99c7968000.ost_server_uuid in FULL state after 0 sec [ 5241.828814] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5241.832348] Lustre: Skipped 7 previous similar messages [ 5245.572761] Lustre: server umount lustre-MDT0000 complete [ 5246.945902] LustreError: 158714:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 5246.967929] LustreError: 158714:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 42 previous similar messages [ 5252.605385] LustreError: 158699:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788669282 with bad export cookie 14884967291985112739 [ 5252.606544] LustreError: MGC192.168.206.105@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5252.619915] LustreError: 158699:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 8 previous similar messages [ 5252.907485] Lustre: server umount lustre-MDT0001 complete [ 5269.981964] Lustre: server umount lustre-OST0000 complete [ 5273.552381] Lustre: 106508:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788669287/real 1788669287] req@ffff8e04a6715180 x1875553704393984/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788669303 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5276.829239] Lustre: server umount lustre-OST0001 complete [ 5290.747713] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing unload_modules_local [ 5292.962496] Key type lgssc unregistered [ 5293.160582] LNet: 175111:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 5293.167521] LNetError: 175111:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 5293.183320] LNet: Removed LNI 192.168.206.105@tcp [ 5293.804151] Key type .llcrypt unregistered [ 5293.806695] Key type ._llcrypt unregistered [ 5315.582504] Key type ._llcrypt registered [ 5315.585973] Key type .llcrypt registered [ 5315.731503] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_hostid [ 5330.054394] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing load_modules_local [ 5330.757376] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 5330.894501] alg: No test for adler32 (adler32-zlib) [ 5331.942494] Lustre: Lustre: Build Version: 2.17.58_4_g3b30273 [ 5332.132031] LNet: Added LNI 192.168.206.105@tcp [8/256/0/180] [ 5333.784147] Key type lgssc registered [ 5334.657470] Lustre: Echo OBD driver; http://www.lustre.org/ [ 5380.813895] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing load_modules_local [ 5391.128865] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 5391.159298] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5392.341264] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 5392.386732] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 5392.473955] Lustre: lustre-MDT0000: new disk, initializing [ 5392.550992] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 5392.565344] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 5395.894304] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5407.204484] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5407.313121] Lustre: 179559: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 [ 5407.342674] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 5407.346606] Lustre: Skipped 1 previous similar message [ 5407.445231] Lustre: lustre-MDT0001: new disk, initializing [ 5407.518939] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 5407.551149] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 5407.557325] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 5411.755979] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5416.234964] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 5424.624143] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5424.793403] Lustre: lustre-OST0000: new disk, initializing [ 5424.796948] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 5424.800125] Lustre: 181494:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 5424.850276] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 5429.528285] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5430.333037] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 5430.342889] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 5430.470362] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 5441.054042] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5441.163420] Lustre: lustre-OST0001: new disk, initializing [ 5441.168326] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 5441.173095] Lustre: 182521:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 5441.217520] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 5447.169223] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 5447.183674] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 5447.245747] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 5447.689652] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5458.453198] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5465.893090] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 5470.678824] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 00:38:18 (1788669498) === [ 5472.103918] Lustre: DEBUG MARKER: == sanity-lfsck test complete, duration 5222 sec ========= 00:38:20 (1788669500) [ 5473.835591] Lustre: DEBUG MARKER: === sanity-lfsck: start cleanup 00:38:22 (1788669502) === [ 5477.116407] Lustre: DEBUG MARKER: === sanity-lfsck: finish cleanup 00:38:25 (1788669505) === [ 5482.977872] 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 [ 5482.979691] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5482.998212] Lustre: Skipped 1 previous similar message [ 5483.010195] Lustre: Skipped 3 previous similar messages [ 5487.279321] Lustre: server umount lustre-MDT0000 complete [ 5493.217769] LustreError: 179563:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 5493.232649] LustreError: 179563:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 8 previous similar messages [ 5495.001501] LustreError: 182520:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788669524 with bad export cookie 8211850793554337635 [ 5495.007449] LustreError: MGC192.168.206.105@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5495.017688] LustreError: 182520:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 5495.316535] Lustre: server umount lustre-MDT0001 complete [ 5513.238975] Lustre: server umount lustre-OST0000 complete [ 5514.208104] Lustre: 176718:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788669528/real 1788669528] req@ffff8e04bba1d880 x1875555765008256/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788669544 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5514.239502] 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 [ 5514.257820] Lustre: Skipped 2 previous similar messages [ 5516.769331] Lustre: 176720:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788669530/real 1788669530] req@ffff8e038540d880 x1875555765008512/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788669546 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5519.840263] Lustre: 176721:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788669533/real 1788669533] req@ffff8e04bba1f480 x1875555765008768/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788669549 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5522.953260] Lustre: server umount lustre-OST0001 complete [ 5538.341572] Lustre: DEBUG MARKER: oleg605-server.virtnet: executing unload_modules_local [ 5541.296368] Key type lgssc unregistered [ 5541.551277] LNet: 185994:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 5541.565316] LNetError: 185994:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 5541.585709] LNet: Removed LNI 192.168.206.105@tcp [ 5542.214587] Key type .llcrypt unregistered [ 5542.219566] Key type ._llcrypt unregistered