[ 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 508934157 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2399.998 MHz processor [ 0.000000] last_pfn = 0x146e00 max_arch_pfn = 0x400000000 [ 0.000000] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT [ 0.000000] last_pfn = 0xbffce max_arch_pfn = 0x400000000 [ 0.000000] found SMP MP-table at [mem 0x000f54b0-0x000f54bf] [ 0.000000] RAMDISK: [mem 0xbcc54000-0xbffbffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F52D0 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE247C 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE2318 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 0022D8 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE238C 000090 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE241C 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE2454 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe2318-0xbffe238b] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe2317] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe238c-0xbffe241b] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe241c-0xbffe2453] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe2454-0xbffe247b] [ 0.000000] No NUMA configuration found [ 0.000000] Faking a node at [mem 0x0000000000000000-0x0000000146dfffff] [ 0.000000] NODE_DATA(0) allocated [mem 0x1465a3000-0x1465cdfff] [ 0.000000] Reserving 256MB of memory at 2752MB for crashkernel (System RAM: 4205MB) [ 0.000000] Zone ranges: [ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.000000] DMA32 [mem 0x0000000001000000-0x00000000ffffffff] [ 0.000000] Normal [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Device empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff] [ 0.000000] node 0: [mem 0x0000000000100000-0x00000000bffcdfff] [ 0.000000] node 0: [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Zeroed struct page in unavailable ranges: 4756 pages [ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x0000000146dfffff] [ 0.000000] ACPI: PM-Timer IO Port: 0x608 [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) [ 0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) [ 0.000000] Using ACPI (MADT) for SMP configuration information [ 0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000] TSC deadline timer available [ 0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs [ 0.000000] kvm-guest: KVM setup pv remote TLB flush [ 0.000000] kvm-guest: setup PV sched yield [ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff] [ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff] [ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff] [ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff] [ 0.000000] PM: Registered nosave memory: [mem 0xbffce000-0xbfffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xc0000000-0xfeffbfff] [ 0.000000] PM: Registered nosave memory: [mem 0xfeffc000-0xfeffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xff000000-0xfffbffff] [ 0.000000] PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff] [ 0.000000] [mem 0xc0000000-0xfeffbfff] available for PCI devices [ 0.000000] Booting paravirtualized kernel on KVM [ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns [ 0.000000] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1 [ 0.000000] percpu: Embedded 63 pages/cpu s221184 r8192 d28672 u524288 [ 0.000000] kvm-guest: PV spinlocks enabled [ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1059606 [ 0.000000] Policy zone: Normal [ 0.000000] Kernel command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] Specific versions of hardware are certified with Red Hat Enterprise Linux 8. Please see the list of hardware certified with Red Hat Enterprise Linux 8 at https://catalog.redhat.com. [ 0.000000] audit: disabled (until reboot) [ 0.000000] software IO TLB: area num 4. [ 0.000000] Memory: 2829652K/4306352K available (18435K kernel code, 11221K rwdata, 7248K rodata, 2908K init, 18040K bss, 524580K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] ftrace: allocating 41240 entries in 162 pages [ 0.000000] ftrace: allocated 162 pages with 3 groups [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] rcu: RCU event tracing is enabled. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ 0.000000] rcu: RCU callback double-/use-after-free debug enabled. [ 0.000000] Rude variant of Tasks RCU enabled. [ 0.000000] Tracing variant of Tasks RCU enabled. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 0.000000] NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16 [ 0.000000] random: get_random_bytes called from start_kernel+0x622/0x9a8 with crng_init=0 [ 0.001000] Console: colour *CGA 80x25 [ 0.001000] printk: console [ttyS1] enabled [ 0.001000] ACPI: Core revision 20220331 [ 0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.001012] APIC: Switch to symmetric I/O mode setup [ 0.002253] x2apic enabled [ 0.003010] Switched APIC routing to physical x2apic. [ 0.004012] kvm-guest: setup PV IPIs [ 0.006300] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.007000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.007021] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.008015] pid_max: default: 32768 minimum: 301 [ 0.009139] LSM: Security Framework initializing [ 0.010090] Yama: becoming mindful. [ 0.011041] SELinux: Initializing. [ 0.012075] *** VALIDATE selinux *** [ 0.021439] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.026345] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.027166] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.028147] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.030119] *** VALIDATE tmpfs *** [ 0.031486] *** VALIDATE proc *** [ 0.032266] *** VALIDATE cgroup *** [ 0.033017] *** VALIDATE cgroup2 *** [ 0.034287] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.036069] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.037012] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.038035] Spectre V2 : User space: Vulnerable [ 0.039010] Speculative Store Bypass: Vulnerable [ 0.041753] debug: unmapping init [mem 0xffffffff99259000-0xffffffff99260fff] [ 0.043916] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.044743] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.045026] ... version: 2 [ 0.046018] ... bit width: 48 [ 0.047016] ... generic registers: 4 [ 0.048014] ... value mask: 0000ffffffffffff [ 0.049015] ... max period: 00007fffffffffff [ 0.050016] ... fixed-purpose events: 3 [ 0.051016] ... event mask: 000000070000000f [ 0.053251] rcu: Hierarchical SRCU implementation. [ 0.055495] smp: Bringing up secondary CPUs ... [ 0.056660] x86: Booting SMP configuration: [ 0.057031] .... node #0, CPUs: #1 #2 #3 [ 0.061012] smp: Brought up 1 node, 4 CPUs [ 0.063018] smpboot: Max logical packages: 1 [ 0.064014] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.140021] node 0 deferred pages initialised in 72ms [ 0.144014] devtmpfs: initialized [ 0.145209] x86/mm: Memory block size: 128MB [ 0.147781] gcov: version magic: 0x41383552 [ 0.149278] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.150083] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.151269] pinctrl core: initialized pinctrl subsystem [ 0.152197] [ 0.152885] ************************************************************* [ 0.153013] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.154015] ** ** [ 0.155014] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.156012] ** ** [ 0.157011] ** This means that this kernel is built to expose internal ** [ 0.158010] ** IOMMU data structures, which may compromise security on ** [ 0.159011] ** your system. ** [ 0.160011] ** ** [ 0.161010] ** If you see this message and you are not debugging the ** [ 0.162013] ** kernel, report this immediately to your vendor! ** [ 0.163013] ** ** [ 0.164016] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.165015] ************************************************************* [ 0.166756] NET: Registered protocol family 16 [ 0.168571] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.171060] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.174059] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.178020] cpuidle: using governor menu [ 0.179731] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.182607] PCI: Using configuration type 1 for base access [ 0.185131] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.193152] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.196024] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.201031] cryptd: max_cpu_qlen set to 1000 [ 0.204358] ACPI: Added _OSI(Module Device) [ 0.206016] ACPI: Added _OSI(Processor Device) [ 0.208012] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.209012] ACPI: Added _OSI(Processor Aggregator Device) [ 0.214243] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.221287] ACPI: Interpreter enabled [ 0.223096] ACPI: PM: (supports S0 S3 S4 S5) [ 0.224013] ACPI: Using IOAPIC for interrupt routing [ 0.225131] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.228721] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.238876] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.241050] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.244023] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.247083] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.252409] acpiphp: Slot [2] registered [ 0.254167] acpiphp: Slot [5] registered [ 0.255168] acpiphp: Slot [6] registered [ 0.257135] acpiphp: Slot [7] registered [ 0.258159] acpiphp: Slot [8] registered [ 0.260128] acpiphp: Slot [9] registered [ 0.262111] acpiphp: Slot [10] registered [ 0.263143] acpiphp: Slot [3] registered [ 0.265120] acpiphp: Slot [4] registered [ 0.267083] acpiphp: Slot [11] registered [ 0.268118] acpiphp: Slot [12] registered [ 0.270111] acpiphp: Slot [13] registered [ 0.272111] acpiphp: Slot [14] registered [ 0.273110] acpiphp: Slot [15] registered [ 0.275142] acpiphp: Slot [16] registered [ 0.276108] acpiphp: Slot [17] registered [ 0.278114] acpiphp: Slot [18] registered [ 0.279109] acpiphp: Slot [19] registered [ 0.281117] acpiphp: Slot [20] registered [ 0.283139] acpiphp: Slot [21] registered [ 0.284108] acpiphp: Slot [22] registered [ 0.286129] acpiphp: Slot [23] registered [ 0.287117] acpiphp: Slot [24] registered [ 0.289120] acpiphp: Slot [25] registered [ 0.290101] acpiphp: Slot [26] registered [ 0.292087] acpiphp: Slot [27] registered [ 0.294128] acpiphp: Slot [28] registered [ 0.296137] acpiphp: Slot [29] registered [ 0.297124] acpiphp: Slot [30] registered [ 0.299112] acpiphp: Slot [31] registered [ 0.300066] PCI host bridge to bus 0000:00 [ 0.302020] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.304025] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.307036] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.310026] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.313025] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.316025] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.318212] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.321192] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.325000] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.335765] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.341042] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.344019] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.346018] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.349023] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.352654] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.355997] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.358048] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.362037] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.368019] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.384920] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.391018] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.398009] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.407015] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.418016] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.435016] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.444994] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.457016] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.462015] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.477015] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.485931] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.492019] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.507017] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.528021] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.538665] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.547013] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.559018] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.579018] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.591982] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.602015] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.607017] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.627017] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 0.637729] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.646014] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.654016] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.673015] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 0.684326] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.687421] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.689404] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.692467] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.693306] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.699052] iommu: Default domain type: Passthrough [ 0.701417] SCSI subsystem initialized [ 0.702118] ACPI: bus type USB registered [ 0.704113] usbcore: registered new interface driver usbfs [ 0.705068] usbcore: registered new interface driver hub [ 0.707102] usbcore: registered new device driver usb [ 0.709181] pps_core: LinuxPPS API ver. 1 registered [ 0.711019] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.714093] PTP clock support registered [ 0.716086] EDAC MC: Ver: 3.0.0 [ 0.718113] PCI: Using ACPI for IRQ routing [ 0.719547] NetLabel: Initializing [ 0.721015] NetLabel: domain hash size = 128 [ 0.723013] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.726152] NetLabel: unlabeled traffic allowed by default [ 0.730145] vgaarb: loaded [ 0.732252] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.734013] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.739345] clocksource: Switched to clocksource kvm-clock [ 0.845523] VFS: Disk quotas dquot_6.6.0 [ 0.847668] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.850089] *** VALIDATE ramfs *** [ 0.851243] *** VALIDATE hugetlbfs *** [ 0.853280] pnp: PnP ACPI init [ 0.855791] pnp: PnP ACPI: found 6 devices [ 0.872259] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.876416] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.879177] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.881981] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.884518] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.887110] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.890361] NET: Registered protocol family 2 [ 0.892431] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.897222] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.900956] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.905681] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.909117] TCP: Hash tables configured (established 65536 bind 65536) [ 0.912112] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.914914] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.917554] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.920448] NET: Registered protocol family 1 [ 0.922936] RPC: Registered named UNIX socket transport module. [ 0.925354] RPC: Registered udp transport module. [ 0.927032] RPC: Registered tcp transport module. [ 0.928351] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.930656] NET: Registered protocol family 44 [ 0.931868] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.933928] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.935594] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.937778] PCI: CLS 0 bytes, default 64 [ 0.939275] Unpacking initramfs... [ 2.350756] debug: unmapping init [mem 0xffff89983cc54000-0xffff89983ffbffff] [ 2.354709] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.356925] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.359782] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 2.856979] Initialise system trusted keyrings [ 2.858693] Key type blacklist registered [ 2.879086] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.889530] zbud: loaded [ 2.892715] *** VALIDATE nfs *** [ 2.894029] *** VALIDATE nfs4 *** [ 2.896396] pstore: using deflate compression [ 2.902374] Platform Keyring initialized [ 3.015626] NET: Registered protocol family 38 [ 3.018036] Key type asymmetric registered [ 3.019737] Asymmetric key parser 'x509' registered [ 3.021296] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 3.025119] io scheduler mq-deadline registered [ 3.026989] io scheduler kyber registered [ 3.028884] io scheduler bfq registered [ 3.031083] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 3.034348] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 3.037571] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 3.040177] ACPI: Power Button [PWRF] [ 3.047401] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 3.054696] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 3.081620] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 3.094108] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 3.124990] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 3.152489] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.181827] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.187221] Non-volatile memory driver v1.3 [ 3.188578] Linux agpgart interface v0.103 [ 3.220212] virtio_blk virtio1: [vda] 145880 512-byte logical blocks (74.7 MB/71.2 MiB) [ 3.223705] vda: detected capacity change from 0 to 74690560 [ 3.241844] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.245307] vdb: detected capacity change from 0 to 1073741824 [ 3.263717] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.266462] vdc: detected capacity change from 0 to 2621440000 [ 3.280314] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.283092] vdd: detected capacity change from 0 to 2621440000 [ 3.298453] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.301471] vde: detected capacity change from 0 to 4294967296 [ 3.317904] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.320836] vdf: detected capacity change from 0 to 4294967296 [ 3.326851] libphy: Fixed MDIO Bus: probed [ 3.334433] usbcore: registered new interface driver usbserial_generic [ 3.336676] usbserial: USB Serial support registered for generic [ 3.338527] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.342327] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.343912] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.345832] mousedev: PS/2 mouse device common for all mice [ 3.348607] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.350458] rtc_cmos 00:05: RTC can wake from S4 [ 3.356843] rtc_cmos 00:05: registered as rtc0 [ 3.358294] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.362659] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.362703] intel_pstate: CPU model not supported [ 3.370894] hid: raw HID events driver (C) Jiri Kosina [ 3.373414] usbcore: registered new interface driver usbhid [ 3.373952] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.375752] usbhid: USB HID core driver [ 3.380992] drop_monitor: Initializing network drop monitor service [ 3.384052] Initializing XFRM netlink socket [ 3.386444] NET: Registered protocol family 10 [ 3.389530] Segment Routing with IPv6 [ 3.390746] NET: Registered protocol family 17 [ 3.393830] mpls_gso: MPLS GSO support [ 3.398916] RAS: Correctable Errors collector initialized. [ 3.401045] AVX version of gcm_enc/dec engaged. [ 3.402278] AES CTR mode by8 optimization enabled [ 3.491914] sched_clock: Marking stable (3491889455, 0)->(4434612576, -942723121) [ 3.494995] registered taskstats version 1 [ 3.496809] Loading compiled-in X.509 certificates [ 3.498624] zswap: loaded using pool lzo/zbud [ 3.525420] Key type big_key registered [ 3.540209] Key type encrypted registered [ 3.541824] ima: No TPM chip found, activating TPM-bypass! [ 3.543613] ima: Allocated hash algorithm: sha1 [ 3.544939] ima: No architecture policies found [ 3.546418] evm: Initialising EVM extended attributes: [ 3.548082] evm: security.selinux [ 3.549106] evm: security.ima [ 3.549982] evm: security.capability [ 3.551167] evm: HMAC attrs: 0x1 [ 3.553713] rtc_cmos 00:05: setting system clock to 2026-09-10 23:27:09 UTC (1789082829) [ 3.560835] debug: unmapping init [mem 0xffffffff9a203000-0xffffffff9a3fffff] [ 3.564178] debug: unmapping init [mem 0xffffffff98f82000-0xffffffff99258fff] [ 3.573153] Write protecting the kernel read-only data: 28672k [ 3.576746] debug: unmapping init [mem 0xffffffff97603000-0xffffffff977fffff] [ 3.579697] debug: unmapping init [mem 0xffffffff97f14000-0xffffffff97ffffff] [ 3.619186] 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.628150] systemd[1]: Detected virtualization kvm. [ 3.630065] systemd[1]: Detected architecture x86-64. [ 3.632076] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.655492] systemd[1]: No hostname configured. [ 3.657889] systemd[1]: Set hostname to . [ 3.660244] random: systemd: uninitialized urandom read (16 bytes read) [ 3.662981] systemd[1]: Initializing machine ID from random generator. [ 3.708794] random: ln: uninitialized urandom read (6 bytes read) [ 3.795238] random: systemd: uninitialized urandom read (16 bytes read) [ 3.798540] systemd[1]: Listening on Journal Socket (/dev/log). [ OK ] Listening on Journal Socket (/dev/log). [ 3.803503] systemd[1]: Reached target Local File Systems. [ OK ] Reached target Local File Systems. [ 3.808160] systemd[1]: Reached target Slices. [ OK ] Reached target Slices. [ OK ] Listening on udev Kernel Socket. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Listening on udev Control Socket. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Timers. [ OK ] Reached target Paths. [ OK ] Reached target Initrd Root Device. [ OK ] Reached target Swap. [ OK ] Listening on Journal Socket. Starting Setup Virtual Console... Starting Journal Service... Starting Create list of required st…ce nodes for the current kernel... [ OK ] Started Memstrack Anylazing Service. Starting Apply Kernel Variables... Starting Create Volatile Files and Directories... [ OK ] Reached target Sockets. [ OK ] Started Setup Virtual Console. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Apply Kernel Variables. [ OK ] Started Create Volatile Files and Directories. 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.466590] device-mapper: uevent: version 1.0.3 [ 4.468625] device-mapper: ioctl: 4.46.0-ioctl (2022-02-22) initialised: dm-devel@redhat.com [ OK ] Started dracut pre-udev hook. Starting udev Kernel Device Manager... [ OK ] Started udev Kernel Device Manager. Starting dracut pre-trigger hook... [ OK ] Started dracut pre-trigger hook. Starting udev Coldplug all Devices... Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. Starting dracut initqueue hook... [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ 5.248052] random: fast init done [ 5.294059] virtio_net virtio0 ens2: renamed from eth0 [ 5.344704] scsi host0: ata_piix [ 5.436909] scsi host1: ata_piix [ 5.438977] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 5.441663] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 9.129873] dracut-initqueue[579]: RTNETLINK answers: File exists [ 10.056701] random: crng init done [ 10.058075] 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.534800] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped target Timers. [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target System Initialization. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Swap. [ OK ] Stopped target Local File Systems. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. Stopping udev Kernel Device Manager... [ OK ] Stopped target Slices. [ OK ] Stopped target Paths. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped target Sockets. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Closed udev Control Socket. [ OK ] Closed udev Kernel Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 11.669173] printk: systemd: 26 output lines suppressed due to ratelimiting [ 11.911559] SELinux: Disabled at runtime. [ 11.970883] 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) [ 11.978057] systemd[1]: Detected virtualization kvm. [ 11.979328] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 12.502613] systemd[1]: initrd-switch-root.service: Succeeded. [ 12.506627] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 12.512879] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 12.522908] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 12.526405] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 12.533499] systemd[1]: Starting Journal Service... Starting Journal Service... [ 12.538213] systemd[1]: Created slice system-getty.slice. [ OK ] Created slice system-getty.slice. [ OK ] Listening on udev Control Socket. Mounting Kernel Debug File System... Starting Create list of required st…ce nodes for the current kernel... [ OK ] Listening on Process Core Dump Socket. Mounting Huge Pages File System... [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Listening on initctl Compatibility Named Pipe. Activating swap /dev/disk/by-label/SWAP... [ OK ] Listening on udev Kernel Socket. Starting udev Coldplug all Devices... Starting Apply Kernel Variables... [ OK ] Reached target rpc_pipefs.target. [ 12.626243] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS Mounting POSIX Message Queue File System... [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Created slice User and Session Slice. [ OK ] Reached target Slices. [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd File Systems. [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Stopped target Initrd Root File System. [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. Starting Remount Root and Kernel File Systems... [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Reached target RPC Port Mapper. [ OK ] Started Journal Service. [ OK ] Mounted Kernel Debug File System. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Mounted Huge Pages File System. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Started Apply Kernel Variables. [ OK ] Mounted POSIX Message Queue File System. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. Starting Configure read-only root support... [ OK ] Reached target Swap. Starting Create Static Device Nodes in /dev... Starting Flush Journal to Persistent Storage... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. Starting udev Kernel Device Manager... [ OK ] Reached target Local File Systems (Pre). Mounting /mnt... Mounting /home/green/git/lustre-release... [ OK ] Mounted /mnt. [ OK ] Started udev Coldplug all Devices. [ 12.972139] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 13.264050] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 13.264890] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 13.351358] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 13.367671] EDAC sbridge: Ver: 1.1.2 [ 14.941573] Key type dns_resolver registered [ 15.243784] NFS: Registering the id_resolver key type [ 15.245985] Key type id_resolver registered [ 15.248106] Key type id_legacy registered [ OK ] Started Configure read-only root support. [ OK ] Reached target Local File Systems. Starting Mark the need to relabel after reboot... Starting Rebuild Dynamic Linker Cache... Starting Load/Save Random Seed... Starting Create Volatile Files and Directories... [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Load/Save Random Seed. [ OK ] Started Create Volatile Files and Directories. Starting RPC Bind... Starting Update UTMP about System Boot/Shutdown... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Started dnf makecache --timer. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. Starting Login Service... [ OK ] Started D-Bus System Message Bus. Starting Network Manager... [ OK ] Started irqbalance daemon. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting Restore /run/initramfs on shutdown... [ OK ] Reached target sshd-keygen.target. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Reached target Timers. [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Login Service. [ OK ] Started Network Manager. Starting Network Manager Wait Online... [ OK ] Reached target Network. Starting GSSAPI Proxy Daemon... Starting Dynamic System Tuning Daemon... Starting OpenSSH server daemon... Starting Hostname Service... [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... [ OK ] Started OpenSSH server daemon. [ OK ] Started Permit User Sessions. [ OK ] Started Command Scheduler. [ OK ] Started Getty on tty1. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Serial Getty on ttyS1. [ 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 oleg455-server login: [ 41.653861] libcfs: loading out-of-tree module taints kernel. [ 41.674453] Key type ._llcrypt registered [ 41.676111] Key type .llcrypt registered [ 41.732929] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_hostid [ 50.800253] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing load_modules_local [ 51.415040] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 51.423372] alg: No test for adler32 (adler32-zlib) [ 52.469975] Lustre: Lustre: Build Version: 2.17.55_25_gfa4fa99 [ 52.832987] LNet: Added LNI 192.168.204.155@tcp [8/256/0/180] [ 54.471191] Key type lgssc registered [ 56.738321] Lustre: Echo OBD driver; http://www.lustre.org/ [ 59.799110] hrtimer: interrupt took 2101714 ns [ 74.416431] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 126.319514] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing load_modules_local [ 141.735354] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 141.799405] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 143.047813] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 143.090163] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 143.212075] Lustre: lustre-MDT0000: new disk, initializing [ 143.371867] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 143.404823] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 148.557275] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 162.612631] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 162.722402] Lustre: 6495: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 [ 162.755375] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 162.763914] Lustre: Skipped 1 previous similar message [ 162.864612] Lustre: lustre-MDT0001: new disk, initializing [ 162.957280] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 162.995836] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 163.017525] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 167.495697] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 172.412964] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 182.837731] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 183.054616] Lustre: lustre-OST0000: new disk, initializing [ 183.058840] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 183.066219] Lustre: 8434:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 183.123805] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 185.327644] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 185.339918] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 185.390048] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 190.133029] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 203.327469] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 203.448163] Lustre: lustre-OST0001: new disk, initializing [ 203.454339] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 203.458452] Lustre: 9506:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 203.520421] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 209.494473] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 209.503844] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 209.572192] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 211.404732] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 227.613706] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 236.946846] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 244.111574] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing check_logdir /tmp/testlogs/ [ 249.080082] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing yml_node [ 254.164122] Lustre: DEBUG MARKER: Client: 2.17.55.25 [ 257.102997] Lustre: DEBUG MARKER: MDS: 2.17.55.25 [ 259.949731] Lustre: DEBUG MARKER: OSS: 2.17.55.25 [ 261.798938] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity-lfsck ============----- Thu Sep 10 19:31:24 EDT 2026 [ 284.250743] Lustre: DEBUG MARKER: excepting tests: 18b 23b [ 297.589778] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing load_modules_local [ 306.657474] 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 [ 306.658216] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 306.675066] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 306.683448] Lustre: Skipped 3 previous similar messages [ 306.703043] Lustre: Skipped 3 previous similar messages [ 310.990593] Lustre: server umount lustre-MDT0000 complete [ 316.897767] LustreError: 7811:0:(ldlm_lib.c:1192: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. [ 316.908985] LustreError: 7811:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 8 previous similar messages [ 319.893871] LustreError: 6488:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1789083145 with bad export cookie 14299172314853600341 [ 319.903414] LustreError: MGC192.168.204.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 320.449365] Lustre: server umount lustre-MDT0001 complete [ 337.247654] Lustre: 3629:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789083147/real 1789083147] req@ffff89989683ce00 x1875989367993600/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1789083163 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 337.295503] 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 [ 339.518039] Lustre: server umount lustre-OST0000 complete [ 340.324925] Lustre: 3627:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789083150/real 1789083150] req@ffff89989683ed80 x1875989367993856/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1789083166 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 343.461123] Lustre: 3629:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789083153/real 1789083153] req@ffff89989683e300 x1875989367994112/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1789083169 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 345.503228] Lustre: 3627:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789083155/real 1789083155] req@ffff899781adb100 x1875989367994496/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1789083171 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 349.196974] Lustre: server umount lustre-OST0001 complete [ 368.297958] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing unload_modules_local [ 371.467776] Key type lgssc unregistered [ 371.837482] LNet: 14784:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 371.851287] LNetError: 14784:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 372.902364] LNet: Removed LNI 192.168.204.155@tcp [ 374.158226] Key type .llcrypt unregistered [ 374.159846] Key type ._llcrypt unregistered [ 404.417045] Key type ._llcrypt registered [ 404.426044] Key type .llcrypt registered [ 404.529616] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_hostid [ 421.982767] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing load_modules_local [ 423.389315] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 423.400319] alg: No test for adler32 (adler32-zlib) [ 424.508733] Lustre: Lustre: Build Version: 2.17.55_25_gfa4fa99 [ 424.761349] LNet: Added LNI 192.168.204.155@tcp [8/256/0/180] [ 426.440605] Key type lgssc registered [ 427.692187] Lustre: Echo OBD driver; http://www.lustre.org/ [ 482.221292] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing load_modules_local [ 497.707136] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 497.758054] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 499.173575] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 499.219577] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 499.333346] Lustre: lustre-MDT0000: new disk, initializing [ 499.484929] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 499.539764] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 505.000609] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 521.449244] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 521.559736] Lustre: 19240: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 [ 521.587876] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 521.591122] Lustre: Skipped 1 previous similar message [ 521.668721] Lustre: lustre-MDT0001: new disk, initializing [ 521.759197] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 521.792530] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 521.800349] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 527.818840] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 535.001206] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 547.990670] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 548.202320] Lustre: lustre-OST0000: new disk, initializing [ 548.212727] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 548.228736] Lustre: 21180:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 548.293495] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 556.096863] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 557.099196] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 557.109515] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 557.184925] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 572.104278] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 572.277449] Lustre: lustre-OST0001: new disk, initializing [ 572.286492] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 572.295103] Lustre: 22203:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 572.410239] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 579.625221] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 579.639240] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 579.670987] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 580.566022] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 594.560987] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 601.593925] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 612.533685] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 19:37:14 (1789083434) === [ 616.909834] Lustre: DEBUG MARKER: == sanity-lfsck test 0: Control LFSCK manually =========== 19:37:18 (1789083438) [ 617.628430] Lustre: 19246:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 251 < left 278, rollback = 2 [ 617.634916] Lustre: 19246:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 617.640418] Lustre: 19246:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 617.645694] Lustre: 19246:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 617.654767] Lustre: 19246:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 617.660675] Lustre: 19246:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 618.208120] Lustre: 19247:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 618.227845] Lustre: 19247:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 8 previous similar messages [ 618.236685] Lustre: 19247:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 618.250634] Lustre: 19247:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 8 previous similar messages [ 618.258423] Lustre: 19247:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 618.273124] Lustre: 19247:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 8 previous similar messages [ 618.294755] Lustre: 19247:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 618.319128] Lustre: 19247:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 8 previous similar messages [ 618.346224] Lustre: 19247:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 618.366053] Lustre: 19247:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 8 previous similar messages [ 618.384762] Lustre: 19247:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 618.397477] Lustre: 19247:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 8 previous similar messages [ 619.290684] Lustre: 19247:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 619.307717] Lustre: 19247:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 17 previous similar messages [ 619.313297] Lustre: 19247:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 619.319296] Lustre: 19247:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 17 previous similar messages [ 619.324835] Lustre: 19247:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 619.330340] Lustre: 19247:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 17 previous similar messages [ 619.335148] Lustre: 19247:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 619.341294] Lustre: 19247:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 17 previous similar messages [ 619.453912] Lustre: 20872:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 619.468358] Lustre: 20872:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 20 previous similar messages [ 619.478729] Lustre: 20872:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 619.493654] Lustre: 20872:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 20 previous similar messages [ 621.304106] Lustre: 20872:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 621.311918] Lustre: 20872:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 62 previous similar messages [ 621.317582] Lustre: 20872:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 621.321462] Lustre: 20872:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 62 previous similar messages [ 621.325389] Lustre: 20872:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 621.329490] Lustre: 20872:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 62 previous similar messages [ 621.385325] Lustre: 19246:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 621.389684] Lustre: 19246:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 65 previous similar messages [ 621.503514] Lustre: 19247:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 621.518028] Lustre: 19247:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 65 previous similar messages [ 621.534590] Lustre: 19247:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 621.552272] Lustre: 19247:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 65 previous similar messages [ 625.401520] Lustre: 19247:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 625.409039] Lustre: 19247:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 128 previous similar messages [ 625.414540] Lustre: 19247:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 625.420268] Lustre: 19247:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 128 previous similar messages [ 625.426947] Lustre: 19247:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 625.433476] Lustre: 19247:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 128 previous similar messages [ 625.439138] Lustre: 19247:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 625.445023] Lustre: 19247:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 125 previous similar messages [ 625.513535] Lustre: 19245:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 625.518935] Lustre: 19245:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 125 previous similar messages [ 625.596092] Lustre: 19246:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 625.603298] Lustre: 19246:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 128 previous similar messages [ 628.198279] Lustre: *** cfs_fail_loc=1600, val=3*** [ 631.271525] Lustre: *** cfs_fail_loc=1600, val=3*** [ 634.316236] Lustre: *** cfs_fail_loc=1600, val=3*** [ 638.134048] Lustre: 23462:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 259 < left 274, rollback = 2 [ 638.148857] Lustre: 23462:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 93 previous similar messages [ 638.164928] Lustre: 23462:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 638.165440] Lustre: 21169:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/1, xattr_set: 2/274/0 [ 638.178692] Lustre: 23462:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 94 previous similar messages [ 638.188680] Lustre: 21169:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 93 previous similar messages [ 638.188703] Lustre: 21169:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 0/0/0, punch: 0/0/0, quota 7/225/0 [ 638.188707] Lustre: 21169:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 93 previous similar messages [ 638.188711] Lustre: 21169:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 638.188713] Lustre: 21169:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 90 previous similar messages [ 638.188718] Lustre: 21169:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 638.188720] Lustre: 21169:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 87 previous similar messages [ 649.698946] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 649.709708] 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 [ 649.735533] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 651.234878] 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 [ 651.236584] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 651.265160] Lustre: Skipped 2 previous similar messages [ 651.279418] Lustre: Skipped 3 previous similar messages [ 655.328354] Lustre: server umount lustre-MDT0000 complete [ 659.792379] LustreError: 21179:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1789083485 with bad export cookie 7285788956344465344 [ 659.801614] LustreError: MGC192.168.204.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 659.806019] LustreError: 21179:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 660.293743] Lustre: server umount lustre-MDT0001 complete [ 675.194562] Lustre: server umount lustre-OST0000 complete [ 677.344096] Lustre: 16400:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789083487/real 1789083487] req@ffff8997834fca80 x1875989758071552/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1789083503 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 677.379886] 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 [ 679.656189] Lustre: server umount lustre-OST0001 complete [ 689.915990] Lustre: DEBUG MARKER: == sanity-lfsck test 1a: LFSCK can find out and repair crashed FID-in-dirent ========================================================== 19:38:32 (1789083512) [ 706.970385] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing load_modules_local [ 718.711379] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 719.114588] LustreError: 26214:0:(ldlm_lib.c:1192: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. [ 719.135213] LustreError: 26214:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 5 previous similar messages [ 719.250779] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 723.274990] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 724.450131] LustreError: 26215:0:(ldlm_lib.c:1192: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. [ 729.572516] LustreError: 26214:0:(ldlm_lib.c:1192: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. [ 734.579682] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 734.693585] LustreError: 26215:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 735.032302] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 740.788669] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 744.529317] Lustre: 27355:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 754.826390] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 755.325146] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 759.398986] LustreError: 27709:0:(ldlm_lib.c:1192: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. [ 762.655036] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 764.578172] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:40 to 0x280000401:65) [ 770.032659] LustreError: 27890:0:(ldlm_lib.c:1192: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. [ 770.058735] LustreError: 27890:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 3 previous similar messages [ 772.405463] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 777.717827] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:41 to 0x2c0000401:65) [ 780.702644] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 789.685111] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 794.619356] Lustre: 29228:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 796.914332] Lustre: 29043:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 796.923092] Lustre: 29043:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 33 previous similar messages [ 796.945433] Lustre: 29043:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 796.957992] Lustre: 29043:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 30 previous similar messages [ 796.968298] Lustre: 29043:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 796.987359] Lustre: 29043:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 33 previous similar messages [ 796.997252] Lustre: 29043:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 797.014744] Lustre: 29043:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 33 previous similar messages [ 797.030464] Lustre: 29043:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 797.038461] Lustre: 29043:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 33 previous similar messages [ 797.047851] Lustre: 29043:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 797.059743] Lustre: 29043:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 33 previous similar messages [ 807.188410] Lustre: *** cfs_fail_loc=1501, val=0*** [ 817.293308] Lustre: Failing over lustre-MDT0000 [ 817.562555] Lustre: server umount lustre-MDT0000 complete [ 818.656564] 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 [ 818.659686] LustreError: 27165:0:(ldlm_lib.c:1192: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. [ 818.672501] Lustre: Skipped 3 previous similar messages [ 818.699630] LustreError: 27165:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 3 previous similar messages [ 831.108776] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 831.231390] LustreError: MGC192.168.204.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 831.521462] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 831.536789] Lustre: Skipped 1 previous similar message [ 831.616643] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 835.579155] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 836.591348] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 836.605889] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 836.673634] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 836.734549] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:105 to 0x280000401:129) [ 836.736605] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:105 to 0x2c0000401:129) [ 839.887523] Lustre: *** cfs_fail_loc=1505, val=0*** [ 847.852996] Lustre: DEBUG MARKER: == sanity-lfsck test 1b: LFSCK can find out and repair the missing FID-in-LMA ========================================================== 19:41:10 (1789083670) [ 849.288612] Lustre: 26211:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 849.299720] Lustre: 26211:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 322 previous similar messages [ 849.313997] Lustre: 26211:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 849.320186] Lustre: 26211:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 849.331213] Lustre: 26211:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 849.340543] Lustre: 26211:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 849.347950] Lustre: 26211:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 849.356534] Lustre: 26211:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 849.363336] Lustre: 26211:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 849.369862] Lustre: 26211:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 849.379188] Lustre: 26211:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 849.384874] Lustre: 26211:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 855.441980] Lustre: *** cfs_fail_loc=1502, val=0*** [ 864.573801] Lustre: Failing over lustre-MDT0000 [ 864.918626] Lustre: server umount lustre-MDT0000 complete [ 867.298087] 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 [ 867.318044] LustreError: 26211:0:(ldlm_lib.c:1192: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. [ 867.336421] LustreError: 26211:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 9 previous similar messages [ 878.230922] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 878.533862] LustreError: MGC192.168.204.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 879.060656] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 883.799348] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 884.195478] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 884.224866] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 884.247447] Lustre: Skipped 3 previous similar messages [ 884.300754] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 884.372874] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:169 to 0x280000401:193) [ 884.373427] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:169 to 0x2c0000401:193) [ 888.204678] Lustre: *** cfs_fail_loc=1505, val=0*** [ 896.619797] Lustre: DEBUG MARKER: == sanity-lfsck test 1c: LFSCK can find out and repair lost FID-in-dirent ========================================================== 19:41:59 (1789083719) [ 905.650758] Lustre: *** cfs_fail_loc=1504, val=0*** [ 905.655937] Lustre: *** cfs_fail_loc=1504, val=0*** [ 905.660603] Lustre: Skipped 1 previous similar message [ 915.785642] Lustre: Failing over lustre-MDT0000 [ 916.099170] Lustre: server umount lustre-MDT0000 complete [ 920.037729] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 920.038747] 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 [ 920.079067] Lustre: Skipped 5 previous similar messages [ 928.241372] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 928.401920] LustreError: MGC192.168.204.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 928.743917] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 928.754862] Lustre: Skipped 1 previous similar message [ 928.814613] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 933.863457] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 933.872077] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 933.885857] Lustre: Skipped 3 previous similar messages [ 933.915862] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 933.930043] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 933.966837] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:233 to 0x2c0000401:257) [ 933.967025] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:233 to 0x280000401:257) [ 937.815411] Lustre: *** cfs_fail_loc=1505, val=0*** [ 946.703425] Lustre: DEBUG MARKER: == sanity-lfsck test 2a: LFSCK can find out and repair crashed linkEA entry ========================================================== 19:42:49 (1789083769) [ 948.585094] Lustre: 26210:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 948.605981] Lustre: 26210:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 644 previous similar messages [ 948.613754] Lustre: 26210:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 948.626597] Lustre: 26210:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 948.649425] Lustre: 26210:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 948.668255] Lustre: 26210:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 948.692573] Lustre: 26210:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 948.715134] Lustre: 26210:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 948.727393] Lustre: 26210:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 948.732954] Lustre: 26210:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 948.744445] Lustre: 26210:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 948.753435] Lustre: 26210:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 956.062976] Lustre: *** cfs_fail_loc=1603, val=0*** [ 966.529156] Lustre: Failing over lustre-MDT0000 [ 966.871264] Lustre: server umount lustre-MDT0000 complete [ 969.696657] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 969.707256] 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 [ 969.713747] LustreError: 26209:0:(ldlm_lib.c:1192: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. [ 969.713760] LustreError: 26209:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 16 previous similar messages [ 969.757606] Lustre: Skipped 3 previous similar messages [ 980.473554] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 980.746751] LustreError: MGC192.168.204.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 981.168805] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 986.583164] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 986.593036] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 986.616485] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 986.622536] Lustre: Skipped 3 previous similar messages [ 986.671507] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 986.744888] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:297 to 0x280000401:321) [ 986.745042] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:297 to 0x2c0000401:321) [ 997.952713] Lustre: DEBUG MARKER: == sanity-lfsck test 2b: LFSCK can find out and remove invalid linkEA entry ========================================================== 19:43:40 (1789083820) [ 1005.631262] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1014.745931] Lustre: Failing over lustre-MDT0000 [ 1015.009402] Lustre: server umount lustre-MDT0000 complete [ 1017.318791] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1017.322899] 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 [ 1017.378937] Lustre: Skipped 4 previous similar messages [ 1029.111031] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1029.358864] LustreError: MGC192.168.204.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1029.683847] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1034.727954] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1034.749036] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1034.754390] Lustre: Skipped 3 previous similar messages [ 1034.777927] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1034.855056] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:361 to 0x280000401:385) [ 1034.864463] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:361 to 0x2c0000401:385) [ 1035.989402] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1048.502309] Lustre: DEBUG MARKER: == sanity-lfsck test 2c: LFSCK can find out and remove repeated linkEA entry ========================================================== 19:44:30 (1789083870) [ 1057.371116] Lustre: *** cfs_fail_loc=1605, val=0*** [ 1066.063184] Lustre: Failing over lustre-MDT0000 [ 1066.456429] Lustre: server umount lustre-MDT0000 complete [ 1070.567843] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1080.114474] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1080.199645] LustreError: MGC192.168.204.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1080.404108] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1080.409844] Lustre: Skipped 2 previous similar messages [ 1080.452311] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1085.420718] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1085.425400] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1085.443995] Lustre: Skipped 3 previous similar messages [ 1085.461264] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1085.507262] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:425 to 0x2c0000401:449) [ 1085.508319] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:425 to 0x280000401:449) [ 1085.660550] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1098.372139] Lustre: DEBUG MARKER: == sanity-lfsck test 2d: LFSCK can recover the missing linkEA entry ========================================================== 19:45:21 (1789083921) [ 1099.945779] Lustre: 28441:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 1099.957693] Lustre: 28441:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 968 previous similar messages [ 1099.967233] Lustre: 28441:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 1099.977692] Lustre: 28441:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 968 previous similar messages [ 1099.991174] Lustre: 28441:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 1100.004465] Lustre: 28441:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 968 previous similar messages [ 1100.015129] Lustre: 28441:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 1100.026233] Lustre: 28441:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 968 previous similar messages [ 1100.039193] Lustre: 28441:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 1100.049924] Lustre: 28441:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 968 previous similar messages [ 1100.062789] Lustre: 28441:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 1100.073618] Lustre: 28441:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 968 previous similar messages [ 1106.532495] Lustre: *** cfs_fail_loc=161d, val=0*** [ 1115.228032] Lustre: Failing over lustre-MDT0000 [ 1115.635680] Lustre: server umount lustre-MDT0000 complete [ 1116.128541] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1116.129883] 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 [ 1116.132337] LustreError: 28441:0:(ldlm_lib.c:1192: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. [ 1116.132349] LustreError: 28441:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 31 previous similar messages [ 1116.210362] Lustre: Skipped 6 previous similar messages [ 1129.439654] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1129.667581] LustreError: MGC192.168.204.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1129.997669] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1135.078391] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1135.111535] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1135.118756] Lustre: Skipped 3 previous similar messages [ 1135.138590] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1135.200858] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:489 to 0x2c0000401:513) [ 1135.205023] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:489 to 0x280000401:513) [ 1135.362391] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1145.431227] Lustre: DEBUG MARKER: == sanity-lfsck test 2e: namespace LFSCK can verify remote object linkEA ========================================================== 19:46:08 (1789083968) [ 1148.865471] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1161.727774] Lustre: DEBUG MARKER: == sanity-lfsck test 3: LFSCK can verify multiple-linked objects ========================================================== 19:46:24 (1789083984) [ 1168.905268] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1170.063043] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1184.778679] Lustre: DEBUG MARKER: == sanity-lfsck test 4: FID-in-dirent can be rebuilt after MDT file-level backup/restore ========================================================== 19:46:47 (1789084007) [ 1219.965092] Lustre: Failing over lustre-MDT0000 [ 1220.152405] Lustre: server umount lustre-MDT0000 complete [ 1222.113175] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1225.203308] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1237.141556] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1238.497546] Lustre: 16401:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789084048/real 1789084048] req@ffff8998b1e16a00 x1875989758725888/t0(0) o400->MGC192.168.204.155@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789084064 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1238.556754] LustreError: MGC192.168.204.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1250.619210] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1250.641477] Lustre: lustre-MDT0000: reset Object Index mappings [ 1263.492431] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1268.704759] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1268.720000] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1268.728264] Lustre: Skipped 3 previous similar messages [ 1268.758240] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1268.803425] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:592 to 0x2c0000401:609) [ 1268.804875] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:592 to 0x280000401:609) [ 1269.017317] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1273.402333] LustreError: 42902:0:(lfsck_engine.c:1018:lfsck_master_engine()) lustre-MDT0000-osd: master engine fail to verify the .lustre/lost+found/, go ahead: rc = -115 [ 1273.444154] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1274.465897] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1275.488654] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1277.540465] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1277.548373] Lustre: Skipped 1 previous similar message [ 1284.105666] Lustre: Failing over lustre-MDT0000 [ 1284.720203] Lustre: server umount lustre-MDT0000 complete [ 1289.189443] 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 [ 1289.229917] Lustre: Skipped 7 previous similar messages [ 1289.233760] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1298.157853] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1303.986251] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1304.124751] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:592 to 0x280000401:641) [ 1304.125091] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:592 to 0x2c0000401:641) [ 1307.868118] Lustre: *** cfs_fail_loc=1505, val=0*** [ 1316.510457] Lustre: DEBUG MARKER: == sanity-lfsck test 5: LFSCK can handle IGIF object upgrading ========================================================== 19:48:59 (1789084139) [ 1320.032213] Lustre: *** cfs_fail_loc=1504, val=0*** [ 1331.472256] Lustre: Failing over lustre-MDT0000 [ 1331.898532] Lustre: server umount lustre-MDT0000 complete [ 1337.595955] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1350.045343] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1350.607394] Lustre: 16403:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789084160/real 1789084160] req@ffff8998a5c6ce00 x1875989758831360/t0(0) o400->MGC192.168.204.155@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789084176 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1363.262210] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1363.291629] Lustre: lustre-MDT0000: reset Object Index mappings [ 1375.202743] LustreError: 29043:0:(ldlm_lib.c:1192: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. [ 1375.229381] LustreError: 29043:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 94 previous similar messages [ 1375.591462] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1375.599851] Lustre: Skipped 3 previous similar messages [ 1375.638437] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1375.654628] Lustre: Skipped 1 previous similar message [ 1380.838108] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1380.843279] Lustre: Skipped 1 previous similar message [ 1380.852872] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1380.871747] Lustre: Skipped 7 previous similar messages [ 1380.928070] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1380.943028] Lustre: Skipped 1 previous similar message [ 1381.019539] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:681 to 0x2c0000401:705) [ 1381.021762] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:681 to 0x280000401:705) [ 1381.493474] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1385.802917] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1398.931850] Lustre: Failing over lustre-MDT0000 [ 1399.233132] Lustre: server umount lustre-MDT0000 complete [ 1401.312667] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1411.317316] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1411.468148] LustreError: MGC192.168.204.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1411.480270] LustreError: Skipped 2 previous similar messages [ 1417.298697] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:681 to 0x2c0000401:737) [ 1417.301496] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:681 to 0x280000401:737) [ 1417.372844] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1423.148477] Lustre: *** cfs_fail_loc=1505, val=0*** [ 1423.152019] Lustre: Skipped 84 previous similar messages [ 1436.730973] Lustre: DEBUG MARKER: == sanity-lfsck test 6a: LFSCK resumes from last checkpoint (1) ========================================================== 19:50:58 (1789084258) [ 1439.001183] Lustre: 29043:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 1439.021673] Lustre: 29043:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 1289 previous similar messages [ 1439.042274] Lustre: 29043:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 1439.056332] Lustre: 29043:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1289 previous similar messages [ 1439.075378] Lustre: 29043:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 1439.098386] Lustre: 29043:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1289 previous similar messages [ 1439.118855] Lustre: 29043:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 1439.157607] Lustre: 29043:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1289 previous similar messages [ 1439.172520] Lustre: 29043:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 1439.199468] Lustre: 29043:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1289 previous similar messages [ 1439.216228] Lustre: 29043:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 1439.239419] Lustre: 29043:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1289 previous similar messages [ 1448.073339] Lustre: *** cfs_fail_loc=1600, val=1*** [ 1448.077306] Lustre: Skipped 7 previous similar messages [ 1472.320113] Lustre: DEBUG MARKER: == sanity-lfsck test 6b: LFSCK resumes from last checkpoint (2) ========================================================== 19:51:35 (1789084295) [ 1483.017903] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1483.032633] Lustre: Skipped 10 previous similar messages [ 1511.655924] Lustre: DEBUG MARKER: == sanity-lfsck test 7a: non-stopped LFSCK should auto restarts after MDS remount (1) ========================================================== 19:52:14 (1789084334) [ 1526.879846] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1526.883590] Lustre: Skipped 13 previous similar messages [ 1533.063373] Lustre: Failing over lustre-MDT0000 [ 1535.368249] Lustre: server umount lustre-MDT0000 complete [ 1546.468838] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1546.979731] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1546.997531] Lustre: Skipped 1 previous similar message [ 1552.285418] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1552.360216] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1552.372736] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1552.373262] Lustre: Skipped 1 previous similar message [ 1552.397719] Lustre: Skipped 7 previous similar messages [ 1552.454938] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1552.460945] Lustre: Skipped 1 previous similar message [ 1552.548613] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:853 to 0x280000401:897) [ 1552.567792] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:854 to 0x2c0000401:897) [ 1562.820743] Lustre: DEBUG MARKER: == sanity-lfsck test 7b: non-stopped LFSCK should auto restarts after MDS remount (2) ========================================================== 19:53:05 (1789084385) [ 1579.286249] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing load_modules_local [ 1600.442607] Lustre: 52895:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 1624.496684] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1627.918842] Lustre: 54032:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 1637.891312] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1637.893823] Lustre: Skipped 81 previous similar messages [ 1641.352640] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1642.399454] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1643.423255] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1645.482722] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1645.484731] Lustre: Skipped 1 previous similar message [ 1648.486596] Lustre: Failing over lustre-MDT0000 [ 1648.749124] Lustre: server umount lustre-MDT0000 complete [ 1649.645233] 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 [ 1649.672473] Lustre: Skipped 15 previous similar messages [ 1649.680846] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1660.547264] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1665.870656] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1666.091552] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:946 to 0x2c0000401:961) [ 1666.091552] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:947 to 0x280000401:993) [ 1675.859301] Lustre: DEBUG MARKER: == sanity-lfsck test 8: LFSCK state machine ============== 19:54:58 (1789084498) [ 1681.386713] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1681.396525] Lustre: Skipped 2 previous similar messages [ 1684.793757] Lustre: server umount lustre-MDT0000 complete [ 1688.264501] LustreError: 37165:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1789084514 with bad export cookie 7285788956344679495 [ 1688.268375] LustreError: MGC192.168.204.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1688.275075] LustreError: 37165:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 1688.281803] LustreError: Skipped 2 previous similar messages [ 1688.603237] Lustre: server umount lustre-MDT0001 complete [ 1703.685194] Lustre: server umount lustre-OST0000 complete [ 1707.488628] Lustre: 16402:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789084517/real 1789084517] req@ffff8998b1f47800 x1875989759185024/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1789084533 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1708.491130] Lustre: server umount lustre-OST0001 complete [ 1716.101188] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_hostid [ 1724.648505] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing load_modules_local [ 1776.608430] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing load_modules_local [ 1788.349215] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1788.721220] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 1788.743112] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 1788.790461] Lustre: lustre-MDT0000: new disk, initializing [ 1788.851848] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 1793.302977] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1804.241068] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1804.366767] Lustre: 59095: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 [ 1804.403832] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 1804.408834] Lustre: Skipped 1 previous similar message [ 1804.478794] Lustre: lustre-MDT0001: new disk, initializing [ 1804.553786] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 1804.559038] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 1809.173217] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1814.212896] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 1820.744805] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 1820.900518] Lustre: lustre-OST0000: new disk, initializing [ 1820.903345] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 1820.907713] Lustre: 60726:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 1822.059438] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 1822.087179] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 1822.161345] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 1826.775324] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1838.188642] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 1838.438604] Lustre: lustre-OST0001: new disk, initializing [ 1838.442113] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 1838.455862] Lustre: 61600:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 1839.814720] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 1839.832042] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 1839.950807] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 1845.235041] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1854.977633] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1858.732852] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 1872.919227] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1873.836956] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1873.838825] Lustre: Skipped 19 previous similar messages [ 1879.747585] Lustre: *** cfs_fail_loc=1601, val=2*** [ 1879.759684] Lustre: Skipped 6 previous similar messages [ 1898.174152] Lustre: Failing over lustre-MDT0000 [ 1898.492521] Lustre: server umount lustre-MDT0000 complete [ 1901.537151] LustreError: 59106:0:(ldlm_lib.c:1192: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. [ 1901.562410] LustreError: 59106:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 43 previous similar messages [ 1908.297971] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1908.656464] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1908.667428] Lustre: Skipped 7 previous similar messages [ 1908.721461] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1908.733581] Lustre: Skipped 1 previous similar message [ 1913.575054] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1913.837967] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1913.854614] Lustre: Skipped 1 previous similar message [ 1913.866230] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1913.876444] Lustre: Skipped 7 previous similar messages [ 1913.906020] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1913.911119] Lustre: Skipped 1 previous similar message [ 1913.947426] Lustre: *** cfs_fail_loc=160b, val=2*** [ 1913.957132] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:65) [ 1913.957901] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:65) [ 1922.763935] Lustre: Failing over lustre-MDT0000 [ 1923.082491] Lustre: server umount lustre-MDT0000 complete [ 1924.076942] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1933.035203] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1937.698920] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1938.484434] Lustre: *** cfs_fail_loc=160b, val=2*** [ 1938.498664] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:97) [ 1938.502264] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:97) [ 1944.500437] Lustre: Failing over lustre-MDT0000 [ 1944.777309] Lustre: server umount lustre-MDT0000 complete [ 1954.750778] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1959.843840] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1960.500431] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:129) [ 1960.507361] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:129) [ 1966.847466] Lustre: *** cfs_fail_loc=1602, val=2*** [ 1966.849462] Lustre: Skipped 2 previous similar messages [ 1980.561189] Lustre: DEBUG MARKER: == sanity-lfsck test 9a: LFSCK speed control (1) ========= 20:00:03 (1789084803) [ 1995.134341] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing load_modules_local [ 2014.181230] Lustre: 68580:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 2041.180457] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 2045.649624] Lustre: 69729:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 2055.652042] Lustre: 59102:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 2055.660021] Lustre: 59102:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 2836 previous similar messages [ 2055.667072] Lustre: 59102:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 2055.675623] Lustre: 59102:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 2836 previous similar messages [ 2055.684949] Lustre: 59102:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 2055.692563] Lustre: 59102:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 2836 previous similar messages [ 2055.700321] Lustre: 59102:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 2055.707031] Lustre: 59102:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 2836 previous similar messages [ 2055.712546] Lustre: 59102:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 2055.717828] Lustre: 59102:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 2836 previous similar messages [ 2055.723588] Lustre: 59102:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 2055.728487] Lustre: 59102:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 2836 previous similar messages [ 2182.016662] Lustre: DEBUG MARKER: == sanity-lfsck test 9b: LFSCK speed control (2) ========= 20:03:25 (1789085005) [ 2242.233533] Lustre: *** cfs_fail_loc=1604, val=0*** [ 2242.237490] Lustre: Skipped 4 previous similar messages [ 2269.743161] Lustre: *** cfs_fail_loc=160c, val=0*** [ 2269.750326] Lustre: Skipped 7 previous similar messages [ 2308.223275] Lustre: DEBUG MARKER: == sanity-lfsck test 10: System is available during LFSCK scanning ========================================================== 20:05:30 (1789085130) [ 2361.432546] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2362.434635] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2362.438882] Lustre: Skipped 51 previous similar messages [ 2364.450038] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2364.454846] Lustre: Skipped 102 previous similar messages [ 2368.468865] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2368.471834] Lustre: Skipped 209 previous similar messages [ 2376.475218] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2376.494741] Lustre: Skipped 355 previous similar messages [ 2392.478975] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2392.482469] Lustre: Skipped 766 previous similar messages [ 2424.527628] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2424.529560] Lustre: Skipped 1530 previous similar messages [ 2436.192371] Lustre: *** cfs_fail_loc=1604, val=0*** [ 2436.195544] Lustre: Skipped 2599 previous similar messages [ 2702.462386] Lustre: DEBUG MARKER: == sanity-lfsck test 11a: LFSCK can rebuild lost last_id ========================================================== 20:12:05 (1789085525) [ 2758.291242] Lustre: 59102:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 320, rollback = 2 [ 2758.305735] Lustre: 59102:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 36831 previous similar messages [ 2758.314114] Lustre: 59102:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 1/4/0 [ 2758.318978] Lustre: 59102:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 36831 previous similar messages [ 2758.323491] Lustre: 59102:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 5/5/0, xattr_set: 7/320/0 [ 2758.329437] Lustre: 59102:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 36831 previous similar messages [ 2758.337098] Lustre: 59102:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 6/46/0, punch: 0/0/0, quota 1/3/0 [ 2758.342503] Lustre: 59102:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 36831 previous similar messages [ 2758.348181] Lustre: 59102:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 2/5/0 [ 2758.352767] Lustre: 59102:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 36831 previous similar messages [ 2758.358084] Lustre: 59102:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 1/1/0, ref_del: 2/2/1 [ 2758.363386] Lustre: 59102:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 36831 previous similar messages [ 2882.017025] 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 [ 2882.018808] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2882.038531] Lustre: Skipped 20 previous similar messages [ 2882.060210] Lustre: Skipped 3 previous similar messages [ 2884.730880] Lustre: server umount lustre-MDT0000 complete [ 2887.148148] LustreError: 59101:0:(ldlm_lib.c:1192: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. [ 2887.176371] LustreError: 59101:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 23 previous similar messages [ 2889.607301] LustreError: 59890:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1789085715 with bad export cookie 7285788956344698591 [ 2889.618330] LustreError: MGC192.168.204.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2889.633351] LustreError: 59890:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 2889.677338] LustreError: Skipped 3 previous similar messages [ 2890.075327] Lustre: server umount lustre-MDT0001 complete [ 2905.754896] Lustre: server umount lustre-OST0000 complete [ 2908.640790] Lustre: 16403:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789085718/real 1789085718] req@ffff8998837edf80 x1875989763009280/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1789085734 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2910.499450] Lustre: 16400:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789085720/real 1789085720] req@ffff8998b1f54700 x1875989763009536/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1789085736 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2911.023594] Lustre: server umount lustre-OST0001 complete [ 2919.456723] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: (null) [ 2929.485039] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 2945.120261] LustreError: Failed to get MGS log lustre-sptlrpc and no local copy. [ 2950.239731] LustreError: 74765:0:(mgc_request.c:233:do_config_log_add()) MGC192.168.204.155@tcp: failed processing log, type 4: rc = -110 [ 2975.905100] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 2975.910851] Lustre: Skipped 2 previous similar messages [ 2982.603605] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2987.299191] Lustre: 75350: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. [ 2987.332943] Lustre: *** cfs_fail_loc=160e, val=3*** [ 2990.383722] Lustre: 75350:0:(ofd_dev.c:573:ofd_lfsck_out_notify()) lustre-OST0000: Rebuilt crashed LAST_ID files successfully. [ 2999.388473] Lustre: DEBUG MARKER: == sanity-lfsck test 11b: LFSCK can rebuild crashed last_id ========================================================== 20:17:02 (1789085822) [ 3015.097833] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing load_modules_local [ 3026.924634] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3027.517700] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3271 to 0x280000401:3297) [ 3032.562239] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3042.355181] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3047.857385] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3051.157429] Lustre: 77968:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3069.283484] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3075.070820] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3208 to 0x2c0000401:3233) [ 3077.555968] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3086.736233] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3091.267128] Lustre: 79465:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 3096.411804] Lustre: *** cfs_fail_loc=160d, val=0*** [ 3103.908651] Lustre: Failing over lustre-OST0000 [ 3104.115095] Lustre: server umount lustre-OST0000 complete [ 3104.224308] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 3104.234025] LustreError: Skipped 1 previous similar message [ 3104.237258] 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 [ 3104.257276] Lustre: Skipped 3 previous similar messages [ 3115.190029] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3115.386615] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 3115.401530] Lustre: Skipped 2 previous similar messages [ 3116.905118] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 3116.913786] Lustre: Skipped 2 previous similar messages [ 3116.925564] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 3116.925907] Lustre: lustre-OST0000-osc-MDT0001: Connection restored to 0@lo (at 0@lo) [ 3116.926446] Lustre: *** cfs_fail_loc=215, val=0*** [ 3116.932697] Lustre: Skipped 2 previous similar messages [ 3116.944292] Lustre: Skipped 11 previous similar messages [ 3122.151970] Lustre: *** cfs_fail_loc=215, val=0*** [ 3122.154968] Lustre: Skipped 3 previous similar messages [ 3122.944342] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3127.209152] Lustre: 80865: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. [ 3127.241069] Lustre: 80865:0:(ofd_dev.c:573:ofd_lfsck_out_notify()) lustre-OST0000: Rebuilt crashed LAST_ID files successfully. [ 3127.266828] Lustre: *** cfs_fail_loc=215, val=0*** [ 3127.285088] Lustre: Skipped 1 previous similar message [ 3130.133788] Lustre: Failing over lustre-OST0000 [ 3130.420415] Lustre: server umount lustre-OST0000 complete [ 3139.358980] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3141.304875] Lustre: *** cfs_fail_loc=215, val=0*** [ 3141.310388] Lustre: Skipped 1 previous similar message [ 3145.805942] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3146.720264] Lustre: *** cfs_fail_loc=215, val=0*** [ 3146.732759] Lustre: Skipped 1 previous similar message [ 3154.913190] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3154.917648] Lustre: Skipped 3 previous similar messages [ 3158.487621] Lustre: server umount lustre-MDT0000 complete [ 3162.759536] LustreError: 74772:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1789085988 with bad export cookie 7285788956346279583 [ 3162.764929] LustreError: MGC192.168.204.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3162.773438] LustreError: 74772:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 3 previous similar messages [ 3163.234283] Lustre: server umount lustre-MDT0001 complete [ 3177.712122] Lustre: server umount lustre-OST0000 complete [ 3181.599084] Lustre: 16402:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789085991/real 1789085991] req@ffff8998b1f54380 x1875989763108480/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1789086007 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3182.179774] Lustre: server umount lustre-OST0001 complete [ 3191.055136] Lustre: DEBUG MARKER: == sanity-lfsck test 12a: single command to trigger LFSCK on all devices ========================================================== 20:20:14 (1789086014) [ 3206.309745] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing load_modules_local [ 3218.402437] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3223.884858] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3233.768325] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3239.621792] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3242.608694] Lustre: 85250:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3249.968313] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3257.475914] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3263.669699] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3362 to 0x280000401:3393) [ 3266.388655] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3272.179499] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3208 to 0x2c0000401:3265) [ 3273.290411] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3281.802926] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3285.382464] Lustre: 87119:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 3319.303726] Lustre: DEBUG MARKER: == sanity-lfsck test 12b: auto detect Lustre device ====== 20:22:22 (1789086142) [ 3333.741379] Lustre: DEBUG MARKER: == sanity-lfsck test 13: LFSCK can repair crashed lmm_oi ========================================================== 20:22:36 (1789086156) [ 3334.992381] Lustre: *** cfs_fail_loc=160f, val=0*** [ 3347.063405] Lustre: DEBUG MARKER: == sanity-lfsck test 14a: LFSCK can repair MDT-object with dangling LOV EA reference (1) ========================================================== 20:22:49 (1789086169) [ 3351.469176] Lustre: *** cfs_fail_loc=1610, val=0*** [ 3351.477081] Lustre: Skipped 7 previous similar messages [ 3358.904983] Lustre: 88674:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 252 < left 278, rollback = 2 [ 3358.917710] Lustre: 88674:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 1234 previous similar messages [ 3358.928149] Lustre: 88674:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 3358.947048] Lustre: 88674:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1234 previous similar messages [ 3358.960825] Lustre: 88674:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3358.976613] Lustre: 88674:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1234 previous similar messages [ 3358.989970] Lustre: 88674:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/1, punch: 0/0/0, quota 1/3/2 [ 3359.003033] Lustre: 88674:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1234 previous similar messages [ 3359.017870] Lustre: 88674:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/1, delete: 0/0/0 [ 3359.027071] Lustre: 88674:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1234 previous similar messages [ 3359.036759] Lustre: 88674:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3359.048740] Lustre: 88674:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1234 previous similar messages [ 3403.232424] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3403.243502] 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 [ 3403.275108] Lustre: Skipped 7 previous similar messages [ 3403.287040] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3407.483794] Lustre: server umount lustre-MDT0000 complete [ 3411.146634] LustreError: 85629:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1789086237 with bad export cookie 7285788956346288039 [ 3411.147607] LustreError: MGC192.168.204.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3411.157470] LustreError: 85629:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 3411.297779] Lustre: server umount lustre-MDT0001 complete [ 3424.882993] Lustre: server umount lustre-OST0000 complete [ 3440.029824] Lustre: server umount lustre-OST0001 complete [ 3459.500435] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing load_modules_local [ 3469.874777] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3475.137238] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3484.072881] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3489.614336] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3492.614866] Lustre: 92986:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3500.164782] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3506.231483] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3509.734983] LustreError: 93340:0:(ldlm_lib.c:1192: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. [ 3509.752139] LustreError: 93340:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 51 previous similar messages [ 3509.757371] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:116 to 0x280000400:161) [ 3515.429221] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3516.654948] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:116 to 0x2c0000400:161) [ 3516.655165] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3317 to 0x2c0000401:3361) [ 3516.757269] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3554 to 0x280000401:3585) [ 3522.754168] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3532.091352] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3536.422752] Lustre: 94858:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 3543.080818] Lustre: DEBUG MARKER: == sanity-lfsck test 14b: LFSCK can repair MDT-object with dangling LOV EA reference (2) ========================================================== 20:26:05 (1789086365) [ 3547.291170] Lustre: *** cfs_fail_loc=1610, val=0*** [ 3547.305192] Lustre: Skipped 63 previous similar messages [ 3573.219238] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3573.231707] Lustre: Skipped 7 previous similar messages [ 3578.336548] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3578.353327] Lustre: Skipped 3 previous similar messages [ 3578.911897] Lustre: server umount lustre-MDT0000 complete [ 3582.833299] LustreError: 91826:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1789086408 with bad export cookie 7285788956346316466 [ 3582.841739] LustreError: 91826:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 3583.151885] Lustre: server umount lustre-MDT0001 complete [ 3596.243364] Lustre: server umount lustre-OST0000 complete [ 3599.845335] Lustre: 16403:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789086409/real 1789086409] req@ffff8998a5c68700 x1875989763470848/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1789086425 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3600.331396] Lustre: server umount lustre-OST0001 complete [ 3617.393177] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing load_modules_local [ 3628.270394] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3628.827433] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3628.833964] Lustre: Skipped 13 previous similar messages [ 3632.639669] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3640.734124] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3644.953164] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3647.891526] Lustre: 98889:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3654.445838] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3660.291184] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3666.033576] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:116 to 0x280000400:193) [ 3671.017803] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3673.212593] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3317 to 0x2c0000401:3393) [ 3673.223529] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:116 to 0x2c0000400:193) [ 3673.380745] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3682 to 0x280000401:3713) [ 3679.711995] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3688.086322] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3700.899681] Lustre: DEBUG MARKER: == sanity-lfsck test 15a: LFSCK can repair unmatched MDT-object/OST-object pairs (1) ========================================================== 20:28:43 (1789086523) [ 3704.928478] Lustre: *** cfs_fail_loc=1611, val=0*** [ 3704.931249] Lustre: Skipped 63 previous similar messages [ 3705.081204] Lustre: *** cfs_fail_loc=1611, val=0*** [ 3718.690462] Lustre: DEBUG MARKER: == sanity-lfsck test 15b: LFSCK can repair unmatched MDT-object/OST-object pairs (2) ========================================================== 20:29:01 (1789086541) [ 3721.622672] Lustre: *** cfs_fail_loc=1612, val=0*** [ 3721.696479] Lustre: *** cfs_fail_loc=1612, val=0*** [ 3721.699411] Lustre: Skipped 3 previous similar messages [ 3733.601698] Lustre: DEBUG MARKER: == sanity-lfsck test 15c: LFSCK can repair unmatched MDT-object/OST-object pairs (3) ========================================================== 20:29:16 (1789086556) [ 3735.371252] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_15c MDS newer than 2.7.55, LU-6475 [ 3737.509322] Lustre: DEBUG MARKER: == sanity-lfsck test 15d: LFSCK don't crash upon dir migration failure ========================================================== 20:29:20 (1789086560) [ 3743.543150] Lustre: *** cfs_fail_loc=1709, val=0*** [ 3743.581942] LustreError: 97757:0:(mdt_reint.c:2644:mdt_reint_migrate()) lustre-MDT0000: migrate [0x240002340:0x6c:0x0]/f59 failed: rc = -5 [ 3749.689854] LustreError: 97745:0:(lod_object.c:945:lod_load_lmv_shards()) lustre-MDT0001-mdtlov: the shard [0x200003ab1:0x46:0x0]:1 for the striped directory [0x240002340:0x88:0x0] is out of the known LMV EA range [0 - 0], failout [ 3753.581936] LustreError: 97745:0:(lod_object.c:945:lod_load_lmv_shards()) lustre-MDT0001-mdtlov: the shard [0x200003ab1:0x46:0x0]:1 for the striped directory [0x240002340:0x88:0x0] is out of the known LMV EA range [0 - 0], failout [ 3753.609463] LustreError: 97745:0:(mdt_handler.c:1498:mdt_getattr_internal()) lustre-MDT0001: getattr error for [0x240002340:0x88:0x0]: rc = -5 [ 3791.329725] 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 [ 3791.351792] Lustre: Skipped 8 previous similar messages [ 3791.361785] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3791.372921] Lustre: Skipped 3 previous similar messages [ 3798.998427] Lustre: server umount lustre-MDT0000 complete [ 3808.343373] LustreError: 101964:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1789086634 with bad export cookie 7285788956346331187 [ 3808.356720] LustreError: MGC192.168.204.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3808.359339] LustreError: 101964:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 3 previous similar messages [ 3808.384806] LustreError: Skipped 1 previous similar message [ 3808.983300] Lustre: server umount lustre-MDT0001 complete [ 3827.167475] Lustre: 16401:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789086637/real 1789086637] req@ffff89978b847480 x1875989763687424/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1789086653 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3828.411842] Lustre: server umount lustre-OST0000 complete [ 3835.872068] Lustre: 16402:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789086645/real 1789086645] req@ffff89978431ea00 x1875989763688320/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1789086661 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3835.910893] Lustre: 16402:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 3837.986948] Lustre: server umount lustre-OST0001 complete [ 3866.917620] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing unload_modules_local [ 3869.992469] Key type lgssc unregistered [ 3870.397976] LNet: 104608:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 3870.408682] LNetError: 104608:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 3870.423597] LNet: Removed LNI 192.168.204.155@tcp [ 3871.474111] Key type .llcrypt unregistered [ 3871.476902] Key type ._llcrypt unregistered [ 3898.839839] Key type ._llcrypt registered [ 3898.842360] Key type .llcrypt registered [ 3898.923277] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_hostid [ 3915.036391] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing load_modules_local [ 3917.562145] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 3917.631242] alg: No test for adler32 (adler32-zlib) [ 3918.654898] Lustre: Lustre: Build Version: 2.17.55_25_gfa4fa99 [ 3918.907679] LNet: Added LNI 192.168.204.155@tcp [8/256/0/180] [ 3920.639248] Key type lgssc registered [ 3921.860294] Lustre: Echo OBD driver; http://www.lustre.org/ [ 3981.820233] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing load_modules_local [ 3997.588344] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 3997.625630] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3998.927949] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 3998.964987] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 3999.061164] Lustre: lustre-MDT0000: new disk, initializing [ 3999.140476] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3999.158259] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 4005.259861] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4022.534470] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4022.702400] Lustre: 109070: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 [ 4022.819531] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 4022.827023] Lustre: Skipped 1 previous similar message [ 4022.892907] Lustre: lustre-MDT0001: new disk, initializing [ 4022.958970] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 4022.990281] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 4023.011550] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 4029.189550] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4034.952580] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 4046.660973] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4046.947377] Lustre: lustre-OST0000: new disk, initializing [ 4046.957950] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 4046.965624] Lustre: 111011:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 4047.044441] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 4053.518865] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 4053.530798] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 4053.617780] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 4054.356385] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4069.174195] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4069.338461] Lustre: lustre-OST0001: new disk, initializing [ 4069.342790] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 4069.350492] Lustre: 112035:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 4069.484452] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 4076.994838] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4078.657540] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 4078.668843] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 4078.748655] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 4089.650553] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4098.730441] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 4105.558545] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 20:35:28 (1789086928) === [ 4112.968859] Lustre: DEBUG MARKER: == sanity-lfsck test 16: LFSCK can repair inconsistent MDT-object/OST-object owner ========================================================== 20:35:35 (1789086935) [ 4113.143663] Lustre: 113126:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 251 < left 278, rollback = 2 [ 4113.154901] Lustre: 113126:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4113.162470] Lustre: 113126:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4113.170725] Lustre: 113126:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 4113.194599] Lustre: 113126:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 4113.208374] Lustre: 113126:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4113.715625] Lustre: 110753:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 4113.729894] Lustre: 110753:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 6 previous similar messages [ 4113.741045] Lustre: 110753:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 4113.754464] Lustre: 110753:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 6 previous similar messages [ 4113.765671] Lustre: 110753:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4113.772894] Lustre: 110753:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 6 previous similar messages [ 4113.792344] Lustre: 110753:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 4113.804693] Lustre: 110753:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 6 previous similar messages [ 4113.813150] Lustre: 110753:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 4113.827314] Lustre: 110753:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 6 previous similar messages [ 4113.839064] Lustre: 110753:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4113.854080] Lustre: 110753:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 6 previous similar messages [ 4114.729328] Lustre: 113126:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 4114.738565] Lustre: 113126:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 107 previous similar messages [ 4114.745371] Lustre: 113126:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 4114.752486] Lustre: 113126:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 107 previous similar messages [ 4114.778870] Lustre: 109078:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4114.787254] Lustre: 109078:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 110 previous similar messages [ 4114.792947] Lustre: 109078:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 7/369/0 [ 4114.799267] Lustre: 109078:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 110 previous similar messages [ 4114.815112] Lustre: 109078:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 4114.824761] Lustre: 109078:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 112 previous similar messages [ 4114.843163] Lustre: 110753:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 4114.848544] Lustre: 110753:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 113 previous similar messages [ 4117.095304] Lustre: *** cfs_fail_loc=1613, val=0*** [ 4130.233534] Lustre: DEBUG MARKER: == sanity-lfsck test 17: LFSCK can repair multiple references ========================================================== 20:35:52 (1789086952) [ 4131.797940] Lustre: 113126:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 256 < left 278, rollback = 2 [ 4131.805450] Lustre: 113126:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 194 previous similar messages [ 4131.810657] Lustre: 113126:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/2, destroy: 0/0/0 [ 4131.815283] Lustre: 113126:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 194 previous similar messages [ 4131.821352] Lustre: 113126:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4131.828426] Lustre: 113126:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 191 previous similar messages [ 4131.836318] Lustre: 113126:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 4131.843596] Lustre: 113126:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 191 previous similar messages [ 4131.850842] Lustre: 113126:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 4131.861824] Lustre: 113126:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 189 previous similar messages [ 4131.870514] Lustre: 113126:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4131.879727] Lustre: 113126:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 188 previous similar messages [ 4133.002096] Lustre: *** cfs_fail_loc=1614, val=0*** [ 4133.548106] Lustre: *** cfs_fail_loc=1614, val=103*** [ 4133.552951] Lustre: Skipped 1 previous similar message [ 4138.237704] Lustre: 111002:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 259 < left 275, rollback = 2 [ 4138.256606] Lustre: 111002:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 11 previous similar messages [ 4138.267881] Lustre: 111002:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 4138.282558] Lustre: 111002:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 4138.291052] Lustre: 111002:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/1, xattr_set: 3/275/0 [ 4138.304852] Lustre: 111002:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 4138.313843] Lustre: 111002:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/9/0, punch: 1/4/0, quota 7/225/0 [ 4138.334798] Lustre: 111002:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 4138.352994] Lustre: 111002:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 4138.362900] Lustre: 111002:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 4138.379773] Lustre: 111002:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 4138.397531] Lustre: 111002:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 4146.465430] Lustre: DEBUG MARKER: == sanity-lfsck test 18a: Find out orphan OST-object and repair it (1) ========================================================== 20:36:09 (1789086969) [ 4146.960407] Lustre: 109078:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 252 < left 278, rollback = 2 [ 4146.967382] Lustre: 109078:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 1 previous similar message [ 4146.972150] Lustre: 109078:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4146.980295] Lustre: 109078:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1 previous similar message [ 4146.986092] Lustre: 109078:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4146.992361] Lustre: 109078:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1 previous similar message [ 4147.001988] Lustre: 109078:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 4147.016126] Lustre: 109078:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1 previous similar message [ 4147.023250] Lustre: 109078:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 4147.028696] Lustre: 109078:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1 previous similar message [ 4147.043518] Lustre: 109078:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4147.051455] Lustre: 109078:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1 previous similar message [ 4149.594949] Lustre: *** cfs_fail_loc=1615, val=0*** [ 4149.597628] Lustre: Skipped 1 previous similar message [ 4150.697799] Lustre: *** cfs_fail_loc=1615, val=0*** [ 4150.700499] Lustre: Skipped 1 previous similar message [ 4171.750245] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_18b skipping excluded test 18b [ 4174.331323] Lustre: DEBUG MARKER: == sanity-lfsck test 18c: Find out orphan OST-object and repair it (3) ========================================================== 20:36:36 (1789086996) [ 4174.940942] Lustre: 110753:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 4174.951676] Lustre: 110753:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 21 previous similar messages [ 4174.956233] Lustre: 110753:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 4174.960512] Lustre: 110753:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4174.964202] Lustre: 110753:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4174.969079] Lustre: 110753:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4174.974798] Lustre: 110753:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 4174.987329] Lustre: 110753:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4175.000280] Lustre: 110753:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 4175.011599] Lustre: 110753:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4175.018016] Lustre: 110753:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4175.030234] Lustre: 110753:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4177.641513] Lustre: *** cfs_fail_loc=1617, val=0*** [ 4177.748210] Lustre: *** cfs_fail_loc=1617, val=0*** [ 4180.182253] Lustre: *** cfs_fail_loc=1616, val=0*** [ 4180.191115] Lustre: Skipped 3 previous similar messages [ 4200.483642] Lustre: DEBUG MARKER: == sanity-lfsck test 18d: Find out orphan OST-object and repair it (4) ========================================================== 20:37:03 (1789087023) [ 4203.071906] Lustre: *** cfs_fail_loc=1618, val=0*** [ 4203.084201] Lustre: Skipped 5 previous similar messages [ 4237.281663] 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 [ 4237.282402] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4237.299761] Lustre: Skipped 2 previous similar messages [ 4237.311260] Lustre: Skipped 3 previous similar messages [ 4242.401856] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4242.414230] Lustre: Skipped 3 previous similar messages [ 4243.460831] Lustre: server umount lustre-MDT0000 complete [ 4248.387218] LustreError: 109062:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1789087074 with bad export cookie 9743611387243190604 [ 4248.392167] LustreError: MGC192.168.204.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4248.402243] LustreError: 109062:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 4248.729490] Lustre: server umount lustre-MDT0001 complete [ 4263.535857] Lustre: server umount lustre-OST0000 complete [ 4277.372738] Lustre: server umount lustre-OST0001 complete [ 4297.793676] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing load_modules_local [ 4309.546382] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4310.055636] LustreError: 117760:0:(ldlm_lib.c:1192: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. [ 4310.090722] LustreError: 117760:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 5 previous similar messages [ 4310.189192] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4315.593191] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4315.617317] LustreError: 117761:0:(ldlm_lib.c:1192: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. [ 4320.735754] LustreError: 117760:0:(ldlm_lib.c:1192: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. [ 4325.264484] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4325.701563] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 4330.668268] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4334.291351] Lustre: 118900:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 4340.894878] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4348.516763] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4350.313222] LustreError: 119252:0:(ldlm_lib.c:1192: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. [ 4350.324428] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:4 to 0x280000400:33) [ 4355.439232] LustreError: 119692:0:(ldlm_lib.c:1192: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. [ 4355.456578] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:116 to 0x280000401:161) [ 4355.465631] LustreError: 119692:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 1 previous similar message [ 4358.686338] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4358.929291] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 4358.938628] Lustre: Skipped 1 previous similar message [ 4364.265577] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:33) [ 4364.271696] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:4 to 0x2c0000401:33) [ 4366.446487] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4375.505572] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4379.966680] Lustre: 120769:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 4395.665156] Lustre: DEBUG MARKER: == sanity-lfsck test 18e: Find out orphan OST-object and repair it (5) ========================================================== 20:40:18 (1789087218) [ 4396.088878] Lustre: 117756:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 252 < left 278, rollback = 2 [ 4396.098380] Lustre: 117756:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 46 previous similar messages [ 4396.110050] Lustre: 117756:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4396.119830] Lustre: 117756:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4396.129242] Lustre: 117756:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4396.134419] Lustre: 117756:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4396.146984] Lustre: 117756:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/1 [ 4396.160113] Lustre: 117756:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4396.169416] Lustre: 117756:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 4396.176610] Lustre: 117756:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4396.183414] Lustre: 117756:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4396.189658] Lustre: 117756:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4398.064954] Lustre: *** cfs_fail_loc=1618, val=0*** [ 4398.072452] Lustre: Skipped 3 previous similar messages [ 4433.376297] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4433.391209] 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 [ 4433.423842] Lustre: Skipped 1 previous similar message [ 4433.432884] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4435.940135] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4435.940754] 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 [ 4435.949789] Lustre: Skipped 1 previous similar message [ 4435.977367] Lustre: Skipped 1 previous similar message [ 4438.667608] Lustre: server umount lustre-MDT0000 complete [ 4441.061158] LustreError: 117757:0:(ldlm_lib.c:1192: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. [ 4441.096395] LustreError: 117757:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 3 previous similar messages [ 4443.062622] LustreError: 117740:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1789087269 with bad export cookie 9743611387243205864 [ 4443.068213] LustreError: MGC192.168.204.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4443.074064] LustreError: 117740:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 4443.343862] Lustre: server umount lustre-MDT0001 complete [ 4457.280763] Lustre: server umount lustre-OST0000 complete [ 4471.280137] Lustre: server umount lustre-OST0001 complete [ 4489.198512] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing load_modules_local [ 4500.943528] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4501.329482] LustreError: 123340:0:(ldlm_lib.c:1192: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. [ 4501.417191] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4506.199827] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4516.654577] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4516.831800] Lustre: lustre-MDT0001: Not available for connect from 0@lo (not set up) [ 4516.843395] Lustre: Skipped 2 previous similar messages [ 4522.688763] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4526.240060] Lustre: 124483:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 4534.957296] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4541.419844] LustreError: 124835:0:(ldlm_lib.c:1192: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. [ 4541.445599] LustreError: 124835:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 2 previous similar messages [ 4541.458800] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:4 to 0x280000400:65) [ 4544.423244] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4546.550548] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:166 to 0x280000401:193) [ 4557.273463] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4562.953348] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:4 to 0x2c0000401:65) [ 4562.964058] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:65) [ 4566.973066] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4576.591683] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4581.014947] Lustre: 126353:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 4589.153145] Lustre: 123341:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 252 < left 260, rollback = 2 [ 4589.160157] Lustre: 123341:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 21 previous similar messages [ 4589.165982] Lustre: 123341:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4589.173559] Lustre: 123341:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4589.189893] Lustre: 123341:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 0/0/0, xattr_set: 1/260/0 [ 4589.202189] Lustre: 123341:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4589.216137] Lustre: 123341:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/9/0, punch: 0/0/0, quota 4/150/2 [ 4589.223152] Lustre: 123341:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4589.233480] Lustre: 123341:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 1/17/2, delete: 0/0/0 [ 4589.237208] Lustre: *** cfs_fail_loc=1602, val=10*** [ 4589.243332] Lustre: 123341:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4589.243362] Lustre: 123341:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 4589.243365] Lustre: 123341:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4589.279638] Lustre: Skipped 1 previous similar message [ 4620.732511] Lustre: DEBUG MARKER: == sanity-lfsck test 18f: Skip the failed OST(s) when handle orphan OST-objects ========================================================== 20:44:03 (1789087443) [ 4624.498044] Lustre: *** cfs_fail_loc=1616, val=0*** [ 4624.510690] Lustre: Skipped 3 previous similar messages [ 4632.186471] Lustre: *** cfs_fail_loc=161c, val=0*** [ 4652.587721] Lustre: DEBUG MARKER: == sanity-lfsck test 18g: Find out orphan OST-object and repair it (7) ========================================================== 20:44:35 (1789087475) [ 4655.150319] Lustre: *** cfs_fail_loc=162e, val=0*** [ 4671.182417] Lustre: DEBUG MARKER: == sanity-lfsck test 18h: LFSCK can repair crashed PFL extent range ========================================================== 20:44:53 (1789087493) [ 4677.612433] Lustre: *** cfs_fail_loc=162f, val=0*** [ 4677.615185] Lustre: Skipped 9 previous similar messages [ 4700.598836] Lustre: DEBUG MARKER: == sanity-lfsck test 19a: OST-object inconsistency self detect ========================================================== 20:45:22 (1789087522) [ 4717.579620] Lustre: DEBUG MARKER: == sanity-lfsck test 19b: OST-object inconsistency self repair ========================================================== 20:45:39 (1789087539) [ 4718.194544] Lustre: 123337:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 253 < left 278, rollback = 2 [ 4718.199940] Lustre: 123337:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 94 previous similar messages [ 4718.205037] Lustre: 123337:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4718.209428] Lustre: 123337:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 94 previous similar messages [ 4718.217314] Lustre: 123337:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4718.226583] Lustre: 123337:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 94 previous similar messages [ 4718.234410] Lustre: 123337:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/1 [ 4718.245460] Lustre: 123337:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 94 previous similar messages [ 4718.253341] Lustre: 123337:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 4718.260748] Lustre: 123337:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 94 previous similar messages [ 4718.268226] Lustre: 123337:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4718.285226] Lustre: 123337:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 94 previous similar messages [ 4721.864839] Lustre: *** cfs_fail_loc=1611, val=0*** [ 4721.910893] Lustre: *** cfs_fail_loc=1611, val=0*** [ 4721.912902] Lustre: Skipped 3 previous similar messages [ 4728.422181] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.204.55@tcp inode [0x2000013a1:0x1f:0x0] object 0x280000401:203 extent [0-4095], client returned csum 0 (type 20), server csum a10080 (type 20) [ 4730.019342] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.204.55@tcp inode [0x2000013a1:0x20:0x0] object 0x280000401:204 extent [0-4095], client returned csum 0 (type 20), server csum a0007f (type 20) [ 4739.964180] Lustre: DEBUG MARKER: == sanity-lfsck test 20a: Handle the orphan with dummy LOV EA slot properly ========================================================== 20:46:02 (1789087562) [ 4743.218093] Lustre: *** cfs_fail_loc=1616, val=0*** [ 4743.226307] Lustre: Skipped 1 previous similar message [ 4769.784798] Lustre: DEBUG MARKER: == sanity-lfsck test 20b: Handle the orphan with dummy LOV EA slot properly - PFL case ========================================================== 20:46:32 (1789087592) [ 4776.765501] Lustre: DEBUG MARKER: == sanity-lfsck test 21: run all LFSCK components by default ========================================================== 20:46:39 (1789087599) [ 4791.450762] Lustre: DEBUG MARKER: == sanity-lfsck test 22a: LFSCK can repair unmatched pairs (1) ========================================================== 20:46:53 (1789087613) [ 4795.290589] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4795.313096] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4795.320061] Lustre: Skipped 1 previous similar message [ 4807.461593] Lustre: DEBUG MARKER: == sanity-lfsck test 22b: LFSCK can repair unmatched pairs (2) ========================================================== 20:47:10 (1789087630) [ 4809.440893] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4809.453787] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4821.740893] Lustre: DEBUG MARKER: == sanity-lfsck test 23a: LFSCK can repair dangling name entry (1) ========================================================== 20:47:24 (1789087644) [ 4823.624175] Lustre: *** cfs_fail_loc=1620, val=0*** [ 4838.482911] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_23b skipping excluded test 23b [ 4840.773388] Lustre: DEBUG MARKER: == sanity-lfsck test 23c: LFSCK can repair dangling name entry (3) ========================================================== 20:47:43 (1789087663) [ 4847.171442] Lustre: *** cfs_fail_loc=1621, val=127*** [ 4847.178132] Lustre: Skipped 1 previous similar message [ 4850.398370] Lustre: *** cfs_fail_loc=1602, val=10*** [ 4872.219643] Lustre: DEBUG MARKER: == sanity-lfsck test 23d: LFSCK can repair a dangling name entry to a remote object ========================================================== 20:48:14 (1789087694) [ 4875.154545] Lustre: Failing over lustre-MDT0000 [ 4875.244956] 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 [ 4875.265140] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4875.270713] Lustre: Skipped 2 previous similar messages [ 4875.271475] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4875.300226] Lustre: Skipped 3 previous similar messages [ 4875.854751] Lustre: server umount lustre-MDT0000 complete [ 4876.479534] LustreError: 124080:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.204.55@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4876.516146] LustreError: 124080:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 6 previous similar messages [ 4888.506325] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4888.697259] LustreError: MGC192.168.204.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4888.996569] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4889.002388] Lustre: Skipped 3 previous similar messages [ 4889.051022] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4891.816371] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4894.198060] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4894.243973] Lustre: lustre-MDT0000: Recovery over after 0:03, of 2 clients 2 recovered and 0 were evicted. [ 4894.300472] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:265 to 0x280000401:289) [ 4894.300573] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:130 to 0x2c0000401:161) [ 4894.381785] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4896.683248] LustreError: 123337:0:(mdt_open.c:1324:mdt_cross_open()) lustre-MDT0000: [0x2000013a3:0x82:0x0] doesn't exist!: rc = -14 [ 4910.171954] Lustre: DEBUG MARKER: == sanity-lfsck test 24: LFSCK can repair multiple-referenced name entry ========================================================== 20:48:52 (1789087732) [ 4912.853778] Lustre: *** cfs_fail_loc=1622, val=0*** [ 4913.066804] Lustre: *** cfs_fail_loc=1622, val=0*** [ 4913.073221] Lustre: Skipped 1 previous similar message [ 4927.334477] Lustre: DEBUG MARKER: == sanity-lfsck test 25: LFSCK can repair bad file type in the name entry ========================================================== 20:49:09 (1789087749) [ 4929.370648] Lustre: *** cfs_fail_loc=1623, val=0*** [ 4942.740855] Lustre: DEBUG MARKER: == sanity-lfsck test 26a: LFSCK can add the missing local name entry back to the namespace ========================================================== 20:49:25 (1789087765) [ 4944.918452] Lustre: *** cfs_fail_loc=1624, val=0*** [ 4957.611660] Lustre: DEBUG MARKER: == sanity-lfsck test 26b: LFSCK can add the missing remote name entry back to the namespace ========================================================== 20:49:40 (1789087780) [ 4972.510297] Lustre: DEBUG MARKER: == sanity-lfsck test 27a: LFSCK can recreate the lost local parent directory as orphan ========================================================== 20:49:54 (1789087794) [ 4974.632353] Lustre: *** cfs_fail_loc=1624, val=0*** [ 4974.641468] Lustre: Skipped 1 previous similar message [ 4987.429059] Lustre: DEBUG MARKER: == sanity-lfsck test 27b: LFSCK can recreate the lost remote parent directory as orphan ========================================================== 20:50:10 (1789087810) [ 4987.749799] Lustre: 124080:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 252 < left 278, rollback = 2 [ 4987.761493] Lustre: 124080:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 497 previous similar messages [ 4987.772727] Lustre: 124080:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4987.782119] Lustre: 124080:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 497 previous similar messages [ 4987.794378] Lustre: 124080:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4987.798970] Lustre: 124080:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 497 previous similar messages [ 4987.804313] Lustre: 124080:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 4987.811421] Lustre: 124080:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 497 previous similar messages [ 4987.818552] Lustre: 124080:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 4987.822418] Lustre: 124080:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 497 previous similar messages [ 4987.828551] Lustre: 124080:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4987.833449] Lustre: 124080:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 497 previous similar messages [ 5002.782230] Lustre: DEBUG MARKER: == sanity-lfsck test 28: Skip the failed MDT(s) when handle orphan MDT-objects ========================================================== 20:50:25 (1789087825) [ 5009.718887] Lustre: *** cfs_fail_loc=161c, val=0*** [ 5009.726301] Lustre: Skipped 1 previous similar message [ 5027.867858] Lustre: DEBUG MARKER: == sanity-lfsck test 29b: LFSCK can repair bad nlink count (2) ========================================================== 20:50:50 (1789087850) [ 5029.961633] Lustre: *** cfs_fail_loc=1626, val=0*** [ 5029.967243] Lustre: Skipped 4 previous similar messages [ 5042.803961] Lustre: DEBUG MARKER: == sanity-lfsck test 29c: verify linkEA size limitation == 20:51:05 (1789087865) [ 5074.221944] Lustre: DEBUG MARKER: == sanity-lfsck test 29d: accessing non-existing inode shouldn't turn fs read-only (ldiskfs) ========================================================== 20:51:37 (1789087897) [ 5076.904770] LustreError: 123336:0:(osd_handler.c:284:osd_idc_find_or_init()) lustre-MDT0000: cannot lookup FID [0x2000013a3:0x9e:0x0]: rc = -2 [ 5084.174566] Lustre: DEBUG MARKER: == sanity-lfsck test 30: LFSCK can recover the orphans from backend /lost+found ========================================================== 20:51:47 (1789087907) [ 5108.133844] Lustre: Failing over lustre-MDT0000 [ 5108.395195] Lustre: server umount lustre-MDT0000 complete [ 5109.221418] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 5109.229601] 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 [ 5109.245983] Lustre: Skipped 2 previous similar messages [ 5109.259356] LustreError: 126614:0:(ldlm_lib.c:1192: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. [ 5109.271387] LustreError: 126614:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 13 previous similar messages [ 5120.247698] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 5120.332621] LustreError: MGC192.168.204.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5120.589405] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 5120.660767] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 5125.067082] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5125.608945] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 5125.633451] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 5125.641722] Lustre: Skipped 3 previous similar messages [ 5125.672856] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 5125.751060] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:295 to 0x280000401:321) [ 5125.752781] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:166 to 0x2c0000401:193) [ 5138.644813] Lustre: DEBUG MARKER: == sanity-lfsck test 31a: The LFSCK can find/repair the name entry with bad name hash (1) ========================================================== 20:52:41 (1789087961) [ 5152.314869] Lustre: DEBUG MARKER: == sanity-lfsck test 31b: The LFSCK can find/repair the name entry with bad name hash (2) ========================================================== 20:52:55 (1789087975) [ 5168.123993] Lustre: DEBUG MARKER: == sanity-lfsck test 31c: Re-generate the lost master LMV EA for striped directory ========================================================== 20:53:10 (1789087990) [ 5169.587958] Lustre: *** cfs_fail_loc=1629, val=0*** [ 5169.591557] Lustre: Skipped 5 previous similar messages [ 5185.013196] Lustre: DEBUG MARKER: == sanity-lfsck test 31d: Set broken striped directory (modified after broken) as read-only ========================================================== 20:53:27 (1789088007) [ 5192.282071] Lustre: Failing over lustre-MDT0000 [ 5192.560949] Lustre: server umount lustre-MDT0000 complete [ 5197.281926] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 5197.287016] 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 [ 5197.314530] Lustre: Skipped 6 previous similar messages [ 5201.363958] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5201.513452] LustreError: MGC192.168.204.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5201.726134] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 5205.998778] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5207.016637] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 5207.018566] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 5207.045993] Lustre: Skipped 3 previous similar messages [ 5207.065283] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 5207.123955] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:295 to 0x280000401:353) [ 5207.124575] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:166 to 0x2c0000401:225) [ 5215.252182] Lustre: Failing over lustre-MDT0000 [ 5215.633426] Lustre: server umount lustre-MDT0000 complete [ 5217.251922] 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 [ 5217.263324] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 5217.265842] Lustre: Skipped 1 previous similar message [ 5225.426070] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5225.546135] LustreError: MGC192.168.204.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5225.929663] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 5229.217706] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 5230.336191] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5231.092768] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 5231.102083] Lustre: Skipped 3 previous similar messages [ 5231.124530] Lustre: lustre-MDT0000: Recovery over after 0:02, of 2 clients 2 recovered and 0 were evicted. [ 5231.191647] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:227 to 0x2c0000401:257) [ 5231.192878] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:295 to 0x280000401:385) [ 5239.614723] Lustre: DEBUG MARKER: == sanity-lfsck test 31e: Re-generate the lost slave LMV EA for striped directory (1) ========================================================== 20:54:22 (1789088062) [ 5252.864316] Lustre: DEBUG MARKER: == sanity-lfsck test 31f: Re-generate the lost slave LMV EA for striped directory (2) ========================================================== 20:54:35 (1789088075) [ 5266.750868] Lustre: DEBUG MARKER: == sanity-lfsck test 31g: Repair the corrupted slave LMV EA ========================================================== 20:54:49 (1789088089) [ 5308.753882] Lustre: DEBUG MARKER: == sanity-lfsck test 31h: Repair the corrupted shard's name entry ========================================================== 20:55:31 (1789088131) [ 5329.063981] Lustre: DEBUG MARKER: == sanity-lfsck test 32a: stop LFSCK when some OST failed ========================================================== 20:55:51 (1789088151) [ 5344.888389] LustreError: 147731:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d sleeping for 3000ms [ 5347.791160] Lustre: Failing over lustre-OST0000 [ 5347.931189] Lustre: server umount lustre-OST0000 complete [ 5347.953609] LustreError: 147731:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d awake [ 5347.974940] LustreError: 147731:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d sleeping for 3000ms [ 5348.837799] Lustre: lustre-OST0000-osc-MDT0000: Connection to lustre-OST0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 5348.854722] Lustre: Skipped 2 previous similar messages [ 5351.071087] LustreError: 147731:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d awake [ 5351.079100] LustreError: 147731:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d sleeping for 3000ms [ 5351.305585] LustreError: 147731:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout interrupted [ 5364.349802] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 5364.541863] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 5366.070686] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 5366.108937] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 5366.111347] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 5366.136700] Lustre: Skipped 3 previous similar messages [ 5371.232284] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5381.788693] Lustre: DEBUG MARKER: == sanity-lfsck test 32b: stop LFSCK when some MDT failed ========================================================== 20:56:44 (1789088204) [ 5400.384386] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing load_modules_local [ 5421.437509] Lustre: 150537:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 5441.719717] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5445.526506] Lustre: 151672:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 5458.483511] LustreError: 151808:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d sleeping for 3000ms [ 5461.029787] Lustre: Failing over lustre-MDT0001 [ 5461.472225] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 5461.486103] 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 [ 5461.501723] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 5461.551807] LustreError: 151807:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d awake [ 5461.566927] LustreError: 151807:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) Skipped 1 previous similar message [ 5461.920995] Lustre: server umount lustre-MDT0001 complete [ 5461.987280] LustreError: 123336:0:(ldlm_lib.c:1192: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. [ 5462.007301] LustreError: 123336:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 31 previous similar messages [ 5464.416067] LustreError: 151807:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout interrupted [ 5476.330465] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 5476.598334] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 5476.602890] Lustre: Skipped 3 previous similar messages [ 5476.635456] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 5480.669582] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5481.956479] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 1 client reconnects [ 5481.958345] Lustre: lustre-MDT0001-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 5481.967782] Lustre: Skipped 1 previous similar message [ 5482.001828] Lustre: lustre-MDT0001: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 5482.035319] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:70 to 0x280000400:97) [ 5482.035465] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:69 to 0x2c0000400:97) [ 5489.578896] Lustre: DEBUG MARKER: == sanity-lfsck test 33: check LFSCK paramters =========== 20:58:32 (1789088312) [ 5504.441923] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing load_modules_local [ 5524.826389] Lustre: 154527:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 5551.789557] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5555.611786] Lustre: 155662:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 5558.209710] Lustre: 129945:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 5558.219709] Lustre: 129945:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 1251 previous similar messages [ 5558.228728] Lustre: 129945:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 5558.235297] Lustre: 129945:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1251 previous similar messages [ 5558.250291] Lustre: 129945:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 5558.258501] Lustre: 129945:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1251 previous similar messages [ 5558.268612] Lustre: 129945:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 5558.277064] Lustre: 129945:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1251 previous similar messages [ 5558.281909] Lustre: 129945:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 5558.292730] Lustre: 129945:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1251 previous similar messages [ 5558.306589] Lustre: 129945:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 5558.316000] Lustre: 129945:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1251 previous similar messages [ 5575.718936] Lustre: DEBUG MARKER: == sanity-lfsck test 34: LFSCK can rebuild the lost agent object ========================================================== 20:59:58 (1789088398) [ 5577.367046] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_34 Only valid for ZFS backend [ 5579.210177] Lustre: DEBUG MARKER: == sanity-lfsck test 35: LFSCK can rebuild the lost agent entry ========================================================== 21:00:02 (1789088402) [ 5586.334574] Lustre: *** cfs_fail_loc=1631, val=0*** [ 5599.712743] 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 [ 5599.714788] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5599.731969] Lustre: Skipped 5 previous similar messages [ 5599.750904] Lustre: Skipped 3 previous similar messages [ 5603.862186] Lustre: server umount lustre-MDT0000 complete [ 5607.909287] LustreError: 123320:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1789088433 with bad export cookie 9743611387243278776 [ 5607.917581] LustreError: MGC192.168.204.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5607.926568] LustreError: 123320:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 3 previous similar messages [ 5608.181303] Lustre: server umount lustre-MDT0001 complete [ 5622.787082] Lustre: server umount lustre-OST0000 complete [ 5625.823172] Lustre: 106225:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789088435/real 1789088435] req@ffff8997831d9500 x1875993423401216/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1789088451 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5626.758327] Lustre: server umount lustre-OST0001 complete [ 5646.091618] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing load_modules_local [ 5660.717238] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5666.431274] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5676.119087] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5680.994051] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5684.321804] Lustre: 159569:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 5691.428221] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5698.396890] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5701.994711] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:70 to 0x280000400:129) [ 5706.086737] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:540 to 0x280000401:577) [ 5706.974503] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5712.365855] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:69 to 0x2c0000400:129) [ 5712.447200] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:412 to 0x2c0000401:449) [ 5713.513251] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5721.592119] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5724.769771] Lustre: 161439:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 5734.476811] Lustre: DEBUG MARKER: == sanity-lfsck test 36a: rebuild LOV EA for mirrored file (1) ========================================================== 21:02:37 (1789088557) [ 5736.062599] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36a needs >= 3 OSTs [ 5738.067737] Lustre: DEBUG MARKER: == sanity-lfsck test 36b: rebuild LOV EA for mirrored file (2) ========================================================== 21:02:40 (1789088560) [ 5739.734455] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36b needs >= 3 OSTs [ 5741.548832] Lustre: DEBUG MARKER: == sanity-lfsck test 36c: rebuild LOV EA for mirrored file (3) ========================================================== 21:02:44 (1789088564) [ 5743.140354] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36c needs >= 3 OSTs [ 5745.008579] Lustre: DEBUG MARKER: == sanity-lfsck test 37: LFSCK must skip a ORPHAN ======== 21:02:48 (1789088568) [ 5755.575509] Lustre: DEBUG MARKER: == sanity-lfsck test 38: LFSCK does not break foreign file and reverse is also true ========================================================== 21:02:58 (1789088578) [ 5770.006436] Lustre: DEBUG MARKER: == sanity-lfsck test 39: LFSCK does not break foreign dir and reverse is also true ========================================================== 21:03:13 (1789088593) [ 5785.186549] Lustre: DEBUG MARKER: == sanity-lfsck test 40a: LFSCK correctly fixes lmm_oi in composite layout ========================================================== 21:03:28 (1789088608) [ 5801.867222] Lustre: DEBUG MARKER: == sanity-lfsck test 41: SEL support in LFSCK ============ 21:03:44 (1789088624) [ 5826.219682] Lustre: DEBUG MARKER: == sanity-lfsck test 42: LFSCK repairs inconsistent MDT-object/OST-object encryption flags ========================================================== 21:04:09 (1789088649) [ 5861.213103] Lustre: *** cfs_fail_loc=1632, val=0*** [ 5878.580613] Lustre: DEBUG MARKER: == sanity-lfsck test 43: LFSCK does not loop endlessly on iget failure in scanning-phase1 ========================================================== 21:05:00 (1789088700) [ 5882.142063] Lustre: Failing over lustre-MDT0001 [ 5882.165761] LustreError: 106228:0:(client.c:1381:ptlrpc_import_delay_req()) @@@ IMP_CLOSED req@ffff899884bf3800 x1875993423593216/t0(0) o103->lustre-MDT0000-osp-MDT0001@0@lo:17/18 lens 328/224 e 0 to 0 dl 0 ref 1 fl Rpc:QU/200/ffffffff rc 0/-1 job:'jbd2/dm-1-8.0' uid:0 gid:0 projid:4294967295 [ 5882.422443] Lustre: server umount lustre-MDT0001 complete [ 5886.438078] 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 [ 5886.449488] Lustre: Skipped 2 previous similar messages [ 5886.459333] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 5890.694793] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5891.356201] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 5891.356865] Lustre: lustre-MDT0001: Aborting client recovery [ 5891.382463] LustreError: 165237:0:(ldlm_lib.c:3003:target_stop_recovery_thread()) lustre-MDT0001: Aborting recovery [ 5891.398810] Lustre: 165261:0:(ldlm_lib.c:2403:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 5891.411503] Lustre: 165261:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0001: disconnect stale client 9924dcc9-5157-4cac-9a3b-f7b650d4306f@ [ 5891.425182] Lustre: lustre-MDT0001: disconnecting 2 stale clients [ 5891.447384] Lustre: lustre-MDT0001-osd: cancel update llog [0x240000400:0x1:0x0] [ 5891.460480] Lustre: lustre-MDT0000-osp-MDT0001: cancel update llog [0x200000401:0x1:0x0] [ 5891.515661] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:69 to 0x2c0000400:161) [ 5891.518293] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:131 to 0x280000400:161) [ 5896.546734] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5896.687150] Lustre: lustre-MDT0001-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 5896.697906] Lustre: Skipped 2 previous similar messages [ 5896.706614] LustreError: lustre-MDT0001-osp-MDT0000: This client was evicted by lustre-MDT0001; in progress operations using this service will fail. [ 5901.070328] Lustre: *** cfs_fail_loc=1e2, val=483*** [ 5907.071200] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing wait_import_state FULL osp.lustre-MDT0001-os[pc]-MDT0000.*_server_uuid [ 5907.532237] Lustre: DEBUG MARKER: osp.lustre-MDT0001-os[pc]-MDT0000.*_server_uuid in FULL state after 0 sec [ 5916.304089] Lustre: DEBUG MARKER: == sanity-lfsck test 44: umount while lfsck is stopping == 21:05:38 (1789088738) [ 5926.596874] Lustre: *** cfs_fail_loc=1600, val=3*** [ 5929.770885] Lustre: Failing over lustre-MDT0000 [ 5930.191214] Lustre: server umount lustre-MDT0000 complete [ 5932.511710] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 5940.848917] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5941.012284] LustreError: MGC192.168.204.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5941.378650] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 5941.392502] Lustre: Skipped 2 previous similar messages [ 5946.036868] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 5946.290778] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5946.345354] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 5946.350568] Lustre: Skipped 2 previous similar messages [ 5946.374767] Lustre: lustre-MDT0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 5946.447348] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:621 to 0x280000401:641) [ 5946.452446] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:489 to 0x2c0000401:513) [ 5958.213256] Lustre: DEBUG MARKER: == sanity-lfsck test 45: LFSCK should fix UID/GID/PROJID of OST object ========================================================== 21:06:20 (1789088780) [ 5988.125519] Lustre: Failing over lustre-OST0000 [ 5988.343029] Lustre: server umount lustre-OST0000 complete [ 5988.831928] LustreError: 159923:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 5988.866803] LustreError: 159923:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 32 previous similar messages [ 5995.412564] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: (null) [ 6008.033248] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 6008.261365] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 6008.267262] Lustre: Skipped 6 previous similar messages [ 6008.279705] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 6009.380847] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 6010.191100] Lustre: lustre-OST0000: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [ 6015.277578] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6021.726503] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing wait_import_state (FULL|IDLE) os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid 50 [ 6021.922275] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid in FULL state after 0 sec [ 6027.605825] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing wait_import_state (FULL|IDLE) os[cp].lustre-OST0000-osc-MDT0001.ost_server_uuid 50 [ 6027.887755] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0001.ost_server_uuid in FULL state after 0 sec [ 6034.298343] Lustre: DEBUG MARKER: oleg455-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0000-osc-ffff94415028f800.ost_server_uuid 50 [ 6035.910616] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff94415028f800.ost_server_uuid in FULL state after 0 sec [ 6093.846933] Lustre: server umount lustre-MDT0000 complete [ 6094.821035] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 6094.828955] LustreError: Skipped 1 previous similar message [ 6101.951427] LustreError: 162154:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1789088927 with bad export cookie 9743611387243361551 [ 6101.952191] LustreError: MGC192.168.204.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 6101.966468] LustreError: 162154:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 6102.252222] Lustre: server umount lustre-MDT0001 complete [ 6119.398925] Lustre: server umount lustre-OST0000 complete [ 6121.439143] Lustre: 106228:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789088931/real 1789088931] req@ffff8998b20ff100 x1875993423783424/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1789088947 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6122.464958] Lustre: 106226:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789088932/real 1789088932] req@ffff8998b20ff800 x1875993423783808/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1789088948 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6125.599096] Lustre: 106228:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789088935/real 1789088935] req@ffff8998b1e6ed80 x1875993423784064/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1789088951 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6128.462899] Lustre: server umount lustre-OST0001 complete [ 6151.559819] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing unload_modules_local [ 6154.443585] Key type lgssc unregistered [ 6154.842482] LNet: 174396:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 6154.852133] LNetError: 174396:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 6154.881974] LNet: Removed LNI 192.168.204.155@tcp [ 6155.697163] Key type .llcrypt unregistered [ 6155.699147] Key type ._llcrypt unregistered [ 6180.610303] Key type ._llcrypt registered [ 6180.613414] Key type .llcrypt registered [ 6180.717720] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_hostid [ 6198.054728] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing load_modules_local [ 6199.183204] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 6199.310104] alg: No test for adler32 (adler32-zlib) [ 6200.430126] Lustre: Lustre: Build Version: 2.17.55_25_gfa4fa99 [ 6200.742935] LNet: Added LNI 192.168.204.155@tcp [8/256/0/180] [ 6202.391786] Key type lgssc registered [ 6203.854469] Lustre: Echo OBD driver; http://www.lustre.org/ [ 6260.641474] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing load_modules_local [ 6273.643402] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 6273.698548] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 6275.003822] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 6275.042886] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 6275.158305] Lustre: lustre-MDT0000: new disk, initializing [ 6275.233494] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 6275.255545] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 6280.517143] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6292.323505] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 6292.446413] Lustre: 178853: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 [ 6292.476314] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 6292.479540] Lustre: Skipped 1 previous similar message [ 6292.537506] Lustre: lustre-MDT0001: new disk, initializing [ 6292.589937] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 6292.629333] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 6292.648117] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 6296.800975] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6301.580136] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 6311.732149] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 6312.110066] Lustre: lustre-OST0000: new disk, initializing [ 6312.114141] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 6312.132234] Lustre: 180793:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 6312.229628] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 6318.531493] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6321.182889] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 6321.189897] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 6321.258303] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 6331.656725] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 6331.753715] Lustre: lustre-OST0001: new disk, initializing [ 6331.756667] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 6331.764707] Lustre: 181816:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 6331.836062] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 6338.258687] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6339.613450] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 6339.630425] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 6339.690129] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 6349.738567] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 6360.537796] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 6366.989267] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 21:13:09 (1789089189) === [ 6368.847338] Lustre: DEBUG MARKER: == sanity-lfsck test complete, duration 6105 sec ========= 21:13:11 (1789089191) [ 6370.694666] Lustre: DEBUG MARKER: === sanity-lfsck: start cleanup 21:13:13 (1789089193) === [ 6374.666695] Lustre: DEBUG MARKER: === sanity-lfsck: finish cleanup 21:13:17 (1789089197) === [ 6380.001716] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 6380.007180] 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 [ 6380.023851] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 6380.513694] 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 [ 6380.530431] Lustre: Skipped 1 previous similar message [ 6380.543474] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 6380.552141] Lustre: Skipped 3 previous similar messages [ 6385.560534] Lustre: server umount lustre-MDT0000 complete [ 6390.757198] LustreError: 180567:0:(ldlm_lib.c:1192: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. [ 6390.773722] LustreError: 180567:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 8 previous similar messages [ 6393.493230] LustreError: 178844:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1789089219 with bad export cookie 1872139400374553818 [ 6393.501882] LustreError: MGC192.168.204.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 6393.507146] LustreError: 178844:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 6393.782534] Lustre: server umount lustre-MDT0001 complete [ 6411.807191] Lustre: 176011:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789089221/real 1789089221] req@ffff89978a311c00 x1875995814609920/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1789089237 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6411.824862] 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 [ 6411.835737] Lustre: Skipped 1 previous similar message [ 6413.072052] Lustre: server umount lustre-OST0000 complete [ 6414.817641] Lustre: 176013:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789089224/real 1789089224] req@ffff8998bc4e8000 x1875995814610176/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1789089240 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6416.354151] Lustre: 176012:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789089226/real 1789089226] req@ffff89978a312d80 x1875995814610432/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1789089242 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6420.000382] Lustre: 176011:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789089229/real 1789089229] req@ffff89978a310e00 x1875995814611072/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1789089245 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6420.049978] Lustre: 176011:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 6422.452953] Lustre: server umount lustre-OST0001 complete [ 6439.097154] Lustre: DEBUG MARKER: oleg455-server.virtnet: executing unload_modules_local [ 6441.421925] Key type lgssc unregistered [ 6441.683317] LNet: 185287:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 6441.691355] LNetError: 185287:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 6441.713439] LNet: Removed LNI 192.168.204.155@tcp [ 6442.369253] Key type .llcrypt unregistered [ 6442.374417] Key type ._llcrypt unregistered