[ 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 469463592 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2400.000 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: 2895240K/4306352K available (18435K kernel code, 11221K rwdata, 7248K rodata, 2908K init, 18040K bss, 524580K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] ftrace: allocating 41240 entries in 162 pages [ 0.000000] ftrace: allocated 162 pages with 3 groups [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] rcu: RCU event tracing is enabled. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ 0.000000] rcu: RCU callback double-/use-after-free debug enabled. [ 0.000000] Rude variant of Tasks RCU enabled. [ 0.000000] Tracing variant of Tasks RCU enabled. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 0.000000] NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16 [ 0.000000] random: get_random_bytes called from start_kernel+0x622/0x9a8 with crng_init=0 [ 0.001000] Console: colour *CGA 80x25 [ 0.001000] printk: console [ttyS1] enabled [ 0.001000] ACPI: Core revision 20220331 [ 0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.001010] APIC: Switch to symmetric I/O mode setup [ 0.003208] x2apic enabled [ 0.004010] Switched APIC routing to physical x2apic. [ 0.005013] kvm-guest: setup PV IPIs [ 0.008526] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.009000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x22983777dd9, max_idle_ns: 440795300422 ns [ 0.009030] Calibrating delay loop (skipped) preset value.. 4800.00 BogoMIPS (lpj=2400000) [ 0.010017] pid_max: default: 32768 minimum: 301 [ 0.012005] LSM: Security Framework initializing [ 0.013052] Yama: becoming mindful. [ 0.014036] SELinux: Initializing. [ 0.014851] *** VALIDATE selinux *** [ 0.022685] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.027259] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.029071] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.030122] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.031116] *** VALIDATE tmpfs *** [ 0.033065] *** VALIDATE proc *** [ 0.034260] *** VALIDATE cgroup *** [ 0.035009] *** VALIDATE cgroup2 *** [ 0.036290] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.038127] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.039009] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.040031] Spectre V2 : User space: Vulnerable [ 0.042009] Speculative Store Bypass: Vulnerable [ 0.045000] debug: unmapping init [mem 0xffffffffa3459000-0xffffffffa3460fff] [ 0.047000] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.047706] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.048026] ... version: 2 [ 0.049013] ... bit width: 48 [ 0.050010] ... generic registers: 4 [ 0.051012] ... value mask: 0000ffffffffffff [ 0.052016] ... max period: 00007fffffffffff [ 0.053021] ... fixed-purpose events: 3 [ 0.054014] ... event mask: 000000070000000f [ 0.055317] rcu: Hierarchical SRCU implementation. [ 0.057405] smp: Bringing up secondary CPUs ... [ 0.058592] x86: Booting SMP configuration: [ 0.059030] .... node #0, CPUs: #1 #2 #3 [ 0.063008] smp: Brought up 1 node, 4 CPUs [ 0.065016] smpboot: Max logical packages: 1 [ 0.066017] smpboot: Total of 4 processors activated (19200.00 BogoMIPS) [ 0.133959] node 0 deferred pages initialised in 65ms [ 0.137513] devtmpfs: initialized [ 0.140318] x86/mm: Memory block size: 128MB [ 0.143862] gcov: version magic: 0x41383552 [ 0.147320] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.150097] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.152238] pinctrl core: initialized pinctrl subsystem [ 0.153099] [ 0.153453] ************************************************************* [ 0.155009] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.156007] ** ** [ 0.158009] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.159009] ** ** [ 0.161012] ** This means that this kernel is built to expose internal ** [ 0.163013] ** IOMMU data structures, which may compromise security on ** [ 0.164007] ** your system. ** [ 0.166011] ** ** [ 0.167007] ** If you see this message and you are not debugging the ** [ 0.169012] ** kernel, report this immediately to your vendor! ** [ 0.171011] ** ** [ 0.173014] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.175011] ************************************************************* [ 0.177663] NET: Registered protocol family 16 [ 0.179398] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.182058] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.184059] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.187100] cpuidle: using governor menu [ 0.188833] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.191462] PCI: Using configuration type 1 for base access [ 0.193143] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.202118] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.205021] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.208081] cryptd: max_cpu_qlen set to 1000 [ 0.210165] ACPI: Added _OSI(Module Device) [ 0.212012] ACPI: Added _OSI(Processor Device) [ 0.213010] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.215011] ACPI: Added _OSI(Processor Aggregator Device) [ 0.219388] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.225026] ACPI: Interpreter enabled [ 0.226056] ACPI: PM: (supports S0 S3 S4 S5) [ 0.227014] ACPI: Using IOAPIC for interrupt routing [ 0.228000] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.230458] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.241598] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.243037] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.246021] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.249083] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.254000] acpiphp: Slot [2] registered [ 0.254000] acpiphp: Slot [5] registered [ 0.256120] acpiphp: Slot [6] registered [ 0.257135] acpiphp: Slot [7] registered [ 0.259124] acpiphp: Slot [8] registered [ 0.260106] acpiphp: Slot [9] registered [ 0.261123] acpiphp: Slot [10] registered [ 0.263121] acpiphp: Slot [3] registered [ 0.264092] acpiphp: Slot [4] registered [ 0.265095] acpiphp: Slot [11] registered [ 0.267092] acpiphp: Slot [12] registered [ 0.268124] acpiphp: Slot [13] registered [ 0.270109] acpiphp: Slot [14] registered [ 0.272084] acpiphp: Slot [15] registered [ 0.273117] acpiphp: Slot [16] registered [ 0.275089] acpiphp: Slot [17] registered [ 0.276084] acpiphp: Slot [18] registered [ 0.277090] acpiphp: Slot [19] registered [ 0.279105] acpiphp: Slot [20] registered [ 0.280111] acpiphp: Slot [21] registered [ 0.282109] acpiphp: Slot [22] registered [ 0.283109] acpiphp: Slot [23] registered [ 0.284097] acpiphp: Slot [24] registered [ 0.285119] acpiphp: Slot [25] registered [ 0.287092] acpiphp: Slot [26] registered [ 0.288090] acpiphp: Slot [27] registered [ 0.289083] acpiphp: Slot [28] registered [ 0.290106] acpiphp: Slot [29] registered [ 0.291126] acpiphp: Slot [30] registered [ 0.293144] acpiphp: Slot [31] registered [ 0.294062] PCI host bridge to bus 0000:00 [ 0.296019] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.298022] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.300024] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.302024] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.304023] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.307026] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.309198] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.312101] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.316207] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.327016] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.331521] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.333018] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.336020] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.338023] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.341416] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.343803] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.347049] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.350325] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.355018] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.369019] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.374014] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.379000] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.389016] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.398015] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.423015] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.431112] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.438017] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.442020] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.456015] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.465076] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.468966] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.473016] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.487015] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.495106] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.502015] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.508017] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.522016] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.531698] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.539017] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.548017] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.569017] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 0.584235] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.590019] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.596022] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.609019] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 0.618375] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.620386] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.625486] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.628480] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.630258] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.636100] iommu: Default domain type: Passthrough [ 0.638470] SCSI subsystem initialized [ 0.639101] ACPI: bus type USB registered [ 0.640087] usbcore: registered new interface driver usbfs [ 0.642107] usbcore: registered new interface driver hub [ 0.644081] usbcore: registered new device driver usb [ 0.645172] pps_core: LinuxPPS API ver. 1 registered [ 0.647013] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.650060] PTP clock support registered [ 0.652069] EDAC MC: Ver: 3.0.0 [ 0.654143] PCI: Using ACPI for IRQ routing [ 0.655882] NetLabel: Initializing [ 0.657012] NetLabel: domain hash size = 128 [ 0.658009] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.660082] NetLabel: unlabeled traffic allowed by default [ 0.663077] vgaarb: loaded [ 0.664242] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.665013] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.669305] clocksource: Switched to clocksource kvm-clock [ 0.776776] VFS: Disk quotas dquot_6.6.0 [ 0.778280] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.780955] *** VALIDATE ramfs *** [ 0.782292] *** VALIDATE hugetlbfs *** [ 0.783754] pnp: PnP ACPI init [ 0.786132] pnp: PnP ACPI: found 6 devices [ 0.801579] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.804209] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.805740] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.807901] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.810022] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.812672] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.815520] NET: Registered protocol family 2 [ 0.817965] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.822736] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.826343] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.830893] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.834178] TCP: Hash tables configured (established 65536 bind 65536) [ 0.836967] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.839778] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.842511] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.845763] NET: Registered protocol family 1 [ 0.848578] RPC: Registered named UNIX socket transport module. [ 0.850740] RPC: Registered udp transport module. [ 0.852509] RPC: Registered tcp transport module. [ 0.854229] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.856630] NET: Registered protocol family 44 [ 0.858149] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.860370] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.862084] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.863800] PCI: CLS 0 bytes, default 64 [ 0.865631] Unpacking initramfs... [ 2.235217] debug: unmapping init [mem 0xffff9196fcc54000-0xffff9196fffbffff] [ 2.239116] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.241566] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.244692] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x22983777dd9, max_idle_ns: 440795300422 ns [ 2.747135] Initialise system trusted keyrings [ 2.749178] Key type blacklist registered [ 2.751319] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.761104] zbud: loaded [ 2.764348] *** VALIDATE nfs *** [ 2.765518] *** VALIDATE nfs4 *** [ 2.767310] pstore: using deflate compression [ 2.770670] Platform Keyring initialized [ 2.869803] NET: Registered protocol family 38 [ 2.871311] Key type asymmetric registered [ 2.872660] Asymmetric key parser 'x509' registered [ 2.874461] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 2.877384] io scheduler mq-deadline registered [ 2.878966] io scheduler kyber registered [ 2.880413] io scheduler bfq registered [ 2.882326] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 2.884943] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 2.887737] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 2.890682] ACPI: Power Button [PWRF] [ 2.896583] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 2.903649] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 2.920368] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 2.926792] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 2.941768] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 2.970701] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.001396] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.005875] Non-volatile memory driver v1.3 [ 3.007724] Linux agpgart interface v0.103 [ 3.038813] virtio_blk virtio1: [vda] 145176 512-byte logical blocks (74.3 MB/70.9 MiB) [ 3.042350] vda: detected capacity change from 0 to 74330112 [ 3.057107] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.060125] vdb: detected capacity change from 0 to 1073741824 [ 3.076207] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.079349] vdc: detected capacity change from 0 to 2621440000 [ 3.092196] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.094839] vdd: detected capacity change from 0 to 2621440000 [ 3.108262] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.110940] vde: detected capacity change from 0 to 4294967296 [ 3.125070] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.128103] vdf: detected capacity change from 0 to 4294967296 [ 3.135420] libphy: Fixed MDIO Bus: probed [ 3.140573] usbcore: registered new interface driver usbserial_generic [ 3.143080] usbserial: USB Serial support registered for generic [ 3.145537] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.150442] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.152267] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.154535] mousedev: PS/2 mouse device common for all mice [ 3.157608] rtc_cmos 00:05: RTC can wake from S4 [ 3.162633] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.166172] rtc_cmos 00:05: registered as rtc0 [ 3.171462] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.173988] intel_pstate: CPU model not supported [ 3.176817] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.181237] hid: raw HID events driver (C) Jiri Kosina [ 3.183345] usbcore: registered new interface driver usbhid [ 3.185402] usbhid: USB HID core driver [ 3.187054] drop_monitor: Initializing network drop monitor service [ 3.187214] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.188938] Initializing XFRM netlink socket [ 3.193773] NET: Registered protocol family 10 [ 3.196625] Segment Routing with IPv6 [ 3.198334] NET: Registered protocol family 17 [ 3.200835] mpls_gso: MPLS GSO support [ 3.206582] RAS: Correctable Errors collector initialized. [ 3.208784] AVX version of gcm_enc/dec engaged. [ 3.210214] AES CTR mode by8 optimization enabled [ 3.284668] sched_clock: Marking stable (3284629238, 0)->(4159338720, -874709482) [ 3.289699] registered taskstats version 1 [ 3.291673] Loading compiled-in X.509 certificates [ 3.293897] zswap: loaded using pool lzo/zbud [ 3.320618] Key type big_key registered [ 3.334653] Key type encrypted registered [ 3.336171] ima: No TPM chip found, activating TPM-bypass! [ 3.338512] ima: Allocated hash algorithm: sha1 [ 3.339738] ima: No architecture policies found [ 3.341320] evm: Initialising EVM extended attributes: [ 3.342855] evm: security.selinux [ 3.344335] evm: security.ima [ 3.345556] evm: security.capability [ 3.347011] evm: HMAC attrs: 0x1 [ 3.349521] rtc_cmos 00:05: setting system clock to 2026-06-23 13:46:06 UTC (1782222366) [ 3.356726] debug: unmapping init [mem 0xffffffffa4403000-0xffffffffa45fffff] [ 3.360024] debug: unmapping init [mem 0xffffffffa3182000-0xffffffffa3458fff] [ 3.365085] Write protecting the kernel read-only data: 28672k [ 3.368619] debug: unmapping init [mem 0xffffffffa1803000-0xffffffffa19fffff] [ 3.371462] debug: unmapping init [mem 0xffffffffa2114000-0xffffffffa21fffff] [ 3.407921] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 3.416968] systemd[1]: Detected virtualization kvm. [ 3.418903] systemd[1]: Detected architecture x86-64. [ 3.420337] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.442485] systemd[1]: No hostname configured. [ 3.444176] systemd[1]: Set hostname to . [ 3.446519] random: systemd: uninitialized urandom read (16 bytes read) [ 3.448738] systemd[1]: Initializing machine ID from random generator. [ 3.502305] random: ln: uninitialized urandom read (6 bytes read) [ 3.599596] random: systemd: uninitialized urandom read (16 bytes read) [ 3.602564] systemd[1]: Reached target Local File Systems. [ OK ] Reached target Local File Systems. [ 3.608361] systemd[1]: Reached target Swap. [ OK ] Reached target Swap. [ 3.612833] systemd[1]: Reached target Timers. [ OK ] Reached target Timers. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Paths. [ OK ] Reached target Initrd Root Device. [ OK ] Listening on udev Control Socket. [ OK ] Listening on Journal Socket (/dev/log). [ OK ] Listening on Journal Socket. Starting Apply Kernel Variables... Starting Create list of required st…ce nodes for the current kernel... Starting Create Volatile Files and Directories... Starting Setup Virtual Console... [ OK ] Started Memstrack Anylazing Service. Starting Journal Service... [ OK ] Listening on udev Kernel Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Slices. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Started Apply Kernel Variables. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Setup Virtual Console. Starting dracut cmdline hook... Starting Create Static Device Nodes in /dev... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started Journal Service. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 4.322477] device-mapper: uevent: version 1.0.3 [ 4.327609] device-mapper: ioctl: 4.46.0-ioctl (2022-02-22) initialised: dm-devel@redhat.com [ OK ] Started dracut pre-udev hook. Starting udev Kernel Device Manager... [ OK ] Started udev Kernel Device Manager. Starting dracut pre-trigger hook... [ OK ] Started dracut pre-trigger hook. Starting udev Coldplug all Devices... Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting dracut initqueue hook... [ 5.042167] virtio_net virtio0 ens2: renamed from eth0 [ 5.052164] random: fast init done [ 5.128313] scsi host0: ata_piix [ 5.136720] scsi host1: ata_piix [ 5.138437] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 5.140924] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 8.755251] dracut-initqueue[585]: RTNETLINK answers: File exists [ 9.851586] random: crng init done [ 9.853117] random: 7 urandom warning(s) missed due to ratelimiting Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. Mounting /sysroot... [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. [ 10.234878] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped target Timers. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Sockets. [ OK ] Stopped target Slices. [ OK ] Stopped target System Initialization. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Swap. [ OK ] Stopped target Local File Systems. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. Stopping udev Kernel Device Manager... [ OK ] Stopped target Paths. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Closed udev Kernel Socket. [ OK ] Closed udev Control Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 11.376669] printk: systemd: 26 output lines suppressed due to ratelimiting [ 11.637853] SELinux: Disabled at runtime. [ 11.696567] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 11.705807] systemd[1]: Detected virtualization kvm. [ 11.707719] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 12.198568] systemd[1]: initrd-switch-root.service: Succeeded. [ 12.202383] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 12.214609] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 12.221323] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 12.223733] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 12.230860] systemd[1]: Starting Journal Service... Starting Journal Service... [ 12.235373] systemd[1]: Created slice system-sshd\x2dkeygen.slice. [ OK ] Created slice system-sshd\x2dkeygen.slice. Activating swap /dev/disk/by-label/SWAP... [ OK ] Listening on udev Kernel Socket. Mounting POSIX Message Queue File System... [ 12.267438] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Listening on initctl Compatibility Named Pipe. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Listening on udev Control Socket. [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 User and Session Slice. [ OK ] Reached target Slices. [ OK ] Reached target rpc_pipefs.target. [ OK ] Created slice system-getty.slice. Starting Apply Kernel Variables... [ OK ] Listening on Process Core Dump Socket. Mounting Huge Pages File System... [ OK ] Reached target RPC Port Mapper. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Paths. [ OK ] Reached target Local Encrypted Volumes. Starting Remount Root and Kernel File Systems... Mounting Kernel Debug File System... Starting udev Coldplug all Devices... [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd Root File System. [ OK ] Stopped target Initrd File Systems. [ OK ] Started Journal Service. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Apply Kernel Variables. [ 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 ] Mounted Kernel Debug File System. Starting Configure read-only root support... Starting Create Static Device Nodes in /dev... [ OK ] Reached target Swap. Starting Flush Journal to Persistent Storage... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. Starting udev Kernel Device Manager... [ OK ] Reached target Local File Systems (Pre). Mounting /mnt... Mounting /home/green/git/lustre-release... [ OK ] Started udev Coldplug all Devices. [ OK ] Mounted /mnt. [ 12.679086] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 12.926102] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 12.942918] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 13.182455] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 13.191344] EDAC sbridge: Ver: 1.1.2 [ 14.995864] Key type dns_resolver registered [ 15.299992] NFS: Registering the id_resolver key type [ 15.302291] Key type id_resolver registered [ 15.303949] Key type id_legacy registered [ OK ] Started Configure read-only root support. Starting Load/Save Random Seed... [ OK ] Reached target Local File Systems. Starting Mark the need to relabel after reboot... Starting Rebuild Dynamic Linker Cache... Starting Create Volatile Files and Directories... [ OK ] Started Load/Save Random Seed. [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Create Volatile Files and Directories. Starting RPC Bind... Starting Update UTMP about System Boot/Shutdown... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Started dnf makecache --timer. [ OK ] Reached target Timers. [ OK ] Reached target Basic System. Starting Restore /run/initramfs on shutdown... [ OK ] Started irqbalance daemon. Starting Login Service... [ OK ] Started D-Bus System Message Bus. Starting Network Manager... [ OK ] Reached target sshd-keygen.target. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Login Service. [ OK ] Started Network Manager. [ OK ] Reached target Network. Starting OpenSSH server daemon... Starting Dynamic System Tuning Daemon... Starting GSSAPI Proxy Daemon... Starting Network Manager Wait Online... Starting Hostname Service... [ OK ] Started OpenSSH server daemon. [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... [ OK ] Started Permit User Sessions. [ OK ] Started Getty on tty1. [ OK ] Started Command Scheduler. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Serial Getty on ttyS1. [ OK ] Reached target Login Prompts. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting Notify NFS peers of a restart... Starting System Logging Service... Starting Crash recovery kernel arming... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Starting Authorization Manager... [ OK ] Started Authorization Manager. [ OK ] Started Dynamic System Tuning Daemon. [ OK ] Reached target Multi-User System. [ OK ] Reached target Graphical Interface. Starting Update UTMP about System Runlevel Changes... [ OK ] Started Update UTMP about System Runlevel Changes. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg411-server login: [ 43.013049] libcfs: loading out-of-tree module taints kernel. [ 43.032614] Key type ._llcrypt registered [ 43.034283] Key type .llcrypt registered [ 43.091546] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_hostid [ 52.303565] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing load_modules_local [ 53.116570] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 53.127918] alg: No test for adler32 (adler32-zlib) [ 54.157612] Lustre: Lustre: Build Version: 2.17.54_83_g330a3f4 [ 54.520547] LNet: Added LNI 192.168.204.111@tcp [8/256/0/180] [ 56.175363] Key type lgssc registered [ 57.002206] Lustre: Echo OBD driver; http://www.lustre.org/ [ 71.518667] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 98.425265] hrtimer: interrupt took 1707631 ns [ 114.942347] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing load_modules_local [ 129.001467] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 129.035197] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 130.354845] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 130.410442] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 130.528277] Lustre: lustre-MDT0000: new disk, initializing [ 130.620399] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 130.648427] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 135.042778] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 150.103799] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 150.212597] Lustre: 6486:0:(mgs_llog.c:1447:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 150.269525] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 150.278982] Lustre: Skipped 1 previous similar message [ 150.379298] Lustre: lustre-MDT0001: new disk, initializing [ 150.426238] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 150.446607] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 150.458633] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 155.326760] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 161.040581] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 171.535962] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 172.068908] Lustre: lustre-OST0000: new disk, initializing [ 172.075473] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 172.084442] Lustre: 8424:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 172.170359] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 179.225472] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 179.244138] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 179.356628] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 179.691351] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 194.135339] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 194.287499] Lustre: lustre-OST0001: new disk, initializing [ 194.292345] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 194.298593] Lustre: 9496:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 194.349486] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 199.727443] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 204.397996] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 204.411839] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 204.492922] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 210.838489] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 219.351508] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 226.623657] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing check_logdir /tmp/testlogs/ [ 232.602249] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing yml_node [ 236.565310] Lustre: DEBUG MARKER: Client: 2.17.54.83 [ 239.015673] Lustre: DEBUG MARKER: MDS: 2.17.54.83 [ 241.350575] Lustre: DEBUG MARKER: OSS: 2.17.54.83 [ 242.894471] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity-lfsck ============----- Tue Jun 23 09:50:04 EDT 2026 [ 261.187910] Lustre: DEBUG MARKER: excepting tests: 18b 23b [ 271.875513] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing load_modules_local [ 281.569583] 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 [ 281.573292] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 281.585692] Lustre: Skipped 1 previous similar message [ 281.601426] Lustre: Skipped 3 previous similar messages [ 285.661300] Lustre: server umount lustre-MDT0000 complete [ 291.811110] LustreError: 6494:0:(ldlm_lib.c:1179: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. [ 291.819596] LustreError: 6494:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 8 previous similar messages [ 295.247145] LustreError: 6479:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1782222658 with bad export cookie 13861916920170857913 [ 295.248735] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 295.267313] LustreError: 6479:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 295.623078] Lustre: server umount lustre-MDT0001 complete [ 313.183659] Lustre: 3620:0:(client.c:2489:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1782222660/real 1782222660] req@ffff919647ca4a80 x1868795653230464/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1782222676 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 313.224246] 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 [ 313.249917] Lustre: Skipped 2 previous similar messages [ 316.562972] Lustre: server umount lustre-OST0000 complete [ 317.410553] Lustre: 3621:0:(client.c:2489:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1782222664/real 1782222664] req@ffff919647ca4000 x1868795653230720/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1782222680 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 321.505782] Lustre: 3622:0:(client.c:2489:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1782222668/real 1782222668] req@ffff9196470d7100 x1868795653231360/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1782222684 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 321.543062] Lustre: 3622:0:(client.c:2489:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 326.687245] Lustre: server umount lustre-OST0001 complete [ 350.439217] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing unload_modules_local [ 354.724287] Key type lgssc unregistered [ 355.240666] LNet: 14792:0:(lib-ptl.c:967:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 355.247639] LNetError: 14792:0:(acceptor.c:246:lnet_acceptor_remove_socket()) Interface ens2 not found [ 355.272269] LNet: Removed LNI 192.168.204.111@tcp [ 356.350154] Key type .llcrypt unregistered [ 356.357870] Key type ._llcrypt unregistered [ 380.655988] Key type ._llcrypt registered [ 380.661659] Key type .llcrypt registered [ 380.793783] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_hostid [ 397.045158] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing load_modules_local [ 398.375593] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 398.424581] alg: No test for adler32 (adler32-zlib) [ 399.623546] Lustre: Lustre: Build Version: 2.17.54_83_g330a3f4 [ 399.841046] LNet: Added LNI 192.168.204.111@tcp [8/256/0/180] [ 401.511979] Key type lgssc registered [ 402.819993] Lustre: Echo OBD driver; http://www.lustre.org/ [ 454.274646] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing load_modules_local [ 467.900596] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 467.939643] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 469.282177] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 469.327353] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 469.453308] Lustre: lustre-MDT0000: new disk, initializing [ 469.550294] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 469.571293] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 473.987964] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 487.843104] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 487.954601] Lustre: 19248:0:(mgs_llog.c:1447:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 487.994757] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 487.998799] Lustre: Skipped 1 previous similar message [ 488.092236] Lustre: lustre-MDT0001: new disk, initializing [ 488.182301] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 488.227554] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 488.233988] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 493.131221] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 497.832477] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 507.388354] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 507.685105] Lustre: lustre-OST0000: new disk, initializing [ 507.689448] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 507.698698] Lustre: 21185:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 507.777313] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 508.510254] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 508.522463] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 508.587302] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 513.688480] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 525.562281] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 525.722910] Lustre: lustre-OST0001: new disk, initializing [ 525.744248] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 525.750544] Lustre: 22212:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 525.867279] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 532.753049] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 533.064524] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 533.081068] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 533.232803] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 544.422061] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 551.902386] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 561.133419] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 09:55:22 (1782222922) === [ 564.243668] Lustre: DEBUG MARKER: == sanity-lfsck test 0: Control LFSCK manually =========== 09:55:25 (1782222925) [ 564.474944] Lustre: 19255:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 251 < left 278, rollback = 2 [ 564.499432] Lustre: 19255:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 564.506269] Lustre: 19255:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 564.516548] Lustre: 19255:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 564.524262] Lustre: 19255:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 564.540031] Lustre: 19255:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 565.020870] Lustre: 21192:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 565.028054] Lustre: 21192:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 11 previous similar messages [ 565.033933] Lustre: 21192:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 565.046857] Lustre: 21192:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 565.054736] Lustre: 21192:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 565.062140] Lustre: 21192:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 565.069701] Lustre: 21192:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 565.075607] Lustre: 21192:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 565.081249] Lustre: 21192:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 565.086311] Lustre: 21192:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 565.113799] Lustre: 21192:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 565.126736] Lustre: 21192:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 566.057131] Lustre: 21192:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 566.066872] Lustre: 21192:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 41 previous similar messages [ 566.073731] Lustre: 21192:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 566.081576] Lustre: 21192:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 41 previous similar messages [ 566.087555] Lustre: 21192:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 566.096990] Lustre: 21192:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 41 previous similar messages [ 566.104833] Lustre: 21192:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 566.111133] Lustre: 21192:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 41 previous similar messages [ 566.117651] Lustre: 21192:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 566.122789] Lustre: 21192:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 41 previous similar messages [ 566.130637] Lustre: 21192:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 566.136738] Lustre: 21192:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 41 previous similar messages [ 568.094855] Lustre: 19255:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 568.104931] Lustre: 19255:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 95 previous similar messages [ 568.111149] Lustre: 19255:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 568.117501] Lustre: 19255:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 95 previous similar messages [ 568.123928] Lustre: 19255:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 568.131476] Lustre: 19255:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 95 previous similar messages [ 568.139657] Lustre: 19255:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 568.151608] Lustre: 19255:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 95 previous similar messages [ 568.159230] Lustre: 19255:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 568.166718] Lustre: 19255:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 95 previous similar messages [ 568.179259] Lustre: 19255:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 568.185405] Lustre: 19255:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 95 previous similar messages [ 572.289963] Lustre: *** cfs_fail_loc=1600, val=3*** [ 575.125340] Lustre: 21175:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 259 < left 274, rollback = 2 [ 575.145668] Lustre: 23399:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 575.151361] Lustre: 21175:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 133 previous similar messages [ 575.151393] Lustre: 21175:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/1, xattr_set: 2/274/0 [ 575.151398] Lustre: 21175:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 133 previous similar messages [ 575.151406] Lustre: 21175:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 0/0/0, punch: 0/0/0, quota 7/225/0 [ 575.151409] Lustre: 21175:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 133 previous similar messages [ 575.151415] Lustre: 21175:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 575.151418] Lustre: 21175:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 133 previous similar messages [ 575.151424] Lustre: 21175:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 575.151428] Lustre: 21175:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 133 previous similar messages [ 575.332944] Lustre: *** cfs_fail_loc=1600, val=3*** [ 575.343770] Lustre: 23399:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 138 previous similar messages [ 578.709554] Lustre: *** cfs_fail_loc=1600, val=3*** [ 588.677759] Lustre: 21174:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 259 < left 274, rollback = 2 [ 588.677994] Lustre: 23602:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 588.706909] Lustre: 21174:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 54 previous similar messages [ 588.706939] Lustre: 21174:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/1, xattr_set: 2/274/0 [ 588.706944] Lustre: 21174:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 54 previous similar messages [ 588.706950] Lustre: 21174:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 0/0/0, punch: 0/0/0, quota 7/225/0 [ 588.706953] Lustre: 21174:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 54 previous similar messages [ 588.706957] Lustre: 21174:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 588.706960] Lustre: 21174:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 54 previous similar messages [ 588.706966] Lustre: 21174:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 588.706969] Lustre: 21174:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 54 previous similar messages [ 588.843700] Lustre: 23602:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 53 previous similar messages [ 594.913171] 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 [ 594.917560] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 594.933943] Lustre: Skipped 1 previous similar message [ 594.965357] Lustre: Skipped 3 previous similar messages [ 598.052796] Lustre: server umount lustre-MDT0000 complete [ 603.114747] LustreError: 19237:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1782222966 with bad export cookie 15307811760301058774 [ 603.117753] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 603.129903] LustreError: 19237:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 603.496072] Lustre: server umount lustre-MDT0001 complete [ 618.374512] Lustre: server umount lustre-OST0000 complete [ 621.536069] Lustre: 16408:0:(client.c:2489:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1782222968/real 1782222968] req@ffff91964d6ff100 x1868796014999552/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1782222984 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 621.590971] 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 [ 621.607108] Lustre: Skipped 2 previous similar messages [ 622.701164] Lustre: server umount lustre-OST0001 complete [ 632.243706] Lustre: DEBUG MARKER: == sanity-lfsck test 1a: LFSCK can find out and repair crashed FID-in-dirent ========================================================== 09:56:33 (1782222993) [ 646.473835] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing load_modules_local [ 655.535761] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 655.887048] LustreError: 26219:0:(ldlm_lib.c:1179: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. [ 655.897480] LustreError: 26219:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 5 previous similar messages [ 655.958253] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 659.951562] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 660.961427] LustreError: 26220:0:(ldlm_lib.c:1179: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. [ 666.080930] LustreError: 26219:0:(ldlm_lib.c:1179: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.673471] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 668.963958] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 673.482318] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 676.023807] Lustre: 27361:0:(mgs_llog.c:1447:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 682.669023] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 688.436939] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 694.189250] LustreError: 27715:0:(ldlm_lib.c:1179: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.268712] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 696.457859] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 696.465260] Lustre: Skipped 1 previous similar message [ 701.614038] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:40 to 0x2c0000401:65) [ 701.615332] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:41 to 0x280000401:65) [ 702.178793] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 708.879326] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 712.274570] Lustre: 29232:0:(mgs_llog.c:1447:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 714.267872] Lustre: 26215:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 714.273396] Lustre: 26215:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 6 previous similar messages [ 714.287507] Lustre: 26215:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 714.291994] Lustre: 26215:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 3 previous similar messages [ 714.299181] Lustre: 26215:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 714.313452] Lustre: 26215:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 7 previous similar messages [ 714.325423] Lustre: 26215:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 714.332992] Lustre: 26215:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 7 previous similar messages [ 714.338546] Lustre: 26215:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 714.345308] Lustre: 26215:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 7 previous similar messages [ 714.351354] Lustre: 26215:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 714.356408] Lustre: 26215:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 7 previous similar messages [ 720.322906] Lustre: *** cfs_fail_loc=1501, val=0*** [ 729.347872] Lustre: Failing over lustre-MDT0000 [ 729.563695] Lustre: server umount lustre-MDT0000 complete [ 730.592547] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 730.599077] 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.622470] LustreError: 29246:0:(ldlm_lib.c:1179: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.648537] 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 [ 732.663820] Lustre: Skipped 1 previous similar message [ 740.256141] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 740.498489] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 740.730852] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 740.768035] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 745.631873] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 745.963182] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 745.969146] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 745.992125] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 746.031299] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:105 to 0x2c0000401:129) [ 746.033575] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:105 to 0x280000401:129) [ 749.181422] Lustre: *** cfs_fail_loc=1505, val=0*** [ 755.539846] Lustre: DEBUG MARKER: == sanity-lfsck test 1b: LFSCK can find out and repair the missing FID-in-LMA ========================================================== 09:58:37 (1782223117) [ 756.787543] Lustre: 26216:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 256 < left 278, rollback = 2 [ 756.793852] Lustre: 26216:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 322 previous similar messages [ 756.798725] Lustre: 26216:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 756.803623] Lustre: 26216:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 756.808267] Lustre: 26216:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 756.813021] Lustre: 26216:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 756.817598] Lustre: 26216:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 756.822237] Lustre: 26216:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 756.827544] Lustre: 26216:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 756.831935] Lustre: 26216:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 756.836717] Lustre: 26216:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 756.841371] Lustre: 26216:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 762.376353] Lustre: *** cfs_fail_loc=1502, val=0*** [ 773.152618] Lustre: Failing over lustre-MDT0000 [ 773.335939] Lustre: server umount lustre-MDT0000 complete [ 776.675244] 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 [ 776.679187] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 776.681872] LustreError: 26214:0:(ldlm_lib.c:1179: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. [ 776.681882] LustreError: 26214:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 8 previous similar messages [ 776.689829] Lustre: Skipped 3 previous similar messages [ 782.532289] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 782.636363] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 782.862335] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 786.505627] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 787.938891] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 787.953586] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 787.976510] Lustre: Skipped 3 previous similar messages [ 788.007624] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 788.061282] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:169 to 0x280000401:193) [ 788.061471] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:169 to 0x2c0000401:193) [ 789.243087] Lustre: *** cfs_fail_loc=1505, val=0*** [ 795.762837] Lustre: DEBUG MARKER: == sanity-lfsck test 1c: LFSCK can find out and repair lost FID-in-dirent ========================================================== 09:59:17 (1782223157) [ 802.757619] Lustre: *** cfs_fail_loc=1504, val=0*** [ 802.769271] Lustre: *** cfs_fail_loc=1504, val=0*** [ 802.774851] Lustre: Skipped 1 previous similar message [ 811.236573] Lustre: Failing over lustre-MDT0000 [ 811.615829] Lustre: server umount lustre-MDT0000 complete [ 813.536205] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 813.539320] 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 [ 813.543917] LustreError: 26219:0:(ldlm_lib.c:1179: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. [ 813.573099] Lustre: Skipped 3 previous similar messages [ 813.615536] LustreError: 26219:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 10 previous similar messages [ 822.445665] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 822.555764] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 822.708621] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 822.713564] Lustre: Skipped 1 previous similar message [ 822.737980] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 827.578532] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 827.879336] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 827.888063] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 827.898718] Lustre: Skipped 3 previous similar messages [ 827.917223] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 827.952867] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:233 to 0x2c0000401:257) [ 827.961953] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:233 to 0x280000401:257) [ 830.830316] Lustre: *** cfs_fail_loc=1505, val=0*** [ 837.643303] Lustre: DEBUG MARKER: == sanity-lfsck test 2a: LFSCK can find out and repair crashed linkEA entry ========================================================== 09:59:59 (1782223199) [ 839.229495] Lustre: 26215:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 839.245878] Lustre: 26215:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 644 previous similar messages [ 839.252531] Lustre: 26215:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 839.259111] Lustre: 26215:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 839.264354] Lustre: 26215:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 839.270628] Lustre: 26215:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 839.275016] Lustre: 26215:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 839.280041] Lustre: 26215:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 839.290642] Lustre: 26215:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 839.304144] Lustre: 26215:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 839.313514] Lustre: 26215:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 839.319645] Lustre: 26215:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 844.820101] Lustre: *** cfs_fail_loc=1603, val=0*** [ 851.694778] Lustre: Failing over lustre-MDT0000 [ 851.894591] Lustre: server umount lustre-MDT0000 complete [ 853.471536] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 853.476054] 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 [ 853.483847] LustreError: 29246:0:(ldlm_lib.c:1179: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. [ 853.496032] Lustre: Skipped 2 previous similar messages [ 853.530299] LustreError: 29246:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 7 previous similar messages [ 861.843233] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 861.963483] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 862.217173] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 866.256506] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 867.308044] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 867.327717] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 867.328987] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 867.336364] Lustre: Skipped 3 previous similar messages [ 867.385691] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:297 to 0x2c0000401:321) [ 867.386828] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:297 to 0x280000401:321) [ 875.202677] Lustre: DEBUG MARKER: == sanity-lfsck test 2b: LFSCK can find out and remove invalid linkEA entry ========================================================== 10:00:36 (1782223236) [ 882.238497] Lustre: *** cfs_fail_loc=1604, val=0*** [ 889.157745] Lustre: Failing over lustre-MDT0000 [ 889.371646] Lustre: server umount lustre-MDT0000 complete [ 892.899138] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 892.904282] 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 [ 892.926563] Lustre: Skipped 5 previous similar messages [ 900.758390] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 900.974134] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 901.365552] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 906.727157] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 906.729349] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 906.745103] Lustre: Skipped 3 previous similar messages [ 906.777615] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 906.828211] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:361 to 0x280000401:385) [ 906.836321] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:361 to 0x2c0000401:385) [ 907.085588] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 917.325606] Lustre: DEBUG MARKER: == sanity-lfsck test 2c: LFSCK can find out and remove repeated linkEA entry ========================================================== 10:01:18 (1782223278) [ 925.124661] Lustre: *** cfs_fail_loc=1605, val=0*** [ 931.828646] Lustre: Failing over lustre-MDT0000 [ 932.090667] Lustre: server umount lustre-MDT0000 complete [ 932.322436] LustreError: 26216:0:(ldlm_lib.c:1179: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. [ 932.323509] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 932.336949] LustreError: 26216:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 15 previous similar messages [ 941.294393] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 941.379333] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 941.623769] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 945.730953] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 946.665077] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 946.694236] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 946.716335] Lustre: Skipped 3 previous similar messages [ 946.754035] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 946.790439] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:425 to 0x280000401:449) [ 946.791381] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:425 to 0x2c0000401:449) [ 954.456971] Lustre: DEBUG MARKER: == sanity-lfsck test 2d: LFSCK can recover the missing linkEA entry ========================================================== 10:01:56 (1782223316) [ 961.475247] Lustre: *** cfs_fail_loc=161d, val=0*** [ 969.787627] Lustre: Failing over lustre-MDT0000 [ 970.190974] Lustre: server umount lustre-MDT0000 complete [ 972.259888] Lustre: lustre-MDT0000-osp-MDT0001: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 972.278375] Lustre: Skipped 6 previous similar messages [ 972.287181] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 981.183398] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 981.320328] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 981.566756] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 981.574487] Lustre: Skipped 3 previous similar messages [ 981.619296] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 985.714389] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 986.593595] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 986.599094] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 986.603635] Lustre: Skipped 3 previous similar messages [ 986.622894] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 986.688986] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:489 to 0x2c0000401:513) [ 986.698969] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:489 to 0x280000401:513) [ 995.171971] Lustre: DEBUG MARKER: == sanity-lfsck test 2e: namespace LFSCK can verify remote object linkEA ========================================================== 10:02:36 (1782223356) [ 996.591832] Lustre: 26216:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 996.602588] Lustre: 26216:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 1290 previous similar messages [ 996.612184] Lustre: 26216:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 996.619549] Lustre: 26216:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1290 previous similar messages [ 996.634886] Lustre: 26216:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 996.645181] Lustre: 26216:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1290 previous similar messages [ 996.652360] Lustre: 26216:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 996.661069] Lustre: 26216:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1290 previous similar messages [ 996.669827] Lustre: 26216:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 996.687257] Lustre: 26216:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1290 previous similar messages [ 996.707789] Lustre: 26216:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 996.718297] Lustre: 26216:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1290 previous similar messages [ 998.098582] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1009.235021] Lustre: DEBUG MARKER: == sanity-lfsck test 3: LFSCK can verify multiple-linked objects ========================================================== 10:02:50 (1782223370) [ 1016.444406] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1017.501530] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1029.638452] Lustre: DEBUG MARKER: == sanity-lfsck test 4: FID-in-dirent can be rebuilt after MDT file-level backup/restore ========================================================== 10:03:11 (1782223391) [ 1065.472220] Lustre: Failing over lustre-MDT0000 [ 1066.062256] Lustre: server umount lustre-MDT0000 complete [ 1068.512388] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1068.521334] LustreError: 26214:0:(ldlm_lib.c:1179: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. [ 1068.541068] LustreError: 26214:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 15 previous similar messages [ 1072.686849] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1083.816507] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1083.871186] Lustre: 16410:0:(client.c:2489:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1782223431/real 1782223431] req@ffff91977e66ca80 x1868796015611776/t0(0) o400->MGC192.168.204.111@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1782223447 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1083.897585] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1097.755920] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1097.783884] Lustre: lustre-MDT0000: reset Object Index mappings [ 1109.471969] LustreError: 16406:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff91977d4a1f80 x1868796015622656/t0(0) o250->MGC192.168.204.111@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 0 ref 1 fl Rpc:NQU/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1109.984757] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1114.736402] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1115.104546] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1115.118719] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1115.133733] Lustre: Skipped 3 previous similar messages [ 1115.170417] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1115.228639] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:592 to 0x2c0000401:609) [ 1115.239211] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:592 to 0x280000401:609) [ 1118.771726] LustreError: 42884:0:(lfsck_engine.c:1018:lfsck_master_engine()) lustre-MDT0000-osd: master engine fail to verify the .lustre/lost+found/, go ahead: rc = -115 [ 1118.786514] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1122.912234] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1122.916980] Lustre: Skipped 3 previous similar messages [ 1128.312986] Lustre: Failing over lustre-MDT0000 [ 1128.561766] Lustre: server umount lustre-MDT0000 complete [ 1130.463640] 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 [ 1130.497266] Lustre: Skipped 8 previous similar messages [ 1139.071522] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1144.581438] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1144.908421] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:592 to 0x280000401:641) [ 1144.908422] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:592 to 0x2c0000401:641) [ 1148.085937] Lustre: *** cfs_fail_loc=1505, val=0*** [ 1155.253564] Lustre: DEBUG MARKER: == sanity-lfsck test 5: LFSCK can handle IGIF object upgrading ========================================================== 10:05:16 (1782223516) [ 1158.178664] Lustre: *** cfs_fail_loc=1504, val=0*** [ 1168.740126] Lustre: Failing over lustre-MDT0000 [ 1169.332804] Lustre: server umount lustre-MDT0000 complete [ 1170.404636] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1176.202888] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1186.799510] Lustre: 16409:0:(client.c:2489:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1782223533/real 1782223533] req@ffff91977b427800 x1868796015711616/t0(0) o400->MGC192.168.204.111@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1782223549 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1191.906108] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1206.965812] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1207.001995] Lustre: lustre-MDT0000: reset Object Index mappings [ 1212.384786] LustreError: 16406:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff91977b4e4700 x1868796015724032/t0(0) o250->MGC192.168.204.111@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 0 ref 1 fl Rpc:NQU/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1212.728386] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1212.741847] Lustre: Skipped 1 previous similar message [ 1217.449711] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1218.033523] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1218.042243] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1218.050915] Lustre: Skipped 7 previous similar messages [ 1218.080194] Lustre: Skipped 1 previous similar message [ 1218.111617] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1218.121398] Lustre: Skipped 1 previous similar message [ 1218.168869] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:681 to 0x280000401:705) [ 1218.169609] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:681 to 0x2c0000401:705) [ 1221.642206] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1234.972268] Lustre: Failing over lustre-MDT0000 [ 1235.246843] Lustre: server umount lustre-MDT0000 complete [ 1245.641547] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1245.763737] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1245.775396] LustreError: Skipped 2 previous similar messages [ 1246.030569] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1246.039564] Lustre: Skipped 3 previous similar messages [ 1250.418687] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1251.370766] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:681 to 0x280000401:737) [ 1251.371439] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:681 to 0x2c0000401:737) [ 1254.117596] Lustre: *** cfs_fail_loc=1505, val=0*** [ 1254.119549] Lustre: Skipped 84 previous similar messages [ 1262.239926] Lustre: DEBUG MARKER: == sanity-lfsck test 6a: LFSCK resumes from last checkpoint (1) ========================================================== 10:07:03 (1782223623) [ 1263.922622] Lustre: 27735:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 1263.936537] Lustre: 27735:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 923 previous similar messages [ 1263.944793] Lustre: 27735:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 1263.953676] Lustre: 27735:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 923 previous similar messages [ 1263.962217] Lustre: 27735:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 1263.970991] Lustre: 27735:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 923 previous similar messages [ 1263.980438] Lustre: 27735:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 1263.987210] Lustre: 27735:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 923 previous similar messages [ 1263.995508] Lustre: 27735:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 1264.004438] Lustre: 27735:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 923 previous similar messages [ 1264.011759] Lustre: 27735:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 1264.018250] Lustre: 27735:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 923 previous similar messages [ 1271.451585] Lustre: *** cfs_fail_loc=1600, val=1*** [ 1271.453619] Lustre: Skipped 8 previous similar messages [ 1294.369055] Lustre: DEBUG MARKER: == sanity-lfsck test 6b: LFSCK resumes from last checkpoint (2) ========================================================== 10:07:35 (1782223655) [ 1304.094183] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1304.106130] Lustre: Skipped 9 previous similar messages [ 1330.135752] Lustre: DEBUG MARKER: == sanity-lfsck test 7a: non-stopped LFSCK should auto restarts after MDS remount (1) ========================================================== 10:08:11 (1782223691) [ 1348.774038] Lustre: Failing over lustre-MDT0000 [ 1349.109555] Lustre: server umount lustre-MDT0000 complete [ 1353.698698] LustreError: 26216:0:(ldlm_lib.c:1179: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. [ 1353.731727] LustreError: 26216:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 91 previous similar messages [ 1358.568070] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1358.937361] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1358.940627] Lustre: Skipped 1 previous similar message [ 1363.474556] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1363.938401] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1363.943581] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1363.950126] Lustre: Skipped 1 previous similar message [ 1363.957521] Lustre: Skipped 7 previous similar messages [ 1363.998655] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1364.008273] Lustre: Skipped 1 previous similar message [ 1364.096110] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:853 to 0x280000401:897) [ 1364.105943] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:854 to 0x2c0000401:897) [ 1372.988286] Lustre: DEBUG MARKER: == sanity-lfsck test 7b: non-stopped LFSCK should auto restarts after MDS remount (2) ========================================================== 10:08:54 (1782223734) [ 1388.394487] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing load_modules_local [ 1406.302657] Lustre: 52983:0:(mgs_llog.c:1447:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 1429.024783] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1432.522642] Lustre: 54119:0:(mgs_llog.c:1447:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 1440.551587] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1440.555139] Lustre: Skipped 81 previous similar messages [ 1443.740967] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1444.768895] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1445.791241] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1447.839092] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1447.846759] Lustre: Skipped 1 previous similar message [ 1448.860269] Lustre: Failing over lustre-MDT0000 [ 1449.254324] Lustre: server umount lustre-MDT0000 complete [ 1450.991304] 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 [ 1450.992862] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1451.016955] Lustre: Skipped 12 previous similar messages [ 1459.141531] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1463.308698] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1464.922814] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:947 to 0x2c0000401:993) [ 1464.932536] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:946 to 0x280000401:961) [ 1472.850276] Lustre: DEBUG MARKER: == sanity-lfsck test 8: LFSCK state machine ============== 10:10:34 (1782223834) [ 1475.040513] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1480.163092] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1480.172664] Lustre: Skipped 6 previous similar messages [ 1485.280520] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1485.291967] Lustre: Skipped 3 previous similar messages [ 1489.375147] Lustre: lustre-MDT0000 is waiting for obd_unlinked_exports more than 8 seconds. The obd refcount = 3. Is it stuck? [ 1489.509493] Lustre: server umount lustre-MDT0000 complete [ 1493.603387] LustreError: 26200:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1782223856 with bad export cookie 15307811760301272673 [ 1493.619162] LustreError: 26200:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 1493.841729] Lustre: server umount lustre-MDT0001 complete [ 1508.725965] Lustre: server umount lustre-OST0000 complete [ 1510.883164] Lustre: 16410:0:(client.c:2489:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1782223858/real 1782223858] req@ffff91977ec34380 x1868796016052864/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1782223874 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1512.622548] Lustre: server umount lustre-OST0001 complete [ 1520.581783] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_hostid [ 1530.586435] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing load_modules_local [ 1581.013254] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing load_modules_local [ 1592.941428] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1593.207209] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 1593.245851] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 1593.361961] Lustre: lustre-MDT0000: new disk, initializing [ 1593.475281] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 1598.887966] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1609.775881] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1609.956609] Lustre: 59179:0:(mgs_llog.c:1447:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 1610.028970] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 1610.037242] Lustre: Skipped 1 previous similar message [ 1610.162504] Lustre: lustre-MDT0001: new disk, initializing [ 1610.256425] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 1610.283885] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 1614.670652] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1620.105293] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 1627.080815] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 1627.371561] Lustre: lustre-OST0000: new disk, initializing [ 1627.377390] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 1627.388456] Lustre: 60809:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 1628.582476] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 1628.597526] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 1628.704152] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 1634.453969] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1646.387464] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 1646.482820] Lustre: lustre-OST0001: new disk, initializing [ 1646.486840] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 1646.493328] Lustre: 61682:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 1648.222417] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 1648.234714] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 1648.289840] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 1653.400761] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1663.564736] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1667.926165] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 1679.336585] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1680.374079] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1680.383877] Lustre: Skipped 19 previous similar messages [ 1686.252581] Lustre: *** cfs_fail_loc=1601, val=2*** [ 1686.258036] Lustre: Skipped 19 previous similar messages [ 1707.299620] Lustre: Failing over lustre-MDT0000 [ 1707.491760] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1707.497873] LustreError: Skipped 1 previous similar message [ 1707.745824] Lustre: server umount lustre-MDT0000 complete [ 1719.221618] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1719.473677] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1719.479788] LustreError: Skipped 3 previous similar messages [ 1719.721014] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1719.731613] Lustre: Skipped 1 previous similar message [ 1724.677119] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1724.902997] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1724.915171] Lustre: Skipped 1 previous similar message [ 1724.925301] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1724.939537] Lustre: Skipped 7 previous similar messages [ 1724.988159] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1725.005514] Lustre: Skipped 1 previous similar message [ 1725.065438] Lustre: *** cfs_fail_loc=160b, val=2*** [ 1725.075957] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:65) [ 1725.076201] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:65) [ 1733.664964] Lustre: Failing over lustre-MDT0000 [ 1733.837906] Lustre: server umount lustre-MDT0000 complete [ 1743.889368] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1748.944019] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1749.565962] Lustre: *** cfs_fail_loc=160b, val=2*** [ 1749.577209] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:97) [ 1749.579907] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:97) [ 1755.239918] Lustre: Failing over lustre-MDT0000 [ 1755.492147] Lustre: server umount lustre-MDT0000 complete [ 1764.290077] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1764.803840] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1764.811914] Lustre: Skipped 8 previous similar messages [ 1770.012461] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:129) [ 1770.018683] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:129) [ 1770.176444] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1776.223828] Lustre: *** cfs_fail_loc=1602, val=2*** [ 1776.227935] Lustre: Skipped 1 previous similar message [ 1790.048726] Lustre: DEBUG MARKER: == sanity-lfsck test 9a: LFSCK speed control (1) ========= 10:15:51 (1782224151) [ 1809.259248] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing load_modules_local [ 1829.031129] Lustre: 68694:0:(mgs_llog.c:1447:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 1853.647779] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1857.278363] Lustre: 69830:0:(mgs_llog.c:1447:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 1868.845824] Lustre: 59183:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 1868.865114] Lustre: 59183:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 2770 previous similar messages [ 1868.879635] Lustre: 59183:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 1868.888090] Lustre: 59183:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 2770 previous similar messages [ 1868.894912] Lustre: 59183:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 1868.902811] Lustre: 59183:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 2770 previous similar messages [ 1868.921144] Lustre: 59183:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 1868.938194] Lustre: 59183:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 2770 previous similar messages [ 1868.952539] Lustre: 59183:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 1868.970174] Lustre: 59183:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 2770 previous similar messages [ 1868.982185] Lustre: 59183:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 1868.995211] Lustre: 59183:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 2770 previous similar messages [ 1991.835948] Lustre: DEBUG MARKER: == sanity-lfsck test 9b: LFSCK speed control (2) ========= 10:19:13 (1782224353) [ 2051.580081] Lustre: *** cfs_fail_loc=1604, val=0*** [ 2051.585828] Lustre: Skipped 4 previous similar messages [ 2081.541582] Lustre: *** cfs_fail_loc=160c, val=0*** [ 2081.544473] Lustre: Skipped 9 previous similar messages [ 2118.072996] Lustre: DEBUG MARKER: == sanity-lfsck test 10: System is available during LFSCK scanning ========================================================== 10:21:19 (1782224479) [ 2171.433463] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2172.441679] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2172.445509] Lustre: Skipped 41 previous similar messages [ 2174.454387] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2174.463122] Lustre: Skipped 98 previous similar messages [ 2178.454608] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2178.457749] Lustre: Skipped 154 previous similar messages [ 2186.455967] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2186.461910] Lustre: Skipped 367 previous similar messages [ 2202.484762] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2202.487366] Lustre: Skipped 744 previous similar messages [ 2234.492956] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2234.495387] Lustre: Skipped 1312 previous similar messages [ 2253.168455] Lustre: *** cfs_fail_loc=1604, val=0*** [ 2253.176493] Lustre: Skipped 2599 previous similar messages [ 2476.045440] Lustre: 60817:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 252 < left 278, rollback = 2 [ 2476.071602] Lustre: 60817:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 36821 previous similar messages [ 2476.085948] Lustre: 60817:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 2476.094603] Lustre: 60817:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 36821 previous similar messages [ 2476.118587] Lustre: 60817:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 2476.129596] Lustre: 60817:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 36821 previous similar messages [ 2476.142333] Lustre: 60817:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/1, punch: 0/0/0, quota 1/3/2 [ 2476.154971] Lustre: 60817:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 36821 previous similar messages [ 2476.177241] Lustre: 60817:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/1, delete: 0/0/0 [ 2476.188960] Lustre: 60817:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 36821 previous similar messages [ 2476.204777] Lustre: 60817:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 2476.216586] Lustre: 60817:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 36821 previous similar messages [ 2526.294798] Lustre: DEBUG MARKER: == sanity-lfsck test 11a: LFSCK can rebuild lost last_id ========================================================== 10:28:07 (1782224887) [ 2698.064814] Lustre: server umount lustre-MDT0000 complete [ 2699.756292] 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 [ 2699.779990] LustreError: 60817:0:(ldlm_lib.c:1179: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. [ 2699.781630] Lustre: Skipped 23 previous similar messages [ 2699.804921] LustreError: 60817:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 36 previous similar messages [ 2702.666479] LustreError: 71534:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1782225065 with bad export cookie 15307811760301291755 [ 2702.668082] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2702.684292] LustreError: 71534:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 2702.707679] LustreError: Skipped 2 previous similar messages [ 2703.157639] Lustre: server umount lustre-MDT0001 complete [ 2717.989682] Lustre: server umount lustre-OST0000 complete [ 2721.824231] Lustre: 16409:0:(client.c:2489:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1782225068/real 1782225068] req@ffff919651b4d180 x1868796019903360/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1782225084 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2722.796724] Lustre: server umount lustre-OST0001 complete [ 2730.087465] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: (null) [ 2739.087639] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 2754.723232] LustreError: Failed to get MGS log lustre-sptlrpc and no local copy. [ 2759.840951] LustreError: 74704:0:(mgc_request.c:233:do_config_log_add()) MGC192.168.204.111@tcp: failed processing log, type 4: rc = -110 [ 2785.503478] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 2793.678604] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2799.312790] Lustre: 75288:0:(ofd_dev.c:561:ofd_lfsck_out_notify()) lustre-OST0000: Found crashed LAST_ID, deny creating new OST-object on the device until the LAST_ID rebuilt successfully. [ 2799.346678] Lustre: *** cfs_fail_loc=160e, val=3*** [ 2802.428405] Lustre: 75288:0:(ofd_dev.c:573:ofd_lfsck_out_notify()) lustre-OST0000: Rebuilt crashed LAST_ID files successfully. [ 2811.538542] Lustre: DEBUG MARKER: == sanity-lfsck test 11b: LFSCK can rebuild crashed last_id ========================================================== 10:32:53 (1782225173) [ 2829.031172] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing load_modules_local [ 2840.412666] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2840.757579] LustreError: 74729:0:(ldlm_lib.c:1179: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. [ 2840.888503] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3271 to 0x280000401:3297) [ 2845.512372] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2854.452587] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2859.557991] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2862.518837] Lustre: 77906:0:(mgs_llog.c:1447:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 2878.773310] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2884.087290] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3208 to 0x2c0000401:3233) [ 2886.102888] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2893.776711] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 2897.197618] Lustre: 79407:0:(mgs_llog.c:1447:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 2901.733959] Lustre: *** cfs_fail_loc=160d, val=0*** [ 2902.383236] Lustre: *** cfs_fail_loc=160d, val=0*** [ 2902.387358] Lustre: Skipped 3 previous similar messages [ 2908.481310] Lustre: Failing over lustre-OST0000 [ 2908.625725] Lustre: server umount lustre-OST0000 complete [ 2909.665971] 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 [ 2909.696453] Lustre: Skipped 1 previous similar message [ 2919.581932] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2919.940350] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 2919.960744] Lustre: Skipped 2 previous similar messages [ 2921.379464] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 2921.392252] Lustre: Skipped 2 previous similar messages [ 2921.416545] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 2921.417309] Lustre: lustre-OST0000-osc-MDT0001: Connection restored to 0@lo (at 0@lo) [ 2921.422254] Lustre: *** cfs_fail_loc=215, val=0*** [ 2921.432454] Lustre: Skipped 2 previous similar messages [ 2921.469092] Lustre: Skipped 11 previous similar messages [ 2926.565791] Lustre: *** cfs_fail_loc=215, val=0*** [ 2926.580834] Lustre: Skipped 2 previous similar messages [ 2928.791707] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2931.681085] Lustre: *** cfs_fail_loc=215, val=0*** [ 2931.685867] Lustre: Skipped 1 previous similar message [ 2933.258599] Lustre: 80806:0:(ofd_dev.c:561:ofd_lfsck_out_notify()) lustre-OST0000: Found crashed LAST_ID, deny creating new OST-object on the device until the LAST_ID rebuilt successfully. [ 2933.281843] Lustre: 80806:0:(ofd_dev.c:573:ofd_lfsck_out_notify()) lustre-OST0000: Rebuilt crashed LAST_ID files successfully. [ 2935.911591] Lustre: Failing over lustre-OST0000 [ 2935.989386] Lustre: server umount lustre-OST0000 complete [ 2936.802214] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 2936.808702] LustreError: Skipped 3 previous similar messages [ 2945.651106] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2947.704193] Lustre: *** cfs_fail_loc=215, val=0*** [ 2947.713547] Lustre: Skipped 3 previous similar messages [ 2952.262725] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2953.183873] Lustre: *** cfs_fail_loc=215, val=0*** [ 2953.194834] Lustre: Skipped 1 previous similar message [ 2961.377193] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2965.312240] Lustre: server umount lustre-MDT0000 complete [ 2968.652861] LustreError: 74710:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1782225331 with bad export cookie 15307811760302877157 [ 2968.668511] LustreError: 74710:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 2968.927728] Lustre: server umount lustre-MDT0001 complete [ 2983.453593] Lustre: server umount lustre-OST0000 complete [ 2986.980500] Lustre: 16409:0:(client.c:2489:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1782225334/real 1782225334] req@ffff91977b4e4000 x1868796019998208/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1782225350 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2987.498245] Lustre: server umount lustre-OST0001 complete [ 2998.817123] Lustre: DEBUG MARKER: == sanity-lfsck test 12a: single command to trigger LFSCK on all devices ========================================================== 10:35:59 (1782225359) [ 3017.532269] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing load_modules_local [ 3028.304551] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3028.744383] LustreError: 84051:0:(ldlm_lib.c:1179: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. [ 3028.775056] LustreError: 84051:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 31 previous similar messages [ 3033.395649] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3041.910721] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3047.444847] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3050.467481] Lustre: 85193:0:(mgs_llog.c:1447:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3057.509410] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3064.738275] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3073.461896] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3073.531120] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3362 to 0x280000401:3393) [ 3079.159985] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3208 to 0x2c0000401:3265) [ 3080.199919] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3087.914271] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3091.875032] Lustre: 87061:0:(mgs_llog.c:1447:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 3093.149517] Lustre: 85567:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 256 < left 278, rollback = 2 [ 3093.167785] Lustre: 85567:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 400 previous similar messages [ 3093.177539] Lustre: 85567:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 3093.189854] Lustre: 85567:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 400 previous similar messages [ 3093.196518] Lustre: 85567:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3093.203661] Lustre: 85567:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 400 previous similar messages [ 3093.211572] Lustre: 85567:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 3093.216990] Lustre: 85567:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 400 previous similar messages [ 3093.222290] Lustre: 85567:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 3093.227664] Lustre: 85567:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 400 previous similar messages [ 3093.232654] Lustre: 85567:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3093.237365] Lustre: 85567:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 400 previous similar messages [ 3124.859240] Lustre: DEBUG MARKER: == sanity-lfsck test 12b: auto detect Lustre device ====== 10:38:06 (1782225486) [ 3140.020687] Lustre: DEBUG MARKER: == sanity-lfsck test 13: LFSCK can repair crashed lmm_oi ========================================================== 10:38:21 (1782225501) [ 3141.425240] Lustre: *** cfs_fail_loc=160f, val=0*** [ 3152.070773] Lustre: DEBUG MARKER: == sanity-lfsck test 14a: LFSCK can repair MDT-object with dangling LOV EA reference (1) ========================================================== 10:38:33 (1782225513) [ 3155.754686] Lustre: *** cfs_fail_loc=1610, val=0*** [ 3155.756916] Lustre: Skipped 3 previous similar messages [ 3206.112043] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3206.118442] 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 [ 3206.125682] Lustre: Skipped 8 previous similar messages [ 3206.128580] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3206.132357] Lustre: Skipped 3 previous similar messages [ 3207.137185] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3207.140423] Lustre: Skipped 1 previous similar message [ 3212.260199] Lustre: server umount lustre-MDT0000 complete [ 3215.978885] LustreError: 89747:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1782225579 with bad export cookie 15307811760302885620 [ 3215.996047] LustreError: 89747:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 3 previous similar messages [ 3216.309292] Lustre: server umount lustre-MDT0001 complete [ 3230.818204] Lustre: server umount lustre-OST0000 complete [ 3233.701719] Lustre: 16409:0:(client.c:2489:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1782225580/real 1782225580] req@ffff91964b351500 x1868796020223872/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1782225596 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3234.872194] Lustre: server umount lustre-OST0001 complete [ 3251.632438] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing load_modules_local [ 3263.677536] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3268.853145] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3277.779257] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3282.774972] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3285.711610] Lustre: 92978:0:(mgs_llog.c:1447:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3293.230453] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3300.678759] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3303.784745] LustreError: 93332:0:(ldlm_lib.c:1179: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. [ 3303.799133] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:116 to 0x280000400:161) [ 3303.805067] LustreError: 93332:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 13 previous similar messages [ 3308.949532] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3554 to 0x280000401:3585) [ 3310.197670] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3315.712541] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3317 to 0x2c0000401:3361) [ 3315.732543] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:116 to 0x2c0000400:161) [ 3316.776524] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3324.127637] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3328.207281] Lustre: 94846:0:(mgs_llog.c:1447:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 3336.419909] Lustre: DEBUG MARKER: == sanity-lfsck test 14b: LFSCK can repair MDT-object with dangling LOV EA reference (2) ========================================================== 10:41:37 (1782225697) [ 3343.949480] Lustre: *** cfs_fail_loc=1610, val=0*** [ 3343.951191] Lustre: Skipped 63 previous similar messages [ 3372.016863] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3372.036099] Lustre: Skipped 3 previous similar messages [ 3377.128577] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3377.140583] Lustre: Skipped 3 previous similar messages [ 3385.312671] Lustre: lustre-MDT0000 is waiting for obd_unlinked_exports more than 8 seconds. The obd refcount = 3. Is it stuck? [ 3385.557754] Lustre: server umount lustre-MDT0000 complete [ 3389.279814] LustreError: 91821:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1782225752 with bad export cookie 15307811760302914033 [ 3389.284180] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3389.292822] LustreError: 91821:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 3389.313988] LustreError: Skipped 2 previous similar messages [ 3389.632642] Lustre: server umount lustre-MDT0001 complete [ 3404.556413] Lustre: server umount lustre-OST0000 complete [ 3418.904330] Lustre: server umount lustre-OST0001 complete [ 3436.651293] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing load_modules_local [ 3446.868900] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3447.235376] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3447.241933] Lustre: Skipped 13 previous similar messages [ 3451.578384] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3460.706241] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3465.737887] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3468.772962] Lustre: 98892:0:(mgs_llog.c:1447:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3475.619695] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3482.168662] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3486.259211] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:116 to 0x280000400:193) [ 3490.826271] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3492.090872] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3682 to 0x280000401:3713) [ 3492.097083] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3317 to 0x2c0000401:3393) [ 3492.189197] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:116 to 0x2c0000400:193) [ 3497.479442] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3504.544212] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3513.710718] Lustre: DEBUG MARKER: == sanity-lfsck test 15a: LFSCK can repair unmatched MDT-object/OST-object pairs (1) ========================================================== 10:44:35 (1782225875) [ 3517.379121] Lustre: *** cfs_fail_loc=1611, val=0*** [ 3517.383251] Lustre: Skipped 63 previous similar messages [ 3517.730123] Lustre: *** cfs_fail_loc=1611, val=0*** [ 3528.576456] Lustre: DEBUG MARKER: == sanity-lfsck test 15b: LFSCK can repair unmatched MDT-object/OST-object pairs (2) ========================================================== 10:44:50 (1782225890) [ 3530.793263] Lustre: *** cfs_fail_loc=1612, val=0*** [ 3530.854154] Lustre: *** cfs_fail_loc=1612, val=0*** [ 3530.855807] Lustre: Skipped 2 previous similar messages [ 3541.556402] Lustre: DEBUG MARKER: == sanity-lfsck test 15c: LFSCK can repair unmatched MDT-object/OST-object pairs (3) ========================================================== 10:45:03 (1782225903) [ 3543.130828] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_15c MDS newer than 2.7.55, LU-6475 [ 3545.057548] Lustre: DEBUG MARKER: == sanity-lfsck test 15d: LFSCK don't crash upon dir migration failure ========================================================== 10:45:06 (1782225906) [ 3551.247526] Lustre: *** cfs_fail_loc=1709, val=0*** [ 3551.249880] LustreError: 97760:0:(osp_object.c:629:osp_attr_get()) lustre-MDT0000-osp-MDT0001: osp_attr_get update error [0x200003ab2:0x1:0x0]: rc = -5 [ 3551.264447] LustreError: 97760:0:(mdt_reint.c:2644:mdt_reint_migrate()) lustre-MDT0001: migrate [0x240002340:0x6c:0x0]/s30 failed: rc = -5 [ 3624.928038] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3624.942473] Lustre: lustre-MDT0000-osp-MDT0001: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 3624.971158] Lustre: Skipped 8 previous similar messages [ 3624.988258] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3624.996092] Lustre: Skipped 4 previous similar messages [ 3629.340043] Lustre: server umount lustre-MDT0000 complete [ 3636.737936] LustreError: 97732:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1782225999 with bad export cookie 15307811760302928775 [ 3636.749872] LustreError: 97732:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 3636.985750] Lustre: server umount lustre-MDT0001 complete [ 3655.687818] Lustre: server umount lustre-OST0000 complete [ 3656.673567] Lustre: 16410:0:(client.c:2489:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1782226003/real 1782226003] req@ffff91964303b800 x1868796020987136/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1782226019 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3661.856091] Lustre: 16410:0:(client.c:2489:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1782226009/real 1782226009] req@ffff919651bbd500 x1868796020987904/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1782226025 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3661.908775] Lustre: 16410:0:(client.c:2489:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 3664.153314] Lustre: server umount lustre-OST0001 complete [ 3681.766910] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing unload_modules_local [ 3684.766936] Key type lgssc unregistered [ 3685.074091] LNet: 104598:0:(lib-ptl.c:967:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 3685.089163] LNetError: 104598:0:(acceptor.c:246:lnet_acceptor_remove_socket()) Interface ens2 not found [ 3685.109726] LNet: Removed LNI 192.168.204.111@tcp [ 3685.999304] Key type .llcrypt unregistered [ 3686.002675] Key type ._llcrypt unregistered [ 3715.421422] Key type ._llcrypt registered [ 3715.424221] Key type .llcrypt registered [ 3715.559911] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_hostid [ 3727.802831] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing load_modules_local [ 3728.754194] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 3729.041768] alg: No test for adler32 (adler32-zlib) [ 3730.199676] Lustre: Lustre: Build Version: 2.17.54_83_g330a3f4 [ 3730.543976] LNet: Added LNI 192.168.204.111@tcp [8/256/0/180] [ 3732.287177] Key type lgssc registered [ 3733.497462] Lustre: Echo OBD driver; http://www.lustre.org/ [ 3785.780564] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing load_modules_local [ 3797.092767] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 3797.158680] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3798.358801] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 3798.382905] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 3798.453283] Lustre: lustre-MDT0000: new disk, initializing [ 3798.531903] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3798.547306] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 3802.524456] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3815.509657] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3815.595021] Lustre: 109032:0:(mgs_llog.c:1447:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 3815.620073] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 3815.623892] Lustre: Skipped 1 previous similar message [ 3815.712344] Lustre: lustre-MDT0001: new disk, initializing [ 3815.771262] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 3815.795930] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 3815.814265] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 3821.008862] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3826.117108] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 3835.602318] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3835.846274] Lustre: lustre-OST0000: new disk, initializing [ 3835.853375] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 3835.863238] Lustre: 110973:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 3835.945541] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 3837.830170] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 3837.847863] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 3838.004305] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 3841.950421] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3854.617563] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3854.761935] Lustre: lustre-OST0001: new disk, initializing [ 3854.766270] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 3854.772767] Lustre: 111998:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 3854.854372] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 3862.623995] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3863.608896] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 3863.628782] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 3863.691802] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 3874.781371] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3881.678272] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 3888.175858] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 10:50:49 (1782226249) === [ 3896.745465] Lustre: DEBUG MARKER: == sanity-lfsck test 16: LFSCK can repair inconsistent MDT-object/OST-object owner ========================================================== 10:50:57 (1782226257) [ 3897.093458] Lustre: 109039:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 251 < left 278, rollback = 2 [ 3897.101928] Lustre: 109039:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 3897.108314] Lustre: 109039:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3897.115701] Lustre: 109039:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 3897.123683] Lustre: 109039:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 3897.130713] Lustre: 109039:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3897.598397] Lustre: 112217:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 3897.606214] Lustre: 112217:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 18 previous similar messages [ 3897.614722] Lustre: 112217:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 3897.625345] Lustre: 112217:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 18 previous similar messages [ 3897.637895] Lustre: 112217:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3897.650254] Lustre: 112217:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 18 previous similar messages [ 3897.673070] Lustre: 112217:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 7/369/0 [ 3897.682031] Lustre: 112217:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 18 previous similar messages [ 3897.693215] Lustre: 112217:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 3897.706193] Lustre: 112217:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 18 previous similar messages [ 3897.717366] Lustre: 112217:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3897.721139] Lustre: 112217:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 18 previous similar messages [ 3898.621840] Lustre: 112217:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 3898.633561] Lustre: 112217:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 131 previous similar messages [ 3898.646924] Lustre: 112217:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 3898.656505] Lustre: 112217:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 131 previous similar messages [ 3898.667690] Lustre: 112217:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3898.676477] Lustre: 112217:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 131 previous similar messages [ 3898.685869] Lustre: 112217:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 7/369/0 [ 3898.692498] Lustre: 112217:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 131 previous similar messages [ 3898.698746] Lustre: 112217:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 3898.716864] Lustre: 112217:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 131 previous similar messages [ 3898.727660] Lustre: 112217:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3898.738136] Lustre: 112217:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 131 previous similar messages [ 3900.881472] Lustre: *** cfs_fail_loc=1613, val=0*** [ 3911.215941] Lustre: DEBUG MARKER: == sanity-lfsck test 17: LFSCK can repair multiple references ========================================================== 10:51:12 (1782226272) [ 3912.467827] Lustre: 109040:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 257 < left 278, rollback = 2 [ 3912.476155] Lustre: 109040:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 158 previous similar messages [ 3912.482755] Lustre: 109040:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 3912.488515] Lustre: 109040:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 158 previous similar messages [ 3912.497571] Lustre: 109040:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3912.504338] Lustre: 109040:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 158 previous similar messages [ 3912.512323] Lustre: 109040:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 3912.518820] Lustre: 109040:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 158 previous similar messages [ 3912.524321] Lustre: 109040:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 3912.529870] Lustre: 109040:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 158 previous similar messages [ 3912.539542] Lustre: 109040:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3912.547834] Lustre: 109040:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 158 previous similar messages [ 3913.951169] Lustre: *** cfs_fail_loc=1614, val=0*** [ 3914.782886] Lustre: *** cfs_fail_loc=1614, val=103*** [ 3914.791042] Lustre: Skipped 1 previous similar message [ 3920.916501] Lustre: 110961:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 259 < left 275, rollback = 2 [ 3920.941116] Lustre: 110961:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 11 previous similar messages [ 3920.957942] Lustre: 110961:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 3920.998055] Lustre: 110961:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3921.018042] Lustre: 110961:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/1, xattr_set: 3/275/0 [ 3921.047320] Lustre: 110961:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3921.065485] Lustre: 110961:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/9/0, punch: 1/4/0, quota 7/225/0 [ 3921.097348] Lustre: 110961:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3921.117681] Lustre: 110961:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 3921.136587] Lustre: 110961:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3921.166198] Lustre: 110961:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3921.186789] Lustre: 110961:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3929.340141] Lustre: DEBUG MARKER: == sanity-lfsck test 18a: Find out orphan OST-object and repair it (1) ========================================================== 10:51:30 (1782226290) [ 3929.701452] Lustre: 109039:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 253 < left 278, rollback = 2 [ 3929.722786] Lustre: 109039:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 1 previous similar message [ 3929.735145] Lustre: 109039:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 3929.740096] Lustre: 109039:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1 previous similar message [ 3929.745576] Lustre: 109039:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3929.750110] Lustre: 109039:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1 previous similar message [ 3929.754950] Lustre: 109039:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/1 [ 3929.761263] Lustre: 109039:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1 previous similar message [ 3929.768612] Lustre: 109039:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 3929.774157] Lustre: 109039:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1 previous similar message [ 3929.783607] Lustre: 109039:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3929.791784] Lustre: 109039:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1 previous similar message [ 3932.095790] Lustre: *** cfs_fail_loc=1615, val=0*** [ 3932.097640] Lustre: Skipped 1 previous similar message [ 3933.182361] Lustre: *** cfs_fail_loc=1615, val=0*** [ 3933.187856] Lustre: Skipped 3 previous similar messages [ 3938.427565] LustreError: 114321:0:(lfsck_layout.c:2103:lfsck_layout_add_comp()) five: Five five five five five five file Hello [0x280000401:0x6d:0x0] and [0x280000401:0x6d:0x0]d: rc = 0 [ 3951.387849] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_18b skipping excluded test 18b [ 3953.411789] Lustre: DEBUG MARKER: == sanity-lfsck test 18c: Find out orphan OST-object and repair it (3) ========================================================== 10:51:54 (1782226314) [ 3953.911505] Lustre: 109039:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 3953.919676] Lustre: 109039:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 21 previous similar messages [ 3953.933126] Lustre: 109039:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 3953.939824] Lustre: 109039:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3953.947716] Lustre: 109039:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3953.956994] Lustre: 109039:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3953.972801] Lustre: 109039:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 3953.983453] Lustre: 109039:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3953.995497] Lustre: 109039:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 3954.008576] Lustre: 109039:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3954.020657] Lustre: 109039:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3954.036386] Lustre: 109039:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3956.475931] Lustre: *** cfs_fail_loc=1617, val=0*** [ 3956.582053] Lustre: *** cfs_fail_loc=1617, val=0*** [ 3959.158242] Lustre: *** cfs_fail_loc=1616, val=0*** [ 3959.162766] Lustre: Skipped 1 previous similar message [ 3978.677471] Lustre: DEBUG MARKER: == sanity-lfsck test 18d: Find out orphan OST-object and repair it (4) ========================================================== 10:52:19 (1782226339) [ 3981.577956] Lustre: *** cfs_fail_loc=1618, val=0*** [ 3981.588579] Lustre: Skipped 5 previous similar messages [ 4015.592862] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4015.601059] 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 [ 4015.618944] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4017.121690] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4017.123025] 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 [ 4021.411236] Lustre: server umount lustre-MDT0000 complete [ 4025.521714] LustreError: 109982:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1782226388 with bad export cookie 636596705001075136 [ 4025.533375] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4026.098431] Lustre: server umount lustre-MDT0001 complete [ 4040.956062] Lustre: server umount lustre-OST0000 complete [ 4043.871287] Lustre: 106193:0:(client.c:2489:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1782226390/real 1782226390] req@ffff91964f08c700 x1868799507906048/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1782226406 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4043.892125] 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 [ 4043.917257] Lustre: Skipped 2 previous similar messages [ 4044.998353] Lustre: server umount lustre-OST0001 complete [ 4060.489353] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing load_modules_local [ 4070.293355] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4070.682112] LustreError: 117710:0:(ldlm_lib.c:1179: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. [ 4070.703865] LustreError: 117710:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 5 previous similar messages [ 4070.750376] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4074.955025] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4076.008201] LustreError: 117711:0:(ldlm_lib.c:1179: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. [ 4080.098978] LustreError: 117710:0:(ldlm_lib.c:1179: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. [ 4084.292587] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4084.545926] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 4091.611536] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4094.602312] Lustre: 118850:0:(mgs_llog.c:1447:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 4101.344220] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4101.757980] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 4108.350397] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4108.961333] LustreError: 119206:0:(ldlm_lib.c:1179: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. [ 4109.006295] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:4 to 0x280000400:33) [ 4114.404379] LustreError: 119204:0:(ldlm_lib.c:1179: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. [ 4115.443538] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:116 to 0x280000401:161) [ 4117.266675] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4122.620370] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:4 to 0x2c0000401:33) [ 4122.625881] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:33) [ 4124.212897] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4132.137583] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4135.502767] Lustre: 120723:0:(mgs_llog.c:1447:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 4148.750616] Lustre: DEBUG MARKER: == sanity-lfsck test 18e: Find out orphan OST-object and repair it (5) ========================================================== 10:55:10 (1782226510) [ 4149.109671] Lustre: 118864:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 252 < left 278, rollback = 2 [ 4149.117083] Lustre: 118864:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 46 previous similar messages [ 4149.132257] Lustre: 118864:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4149.141605] Lustre: 118864:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4149.151504] Lustre: 118864:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4149.163626] Lustre: 118864:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4149.175892] Lustre: 118864:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/1 [ 4149.181988] Lustre: 118864:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4149.187344] Lustre: 118864:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 4149.199793] Lustre: 118864:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4149.204640] Lustre: 118864:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4149.208767] Lustre: 118864:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4151.246626] Lustre: *** cfs_fail_loc=1618, val=0*** [ 4151.250850] Lustre: Skipped 3 previous similar messages [ 4187.104195] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4187.118463] 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 [ 4187.144832] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4187.150901] Lustre: Skipped 3 previous similar messages [ 4189.152731] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4191.171948] Lustre: server umount lustre-MDT0000 complete [ 4194.286697] LustreError: 117706:0:(ldlm_lib.c:1179: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. [ 4194.333769] LustreError: 117706:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 5 previous similar messages [ 4195.487101] LustreError: 117691:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1782226558 with bad export cookie 636596705001090375 [ 4195.502656] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4195.515791] LustreError: 117691:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 8 previous similar messages [ 4196.460779] Lustre: server umount lustre-MDT0001 complete [ 4211.135533] Lustre: server umount lustre-OST0000 complete [ 4225.608467] Lustre: server umount lustre-OST0001 complete [ 4246.111842] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing load_modules_local [ 4258.180056] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4258.861866] LustreError: 123296:0:(ldlm_lib.c:1179: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. [ 4258.943790] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4258.949275] Lustre: Skipped 1 previous similar message [ 4264.497109] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4274.551798] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4281.289693] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4284.549623] Lustre: 124437:0:(mgs_llog.c:1447:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 4291.653432] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4299.227594] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4300.204387] LustreError: 124791:0:(ldlm_lib.c:1179: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. [ 4300.221269] LustreError: 124791:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 3 previous similar messages [ 4300.225678] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:4 to 0x280000400:65) [ 4304.294750] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:166 to 0x280000401:193) [ 4308.412031] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4314.109592] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:4 to 0x2c0000401:65) [ 4314.121464] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:65) [ 4315.523531] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4323.988617] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4328.172862] Lustre: 126308:0:(mgs_llog.c:1447:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 4333.849365] Lustre: 123296:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 252 < left 260, rollback = 2 [ 4333.866373] Lustre: 123296:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 21 previous similar messages [ 4333.872237] Lustre: 123296:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4333.877134] Lustre: 123296:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4333.881756] Lustre: 123296:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 0/0/0, xattr_set: 1/260/0 [ 4333.886500] Lustre: 123296:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4333.891732] Lustre: 123296:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/9/0, punch: 0/0/0, quota 4/150/2 [ 4333.902377] Lustre: 123296:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4333.911885] Lustre: 123296:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 1/17/2, delete: 0/0/0 [ 4333.919619] Lustre: 123296:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4333.924916] Lustre: 123296:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 4333.933710] Lustre: 123296:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4333.984236] Lustre: *** cfs_fail_loc=1602, val=10*** [ 4361.234400] Lustre: DEBUG MARKER: == sanity-lfsck test 18f: Skip the failed OST(s) when handle orphan OST-objects ========================================================== 10:58:42 (1782226722) [ 4365.043556] Lustre: *** cfs_fail_loc=1616, val=0*** [ 4365.049269] Lustre: Skipped 3 previous similar messages [ 4372.042783] Lustre: *** cfs_fail_loc=161c, val=0*** [ 4381.262874] Lustre: DEBUG MARKER: sanity-lfsck test_18f: @@@@@@ FAIL: (6) Expect 1 fixed on mds{2}, but got: 3 [ 4390.301639] Lustre: DEBUG MARKER: == sanity-lfsck test 18g: Find out orphan OST-object and repair it (7) ========================================================== 10:59:11 (1782226751) [ 4392.688518] Lustre: *** cfs_fail_loc=162e, val=0*** [ 4394.641087] Lustre: lustre-MDT0000: trigger OI scrub by RPC for [0x2000013a1:0x10:0x0]/207 with flags 0x4a: rc = 0 [ 4400.726672] Lustre: DEBUG MARKER: sanity-lfsck test_18g: @@@@@@ FAIL: (4) Expect 2 fixed, but got: 3 [ 4406.057096] Lustre: DEBUG MARKER: == sanity-lfsck test 18h: LFSCK can repair crashed PFL extent range ========================================================== 10:59:27 (1782226767) [ 4410.949451] Lustre: *** cfs_fail_loc=162f, val=0*** [ 4410.952916] Lustre: Skipped 9 previous similar messages [ 4413.065118] LustreError: 129052:0:(lfsck_layout.c:2103:lfsck_layout_add_comp()) five: Five five five five five five file Hello [0x2c0000401:0x44:0x0] and [0x2c0000401:0x44:0x0]d: rc = 0 [ 4419.366757] Lustre: DEBUG MARKER: sanity-lfsck test_18h: @@@@@@ FAIL: (5) Fail to repair crashed PFL range: 3 [ 4424.605385] Lustre: DEBUG MARKER: == sanity-lfsck test 19a: OST-object inconsistency self detect ========================================================== 10:59:46 (1782226786) [ 4436.081754] Lustre: DEBUG MARKER: == sanity-lfsck test 19b: OST-object inconsistency self repair ========================================================== 10:59:57 (1782226797) [ 4439.190386] Lustre: *** cfs_fail_loc=1611, val=0*** [ 4439.233537] Lustre: *** cfs_fail_loc=1611, val=0*** [ 4439.235558] Lustre: Skipped 3 previous similar messages [ 4444.816306] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.204.11@tcp inode [0x2000013a1:0x1f:0x0] object 0x280000401:202 extent [0-4095], client returned csum 0 (type 4), server csum 703fb3ad (type 4) [ 4445.968963] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.204.11@tcp inode [0x2000013a1:0x20:0x0] object 0x280000401:203 extent [0-4095], client returned csum 0 (type 4), server csum 7cbb935c (type 4) [ 4454.356574] Lustre: DEBUG MARKER: == sanity-lfsck test 20a: Handle the orphan with dummy LOV EA slot properly ========================================================== 11:00:15 (1782226815) [ 4467.953398] Lustre: 130621:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 253 < left 263, rollback = 2 [ 4467.962186] Lustre: 130621:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 128 previous similar messages [ 4467.966616] Lustre: 130621:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4467.973350] Lustre: 130621:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 128 previous similar messages [ 4467.977550] Lustre: 130621:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 0/0/0, xattr_set: 2/263/0 [ 4467.981026] Lustre: 130621:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 128 previous similar messages [ 4467.987612] Lustre: 130621:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 0/0/0, punch: 0/0/0, quota 1/3/2 [ 4467.995061] Lustre: 130621:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 128 previous similar messages [ 4468.003132] Lustre: 130621:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/1, delete: 0/0/0 [ 4468.008660] Lustre: 130621:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 128 previous similar messages [ 4468.018553] Lustre: 130621:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 4468.022831] Lustre: 130621:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 128 previous similar messages [ 4487.372834] Lustre: DEBUG MARKER: == sanity-lfsck test 20b: Handle the orphan with dummy LOV EA slot properly - PFL case ========================================================== 11:00:48 (1782226848) [ 4495.393690] Lustre: DEBUG MARKER: == sanity-lfsck test 21: run all LFSCK components by default ========================================================== 11:00:56 (1782226856) [ 4509.525829] Lustre: DEBUG MARKER: == sanity-lfsck test 22a: LFSCK can repair unmatched pairs (1) ========================================================== 11:01:10 (1782226870) [ 4512.061297] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4512.075548] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4512.083341] Lustre: Skipped 1 previous similar message [ 4525.883996] Lustre: DEBUG MARKER: == sanity-lfsck test 22b: LFSCK can repair unmatched pairs (2) ========================================================== 11:01:27 (1782226887) [ 4528.148415] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4528.167424] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4539.868138] Lustre: DEBUG MARKER: == sanity-lfsck test 23a: LFSCK can repair dangling name entry (1) ========================================================== 11:01:41 (1782226901) [ 4541.693916] Lustre: *** cfs_fail_loc=1620, val=0*** [ 4556.745508] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_23b skipping excluded test 23b [ 4558.413474] Lustre: DEBUG MARKER: == sanity-lfsck test 23c: LFSCK can repair dangling name entry (3) ========================================================== 11:02:00 (1782226920) [ 4564.679793] Lustre: *** cfs_fail_loc=1621, val=127*** [ 4564.683523] Lustre: Skipped 1 previous similar message [ 4568.023728] Lustre: *** cfs_fail_loc=1602, val=10*** [ 4590.254272] Lustre: DEBUG MARKER: == sanity-lfsck test 23d: LFSCK can repair a dangling name entry to a remote object ========================================================== 11:02:31 (1782226951) [ 4592.822668] Lustre: Failing over lustre-MDT0000 [ 4593.124166] Lustre: server umount lustre-MDT0000 complete [ 4595.385646] LustreError: 129604:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.204.11@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4595.406840] LustreError: 129604:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 2 previous similar messages [ 4595.680544] 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 [ 4595.705194] Lustre: Skipped 5 previous similar messages [ 4603.901025] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4604.024653] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4604.236430] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4604.240035] Lustre: Skipped 3 previous similar messages [ 4604.278519] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4605.585763] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4609.205609] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4609.521647] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4609.568129] Lustre: lustre-MDT0000: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 4609.610354] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:130 to 0x2c0000401:161) [ 4609.614360] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:265 to 0x280000401:289) [ 4611.347927] LustreError: 126073:0:(mdt_open.c:1324:mdt_cross_open()) lustre-MDT0000: [0x2000013a3:0x82:0x0] doesn't exist!: rc = -14 [ 4622.877485] Lustre: DEBUG MARKER: == sanity-lfsck test 24: LFSCK can repair multiple-referenced name entry ========================================================== 11:03:04 (1782226984) [ 4625.058625] Lustre: *** cfs_fail_loc=1622, val=0*** [ 4625.263520] Lustre: *** cfs_fail_loc=1622, val=0*** [ 4625.270192] Lustre: Skipped 1 previous similar message [ 4637.917066] Lustre: DEBUG MARKER: == sanity-lfsck test 25: LFSCK can repair bad file type in the name entry ========================================================== 11:03:19 (1782226999) [ 4639.855438] Lustre: *** cfs_fail_loc=1623, val=0*** [ 4651.759497] Lustre: DEBUG MARKER: == sanity-lfsck test 26a: LFSCK can add the missing local name entry back to the namespace ========================================================== 11:03:33 (1782227013) [ 4653.598355] Lustre: *** cfs_fail_loc=1624, val=0*** [ 4664.576642] Lustre: DEBUG MARKER: == sanity-lfsck test 26b: LFSCK can add the missing remote name entry back to the namespace ========================================================== 11:03:46 (1782227026) [ 4678.603209] Lustre: DEBUG MARKER: == sanity-lfsck test 27a: LFSCK can recreate the lost local parent directory as orphan ========================================================== 11:04:00 (1782227040) [ 4680.325357] Lustre: *** cfs_fail_loc=1624, val=0*** [ 4680.328252] Lustre: Skipped 1 previous similar message [ 4691.635548] Lustre: DEBUG MARKER: == sanity-lfsck test 27b: LFSCK can recreate the lost remote parent directory as orphan ========================================================== 11:04:13 (1782227053) [ 4705.092426] Lustre: DEBUG MARKER: == sanity-lfsck test 28: Skip the failed MDT(s) when handle orphan MDT-objects ========================================================== 11:04:26 (1782227066) [ 4712.086794] Lustre: *** cfs_fail_loc=161c, val=0*** [ 4712.089689] Lustre: Skipped 1 previous similar message [ 4729.586420] Lustre: DEBUG MARKER: == sanity-lfsck test 29b: LFSCK can repair bad nlink count (2) ========================================================== 11:04:50 (1782227090) [ 4730.590595] Lustre: 126073:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 4730.602577] Lustre: 126073:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 497 previous similar messages [ 4730.609232] Lustre: 126073:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 4730.614226] Lustre: 126073:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 497 previous similar messages [ 4730.619487] Lustre: 126073:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4730.625317] Lustre: 126073:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 497 previous similar messages [ 4730.634596] Lustre: 126073:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 4730.640609] Lustre: 126073:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 497 previous similar messages [ 4730.650082] Lustre: 126073:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 4730.655206] Lustre: 126073:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 497 previous similar messages [ 4730.674250] Lustre: 126073:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4730.682414] Lustre: 126073:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 497 previous similar messages [ 4732.156656] Lustre: *** cfs_fail_loc=1626, val=0*** [ 4732.165017] Lustre: Skipped 4 previous similar messages [ 4743.916580] Lustre: DEBUG MARKER: == sanity-lfsck test 29c: verify linkEA size limitation == 11:05:05 (1782227105) [ 4775.153295] Lustre: DEBUG MARKER: == sanity-lfsck test 29d: accessing non-existing inode shouldn't turn fs read-only (ldiskfs) ========================================================== 11:05:36 (1782227136) [ 4778.290471] LustreError: 130526:0:(osd_handler.c:284:osd_idc_find_or_init()) lustre-MDT0000: cannot lookup FID [0x2000013a3:0x9e:0x0]: rc = -2 [ 4785.917328] Lustre: DEBUG MARKER: == sanity-lfsck test 30: LFSCK can recover the orphans from backend /lost+found ========================================================== 11:05:47 (1782227147) [ 4819.422454] Lustre: Failing over lustre-MDT0000 [ 4819.425883] 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 [ 4819.425892] Lustre: Skipped 1 previous similar message [ 4819.429780] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -19 [ 4819.486987] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4819.497447] Lustre: Skipped 5 previous similar messages [ 4819.827352] Lustre: server umount lustre-MDT0000 complete [ 4824.550862] LustreError: 123297:0:(ldlm_lib.c:1179: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. [ 4824.576773] LustreError: 123297:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 12 previous similar messages [ 4833.418132] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 4833.559896] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4833.848783] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4833.903181] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4838.880215] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4838.884984] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4838.911067] Lustre: Skipped 3 previous similar messages [ 4838.952321] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4839.027036] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:294 to 0x280000401:321) [ 4839.029156] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:167 to 0x2c0000401:193) [ 4839.754548] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4855.603795] Lustre: DEBUG MARKER: == sanity-lfsck test 31a: The LFSCK can find/repair the name entry with bad name hash (1) ========================================================== 11:06:56 (1782227216) [ 4871.480883] Lustre: DEBUG MARKER: == sanity-lfsck test 31b: The LFSCK can find/repair the name entry with bad name hash (2) ========================================================== 11:07:13 (1782227233) [ 4887.756894] Lustre: DEBUG MARKER: == sanity-lfsck test 31c: Re-generate the lost master LMV EA for striped directory ========================================================== 11:07:28 (1782227248) [ 4889.722321] Lustre: *** cfs_fail_loc=1629, val=0*** [ 4889.728474] Lustre: Skipped 7 previous similar messages [ 4904.345109] Lustre: DEBUG MARKER: == sanity-lfsck test 31d: Set broken striped directory (modified after broken) as read-only ========================================================== 11:07:45 (1782227265) [ 4911.311625] Lustre: Failing over lustre-MDT0000 [ 4911.584804] Lustre: server umount lustre-MDT0000 complete [ 4915.680472] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4915.682766] 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 [ 4915.724788] Lustre: Skipped 5 previous similar messages [ 4920.469028] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4920.594350] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4920.912805] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4925.933657] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4925.943801] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4925.965813] Lustre: Skipped 3 previous similar messages [ 4926.000672] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4926.059913] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:167 to 0x2c0000401:225) [ 4926.062655] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:294 to 0x280000401:353) [ 4927.047748] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4938.377932] Lustre: Failing over lustre-MDT0000 [ 4938.919794] Lustre: server umount lustre-MDT0000 complete [ 4941.283666] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4948.537081] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4948.705665] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4949.019869] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4950.685573] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4953.664291] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4954.084860] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4954.092153] Lustre: Skipped 3 previous similar messages [ 4954.114291] Lustre: lustre-MDT0000: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 4954.179956] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:355 to 0x280000401:385) [ 4954.182132] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:167 to 0x2c0000401:257) [ 4963.356249] Lustre: DEBUG MARKER: == sanity-lfsck test 31e: Re-generate the lost slave LMV EA for striped directory (1) ========================================================== 11:08:44 (1782227324) [ 4976.812325] Lustre: DEBUG MARKER: == sanity-lfsck test 31f: Re-generate the lost slave LMV EA for striped directory (2) ========================================================== 11:08:58 (1782227338) [ 4989.373920] Lustre: DEBUG MARKER: == sanity-lfsck test 31g: Repair the corrupted slave LMV EA ========================================================== 11:09:10 (1782227350) [ 5028.459196] Lustre: DEBUG MARKER: == sanity-lfsck test 31h: Repair the corrupted shard's name entry ========================================================== 11:09:49 (1782227389) [ 5029.902657] Lustre: *** cfs_fail_loc=162c, val=0*** [ 5029.912246] Lustre: Skipped 13 previous similar messages [ 5043.403578] Lustre: DEBUG MARKER: == sanity-lfsck test 32a: stop LFSCK when some OST failed ========================================================== 11:10:04 (1782227404) [ 5052.216870] LustreError: 147476:0:(lfsck_layout.c:4532:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d sleeping for 3000ms [ 5055.280199] LustreError: 147476:0:(lfsck_layout.c:4532:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d awake [ 5055.296492] LustreError: 147476:0:(lfsck_layout.c:4532:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d sleeping for 3000ms [ 5055.371745] Lustre: Failing over lustre-OST0000 [ 5055.572419] Lustre: server umount lustre-OST0000 complete [ 5056.484302] 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 [ 5056.524347] Lustre: Skipped 6 previous similar messages [ 5058.343305] LustreError: 147476:0:(lfsck_layout.c:4532:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d awake [ 5058.355672] LustreError: 147476:0:(lfsck_layout.c:4532:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d sleeping for 3000ms [ 5058.687179] LustreError: 147476:0:(lfsck_layout.c:4532:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout interrupted [ 5071.029128] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 5071.262875] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 5072.359376] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 5072.422915] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 5072.429683] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 5072.457137] Lustre: Skipped 3 previous similar messages [ 5078.558427] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5089.148620] Lustre: DEBUG MARKER: == sanity-lfsck test 32b: stop LFSCK when some MDT failed ========================================================== 11:10:50 (1782227450) [ 5105.102874] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing load_modules_local [ 5128.210604] Lustre: 150283:0:(mgs_llog.c:1447:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 5153.442271] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5157.375623] Lustre: 151417:0:(mgs_llog.c:1447:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 5170.406623] LustreError: 151557:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d sleeping for 3000ms [ 5173.428481] Lustre: Failing over lustre-MDT0001 [ 5173.448353] LustreError: 151557:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d awake [ 5173.464636] LustreError: lustre-MDT0001-osp-MDT0000: operation out_update to node 0@lo failed: rc = -107 [ 5173.475470] 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 [ 5173.496387] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 5173.729087] LustreError: 123292:0:(ldlm_lib.c:1179: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. [ 5173.753333] LustreError: 123292:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 25 previous similar messages [ 5173.848423] Lustre: server umount lustre-MDT0001 complete [ 5176.519181] LustreError: 151556:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d awake [ 5176.532717] LustreError: 151556:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) Skipped 1 previous similar message [ 5188.774341] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 5189.242579] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 5189.252916] Lustre: Skipped 3 previous similar messages [ 5189.291146] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 5193.635754] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5194.724994] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 1 client reconnects [ 5194.739501] Lustre: lustre-MDT0001-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 5194.755180] Lustre: Skipped 1 previous similar message [ 5194.806865] Lustre: lustre-MDT0001: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 5194.861630] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:69 to 0x2c0000400:97) [ 5194.861982] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:70 to 0x280000400:97) [ 5201.951335] Lustre: DEBUG MARKER: == sanity-lfsck test 33: check LFSCK paramters =========== 11:12:43 (1782227563) [ 5216.468962] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing load_modules_local [ 5234.733297] Lustre: 154292:0:(mgs_llog.c:1447:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 5257.496649] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5261.347583] Lustre: 155426:0:(mgs_llog.c:1447:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 5263.872222] Lustre: 123291:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 5263.880173] Lustre: 123291:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 1222 previous similar messages [ 5263.886614] Lustre: 123291:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 5263.893193] Lustre: 123291:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1222 previous similar messages [ 5263.902872] Lustre: 123291:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 5263.910488] Lustre: 123291:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1222 previous similar messages [ 5263.914779] Lustre: 123291:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 5263.921143] Lustre: 123291:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1222 previous similar messages [ 5263.926185] Lustre: 123291:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 5263.930726] Lustre: 123291:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1222 previous similar messages [ 5263.936227] Lustre: 123291:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 5263.941590] Lustre: 123291:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1222 previous similar messages [ 5282.126885] Lustre: DEBUG MARKER: == sanity-lfsck test 34: LFSCK can rebuild the lost agent object ========================================================== 11:14:03 (1782227643) [ 5283.676816] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_34 Only valid for ZFS backend [ 5285.709986] Lustre: DEBUG MARKER: == sanity-lfsck test 35: LFSCK can rebuild the lost agent entry ========================================================== 11:14:06 (1782227646) [ 5293.616919] Lustre: *** cfs_fail_loc=1631, val=0*** [ 5306.847699] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 5306.869073] 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 [ 5306.884656] Lustre: Skipped 2 previous similar messages [ 5306.896357] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5312.191695] Lustre: server umount lustre-MDT0000 complete [ 5315.747801] LustreError: 123276:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1782227678 with bad export cookie 636596705001162972 [ 5315.748782] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5315.763309] LustreError: 123276:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 5316.039430] Lustre: server umount lustre-MDT0001 complete [ 5329.903384] Lustre: server umount lustre-OST0000 complete [ 5343.272033] Lustre: server umount lustre-OST0001 complete [ 5360.054614] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing load_modules_local [ 5370.299764] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5374.846730] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5383.280387] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5387.939323] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5390.692986] Lustre: 159322:0:(mgs_llog.c:1447:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 5397.222991] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5403.961994] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5408.806132] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:70 to 0x280000400:129) [ 5412.532414] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5415.723553] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:69 to 0x2c0000400:129) [ 5415.728513] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:540 to 0x280000401:577) [ 5415.830602] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:412 to 0x2c0000401:449) [ 5418.872922] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5426.862275] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5430.554819] Lustre: 161192:0:(mgs_llog.c:1447:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 5440.454545] Lustre: DEBUG MARKER: == sanity-lfsck test 36a: rebuild LOV EA for mirrored file (1) ========================================================== 11:16:42 (1782227802) [ 5442.006739] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36a needs >= 3 OSTs [ 5443.714242] Lustre: DEBUG MARKER: == sanity-lfsck test 36b: rebuild LOV EA for mirrored file (2) ========================================================== 11:16:45 (1782227805) [ 5445.156776] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36b needs >= 3 OSTs [ 5446.589441] Lustre: DEBUG MARKER: == sanity-lfsck test 36c: rebuild LOV EA for mirrored file (3) ========================================================== 11:16:48 (1782227808) [ 5448.249566] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36c needs >= 3 OSTs [ 5450.408609] Lustre: DEBUG MARKER: == sanity-lfsck test 37: LFSCK must skip a ORPHAN ======== 11:16:51 (1782227811) [ 5462.091909] Lustre: DEBUG MARKER: == sanity-lfsck test 38: LFSCK does not break foreign file and reverse is also true ========================================================== 11:17:03 (1782227823) [ 5479.100541] Lustre: DEBUG MARKER: == sanity-lfsck test 39: LFSCK does not break foreign dir and reverse is also true ========================================================== 11:17:19 (1782227839) [ 5504.024650] Lustre: DEBUG MARKER: == sanity-lfsck test 40a: LFSCK correctly fixes lmm_oi in composite layout ========================================================== 11:17:45 (1782227865) [ 5523.146774] Lustre: DEBUG MARKER: == sanity-lfsck test 41: SEL support in LFSCK ============ 11:18:04 (1782227884) [ 5543.594940] Lustre: DEBUG MARKER: == sanity-lfsck test 42: LFSCK repairs inconsistent MDT-object/OST-object encryption flags ========================================================== 11:18:25 (1782227905) [ 5578.093338] Lustre: *** cfs_fail_loc=1632, val=0*** [ 5597.169478] Lustre: DEBUG MARKER: == sanity-lfsck test 43: LFSCK does not loop endlessly on iget failure in scanning-phase1 ========================================================== 11:19:18 (1782227958) [ 5600.226251] Lustre: Failing over lustre-MDT0001 [ 5600.236973] 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 [ 5600.252485] Lustre: Skipped 4 previous similar messages [ 5600.271028] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 5600.284652] Lustre: Skipped 4 previous similar messages [ 5600.580834] Lustre: server umount lustre-MDT0001 complete [ 5603.807506] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 5608.474611] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5608.958557] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 5608.959218] Lustre: lustre-MDT0001: Aborting client recovery [ 5608.984849] LustreError: 164982:0:(ldlm_lib.c:2990:target_stop_recovery_thread()) lustre-MDT0001: Aborting recovery [ 5609.001306] LustreError: 165004:0:(lod_dev.c:511:lod_sub_recovery_thread()) lustre-MDT0001-osd: get update log duration 0, retries 0, failed: rc = -108 [ 5609.001464] Lustre: 165006:0:(ldlm_lib.c:2390:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 5609.025537] Lustre: 165006:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0001: disconnect stale client 0bbb51cf-4ef8-4174-9644-b1720a61ab6c@ [ 5609.044081] Lustre: lustre-MDT0001: disconnecting 2 stale clients [ 5609.057065] Lustre: lustre-MDT0001-osd: cancel update llog [0x240000400:0x1:0x0] [ 5609.074235] Lustre: lustre-MDT0000-osp-MDT0001: cancel update llog [0x200000401:0x1:0x0] [ 5609.120931] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:131 to 0x280000400:161) [ 5609.121099] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:69 to 0x2c0000400:161) [ 5614.050045] LustreError: lustre-MDT0001-osp-MDT0000: This client was evicted by lustre-MDT0001; in progress operations using this service will fail. [ 5614.072432] Lustre: lustre-MDT0001-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 5614.081469] Lustre: Skipped 3 previous similar messages [ 5614.720242] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5618.757931] Lustre: *** cfs_fail_loc=1e2, val=483*** [ 5623.201075] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing wait_import_state FULL osp.lustre-MDT0001-os[pc]-MDT0000.*_server_uuid [ 5623.458911] Lustre: DEBUG MARKER: osp.lustre-MDT0001-os[pc]-MDT0000.*_server_uuid in FULL state after 0 sec [ 5629.592698] Lustre: DEBUG MARKER: == sanity-lfsck test 44: umount while lfsck is stopping == 11:19:51 (1782227991) [ 5639.333631] Lustre: *** cfs_fail_loc=1600, val=3*** [ 5642.991124] Lustre: Failing over lustre-MDT0000 [ 5643.602874] Lustre: server umount lustre-MDT0000 complete [ 5644.770694] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 5655.445921] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5655.505756] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5655.686983] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 5655.694769] Lustre: Skipped 2 previous similar messages [ 5659.808269] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 5661.183355] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 5661.190926] Lustre: Skipped 1 previous similar message [ 5661.219352] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5661.238467] Lustre: lustre-MDT0000: Recovery over after 0:02, of 2 clients 2 recovered and 0 were evicted. [ 5661.278150] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:489 to 0x2c0000401:513) [ 5661.279042] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:621 to 0x280000401:641) [ 5672.062415] Lustre: DEBUG MARKER: == sanity-lfsck test 45: LFSCK should fix UID/GID/PROJID of OST object ========================================================== 11:20:33 (1782228033) [ 5701.781351] Lustre: Failing over lustre-OST0000 [ 5702.036718] Lustre: server umount lustre-OST0000 complete [ 5702.111544] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 5702.122341] LustreError: 160663:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 5702.138294] LustreError: 160663:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 36 previous similar messages [ 5709.122779] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: (null) [ 5721.263445] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5721.541080] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 5721.548128] Lustre: Skipped 6 previous similar messages [ 5721.559318] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 5722.982791] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 5723.267941] Lustre: lustre-OST0000: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [ 5728.748829] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5735.822223] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing wait_import_state FULL os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid 50 [ 5736.048510] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid in FULL state after 0 sec [ 5740.840643] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing wait_import_state FULL os[cp].lustre-OST0000-osc-MDT0001.ost_server_uuid 50 [ 5741.042320] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0001.ost_server_uuid in FULL state after 0 sec [ 5747.383816] Lustre: DEBUG MARKER: oleg411-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff90c749810000.ost_server_uuid 50 [ 5749.090678] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff90c749810000.ost_server_uuid in FULL state after 0 sec [ 5802.495154] Lustre: server umount lustre-MDT0000 complete [ 5811.514321] LustreError: 158162:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1782228174 with bad export cookie 636596705001245978 [ 5811.518207] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5811.523582] LustreError: 158162:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 5812.083503] Lustre: server umount lustre-MDT0001 complete [ 5829.087347] Lustre: 106195:0:(client.c:2489:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1782228176/real 1782228176] req@ffff91964505c380 x1868799509783424/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1782228192 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5832.159115] Lustre: 106194:0:(client.c:2489:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1782228179/real 1782228179] req@ffff9196475dd880 x1868799509783808/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1782228195 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5832.322529] Lustre: server umount lustre-OST0000 complete [ 5833.887139] Lustre: 106196:0:(client.c:2489:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1782228181/real 1782228181] req@ffff9197477e2d80 x1868799509784064/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1782228197 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5838.314849] Lustre: 106193:0:(client.c:2489:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1782228185/real 1782228185] req@ffff919652972d80 x1868799509784448/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1782228201 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5841.726613] Lustre: server umount lustre-OST0001 complete [ 5863.603117] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing unload_modules_local [ 5866.679933] Key type lgssc unregistered [ 5867.177678] LNet: 174114:0:(lib-ptl.c:967:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 5867.190196] LNetError: 174114:0:(acceptor.c:246:lnet_acceptor_remove_socket()) Interface ens2 not found [ 5867.227327] LNet: Removed LNI 192.168.204.111@tcp [ 5868.258437] Key type .llcrypt unregistered [ 5868.260568] Key type ._llcrypt unregistered [ 5893.386527] Key type ._llcrypt registered [ 5893.390703] Key type .llcrypt registered [ 5893.495382] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_hostid [ 5912.720232] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing load_modules_local [ 5913.971908] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 5914.052869] alg: No test for adler32 (adler32-zlib) [ 5915.096271] Lustre: Lustre: Build Version: 2.17.54_83_g330a3f4 [ 5915.402019] LNet: Added LNI 192.168.204.111@tcp [8/256/0/180] [ 5917.185793] Key type lgssc registered [ 5918.506897] Lustre: Echo OBD driver; http://www.lustre.org/ [ 5976.034434] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing load_modules_local [ 5992.114507] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 5992.145524] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5993.514177] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 5993.542385] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 5993.642180] Lustre: lustre-MDT0000: new disk, initializing [ 5993.737661] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 5993.768070] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 6000.658447] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6018.739138] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 6018.877453] Lustre: 178586:0:(mgs_llog.c:1447:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 6018.915493] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 6018.918584] Lustre: Skipped 1 previous similar message [ 6019.024352] Lustre: lustre-MDT0001: new disk, initializing [ 6019.093442] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 6019.134793] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 6019.141779] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 6024.301836] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6029.984972] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 6042.232751] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 6042.466900] Lustre: lustre-OST0000: new disk, initializing [ 6042.474683] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 6042.496143] Lustre: 180527:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 6042.596187] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 6042.965862] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 6042.982311] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 6043.134140] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 6050.425758] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6066.083121] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 6066.276898] Lustre: lustre-OST0001: new disk, initializing [ 6066.280427] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 6066.285353] Lustre: 181550:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 6066.358334] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 6074.008964] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6075.951730] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 6075.975197] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 6076.056660] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 6088.349723] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 6095.764164] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 6104.532416] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 11:27:45 (1782228465) === [ 6106.340463] Lustre: DEBUG MARKER: == sanity-lfsck test complete, duration 5861 sec ========= 11:27:47 (1782228467) [ 6108.250823] Lustre: DEBUG MARKER: === sanity-lfsck: start cleanup 11:27:49 (1782228469) === [ 6112.139271] Lustre: DEBUG MARKER: === sanity-lfsck: finish cleanup 11:27:53 (1782228473) === [ 6121.441498] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 6121.445394] 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 [ 6121.462386] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 6121.951997] 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 [ 6121.980273] Lustre: Skipped 1 previous similar message [ 6121.982874] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 6121.988499] Lustre: Skipped 2 previous similar messages [ 6123.444685] Lustre: server umount lustre-MDT0000 complete [ 6132.194534] LustreError: 178596:0:(ldlm_lib.c:1179: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. [ 6132.214303] LustreError: 178596:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 8 previous similar messages [ 6132.608626] LustreError: 178576:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1782228495 with bad export cookie 13836146299532965969 [ 6132.614723] LustreError: MGC192.168.204.111@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 6132.630901] LustreError: 178576:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 6132.962802] Lustre: server umount lustre-MDT0001 complete [ 6151.935108] Lustre: server umount lustre-OST0000 complete [ 6153.695353] Lustre: 175744:0:(client.c:2489:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1782228500/real 1782228500] req@ffff91964505d500 x1868801798922752/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1782228516 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6153.719518] 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 [ 6153.739219] Lustre: Skipped 1 previous similar message [ 6158.815276] Lustre: 175745:0:(client.c:2489:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1782228505/real 1782228505] req@ffff91964dc7dc00 x1868801798923008/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1782228521 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6161.848879] Lustre: server umount lustre-OST0001 complete [ 6182.171287] Lustre: DEBUG MARKER: oleg411-server.virtnet: executing unload_modules_local [ 6185.284080] Key type lgssc unregistered [ 6185.621200] LNet: 185028:0:(lib-ptl.c:967:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 6185.627542] LNetError: 185028:0:(acceptor.c:246:lnet_acceptor_remove_socket()) Interface ens2 not found [ 6186.665850] LNet: Removed LNI 192.168.204.111@tcp [ 6187.511206] Key type .llcrypt unregistered [ 6187.514326] Key type ._llcrypt unregistered