[ 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 597984155 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2399.998 MHz processor [ 0.000000] last_pfn = 0x146e00 max_arch_pfn = 0x400000000 [ 0.000000] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT [ 0.000000] last_pfn = 0xbffce max_arch_pfn = 0x400000000 [ 0.000000] found SMP MP-table at [mem 0x000f54b0-0x000f54bf] [ 0.000000] RAMDISK: [mem 0xbcc54000-0xbffbffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F52D0 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE247C 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE2318 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 0022D8 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE238C 000090 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE241C 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE2454 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe2318-0xbffe238b] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe2317] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe238c-0xbffe241b] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe241c-0xbffe2453] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe2454-0xbffe247b] [ 0.000000] No NUMA configuration found [ 0.000000] Faking a node at [mem 0x0000000000000000-0x0000000146dfffff] [ 0.000000] NODE_DATA(0) allocated [mem 0x1465a3000-0x1465cdfff] [ 0.000000] Reserving 256MB of memory at 2752MB for crashkernel (System RAM: 4205MB) [ 0.000000] Zone ranges: [ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.000000] DMA32 [mem 0x0000000001000000-0x00000000ffffffff] [ 0.000000] Normal [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Device empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff] [ 0.000000] node 0: [mem 0x0000000000100000-0x00000000bffcdfff] [ 0.000000] node 0: [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Zeroed struct page in unavailable ranges: 4756 pages [ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x0000000146dfffff] [ 0.000000] ACPI: PM-Timer IO Port: 0x608 [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) [ 0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) [ 0.000000] Using ACPI (MADT) for SMP configuration information [ 0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000] TSC deadline timer available [ 0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs [ 0.000000] kvm-guest: KVM setup pv remote TLB flush [ 0.000000] kvm-guest: setup PV sched yield [ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff] [ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff] [ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff] [ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff] [ 0.000000] PM: Registered nosave memory: [mem 0xbffce000-0xbfffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xc0000000-0xfeffbfff] [ 0.000000] PM: Registered nosave memory: [mem 0xfeffc000-0xfeffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xff000000-0xfffbffff] [ 0.000000] PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff] [ 0.000000] [mem 0xc0000000-0xfeffbfff] available for PCI devices [ 0.000000] Booting paravirtualized kernel on KVM [ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns [ 0.000000] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1 [ 0.000000] percpu: Embedded 63 pages/cpu s221184 r8192 d28672 u524288 [ 0.000000] kvm-guest: PV spinlocks enabled [ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1059606 [ 0.000000] Policy zone: Normal [ 0.000000] Kernel command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] Specific versions of hardware are certified with Red Hat Enterprise Linux 8. Please see the list of hardware certified with Red Hat Enterprise Linux 8 at https://catalog.redhat.com. [ 0.000000] audit: disabled (until reboot) [ 0.000000] software IO TLB: area num 4. [ 0.000000] Memory: 2829652K/4306352K available (18435K kernel code, 11221K rwdata, 7248K rodata, 2908K init, 18040K bss, 524580K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] ftrace: allocating 41240 entries in 162 pages [ 0.000000] ftrace: allocated 162 pages with 3 groups [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] rcu: RCU event tracing is enabled. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ 0.000000] rcu: RCU callback double-/use-after-free debug enabled. [ 0.000000] Rude variant of Tasks RCU enabled. [ 0.000000] Tracing variant of Tasks RCU enabled. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 0.000000] NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16 [ 0.000000] random: get_random_bytes called from start_kernel+0x622/0x9a8 with crng_init=0 [ 0.001000] Console: colour *CGA 80x25 [ 0.001000] printk: console [ttyS1] enabled [ 0.001000] ACPI: Core revision 20220331 [ 0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.001012] APIC: Switch to symmetric I/O mode setup [ 0.002333] x2apic enabled [ 0.003010] Switched APIC routing to physical x2apic. [ 0.004013] kvm-guest: setup PV IPIs [ 0.007000] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.007000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.007018] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.008010] pid_max: default: 32768 minimum: 301 [ 0.009201] LSM: Security Framework initializing [ 0.010047] Yama: becoming mindful. [ 0.011030] SELinux: Initializing. [ 0.012062] *** VALIDATE selinux *** [ 0.020020] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.025232] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.027076] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.029092] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.031085] *** VALIDATE tmpfs *** [ 0.032478] *** VALIDATE proc *** [ 0.033194] *** VALIDATE cgroup *** [ 0.034000] *** VALIDATE cgroup2 *** [ 0.034238] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.036081] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.037006] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.038025] Spectre V2 : User space: Vulnerable [ 0.039006] Speculative Store Bypass: Vulnerable [ 0.042248] debug: unmapping init [mem 0xffffffffa0059000-0xffffffffa0060fff] [ 0.044873] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.045641] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.046019] ... version: 2 [ 0.047009] ... bit width: 48 [ 0.048008] ... generic registers: 4 [ 0.049008] ... value mask: 0000ffffffffffff [ 0.050012] ... max period: 00007fffffffffff [ 0.051012] ... fixed-purpose events: 3 [ 0.052012] ... event mask: 000000070000000f [ 0.053265] rcu: Hierarchical SRCU implementation. [ 0.055411] smp: Bringing up secondary CPUs ... [ 0.056543] x86: Booting SMP configuration: [ 0.057025] .... node #0, CPUs: #1 #2 #3 [ 0.060410] smp: Brought up 1 node, 4 CPUs [ 0.062010] smpboot: Max logical packages: 1 [ 0.063014] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.135396] node 0 deferred pages initialised in 68ms [ 0.140188] devtmpfs: initialized [ 0.142398] x86/mm: Memory block size: 128MB [ 0.150128] gcov: version magic: 0x41383552 [ 0.153275] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.154078] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.157246] pinctrl core: initialized pinctrl subsystem [ 0.159151] [ 0.159748] ************************************************************* [ 0.162012] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.164009] ** ** [ 0.166011] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.169011] ** ** [ 0.171009] ** This means that this kernel is built to expose internal ** [ 0.174011] ** IOMMU data structures, which may compromise security on ** [ 0.177010] ** your system. ** [ 0.179010] ** ** [ 0.182064] ** If you see this message and you are not debugging the ** [ 0.185012] ** kernel, report this immediately to your vendor! ** [ 0.187013] ** ** [ 0.190009] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.193013] ************************************************************* [ 0.196212] NET: Registered protocol family 16 [ 0.200716] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.204127] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.207059] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.210373] cpuidle: using governor menu [ 0.212568] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.215722] PCI: Using configuration type 1 for base access [ 0.219146] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.227100] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.228017] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.233424] cryptd: max_cpu_qlen set to 1000 [ 0.235329] ACPI: Added _OSI(Module Device) [ 0.236094] ACPI: Added _OSI(Processor Device) [ 0.238009] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.239025] ACPI: Added _OSI(Processor Aggregator Device) [ 0.246028] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.253589] ACPI: Interpreter enabled [ 0.255051] ACPI: PM: (supports S0 S3 S4 S5) [ 0.257012] ACPI: Using IOAPIC for interrupt routing [ 0.258085] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.262529] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.275760] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.278040] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.281015] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.285086] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.291883] acpiphp: Slot [2] registered [ 0.294102] acpiphp: Slot [5] registered [ 0.295098] acpiphp: Slot [6] registered [ 0.297111] acpiphp: Slot [7] registered [ 0.299152] acpiphp: Slot [8] registered [ 0.300111] acpiphp: Slot [9] registered [ 0.302089] acpiphp: Slot [10] registered [ 0.304109] acpiphp: Slot [3] registered [ 0.305115] acpiphp: Slot [4] registered [ 0.306106] acpiphp: Slot [11] registered [ 0.308140] acpiphp: Slot [12] registered [ 0.309144] acpiphp: Slot [13] registered [ 0.310292] acpiphp: Slot [14] registered [ 0.312115] acpiphp: Slot [15] registered [ 0.314116] acpiphp: Slot [16] registered [ 0.317114] acpiphp: Slot [17] registered [ 0.318095] acpiphp: Slot [18] registered [ 0.320220] acpiphp: Slot [19] registered [ 0.323130] acpiphp: Slot [20] registered [ 0.325174] acpiphp: Slot [21] registered [ 0.327109] acpiphp: Slot [22] registered [ 0.329181] acpiphp: Slot [23] registered [ 0.331108] acpiphp: Slot [24] registered [ 0.333135] acpiphp: Slot [25] registered [ 0.335077] acpiphp: Slot [26] registered [ 0.337090] acpiphp: Slot [27] registered [ 0.339182] acpiphp: Slot [28] registered [ 0.341096] acpiphp: Slot [29] registered [ 0.343144] acpiphp: Slot [30] registered [ 0.345091] acpiphp: Slot [31] registered [ 0.346069] PCI host bridge to bus 0000:00 [ 0.348016] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.350019] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.352026] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.353000] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.355024] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.358023] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.361187] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.364666] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.368529] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.379973] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.386112] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.389071] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.392065] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.398022] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.401768] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.404285] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.408040] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.412160] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.420016] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.436014] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.442015] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.448637] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.463012] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.473013] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.505013] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.522439] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.542025] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.556013] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.596014] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.609740] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.619014] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.628014] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.655010] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.670086] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.682034] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.693021] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.722016] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.738196] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.751007] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.766014] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.792017] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 0.809000] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.822014] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.836015] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.865012] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 0.885762] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.888383] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.892736] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.896443] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.900207] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.907085] iommu: Default domain type: Passthrough [ 0.908000] SCSI subsystem initialized [ 0.908000] ACPI: bus type USB registered [ 0.909083] usbcore: registered new interface driver usbfs [ 0.912096] usbcore: registered new interface driver hub [ 0.914068] usbcore: registered new device driver usb [ 0.916134] pps_core: LinuxPPS API ver. 1 registered [ 0.919012] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.922071] PTP clock support registered [ 0.924356] EDAC MC: Ver: 3.0.0 [ 0.925271] PCI: Using ACPI for IRQ routing [ 0.926383] NetLabel: Initializing [ 0.927000] NetLabel: domain hash size = 128 [ 0.929008] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.931073] NetLabel: unlabeled traffic allowed by default [ 0.934252] vgaarb: loaded [ 0.936632] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.937007] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.944918] clocksource: Switched to clocksource kvm-clock [ 1.100434] VFS: Disk quotas dquot_6.6.0 [ 1.102557] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 1.105437] *** VALIDATE ramfs *** [ 1.106671] *** VALIDATE hugetlbfs *** [ 1.108405] pnp: PnP ACPI init [ 1.110724] pnp: PnP ACPI: found 6 devices [ 1.128180] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 1.133301] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 1.136582] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 1.139735] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 1.142644] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 1.145818] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 1.150091] NET: Registered protocol family 2 [ 1.154330] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 1.161796] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 1.165953] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 1.172733] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 1.176259] TCP: Hash tables configured (established 65536 bind 65536) [ 1.180285] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 1.185195] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 1.188762] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 1.196512] NET: Registered protocol family 1 [ 1.200092] RPC: Registered named UNIX socket transport module. [ 1.203314] RPC: Registered udp transport module. [ 1.205080] RPC: Registered tcp transport module. [ 1.207193] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 1.210348] NET: Registered protocol family 44 [ 1.213741] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 1.216920] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 1.220558] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 1.223816] PCI: CLS 0 bytes, default 64 [ 1.226215] Unpacking initramfs... [ 3.015421] debug: unmapping init [mem 0xffff9a8e3cc54000-0xffff9a8e3ffbffff] [ 3.020320] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 3.022534] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 3.026197] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 3.652591] Initialise system trusted keyrings [ 3.655430] Key type blacklist registered [ 3.657401] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 3.671762] zbud: loaded [ 3.675353] *** VALIDATE nfs *** [ 3.676836] *** VALIDATE nfs4 *** [ 3.679415] pstore: using deflate compression [ 3.684361] Platform Keyring initialized [ 3.819535] NET: Registered protocol family 38 [ 3.823978] Key type asymmetric registered [ 3.827578] Asymmetric key parser 'x509' registered [ 3.831550] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 3.838020] io scheduler mq-deadline registered [ 3.840926] io scheduler kyber registered [ 3.843895] io scheduler bfq registered [ 3.846800] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 3.850753] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 3.859488] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 3.863870] ACPI: Power Button [PWRF] [ 3.872103] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 3.883502] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 3.906472] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 3.917674] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 3.942418] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 3.975390] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 4.008024] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 4.013648] Non-volatile memory driver v1.3 [ 4.015112] Linux agpgart interface v0.103 [ 4.057819] virtio_blk virtio1: [vda] 146864 512-byte logical blocks (75.2 MB/71.7 MiB) [ 4.062713] vda: detected capacity change from 0 to 75194368 [ 4.089063] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 4.092838] vdb: detected capacity change from 0 to 1073741824 [ 4.113718] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 4.117215] vdc: detected capacity change from 0 to 2621440000 [ 4.141103] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 4.144412] vdd: detected capacity change from 0 to 2621440000 [ 4.168109] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 4.171466] vde: detected capacity change from 0 to 4294967296 [ 4.193517] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 4.199813] vdf: detected capacity change from 0 to 4294967296 [ 4.208278] libphy: Fixed MDIO Bus: probed [ 4.223150] usbcore: registered new interface driver usbserial_generic [ 4.228949] usbserial: USB Serial support registered for generic [ 4.236929] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 4.244825] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 4.251483] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 4.254224] mousedev: PS/2 mouse device common for all mice [ 4.259421] rtc_cmos 00:05: RTC can wake from S4 [ 4.265236] rtc_cmos 00:05: registered as rtc0 [ 4.268872] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 4.272044] intel_pstate: CPU model not supported [ 4.272260] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 4.282341] hid: raw HID events driver (C) Jiri Kosina [ 4.289264] usbcore: registered new interface driver usbhid [ 4.292551] usbhid: USB HID core driver [ 4.294403] drop_monitor: Initializing network drop monitor service [ 4.295403] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 4.300958] Initializing XFRM netlink socket [ 4.301476] NET: Registered protocol family 10 [ 4.305843] Segment Routing with IPv6 [ 4.309878] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 4.313707] NET: Registered protocol family 17 [ 4.320691] mpls_gso: MPLS GSO support [ 4.327201] RAS: Correctable Errors collector initialized. [ 4.329412] AVX version of gcm_enc/dec engaged. [ 4.331230] AES CTR mode by8 optimization enabled [ 4.426132] sched_clock: Marking stable (4426025095, 0)->(5448480499, -1022455404) [ 4.430202] registered taskstats version 1 [ 4.432429] Loading compiled-in X.509 certificates [ 4.434637] zswap: loaded using pool lzo/zbud [ 4.463335] Key type big_key registered [ 4.477368] Key type encrypted registered [ 4.478954] ima: No TPM chip found, activating TPM-bypass! [ 4.481787] ima: Allocated hash algorithm: sha1 [ 4.483784] ima: No architecture policies found [ 4.489512] evm: Initialising EVM extended attributes: [ 4.492099] evm: security.selinux [ 4.496309] evm: security.ima [ 4.499696] evm: security.capability [ 4.504297] evm: HMAC attrs: 0x1 [ 4.508656] rtc_cmos 00:05: setting system clock to 2026-08-27 16:51:50 UTC (1787849510) [ 4.523694] debug: unmapping init [mem 0xffffffffa1003000-0xffffffffa11fffff] [ 4.529557] debug: unmapping init [mem 0xffffffff9fd82000-0xffffffffa0058fff] [ 4.540316] Write protecting the kernel read-only data: 28672k [ 4.546168] debug: unmapping init [mem 0xffffffff9e403000-0xffffffff9e5fffff] [ 4.550654] debug: unmapping init [mem 0xffffffff9ed14000-0xffffffff9edfffff] [ 4.587941] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 4.598318] systemd[1]: Detected virtualization kvm. [ 4.600744] systemd[1]: Detected architecture x86-64. [ 4.603297] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 4.641624] systemd[1]: No hostname configured. [ 4.644475] systemd[1]: Set hostname to . [ 4.646623] random: systemd: uninitialized urandom read (16 bytes read) [ 4.649074] systemd[1]: Initializing machine ID from random generator. [ 4.740230] random: ln: uninitialized urandom read (6 bytes read) [ 4.883977] random: systemd: uninitialized urandom read (16 bytes read) [ 4.887939] systemd[1]: Listening on Journal Socket (/dev/log). [ OK ] Listening on Journal Socket (/dev/log). [ 4.893661] systemd[1]: Reached target Timers. [ OK ] Reached target Timers. [ 4.897632] systemd[1]: Reached target Initrd Root Device. [ OK ] Reached target Initrd Root Device. [ OK ] Reached target Swap. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. [ OK ] Listening on udev Control Socket. [ OK ] Listening on Journal Socket. [ OK ] Reached target Local File Systems. Starting Create Volatile Files and Directories... [ OK ] Started Memstrack Anylazing Service. Starting Setup Virtual Console... Starting Journal Service... Starting Apply Kernel Variables... [ OK ] Reached target Slices. [ OK ] Listening on udev Kernel Socket. [ OK ] Reached target Sockets. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Setup Virtual Console. [ OK ] Started Apply Kernel Variables. [ OK ] Started Create list of required sta…vice nodes for the current kernel. Starting Create Static Device Nodes in /dev... Starting dracut cmdline hook... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started Journal Service. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 5.737867] device-mapper: uevent: version 1.0.3 [ 5.741263] device-mapper: ioctl: 4.46.0-ioctl (2022-02-22) initialised: dm-devel@redhat.com [ OK ] Started dracut pre-udev hook. Starting udev Kernel Device Manager... [ OK ] Started udev Kernel Device Manager. Starting dracut pre-trigger hook... [ OK ] Started dracut pre-trigger hook. Starting udev Coldplug all Devices... Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. Starting dracut initqueue hook... [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ 6.794854] virtio_net virtio0 ens2: renamed from eth0 [ 6.818996] random: fast init done [ 7.249926] scsi host0: ata_piix [ 7.353182] scsi host1: ata_piix [ 7.369562] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 7.375414] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 12.014624] random: crng init done [ 12.018664] random: 7 urandom warning(s) missed due to ratelimiting [ 12.212208] dracut-initqueue[583]: RTNETLINK answers: File exists Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. Mounting /sysroot... [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. [ 13.733676] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped dracut initqueue hook. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped target Timers. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Paths. [ OK ] Stopped target System Initialization. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. Stopping udev Kernel Device Manager... [ OK ] Stopped target Swap. [ OK ] Stopped target Slices. [ OK ] Stopped target Sockets. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ 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 Kernel Socket. [ OK ] Closed udev Control Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 15.587756] printk: systemd: 26 output lines suppressed due to ratelimiting [ 15.995723] SELinux: Disabled at runtime. [ 16.067150] 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) [ 16.082898] systemd[1]: Detected virtualization kvm. [ 16.085564] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 16.890429] systemd[1]: initrd-switch-root.service: Succeeded. [ 16.893629] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 16.898728] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 16.906588] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 16.912413] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 16.924274] systemd[1]: Starting Journal Service... Starting Journal Service... [ 16.936872] systemd[1]: proc-sys-fs-binfmt_misc.automount: Refusing to start, unit to trigger not loaded. [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Created slice system-getty.slice. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Created slice User and Session Slice. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Listening on Process Core Dump Socket. [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Reached target Local Encrypted Volumes. Mounting Kernel Debug File System... [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd File Systems. [ OK ] Reached target rpc_pipefs.target. [ OK ] Reached target Paths. Mounting Huge Pages File System... [ OK ] Reached target Slices. [ OK ] Stopped target Initrd Root File System. [ OK ] Listening on udev Kernel Socket. Starting Remount Root and Kernel File Systems... [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Listening on initctl Compatibility Named Pipe. Activating swap /dev/disk/by-label/SWAP... Mounting POSIX Message Queue File System... [ 17.206362] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS [ OK ] Reached target RPC Port Mapper. [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Listening on udev Control Socket. Starting Apply Kernel Variables... [ OK ] Created slice system-sshd\x2dkeygen.slice. Starting udev Coldplug all Devices... [ OK ] Started Journal Service. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Mounted Kernel Debug File System. [ OK ] Mounted Huge Pages File System. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Started Apply Kernel Variables. [ OK ] Reached target Swap. Starting Configure read-only root support... Starting Create Static Device Nodes in /dev... Starting Flush Journal to Persistent Storage... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Reached target Local File Systems (Pre). Mounting /home/green/git/lustre-release... Mounting /mnt... Starting udev Kernel Device Manager... [ OK ] Mounted /mnt. [ 17.823505] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Started udev Coldplug all Devices. [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 18.500780] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 18.538318] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 18.918672] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 18.972716] EDAC sbridge: Ver: 1.1.2 [ 23.329703] Key type dns_resolver registered [* ] A start job is running for Configur…-only root support (6s / no limit) [** ] A start job is running for Configur…-only root support (7s / no limit)[ 24.145457] NFS: Registering the id_resolver key type [ 24.148643] Key type id_resolver registered [ 24.154642] Key type id_legacy registered [*** ] A start job is running for Configur…-only root support (7s / no limit) [ *** ] A start job is running for Configur…-only root support (8s / no limit) [ OK ] Started Configure read-only root support. Starting Load/Save Random Seed... [ OK ] Reached target Local File Systems. Starting Mark the need to relabel after reboot... Starting Create Volatile Files and Directories... Starting Rebuild Dynamic Linker Cache... [ OK ] Started Load/Save Random Seed. [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Create Volatile Files and Directories. Starting RPC Bind... Starting Update UTMP about System Boot/Shutdown... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Started dnf makecache --timer. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. [ OK ] Started D-Bus System Message Bus. Starting Network Manager... [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Started irqbalance daemon. Starting Restore /run/initramfs on shutdown... Starting Login Service... [ OK ] Reached target sshd-keygen.target. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Reached target Timers. [ 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 Login Service. [ OK ] Started Permit User Sessions. [ OK ] Started Getty on tty1. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Serial Getty on ttyS1. [ OK ] Reached target Login Prompts. [ OK ] Started Command Scheduler. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting Notify NFS peers of a restart... Starting Crash recovery kernel arming... Starting System Logging Service... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Starting Authorization Manager... Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg611-server login: [ 87.485977] libcfs: loading out-of-tree module taints kernel. [ 87.525842] Key type ._llcrypt registered [ 87.528489] Key type .llcrypt registered [ 87.622769] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_hostid [ 105.304626] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing load_modules_local [ 107.319445] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 107.346322] alg: No test for adler32 (adler32-zlib) [ 108.816804] Lustre: Lustre: Build Version: 2.17.57_85_gfc6b239 [ 109.747442] LNet: Added LNI 192.168.206.111@tcp [8/256/0/180] [ 111.554247] Key type lgssc registered [ 113.224789] Lustre: Echo OBD driver; http://www.lustre.org/ [ 129.984633] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 168.198524] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing load_modules_local [ 180.746232] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 180.799554] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 182.026367] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 182.051893] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 182.153655] Lustre: lustre-MDT0000: new disk, initializing [ 182.222660] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 182.255142] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 186.975320] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 200.670541] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 200.778396] Lustre: 6521: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 [ 200.808987] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 200.812131] Lustre: Skipped 1 previous similar message [ 200.885727] Lustre: lustre-MDT0001: new disk, initializing [ 200.929783] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 200.969091] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 200.986414] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 204.772132] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 209.086217] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 215.691016] hrtimer: interrupt took 5933988 ns [ 218.239080] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 218.473828] Lustre: lustre-OST0000: new disk, initializing [ 218.477451] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 218.486896] Lustre: 8460:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 218.537155] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 220.882506] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 220.892878] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 220.934390] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 225.147591] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 239.185703] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 239.341448] Lustre: lustre-OST0001: new disk, initializing [ 239.346719] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 239.353766] Lustre: 9535:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 239.445923] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 246.129599] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 247.313351] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 247.339908] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 247.394720] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 258.300930] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 265.987885] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 273.559825] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing check_logdir /tmp/testlogs/ [ 279.096922] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing yml_node [ 283.895570] Lustre: DEBUG MARKER: Client: 2.17.57.85 [ 286.570379] Lustre: DEBUG MARKER: MDS: 2.17.57.85 [ 288.875550] Lustre: DEBUG MARKER: OSS: 2.17.57.85 [ 290.548303] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity-lfsck ============----- Thu Aug 27 12:56:34 EDT 2026 [ 306.569588] Lustre: DEBUG MARKER: excepting tests: 18b 23b [ 316.141367] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing load_modules_local [ 324.066455] 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 [ 324.083523] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 324.086398] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 324.101905] Lustre: Skipped 3 previous similar messages [ 329.189234] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 329.201706] Lustre: Skipped 3 previous similar messages [ 329.412489] Lustre: server umount lustre-MDT0000 complete [ 337.501719] LustreError: 6515:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787849843 with bad export cookie 5094296239368094885 [ 337.502986] LustreError: MGC192.168.206.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 337.516640] LustreError: 6515:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 337.927461] Lustre: server umount lustre-MDT0001 complete [ 355.254666] Lustre: server umount lustre-OST0000 complete [ 355.809185] Lustre: 3657:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787849845/real 1787849845] req@ffff9a8d83f40b40 x1874696197996160/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787849861 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 355.841072] 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 [ 355.850361] Lustre: Skipped 3 previous similar messages [ 358.368275] Lustre: 3654:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787849848/real 1787849848] req@ffff9a8d84150b40 x1874696197996416/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787849864 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 360.991186] Lustre: 3657:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787849850/real 1787849850] req@ffff9a8e9bb2a580 x1874696197996672/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787849866 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 362.176622] Lustre: server umount lustre-OST0001 complete [ 375.635068] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing unload_modules_local [ 378.348474] Key type lgssc unregistered [ 378.548103] LNet: 14808:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 378.557211] LNetError: 14808:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 378.576718] LNet: Removed LNI 192.168.206.111@tcp [ 379.419430] Key type .llcrypt unregistered [ 379.421086] Key type ._llcrypt unregistered [ 399.711291] Key type ._llcrypt registered [ 399.713268] Key type .llcrypt registered [ 399.819646] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_hostid [ 413.340419] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing load_modules_local [ 414.236315] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 414.311076] alg: No test for adler32 (adler32-zlib) [ 415.351980] Lustre: Lustre: Build Version: 2.17.57_85_gfc6b239 [ 415.566735] LNet: Added LNI 192.168.206.111@tcp [8/256/0/180] [ 417.247155] Key type lgssc registered [ 418.409193] Lustre: Echo OBD driver; http://www.lustre.org/ [ 466.028407] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing load_modules_local [ 478.653861] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 478.684730] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 479.934770] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 479.961814] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 480.053994] Lustre: lustre-MDT0000: new disk, initializing [ 480.117364] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 480.135946] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 484.979926] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 498.892116] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 499.023879] Lustre: 19273: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 [ 499.059894] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 499.063436] Lustre: Skipped 1 previous similar message [ 499.114241] Lustre: lustre-MDT0001: new disk, initializing [ 499.173776] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 499.219439] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 499.230881] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 504.118033] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 508.847753] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 518.150685] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 518.463805] Lustre: lustre-OST0000: new disk, initializing [ 518.468439] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 518.474878] Lustre: 21211:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 518.533780] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 519.697924] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 519.709589] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 519.761961] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 524.195939] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 535.811101] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 535.917984] Lustre: lustre-OST0001: new disk, initializing [ 535.921517] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 535.927860] Lustre: 22235:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 535.976137] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 541.577635] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 545.296370] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 545.308094] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 545.352421] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 552.101536] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 558.514082] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 567.145975] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 13:01:11 (1787850071) === [ 569.711989] Lustre: DEBUG MARKER: == sanity-lfsck test 0: Control LFSCK manually =========== 13:01:14 (1787850074) [ 569.920584] Lustre: 19281:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 251 < left 278, rollback = 2 [ 569.929112] Lustre: 19281:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 569.936755] Lustre: 19281:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 569.945657] Lustre: 19281:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 569.956686] Lustre: 19281:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 569.962033] Lustre: 19281:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 570.456403] Lustre: 19282:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 570.471160] Lustre: 19282:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 14 previous similar messages [ 570.483131] Lustre: 19282:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 570.492257] Lustre: 19282:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 14 previous similar messages [ 570.500669] Lustre: 19282:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 570.506655] Lustre: 19282:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 14 previous similar messages [ 570.511959] Lustre: 19282:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 570.519387] Lustre: 19282:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 14 previous similar messages [ 570.524686] Lustre: 19282:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 570.533650] Lustre: 19282:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 14 previous similar messages [ 570.540284] Lustre: 19282:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 570.548626] Lustre: 19282:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 14 previous similar messages [ 571.474176] Lustre: 22162:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 571.484017] Lustre: 22162:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 59 previous similar messages [ 571.489342] Lustre: 22162:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 571.494824] Lustre: 22162:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 59 previous similar messages [ 571.571848] Lustre: 19280:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 571.584045] Lustre: 19280:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 62 previous similar messages [ 571.598676] Lustre: 19280:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 571.610762] Lustre: 19280:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 62 previous similar messages [ 571.632165] Lustre: 19280:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 571.644949] Lustre: 19280:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 62 previous similar messages [ 571.653452] Lustre: 19280:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 571.662794] Lustre: 19280:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 62 previous similar messages [ 573.513166] Lustre: 19281:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 573.523473] Lustre: 19281:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 95 previous similar messages [ 573.528537] Lustre: 19281:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 573.535449] Lustre: 19281:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 95 previous similar messages [ 573.642312] Lustre: 22162:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 573.648663] Lustre: 22162:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 95 previous similar messages [ 573.659650] Lustre: 22162:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 573.669927] Lustre: 22162:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 95 previous similar messages [ 573.679847] Lustre: 22162:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 573.693537] Lustre: 22162:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 95 previous similar messages [ 573.707114] Lustre: 22162:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 573.724837] Lustre: 22162:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 95 previous similar messages [ 577.521979] Lustre: *** cfs_fail_loc=1600, val=3*** [ 580.473869] Lustre: 21202:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-OST0001: opcode 2: before 259 < left 274, rollback = 2 [ 580.476273] Lustre: 23438:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 580.490143] Lustre: 21202:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 109 previous similar messages [ 580.490167] Lustre: 21202:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/1, xattr_set: 2/274/0 [ 580.490171] Lustre: 21202:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 105 previous similar messages [ 580.490178] Lustre: 21202:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 0/0/0, punch: 0/0/0, quota 7/225/0 [ 580.490180] Lustre: 21202:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 105 previous similar messages [ 580.490185] Lustre: 21202:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 580.490199] Lustre: 21202:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 105 previous similar messages [ 580.490204] Lustre: 21202:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 580.490207] Lustre: 21202:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 105 previous similar messages [ 580.616285] Lustre: 23438:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 116 previous similar messages [ 582.645033] Lustre: *** cfs_fail_loc=1600, val=3*** [ 594.163601] Lustre: 23684:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 259 < left 274, rollback = 2 [ 594.178212] Lustre: 23684:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 63 previous similar messages [ 594.184626] Lustre: 23676:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 594.187218] Lustre: 23684:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/1, xattr_set: 2/274/0 [ 594.187227] Lustre: 23684:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 64 previous similar messages [ 594.187234] Lustre: 23684:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 0/0/0, punch: 0/0/0, quota 7/225/0 [ 594.187238] Lustre: 23684:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 64 previous similar messages [ 594.187244] Lustre: 23684:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 594.187247] Lustre: 23684:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 64 previous similar messages [ 594.187252] Lustre: 23684:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 594.187255] Lustre: 23684:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 64 previous similar messages [ 594.265226] Lustre: 23676:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 57 previous similar messages [ 596.448833] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 596.450736] 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 [ 596.462449] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 596.469631] Lustre: Skipped 3 previous similar messages [ 596.484636] Lustre: Skipped 3 previous similar messages [ 601.569645] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 601.590035] Lustre: Skipped 3 previous similar messages [ 602.509491] Lustre: server umount lustre-MDT0000 complete [ 605.928167] LustreError: 19265:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787850111 with bad export cookie 1262541208078342121 [ 605.937058] LustreError: MGC192.168.206.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 605.941036] LustreError: 19265:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 606.336557] Lustre: server umount lustre-MDT0001 complete [ 620.495350] Lustre: server umount lustre-OST0000 complete [ 622.047170] Lustre: 16435:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787850112/real 1787850112] req@ffff9a8d8ad08000 x1874696518867072/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787850128 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 622.070858] 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 [ 624.434083] Lustre: server umount lustre-OST0001 complete [ 633.670709] Lustre: DEBUG MARKER: == sanity-lfsck test 1a: LFSCK can find out and repair crashed FID-in-dirent ========================================================== 13:02:18 (1787850138) [ 646.495791] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing load_modules_local [ 656.212156] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 656.683699] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 660.370580] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 661.985426] LustreError: 26307:0:(ldlm_lib.c:1200: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. [ 661.991083] LustreError: 26307:0:(ldlm_lib.c:1200:target_handle_connect()) Skipped 2 previous similar messages [ 666.084437] LustreError: 26308:0:(ldlm_lib.c:1200: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. [ 668.040302] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 668.404591] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 673.271894] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 676.432928] Lustre: 27447:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 682.454776] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 688.817422] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 693.103116] LustreError: 27801:0:(ldlm_lib.c:1200: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. [ 696.418227] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 696.518905] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 696.524081] Lustre: Skipped 1 previous similar message [ 701.575657] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 701.674167] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:40 to 0x2c0000401:65) [ 701.680419] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:41 to 0x280000401:65) [ 709.165765] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 713.413761] Lustre: 29317:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 714.992631] Lustre: 26304:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 715.000588] Lustre: 26304:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 715.006211] Lustre: 26304:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 715.012056] Lustre: 26304:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1 previous similar message [ 715.015898] Lustre: 26304:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 715.020564] Lustre: 26304:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1 previous similar message [ 715.027042] Lustre: 26304:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 715.043393] Lustre: 26304:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1 previous similar message [ 715.054098] Lustre: 26304:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 715.057905] Lustre: 26304:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1 previous similar message [ 721.025064] Lustre: *** cfs_fail_loc=1501, val=0*** [ 728.946599] Lustre: Failing over lustre-MDT0000 [ 729.257472] Lustre: server umount lustre-MDT0000 complete [ 730.080905] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 730.090040] 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 [ 730.106476] LustreError: 26308:0:(ldlm_lib.c:1200: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. [ 732.641995] 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 [ 732.661357] Lustre: Skipped 2 previous similar messages [ 737.785826] LustreError: 29331:0:(ldlm_lib.c:1200: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. [ 737.799650] LustreError: 29331:0:(ldlm_lib.c:1200:target_handle_connect()) Skipped 6 previous similar messages [ 739.754379] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 739.924903] LustreError: MGC192.168.206.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 740.184696] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 740.229665] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 744.235794] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 745.442830] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 745.443423] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 745.455096] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 745.508761] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:105 to 0x2c0000401:129) [ 745.512121] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:105 to 0x280000401:129) [ 747.393773] Lustre: *** cfs_fail_loc=1505, val=0*** [ 754.766845] Lustre: DEBUG MARKER: == sanity-lfsck test 1b: LFSCK can find out and repair the missing FID-in-LMA ========================================================== 13:04:18 (1787850258) [ 755.796257] Lustre: 26302:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 755.807146] Lustre: 26302:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 322 previous similar messages [ 755.815211] Lustre: 26302:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 755.824740] Lustre: 26302:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 755.831904] Lustre: 26302:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 755.841797] Lustre: 26302:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 755.850048] Lustre: 26302:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 755.856438] Lustre: 26302:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 755.862887] Lustre: 26302:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 755.867970] Lustre: 26302:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 755.873070] Lustre: 26302:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 755.878631] Lustre: 26302:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 760.906191] Lustre: *** cfs_fail_loc=1502, val=0*** [ 769.582812] Lustre: Failing over lustre-MDT0000 [ 769.792871] Lustre: server umount lustre-MDT0000 complete [ 771.041490] 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 [ 771.046112] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 771.054389] LustreError: 26303:0:(ldlm_lib.c:1200: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. [ 771.079387] LustreError: 26303:0:(ldlm_lib.c:1200:target_handle_connect()) Skipped 3 previous similar messages [ 779.379796] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 779.459686] LustreError: MGC192.168.206.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 779.702927] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 783.963488] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 784.873311] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 784.873617] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 784.880713] Lustre: Skipped 3 previous similar messages [ 784.912262] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 784.977916] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:169 to 0x2c0000401:193) [ 784.978128] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:169 to 0x280000401:193) [ 787.198126] Lustre: *** cfs_fail_loc=1505, val=0*** [ 794.662778] Lustre: DEBUG MARKER: == sanity-lfsck test 1c: LFSCK can find out and repair lost FID-in-dirent ========================================================== 13:04:59 (1787850299) [ 800.612739] Lustre: *** cfs_fail_loc=1504, val=0*** [ 800.615068] Lustre: *** cfs_fail_loc=1504, val=0*** [ 800.620482] Lustre: Skipped 1 previous similar message [ 807.074630] Lustre: Failing over lustre-MDT0000 [ 807.251534] Lustre: server umount lustre-MDT0000 complete [ 810.464216] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 810.470696] 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 [ 810.472564] LustreError: 29336:0:(ldlm_lib.c:1200: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. [ 810.472572] LustreError: 29336:0:(ldlm_lib.c:1200:target_handle_connect()) Skipped 4 previous similar messages [ 810.497745] Lustre: Skipped 6 previous similar messages [ 815.559504] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 815.677818] LustreError: MGC192.168.206.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 815.876897] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 815.881553] Lustre: Skipped 1 previous similar message [ 815.920571] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 819.929796] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 821.226091] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 821.231884] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 821.247984] Lustre: Skipped 3 previous similar messages [ 821.267392] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 821.320350] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:233 to 0x280000401:257) [ 821.320444] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:233 to 0x2c0000401:257) [ 823.146729] Lustre: *** cfs_fail_loc=1505, val=0*** [ 829.979774] Lustre: DEBUG MARKER: == sanity-lfsck test 2a: LFSCK can find out and repair crashed linkEA entry ========================================================== 13:05:34 (1787850334) [ 831.293513] Lustre: 26303:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 831.302442] Lustre: 26303:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 644 previous similar messages [ 831.314826] Lustre: 26303:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 831.320735] Lustre: 26303:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 831.335616] Lustre: 26303:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 831.355554] Lustre: 26303:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 831.365554] Lustre: 26303:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 831.375788] Lustre: 26303:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 831.385251] Lustre: 26303:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 831.396333] Lustre: 26303:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 831.408846] Lustre: 26303:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 831.415661] Lustre: 26303:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 836.662366] Lustre: *** cfs_fail_loc=1603, val=0*** [ 844.590101] Lustre: Failing over lustre-MDT0000 [ 844.929564] Lustre: server umount lustre-MDT0000 complete [ 846.827668] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 846.829240] 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 [ 846.832671] LustreError: 29336:0:(ldlm_lib.c:1200: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. [ 846.832683] LustreError: 29336:0:(ldlm_lib.c:1200:target_handle_connect()) Skipped 7 previous similar messages [ 846.876296] Lustre: Skipped 3 previous similar messages [ 855.905403] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 856.031242] LustreError: MGC192.168.206.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 856.233372] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 859.804874] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 861.665024] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 861.673939] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 861.679538] Lustre: Skipped 3 previous similar messages [ 861.706396] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 861.759363] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:297 to 0x280000401:321) [ 861.760301] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:297 to 0x2c0000401:321) [ 869.199629] Lustre: DEBUG MARKER: == sanity-lfsck test 2b: LFSCK can find out and remove invalid linkEA entry ========================================================== 13:06:13 (1787850373) [ 875.333239] Lustre: *** cfs_fail_loc=1604, val=0*** [ 882.065051] Lustre: Failing over lustre-MDT0000 [ 882.144820] 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 [ 882.157309] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 882.160513] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 882.171260] Lustre: Skipped 3 previous similar messages [ 882.311911] Lustre: server umount lustre-MDT0000 complete [ 891.333345] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 891.422471] LustreError: MGC192.168.206.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 891.633774] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 895.531780] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 896.992992] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 896.998321] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 897.004378] Lustre: Skipped 3 previous similar messages [ 897.022887] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 897.068653] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:361 to 0x280000401:385) [ 897.077473] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:361 to 0x2c0000401:385) [ 903.435815] Lustre: DEBUG MARKER: == sanity-lfsck test 2c: LFSCK can find out and remove repeated linkEA entry ========================================================== 13:06:47 (1787850407) [ 909.653598] Lustre: *** cfs_fail_loc=1605, val=0*** [ 916.983808] Lustre: Failing over lustre-MDT0000 [ 917.344185] Lustre: server umount lustre-MDT0000 complete [ 917.472425] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 917.481657] LustreError: 29336:0:(ldlm_lib.c:1200: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. [ 917.495649] LustreError: 29336:0:(ldlm_lib.c:1200:target_handle_connect()) Skipped 14 previous similar messages [ 927.812593] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 927.977117] LustreError: MGC192.168.206.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 928.185636] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 932.150681] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 933.347570] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 933.352167] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 933.369099] Lustre: Skipped 3 previous similar messages [ 933.391959] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 933.452335] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:425 to 0x2c0000401:449) [ 933.469542] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:425 to 0x280000401:449) [ 940.619789] Lustre: DEBUG MARKER: == sanity-lfsck test 2d: LFSCK can recover the missing linkEA entry ========================================================== 13:07:25 (1787850445) [ 946.235674] Lustre: *** cfs_fail_loc=161d, val=0*** [ 953.392669] Lustre: Failing over lustre-MDT0000 [ 953.737526] Lustre: server umount lustre-MDT0000 complete [ 953.825284] 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 [ 953.849971] Lustre: Skipped 9 previous similar messages [ 963.585460] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 963.751832] LustreError: MGC192.168.206.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 964.025070] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 964.034970] Lustre: Skipped 3 previous similar messages [ 964.072613] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 968.137792] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 969.199870] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 969.217285] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 969.222826] Lustre: Skipped 3 previous similar messages [ 969.232996] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 969.289375] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:489 to 0x2c0000401:513) [ 969.289609] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:489 to 0x280000401:513) [ 976.334869] Lustre: DEBUG MARKER: == sanity-lfsck test 2e: namespace LFSCK can verify remote object linkEA ========================================================== 13:08:01 (1787850481) [ 977.582558] Lustre: 29336:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 977.590902] Lustre: 29336:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 1290 previous similar messages [ 977.597563] Lustre: 29336:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 977.603662] Lustre: 29336:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1290 previous similar messages [ 977.614602] Lustre: 29336:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 977.622484] Lustre: 29336:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1290 previous similar messages [ 977.629865] Lustre: 29336:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 977.637289] Lustre: 29336:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1290 previous similar messages [ 977.642923] Lustre: 29336:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 977.647499] Lustre: 29336:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1290 previous similar messages [ 977.652944] Lustre: 29336:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 977.660764] Lustre: 29336:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1290 previous similar messages [ 978.630398] Lustre: *** cfs_fail_loc=1603, val=0*** [ 988.103980] Lustre: DEBUG MARKER: == sanity-lfsck test 3: LFSCK can verify multiple-linked objects ========================================================== 13:08:12 (1787850492) [ 993.904190] Lustre: *** cfs_fail_loc=1603, val=0*** [ 994.707668] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1004.584323] Lustre: DEBUG MARKER: == sanity-lfsck test 4: FID-in-dirent can be rebuilt after MDT file-level backup/restore ========================================================== 13:08:28 (1787850508) [ 1039.412842] Lustre: Failing over lustre-MDT0000 [ 1039.804990] Lustre: server umount lustre-MDT0000 complete [ 1040.880229] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1045.983828] LustreError: 34167:0:(ldlm_lib.c:1200: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. [ 1046.006146] LustreError: 34167:0:(ldlm_lib.c:1200:target_handle_connect()) Skipped 23 previous similar messages [ 1046.338545] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1055.998721] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1056.225284] Lustre: 16434:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787850546/real 1787850546] req@ffff9a8ea7525e00 x1874696519498496/t0(0) o400->MGC192.168.206.111@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1787850562 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1056.278537] LustreError: MGC192.168.206.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1067.207310] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1067.235263] Lustre: lustre-MDT0000: reset Object Index mappings [ 1068.002164] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1072.816546] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1073.125859] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1073.127965] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1073.142694] Lustre: Skipped 3 previous similar messages [ 1073.170120] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1073.217277] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:592 to 0x280000401:609) [ 1073.221320] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:592 to 0x2c0000401:609) [ 1076.042747] LustreError: 42954:0:(lfsck_engine.c:1018:lfsck_master_engine()) lustre-MDT0000-osd: master engine fail to verify the .lustre/lost+found/, go ahead: rc = -115 [ 1076.088673] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1078.175125] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1078.178665] Lustre: Skipped 1 previous similar message [ 1085.316093] Lustre: Failing over lustre-MDT0000 [ 1085.513865] Lustre: server umount lustre-MDT0000 complete [ 1088.479834] 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 [ 1088.504313] Lustre: Skipped 8 previous similar messages [ 1097.410806] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1102.431816] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1102.856066] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:592 to 0x280000401:641) [ 1102.856143] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:592 to 0x2c0000401:641) [ 1105.894308] Lustre: *** cfs_fail_loc=1505, val=0*** [ 1112.870646] Lustre: DEBUG MARKER: == sanity-lfsck test 5: LFSCK can handle IGIF object upgrading ========================================================== 13:10:17 (1787850617) [ 1115.302272] Lustre: *** cfs_fail_loc=1504, val=0*** [ 1124.032751] Lustre: Failing over lustre-MDT0000 [ 1124.421404] Lustre: server umount lustre-MDT0000 complete [ 1128.418466] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1129.590398] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1140.045455] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1144.820500] Lustre: 16437:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787850634/real 1787850634] req@ffff9a8ebb358000 x1874696519593344/t0(0) o400->MGC192.168.206.111@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1787850650 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1151.582839] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1151.599963] Lustre: lustre-MDT0000: reset Object Index mappings [ 1154.345986] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1154.360201] Lustre: Skipped 1 previous similar message [ 1158.363334] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1159.652352] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1159.654620] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1159.661248] Lustre: Skipped 7 previous similar messages [ 1159.684125] Lustre: Skipped 1 previous similar message [ 1159.708680] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1159.717647] Lustre: Skipped 1 previous similar message [ 1159.775141] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:681 to 0x280000401:705) [ 1159.775978] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:681 to 0x2c0000401:705) [ 1161.799875] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1161.823728] Lustre: Skipped 2 previous similar messages [ 1170.020027] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1170.023185] Lustre: Skipped 7 previous similar messages [ 1175.476872] Lustre: Failing over lustre-MDT0000 [ 1175.929286] Lustre: server umount lustre-MDT0000 complete [ 1187.443950] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1187.559520] LustreError: MGC192.168.206.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1187.573558] LustreError: Skipped 2 previous similar messages [ 1192.408978] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1192.996894] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:681 to 0x2c0000401:737) [ 1192.997251] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:681 to 0x280000401:737) [ 1195.729298] Lustre: *** cfs_fail_loc=1505, val=0*** [ 1195.738628] Lustre: Skipped 84 previous similar messages [ 1203.550165] Lustre: DEBUG MARKER: == sanity-lfsck test 6a: LFSCK resumes from last checkpoint (1) ========================================================== 13:11:47 (1787850707) [ 1212.267583] Lustre: *** cfs_fail_loc=1600, val=1*** [ 1234.594743] Lustre: DEBUG MARKER: == sanity-lfsck test 6b: LFSCK resumes from last checkpoint (2) ========================================================== 13:12:19 (1787850739) [ 1236.479588] Lustre: 26302:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 1236.491996] Lustre: 26302:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 1314 previous similar messages [ 1236.507960] Lustre: 26302:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 1236.520721] Lustre: 26302:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1314 previous similar messages [ 1236.537738] Lustre: 26302:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 1236.546906] Lustre: 26302:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1314 previous similar messages [ 1236.560409] Lustre: 26302:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 1236.571662] Lustre: 26302:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1314 previous similar messages [ 1236.580314] Lustre: 26302:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 1236.585031] Lustre: 26302:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1314 previous similar messages [ 1236.594388] Lustre: 26302:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 1236.602115] Lustre: 26302:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1314 previous similar messages [ 1244.703851] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1244.709140] Lustre: Skipped 11 previous similar messages [ 1266.047902] Lustre: DEBUG MARKER: == sanity-lfsck test 7a: non-stopped LFSCK should auto restarts after MDS remount (1) ========================================================== 13:12:50 (1787850770) [ 1283.348768] Lustre: Failing over lustre-MDT0000 [ 1283.590962] Lustre: server umount lustre-MDT0000 complete [ 1285.094026] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1285.109138] LustreError: Skipped 1 previous similar message [ 1293.494364] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1293.797846] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1293.803424] Lustre: Skipped 4 previous similar messages [ 1293.835974] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1293.844944] Lustre: Skipped 1 previous similar message [ 1298.117555] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1298.912208] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1298.922213] Lustre: Skipped 1 previous similar message [ 1298.923564] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1298.938234] Lustre: Skipped 7 previous similar messages [ 1298.966305] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1298.973306] Lustre: Skipped 1 previous similar message [ 1299.043257] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:853 to 0x2c0000401:897) [ 1299.047745] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:854 to 0x280000401:897) [ 1307.030218] Lustre: DEBUG MARKER: == sanity-lfsck test 7b: non-stopped LFSCK should auto restarts after MDS remount (2) ========================================================== 13:13:31 (1787850811) [ 1321.529225] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing load_modules_local [ 1351.667307] Lustre: 53070:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 1375.733197] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1379.587640] Lustre: 54206:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 1387.774681] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1387.776966] Lustre: Skipped 81 previous similar messages [ 1390.778057] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1391.847669] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1392.863266] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1394.911699] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1394.914025] Lustre: Skipped 1 previous similar message [ 1395.670300] Lustre: Failing over lustre-MDT0000 [ 1396.075631] Lustre: server umount lustre-MDT0000 complete [ 1396.192554] 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 [ 1396.211486] Lustre: Skipped 12 previous similar messages [ 1396.226190] LustreError: 26304:0:(ldlm_lib.c:1200: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. [ 1396.242996] LustreError: 26304:0:(ldlm_lib.c:1200:target_handle_connect()) Skipped 75 previous similar messages [ 1404.926179] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1409.908894] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1410.632697] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:947 to 0x280000401:993) [ 1410.632954] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:946 to 0x2c0000401:961) [ 1419.022881] Lustre: DEBUG MARKER: == sanity-lfsck test 8: LFSCK state machine ============== 13:15:23 (1787850923) [ 1425.889459] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1425.902077] Lustre: Skipped 3 previous similar messages [ 1427.530752] Lustre: server umount lustre-MDT0000 complete [ 1431.061448] LustreError: 29352:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787850937 with bad export cookie 1262541208078557392 [ 1431.083415] LustreError: 29352:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 1431.358916] Lustre: server umount lustre-MDT0001 complete [ 1445.454181] Lustre: server umount lustre-OST0000 complete [ 1459.716422] Lustre: server umount lustre-OST0001 complete [ 1466.376352] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_hostid [ 1474.523274] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing load_modules_local [ 1510.180481] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing load_modules_local [ 1518.555108] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1518.774632] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 1518.811595] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 1518.929051] Lustre: lustre-MDT0000: new disk, initializing [ 1519.002607] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 1523.370873] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1533.516441] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1533.626949] Lustre: 59263: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 [ 1533.664681] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 1533.674085] Lustre: Skipped 1 previous similar message [ 1533.727547] Lustre: lustre-MDT0001: new disk, initializing [ 1533.836551] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 1533.848685] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 1538.497142] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1543.055727] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 1550.135403] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 1550.452551] Lustre: lustre-OST0000: new disk, initializing [ 1550.461272] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 1550.468403] Lustre: 60895:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 1552.388449] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 1552.406107] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 1552.489393] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 1557.350794] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1566.417473] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 1566.543337] Lustre: lustre-OST0001: new disk, initializing [ 1566.546538] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 1566.551347] Lustre: 61763:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 1568.527970] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 1568.541354] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 1568.584583] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 1572.131333] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1580.148287] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1583.459622] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 1592.994721] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1593.821466] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1593.825854] Lustre: Skipped 19 previous similar messages [ 1597.493942] Lustre: *** cfs_fail_loc=1601, val=2*** [ 1597.497365] Lustre: Skipped 16 previous similar messages [ 1613.179141] Lustre: Failing over lustre-MDT0000 [ 1613.466075] Lustre: server umount lustre-MDT0000 complete [ 1622.464327] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1622.561392] LustreError: MGC192.168.206.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1622.569142] LustreError: Skipped 3 previous similar messages [ 1622.838380] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1622.850147] Lustre: Skipped 1 previous similar message [ 1627.088981] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1628.132668] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1628.144945] Lustre: Skipped 1 previous similar message [ 1628.147540] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1628.160497] Lustre: Skipped 7 previous similar messages [ 1628.209941] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1628.220134] Lustre: Skipped 1 previous similar message [ 1628.284337] Lustre: *** cfs_fail_loc=160b, val=2*** [ 1628.293723] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:65) [ 1628.299200] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:65) [ 1635.026165] Lustre: Failing over lustre-MDT0000 [ 1635.317973] Lustre: server umount lustre-MDT0000 complete [ 1638.369744] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1638.376781] LustreError: Skipped 2 previous similar messages [ 1643.868263] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1648.042818] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1649.700055] Lustre: *** cfs_fail_loc=160b, val=2*** [ 1649.708217] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:97) [ 1649.709652] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:97) [ 1652.404335] Lustre: Failing over lustre-MDT0000 [ 1652.564251] Lustre: server umount lustre-MDT0000 complete [ 1659.288762] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1663.499622] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1665.044568] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:129) [ 1665.044882] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:129) [ 1667.761752] Lustre: *** cfs_fail_loc=1602, val=2*** [ 1675.245918] Lustre: DEBUG MARKER: == sanity-lfsck test 9a: LFSCK speed control (1) ========= 13:19:40 (1787851180) [ 1687.133509] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing load_modules_local [ 1701.002478] Lustre: 68663:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 1720.762730] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1723.704915] Lustre: 69800:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 1748.506361] Lustre: 59270:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 1748.536503] Lustre: 59270:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 5169 previous similar messages [ 1748.558809] Lustre: 59270:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 1748.577779] Lustre: 59270:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 5169 previous similar messages [ 1748.584236] Lustre: 59270:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 1748.593794] Lustre: 59270:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 5169 previous similar messages [ 1748.612523] Lustre: 59270:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 1748.626773] Lustre: 59270:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 5169 previous similar messages [ 1748.643894] Lustre: 59270:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 1748.656796] Lustre: 59270:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 5169 previous similar messages [ 1748.672836] Lustre: 59270:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 1748.681234] Lustre: 59270:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 5169 previous similar messages [ 1847.990535] Lustre: DEBUG MARKER: == sanity-lfsck test 9b: LFSCK speed control (2) ========= 13:22:32 (1787851352) [ 1895.406204] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1895.412831] Lustre: Skipped 4 previous similar messages [ 1919.174536] Lustre: *** cfs_fail_loc=160c, val=0*** [ 1919.182406] Lustre: Skipped 7 previous similar messages [ 1954.862764] Lustre: DEBUG MARKER: == sanity-lfsck test 10: System is available during LFSCK scanning ========================================================== 13:24:19 (1787851459) [ 2004.022538] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2012.032482] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2012.038641] Lustre: Skipped 366 previous similar messages [ 2028.034374] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2028.036780] Lustre: Skipped 720 previous similar messages [ 2060.083847] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2060.090921] Lustre: Skipped 1552 previous similar messages [ 2078.104182] Lustre: *** cfs_fail_loc=1604, val=0*** [ 2078.106887] Lustre: Skipped 2599 previous similar messages [ 2336.540159] Lustre: DEBUG MARKER: == sanity-lfsck test 11a: LFSCK can rebuild lost last_id ========================================================== 13:30:40 (1787851840) [ 2401.919746] Lustre: 62550:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 320, rollback = 2 [ 2401.926715] Lustre: 62550:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 34107 previous similar messages [ 2401.932204] Lustre: 62550:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 1/4/0 [ 2401.936033] Lustre: 62550:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 34107 previous similar messages [ 2401.940676] Lustre: 62550:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 5/5/0, xattr_set: 7/320/0 [ 2401.945138] Lustre: 62550:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 34107 previous similar messages [ 2401.961199] Lustre: 62550:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 6/46/0, punch: 0/0/0, quota 1/3/0 [ 2401.976173] Lustre: 62550:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 34107 previous similar messages [ 2401.982820] Lustre: 62550:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 2/5/0 [ 2401.987782] Lustre: 62550:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 34107 previous similar messages [ 2401.992472] Lustre: 62550:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 1/1/0, ref_del: 2/2/1 [ 2401.996729] Lustre: 62550:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 34107 previous similar messages [ 2499.559559] 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 [ 2499.560194] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 2499.563516] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2499.580763] Lustre: Skipped 21 previous similar messages [ 2499.588238] LustreError: Skipped 1 previous similar message [ 2504.337640] Lustre: server umount lustre-MDT0000 complete [ 2504.679481] LustreError: 70230:0:(ldlm_lib.c:1200: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. [ 2504.700290] LustreError: 70230:0:(ldlm_lib.c:1200:target_handle_connect()) Skipped 31 previous similar messages [ 2507.488820] LustreError: 60057:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787852013 with bad export cookie 1262541208078576495 [ 2507.498086] LustreError: 60057:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 2507.498296] LustreError: MGC192.168.206.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2507.509682] LustreError: Skipped 2 previous similar messages [ 2507.713612] Lustre: server umount lustre-MDT0001 complete [ 2521.313633] Lustre: server umount lustre-OST0000 complete [ 2525.160231] Lustre: 16436:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787852015/real 1787852015] req@ffff9a8e9790cb40 x1874696523685248/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787852031 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2526.398790] Lustre: server umount lustre-OST0001 complete [ 2534.984450] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: (null) [ 2543.523305] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 2559.135451] LustreError: Failed to get MGS log lustre-sptlrpc and no local copy. [ 2564.255496] LustreError: 74599:0:(mgc_request.c:233:do_config_log_add()) MGC192.168.206.111@tcp: failed processing log, type 4: rc = -110 [ 2589.919195] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 2589.931886] Lustre: Skipped 8 previous similar messages [ 2595.913665] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2600.247886] Lustre: 75182:0:(ofd_dev.c:564:ofd_lfsck_out_notify()) lustre-OST0000: Found crashed LAST_ID, deny creating new OST-object on the device until the LAST_ID rebuilt successfully. [ 2600.267712] Lustre: *** cfs_fail_loc=160e, val=3*** [ 2603.311265] Lustre: 75182:0:(ofd_dev.c:576:ofd_lfsck_out_notify()) lustre-OST0000: Rebuilt crashed LAST_ID files successfully. [ 2613.343297] Lustre: DEBUG MARKER: == sanity-lfsck test 11b: LFSCK can rebuild crashed last_id ========================================================== 13:35:17 (1787852117) [ 2630.272037] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing load_modules_local [ 2644.609489] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2644.979459] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3272 to 0x280000401:3297) [ 2652.241756] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2665.711244] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2666.236547] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 2666.240729] Lustre: Skipped 1 previous similar message [ 2673.147731] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2676.855255] Lustre: 77801:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 2693.548851] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2699.248687] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3207 to 0x2c0000401:3233) [ 2700.572546] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2707.670207] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 2711.069612] Lustre: 79298:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 2715.517450] Lustre: *** cfs_fail_loc=160d, val=0*** [ 2722.119547] Lustre: Failing over lustre-OST0000 [ 2722.235800] Lustre: server umount lustre-OST0000 complete [ 2731.756784] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2731.934064] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 2731.937945] Lustre: Skipped 2 previous similar messages [ 2733.792244] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 2733.820053] Lustre: Skipped 2 previous similar messages [ 2733.874790] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 2733.879212] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 2733.879222] Lustre: Skipped 11 previous similar messages [ 2733.880391] Lustre: *** cfs_fail_loc=215, val=0*** [ 2733.891611] Lustre: Skipped 2 previous similar messages [ 2738.804468] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2739.168986] Lustre: *** cfs_fail_loc=215, val=0*** [ 2739.176734] Lustre: Skipped 3 previous similar messages [ 2743.597324] Lustre: 80697:0:(ofd_dev.c:564:ofd_lfsck_out_notify()) lustre-OST0000: Found crashed LAST_ID, deny creating new OST-object on the device until the LAST_ID rebuilt successfully. [ 2743.613827] Lustre: 80697:0:(ofd_dev.c:576:ofd_lfsck_out_notify()) lustre-OST0000: Rebuilt crashed LAST_ID files successfully. [ 2744.287780] Lustre: *** cfs_fail_loc=215, val=0*** [ 2746.530840] Lustre: Failing over lustre-OST0000 [ 2746.599539] Lustre: server umount lustre-OST0000 complete [ 2755.732326] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2757.003670] Lustre: *** cfs_fail_loc=215, val=0*** [ 2757.018653] Lustre: Skipped 1 previous similar message [ 2762.207909] Lustre: *** cfs_fail_loc=215, val=0*** [ 2763.465258] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2771.425844] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2771.438792] Lustre: Skipped 6 previous similar messages [ 2776.545250] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2777.715473] Lustre: server umount lustre-MDT0000 complete [ 2781.308380] LustreError: 74607:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787852287 with bad export cookie 1262541208080154470 [ 2781.317748] LustreError: 74607:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 2781.695463] Lustre: server umount lustre-MDT0001 complete [ 2795.287980] Lustre: server umount lustre-OST0000 complete [ 2797.538987] Lustre: 16434:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787852287/real 1787852287] req@ffff9a8ebb08bc00 x1874696523783040/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787852303 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2799.172931] Lustre: server umount lustre-OST0001 complete [ 2807.964634] Lustre: DEBUG MARKER: == sanity-lfsck test 12a: single command to trigger LFSCK on all devices ========================================================== 13:38:32 (1787852312) [ 2823.653079] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing load_modules_local [ 2833.416623] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2833.973238] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 2833.979087] Lustre: Skipped 3 previous similar messages [ 2838.708805] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2847.168320] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2852.356584] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2855.637402] Lustre: 85088:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 2863.074347] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2869.809681] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2878.961724] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3362 to 0x280000401:3393) [ 2881.078338] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2886.639838] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3207 to 0x2c0000401:3265) [ 2888.724540] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2898.581766] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 2903.137202] Lustre: 86959:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 2940.655506] Lustre: DEBUG MARKER: == sanity-lfsck test 12b: auto detect Lustre device ====== 13:40:44 (1787852444) [ 2955.458724] Lustre: DEBUG MARKER: == sanity-lfsck test 13: LFSCK can repair crashed lmm_oi ========================================================== 13:40:59 (1787852459) [ 2956.768000] Lustre: *** cfs_fail_loc=160f, val=0*** [ 2968.754316] Lustre: DEBUG MARKER: == sanity-lfsck test 14a: LFSCK can repair MDT-object with dangling LOV EA reference (1) ========================================================== 13:41:12 (1787852472) [ 2972.928702] Lustre: *** cfs_fail_loc=1610, val=0*** [ 2972.930495] Lustre: Skipped 7 previous similar messages [ 3024.866376] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3024.878396] Lustre: Skipped 6 previous similar messages [ 3026.194786] Lustre: server umount lustre-MDT0000 complete [ 3030.211849] LustreError: 83930:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787852536 with bad export cookie 1262541208080162926 [ 3030.243061] LustreError: 83930:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 3030.525782] Lustre: server umount lustre-MDT0001 complete [ 3045.622588] Lustre: server umount lustre-OST0000 complete [ 3059.787222] Lustre: server umount lustre-OST0001 complete [ 3080.423421] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing load_modules_local [ 3090.095492] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3090.825837] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3090.830017] Lustre: Skipped 3 previous similar messages [ 3096.127130] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3104.008083] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3108.227216] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3110.895141] Lustre: 92832:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3119.086199] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3129.224329] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3129.760789] LustreError: 93187:0:(ldlm_lib.c:1200: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. [ 3129.785174] LustreError: 93187:0:(ldlm_lib.c:1200:target_handle_connect()) Skipped 49 previous similar messages [ 3129.797281] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:116 to 0x280000400:161) [ 3136.003819] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3554 to 0x280000401:3585) [ 3140.832727] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3146.220305] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3317 to 0x2c0000401:3361) [ 3146.223639] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:116 to 0x2c0000400:161) [ 3146.992234] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3155.316157] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3159.743908] Lustre: 94706:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 3168.540384] Lustre: DEBUG MARKER: == sanity-lfsck test 14b: LFSCK can repair MDT-object with dangling LOV EA reference (2) ========================================================== 13:44:32 (1787852672) [ 3170.973536] Lustre: 93802:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 256 < left 278, rollback = 2 [ 3170.984249] Lustre: 93802:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 1364 previous similar messages [ 3170.993049] Lustre: 93802:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 3171.000754] Lustre: 93802:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1364 previous similar messages [ 3171.010329] Lustre: 93802:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3171.019117] Lustre: 93802:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1364 previous similar messages [ 3171.027874] Lustre: 93802:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 3171.037187] Lustre: 93802:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1364 previous similar messages [ 3171.043906] Lustre: 93802:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 3171.051267] Lustre: 93802:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1364 previous similar messages [ 3171.060864] Lustre: 93802:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3171.072230] Lustre: 93802:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1364 previous similar messages [ 3174.716490] Lustre: *** cfs_fail_loc=1610, val=0*** [ 3174.718393] Lustre: Skipped 63 previous similar messages [ 3201.507208] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3201.513625] LustreError: Skipped 1 previous similar message [ 3201.515243] 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 [ 3201.535596] Lustre: Skipped 15 previous similar messages [ 3201.538197] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3206.804182] Lustre: server umount lustre-MDT0000 complete [ 3211.273902] LustreError: 91671:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787852717 with bad export cookie 1262541208080191346 [ 3211.274758] LustreError: MGC192.168.206.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3211.281022] LustreError: 91671:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 3 previous similar messages [ 3211.297894] LustreError: Skipped 2 previous similar messages [ 3211.558324] Lustre: server umount lustre-MDT0001 complete [ 3226.501655] Lustre: server umount lustre-OST0000 complete [ 3228.639205] Lustre: 16434:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787852718/real 1787852718] req@ffff9a8d8ea82940 x1874696524147328/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787852734 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3230.284613] Lustre: server umount lustre-OST0001 complete [ 3246.032752] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing load_modules_local [ 3255.523463] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3260.935419] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3268.448368] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3273.761300] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3276.833577] Lustre: 98739:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3284.847212] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3291.704541] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3293.226139] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:116 to 0x280000400:193) [ 3300.388323] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3301.570893] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:116 to 0x2c0000400:193) [ 3301.573619] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3317 to 0x2c0000401:3393) [ 3301.697498] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3682 to 0x280000401:3713) [ 3307.035402] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3315.834643] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3329.227811] Lustre: DEBUG MARKER: == sanity-lfsck test 15a: LFSCK can repair unmatched MDT-object/OST-object pairs (1) ========================================================== 13:47:12 (1787852832) [ 3333.097449] Lustre: *** cfs_fail_loc=1611, val=0*** [ 3333.104764] Lustre: Skipped 63 previous similar messages [ 3333.435721] Lustre: *** cfs_fail_loc=1611, val=0*** [ 3344.974928] Lustre: DEBUG MARKER: == sanity-lfsck test 15b: LFSCK can repair unmatched MDT-object/OST-object pairs (2) ========================================================== 13:47:29 (1787852849) [ 3347.224888] Lustre: *** cfs_fail_loc=1612, val=0*** [ 3347.297635] Lustre: *** cfs_fail_loc=1612, val=0*** [ 3347.302037] Lustre: Skipped 2 previous similar messages [ 3357.826512] Lustre: DEBUG MARKER: == sanity-lfsck test 15c: LFSCK can repair unmatched MDT-object/OST-object pairs (3) ========================================================== 13:47:42 (1787852862) [ 3359.449110] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_15c MDS newer than 2.7.55, LU-6475 [ 3361.606817] Lustre: DEBUG MARKER: == sanity-lfsck test 15d: LFSCK don't crash upon dir migration failure ========================================================== 13:47:45 (1787852865) [ 3367.977893] Lustre: *** cfs_fail_loc=1709, val=0*** [ 3368.062904] LustreError: 97607:0:(osp_object.c:618:osp_attr_get()) lustre-MDT0000-osp-MDT0001: osp_attr_get update error [0x200003ab2:0x1:0x0]: rc = -5 [ 3368.077084] LustreError: 97607:0:(mdt_reint.c:2644:mdt_reint_migrate()) lustre-MDT0001: migrate [0x240002340:0x6c:0x0]/s61 failed: rc = -5 [ 3382.367338] LustreError: 97596:0:(lod_object.c:945:lod_load_lmv_shards()) lustre-MDT0001-mdtlov: the shard [0x200003ab1:0x56:0x0]:1 for the striped directory [0x240002340:0x89:0x0] is out of the known LMV EA range [0 - 0], failout [ 3388.681114] LustreError: 97596:0:(lod_object.c:945:lod_load_lmv_shards()) lustre-MDT0001-mdtlov: the shard [0x200003ab1:0x56:0x0]:1 for the striped directory [0x240002340:0x89:0x0] is out of the known LMV EA range [0 - 0], failout [ 3388.712989] LustreError: 97596:0:(mdt_handler.c:1498:mdt_getattr_internal()) lustre-MDT0001: getattr error for [0x240002340:0x89:0x0]: rc = -5 [ 3424.736821] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3424.742492] Lustre: Skipped 6 previous similar messages [ 3430.810326] Lustre: server umount lustre-MDT0000 complete [ 3438.739494] LustreError: 99118:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787852944 with bad export cookie 1262541208080206088 [ 3438.764811] LustreError: 99118:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 3439.113828] Lustre: server umount lustre-MDT0001 complete [ 3456.287131] Lustre: 16436:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787852946/real 1787852946] req@ffff9a8d8edf3480 x1874696524575360/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787852962 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3457.431476] Lustre: server umount lustre-OST0000 complete [ 3461.471495] Lustre: 16436:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787852951/real 1787852951] req@ffff9a8e9bc65a40 x1874696524575872/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787852967 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3461.500113] Lustre: 16436:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 3464.254478] Lustre: server umount lustre-OST0001 complete [ 3479.367367] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing unload_modules_local [ 3482.733422] Key type lgssc unregistered [ 3483.302568] LNet: 104442:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 3483.310316] LNetError: 104442:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 3483.357930] LNet: Removed LNI 192.168.206.111@tcp [ 3484.391255] Key type .llcrypt unregistered [ 3484.396458] Key type ._llcrypt unregistered [ 3506.986842] Key type ._llcrypt registered [ 3506.989139] Key type .llcrypt registered [ 3507.060854] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_hostid [ 3518.586901] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing load_modules_local [ 3519.237223] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 3519.268065] alg: No test for adler32 (adler32-zlib) [ 3520.328958] Lustre: Lustre: Build Version: 2.17.57_85_gfc6b239 [ 3520.586616] LNet: Added LNI 192.168.206.111@tcp [8/256/0/180] [ 3522.471704] Key type lgssc registered [ 3523.315551] Lustre: Echo OBD driver; http://www.lustre.org/ [ 3569.361403] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing load_modules_local [ 3580.706506] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 3580.716153] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3581.998885] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 3582.035224] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 3582.106973] Lustre: lustre-MDT0000: new disk, initializing [ 3582.183977] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3582.198709] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 3586.058661] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3597.408872] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3597.510766] Lustre: 108877: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 [ 3597.535850] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 3597.540423] Lustre: Skipped 1 previous similar message [ 3597.596358] Lustre: lustre-MDT0001: new disk, initializing [ 3597.654754] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 3597.680103] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 3597.697069] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 3602.086274] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3606.591537] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 3614.702207] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3614.910967] Lustre: lustre-OST0000: new disk, initializing [ 3614.919655] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 3614.933268] Lustre: 110818:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 3615.008960] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 3618.317711] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 3618.321268] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 3618.403721] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 3621.916757] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3636.394151] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3636.575628] Lustre: lustre-OST0001: new disk, initializing [ 3636.578899] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 3636.587121] Lustre: 111843:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 3636.659309] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 3643.389635] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3646.544221] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 3646.562336] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 3646.682390] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 3655.221081] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3659.625497] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 3665.369046] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 13:52:49 (1787853169) === [ 3672.673126] Lustre: DEBUG MARKER: == sanity-lfsck test 16: LFSCK can repair inconsistent MDT-object/OST-object owner ========================================================== 13:52:57 (1787853177) [ 3672.838510] Lustre: 108884:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 251 < left 278, rollback = 2 [ 3672.850439] Lustre: 108884:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 3672.856297] Lustre: 108884:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3672.862923] Lustre: 108884:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 3672.876503] Lustre: 108884:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 3672.891453] Lustre: 108884:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3673.455896] Lustre: 108884:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 252 < left 278, rollback = 2 [ 3673.466018] Lustre: 108884:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 9 previous similar messages [ 3673.472996] Lustre: 108884:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 3673.482404] Lustre: 108884:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3673.496445] Lustre: 108884:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3673.512158] Lustre: 108884:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3673.530417] Lustre: 108884:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/1, punch: 0/0/0, quota 7/369/2 [ 3673.538980] Lustre: 108884:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3673.546441] Lustre: 108884:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/1, delete: 0/0/0 [ 3673.553466] Lustre: 108884:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3673.558513] Lustre: 108884:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3673.564238] Lustre: 108884:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3674.468944] Lustre: 108883:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 3674.475484] Lustre: 108883:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 206 previous similar messages [ 3674.480418] Lustre: 108883:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 3674.485949] Lustre: 108883:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 206 previous similar messages [ 3674.508731] Lustre: 108884:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3674.519117] Lustre: 108884:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 209 previous similar messages [ 3674.532325] Lustre: 111481:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 7/369/0 [ 3674.539467] Lustre: 111481:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 212 previous similar messages [ 3674.548819] Lustre: 111481:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 3674.554991] Lustre: 111481:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 212 previous similar messages [ 3674.564139] Lustre: 111481:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3674.571250] Lustre: 111481:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 212 previous similar messages [ 3675.784188] Lustre: *** cfs_fail_loc=1613, val=0*** [ 3684.464876] Lustre: DEBUG MARKER: == sanity-lfsck test 17: LFSCK can repair multiple references ========================================================== 13:53:09 (1787853189) [ 3685.473404] Lustre: 111481:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 256 < left 278, rollback = 2 [ 3685.482125] Lustre: 111481:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 92 previous similar messages [ 3685.486797] Lustre: 111481:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/2, destroy: 0/0/0 [ 3685.497246] Lustre: 111481:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 92 previous similar messages [ 3685.508491] Lustre: 111481:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3685.515875] Lustre: 111481:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 89 previous similar messages [ 3685.523030] Lustre: 111481:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 3685.528370] Lustre: 111481:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 86 previous similar messages [ 3685.532563] Lustre: 111481:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 3685.538031] Lustre: 111481:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 86 previous similar messages [ 3685.546330] Lustre: 111481:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3685.552496] Lustre: 111481:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 86 previous similar messages [ 3686.511049] Lustre: *** cfs_fail_loc=1614, val=0*** [ 3690.266830] Lustre: 110808:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 259 < left 275, rollback = 2 [ 3690.278884] Lustre: 110808:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 11 previous similar messages [ 3690.286372] Lustre: 110808:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 3690.295324] Lustre: 110808:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3690.301285] Lustre: 110808:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/1, xattr_set: 3/275/0 [ 3690.307891] Lustre: 110808:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3690.315924] Lustre: 110808:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/9/0, punch: 1/4/0, quota 7/225/0 [ 3690.331048] Lustre: 110808:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3690.343362] Lustre: 110808:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 3690.348214] Lustre: 110808:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3690.356131] Lustre: 110808:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3690.362877] Lustre: 110808:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3697.340539] Lustre: DEBUG MARKER: == sanity-lfsck test 18a: Find out orphan OST-object and repair it (1) ========================================================== 13:53:21 (1787853201) [ 3698.295814] Lustre: 108885:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0001: opcode 2: before 251 < left 306, rollback = 2 [ 3698.303551] Lustre: 108885:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 10 previous similar messages [ 3698.310502] Lustre: 108885:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 3/12/6, destroy: 0/0/0 [ 3698.317706] Lustre: 108885:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 10 previous similar messages [ 3698.322721] Lustre: 108885:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 3/3/0, xattr_set: 6/306/0 [ 3698.336766] Lustre: 108885:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 10 previous similar messages [ 3698.342394] Lustre: 108885:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 7/145/0, punch: 0/0/0, quota 1/3/0 [ 3698.347331] Lustre: 108885:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 10 previous similar messages [ 3698.351214] Lustre: 108885:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 7/135/3, delete: 0/0/0 [ 3698.354669] Lustre: 108885:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 10 previous similar messages [ 3698.363856] Lustre: 108885:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 1/1/0, ref_del: 0/0/0 [ 3698.370501] Lustre: 108885:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 10 previous similar messages [ 3700.266841] Lustre: *** cfs_fail_loc=1615, val=0*** [ 3700.269471] Lustre: Skipped 1 previous similar message [ 3701.354695] Lustre: *** cfs_fail_loc=1615, val=0*** [ 3701.356906] Lustre: Skipped 3 previous similar messages [ 3718.974550] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_18b skipping excluded test 18b [ 3720.805346] Lustre: DEBUG MARKER: == sanity-lfsck test 18c: Find out orphan OST-object and repair it (3) ========================================================== 13:53:45 (1787853225) [ 3721.241918] Lustre: 108884:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 3721.257719] Lustre: 108884:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 12 previous similar messages [ 3721.270796] Lustre: 108884:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 3721.288319] Lustre: 108884:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 12 previous similar messages [ 3721.300373] Lustre: 108884:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3721.316634] Lustre: 108884:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 12 previous similar messages [ 3721.322791] Lustre: 108884:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 3721.328551] Lustre: 108884:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 12 previous similar messages [ 3721.336571] Lustre: 108884:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 3721.343600] Lustre: 108884:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 12 previous similar messages [ 3721.349469] Lustre: 108884:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3721.353890] Lustre: 108884:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 12 previous similar messages [ 3723.755795] Lustre: *** cfs_fail_loc=1617, val=0*** [ 3723.875991] Lustre: *** cfs_fail_loc=1617, val=0*** [ 3725.948793] Lustre: *** cfs_fail_loc=1616, val=0*** [ 3725.952322] Lustre: Skipped 1 previous similar message [ 3744.009295] Lustre: DEBUG MARKER: == sanity-lfsck test 18d: Find out orphan OST-object and repair it (4) ========================================================== 13:54:08 (1787853248) [ 3746.149307] Lustre: *** cfs_fail_loc=1618, val=0*** [ 3746.152280] Lustre: Skipped 5 previous similar messages [ 3780.070318] 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 [ 3780.071546] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3780.079370] Lustre: Skipped 3 previous similar messages [ 3780.082904] Lustre: Skipped 3 previous similar messages [ 3785.187814] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3785.196486] Lustre: Skipped 3 previous similar messages [ 3785.298425] Lustre: server umount lustre-MDT0000 complete [ 3788.565109] LustreError: 108869:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787853294 with bad export cookie 7078262938038328758 [ 3788.568701] LustreError: MGC192.168.206.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3788.573980] LustreError: 108869:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 3788.884179] Lustre: server umount lustre-MDT0001 complete [ 3803.832050] Lustre: server umount lustre-OST0000 complete [ 3806.496406] Lustre: 106038:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787853296/real 1787853296] req@ffff9a8d8bdc2940 x1874699774792704/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787853312 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3806.542154] 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 [ 3808.761228] Lustre: server umount lustre-OST0001 complete [ 3826.617389] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing load_modules_local [ 3836.335264] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3836.792779] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3841.292148] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3842.016752] LustreError: 117568:0:(ldlm_lib.c:1200: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. [ 3842.037054] LustreError: 117568:0:(ldlm_lib.c:1200:target_handle_connect()) Skipped 2 previous similar messages [ 3846.115275] LustreError: 117569:0:(ldlm_lib.c:1200: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. [ 3849.974722] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3850.345304] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 3855.367646] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3858.147397] Lustre: 118709:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3864.452569] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3869.820152] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3875.941036] LustreError: 119062:0:(ldlm_lib.c:1200: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. [ 3875.946240] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:4 to 0x280000400:33) [ 3878.098442] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3878.274489] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 3878.278311] Lustre: Skipped 1 previous similar message [ 3881.399991] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:116 to 0x280000401:161) [ 3881.409749] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:4 to 0x2c0000401:33) [ 3881.424664] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:33) [ 3883.977411] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3891.196469] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3894.708993] Lustre: 120578:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 3907.704610] Lustre: DEBUG MARKER: == sanity-lfsck test 18e: Find out orphan OST-object and repair it (5) ========================================================== 13:56:51 (1787853411) [ 3908.128833] Lustre: 119447:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 252 < left 278, rollback = 2 [ 3908.135294] Lustre: 119447:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 46 previous similar messages [ 3908.141686] Lustre: 119447:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 3908.146339] Lustre: 119447:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 3908.150151] Lustre: 119447:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3908.157660] Lustre: 119447:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 3908.162181] Lustre: 119447:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/1 [ 3908.172160] Lustre: 119447:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 3908.179743] Lustre: 119447:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 3908.184913] Lustre: 119447:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 3908.192079] Lustre: 119447:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3908.199988] Lustre: 119447:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 3909.856845] Lustre: *** cfs_fail_loc=1618, val=0*** [ 3909.858924] Lustre: Skipped 3 previous similar messages [ 3942.879703] 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 [ 3942.883864] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3942.894297] Lustre: Skipped 2 previous similar messages [ 3942.897321] Lustre: Skipped 1 previous similar message [ 3947.488045] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3947.491908] 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 [ 3947.510925] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3947.514490] Lustre: Skipped 1 previous similar message [ 3948.893181] Lustre: server umount lustre-MDT0000 complete [ 3951.026169] LustreError: 117568:0:(ldlm_lib.c:1200: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. [ 3951.053896] LustreError: 117568:0:(ldlm_lib.c:1200:target_handle_connect()) Skipped 3 previous similar messages [ 3952.251173] LustreError: 117548:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787853458 with bad export cookie 7078262938038343997 [ 3952.254881] LustreError: MGC192.168.206.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3952.260818] LustreError: 117548:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 3952.579196] Lustre: server umount lustre-MDT0001 complete [ 3966.965785] Lustre: server umount lustre-OST0000 complete [ 3981.042874] Lustre: server umount lustre-OST0001 complete [ 3997.726374] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing load_modules_local [ 4008.615572] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4008.975814] LustreError: 123149:0:(ldlm_lib.c:1200: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. [ 4009.080479] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4013.459549] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4019.680762] LustreError: 123150:0:(ldlm_lib.c:1200: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. [ 4019.695884] LustreError: 123150:0:(ldlm_lib.c:1200:target_handle_connect()) Skipped 2 previous similar messages [ 4022.071781] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4027.286397] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4030.225390] Lustre: 124290:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 4036.629261] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4043.502829] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4047.210269] LustreError: 124644:0:(ldlm_lib.c:1200: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. [ 4047.216656] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:4 to 0x280000400:65) [ 4051.533074] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4054.763302] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:65) [ 4054.764690] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:166 to 0x280000401:193) [ 4054.767659] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:4 to 0x2c0000401:65) [ 4057.599934] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4065.016714] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4068.253892] Lustre: 126157:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 4073.512257] Lustre: 123150:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 252 < left 260, rollback = 2 [ 4073.522565] Lustre: 123150:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 21 previous similar messages [ 4073.526709] Lustre: 123150:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4073.530359] Lustre: 123150:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4073.535110] Lustre: 123150:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 0/0/0, xattr_set: 1/260/0 [ 4073.538974] Lustre: 123150:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4073.542794] Lustre: 123150:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/9/0, punch: 0/0/0, quota 4/150/2 [ 4073.549640] Lustre: 123150:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4073.554615] Lustre: 123150:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 1/17/2, delete: 0/0/0 [ 4073.560519] Lustre: 123150:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4073.564703] Lustre: 123150:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 4073.569510] Lustre: 123150:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4073.570274] Lustre: *** cfs_fail_loc=1602, val=10*** [ 4096.656383] Lustre: DEBUG MARKER: == sanity-lfsck test 18f: Skip the failed OST(s) when handle orphan OST-objects ========================================================== 14:00:01 (1787853601) [ 4099.935336] Lustre: *** cfs_fail_loc=1616, val=0*** [ 4099.937325] Lustre: Skipped 3 previous similar messages [ 4107.013673] Lustre: *** cfs_fail_loc=161c, val=0*** [ 4107.019593] Lustre: Skipped 1 previous similar message [ 4124.390588] Lustre: DEBUG MARKER: == sanity-lfsck test 18g: Find out orphan OST-object and repair it (7) ========================================================== 14:00:28 (1787853628) [ 4126.389495] Lustre: *** cfs_fail_loc=162e, val=0*** [ 4139.533343] Lustre: DEBUG MARKER: == sanity-lfsck test 18h: LFSCK can repair crashed PFL extent range ========================================================== 14:00:44 (1787853644) [ 4144.678583] Lustre: *** cfs_fail_loc=162f, val=0*** [ 4144.682704] Lustre: Skipped 9 previous similar messages [ 4161.409967] Lustre: DEBUG MARKER: == sanity-lfsck test 18i: LFSCK can repair crashed PFL with compression ========================================================== 14:01:05 (1787853665) [ 4183.497715] Lustre: DEBUG MARKER: == sanity-lfsck test 19a: OST-object inconsistency self detect ========================================================== 14:01:27 (1787853687) [ 4194.850554] Lustre: DEBUG MARKER: == sanity-lfsck test 19b: OST-object inconsistency self repair ========================================================== 14:01:39 (1787853699) [ 4197.779523] Lustre: *** cfs_fail_loc=1611, val=0*** [ 4197.823719] Lustre: *** cfs_fail_loc=1611, val=0*** [ 4197.828845] Lustre: Skipped 3 previous similar messages [ 4202.676459] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.206.11@tcp inode [0x2000013a1:0x25:0x0] object 0x280000401:204 extent [0-4095], client returned csum 0 (type 4), server csum 703fb3ad (type 4) [ 4203.379585] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.206.11@tcp inode [0x2000013a1:0x26:0x0] object 0x280000401:205 extent [0-4095], client returned csum 0 (type 4), server csum 7cbb935c (type 4) [ 4210.518262] Lustre: DEBUG MARKER: == sanity-lfsck test 20a: Handle the orphan with dummy LOV EA slot properly ========================================================== 14:01:54 (1787853714) [ 4210.858678] Lustre: 123145:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 253 < left 278, rollback = 2 [ 4210.864872] Lustre: 123145:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 116 previous similar messages [ 4210.874260] Lustre: 123145:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4210.881464] Lustre: 123145:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 116 previous similar messages [ 4210.886585] Lustre: 123145:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4210.891618] Lustre: 123145:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 116 previous similar messages [ 4210.898358] Lustre: 123145:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/1 [ 4210.904565] Lustre: 123145:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 116 previous similar messages [ 4210.909443] Lustre: 123145:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 4210.913713] Lustre: 123145:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 116 previous similar messages [ 4210.918585] Lustre: 123145:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4210.923526] Lustre: 123145:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 116 previous similar messages [ 4212.896595] Lustre: *** cfs_fail_loc=1616, val=0*** [ 4212.902154] Lustre: Skipped 3 previous similar messages [ 4258.928325] Lustre: DEBUG MARKER: == sanity-lfsck test 20b: Handle the orphan with dummy LOV EA slot properly - PFL case ========================================================== 14:02:43 (1787853763) [ 4265.129618] Lustre: DEBUG MARKER: == sanity-lfsck test 21: run all LFSCK components by default ========================================================== 14:02:49 (1787853769) [ 4276.011951] Lustre: DEBUG MARKER: == sanity-lfsck test 22a: LFSCK can repair unmatched pairs (1) ========================================================== 14:03:00 (1787853780) [ 4278.098996] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4278.105518] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4278.110068] Lustre: Skipped 1 previous similar message [ 4287.895528] Lustre: DEBUG MARKER: == sanity-lfsck test 22b: LFSCK can repair unmatched pairs (2) ========================================================== 14:03:12 (1787853792) [ 4289.146958] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4289.150816] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4299.801831] Lustre: DEBUG MARKER: == sanity-lfsck test 23a: LFSCK can repair dangling name entry (1) ========================================================== 14:03:24 (1787853804) [ 4301.490073] Lustre: *** cfs_fail_loc=1620, val=0*** [ 4313.655655] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_23b skipping excluded test 23b [ 4315.047118] Lustre: DEBUG MARKER: == sanity-lfsck test 23c: LFSCK can repair dangling name entry (3) ========================================================== 14:03:39 (1787853819) [ 4321.271951] Lustre: *** cfs_fail_loc=1621, val=127*** [ 4321.274582] Lustre: Skipped 1 previous similar message [ 4323.950601] Lustre: *** cfs_fail_loc=1602, val=10*** [ 4346.023266] Lustre: DEBUG MARKER: == sanity-lfsck test 23d: LFSCK can repair a dangling name entry to a remote object ========================================================== 14:04:10 (1787853850) [ 4349.167666] Lustre: Failing over lustre-MDT0000 [ 4349.494593] Lustre: server umount lustre-MDT0000 complete [ 4350.444996] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4350.465804] 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 [ 4350.493244] LustreError: 126419:0:(ldlm_lib.c:1200: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. [ 4358.813866] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4358.990520] LustreError: MGC192.168.206.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4359.264359] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4359.274716] Lustre: Skipped 3 previous similar messages [ 4359.348820] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4363.122925] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4363.537917] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4364.282220] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4364.322141] Lustre: lustre-MDT0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 4364.355698] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:267 to 0x280000401:289) [ 4364.359724] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:131 to 0x2c0000401:161) [ 4365.636848] LustreError: 130358:0:(mdt_open.c:1324:mdt_cross_open()) lustre-MDT0000: [0x2000013a3:0x82:0x0] doesn't exist!: rc = -14 [ 4376.125459] Lustre: DEBUG MARKER: == sanity-lfsck test 24: LFSCK can repair multiple-referenced name entry ========================================================== 14:04:40 (1787853880) [ 4378.095236] Lustre: *** cfs_fail_loc=1622, val=0*** [ 4378.225986] Lustre: *** cfs_fail_loc=1622, val=0*** [ 4378.228840] Lustre: Skipped 1 previous similar message [ 4391.411957] Lustre: DEBUG MARKER: == sanity-lfsck test 25: LFSCK can repair bad file type in the name entry ========================================================== 14:04:54 (1787853894) [ 4393.338324] Lustre: *** cfs_fail_loc=1623, val=0*** [ 4404.941335] Lustre: DEBUG MARKER: == sanity-lfsck test 26a: LFSCK can add the missing local name entry back to the namespace ========================================================== 14:05:09 (1787853909) [ 4406.762650] Lustre: *** cfs_fail_loc=1624, val=0*** [ 4418.035281] Lustre: DEBUG MARKER: == sanity-lfsck test 26b: LFSCK can add the missing remote name entry back to the namespace ========================================================== 14:05:22 (1787853922) [ 4432.355050] Lustre: DEBUG MARKER: == sanity-lfsck test 27a: LFSCK can recreate the lost local parent directory as orphan ========================================================== 14:05:36 (1787853936) [ 4434.152275] Lustre: *** cfs_fail_loc=1624, val=0*** [ 4434.155546] Lustre: Skipped 1 previous similar message [ 4445.405927] Lustre: DEBUG MARKER: == sanity-lfsck test 27b: LFSCK can recreate the lost remote parent directory as orphan ========================================================== 14:05:49 (1787853949) [ 4457.514390] Lustre: DEBUG MARKER: == sanity-lfsck test 28: Skip the failed MDT(s) when handle orphan MDT-objects ========================================================== 14:06:01 (1787853961) [ 4463.353975] Lustre: *** cfs_fail_loc=161c, val=0*** [ 4478.024265] Lustre: DEBUG MARKER: == sanity-lfsck test 29b: LFSCK can repair bad nlink count (2) ========================================================== 14:06:22 (1787853982) [ 4478.956521] Lustre: 123144:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 4478.965423] Lustre: 123144:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 518 previous similar messages [ 4478.971742] Lustre: 123144:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 4478.984136] Lustre: 123144:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 518 previous similar messages [ 4478.994830] Lustre: 123144:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4479.021891] Lustre: 123144:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 518 previous similar messages [ 4479.035565] Lustre: 123144:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 4479.042488] Lustre: 123144:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 518 previous similar messages [ 4479.057284] Lustre: 123144:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 4479.069803] Lustre: 123144:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 518 previous similar messages [ 4479.075778] Lustre: 123144:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4479.080497] Lustre: 123144:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 518 previous similar messages [ 4480.496850] Lustre: *** cfs_fail_loc=1626, val=0*** [ 4480.504033] Lustre: Skipped 4 previous similar messages [ 4492.226711] Lustre: DEBUG MARKER: == sanity-lfsck test 29c: verify linkEA size limitation == 14:06:36 (1787853996) [ 4520.671158] Lustre: DEBUG MARKER: == sanity-lfsck test 29d: accessing non-existing inode shouldn't turn fs read-only (ldiskfs) ========================================================== 14:07:04 (1787854024) [ 4523.803432] LustreError: 123144:0:(osd_handler.c:284:osd_idc_find_or_init()) lustre-MDT0000: cannot lookup FID [0x2000013a3:0x9e:0x0]: rc = -2 [ 4531.255547] Lustre: DEBUG MARKER: == sanity-lfsck test 30: LFSCK can recover the orphans from backend /lost+found ========================================================== 14:07:15 (1787854035) [ 4554.831413] Lustre: Failing over lustre-MDT0000 [ 4555.209234] Lustre: server umount lustre-MDT0000 complete [ 4558.817425] 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 [ 4558.820428] LustreError: 123144:0:(ldlm_lib.c:1200: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. [ 4558.837783] Lustre: Skipped 5 previous similar messages [ 4558.881726] LustreError: 123144:0:(ldlm_lib.c:1200:target_handle_connect()) Skipped 13 previous similar messages [ 4566.705239] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 4566.819320] LustreError: MGC192.168.206.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4567.024168] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4567.086621] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4571.891189] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4572.131443] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4572.139798] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4572.153315] Lustre: Skipped 3 previous similar messages [ 4572.196631] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4572.248538] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:167 to 0x2c0000401:193) [ 4572.250278] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:294 to 0x280000401:321) [ 4586.396329] Lustre: DEBUG MARKER: == sanity-lfsck test 31a: The LFSCK can find/repair the name entry with bad name hash (1) ========================================================== 14:08:10 (1787854090) [ 4604.361898] Lustre: DEBUG MARKER: == sanity-lfsck test 31b: The LFSCK can find/repair the name entry with bad name hash (2) ========================================================== 14:08:28 (1787854108) [ 4622.043972] Lustre: DEBUG MARKER: == sanity-lfsck test 31c: Re-generate the lost master LMV EA for striped directory ========================================================== 14:08:46 (1787854126) [ 4623.490600] Lustre: *** cfs_fail_loc=1629, val=0*** [ 4623.492404] Lustre: Skipped 5 previous similar messages [ 4654.104653] Lustre: DEBUG MARKER: == sanity-lfsck test 31d: Set broken striped directory (modified after broken) as read-only ========================================================== 14:09:18 (1787854158) [ 4661.547300] Lustre: Failing over lustre-MDT0000 [ 4661.874810] Lustre: server umount lustre-MDT0000 complete [ 4664.289180] 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 [ 4664.294552] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4664.311228] Lustre: Skipped 3 previous similar messages [ 4671.447993] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4671.603894] LustreError: MGC192.168.206.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4671.829708] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4675.941859] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4677.091930] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4677.098817] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 4677.113079] Lustre: Skipped 3 previous similar messages [ 4677.132718] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4677.176817] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:167 to 0x2c0000401:225) [ 4677.176965] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:294 to 0x280000401:353) [ 4686.344767] Lustre: Failing over lustre-MDT0000 [ 4686.669376] Lustre: server umount lustre-MDT0000 complete [ 4687.329356] LustreError: 123145:0:(ldlm_lib.c:1200: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. [ 4687.337020] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4687.350505] LustreError: 123145:0:(ldlm_lib.c:1200:target_handle_connect()) Skipped 12 previous similar messages [ 4695.815338] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4695.919377] LustreError: MGC192.168.206.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4696.329650] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4698.484567] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4701.683589] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4701.700350] Lustre: Skipped 3 previous similar messages [ 4701.763093] Lustre: lustre-MDT0000: Recovery over after 0:03, of 2 clients 2 recovered and 0 were evicted. [ 4701.819058] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:294 to 0x280000401:385) [ 4701.825227] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:227 to 0x2c0000401:257) [ 4702.003137] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4712.487374] Lustre: DEBUG MARKER: == sanity-lfsck test 31e: Re-generate the lost slave LMV EA for striped directory (1) ========================================================== 14:10:16 (1787854216) [ 4725.764530] Lustre: DEBUG MARKER: == sanity-lfsck test 31f: Re-generate the lost slave LMV EA for striped directory (2) ========================================================== 14:10:30 (1787854230) [ 4737.462260] Lustre: DEBUG MARKER: == sanity-lfsck test 31g: Repair the corrupted slave LMV EA ========================================================== 14:10:41 (1787854241) [ 4776.213912] Lustre: DEBUG MARKER: == sanity-lfsck test 31h: Repair the corrupted shard's name entry ========================================================== 14:11:20 (1787854280) [ 4790.937501] Lustre: DEBUG MARKER: == sanity-lfsck test 32a: stop LFSCK when some OST failed ========================================================== 14:11:35 (1787854295) [ 4800.650944] LustreError: 148257:0:(lfsck_layout.c:4564:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d sleeping for 3000ms [ 4803.721564] LustreError: 148257:0:(lfsck_layout.c:4564:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d awake [ 4803.738422] LustreError: 148257:0:(lfsck_layout.c:4564:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d sleeping for 3000ms [ 4803.803237] Lustre: Failing over lustre-OST0000 [ 4803.931981] Lustre: server umount lustre-OST0000 complete [ 4804.069869] Lustre: lustre-OST0000-osc-MDT0000: Connection to lustre-OST0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 4804.083265] Lustre: Skipped 6 previous similar messages [ 4806.807127] LustreError: 148257:0:(lfsck_layout.c:4564:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d awake [ 4806.827073] LustreError: 148257:0:(lfsck_layout.c:4564:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d sleeping for 3000ms [ 4807.057111] LustreError: 148257:0:(lfsck_layout.c:4564:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout interrupted [ 4818.896745] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 4819.199096] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 4821.093420] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4821.114631] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 4821.115275] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 4821.129705] Lustre: Skipped 3 previous similar messages [ 4824.782628] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4834.661292] Lustre: DEBUG MARKER: == sanity-lfsck test 32b: stop LFSCK when some MDT failed ========================================================== 14:12:18 (1787854338) [ 4851.492255] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing load_modules_local [ 4869.860683] Lustre: 151063:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 4892.928833] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4897.303591] Lustre: 152199:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 4911.024695] LustreError: 152331:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d sleeping for 3000ms [ 4913.310407] Lustre: Failing over lustre-MDT0001 [ 4914.055175] LustreError: 152331:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d awake [ 4914.089788] LustreError: lustre-MDT0001-osp-MDT0000: operation out_update to node 0@lo failed: rc = -107 [ 4914.096360] 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 [ 4914.103247] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 4914.105632] Lustre: Skipped 3 previous similar messages [ 4914.241123] Lustre: server umount lustre-MDT0001 complete [ 4916.744158] LustreError: 152330:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout interrupted [ 4928.217741] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 4928.540409] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 4928.544453] Lustre: Skipped 3 previous similar messages [ 4928.582019] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 4933.326784] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4933.602407] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4933.610511] Lustre: lustre-MDT0001-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 4933.626360] Lustre: Skipped 1 previous similar message [ 4933.641685] Lustre: lustre-MDT0001: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4933.681463] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:71 to 0x280000400:97) [ 4933.685507] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:68 to 0x2c0000400:97) [ 4942.434346] Lustre: DEBUG MARKER: == sanity-lfsck test 33: check LFSCK paramters =========== 14:14:06 (1787854446) [ 4956.665422] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing load_modules_local [ 4976.733200] Lustre: 155050:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 4998.604268] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5002.626755] Lustre: 156185:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 5004.953832] Lustre: 123146:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 5004.961163] Lustre: 123146:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 1220 previous similar messages [ 5004.967032] Lustre: 123146:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 5004.971367] Lustre: 123146:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1220 previous similar messages [ 5004.975876] Lustre: 123146:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 5004.985445] Lustre: 123146:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1220 previous similar messages [ 5004.990732] Lustre: 123146:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 5004.996549] Lustre: 123146:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1220 previous similar messages [ 5005.002612] Lustre: 123146:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 5005.007293] Lustre: 123146:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1220 previous similar messages [ 5005.013550] Lustre: 123146:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 5005.019398] Lustre: 123146:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1220 previous similar messages [ 5024.314191] Lustre: DEBUG MARKER: == sanity-lfsck test 34: LFSCK can rebuild the lost agent object ========================================================== 14:15:28 (1787854528) [ 5025.906145] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_34 Only valid for ZFS backend [ 5027.894804] Lustre: DEBUG MARKER: == sanity-lfsck test 35: LFSCK can rebuild the lost agent entry ========================================================== 14:15:32 (1787854532) [ 5034.922818] Lustre: *** cfs_fail_loc=1631, val=0*** [ 5046.240649] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 5046.246256] 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 [ 5046.257649] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5046.264049] Lustre: Skipped 5 previous similar messages [ 5046.289926] Lustre: Skipped 3 previous similar messages [ 5051.370468] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5051.386978] Lustre: Skipped 3 previous similar messages [ 5056.482080] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5056.487150] Lustre: Skipped 3 previous similar messages [ 5060.063169] Lustre: lustre-MDT0000 is waiting for obd_unlinked_exports more than 8 seconds. The obd refcount = 3. Is it stuck? [ 5060.312251] Lustre: server umount lustre-MDT0000 complete [ 5061.606172] LustreError: 123145:0:(ldlm_lib.c:1200: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. [ 5061.630187] LustreError: 123145:0:(ldlm_lib.c:1200:target_handle_connect()) Skipped 27 previous similar messages [ 5063.615457] LustreError: 127266:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787854569 with bad export cookie 7078262938038418078 [ 5063.617667] LustreError: MGC192.168.206.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5063.631660] LustreError: 127266:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 5063.955595] Lustre: server umount lustre-MDT0001 complete [ 5077.853758] Lustre: server umount lustre-OST0000 complete [ 5092.559207] Lustre: server umount lustre-OST0001 complete [ 5109.811135] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing load_modules_local [ 5119.237328] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5123.883543] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5132.810133] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5137.939946] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5141.020584] Lustre: 160091:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 5147.864821] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5154.466512] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5158.445791] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:71 to 0x280000400:129) [ 5163.343158] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5164.592114] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:412 to 0x2c0000401:449) [ 5164.597583] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:540 to 0x280000401:577) [ 5164.658888] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:68 to 0x2c0000400:129) [ 5170.287241] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5178.443325] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5182.770278] Lustre: 161962:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 5192.235508] Lustre: DEBUG MARKER: == sanity-lfsck test 36a: rebuild LOV EA for mirrored file (1) ========================================================== 14:18:16 (1787854696) [ 5194.177786] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36a needs >= 3 OSTs [ 5196.236615] Lustre: DEBUG MARKER: == sanity-lfsck test 36b: rebuild LOV EA for mirrored file (2) ========================================================== 14:18:20 (1787854700) [ 5197.908423] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36b needs >= 3 OSTs [ 5200.030657] Lustre: DEBUG MARKER: == sanity-lfsck test 36c: rebuild LOV EA for mirrored file (3) ========================================================== 14:18:24 (1787854704) [ 5202.200645] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36c needs >= 3 OSTs [ 5203.919641] Lustre: DEBUG MARKER: == sanity-lfsck test 37: LFSCK must skip a ORPHAN ======== 14:18:28 (1787854708) [ 5215.293578] Lustre: DEBUG MARKER: == sanity-lfsck test 38: LFSCK does not break foreign file and reverse is also true ========================================================== 14:18:39 (1787854719) [ 5228.832765] Lustre: DEBUG MARKER: == sanity-lfsck test 39: LFSCK does not break foreign dir and reverse is also true ========================================================== 14:18:52 (1787854732) [ 5243.385040] Lustre: DEBUG MARKER: == sanity-lfsck test 40a: LFSCK correctly fixes lmm_oi in composite layout ========================================================== 14:19:07 (1787854747) [ 5260.164692] Lustre: DEBUG MARKER: == sanity-lfsck test 41: SEL support in LFSCK ============ 14:19:24 (1787854764) [ 5277.161879] Lustre: DEBUG MARKER: == sanity-lfsck test 42: LFSCK repairs inconsistent MDT-object/OST-object encryption flags ========================================================== 14:19:41 (1787854781) [ 5311.229199] Lustre: *** cfs_fail_loc=1632, val=0*** [ 5325.694632] Lustre: DEBUG MARKER: == sanity-lfsck test 43: LFSCK does not loop endlessly on iget failure in scanning-phase1 ========================================================== 14:20:29 (1787854829) [ 5328.992964] Lustre: Failing over lustre-MDT0001 [ 5329.211272] Lustre: server umount lustre-MDT0001 complete [ 5332.961847] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 5332.971286] 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 [ 5336.948046] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5337.572758] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 5337.573535] Lustre: lustre-MDT0001: Aborting client recovery [ 5337.589631] LustreError: 165758:0:(ldlm_lib.c:3039:target_stop_recovery_thread()) lustre-MDT0001: Aborting recovery [ 5337.590810] Lustre: 165782:0:(ldlm_lib.c:2439:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 5337.619959] Lustre: 165782:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0001: disconnect stale client 0bc9bb28-ca81-4702-a61a-143954bb75eb@ [ 5337.632875] Lustre: lustre-MDT0001: disconnecting 2 stale clients [ 5337.642849] Lustre: lustre-MDT0001-osd: cancel update llog [0x240000400:0x1:0x0] [ 5337.653023] Lustre: lustre-MDT0000-osp-MDT0001: cancel update llog [0x200000401:0x1:0x0] [ 5337.709890] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:71 to 0x280000400:161) [ 5337.717063] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:131 to 0x2c0000400:161) [ 5342.184062] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5342.692779] LustreError: lustre-MDT0001-osp-MDT0000: This client was evicted by lustre-MDT0001; in progress operations using this service will fail. [ 5342.705416] Lustre: lustre-MDT0001-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 5342.710327] Lustre: Skipped 3 previous similar messages [ 5345.595097] Lustre: *** cfs_fail_loc=1e2, val=483*** [ 5349.820320] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing wait_import_state FULL osp.lustre-MDT0001-os[pc]-MDT0000.*_server_uuid [ 5350.026528] Lustre: DEBUG MARKER: osp.lustre-MDT0001-os[pc]-MDT0000.*_server_uuid in FULL state after 0 sec [ 5355.656816] Lustre: DEBUG MARKER: == sanity-lfsck test 44: umount while lfsck is stopping == 14:21:00 (1787854860) [ 5364.007067] Lustre: *** cfs_fail_loc=1600, val=3*** [ 5366.611721] Lustre: Failing over lustre-MDT0000 [ 5366.889103] Lustre: server umount lustre-MDT0000 complete [ 5368.291456] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 5375.699918] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5375.785519] LustreError: MGC192.168.206.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5376.075578] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 5376.089808] Lustre: Skipped 2 previous similar messages [ 5378.942201] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 5380.080652] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5381.093272] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 5381.102085] Lustre: Skipped 1 previous similar message [ 5381.139692] Lustre: lustre-MDT0000: Recovery over after 0:03, of 2 clients 2 recovered and 0 were evicted. [ 5381.193851] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:489 to 0x2c0000401:513) [ 5381.196938] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:621 to 0x280000401:641) [ 5388.869497] Lustre: DEBUG MARKER: == sanity-lfsck test 45: LFSCK should fix UID/GID/PROJID of OST object ========================================================== 14:21:33 (1787854893) [ 5414.306094] Lustre: Failing over lustre-OST0000 [ 5414.661533] Lustre: server umount lustre-OST0000 complete [ 5421.680165] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: (null) [ 5433.893460] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5435.250738] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 5435.980432] Lustre: lustre-OST0000: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [ 5439.922734] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5444.616358] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing wait_import_state (FULL|IDLE) os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid 50 [ 5444.753360] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid in FULL state after 0 sec [ 5448.150469] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing wait_import_state (FULL|IDLE) os[cp].lustre-OST0000-osc-MDT0001.ost_server_uuid 50 [ 5448.306360] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0001.ost_server_uuid in FULL state after 0 sec [ 5453.089138] Lustre: DEBUG MARKER: oleg611-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0000-osc-ffff92cb18902000.ost_server_uuid 50 [ 5454.385480] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff92cb18902000.ost_server_uuid in FULL state after 0 sec [ 5499.443032] Lustre: server umount lustre-MDT0000 complete [ 5506.587192] LustreError: 162680:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787855012 with bad export cookie 7078262938038500930 [ 5506.588423] LustreError: MGC192.168.206.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5506.594364] LustreError: 162680:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 5506.910412] Lustre: server umount lustre-MDT0001 complete [ 5523.185965] Lustre: server umount lustre-OST0000 complete [ 5527.523166] Lustre: 106041:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787855017/real 1787855017] req@ffff9a8e9bac4000 x1874699776655488/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787855033 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5531.085140] Lustre: server umount lustre-OST0001 complete [ 5546.486741] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing unload_modules_local [ 5550.269522] Key type lgssc unregistered [ 5550.473441] LNet: 174886:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 5550.488602] LNetError: 174886:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 5550.513694] LNet: Removed LNI 192.168.206.111@tcp [ 5551.307131] Key type .llcrypt unregistered [ 5551.308793] Key type ._llcrypt unregistered [ 5575.554964] Key type ._llcrypt registered [ 5575.556576] Key type .llcrypt registered [ 5575.648717] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_hostid [ 5592.261571] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing load_modules_local [ 5593.174412] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 5593.249889] alg: No test for adler32 (adler32-zlib) [ 5594.370332] Lustre: Lustre: Build Version: 2.17.57_85_gfc6b239 [ 5594.648914] LNet: Added LNI 192.168.206.111@tcp [8/256/0/180] [ 5596.359146] Key type lgssc registered [ 5597.390688] Lustre: Echo OBD driver; http://www.lustre.org/ [ 5646.328644] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing load_modules_local [ 5658.776848] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 5658.809909] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5659.997368] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 5660.017333] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 5660.070245] Lustre: lustre-MDT0000: new disk, initializing [ 5660.137316] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 5660.151387] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 5664.664035] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5677.813485] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5677.909459] Lustre: 179342: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 [ 5677.993972] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 5678.002663] Lustre: Skipped 1 previous similar message [ 5678.118900] Lustre: lustre-MDT0001: new disk, initializing [ 5678.191202] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 5678.218950] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 5678.226756] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 5682.671137] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5687.705490] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 5697.340796] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5697.632947] Lustre: lustre-OST0000: new disk, initializing [ 5697.637994] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 5697.643567] Lustre: 181283:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 5697.698945] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 5700.634229] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 5700.648050] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 5700.717314] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 5703.283217] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5716.106959] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5716.307790] Lustre: lustre-OST0001: new disk, initializing [ 5716.316471] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 5716.329895] Lustre: 182307:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 5716.391491] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 5722.063131] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5726.267092] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 5726.273635] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 5726.332770] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 5733.238128] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5744.822681] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 5750.966403] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 14:27:35 (1787855255) === [ 5752.627530] Lustre: DEBUG MARKER: == sanity-lfsck test complete, duration 5460 sec ========= 14:27:36 (1787855256) [ 5754.733425] Lustre: DEBUG MARKER: === sanity-lfsck: start cleanup 14:27:38 (1787855258) === [ 5758.602176] Lustre: DEBUG MARKER: === sanity-lfsck: finish cleanup 14:27:42 (1787855262) === [ 5765.088385] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 5765.097363] 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 [ 5765.113753] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5767.137773] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5767.138957] 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 [ 5767.143184] Lustre: Skipped 2 previous similar messages [ 5767.165832] Lustre: Skipped 2 previous similar messages [ 5769.158510] Lustre: server umount lustre-MDT0000 complete [ 5776.558745] LustreError: 179336:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787855282 with bad export cookie 14014936299606009516 [ 5776.570860] LustreError: MGC192.168.206.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5776.575670] LustreError: 179336:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 5776.978830] Lustre: server umount lustre-MDT0001 complete [ 5793.759379] Lustre: 176505:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787855283/real 1787855283] req@ffff9a8e9bac6580 x1874701949419520/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787855299 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5793.776764] 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 [ 5794.917822] Lustre: server umount lustre-OST0000 complete [ 5797.407420] Lustre: 176506:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787855287/real 1787855287] req@ffff9a8d97d5f0c0 x1874701949419776/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787855303 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5798.880590] Lustre: 176504:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787855288/real 1787855288] req@ffff9a8d97d5cf00 x1874701949420032/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787855304 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5802.486436] Lustre: server umount lustre-OST0001 complete [ 5819.110794] Lustre: DEBUG MARKER: oleg611-server.virtnet: executing unload_modules_local [ 5821.701303] Key type lgssc unregistered [ 5821.976991] LNet: 185783:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 5821.992342] LNetError: 185783:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 5822.012507] LNet: Removed LNI 192.168.206.111@tcp [ 5822.951152] Key type .llcrypt unregistered [ 5822.957453] Key type ._llcrypt unregistered