[ 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 498880054 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.001010] APIC: Switch to symmetric I/O mode setup [ 0.003386] x2apic enabled [ 0.004008] Switched APIC routing to physical x2apic. [ 0.005015] kvm-guest: setup PV IPIs [ 0.008415] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.009000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.010019] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.011014] pid_max: default: 32768 minimum: 301 [ 0.012129] LSM: Security Framework initializing [ 0.013059] Yama: becoming mindful. [ 0.014049] SELinux: Initializing. [ 0.016078] *** VALIDATE selinux *** [ 0.024669] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.030871] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.031211] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.032143] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.034084] *** VALIDATE tmpfs *** [ 0.036379] *** VALIDATE proc *** [ 0.038193] *** VALIDATE cgroup *** [ 0.039016] *** VALIDATE cgroup2 *** [ 0.041175] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.042201] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.043017] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.044042] Spectre V2 : User space: Vulnerable [ 0.046002] Speculative Store Bypass: Vulnerable [ 0.049082] debug: unmapping init [mem 0xffffffffb6659000-0xffffffffb6660fff] [ 0.051998] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.052845] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.053033] ... version: 2 [ 0.054019] ... bit width: 48 [ 0.055018] ... generic registers: 4 [ 0.056023] ... value mask: 0000ffffffffffff [ 0.057022] ... max period: 00007fffffffffff [ 0.058021] ... fixed-purpose events: 3 [ 0.059020] ... event mask: 000000070000000f [ 0.061298] rcu: Hierarchical SRCU implementation. [ 0.063656] smp: Bringing up secondary CPUs ... [ 0.064714] x86: Booting SMP configuration: [ 0.065037] .... node #0, CPUs: #1 #2 #3 [ 0.068708] smp: Brought up 1 node, 4 CPUs [ 0.070023] smpboot: Max logical packages: 1 [ 0.071032] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.253674] node 0 deferred pages initialised in 178ms [ 0.256337] devtmpfs: initialized [ 0.257321] x86/mm: Memory block size: 128MB [ 0.260850] gcov: version magic: 0x41383552 [ 0.264393] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.265095] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.266370] pinctrl core: initialized pinctrl subsystem [ 0.267273] [ 0.267897] ************************************************************* [ 0.268020] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.269019] ** ** [ 0.270024] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.271020] ** ** [ 0.272022] ** This means that this kernel is built to expose internal ** [ 0.273023] ** IOMMU data structures, which may compromise security on ** [ 0.274020] ** your system. ** [ 0.275025] ** ** [ 0.276022] ** If you see this message and you are not debugging the ** [ 0.277022] ** kernel, report this immediately to your vendor! ** [ 0.278021] ** ** [ 0.279022] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.280020] ************************************************************* [ 0.281790] NET: Registered protocol family 16 [ 0.282473] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.283091] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.284090] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.286078] cpuidle: using governor menu [ 0.287681] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.290497] PCI: Using configuration type 1 for base access [ 0.293138] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.302122] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.303057] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.305053] cryptd: max_cpu_qlen set to 1000 [ 0.307309] ACPI: Added _OSI(Module Device) [ 0.308019] ACPI: Added _OSI(Processor Device) [ 0.309026] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.310020] ACPI: Added _OSI(Processor Aggregator Device) [ 0.314471] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.317383] ACPI: Interpreter enabled [ 0.319158] ACPI: PM: (supports S0 S3 S4 S5) [ 0.321018] ACPI: Using IOAPIC for interrupt routing [ 0.323892] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.327560] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.338674] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.341055] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.344030] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.348120] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.354562] acpiphp: Slot [2] registered [ 0.356237] acpiphp: Slot [5] registered [ 0.358249] acpiphp: Slot [6] registered [ 0.359151] acpiphp: Slot [7] registered [ 0.360267] acpiphp: Slot [8] registered [ 0.362179] acpiphp: Slot [9] registered [ 0.363167] acpiphp: Slot [10] registered [ 0.365176] acpiphp: Slot [3] registered [ 0.366118] acpiphp: Slot [4] registered [ 0.368137] acpiphp: Slot [11] registered [ 0.369093] acpiphp: Slot [12] registered [ 0.370128] acpiphp: Slot [13] registered [ 0.372144] acpiphp: Slot [14] registered [ 0.373130] acpiphp: Slot [15] registered [ 0.375157] acpiphp: Slot [16] registered [ 0.377136] acpiphp: Slot [17] registered [ 0.379146] acpiphp: Slot [18] registered [ 0.380164] acpiphp: Slot [19] registered [ 0.382147] acpiphp: Slot [20] registered [ 0.384144] acpiphp: Slot [21] registered [ 0.386131] acpiphp: Slot [22] registered [ 0.387123] acpiphp: Slot [23] registered [ 0.389141] acpiphp: Slot [24] registered [ 0.391121] acpiphp: Slot [25] registered [ 0.393153] acpiphp: Slot [26] registered [ 0.395116] acpiphp: Slot [27] registered [ 0.396104] acpiphp: Slot [28] registered [ 0.398116] acpiphp: Slot [29] registered [ 0.399139] acpiphp: Slot [30] registered [ 0.401114] acpiphp: Slot [31] registered [ 0.402096] PCI host bridge to bus 0000:00 [ 0.404028] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.406106] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.409061] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.412031] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.415029] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.418034] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.420332] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.424114] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.427048] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.436019] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.440660] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.444026] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.446021] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.448023] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.452746] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.455765] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.458060] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.460943] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.468019] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.481032] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.488961] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.493831] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.502019] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.512022] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.533018] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.542275] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.550022] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.556021] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.574022] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.587276] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.592018] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.601019] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.614022] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.623698] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.634020] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.642029] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.662019] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.675000] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.680019] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.685018] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.699026] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 0.708887] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.714018] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.719018] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.735019] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 0.745437] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.748561] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.751432] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.753480] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.756279] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.762035] iommu: Default domain type: Passthrough [ 0.764535] SCSI subsystem initialized [ 0.765139] ACPI: bus type USB registered [ 0.767138] usbcore: registered new interface driver usbfs [ 0.769096] usbcore: registered new interface driver hub [ 0.771118] usbcore: registered new device driver usb [ 0.773191] pps_core: LinuxPPS API ver. 1 registered [ 0.775021] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.778067] PTP clock support registered [ 0.780177] EDAC MC: Ver: 3.0.0 [ 0.783192] PCI: Using ACPI for IRQ routing [ 0.784000] NetLabel: Initializing [ 0.785013] NetLabel: domain hash size = 128 [ 0.787020] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.790116] NetLabel: unlabeled traffic allowed by default [ 0.792108] vgaarb: loaded [ 0.793637] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.795017] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.805790] clocksource: Switched to clocksource kvm-clock [ 0.916506] VFS: Disk quotas dquot_6.6.0 [ 0.918140] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.920503] *** VALIDATE ramfs *** [ 0.921889] *** VALIDATE hugetlbfs *** [ 0.924389] pnp: PnP ACPI init [ 0.926743] pnp: PnP ACPI: found 6 devices [ 0.945088] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.948872] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.951294] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.953680] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.956455] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.959205] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.962401] NET: Registered protocol family 2 [ 0.964852] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.969473] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.972543] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.980081] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.983645] TCP: Hash tables configured (established 65536 bind 65536) [ 0.987085] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.990901] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.993989] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.997518] NET: Registered protocol family 1 [ 1.001266] RPC: Registered named UNIX socket transport module. [ 1.003630] RPC: Registered udp transport module. [ 1.005380] RPC: Registered tcp transport module. [ 1.007205] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 1.009750] NET: Registered protocol family 44 [ 1.011416] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 1.013608] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 1.015796] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 1.018701] PCI: CLS 0 bytes, default 64 [ 1.021554] Unpacking initramfs... [ 2.450041] debug: unmapping init [mem 0xffff9777fcc54000-0xffff9777fffbffff] [ 2.453643] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.455423] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.457664] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 2.935190] Initialise system trusted keyrings [ 2.936673] Key type blacklist registered [ 2.938338] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.946797] zbud: loaded [ 2.949494] *** VALIDATE nfs *** [ 2.950528] *** VALIDATE nfs4 *** [ 2.951812] pstore: using deflate compression [ 2.956739] Platform Keyring initialized [ 3.065328] NET: Registered protocol family 38 [ 3.067335] Key type asymmetric registered [ 3.069599] Asymmetric key parser 'x509' registered [ 3.071577] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 3.074052] io scheduler mq-deadline registered [ 3.075586] io scheduler kyber registered [ 3.077122] io scheduler bfq registered [ 3.078682] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 3.081368] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 3.083937] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 3.086481] ACPI: Power Button [PWRF] [ 3.091669] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 3.098298] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 3.111690] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 3.122411] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 3.138406] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 3.168541] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.200178] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.204759] Non-volatile memory driver v1.3 [ 3.206437] Linux agpgart interface v0.103 [ 3.243076] virtio_blk virtio1: [vda] 145912 512-byte logical blocks (74.7 MB/71.2 MiB) [ 3.246116] vda: detected capacity change from 0 to 74706944 [ 3.261088] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.264155] vdb: detected capacity change from 0 to 1073741824 [ 3.279190] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.282480] vdc: detected capacity change from 0 to 2621440000 [ 3.297469] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.301145] vdd: detected capacity change from 0 to 2621440000 [ 3.319018] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.322185] vde: detected capacity change from 0 to 4294967296 [ 3.340961] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.344028] vdf: detected capacity change from 0 to 4294967296 [ 3.351408] libphy: Fixed MDIO Bus: probed [ 3.356228] usbcore: registered new interface driver usbserial_generic [ 3.358486] usbserial: USB Serial support registered for generic [ 3.360514] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.364470] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.366056] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.380329] mousedev: PS/2 mouse device common for all mice [ 3.383525] rtc_cmos 00:05: RTC can wake from S4 [ 3.389141] rtc_cmos 00:05: registered as rtc0 [ 3.390468] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.392888] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.392941] intel_pstate: CPU model not supported [ 3.401821] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.402524] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.413965] hid: raw HID events driver (C) Jiri Kosina [ 3.416510] usbcore: registered new interface driver usbhid [ 3.418689] usbhid: USB HID core driver [ 3.420646] drop_monitor: Initializing network drop monitor service [ 3.423634] Initializing XFRM netlink socket [ 3.426029] NET: Registered protocol family 10 [ 3.429479] Segment Routing with IPv6 [ 3.430547] NET: Registered protocol family 17 [ 3.432341] mpls_gso: MPLS GSO support [ 3.437324] RAS: Correctable Errors collector initialized. [ 3.439392] AVX version of gcm_enc/dec engaged. [ 3.440819] AES CTR mode by8 optimization enabled [ 3.518348] sched_clock: Marking stable (3518315709, 0)->(4516767108, -998451399) [ 3.522474] registered taskstats version 1 [ 3.525225] Loading compiled-in X.509 certificates [ 3.527679] zswap: loaded using pool lzo/zbud [ 3.554625] Key type big_key registered [ 3.567565] Key type encrypted registered [ 3.569112] ima: No TPM chip found, activating TPM-bypass! [ 3.571206] ima: Allocated hash algorithm: sha1 [ 3.572845] ima: No architecture policies found [ 3.574654] evm: Initialising EVM extended attributes: [ 3.576476] evm: security.selinux [ 3.577616] evm: security.ima [ 3.578769] evm: security.capability [ 3.580062] evm: HMAC attrs: 0x1 [ 3.582427] rtc_cmos 00:05: setting system clock to 2026-08-14 18:29:46 UTC (1786732186) [ 3.589136] debug: unmapping init [mem 0xffffffffb7603000-0xffffffffb77fffff] [ 3.592330] debug: unmapping init [mem 0xffffffffb6382000-0xffffffffb6658fff] [ 3.601105] Write protecting the kernel read-only data: 28672k [ 3.604706] debug: unmapping init [mem 0xffffffffb4a03000-0xffffffffb4bfffff] [ 3.607449] debug: unmapping init [mem 0xffffffffb5314000-0xffffffffb53fffff] [ 3.651414] 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.660743] systemd[1]: Detected virtualization kvm. [ 3.662884] systemd[1]: Detected architecture x86-64. [ 3.664734] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.690671] systemd[1]: No hostname configured. [ 3.692448] systemd[1]: Set hostname to . [ 3.694571] random: systemd: uninitialized urandom read (16 bytes read) [ 3.696848] systemd[1]: Initializing machine ID from random generator. [ 3.833471] random: systemd: uninitialized urandom read (16 bytes read) [ 3.836506] systemd[1]: Reached target Initrd Root Device. [ OK ] Reached target Initrd Root Device. [ 3.841432] random: systemd: uninitialized urandom read (16 bytes read) [ 3.844511] systemd[1]: Listening on Journal Socket. [ OK ] Listening on Journal Socket. [ 3.853482] systemd[1]: Started Memstrack Anylazing Service. [ OK ] Started Memstrack Anylazing Service. [ OK ] Listening on udev Kernel Socket. [ OK ] Reached target Timers. Starting Create list of required st…ce nodes for the current kernel... Starting Setup Virtual Console... [ OK ] Reached target Local File Systems. Starting Create Volatile Files and Directories... Starting Apply Kernel Variables... [ OK ] Listening on Journal Socket (/dev/log). Starting Journal Service... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Paths. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Slices. [ OK ] Reached target Swap. [ OK ] Listening on udev Control Socket. [ OK ] Reached target Sockets. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Setup Virtual Console. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Apply Kernel Variables. Starting dracut cmdline hook... Starting Create Static Device Nodes in /dev... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started Journal Service. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 4.458912] device-mapper: uevent: version 1.0.3 [ 4.461411] 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 [ 5.199402] random: fast init done ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ 5.329727] virtio_net virtio0 ens2: renamed from eth0 [ 5.406312] scsi host0: ata_piix [ 5.452246] scsi host1: ata_piix [ 5.455225] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 5.457989] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 9.137737] dracut-initqueue[593]: RTNETLINK answers: File exists [ 10.085498] random: crng init done [ 10.086923] random: 7 urandom warning(s) missed due to ratelimiting Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Mounting /sysroot... [ 10.596488] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped target Timers. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Sockets. [ OK ] Stopped target Slices. [ OK ] Stopped target Paths. [ OK ] Stopped target System Initialization. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. [ OK ] Stopped target Swap. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped Create Volatile Files and Directories. Stopping udev Kernel Device Manager... [ OK ] Stopped target Local File Systems. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Stopped 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.788211] printk: systemd: 26 output lines suppressed due to ratelimiting [ 12.062125] SELinux: Disabled at runtime. [ 12.126970] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 12.135371] systemd[1]: Detected virtualization kvm. [ 12.137615] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 12.589941] systemd[1]: initrd-switch-root.service: Succeeded. [ 12.593424] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 12.599271] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 12.604759] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 12.608663] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 12.619229] systemd[1]: Starting Journal Service... Starting Journal Service... [ 12.626193] systemd[1]: Reached target rpc_pipefs.target. [ OK ] Reached target rpc_pipefs.target. [ OK ] Listening on udev Kernel Socket. Activating swap /dev/disk/by-label/SWAP... [ OK ] Stopped target Switch Root. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Listening on udev Control Socket. Starting udev Coldplug all Devices... [ OK ] Created slice User and Session Slice. [ OK [[ 12.674453] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS 0m] Created slice system-serial\x2dgetty.slice. Starting Remount Root and Kernel File Systems... [ OK ] Reached target Paths. Mounting Huge Pages File System... [ OK ] Created slice system-getty.slice. [ OK ] Stopped target Initrd Root File System. [ OK ] Listening on Process Core Dump Socket. [ OK ] Stopped target Initrd File Systems. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Listening on initctl Compatibility Named Pipe. Mounting Kernel Debug File System... [ OK ] Reached target Slices. Mounting POSIX Message Queue File System... Starting Apply Kernel Variables... [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Reached target RPC Port Mapper. [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Started Journal Service. [ OK ] Activated swap /dev/disk/by-label/SWAP. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Mounted Huge Pages File System. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Mounted Kernel Debug File System. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Started Apply Kernel Variables. Starting Create Static Device Nodes in /dev... Starting Configure read-only root support... [ OK ] Reached target Swap. Starting Flush Journal to Persistent Storage... [ OK ] Started Create Static Device Nodes in /dev. Starting udev Kernel Device Manager... [ OK ] Reached target Local File Systems (Pre). Mounting /home/green/git/lustre-release... Mounting /mnt... [ OK ] Started udev Coldplug all Devices. [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Mounted /mnt. [ 13.022561] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 13.269366] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 13.326394] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 13.434258] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 13.452228] EDAC sbridge: Ver: 1.1.2 [ 15.331546] Key type dns_resolver registered [ 15.638516] NFS: Registering the id_resolver key type [ 15.640284] Key type id_resolver registered [ 15.642010] Key type id_legacy registered [ OK ] Started Configure read-only root support. [ OK ] Reached target Local File Systems. Starting Mark the need to relabel after reboot... Starting Rebuild Dynamic Linker Cache... Starting Create Volatile Files and Directories... Starting Load/Save Random Seed... [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Load/Save Random Seed. [ OK ] Started Create Volatile Files and Directories. Starting RPC Bind... Starting Update UTMP about System Boot/Shutdown... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Started dnf makecache --timer. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Reached target Timers. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting Login Service... [ OK ] Started D-Bus System Message Bus. Starting Network Manager... [ OK ] Started irqbalance daemon. Starting Restore /run/initramfs on shutdown... [ OK ] Reached target sshd-keygen.target. [ OK ] Started Login Service. [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Network Manager. Starting Network Manager Wait Online... [ OK ] Reached target Network. Starting GSSAPI Proxy Daemon... Starting OpenSSH server daemon... Starting Dynamic System Tuning Daemon... Starting Hostname Service... [ OK ] Started OpenSSH server daemon. [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... [ OK ] Started Permit User Sessions. [ OK ] Started Command Scheduler. [ OK ] Started Serial Getty on ttyS1. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Getty on tty1. [ OK ] Reached target Login Prompts. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting 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 oleg326-server login: [ 71.924709] libcfs: loading out-of-tree module taints kernel. [ 72.028967] Key type ._llcrypt registered [ 72.034480] Key type .llcrypt registered [ 72.166747] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_hostid [ 94.338121] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing load_modules_local [ 96.619900] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 96.632813] alg: No test for adler32 (adler32-zlib) [ 97.638171] hrtimer: interrupt took 2815222 ns [ 98.656895] Lustre: Lustre: Build Version: 2.17.56_2_gd9f03f2 [ 99.510971] LNet: Added LNI 192.168.203.126@tcp [8/256/0/180] [ 101.311242] Key type lgssc registered [ 103.885374] Lustre: Echo OBD driver; http://www.lustre.org/ [ 126.418737] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 172.335426] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing load_modules_local [ 187.854651] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 187.945166] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 189.259482] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 189.301118] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 189.440499] Lustre: lustre-MDT0000: new disk, initializing [ 189.593286] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 189.637588] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 194.346224] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 211.125701] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 211.312643] Lustre: 6526: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 [ 211.343464] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 211.348197] Lustre: Skipped 1 previous similar message [ 211.455308] Lustre: lustre-MDT0001: new disk, initializing [ 211.582258] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 211.625992] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 211.645576] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 216.344575] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 221.770536] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 232.484114] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 232.939813] Lustre: lustre-OST0000: new disk, initializing [ 232.946852] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 232.956710] Lustre: 8465:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 233.037936] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 234.095149] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 234.128460] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 234.288443] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 239.414324] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 253.440394] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 253.618441] Lustre: lustre-OST0001: new disk, initializing [ 253.629497] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 253.637968] Lustre: 9538:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 253.738877] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 259.871749] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 262.784228] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 262.800902] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 262.921828] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 272.569294] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 281.490459] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 289.587202] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing check_logdir /tmp/testlogs/ [ 295.487502] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing yml_node [ 300.929455] Lustre: DEBUG MARKER: Client: 2.17.56.2 [ 304.181374] Lustre: DEBUG MARKER: MDS: 2.17.56.2 [ 306.697184] Lustre: DEBUG MARKER: OSS: 2.17.56.2 [ 308.793336] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity-lfsck ============----- Fri Aug 14 14:34:48 EDT 2026 [ 328.551605] Lustre: DEBUG MARKER: excepting tests: 18b 23b [ 339.121585] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing load_modules_local [ 350.175944] 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 [ 350.177154] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 350.179252] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 350.185200] Lustre: Skipped 3 previous similar messages [ 353.069132] Lustre: server umount lustre-MDT0000 complete [ 360.421652] LustreError: 6534: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. [ 360.437049] LustreError: 6534:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 8 previous similar messages [ 362.234566] LustreError: 6519:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1786732545 with bad export cookie 7138911365625369854 [ 362.254130] LustreError: MGC192.168.203.126@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 362.258219] LustreError: 6519:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 363.018671] Lustre: server umount lustre-MDT0001 complete [ 381.920660] Lustre: 3657:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786732548/real 1786732548] req@ffff977875645f80 x1873524589436288/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786732564 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 381.986650] 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 [ 383.182573] Lustre: server umount lustre-OST0000 complete [ 383.971045] Lustre: 3660:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786732550/real 1786732550] req@ffff977875647b80 x1873524589436544/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786732566 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 387.042621] Lustre: 3658:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786732553/real 1786732553] req@ffff977875688380 x1873524589436800/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786732569 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 389.600082] Lustre: 3659:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786732556/real 1786732556] req@ffff977875647800 x1873524589437184/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786732572 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 391.649364] Lustre: server umount lustre-OST0001 complete [ 407.113333] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing unload_modules_local [ 409.839407] Key type lgssc unregistered [ 410.189720] LNet: 14816:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 410.196681] LNetError: 14816:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 410.208699] LNet: Removed LNI 192.168.203.126@tcp [ 411.211597] Key type .llcrypt unregistered [ 411.216108] Key type ._llcrypt unregistered [ 437.108712] Key type ._llcrypt registered [ 437.110875] Key type .llcrypt registered [ 437.221821] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_hostid [ 453.426450] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing load_modules_local [ 454.469100] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 454.483521] alg: No test for adler32 (adler32-zlib) [ 455.742827] Lustre: Lustre: Build Version: 2.17.56_2_gd9f03f2 [ 456.148820] LNet: Added LNI 192.168.203.126@tcp [8/256/0/180] [ 457.831310] Key type lgssc registered [ 458.977650] Lustre: Echo OBD driver; http://www.lustre.org/ [ 514.945198] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing load_modules_local [ 527.173649] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 527.215954] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 528.552247] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 528.584447] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 528.741594] Lustre: lustre-MDT0000: new disk, initializing [ 528.840254] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 528.859947] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 532.497865] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 545.961711] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 546.073180] Lustre: 19269: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 [ 546.122263] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 546.126364] Lustre: Skipped 1 previous similar message [ 546.208353] Lustre: lustre-MDT0001: new disk, initializing [ 546.308301] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 546.343423] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 546.350842] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 550.991311] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 556.274631] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 565.682991] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 565.974662] Lustre: lustre-OST0000: new disk, initializing [ 565.980169] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 565.990939] Lustre: 21208:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 566.073528] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 569.108053] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 569.120988] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 569.252124] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 572.283781] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 586.248170] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 586.334795] Lustre: lustre-OST0001: new disk, initializing [ 586.338488] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 586.342944] Lustre: 22232:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 586.399965] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 592.925908] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 592.941659] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 593.017529] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 593.107963] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 605.578056] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 615.066136] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 623.067747] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 14:40:03 (1786732803) === [ 625.752971] Lustre: DEBUG MARKER: == sanity-lfsck test 0: Control LFSCK manually =========== 14:40:06 (1786732806) [ 626.120270] Lustre: 19276:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 251 < left 278, rollback = 2 [ 626.136114] Lustre: 19276:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 626.152485] Lustre: 19276:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 626.163707] Lustre: 19276:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 626.180134] Lustre: 19276:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 626.190767] Lustre: 19276:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 626.677332] Lustre: 19278:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 626.691361] Lustre: 19278:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 11 previous similar messages [ 626.708190] Lustre: 19278:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 626.719922] Lustre: 19278:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 626.727911] Lustre: 19278:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 626.738157] Lustre: 19278:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 626.745861] Lustre: 19278:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 626.759870] Lustre: 19278:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 626.769042] Lustre: 19278:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 626.775896] Lustre: 19278:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 626.782673] Lustre: 19278:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 626.788953] Lustre: 19278:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 627.760607] Lustre: 19276:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 627.770864] Lustre: 19276:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 29 previous similar messages [ 627.778363] Lustre: 19276:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 627.787170] Lustre: 19276:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 29 previous similar messages [ 627.798520] Lustre: 19276:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 627.813646] Lustre: 19276:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 29 previous similar messages [ 627.829533] Lustre: 19276:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 627.841969] Lustre: 19276:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 29 previous similar messages [ 627.847883] Lustre: 19276:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 627.852826] Lustre: 19276:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 29 previous similar messages [ 627.858818] Lustre: 19276:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 627.877662] Lustre: 19276:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 29 previous similar messages [ 629.769722] Lustre: 19277:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 629.776289] Lustre: 19277:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 104 previous similar messages [ 629.781622] Lustre: 19277:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 629.786225] Lustre: 19277:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 629.832659] Lustre: 19276:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 629.838248] Lustre: 19276:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 107 previous similar messages [ 629.843675] Lustre: 19276:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 629.849398] Lustre: 19276:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 107 previous similar messages [ 629.855477] Lustre: 19276:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 629.860768] Lustre: 19276:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 107 previous similar messages [ 629.867288] Lustre: 19276:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 629.872984] Lustre: 19276:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 107 previous similar messages [ 634.429729] Lustre: *** cfs_fail_loc=1600, val=3*** [ 636.418227] Lustre: 21198:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-OST0001: opcode 2: before 260 < left 274, rollback = 2 [ 636.440687] Lustre: 21198:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 128 previous similar messages [ 636.452164] Lustre: 21198:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 636.466684] Lustre: 21198:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 128 previous similar messages [ 636.475613] Lustre: 21198:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 2/274/0 [ 636.486465] Lustre: 21198:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 125 previous similar messages [ 636.493916] Lustre: 21198:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 0/0/0, punch: 0/0/0, quota 7/225/0 [ 636.506302] Lustre: 21198:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 125 previous similar messages [ 636.512129] Lustre: 21198:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 636.529562] Lustre: 21198:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 125 previous similar messages [ 636.535627] Lustre: 21198:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 636.542872] Lustre: 21198:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 125 previous similar messages [ 638.493508] Lustre: *** cfs_fail_loc=1600, val=3*** [ 650.143616] Lustre: 21199:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-OST0001: opcode 2: before 259 < left 274, rollback = 2 [ 650.156414] Lustre: 21199:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 61 previous similar messages [ 650.169316] Lustre: 21199:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 650.170516] Lustre: 21197:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/1, xattr_set: 2/274/0 [ 650.192627] Lustre: 21199:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 62 previous similar messages [ 650.192661] Lustre: 21199:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 0/0/0, punch: 0/0/0, quota 7/225/0 [ 650.192665] Lustre: 21199:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 61 previous similar messages [ 650.192671] Lustre: 21199:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 650.192675] Lustre: 21199:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 61 previous similar messages [ 650.192681] Lustre: 21199:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 650.192683] Lustre: 21199:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 61 previous similar messages [ 650.281806] Lustre: 21197:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 66 previous similar messages [ 653.793070] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 653.801925] 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 [ 653.815791] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 654.307378] 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 [ 654.335829] Lustre: Skipped 2 previous similar messages [ 654.342819] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 654.345653] Lustre: Skipped 3 previous similar messages [ 659.251665] Lustre: server umount lustre-MDT0000 complete [ 662.715076] LustreError: 19261:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1786732845 with bad export cookie 14632654493501922220 [ 662.725686] LustreError: MGC192.168.203.126@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 662.734059] LustreError: 19261:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 663.022411] Lustre: server umount lustre-MDT0001 complete [ 677.574311] Lustre: server umount lustre-OST0000 complete [ 680.927106] Lustre: 16433:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786732847/real 1786732847] req@ffff977749a36300 x1873524963784960/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786732863 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 680.965133] 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 [ 681.511828] Lustre: server umount lustre-OST0001 complete [ 689.968557] Lustre: DEBUG MARKER: == sanity-lfsck test 1a: LFSCK can find out and repair crashed FID-in-dirent ========================================================== 14:41:10 (1786732870) [ 705.131933] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing load_modules_local [ 716.190913] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 716.603467] LustreError: 26288: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. [ 716.642740] LustreError: 26288:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 5 previous similar messages [ 716.706055] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 720.874088] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 721.893608] LustreError: 26289: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. [ 727.010625] LustreError: 26288: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.203943] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 729.589976] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 734.019877] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 736.935547] Lustre: 27428:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 743.958085] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 749.595647] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 754.480896] LustreError: 27781: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. [ 757.885405] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 758.097479] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 758.103399] Lustre: Skipped 1 previous similar message [ 761.204465] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:41 to 0x2c0000401:65) [ 761.208046] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:40 to 0x280000401:65) [ 764.252512] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 772.299056] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 776.272696] Lustre: 29298:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 778.153641] Lustre: 26285:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 778.163074] Lustre: 26285:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 8 previous similar messages [ 778.169513] Lustre: 26285:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 778.176529] Lustre: 26285:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 7 previous similar messages [ 778.183681] Lustre: 26285:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 778.191088] Lustre: 26285:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 3 previous similar messages [ 778.198767] Lustre: 26285:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 778.213761] Lustre: 26285:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 8 previous similar messages [ 778.224083] Lustre: 26285:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 778.233143] Lustre: 26285:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 8 previous similar messages [ 778.244454] Lustre: 26285:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 778.249723] Lustre: 26285:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 8 previous similar messages [ 783.745815] Lustre: *** cfs_fail_loc=1501, val=0*** [ 792.242346] Lustre: Failing over lustre-MDT0000 [ 792.458560] Lustre: server umount lustre-MDT0000 complete [ 796.136457] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 796.142620] 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 [ 796.160301] LustreError: 26289: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. [ 803.069201] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 803.243096] LustreError: MGC192.168.203.126@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 803.560824] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 803.615829] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 808.075653] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 808.929234] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 808.935730] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 808.965974] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 809.019696] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:105 to 0x280000401:129) [ 809.023268] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:105 to 0x2c0000401:129) [ 811.765362] Lustre: *** cfs_fail_loc=1505, val=0*** [ 821.619495] Lustre: DEBUG MARKER: == sanity-lfsck test 1b: LFSCK can find out and repair the missing FID-in-LMA ========================================================== 14:43:21 (1786733001) [ 823.434493] Lustre: 26283:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 823.451837] Lustre: 26283:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 322 previous similar messages [ 823.461507] Lustre: 26283:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 823.479880] Lustre: 26283:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 823.490619] Lustre: 26283:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 823.506063] Lustre: 26283:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 823.511202] Lustre: 26283:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 823.532517] Lustre: 26283:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 823.543029] Lustre: 26283:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 823.557639] Lustre: 26283:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 823.568634] Lustre: 26283:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 823.579513] Lustre: 26283:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 830.369548] Lustre: *** cfs_fail_loc=1502, val=0*** [ 841.956792] Lustre: Failing over lustre-MDT0000 [ 842.321080] Lustre: server umount lustre-MDT0000 complete [ 844.770018] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 844.776847] 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 [ 844.787333] LustreError: 26284: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. [ 844.809111] Lustre: Skipped 5 previous similar messages [ 844.841665] LustreError: 26284:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 11 previous similar messages [ 854.681376] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 854.913795] LustreError: MGC192.168.203.126@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 855.010249] Lustre: lustre-MDT0000: Not available for connect from 0@lo (not set up) [ 855.030031] Lustre: Skipped 3 previous similar messages [ 855.379281] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 860.369607] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 860.644812] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 860.652111] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 860.659847] Lustre: Skipped 3 previous similar messages [ 860.744596] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 860.825874] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:169 to 0x280000401:193) [ 860.827265] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:169 to 0x2c0000401:193) [ 864.645324] Lustre: *** cfs_fail_loc=1505, val=0*** [ 873.690831] Lustre: DEBUG MARKER: == sanity-lfsck test 1c: LFSCK can find out and repair lost FID-in-dirent ========================================================== 14:44:13 (1786733053) [ 880.506318] Lustre: *** cfs_fail_loc=1504, val=0*** [ 880.512075] Lustre: *** cfs_fail_loc=1504, val=0*** [ 880.515910] Lustre: Skipped 1 previous similar message [ 887.186519] Lustre: Failing over lustre-MDT0000 [ 887.490054] Lustre: server umount lustre-MDT0000 complete [ 891.369088] 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 [ 891.369526] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 891.374769] LustreError: 26283: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. [ 891.374784] LustreError: 26283:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 4 previous similar messages [ 891.381427] Lustre: Skipped 3 previous similar messages [ 896.435467] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 896.563893] LustreError: MGC192.168.203.126@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 896.751664] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 896.757414] Lustre: Skipped 1 previous similar message [ 896.789902] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 901.430181] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 902.119058] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 902.123890] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 902.137288] Lustre: Skipped 3 previous similar messages [ 902.174636] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 902.227975] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:233 to 0x2c0000401:257) [ 902.238254] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:233 to 0x280000401:257) [ 905.038870] Lustre: *** cfs_fail_loc=1505, val=0*** [ 912.205557] Lustre: DEBUG MARKER: == sanity-lfsck test 2a: LFSCK can find out and repair crashed linkEA entry ========================================================== 14:44:52 (1786733092) [ 913.559871] Lustre: 26283:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 256 < left 278, rollback = 2 [ 913.576059] Lustre: 26283:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 644 previous similar messages [ 913.587924] Lustre: 26283:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 913.599288] Lustre: 26283:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 913.605469] Lustre: 26283:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 913.614724] Lustre: 26283:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 913.622512] Lustre: 26283:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 913.630687] Lustre: 26283:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 913.635662] Lustre: 26283:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 913.641822] Lustre: 26283:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 913.651625] Lustre: 26283:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 913.655262] Lustre: 26283:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 918.977922] Lustre: *** cfs_fail_loc=1603, val=0*** [ 926.837399] Lustre: Failing over lustre-MDT0000 [ 927.118808] Lustre: server umount lustre-MDT0000 complete [ 927.716847] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 927.722726] 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 [ 927.726545] LustreError: 26283: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. [ 927.726557] LustreError: 26283:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 7 previous similar messages [ 927.779215] Lustre: Skipped 3 previous similar messages [ 936.164225] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 936.272450] LustreError: MGC192.168.203.126@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 936.529904] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 941.233295] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 941.539973] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 941.553589] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 941.563627] Lustre: Skipped 3 previous similar messages [ 941.583749] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 941.684388] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:297 to 0x280000401:321) [ 941.687176] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:297 to 0x2c0000401:321) [ 951.485129] Lustre: DEBUG MARKER: == sanity-lfsck test 2b: LFSCK can find out and remove invalid linkEA entry ========================================================== 14:45:31 (1786733131) [ 960.365914] Lustre: *** cfs_fail_loc=1604, val=0*** [ 969.355383] Lustre: Failing over lustre-MDT0000 [ 969.653949] Lustre: server umount lustre-MDT0000 complete [ 972.262354] 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 [ 972.283467] Lustre: Skipped 2 previous similar messages [ 981.045459] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 981.196452] LustreError: MGC192.168.203.126@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 981.487937] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 986.055827] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 986.592687] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 986.607184] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 986.616682] Lustre: Skipped 3 previous similar messages [ 986.654063] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 986.718939] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:361 to 0x2c0000401:385) [ 986.719230] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:361 to 0x280000401:385) [ 995.206651] Lustre: DEBUG MARKER: == sanity-lfsck test 2c: LFSCK can find out and remove repeated linkEA entry ========================================================== 14:46:15 (1786733175) [ 1001.743950] Lustre: *** cfs_fail_loc=1605, val=0*** [ 1009.135112] Lustre: Failing over lustre-MDT0000 [ 1009.430314] Lustre: server umount lustre-MDT0000 complete [ 1012.199952] LustreError: 26285: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. [ 1012.200985] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1012.230230] LustreError: 26285:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 15 previous similar messages [ 1019.282771] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1019.354407] LustreError: MGC192.168.203.126@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1019.615902] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1024.149688] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1024.994494] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1025.003952] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1025.018971] Lustre: Skipped 3 previous similar messages [ 1025.036777] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1025.100918] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:425 to 0x2c0000401:449) [ 1025.107244] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:425 to 0x280000401:449) [ 1033.409649] Lustre: DEBUG MARKER: == sanity-lfsck test 2d: LFSCK can recover the missing linkEA entry ========================================================== 14:46:53 (1786733213) [ 1041.289373] Lustre: *** cfs_fail_loc=161d, val=0*** [ 1044.085389] Lustre: 31009:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-OST0001: opcode 2: before 260 < left 274, rollback = 2 [ 1044.085830] Lustre: 29426:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 1044.107613] Lustre: 31009:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 1218 previous similar messages [ 1044.107638] Lustre: 31009:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 2/274/0 [ 1044.107641] Lustre: 31009:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1217 previous similar messages [ 1044.107928] Lustre: 31009:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 0/0/0, punch: 0/0/0, quota 7/225/0 [ 1044.107932] Lustre: 31009:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1217 previous similar messages [ 1044.107938] Lustre: 31009:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 1044.107941] Lustre: 31009:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1217 previous similar messages [ 1044.107946] Lustre: 31009:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 1044.107948] Lustre: 31009:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1217 previous similar messages [ 1044.239925] Lustre: 29426:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1251 previous similar messages [ 1049.482829] Lustre: Failing over lustre-MDT0000 [ 1049.868158] Lustre: server umount lustre-MDT0000 complete [ 1050.593028] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1050.597389] 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 [ 1050.615315] Lustre: Skipped 9 previous similar messages [ 1060.869692] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1061.040625] LustreError: MGC192.168.203.126@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1061.310424] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1061.324097] Lustre: Skipped 3 previous similar messages [ 1061.360664] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1065.513751] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1066.467594] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1066.485660] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1066.490567] Lustre: Skipped 3 previous similar messages [ 1066.507826] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1066.556784] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:489 to 0x280000401:513) [ 1066.560120] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:489 to 0x2c0000401:513) [ 1074.167156] Lustre: DEBUG MARKER: == sanity-lfsck test 2e: namespace LFSCK can verify remote object linkEA ========================================================== 14:47:34 (1786733254) [ 1076.627139] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1087.063555] Lustre: DEBUG MARKER: == sanity-lfsck test 3: LFSCK can verify multiple-linked objects ========================================================== 14:47:47 (1786733267) [ 1093.110091] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1093.969577] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1104.948323] Lustre: DEBUG MARKER: == sanity-lfsck test 4: FID-in-dirent can be rebuilt after MDT file-level backup/restore ========================================================== 14:48:05 (1786733285) [ 1139.853570] Lustre: Failing over lustre-MDT0000 [ 1140.114108] Lustre: server umount lustre-MDT0000 complete [ 1143.268744] LustreError: 26285: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. [ 1143.269974] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1143.293501] LustreError: 26285:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 18 previous similar messages [ 1144.743620] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1153.766264] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1159.647136] Lustre: 16430:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786733326/real 1786733326] req@ffff97774b078e00 x1873524964411776/t0(0) o400->MGC192.168.203.126@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1786733342 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1159.687915] LustreError: MGC192.168.203.126@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1165.487833] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1165.517034] Lustre: lustre-MDT0000: reset Object Index mappings [ 1169.898486] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xcb11a1bc1636b620 [ 1169.911045] Lustre: MGC192.168.203.126@tcp: Connection restored to 0@lo (at 0@lo) [ 1169.919023] Lustre: Skipped 3 previous similar messages [ 1170.211972] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1174.155694] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1175.520676] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1175.564232] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1175.618064] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:592 to 0x2c0000401:609) [ 1175.622828] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:592 to 0x280000401:609) [ 1178.120812] LustreError: 42944:0:(lfsck_engine.c:1018:lfsck_master_engine()) lustre-MDT0000-osd: master engine fail to verify the .lustre/lost+found/, go ahead: rc = -115 [ 1178.148787] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1180.191148] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1180.195563] Lustre: Skipped 1 previous similar message [ 1188.194852] Lustre: Failing over lustre-MDT0000 [ 1188.480877] Lustre: server umount lustre-MDT0000 complete [ 1190.879719] 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 [ 1190.909300] Lustre: Skipped 4 previous similar messages [ 1199.874450] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1204.652814] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1205.783306] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:592 to 0x2c0000401:641) [ 1205.783623] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:592 to 0x280000401:641) [ 1208.206916] Lustre: *** cfs_fail_loc=1505, val=0*** [ 1216.096806] Lustre: DEBUG MARKER: == sanity-lfsck test 5: LFSCK can handle IGIF object upgrading ========================================================== 14:49:56 (1786733396) [ 1218.914761] Lustre: *** cfs_fail_loc=1504, val=0*** [ 1228.258278] Lustre: Failing over lustre-MDT0000 [ 1228.518770] Lustre: server umount lustre-MDT0000 complete [ 1233.509822] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1243.724405] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1247.711113] Lustre: 16433:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786733414/real 1786733414] req@ffff97774932ad80 x1873524964507008/t0(0) o400->MGC192.168.203.126@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1786733430 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1254.933361] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1254.960454] Lustre: lustre-MDT0000: reset Object Index mappings [ 1257.968101] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xcb11a1bc1636f463 [ 1257.989825] Lustre: MGC192.168.203.126@tcp: Connection restored to 0@lo (at 0@lo) [ 1257.998579] Lustre: Skipped 8 previous similar messages [ 1258.350477] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1258.363716] Lustre: Skipped 1 previous similar message [ 1263.177767] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1263.591577] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1263.604837] Lustre: Skipped 1 previous similar message [ 1263.624775] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1263.631850] Lustre: Skipped 1 previous similar message [ 1263.674023] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:681 to 0x280000401:705) [ 1263.676456] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:681 to 0x2c0000401:705) [ 1266.696843] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1266.707213] Lustre: Skipped 2 previous similar messages [ 1278.705510] Lustre: Failing over lustre-MDT0000 [ 1278.944466] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1278.951699] LustreError: Skipped 1 previous similar message [ 1279.063509] Lustre: server umount lustre-MDT0000 complete [ 1288.854327] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1288.975187] LustreError: MGC192.168.203.126@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1288.984540] LustreError: Skipped 2 previous similar messages [ 1293.530604] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1294.360868] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:681 to 0x2c0000401:737) [ 1294.361089] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:681 to 0x280000401:737) [ 1296.650626] Lustre: *** cfs_fail_loc=1505, val=0*** [ 1296.658646] Lustre: Skipped 84 previous similar messages [ 1304.580583] Lustre: DEBUG MARKER: == sanity-lfsck test 6a: LFSCK resumes from last checkpoint (1) ========================================================== 14:51:25 (1786733485) [ 1306.016967] Lustre: 26283:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 1306.024555] Lustre: 26283:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 1026 previous similar messages [ 1306.030131] Lustre: 26283:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 1306.034368] Lustre: 26283:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 991 previous similar messages [ 1306.040350] Lustre: 26283:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 1306.045962] Lustre: 26283:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1028 previous similar messages [ 1306.051349] Lustre: 26283:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 1306.057783] Lustre: 26283:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1028 previous similar messages [ 1306.064231] Lustre: 26283:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 1306.070966] Lustre: 26283:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1028 previous similar messages [ 1306.076639] Lustre: 26283:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 1306.082711] Lustre: 26283:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1028 previous similar messages [ 1313.645340] Lustre: *** cfs_fail_loc=1600, val=1*** [ 1313.649478] Lustre: Skipped 7 previous similar messages [ 1333.344668] Lustre: DEBUG MARKER: == sanity-lfsck test 6b: LFSCK resumes from last checkpoint (2) ========================================================== 14:51:54 (1786733514) [ 1343.174947] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1343.185733] Lustre: Skipped 10 previous similar messages [ 1367.282359] Lustre: DEBUG MARKER: == sanity-lfsck test 7a: non-stopped LFSCK should auto restarts after MDS remount (1) ========================================================== 14:52:27 (1786733547) [ 1379.950417] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1379.957299] Lustre: Skipped 12 previous similar messages [ 1385.712447] Lustre: Failing over lustre-MDT0000 [ 1387.951409] Lustre: server umount lustre-MDT0000 complete [ 1396.635569] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1397.011040] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1397.016574] Lustre: Skipped 4 previous similar messages [ 1397.066444] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1397.084322] Lustre: Skipped 1 previous similar message [ 1401.816830] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1402.345574] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1402.358818] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1402.361862] Lustre: Skipped 1 previous similar message [ 1402.382873] Lustre: Skipped 8 previous similar messages [ 1402.422235] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1402.433510] Lustre: Skipped 1 previous similar message [ 1402.516117] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:853 to 0x2c0000401:897) [ 1402.546921] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:854 to 0x280000401:897) [ 1411.245818] Lustre: DEBUG MARKER: == sanity-lfsck test 7b: non-stopped LFSCK should auto restarts after MDS remount (2) ========================================================== 14:53:11 (1786733591) [ 1427.279846] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing load_modules_local [ 1445.492865] Lustre: 52981:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 1467.442542] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1471.060702] Lustre: 54116:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 1478.634782] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1478.645918] Lustre: Skipped 81 previous similar messages [ 1481.244668] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1482.280055] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1483.295275] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1485.343138] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1485.346408] Lustre: Skipped 1 previous similar message [ 1486.589665] Lustre: Failing over lustre-MDT0000 [ 1486.892170] Lustre: server umount lustre-MDT0000 complete [ 1489.380087] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1489.384767] 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 [ 1489.386229] LustreError: Skipped 1 previous similar message [ 1489.391655] LustreError: 26283: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. [ 1489.391664] LustreError: 26283:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 81 previous similar messages [ 1489.442734] Lustre: Skipped 18 previous similar messages [ 1496.384753] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1501.263821] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1502.285656] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:946 to 0x2c0000401:961) [ 1502.290025] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:947 to 0x280000401:993) [ 1514.229851] Lustre: DEBUG MARKER: == sanity-lfsck test 8: LFSCK state machine ============== 14:54:53 (1786733693) [ 1517.539637] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1517.558655] Lustre: Skipped 3 previous similar messages [ 1522.664978] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1522.676732] Lustre: Skipped 3 previous similar messages [ 1522.900593] Lustre: server umount lustre-MDT0000 complete [ 1527.009684] LustreError: 29320:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1786733709 with bad export cookie 14632654493502136476 [ 1527.023374] LustreError: 29320:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 1527.177697] Lustre: server umount lustre-MDT0001 complete [ 1542.838248] Lustre: server umount lustre-OST0000 complete [ 1543.137206] Lustre: 16433:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786733710/real 1786733710] req@ffff977875679880 x1873524964835072/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786733726 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1546.674607] Lustre: server umount lustre-OST0001 complete [ 1552.647623] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_hostid [ 1559.717620] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing load_modules_local [ 1598.611695] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing load_modules_local [ 1608.151793] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1608.497813] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 1608.532176] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 1608.599886] Lustre: lustre-MDT0000: new disk, initializing [ 1608.720985] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 1613.488600] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1623.824915] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1623.921429] Lustre: 59173: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 [ 1623.942511] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 1623.945504] Lustre: Skipped 1 previous similar message [ 1624.011388] Lustre: lustre-MDT0001: new disk, initializing [ 1624.079528] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 1624.095073] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 1628.076907] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1632.592200] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 1639.020155] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 1639.220721] Lustre: lustre-OST0000: new disk, initializing [ 1639.224729] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 1639.238314] Lustre: 60809:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 1640.803037] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 1640.813600] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 1640.871919] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 1644.541605] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1654.310657] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 1654.401682] Lustre: lustre-OST0001: new disk, initializing [ 1654.405658] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 1654.410278] Lustre: 61678:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 1655.840359] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 1655.854883] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 1655.898640] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 1659.817330] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1668.436464] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1672.169272] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 1683.985114] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1685.085296] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1685.088466] Lustre: Skipped 19 previous similar messages [ 1690.220096] Lustre: *** cfs_fail_loc=1601, val=2*** [ 1690.234920] Lustre: Skipped 5 previous similar messages [ 1711.075751] Lustre: Failing over lustre-MDT0000 [ 1711.294807] Lustre: server umount lustre-MDT0000 complete [ 1719.734974] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1719.847875] LustreError: MGC192.168.203.126@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1719.855739] LustreError: Skipped 3 previous similar messages [ 1720.047926] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1720.062095] Lustre: Skipped 1 previous similar message [ 1723.501806] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1725.413179] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1725.414566] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1725.420070] Lustre: Skipped 1 previous similar message [ 1725.431749] Lustre: Skipped 7 previous similar messages [ 1725.451764] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1725.468449] Lustre: Skipped 1 previous similar message [ 1725.548176] Lustre: *** cfs_fail_loc=160b, val=2*** [ 1725.556391] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:65) [ 1725.561284] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:65) [ 1731.941969] Lustre: Failing over lustre-MDT0000 [ 1734.248183] Lustre: server umount lustre-MDT0000 complete [ 1743.230260] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1747.613374] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1749.021646] Lustre: *** cfs_fail_loc=160b, val=2*** [ 1749.027487] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:97) [ 1749.034199] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:97) [ 1752.279660] Lustre: Failing over lustre-MDT0000 [ 1752.404872] Lustre: server umount lustre-MDT0000 complete [ 1759.737333] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1764.293900] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1765.433367] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:129) [ 1765.434357] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:129) [ 1769.227235] Lustre: *** cfs_fail_loc=1602, val=2*** [ 1769.229636] Lustre: Skipped 1 previous similar message [ 1781.818903] Lustre: DEBUG MARKER: == sanity-lfsck test 9a: LFSCK speed control (1) ========= 14:59:22 (1786733962) [ 1794.940889] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing load_modules_local [ 1812.400266] Lustre: 68683:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 1833.467960] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1837.015568] Lustre: 69817:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 1845.519620] Lustre: 59181:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 1845.541847] Lustre: 59181:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 2777 previous similar messages [ 1845.553983] Lustre: 59181:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 1845.564278] Lustre: 59181:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 2777 previous similar messages [ 1845.586930] Lustre: 59181:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 1845.600264] Lustre: 59181:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 2777 previous similar messages [ 1845.610270] Lustre: 59181:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 1845.618447] Lustre: 59181:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 2777 previous similar messages [ 1845.643303] Lustre: 59181:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 1845.652489] Lustre: 59181:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 2777 previous similar messages [ 1845.662280] Lustre: 59181:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 1845.673955] Lustre: 59181:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 2777 previous similar messages [ 1962.929939] Lustre: DEBUG MARKER: == sanity-lfsck test 9b: LFSCK speed control (2) ========= 15:02:23 (1786734143) [ 2015.068090] Lustre: *** cfs_fail_loc=1604, val=0*** [ 2015.077882] Lustre: Skipped 4 previous similar messages [ 2040.548136] Lustre: *** cfs_fail_loc=160c, val=0*** [ 2040.551455] Lustre: Skipped 9 previous similar messages [ 2075.961588] Lustre: DEBUG MARKER: == sanity-lfsck test 10: System is available during LFSCK scanning ========================================================== 15:04:16 (1786734256) [ 2123.889790] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2131.900648] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2131.914845] Lustre: Skipped 396 previous similar messages [ 2147.947360] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2147.949438] Lustre: Skipped 857 previous similar messages [ 2179.966627] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2179.968667] Lustre: Skipped 1796 previous similar messages [ 2189.944213] Lustre: *** cfs_fail_loc=1604, val=0*** [ 2189.950697] Lustre: Skipped 2599 previous similar messages [ 2434.669545] Lustre: DEBUG MARKER: == sanity-lfsck test 11a: LFSCK can rebuild lost last_id ========================================================== 15:10:15 (1786734615) [ 2469.808459] Lustre: 73646:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 320, rollback = 2 [ 2469.816292] Lustre: 73646:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 36831 previous similar messages [ 2469.821953] Lustre: 73646:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 1/4/0 [ 2469.830863] Lustre: 73646:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 36831 previous similar messages [ 2469.836684] Lustre: 73646:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 5/5/0, xattr_set: 7/320/0 [ 2469.842917] Lustre: 73646:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 36831 previous similar messages [ 2469.849635] Lustre: 73646:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 6/46/0, punch: 0/0/0, quota 1/3/0 [ 2469.856626] Lustre: 73646:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 36831 previous similar messages [ 2469.862604] Lustre: 73646:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 2/5/0 [ 2469.867940] Lustre: 73646:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 36831 previous similar messages [ 2469.874379] Lustre: 73646:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 1/1/0, ref_del: 2/2/1 [ 2469.878606] Lustre: 73646:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 36831 previous similar messages [ 2599.906712] 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 [ 2599.908325] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2599.910753] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 2599.910761] LustreError: Skipped 3 previous similar messages [ 2599.923751] Lustre: Skipped 18 previous similar messages [ 2599.962491] Lustre: Skipped 3 previous similar messages [ 2605.021291] Lustre: server umount lustre-MDT0000 complete [ 2605.024419] LustreError: 61684: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. [ 2605.058884] LustreError: 61684:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 34 previous similar messages [ 2609.295575] LustreError: 59165:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1786734792 with bad export cookie 14632654493502155572 [ 2609.301140] LustreError: MGC192.168.203.126@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2609.314283] LustreError: 59165:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 2609.353846] LustreError: Skipped 2 previous similar messages [ 2609.821023] Lustre: server umount lustre-MDT0001 complete [ 2625.874694] Lustre: server umount lustre-OST0000 complete [ 2626.786891] Lustre: 16433:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786734793/real 1786734793] req@ffff97784628a680 x1873524968616192/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786734809 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2630.388533] Lustre: server umount lustre-OST0001 complete [ 2637.392837] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: (null) [ 2648.215433] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 2663.968255] LustreError: Failed to get MGS log lustre-sptlrpc and no local copy. [ 2669.087313] LustreError: 75178:0:(mgc_request.c:233:do_config_log_add()) MGC192.168.203.126@tcp: failed processing log, type 4: rc = -110 [ 2694.751367] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 2694.759273] Lustre: Skipped 8 previous similar messages [ 2700.974214] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2705.331839] Lustre: 75763: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. [ 2705.359742] Lustre: *** cfs_fail_loc=160e, val=3*** [ 2708.401447] Lustre: 75763:0:(ofd_dev.c:573:ofd_lfsck_out_notify()) lustre-OST0000: Rebuilt crashed LAST_ID files successfully. [ 2718.043444] Lustre: DEBUG MARKER: == sanity-lfsck test 11b: LFSCK can rebuild crashed last_id ========================================================== 15:14:58 (1786734898) [ 2732.049343] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing load_modules_local [ 2742.321657] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2742.703679] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3272 to 0x280000401:3297) [ 2747.480900] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2759.259775] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2759.573948] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 2759.584841] Lustre: Skipped 1 previous similar message [ 2764.726089] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2768.156583] Lustre: 78427:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 2784.410104] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2789.882529] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3207 to 0x2c0000401:3233) [ 2790.718667] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2798.951645] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 2804.366388] Lustre: 79926:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 2809.420042] Lustre: *** cfs_fail_loc=160d, val=0*** [ 2810.166236] Lustre: *** cfs_fail_loc=160d, val=0*** [ 2810.173661] Lustre: Skipped 3 previous similar messages [ 2817.721818] Lustre: Failing over lustre-OST0000 [ 2817.807741] Lustre: server umount lustre-OST0000 complete [ 2819.552075] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 2831.591311] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2832.079407] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 2832.089245] Lustre: Skipped 2 previous similar messages [ 2833.639932] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 2833.655589] Lustre: Skipped 2 previous similar messages [ 2833.693338] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 2833.695120] Lustre: lustre-OST0000-osc-MDT0001: Connection restored to 0@lo (at 0@lo) [ 2833.697524] Lustre: *** cfs_fail_loc=215, val=0*** [ 2833.708963] Lustre: Skipped 2 previous similar messages [ 2833.715409] Lustre: Skipped 11 previous similar messages [ 2839.007889] Lustre: *** cfs_fail_loc=215, val=0*** [ 2839.009898] Lustre: Skipped 2 previous similar messages [ 2840.415411] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2844.127387] Lustre: *** cfs_fail_loc=215, val=0*** [ 2845.054094] Lustre: 81328: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. [ 2845.113310] Lustre: 81328:0:(ofd_dev.c:573:ofd_lfsck_out_notify()) lustre-OST0000: Rebuilt crashed LAST_ID files successfully. [ 2848.581598] Lustre: Failing over lustre-OST0000 [ 2848.678425] Lustre: server umount lustre-OST0000 complete [ 2857.088878] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2859.062804] Lustre: *** cfs_fail_loc=215, val=0*** [ 2859.068212] Lustre: Skipped 4 previous similar messages [ 2863.439636] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2864.097127] Lustre: *** cfs_fail_loc=215, val=0*** [ 2864.104627] Lustre: Skipped 1 previous similar message [ 2872.293058] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2877.238345] Lustre: server umount lustre-MDT0000 complete [ 2881.756860] LustreError: 75184:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1786735064 with bad export cookie 14632654493503723278 [ 2881.793309] LustreError: 75184:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 3 previous similar messages [ 2882.037927] Lustre: server umount lustre-MDT0001 complete [ 2895.615975] Lustre: server umount lustre-OST0000 complete [ 2898.413099] Lustre: 16431:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786735065/real 1786735065] req@ffff977870981880 x1873524968717952/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786735081 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2900.109957] Lustre: server umount lustre-OST0001 complete [ 2907.800630] Lustre: DEBUG MARKER: == sanity-lfsck test 12a: single command to trigger LFSCK on all devices ========================================================== 15:18:08 (1786735088) [ 2923.436346] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing load_modules_local [ 2934.094993] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2934.495151] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 2934.504618] Lustre: Skipped 3 previous similar messages [ 2938.801252] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2947.737901] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2953.438420] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2957.194195] Lustre: 85712:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 2965.078529] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2973.417840] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2979.349710] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3362 to 0x280000401:3393) [ 2987.506996] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2993.151773] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3207 to 0x2c0000401:3265) [ 2995.727830] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3005.720874] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3011.183755] Lustre: 87584:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 3053.355833] Lustre: DEBUG MARKER: == sanity-lfsck test 12b: auto detect Lustre device ====== 15:20:33 (1786735233) [ 3067.259779] Lustre: DEBUG MARKER: == sanity-lfsck test 13: LFSCK can repair crashed lmm_oi ========================================================== 15:20:47 (1786735247) [ 3068.648572] Lustre: *** cfs_fail_loc=160f, val=0*** [ 3080.381163] Lustre: DEBUG MARKER: == sanity-lfsck test 14a: LFSCK can repair MDT-object with dangling LOV EA reference (1) ========================================================== 15:21:00 (1786735260) [ 3080.717743] Lustre: 86594:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 253 < left 278, rollback = 2 [ 3080.724516] Lustre: 86594:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 1010 previous similar messages [ 3080.729216] Lustre: 86594:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 3080.733298] Lustre: 86594:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1010 previous similar messages [ 3080.737523] Lustre: 86594:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3080.741748] Lustre: 86594:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1010 previous similar messages [ 3080.746513] Lustre: 86594:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/1 [ 3080.756412] Lustre: 86594:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1010 previous similar messages [ 3080.761448] Lustre: 86594:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 3080.764938] Lustre: 86594:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1010 previous similar messages [ 3080.769668] Lustre: 86594:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3080.773337] Lustre: 86594:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1010 previous similar messages [ 3083.932048] Lustre: *** cfs_fail_loc=1610, val=0*** [ 3083.993332] Lustre: Skipped 3 previous similar messages [ 3136.481420] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3136.485559] Lustre: Skipped 3 previous similar messages [ 3139.332742] Lustre: server umount lustre-MDT0000 complete [ 3144.324502] LustreError: 84553:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1786735327 with bad export cookie 14632654493503731776 [ 3144.343560] LustreError: 84553:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 3144.739653] Lustre: server umount lustre-MDT0001 complete [ 3160.234824] Lustre: server umount lustre-OST0000 complete [ 3162.149633] Lustre: 16430:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786735329/real 1786735329] req@ffff9778708aa300 x1873524968954368/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786735345 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3165.270679] Lustre: 16430:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786735332/real 1786735332] req@ffff9778708aad80 x1873524968954624/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786735348 ref 1 fl Rpc:EXNQr/200/ffffffff rc -5/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3165.708509] Lustre: server umount lustre-OST0001 complete [ 3182.935271] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing load_modules_local [ 3193.026441] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3193.440892] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3193.447133] Lustre: Skipped 3 previous similar messages [ 3197.822261] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3206.536943] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3211.265723] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3214.193420] Lustre: 93449:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3220.364385] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3226.441283] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3231.915235] LustreError: 93805: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. [ 3231.937207] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:116 to 0x280000400:161) [ 3231.940028] LustreError: 93805:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 50 previous similar messages [ 3235.000192] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3238.258078] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3317 to 0x2c0000401:3361) [ 3238.259952] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:116 to 0x2c0000400:161) [ 3238.261779] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3554 to 0x280000401:3585) [ 3240.545753] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3247.424985] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3250.662723] Lustre: 95320:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 3256.646083] Lustre: DEBUG MARKER: == sanity-lfsck test 14b: LFSCK can repair MDT-object with dangling LOV EA reference (2) ========================================================== 15:23:57 (1786735437) [ 3261.660931] Lustre: *** cfs_fail_loc=1610, val=0*** [ 3261.662917] Lustre: Skipped 63 previous similar messages [ 3283.936033] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3283.943499] LustreError: Skipped 3 previous similar messages [ 3283.948817] 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 [ 3283.963205] Lustre: Skipped 17 previous similar messages [ 3283.970890] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3283.974399] Lustre: Skipped 3 previous similar messages [ 3289.575171] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3289.583050] Lustre: Skipped 7 previous similar messages [ 3289.994320] Lustre: server umount lustre-MDT0000 complete [ 3293.616684] LustreError: 92289:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1786735476 with bad export cookie 14632654493503760189 [ 3293.623206] LustreError: MGC192.168.203.126@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3293.626500] LustreError: 92289:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 3293.644753] LustreError: Skipped 2 previous similar messages [ 3294.003545] Lustre: server umount lustre-MDT0001 complete [ 3306.382944] Lustre: server umount lustre-OST0000 complete [ 3320.289886] Lustre: server umount lustre-OST0001 complete [ 3336.188728] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing load_modules_local [ 3346.436058] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3351.256526] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3359.808600] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3364.488630] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3367.776361] Lustre: 99357:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3374.933946] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3381.152408] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3384.441642] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:116 to 0x280000400:193) [ 3391.756885] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3391.984701] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3682 to 0x280000401:3713) [ 3397.114247] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:116 to 0x2c0000400:193) [ 3397.129961] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3317 to 0x2c0000401:3393) [ 3400.996848] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3411.465681] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3423.239702] Lustre: DEBUG MARKER: == sanity-lfsck test 15a: LFSCK can repair unmatched MDT-object/OST-object pairs (1) ========================================================== 15:26:43 (1786735603) [ 3427.759195] Lustre: *** cfs_fail_loc=1611, val=0*** [ 3427.765058] Lustre: Skipped 63 previous similar messages [ 3428.058398] Lustre: *** cfs_fail_loc=1611, val=0*** [ 3439.942489] Lustre: DEBUG MARKER: == sanity-lfsck test 15b: LFSCK can repair unmatched MDT-object/OST-object pairs (2) ========================================================== 15:27:00 (1786735620) [ 3442.405144] Lustre: *** cfs_fail_loc=1612, val=0*** [ 3442.492321] Lustre: *** cfs_fail_loc=1612, val=0*** [ 3442.494352] Lustre: Skipped 2 previous similar messages [ 3453.420776] Lustre: DEBUG MARKER: == sanity-lfsck test 15c: LFSCK can repair unmatched MDT-object/OST-object pairs (3) ========================================================== 15:27:13 (1786735633) [ 3455.355991] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_15c MDS newer than 2.7.55, LU-6475 [ 3457.515629] Lustre: DEBUG MARKER: == sanity-lfsck test 15d: LFSCK don't crash upon dir migration failure ========================================================== 15:27:17 (1786735637) [ 3464.322474] Lustre: *** cfs_fail_loc=1709, val=0*** [ 3464.326882] LustreError: 98225:0:(mdt_reint.c:2644:mdt_reint_migrate()) lustre-MDT0000: migrate [0x240002340:0x6c:0x0]/f36 failed: rc = -5 [ 3539.426801] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3539.436532] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3541.803956] Lustre: server umount lustre-MDT0000 complete [ 3551.410820] LustreError: 98198:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1786735734 with bad export cookie 14632654493503774924 [ 3551.449044] LustreError: 98198:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 3551.893957] Lustre: server umount lustre-MDT0001 complete [ 3571.167149] Lustre: 16431:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786735738/real 1786735738] req@ffff97774e200e00 x1873524969718656/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786735754 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3572.315239] Lustre: server umount lustre-OST0000 complete [ 3582.431330] Lustre: 16431:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786735749/real 1786735749] req@ffff977746ae9f80 x1873524969719808/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786735765 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3582.493638] Lustre: 16431:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 3584.334669] Lustre: server umount lustre-OST0001 complete [ 3603.498823] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing unload_modules_local [ 3607.290204] Key type lgssc unregistered [ 3607.692937] LNet: 105063:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 3607.703578] LNetError: 105063:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 3607.734669] LNet: Removed LNI 192.168.203.126@tcp [ 3608.862498] Key type .llcrypt unregistered [ 3608.864936] Key type ._llcrypt unregistered [ 3638.656293] Key type ._llcrypt registered [ 3638.664629] Key type .llcrypt registered [ 3638.861485] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_hostid [ 3652.884557] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing load_modules_local [ 3654.238084] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 3654.271350] alg: No test for adler32 (adler32-zlib) [ 3655.322862] Lustre: Lustre: Build Version: 2.17.56_2_gd9f03f2 [ 3655.549076] LNet: Added LNI 192.168.203.126@tcp [8/256/0/180] [ 3657.279331] Key type lgssc registered [ 3658.570264] Lustre: Echo OBD driver; http://www.lustre.org/ [ 3706.839509] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing load_modules_local [ 3720.081874] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 3720.146463] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3721.390172] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 3721.438926] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 3721.572440] Lustre: lustre-MDT0000: new disk, initializing [ 3721.648859] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3721.673956] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 3725.946656] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3739.014444] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3739.118130] Lustre: 109520: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 [ 3739.171156] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 3739.180252] Lustre: Skipped 1 previous similar message [ 3739.324983] Lustre: lustre-MDT0001: new disk, initializing [ 3739.374337] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 3739.420120] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 3739.426721] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 3744.301352] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3749.500482] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 3759.109992] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3759.284715] Lustre: lustre-OST0000: new disk, initializing [ 3759.290584] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 3759.296351] Lustre: 111458:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 3759.354832] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 3761.307149] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 3761.328830] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 3761.438912] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 3766.323609] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3780.911299] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3781.114448] Lustre: lustre-OST0001: new disk, initializing [ 3781.116855] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 3781.121343] Lustre: 112482:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 3781.179080] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 3787.502158] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 3787.526892] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 3787.631031] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 3790.010557] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3801.999319] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3806.950876] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 3813.274363] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 15:33:13 (1786735993) === [ 3819.787144] Lustre: DEBUG MARKER: == sanity-lfsck test 16: LFSCK can repair inconsistent MDT-object/OST-object owner ========================================================== 15:33:20 (1786736000) [ 3820.009343] Lustre: 109525:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 251 < left 278, rollback = 2 [ 3820.025926] Lustre: 109525:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 3820.046423] Lustre: 109525:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3820.064924] Lustre: 109525:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 3820.082515] Lustre: 109525:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 3820.098791] Lustre: 109525:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3820.642943] Lustre: 109527:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 252 < left 278, rollback = 2 [ 3820.655741] Lustre: 109527:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 9 previous similar messages [ 3820.674618] Lustre: 109527:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 3820.693511] Lustre: 109527:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3820.701267] Lustre: 109527:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3820.706395] Lustre: 109527:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3820.711742] Lustre: 109527:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/1, punch: 0/0/0, quota 7/369/2 [ 3820.716117] Lustre: 109527:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3820.721319] Lustre: 109527:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/1, delete: 0/0/0 [ 3820.728742] Lustre: 109527:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3820.733644] Lustre: 109527:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3820.745252] Lustre: 109527:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3821.646166] Lustre: 109526:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 3821.654676] Lustre: 109526:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 218 previous similar messages [ 3821.684392] Lustre: 113011:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 3821.689643] Lustre: 113011:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 224 previous similar messages [ 3821.704854] Lustre: 109527:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3821.710231] Lustre: 109527:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 227 previous similar messages [ 3821.716113] Lustre: 109527:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 7/369/0 [ 3821.726576] Lustre: 109527:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 227 previous similar messages [ 3821.733197] Lustre: 109527:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 3821.739581] Lustre: 109527:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 227 previous similar messages [ 3821.745389] Lustre: 109527:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3821.752967] Lustre: 109527:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 227 previous similar messages [ 3823.258820] Lustre: *** cfs_fail_loc=1613, val=0*** [ 3835.154561] Lustre: DEBUG MARKER: == sanity-lfsck test 17: LFSCK can repair multiple references ========================================================== 15:33:35 (1786736015) [ 3836.565783] Lustre: 109527:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 257 < left 278, rollback = 2 [ 3836.573664] Lustre: 109527:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 80 previous similar messages [ 3836.579204] Lustre: 109527:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 3836.585243] Lustre: 109527:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 74 previous similar messages [ 3836.590569] Lustre: 109527:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3836.595932] Lustre: 109527:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 71 previous similar messages [ 3836.603468] Lustre: 109527:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 3836.612081] Lustre: 109527:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 71 previous similar messages [ 3836.626664] Lustre: 109527:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 3836.635307] Lustre: 109527:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 71 previous similar messages [ 3836.649271] Lustre: 109527:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3836.654911] Lustre: 109527:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 71 previous similar messages [ 3837.873175] Lustre: *** cfs_fail_loc=1614, val=0*** [ 3838.417920] Lustre: *** cfs_fail_loc=1614, val=103*** [ 3838.419672] Lustre: Skipped 1 previous similar message [ 3842.539764] Lustre: 111449:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 259 < left 275, rollback = 2 [ 3842.554104] Lustre: 111449:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 11 previous similar messages [ 3842.563867] Lustre: 111449:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 3842.572983] Lustre: 111449:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3842.578537] Lustre: 111449:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/1, xattr_set: 3/275/0 [ 3842.583219] Lustre: 111449:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3842.588427] Lustre: 111449:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/9/0, punch: 1/4/0, quota 7/225/0 [ 3842.594372] Lustre: 111449:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3842.602577] Lustre: 111449:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 3842.613092] Lustre: 111449:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3842.622968] Lustre: 111449:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3842.631313] Lustre: 111449:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3849.926044] Lustre: DEBUG MARKER: == sanity-lfsck test 18a: Find out orphan OST-object and repair it (1) ========================================================== 15:33:50 (1786736030) [ 3850.557766] Lustre: 109527:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 3850.566347] Lustre: 109527:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 4 previous similar messages [ 3850.572198] Lustre: 109527:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 3850.578176] Lustre: 109527:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 4 previous similar messages [ 3850.584317] Lustre: 109527:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3850.592022] Lustre: 109527:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 4 previous similar messages [ 3850.599059] Lustre: 109527:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 3850.605662] Lustre: 109527:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 4 previous similar messages [ 3850.612217] Lustre: 109527:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 3850.618555] Lustre: 109527:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 4 previous similar messages [ 3850.644087] Lustre: 109527:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3850.657488] Lustre: 109527:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 4 previous similar messages [ 3852.906279] Lustre: *** cfs_fail_loc=1615, val=0*** [ 3852.916863] Lustre: Skipped 1 previous similar message [ 3854.390223] Lustre: *** cfs_fail_loc=1615, val=0*** [ 3854.392395] Lustre: Skipped 1 previous similar message [ 3876.668840] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_18b skipping excluded test 18b [ 3879.216137] Lustre: DEBUG MARKER: == sanity-lfsck test 18c: Find out orphan OST-object and repair it (3) ========================================================== 15:34:18 (1786736058) [ 3879.968853] Lustre: 113011:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 3879.999768] Lustre: 113011:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 18 previous similar messages [ 3880.017585] Lustre: 113011:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 3880.040384] Lustre: 113011:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 18 previous similar messages [ 3880.062597] Lustre: 113011:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3880.084777] Lustre: 113011:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 18 previous similar messages [ 3880.104273] Lustre: 113011:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 3880.127535] Lustre: 113011:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 18 previous similar messages [ 3880.143515] Lustre: 113011:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 3880.163051] Lustre: 113011:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 18 previous similar messages [ 3880.182613] Lustre: 113011:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3880.204812] Lustre: 113011:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 18 previous similar messages [ 3882.770965] Lustre: *** cfs_fail_loc=1617, val=0*** [ 3882.839639] Lustre: *** cfs_fail_loc=1617, val=0*** [ 3885.518211] Lustre: *** cfs_fail_loc=1616, val=0*** [ 3885.520229] Lustre: Skipped 3 previous similar messages [ 3905.527681] Lustre: DEBUG MARKER: == sanity-lfsck test 18d: Find out orphan OST-object and repair it (4) ========================================================== 15:34:45 (1786736085) [ 3907.920276] Lustre: *** cfs_fail_loc=1618, val=0*** [ 3907.925898] Lustre: Skipped 5 previous similar messages [ 3944.415888] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3944.429652] 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 [ 3944.445294] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3946.471236] 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 [ 3946.478120] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3946.499093] Lustre: Skipped 2 previous similar messages [ 3946.506556] Lustre: Skipped 2 previous similar messages [ 3947.976968] Lustre: server umount lustre-MDT0000 complete [ 3951.774340] LustreError: 110470:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1786736134 with bad export cookie 1726000539780403603 [ 3951.777270] LustreError: MGC192.168.203.126@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3951.790481] LustreError: 110470:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 3952.154704] Lustre: server umount lustre-MDT0001 complete [ 3967.128484] Lustre: server umount lustre-OST0000 complete [ 3980.550475] Lustre: server umount lustre-OST0001 complete [ 4001.007647] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing load_modules_local [ 4013.578678] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4013.897065] LustreError: 118210: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. [ 4013.916794] LustreError: 118210:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 5 previous similar messages [ 4014.004770] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4017.829828] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4019.173572] LustreError: 118211: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. [ 4023.266592] LustreError: 118210: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. [ 4026.619900] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4027.118965] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 4031.078099] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4034.293548] Lustre: 119350:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 4042.062147] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4048.448784] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4051.694129] LustreError: 119703: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. [ 4051.720807] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:4 to 0x280000400:33) [ 4057.075845] LustreError: 119703: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. [ 4058.641414] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4058.888256] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 4058.893290] Lustre: Skipped 1 previous similar message [ 4059.949495] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:4 to 0x2c0000401:33) [ 4059.950951] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:33) [ 4060.003219] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:116 to 0x280000401:161) [ 4065.525592] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4072.916731] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4076.562829] Lustre: 121222:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 4090.105450] Lustre: DEBUG MARKER: == sanity-lfsck test 18e: Find out orphan OST-object and repair it (5) ========================================================== 15:37:50 (1786736270) [ 4090.513664] Lustre: 118206:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 4090.524759] Lustre: 118206:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 46 previous similar messages [ 4090.533713] Lustre: 118206:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 4090.545054] Lustre: 118206:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4090.553379] Lustre: 118206:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4090.558790] Lustre: 118206:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4090.565494] Lustre: 118206:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 4090.571221] Lustre: 118206:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4090.577242] Lustre: 118206:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 4090.582849] Lustre: 118206:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4090.588628] Lustre: 118206:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4090.603311] Lustre: 118206:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4092.462662] Lustre: *** cfs_fail_loc=1618, val=0*** [ 4092.464584] Lustre: Skipped 3 previous similar messages [ 4126.688988] 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 [ 4126.693029] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4126.711795] Lustre: Skipped 2 previous similar messages [ 4126.737742] Lustre: Skipped 3 previous similar messages [ 4131.810132] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4131.822308] Lustre: Skipped 3 previous similar messages [ 4132.219811] Lustre: server umount lustre-MDT0000 complete [ 4135.927473] LustreError: 118191:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1786736318 with bad export cookie 1726000539780418842 [ 4135.952829] LustreError: MGC192.168.203.126@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4136.458042] Lustre: server umount lustre-MDT0001 complete [ 4150.772274] Lustre: server umount lustre-OST0000 complete [ 4152.675937] Lustre: 106678:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786736319/real 1786736319] req@ffff97774b1f1180 x1873528318352000/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786736335 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4152.692724] 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 [ 4152.699761] Lustre: Skipped 1 previous similar message [ 4154.813708] Lustre: server umount lustre-OST0001 complete [ 4173.397705] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing load_modules_local [ 4185.482701] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4185.857519] LustreError: 123796: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. [ 4185.957189] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4191.580680] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4200.391271] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4205.403107] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4208.674467] Lustre: 124935:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 4216.085697] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4224.012894] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4225.645696] LustreError: 125289: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. [ 4225.666973] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:4 to 0x280000400:65) [ 4225.682736] LustreError: 125289:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 3 previous similar messages [ 4230.767936] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:166 to 0x280000401:193) [ 4234.872305] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4240.369203] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:4 to 0x2c0000401:65) [ 4240.378297] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:65) [ 4241.730698] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4249.245170] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4253.314502] Lustre: 126808:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 4259.884968] Lustre: 125958:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 252 < left 260, rollback = 2 [ 4259.893430] Lustre: 125958:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 21 previous similar messages [ 4259.905865] Lustre: 125958:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4259.913323] Lustre: 125958:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4259.933153] Lustre: 125958:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 0/0/0, xattr_set: 1/260/0 [ 4259.944413] Lustre: 125958:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4259.953221] Lustre: 125958:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/9/0, punch: 0/0/0, quota 4/150/2 [ 4259.954442] Lustre: *** cfs_fail_loc=1602, val=10*** [ 4259.975078] Lustre: 125958:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4259.975100] Lustre: 125958:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 1/17/2, delete: 0/0/0 [ 4259.975104] Lustre: 125958:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4259.975108] Lustre: 125958:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 4259.975111] Lustre: 125958:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4260.063214] Lustre: Skipped 1 previous similar message [ 4287.017767] Lustre: DEBUG MARKER: == sanity-lfsck test 18f: Skip the failed OST(s) when handle orphan OST-objects ========================================================== 15:41:07 (1786736467) [ 4290.611080] Lustre: *** cfs_fail_loc=1616, val=0*** [ 4290.617443] Lustre: Skipped 3 previous similar messages [ 4297.308883] Lustre: *** cfs_fail_loc=161c, val=0*** [ 4297.317884] Lustre: Skipped 1 previous similar message [ 4320.899280] Lustre: DEBUG MARKER: == sanity-lfsck test 18g: Find out orphan OST-object and repair it (7) ========================================================== 15:41:41 (1786736501) [ 4322.858131] Lustre: *** cfs_fail_loc=162e, val=0*** [ 4322.862046] Lustre: *** cfs_fail_loc=162e, val=0*** [ 4322.864934] Lustre: Skipped 7 previous similar messages [ 4338.234892] Lustre: DEBUG MARKER: == sanity-lfsck test 18h: LFSCK can repair crashed PFL extent range ========================================================== 15:41:58 (1786736518) [ 4361.172525] Lustre: DEBUG MARKER: == sanity-lfsck test 19a: OST-object inconsistency self detect ========================================================== 15:42:21 (1786736541) [ 4373.934195] Lustre: DEBUG MARKER: == sanity-lfsck test 19b: OST-object inconsistency self repair ========================================================== 15:42:34 (1786736554) [ 4376.815341] Lustre: *** cfs_fail_loc=1611, val=0*** [ 4376.862666] Lustre: *** cfs_fail_loc=1611, val=0*** [ 4376.877813] Lustre: Skipped 3 previous similar messages [ 4381.615607] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.203.26@tcp inode [0x2000013a1:0x1f:0x0] object 0x280000401:202 extent [0-4095], client returned csum 0 (type 4), server csum 703fb3ad (type 4) [ 4382.698050] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.203.26@tcp inode [0x2000013a1:0x20:0x0] object 0x280000401:203 extent [0-4095], client returned csum 0 (type 4), server csum 7cbb935c (type 4) [ 4390.875993] Lustre: DEBUG MARKER: == sanity-lfsck test 20a: Handle the orphan with dummy LOV EA slot properly ========================================================== 15:42:51 (1786736571) [ 4391.374901] Lustre: 125311:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 252 < left 278, rollback = 2 [ 4391.388216] Lustre: 125311:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 104 previous similar messages [ 4391.404891] Lustre: 125311:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4391.416842] Lustre: 125311:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 4391.432122] Lustre: 125311:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4391.442043] Lustre: 125311:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 4391.454216] Lustre: 125311:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 4391.468145] Lustre: 125311:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 4391.486542] Lustre: 125311:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 4391.497732] Lustre: 125311:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 4391.509567] Lustre: 125311:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4391.520425] Lustre: 125311:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 4393.432228] Lustre: *** cfs_fail_loc=1616, val=0*** [ 4393.435805] Lustre: Skipped 3 previous similar messages [ 4417.277766] Lustre: DEBUG MARKER: == sanity-lfsck test 20b: Handle the orphan with dummy LOV EA slot properly - PFL case ========================================================== 15:43:17 (1786736597) [ 4424.441579] Lustre: DEBUG MARKER: == sanity-lfsck test 21: run all LFSCK components by default ========================================================== 15:43:24 (1786736604) [ 4437.563957] Lustre: DEBUG MARKER: == sanity-lfsck test 22a: LFSCK can repair unmatched pairs (1) ========================================================== 15:43:37 (1786736617) [ 4440.093147] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4440.102355] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4440.109214] Lustre: Skipped 1 previous similar message [ 4452.344421] Lustre: DEBUG MARKER: == sanity-lfsck test 22b: LFSCK can repair unmatched pairs (2) ========================================================== 15:43:52 (1786736632) [ 4454.185318] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4454.191045] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4466.942171] Lustre: DEBUG MARKER: == sanity-lfsck test 23a: LFSCK can repair dangling name entry (1) ========================================================== 15:44:07 (1786736647) [ 4469.216836] Lustre: *** cfs_fail_loc=1620, val=0*** [ 4484.552301] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_23b skipping excluded test 23b [ 4486.837855] Lustre: DEBUG MARKER: == sanity-lfsck test 23c: LFSCK can repair dangling name entry (3) ========================================================== 15:44:26 (1786736666) [ 4493.945697] Lustre: *** cfs_fail_loc=1621, val=127*** [ 4493.961555] Lustre: Skipped 1 previous similar message [ 4497.305179] Lustre: *** cfs_fail_loc=1602, val=10*** [ 4521.084430] Lustre: DEBUG MARKER: == sanity-lfsck test 23d: LFSCK can repair a dangling name entry to a remote object ========================================================== 15:45:01 (1786736701) [ 4523.760460] Lustre: Failing over lustre-MDT0000 [ 4524.312273] Lustre: server umount lustre-MDT0000 complete [ 4524.545646] LustreError: 123793:0:(ldlm_lib.c:1192:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.203.26@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4524.576926] LustreError: 123793:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 2 previous similar messages [ 4527.082756] 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 [ 4527.115324] Lustre: Skipped 2 previous similar messages [ 4534.725575] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4534.976591] LustreError: MGC192.168.203.126@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4535.216959] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4535.222977] Lustre: Skipped 3 previous similar messages [ 4535.262772] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4539.896246] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4539.941581] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4540.402537] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4540.424878] Lustre: lustre-MDT0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 4540.468283] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:265 to 0x280000401:289) [ 4540.472352] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:130 to 0x2c0000401:161) [ 4541.922393] LustreError: 123792:0:(mdt_open.c:1324:mdt_cross_open()) lustre-MDT0000: [0x2000013a3:0x82:0x0] doesn't exist!: rc = -14 [ 4553.692449] Lustre: DEBUG MARKER: == sanity-lfsck test 24: LFSCK can repair multiple-referenced name entry ========================================================== 15:45:33 (1786736733) [ 4555.880354] Lustre: *** cfs_fail_loc=1622, val=0*** [ 4556.017390] Lustre: *** cfs_fail_loc=1622, val=0*** [ 4556.023211] Lustre: Skipped 1 previous similar message [ 4567.403797] Lustre: DEBUG MARKER: == sanity-lfsck test 25: LFSCK can repair bad file type in the name entry ========================================================== 15:45:47 (1786736747) [ 4569.247454] Lustre: *** cfs_fail_loc=1623, val=0*** [ 4580.138784] Lustre: DEBUG MARKER: == sanity-lfsck test 26a: LFSCK can add the missing local name entry back to the namespace ========================================================== 15:46:00 (1786736760) [ 4581.667976] Lustre: *** cfs_fail_loc=1624, val=0*** [ 4593.438563] Lustre: DEBUG MARKER: == sanity-lfsck test 26b: LFSCK can add the missing remote name entry back to the namespace ========================================================== 15:46:13 (1786736773) [ 4606.131407] Lustre: DEBUG MARKER: == sanity-lfsck test 27a: LFSCK can recreate the lost local parent directory as orphan ========================================================== 15:46:26 (1786736786) [ 4607.915539] Lustre: *** cfs_fail_loc=1624, val=0*** [ 4607.925711] Lustre: Skipped 1 previous similar message [ 4618.856250] Lustre: DEBUG MARKER: == sanity-lfsck test 27b: LFSCK can recreate the lost remote parent directory as orphan ========================================================== 15:46:39 (1786736799) [ 4631.759822] Lustre: DEBUG MARKER: == sanity-lfsck test 28: Skip the failed MDT(s) when handle orphan MDT-objects ========================================================== 15:46:52 (1786736812) [ 4638.567236] Lustre: *** cfs_fail_loc=161c, val=0*** [ 4654.556124] Lustre: DEBUG MARKER: == sanity-lfsck test 29b: LFSCK can repair bad nlink count (2) ========================================================== 15:47:14 (1786736834) [ 4655.462575] Lustre: 123791:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 4655.481867] Lustre: 123791:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 518 previous similar messages [ 4655.499364] Lustre: 123791:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 4655.515764] Lustre: 123791:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 518 previous similar messages [ 4655.534747] Lustre: 123791:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4655.558205] Lustre: 123791:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 518 previous similar messages [ 4655.574918] Lustre: 123791:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 4655.599724] Lustre: 123791:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 518 previous similar messages [ 4655.613289] Lustre: 123791:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 4655.625327] Lustre: 123791:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 518 previous similar messages [ 4655.644475] Lustre: 123791:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4655.666450] Lustre: 123791:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 518 previous similar messages [ 4657.188318] Lustre: *** cfs_fail_loc=1626, val=0*** [ 4657.196374] Lustre: Skipped 4 previous similar messages [ 4670.959360] Lustre: DEBUG MARKER: == sanity-lfsck test 29c: verify linkEA size limitation == 15:47:30 (1786736850) [ 4700.402561] Lustre: DEBUG MARKER: == sanity-lfsck test 29d: accessing non-existing inode shouldn't turn fs read-only (ldiskfs) ========================================================== 15:48:00 (1786736880) [ 4703.068606] LustreError: 123792:0:(osd_handler.c:284:osd_idc_find_or_init()) lustre-MDT0000: cannot lookup FID [0x2000013a3:0x9e:0x0]: rc = -2 [ 4709.974967] Lustre: DEBUG MARKER: == sanity-lfsck test 30: LFSCK can recover the orphans from backend /lost+found ========================================================== 15:48:10 (1786736890) [ 4733.756613] Lustre: Failing over lustre-MDT0000 [ 4734.215789] Lustre: server umount lustre-MDT0000 complete [ 4734.945190] 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 [ 4734.949472] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4734.951057] LustreError: 126118: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. [ 4734.951070] LustreError: 126118:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 10 previous similar messages [ 4734.963749] Lustre: Skipped 2 previous similar messages [ 4745.290484] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 4745.405441] LustreError: MGC192.168.203.126@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4745.685486] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4745.729129] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4749.713942] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4750.817723] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4750.833291] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4750.848044] Lustre: Skipped 3 previous similar messages [ 4750.874322] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4750.929067] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:295 to 0x280000401:321) [ 4750.933132] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:166 to 0x2c0000401:193) [ 4763.212411] Lustre: DEBUG MARKER: == sanity-lfsck test 31a: The LFSCK can find/repair the name entry with bad name hash (1) ========================================================== 15:49:03 (1786736943) [ 4778.574084] Lustre: DEBUG MARKER: == sanity-lfsck test 31b: The LFSCK can find/repair the name entry with bad name hash (2) ========================================================== 15:49:18 (1786736958) [ 4796.540620] Lustre: DEBUG MARKER: == sanity-lfsck test 31c: Re-generate the lost master LMV EA for striped directory ========================================================== 15:49:36 (1786736976) [ 4798.229385] Lustre: *** cfs_fail_loc=1629, val=0*** [ 4798.231319] Lustre: Skipped 5 previous similar messages [ 4814.565237] Lustre: DEBUG MARKER: == sanity-lfsck test 31d: Set broken striped directory (modified after broken) as read-only ========================================================== 15:49:54 (1786736994) [ 4823.141764] Lustre: Failing over lustre-MDT0000 [ 4823.411046] Lustre: server umount lustre-MDT0000 complete [ 4827.618136] 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 [ 4827.618314] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4827.629686] Lustre: Skipped 5 previous similar messages [ 4832.494298] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4832.594292] LustreError: MGC192.168.203.126@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4832.740356] Lustre: lustre-MDT0000: Not available for connect from 0@lo (not set up) [ 4832.742623] Lustre: Skipped 2 previous similar messages [ 4832.878934] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4837.236848] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4837.862582] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4837.864883] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4837.871223] Lustre: Skipped 3 previous similar messages [ 4837.894211] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4837.943153] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:295 to 0x280000401:353) [ 4837.945024] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:166 to 0x2c0000401:225) [ 4847.526698] Lustre: Failing over lustre-MDT0000 [ 4847.916612] Lustre: server umount lustre-MDT0000 complete [ 4848.096467] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4857.222292] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4857.388969] LustreError: MGC192.168.203.126@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4857.751802] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4859.886585] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4862.384776] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4862.955765] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4862.970762] Lustre: Skipped 3 previous similar messages [ 4863.005340] Lustre: lustre-MDT0000: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 4863.058814] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:295 to 0x280000401:385) [ 4863.059616] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:227 to 0x2c0000401:257) [ 4871.510292] Lustre: DEBUG MARKER: == sanity-lfsck test 31e: Re-generate the lost slave LMV EA for striped directory (1) ========================================================== 15:50:51 (1786737051) [ 4885.194752] Lustre: DEBUG MARKER: == sanity-lfsck test 31f: Re-generate the lost slave LMV EA for striped directory (2) ========================================================== 15:51:05 (1786737065) [ 4899.121259] Lustre: DEBUG MARKER: == sanity-lfsck test 31g: Repair the corrupted slave LMV EA ========================================================== 15:51:19 (1786737079) [ 4940.015963] Lustre: DEBUG MARKER: == sanity-lfsck test 31h: Repair the corrupted shard's name entry ========================================================== 15:51:59 (1786737119) [ 4957.250427] Lustre: DEBUG MARKER: == sanity-lfsck test 32a: stop LFSCK when some OST failed ========================================================== 15:52:17 (1786737137) [ 4967.499059] LustreError: 148166:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d sleeping for 3000ms [ 4970.324049] Lustre: Failing over lustre-OST0000 [ 4970.406181] Lustre: server umount lustre-OST0000 complete [ 4970.467392] 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 [ 4970.472564] LustreError: 129753: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. [ 4970.485943] Lustre: Skipped 5 previous similar messages [ 4970.512878] LustreError: 148166:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d awake [ 4970.513149] LustreError: 129753:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 26 previous similar messages [ 4970.536172] LustreError: 148166:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d sleeping for 3000ms [ 4973.544198] LustreError: 148166:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d awake [ 4973.551766] LustreError: 148166:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d sleeping for 3000ms [ 4973.679515] LustreError: 148166:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout interrupted [ 4986.889802] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 4987.116086] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 4988.194951] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4988.243915] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 4988.244183] Lustre: lustre-OST0000-osc-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4988.254665] Lustre: Skipped 3 previous similar messages [ 4994.821908] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5005.965813] Lustre: DEBUG MARKER: == sanity-lfsck test 32b: stop LFSCK when some MDT failed ========================================================== 15:53:06 (1786737186) [ 5021.192830] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing load_modules_local [ 5043.506605] Lustre: 150971:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 5071.073596] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5075.850856] Lustre: 152106:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 5089.873918] LustreError: 152251:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d sleeping for 3000ms [ 5092.937843] LustreError: 152251:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d awake [ 5092.977574] Lustre: Failing over lustre-MDT0001 [ 5092.995142] LustreError: lustre-MDT0001-osp-MDT0000: operation out_update to node 0@lo failed: rc = -107 [ 5093.004631] 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 [ 5093.015076] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 5094.880663] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 5094.889302] Lustre: Skipped 2 previous similar messages [ 5096.007186] LustreError: 152251:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d awake [ 5096.015385] LustreError: 152251:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) Skipped 1 previous similar message [ 5096.316965] Lustre: server umount lustre-MDT0001 complete [ 5111.243737] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 5111.774333] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 5111.785479] Lustre: Skipped 3 previous similar messages [ 5111.819255] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 5116.416499] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5116.898618] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 1 client reconnects [ 5116.908293] Lustre: lustre-MDT0001-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 5116.923027] Lustre: Skipped 1 previous similar message [ 5116.934409] Lustre: lustre-MDT0001: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 5117.016240] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:68 to 0x2c0000400:97) [ 5117.021103] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:71 to 0x280000400:97) [ 5126.218697] Lustre: DEBUG MARKER: == sanity-lfsck test 33: check LFSCK paramters =========== 15:55:06 (1786737306) [ 5141.011237] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing load_modules_local [ 5160.982041] Lustre: 154968:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 5185.350439] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5189.521516] Lustre: 156103:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 5191.737822] Lustre: 123792:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 5191.750763] Lustre: 123792:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 1222 previous similar messages [ 5191.763659] Lustre: 123792:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 5191.769319] Lustre: 123792:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1222 previous similar messages [ 5191.781803] Lustre: 123792:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 5191.798264] Lustre: 123792:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1222 previous similar messages [ 5191.821382] Lustre: 123792:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 5191.842149] Lustre: 123792:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1222 previous similar messages [ 5191.854042] Lustre: 123792:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 5191.861347] Lustre: 123792:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1222 previous similar messages [ 5191.872383] Lustre: 123792:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 5191.879929] Lustre: 123792:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1222 previous similar messages [ 5211.714716] Lustre: DEBUG MARKER: == sanity-lfsck test 34: LFSCK can rebuild the lost agent object ========================================================== 15:56:31 (1786737391) [ 5213.464232] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_34 Only valid for ZFS backend [ 5215.755530] Lustre: DEBUG MARKER: == sanity-lfsck test 35: LFSCK can rebuild the lost agent entry ========================================================== 15:56:35 (1786737395) [ 5223.505056] Lustre: *** cfs_fail_loc=1631, val=0*** [ 5239.776230] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 5239.779381] 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 [ 5239.789984] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5239.823770] Lustre: Skipped 4 previous similar messages [ 5241.604441] Lustre: server umount lustre-MDT0000 complete [ 5244.901299] LustreError: 123792: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. [ 5244.927835] LustreError: 123792:0:(ldlm_lib.c:1192:target_handle_connect()) Skipped 18 previous similar messages [ 5245.176937] LustreError: 156124:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1786737428 with bad export cookie 1726000539780491593 [ 5245.192758] LustreError: 156124:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 5245.202058] LustreError: MGC192.168.203.126@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5245.549250] Lustre: server umount lustre-MDT0001 complete [ 5259.370749] Lustre: server umount lustre-OST0000 complete [ 5273.565927] Lustre: server umount lustre-OST0001 complete [ 5291.028694] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing load_modules_local [ 5303.313426] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5309.161895] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5318.323087] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5326.390318] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5330.771490] Lustre: 159998:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 5339.762363] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5344.113592] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:71 to 0x280000400:129) [ 5346.157511] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5348.220087] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:540 to 0x280000401:577) [ 5354.598603] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5360.104935] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:68 to 0x2c0000400:129) [ 5360.111807] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:412 to 0x2c0000401:449) [ 5360.835184] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5368.113604] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5372.252175] Lustre: 161868:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 5381.479938] Lustre: DEBUG MARKER: == sanity-lfsck test 36a: rebuild LOV EA for mirrored file (1) ========================================================== 15:59:21 (1786737561) [ 5383.155226] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36a needs >= 3 OSTs [ 5385.052702] Lustre: DEBUG MARKER: == sanity-lfsck test 36b: rebuild LOV EA for mirrored file (2) ========================================================== 15:59:25 (1786737565) [ 5386.740893] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36b needs >= 3 OSTs [ 5388.323345] Lustre: DEBUG MARKER: == sanity-lfsck test 36c: rebuild LOV EA for mirrored file (3) ========================================================== 15:59:28 (1786737568) [ 5389.929138] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36c needs >= 3 OSTs [ 5391.539982] Lustre: DEBUG MARKER: == sanity-lfsck test 37: LFSCK must skip a ORPHAN ======== 15:59:31 (1786737571) [ 5404.890742] Lustre: DEBUG MARKER: == sanity-lfsck test 38: LFSCK does not break foreign file and reverse is also true ========================================================== 15:59:45 (1786737585) [ 5420.109893] Lustre: DEBUG MARKER: == sanity-lfsck test 39: LFSCK does not break foreign dir and reverse is also true ========================================================== 16:00:00 (1786737600) [ 5434.823919] Lustre: DEBUG MARKER: == sanity-lfsck test 40a: LFSCK correctly fixes lmm_oi in composite layout ========================================================== 16:00:14 (1786737614) [ 5450.075775] Lustre: DEBUG MARKER: == sanity-lfsck test 41: SEL support in LFSCK ============ 16:00:30 (1786737630) [ 5468.088765] Lustre: DEBUG MARKER: == sanity-lfsck test 42: LFSCK repairs inconsistent MDT-object/OST-object encryption flags ========================================================== 16:00:48 (1786737648) [ 5501.773694] Lustre: *** cfs_fail_loc=1632, val=0*** [ 5516.978921] Lustre: DEBUG MARKER: == sanity-lfsck test 43: LFSCK does not loop endlessly on iget failure in scanning-phase1 ========================================================== 16:01:37 (1786737697) [ 5520.702382] Lustre: Failing over lustre-MDT0001 [ 5521.167538] Lustre: server umount lustre-MDT0001 complete [ 5523.937368] 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 [ 5523.942284] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 5523.962791] Lustre: Skipped 3 previous similar messages [ 5528.883139] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5529.145805] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 5529.151274] Lustre: lustre-MDT0001: Aborting client recovery [ 5529.156849] LustreError: 165670:0:(ldlm_lib.c:3003:target_stop_recovery_thread()) lustre-MDT0001: Aborting recovery [ 5529.159095] Lustre: 165694:0:(ldlm_lib.c:2403:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 5529.168049] Lustre: 165694:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0001: disconnect stale client 69e0a341-4f81-494e-b391-6d330c5e48a6@ [ 5529.185867] Lustre: lustre-MDT0001: disconnecting 2 stale clients [ 5529.192812] Lustre: lustre-MDT0001-osd: cancel update llog [0x240000400:0x1:0x0] [ 5529.214167] Lustre: lustre-MDT0000-osp-MDT0001: cancel update llog [0x200000401:0x1:0x0] [ 5529.262191] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:131 to 0x2c0000400:161) [ 5529.274484] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:71 to 0x280000400:161) [ 5533.757996] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5534.191513] LustreError: lustre-MDT0001-osp-MDT0000: This client was evicted by lustre-MDT0001; in progress operations using this service will fail. [ 5534.210639] Lustre: lustre-MDT0001-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 5534.216637] Lustre: Skipped 3 previous similar messages [ 5537.817358] Lustre: *** cfs_fail_loc=1e2, val=483*** [ 5542.235930] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing wait_import_state FULL osp.lustre-MDT0001-os[pc]-MDT0000.*_server_uuid [ 5542.541940] Lustre: DEBUG MARKER: osp.lustre-MDT0001-os[pc]-MDT0000.*_server_uuid in FULL state after 0 sec [ 5549.310869] Lustre: DEBUG MARKER: == sanity-lfsck test 44: umount while lfsck is stopping == 16:02:09 (1786737729) [ 5558.149090] Lustre: *** cfs_fail_loc=1600, val=3*** [ 5560.777085] Lustre: Failing over lustre-MDT0000 [ 5560.979191] Lustre: server umount lustre-MDT0000 complete [ 5564.897066] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 5569.988501] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5570.135310] LustreError: MGC192.168.203.126@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5570.377516] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 5570.388216] Lustre: Skipped 2 previous similar messages [ 5574.572412] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5575.167150] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 5575.657185] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 5575.666707] Lustre: Skipped 1 previous similar message [ 5575.700097] Lustre: lustre-MDT0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 5575.753279] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:621 to 0x280000401:641) [ 5575.753759] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:489 to 0x2c0000401:513) [ 5584.035653] Lustre: DEBUG MARKER: == sanity-lfsck test 45: LFSCK should fix UID/GID/PROJID of OST object ========================================================== 16:02:44 (1786737764) [ 5610.278504] Lustre: Failing over lustre-OST0000 [ 5610.500523] Lustre: server umount lustre-OST0000 complete [ 5610.977237] LustreError: lustre-OST0000-osc-MDT0001: operation ost_statfs to node 0@lo failed: rc = -107 [ 5617.540664] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: (null) [ 5629.834628] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5630.056261] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 5630.061416] Lustre: Skipped 6 previous similar messages [ 5631.250557] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 5631.983054] Lustre: lustre-OST0000: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [ 5636.740071] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5643.901328] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing wait_import_state (FULL|IDLE) os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid 50 [ 5644.153471] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid in FULL state after 0 sec [ 5648.750235] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing wait_import_state (FULL|IDLE) os[cp].lustre-OST0000-osc-MDT0001.ost_server_uuid 50 [ 5649.005206] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0001.ost_server_uuid in FULL state after 0 sec [ 5654.966632] Lustre: DEBUG MARKER: oleg326-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0000-osc-ffff927a45213800.ost_server_uuid 50 [ 5656.972938] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff927a45213800.ost_server_uuid in FULL state after 0 sec [ 5719.009218] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 5719.014272] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5719.017094] Lustre: Skipped 3 previous similar messages [ 5724.837758] Lustre: server umount lustre-MDT0000 complete [ 5732.059541] LustreError: 158839:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1786737914 with bad export cookie 1726000539780574403 [ 5732.059896] LustreError: MGC192.168.203.126@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5732.068361] LustreError: 158839:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 5732.283046] Lustre: server umount lustre-MDT0001 complete [ 5749.023187] Lustre: 106681:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786737915/real 1786737915] req@ffff977858d36680 x1873528320145280/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786737931 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5753.313689] Lustre: 106679:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786737920/real 1786737920] req@ffff977858d34e00 x1873528320145664/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786737936 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5753.373597] Lustre: server umount lustre-OST0000 complete [ 5758.431114] Lustre: 106680:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786737925/real 1786737925] req@ffff97787f22df80 x1873528320145920/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786737941 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5762.658662] Lustre: server umount lustre-OST0001 complete [ 5780.688103] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing unload_modules_local [ 5783.479387] Key type lgssc unregistered [ 5783.770943] LNet: 174803:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 5783.782309] LNetError: 174803:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 5783.797349] LNet: Removed LNI 192.168.203.126@tcp [ 5784.714134] Key type .llcrypt unregistered [ 5784.722842] Key type ._llcrypt unregistered [ 5810.741319] Key type ._llcrypt registered [ 5810.745793] Key type .llcrypt registered [ 5810.951549] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_hostid [ 5830.380185] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing load_modules_local [ 5831.418709] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 5831.504717] alg: No test for adler32 (adler32-zlib) [ 5832.568691] Lustre: Lustre: Build Version: 2.17.56_2_gd9f03f2 [ 5832.803623] LNet: Added LNI 192.168.203.126@tcp [8/256/0/180] [ 5834.495156] Key type lgssc registered [ 5835.900898] Lustre: Echo OBD driver; http://www.lustre.org/ [ 5885.470502] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing load_modules_local [ 5898.382336] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 5898.421701] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5899.739275] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 5899.781933] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 5899.888773] Lustre: lustre-MDT0000: new disk, initializing [ 5899.968627] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 5900.009466] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 5904.248706] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5917.346176] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5917.471628] Lustre: 179265: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 [ 5917.496698] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 5917.501419] Lustre: Skipped 1 previous similar message [ 5917.594759] Lustre: lustre-MDT0001: new disk, initializing [ 5917.671037] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 5917.698302] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 5917.712649] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 5921.776956] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5926.656984] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 5938.250808] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5938.592557] Lustre: lustre-OST0000: new disk, initializing [ 5938.598931] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 5938.614482] Lustre: 181202:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 5938.752543] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 5946.830302] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5948.470326] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 5948.482406] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 5948.601333] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 5960.951120] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5961.106710] Lustre: lustre-OST0001: new disk, initializing [ 5961.109917] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 5961.116366] Lustre: 182228:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 5961.210737] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 5966.908657] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 5966.913668] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 5967.041526] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 5968.596400] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5978.340035] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5989.324973] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 5995.433984] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 16:09:35 (1786738175) === [ 5997.058590] Lustre: DEBUG MARKER: == sanity-lfsck test complete, duration 5687 sec ========= 16:09:37 (1786738177) [ 5998.926498] Lustre: DEBUG MARKER: === sanity-lfsck: start cleanup 16:09:39 (1786738179) === [ 6002.738493] Lustre: DEBUG MARKER: === sanity-lfsck: finish cleanup 16:09:42 (1786738182) === [ 6008.292336] 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 [ 6008.307398] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 6008.317920] Lustre: Skipped 3 previous similar messages [ 6008.332158] Lustre: Skipped 3 previous similar messages [ 6013.408413] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 6013.419126] Lustre: Skipped 1 previous similar message [ 6014.319976] Lustre: server umount lustre-MDT0000 complete [ 6022.577781] LustreError: 180224:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1786738205 with bad export cookie 3411615252104488402 [ 6022.580159] LustreError: MGC192.168.203.126@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 6022.599759] LustreError: 180224:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 6023.024815] Lustre: server umount lustre-MDT0001 complete [ 6039.775956] Lustre: 176428:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786738206/real 1786738206] req@ffff977847461880 x1873530600900608/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786738222 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6039.810528] 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 [ 6040.998877] Lustre: server umount lustre-OST0000 complete [ 6043.872758] Lustre: 176429:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786738210/real 1786738210] req@ffff977749ed6300 x1873530600900864/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786738226 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6048.224651] Lustre: 176430:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786738215/real 1786738215] req@ffff977749ed5500 x1873530600901504/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786738231 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6048.262146] Lustre: 176430:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 6049.325249] Lustre: server umount lustre-OST0001 complete [ 6065.504993] Lustre: DEBUG MARKER: oleg326-server.virtnet: executing unload_modules_local [ 6068.005702] Key type lgssc unregistered [ 6068.227597] LNet: 185705:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 6068.233564] LNetError: 185705:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 6068.248331] LNet: Removed LNI 192.168.203.126@tcp [ 6069.119249] Key type .llcrypt unregistered [ 6069.122097] Key type ._llcrypt unregistered