[ 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 456101352 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: 2829652K/4306352K available (18435K kernel code, 11221K rwdata, 7248K rodata, 2908K init, 18040K bss, 524580K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] ftrace: allocating 41240 entries in 162 pages [ 0.000000] ftrace: allocated 162 pages with 3 groups [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] rcu: RCU event tracing is enabled. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ 0.000000] rcu: RCU callback double-/use-after-free debug enabled. [ 0.000000] Rude variant of Tasks RCU enabled. [ 0.000000] Tracing variant of Tasks RCU enabled. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 0.000000] NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16 [ 0.000000] random: get_random_bytes called from start_kernel+0x622/0x9a8 with crng_init=0 [ 0.001000] Console: colour *CGA 80x25 [ 0.001000] printk: console [ttyS1] enabled [ 0.001000] ACPI: Core revision 20220331 [ 0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.001011] APIC: Switch to symmetric I/O mode setup [ 0.002233] x2apic enabled [ 0.004004] Switched APIC routing to physical x2apic. [ 0.005017] kvm-guest: setup PV IPIs [ 0.007802] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.008000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x22983777dd9, max_idle_ns: 440795300422 ns [ 0.008022] Calibrating delay loop (skipped) preset value.. 4800.00 BogoMIPS (lpj=2400000) [ 0.009013] pid_max: default: 32768 minimum: 301 [ 0.010129] LSM: Security Framework initializing [ 0.011050] Yama: becoming mindful. [ 0.012045] SELinux: Initializing. [ 0.013080] *** VALIDATE selinux *** [ 0.020649] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.025190] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.026142] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.027089] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.029019] *** VALIDATE tmpfs *** [ 0.030146] *** VALIDATE proc *** [ 0.031197] *** VALIDATE cgroup *** [ 0.032010] *** VALIDATE cgroup2 *** [ 0.033283] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.035153] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.036009] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.037028] Spectre V2 : User space: Vulnerable [ 0.038010] Speculative Store Bypass: Vulnerable [ 0.040672] debug: unmapping init [mem 0xffffffffbbc59000-0xffffffffbbc60fff] [ 0.042951] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.043778] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.044028] ... version: 2 [ 0.045018] ... bit width: 48 [ 0.046017] ... generic registers: 4 [ 0.047017] ... value mask: 0000ffffffffffff [ 0.048016] ... max period: 00007fffffffffff [ 0.049017] ... fixed-purpose events: 3 [ 0.050013] ... event mask: 000000070000000f [ 0.051340] rcu: Hierarchical SRCU implementation. [ 0.053564] smp: Bringing up secondary CPUs ... [ 0.054602] x86: Booting SMP configuration: [ 0.055028] .... node #0, CPUs: #1 #2 #3 [ 0.058106] smp: Brought up 1 node, 4 CPUs [ 0.060015] smpboot: Max logical packages: 1 [ 0.061022] smpboot: Total of 4 processors activated (19200.00 BogoMIPS) [ 0.127929] node 0 deferred pages initialised in 65ms [ 0.131014] devtmpfs: initialized [ 0.131844] x86/mm: Memory block size: 128MB [ 0.133130] gcov: version magic: 0x41383552 [ 0.134594] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.137139] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.139263] pinctrl core: initialized pinctrl subsystem [ 0.140140] [ 0.140489] ************************************************************* [ 0.142010] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.143007] ** ** [ 0.144010] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.146008] ** ** [ 0.147011] ** This means that this kernel is built to expose internal ** [ 0.148009] ** IOMMU data structures, which may compromise security on ** [ 0.150008] ** your system. ** [ 0.151006] ** ** [ 0.152011] ** If you see this message and you are not debugging the ** [ 0.154008] ** kernel, report this immediately to your vendor! ** [ 0.155006] ** ** [ 0.156009] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.157007] ************************************************************* [ 0.159586] NET: Registered protocol family 16 [ 0.160318] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.162041] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.163034] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.165341] cpuidle: using governor menu [ 0.166690] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.169540] PCI: Using configuration type 1 for base access [ 0.171129] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.180104] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.183055] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.186064] cryptd: max_cpu_qlen set to 1000 [ 0.188261] ACPI: Added _OSI(Module Device) [ 0.190021] ACPI: Added _OSI(Processor Device) [ 0.191031] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.192012] ACPI: Added _OSI(Processor Aggregator Device) [ 0.193394] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.198204] ACPI: Interpreter enabled [ 0.200075] ACPI: PM: (supports S0 S3 S4 S5) [ 0.201015] ACPI: Using IOAPIC for interrupt routing [ 0.203119] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.205336] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.213607] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.214033] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.216017] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.218076] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.222035] acpiphp: Slot [2] registered [ 0.223141] acpiphp: Slot [5] registered [ 0.224104] acpiphp: Slot [6] registered [ 0.225082] acpiphp: Slot [7] registered [ 0.226088] acpiphp: Slot [8] registered [ 0.228143] acpiphp: Slot [9] registered [ 0.229153] acpiphp: Slot [10] registered [ 0.231159] acpiphp: Slot [3] registered [ 0.232105] acpiphp: Slot [4] registered [ 0.234103] acpiphp: Slot [11] registered [ 0.235114] acpiphp: Slot [12] registered [ 0.237130] acpiphp: Slot [13] registered [ 0.238155] acpiphp: Slot [14] registered [ 0.240108] acpiphp: Slot [15] registered [ 0.241185] acpiphp: Slot [16] registered [ 0.243105] acpiphp: Slot [17] registered [ 0.244164] acpiphp: Slot [18] registered [ 0.246111] acpiphp: Slot [19] registered [ 0.247125] acpiphp: Slot [20] registered [ 0.248144] acpiphp: Slot [21] registered [ 0.250110] acpiphp: Slot [22] registered [ 0.251102] acpiphp: Slot [23] registered [ 0.253097] acpiphp: Slot [24] registered [ 0.254105] acpiphp: Slot [25] registered [ 0.255096] acpiphp: Slot [26] registered [ 0.256059] acpiphp: Slot [27] registered [ 0.256960] acpiphp: Slot [28] registered [ 0.258063] acpiphp: Slot [29] registered [ 0.258972] acpiphp: Slot [30] registered [ 0.260058] acpiphp: Slot [31] registered [ 0.260959] PCI host bridge to bus 0000:00 [ 0.261014] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.263014] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.264016] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.266020] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.268023] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.269022] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.271197] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.272716] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.274917] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.282013] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.285039] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.287011] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.289012] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.290012] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.292333] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.295582] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.297030] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.299730] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.303015] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.315018] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.320014] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.325178] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.331014] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.338024] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.350013] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.356789] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.365015] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.370017] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.388029] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.398000] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.407025] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.415018] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.427029] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.433196] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.448024] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.464018] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.478015] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.483739] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.490019] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.502015] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.519019] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 0.533087] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.540016] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.545016] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.559022] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 0.567140] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.570406] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.571228] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.573330] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.575223] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.579188] iommu: Default domain type: Passthrough [ 0.580499] SCSI subsystem initialized [ 0.581000] ACPI: bus type USB registered [ 0.582122] usbcore: registered new interface driver usbfs [ 0.583062] usbcore: registered new interface driver hub [ 0.585094] usbcore: registered new device driver usb [ 0.586130] pps_core: LinuxPPS API ver. 1 registered [ 0.588008] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.590073] PTP clock support registered [ 0.593033] EDAC MC: Ver: 3.0.0 [ 0.595091] PCI: Using ACPI for IRQ routing [ 0.596900] NetLabel: Initializing [ 0.598012] NetLabel: domain hash size = 128 [ 0.600012] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.601084] NetLabel: unlabeled traffic allowed by default [ 0.603109] vgaarb: loaded [ 0.605286] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.607015] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.612264] clocksource: Switched to clocksource kvm-clock [ 0.718435] VFS: Disk quotas dquot_6.6.0 [ 0.720070] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.722774] *** VALIDATE ramfs *** [ 0.723857] *** VALIDATE hugetlbfs *** [ 0.726152] pnp: PnP ACPI init [ 0.728630] pnp: PnP ACPI: found 6 devices [ 0.746158] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.749399] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.751358] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.753574] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.755448] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.757833] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.760500] NET: Registered protocol family 2 [ 0.763231] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.767910] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.771682] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.776898] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.780491] TCP: Hash tables configured (established 65536 bind 65536) [ 0.783350] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.786636] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.789608] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.792309] NET: Registered protocol family 1 [ 0.795890] RPC: Registered named UNIX socket transport module. [ 0.798088] RPC: Registered udp transport module. [ 0.800296] RPC: Registered tcp transport module. [ 0.802160] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.804177] NET: Registered protocol family 44 [ 0.805893] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.807711] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.809057] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.810759] PCI: CLS 0 bytes, default 64 [ 0.811842] Unpacking initramfs... [ 2.190845] debug: unmapping init [mem 0xffff9a9afcc54000-0xffff9a9afffbffff] [ 2.194862] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.197068] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.200151] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x22983777dd9, max_idle_ns: 440795300422 ns [ 2.707088] Initialise system trusted keyrings [ 2.708663] Key type blacklist registered [ 2.710067] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.717961] zbud: loaded [ 2.720523] *** VALIDATE nfs *** [ 2.721792] *** VALIDATE nfs4 *** [ 2.723428] pstore: using deflate compression [ 2.726832] Platform Keyring initialized [ 2.823366] NET: Registered protocol family 38 [ 2.824763] Key type asymmetric registered [ 2.825889] Asymmetric key parser 'x509' registered [ 2.827563] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 2.829905] io scheduler mq-deadline registered [ 2.831734] io scheduler kyber registered [ 2.833142] io scheduler bfq registered [ 2.834921] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 2.837782] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 2.839856] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 2.841748] ACPI: Power Button [PWRF] [ 2.845798] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 2.850591] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 2.859815] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 2.865768] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 2.879596] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 2.910942] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 2.940895] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 2.945968] Non-volatile memory driver v1.3 [ 2.947750] Linux agpgart interface v0.103 [ 2.973760] virtio_blk virtio1: [vda] 149952 512-byte logical blocks (76.8 MB/73.2 MiB) [ 2.976820] vda: detected capacity change from 0 to 76775424 [ 2.998841] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.001912] vdb: detected capacity change from 0 to 1073741824 [ 3.019975] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.022994] vdc: detected capacity change from 0 to 2621440000 [ 3.039644] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.042810] vdd: detected capacity change from 0 to 2621440000 [ 3.057900] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.060212] vde: detected capacity change from 0 to 4294967296 [ 3.080115] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.083100] vdf: detected capacity change from 0 to 4294967296 [ 3.091597] libphy: Fixed MDIO Bus: probed [ 3.101456] usbcore: registered new interface driver usbserial_generic [ 3.103921] usbserial: USB Serial support registered for generic [ 3.106167] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.109155] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.110479] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.112188] mousedev: PS/2 mouse device common for all mice [ 3.114389] rtc_cmos 00:05: RTC can wake from S4 [ 3.116928] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.117941] rtc_cmos 00:05: registered as rtc0 [ 3.123440] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.124996] intel_pstate: CPU model not supported [ 3.126687] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.130692] hid: raw HID events driver (C) Jiri Kosina [ 3.134276] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.134308] usbcore: registered new interface driver usbhid [ 3.138033] usbhid: USB HID core driver [ 3.139856] drop_monitor: Initializing network drop monitor service [ 3.142409] Initializing XFRM netlink socket [ 3.143953] NET: Registered protocol family 10 [ 3.146241] Segment Routing with IPv6 [ 3.147073] NET: Registered protocol family 17 [ 3.148140] mpls_gso: MPLS GSO support [ 3.153049] RAS: Correctable Errors collector initialized. [ 3.154300] AVX version of gcm_enc/dec engaged. [ 3.155159] AES CTR mode by8 optimization enabled [ 3.219088] sched_clock: Marking stable (3219042249, 0)->(4058542765, -839500516) [ 3.221267] registered taskstats version 1 [ 3.222503] Loading compiled-in X.509 certificates [ 3.223734] zswap: loaded using pool lzo/zbud [ 3.245848] Key type big_key registered [ 3.258831] Key type encrypted registered [ 3.260440] ima: No TPM chip found, activating TPM-bypass! [ 3.262265] ima: Allocated hash algorithm: sha1 [ 3.263980] ima: No architecture policies found [ 3.264920] evm: Initialising EVM extended attributes: [ 3.265890] evm: security.selinux [ 3.266572] evm: security.ima [ 3.267082] evm: security.capability [ 3.267777] evm: HMAC attrs: 0x1 [ 3.269192] rtc_cmos 00:05: setting system clock to 2026-09-09 03:31:43 UTC (1788924703) [ 3.273061] debug: unmapping init [mem 0xffffffffbcc03000-0xffffffffbcdfffff] [ 3.274688] debug: unmapping init [mem 0xffffffffbb982000-0xffffffffbbc58fff] [ 3.282092] Write protecting the kernel read-only data: 28672k [ 3.284034] debug: unmapping init [mem 0xffffffffba003000-0xffffffffba1fffff] [ 3.285758] debug: unmapping init [mem 0xffffffffba914000-0xffffffffba9fffff] [ 3.312809] 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.320312] systemd[1]: Detected virtualization kvm. [ 3.321582] systemd[1]: Detected architecture x86-64. [ 3.322831] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.348969] systemd[1]: No hostname configured. [ 3.350506] systemd[1]: Set hostname to . [ 3.352881] random: systemd: uninitialized urandom read (16 bytes read) [ 3.355162] systemd[1]: Initializing machine ID from random generator. [ 3.515294] random: systemd: uninitialized urandom read (16 bytes read) [ 3.517736] systemd[1]: Started Dispatch Password Requests to Console Directory Watch. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ 3.523466] random: systemd: uninitialized urandom read (16 bytes read) [ 3.525393] systemd[1]: Reached target Initrd Root Device. [ OK ] Reached target Initrd Root Device. [ 3.529537] systemd[1]: Reached target Paths. [ OK ] Reached target Paths. [ OK ] Listening on udev Kernel Socket. [ OK ] Reached target Swap. [ OK ] Reached target Timers. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Local File Systems. [ OK ] Reached target Slices. [ OK ] Listening on Journal Socket (/dev/log). [ OK ] Listening on udev Control Socket. [ OK ] Listening on Journal Socket. [ OK ] Reached target Sockets. Starting Apply Kernel Variables... Starting Create Volatile Files and Directories... Starting Setup Virtual Console... Starting Create list of required st…ce nodes for the current kernel... [ OK ] Started Memstrack Anylazing Service. Starting Journal Service... [ OK ] Started Apply Kernel Variables. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Setup Virtual Console. [ OK ] Started Create list of required sta…vice nodes for the current kernel. Starting Create Static Device Nodes in /dev... Starting dracut cmdline hook... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started Journal Service. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 4.103185] device-mapper: uevent: version 1.0.3 [ 4.105483] device-mapper: ioctl: 4.46.0-ioctl (2022-02-22) initialised: dm-devel@redhat.com [ OK ] Started dracut pre-udev hook. Starting udev Kernel Device Manager... [ OK ] Started udev Kernel Device Manager. Starting dracut pre-trigger hook... [ OK ] Started dracut pre-trigger hook. Starting udev Coldplug all Devices... Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. Starting dracut initqueue hook... [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ 4.920415] random: fast init done [ 4.983671] virtio_net virtio0 ens2: renamed from eth0 [ 5.091872] scsi host0: ata_piix [ 5.109582] scsi host1: ata_piix [ 5.111237] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 5.113653] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 8.809192] dracut-initqueue[584]: RTNETLINK answers: File exists [ 9.776357] random: crng init done [ 9.777719] random: 7 urandom warning(s) missed due to ratelimiting Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Mounting /sysroot... [ 10.257848] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped dracut pre-pivot and cleanup hook. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped target Timers. [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Slices. [ OK ] Stopped target Paths. [ OK ] Stopped target Sockets. [ OK ] Stopped target System Initialization. [ OK ] Stopped target Swap. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. Stopping udev Kernel Device Manager... [ OK ] Stopped Apply Kernel Variables. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Closed udev Control Socket. [ OK ] Closed udev Kernel Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 11.502424] printk: systemd: 26 output lines suppressed due to ratelimiting [ 11.818450] SELinux: Disabled at runtime. [ 11.894355] 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.900912] systemd[1]: Detected virtualization kvm. [ 11.902110] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 12.497329] systemd[1]: initrd-switch-root.service: Succeeded. [ 12.501112] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 12.505815] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 12.508903] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 12.512076] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 12.518070] systemd[1]: Starting Journal Service... Starting Journal Service... [ 12.523326] systemd[1]: Created slice User and Session Slice. [ OK ] Created slice User and Session Slice. [ OK ] Listening on Process Core Dump Socket. [ OK ] Created slice system-getty.slice. [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Reached target Slices. Activating swap /dev/disk/by-label/SWAP... [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target rpc_pipefs.target. Mounting POSIX Message Queue File System... [ 12.611852] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS Starting Create list of required st…ce nodes for the current kernel... [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Reached target Paths. Mounting Kernel Debug File System... Starting Apply Kernel Variables... [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd File Systems. Mounting Huge Pages File System... [ 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. Starting Remount Root and Kernel File Systems... [ OK ] Stopped target Initrd Root File System. [ OK ] Listening on udev Kernel Socket. Starting udev Coldplug all Devices... [ OK ] Reached target Local Encrypted Volumes. [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Reached target RPC Port Mapper. [ OK ] Created slice system-serial\x2dgetty.slice. [ 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 ] Mounted Kernel Debug File System. [ 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. 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 ] Mounted /mnt. [ 13.006692] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Coldplug all Devices. [ OK ] Started udev Kernel Device Manager. [ 13.385435] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 13.491278] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 13.642733] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 13.652667] EDAC sbridge: Ver: 1.1.2 [ 15.141029] Key type dns_resolver registered [ 15.439629] NFS: Registering the id_resolver key type [ 15.441637] Key type id_resolver registered [ 15.443018] 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 update of the root trust anchor for DNSSEC. [ OK ] Started dnf makecache --timer. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Reached target Timers. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Started irqbalance daemon. Starting Restore /run/initramfs on shutdown... [ OK ] Reached target sshd-keygen.target. Starting Login Service... [ OK ] Started D-Bus System Message Bus. Starting Network Manager... [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Login Service. [ OK ] Started Network Manager. Starting Network Manager Wait Online... [ OK ] Reached target Network. Starting GSSAPI Proxy Daemon... Starting Dynamic System Tuning Daemon... Starting OpenSSH server daemon... Starting Hostname Service... [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... [ OK ] Started OpenSSH server daemon. [ OK ] Started Permit User Sessions. [ OK ] Started Command Scheduler. [ OK ] Started Getty on tty1. [ OK ] Started Serial Getty on ttyS1. [ OK ] Started Serial Getty on ttyS0. [ OK ] Reached target Login Prompts. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting Notify NFS peers of a restart... Starting Crash recovery kernel arming... Starting System Logging Service... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Starting Authorization Manager... [ 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 oleg103-server login: [ 41.433989] libcfs: loading out-of-tree module taints kernel. [ 41.455684] Key type ._llcrypt registered [ 41.456851] Key type .llcrypt registered [ 41.509213] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_hostid [ 62.648097] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing load_modules_local [ 65.310544] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 65.341882] alg: No test for adler32 (adler32-zlib) [ 66.737633] Lustre: Lustre: Build Version: 2.17.58_39_gf1a8369 [ 68.163237] LNet: Added LNI 192.168.201.103@tcp [8/256/0/180] [ 70.025057] Key type lgssc registered [ 72.346508] Lustre: Echo OBD driver; http://www.lustre.org/ [ 95.318690] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 115.872124] hrtimer: interrupt took 8313392 ns [ 147.170296] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing load_modules_local [ 164.471327] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 164.546605] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 166.002423] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 166.049094] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 166.180707] Lustre: lustre-MDT0000: new disk, initializing [ 166.289606] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 166.309950] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 170.878908] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 186.589708] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 186.732987] Lustre: 6524:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 186.828904] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 186.835232] Lustre: Skipped 1 previous similar message [ 186.992145] Lustre: lustre-MDT0001: new disk, initializing [ 187.126865] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 187.188887] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 187.215310] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 192.073825] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 197.563804] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 209.268563] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 209.735375] Lustre: lustre-OST0000: new disk, initializing [ 209.738572] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 209.748679] Lustre: 8464:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 209.841383] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 210.029812] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 210.040477] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 210.087744] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 216.937024] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 232.910434] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 233.033272] Lustre: lustre-OST0001: new disk, initializing [ 233.036372] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 233.042568] Lustre: 9536:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 233.096315] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 239.804779] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 241.724909] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 241.732892] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 241.799709] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 252.746578] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 261.236285] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 268.912283] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing check_logdir /tmp/testlogs/ [ 276.037436] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing yml_node [ 283.330671] Lustre: DEBUG MARKER: Client: 2.17.58.39 [ 286.740818] Lustre: DEBUG MARKER: MDS: 2.17.58.39 [ 289.702086] Lustre: DEBUG MARKER: OSS: 2.17.58.39 [ 291.764915] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity-lfsck ============----- Tue Sep 8 23:36:30 EDT 2026 [ 311.885454] Lustre: DEBUG MARKER: excepting tests: 18b 23b [ 323.053950] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing load_modules_local [ 333.794073] 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 [ 333.795826] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 333.815977] Lustre: Skipped 3 previous similar messages [ 333.828674] Lustre: Skipped 3 previous similar messages [ 338.443640] Lustre: server umount lustre-MDT0000 complete [ 344.042627] LustreError: 6533:0:(ldlm_lib.c:1199: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. [ 344.067633] LustreError: 6533:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 8 previous similar messages [ 348.455158] LustreError: 6516:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788925048 with bad export cookie 13630860434429100343 [ 348.460427] LustreError: MGC192.168.201.103@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 348.467441] LustreError: 6516:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 348.834114] Lustre: server umount lustre-MDT0001 complete [ 365.407163] Lustre: 3654:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788925049/real 1788925049] req@ffff9a9b7fa9c700 x1875823577639808/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788925065 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 365.433703] 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 [ 369.640323] Lustre: 3656:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788925053/real 1788925053] req@ffff9a9a43765880 x1875823577640064/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788925069 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 369.829511] Lustre: server umount lustre-OST0000 complete [ 373.791410] Lustre: 3656:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788925058/real 1788925058] req@ffff9a9a436f8a80 x1875823577640704/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788925074 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 373.804856] Lustre: 3656:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 378.847431] Lustre: 3655:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788925063/real 1788925063] req@ffff9a9b7fa9ea00 x1875823577640960/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788925079 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 380.954538] Lustre: server umount lustre-OST0001 complete [ 400.662431] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing unload_modules_local [ 403.203586] Key type lgssc unregistered [ 403.568807] LNet: 14812:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 403.574840] LNetError: 14812:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 403.596423] LNet: Removed LNI 192.168.201.103@tcp [ 405.023513] Key type .llcrypt unregistered [ 405.028571] Key type ._llcrypt unregistered [ 430.897806] Key type ._llcrypt registered [ 430.899673] Key type .llcrypt registered [ 430.994173] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_hostid [ 450.490869] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing load_modules_local [ 451.461312] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 451.492589] alg: No test for adler32 (adler32-zlib) [ 452.572376] Lustre: Lustre: Build Version: 2.17.58_39_gf1a8369 [ 452.902886] LNet: Added LNI 192.168.201.103@tcp [8/256/0/180] [ 454.599577] Key type lgssc registered [ 455.843928] Lustre: Echo OBD driver; http://www.lustre.org/ [ 519.445384] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing load_modules_local [ 534.127335] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 534.180352] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 535.501528] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 535.525392] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 535.637694] Lustre: lustre-MDT0000: new disk, initializing [ 535.732120] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 535.746633] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 540.736774] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 557.142180] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 557.327697] Lustre: 19265:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 557.363575] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 557.366958] Lustre: Skipped 1 previous similar message [ 557.504734] Lustre: lustre-MDT0001: new disk, initializing [ 557.599241] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 557.680904] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 557.715411] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 563.557841] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 568.931774] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 582.181524] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 582.666526] Lustre: lustre-OST0000: new disk, initializing [ 582.674812] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 582.683903] Lustre: 21205:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 582.831512] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 584.614677] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 584.635311] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 584.730706] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 589.590419] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 605.562446] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 605.728451] Lustre: lustre-OST0001: new disk, initializing [ 605.732732] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 605.736649] Lustre: 22229:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 605.853794] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 610.855979] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 610.872236] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 610.918551] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 612.067414] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 627.047935] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 635.873836] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 644.690362] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 23:42:23 (1788925343) === [ 648.483689] Lustre: DEBUG MARKER: == sanity-lfsck test 0: Control LFSCK manually =========== 23:42:27 (1788925347) [ 648.982049] Lustre: 19270:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 251 < left 278, rollback = 2 [ 648.993740] Lustre: 19270:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 649.003817] Lustre: 19270:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 649.018947] Lustre: 19270:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 649.024600] Lustre: 19270:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 649.034974] Lustre: 19270:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 649.530206] Lustre: 22006:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 649.549912] Lustre: 22006:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 8 previous similar messages [ 649.562350] Lustre: 22006:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 649.576943] Lustre: 22006:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 8 previous similar messages [ 649.590638] Lustre: 22006:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 649.602610] Lustre: 22006:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 8 previous similar messages [ 649.614758] Lustre: 22006:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 649.627723] Lustre: 22006:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 8 previous similar messages [ 649.635379] Lustre: 22006:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 649.642217] Lustre: 22006:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 8 previous similar messages [ 649.649320] Lustre: 22006:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 649.656665] Lustre: 22006:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 8 previous similar messages [ 650.535197] Lustre: 19272:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 650.542996] Lustre: 19272:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 35 previous similar messages [ 650.585508] Lustre: 19272:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 650.587700] Lustre: 19272:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 38 previous similar messages [ 650.598287] Lustre: 19272:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 650.603465] Lustre: 19272:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 38 previous similar messages [ 650.639632] Lustre: 19272:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 650.643353] Lustre: 19272:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 41 previous similar messages [ 650.647821] Lustre: 19272:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 650.657024] Lustre: 19272:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 41 previous similar messages [ 650.663137] Lustre: 19272:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 650.668981] Lustre: 19272:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 41 previous similar messages [ 652.567159] Lustre: 23222:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 652.574444] Lustre: 23222:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 101 previous similar messages [ 652.622253] Lustre: 23222:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 652.627192] Lustre: 23222:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 101 previous similar messages [ 652.631203] Lustre: 23222:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 652.636338] Lustre: 23222:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 101 previous similar messages [ 652.641717] Lustre: 23222:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 652.647410] Lustre: 23222:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 98 previous similar messages [ 652.652085] Lustre: 23222:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 652.655751] Lustre: 23222:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 98 previous similar messages [ 652.706826] Lustre: 23222:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 652.715466] Lustre: 23222:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 101 previous similar messages [ 656.198116] Lustre: *** cfs_fail_loc=1600, val=3*** [ 659.233126] Lustre: *** cfs_fail_loc=1600, val=3*** [ 659.372881] Lustre: 23418:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 260 < left 274, rollback = 2 [ 659.377578] Lustre: 23418:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 129 previous similar messages [ 659.389693] Lustre: 23418:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 659.394016] Lustre: 23418:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 126 previous similar messages [ 659.399512] Lustre: 23632:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 2/274/0 [ 659.403654] Lustre: 23418:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 0/0/0, punch: 0/0/0, quota 7/225/0 [ 659.403668] Lustre: 23418:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 126 previous similar messages [ 659.403692] Lustre: 23418:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 659.403696] Lustre: 23418:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 126 previous similar messages [ 659.403702] Lustre: 23418:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 659.403705] Lustre: 23418:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 123 previous similar messages [ 659.490645] Lustre: 23632:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 131 previous similar messages [ 661.998727] Lustre: *** cfs_fail_loc=1600, val=3*** [ 672.164428] Lustre: 23637:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-OST0001: opcode 2: before 259 < left 274, rollback = 2 [ 672.181160] Lustre: 23637:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 67 previous similar messages [ 672.185463] Lustre: 23418:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 672.188941] Lustre: 23637:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/1, xattr_set: 2/274/0 [ 672.188952] Lustre: 23637:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 60 previous similar messages [ 672.188959] Lustre: 23637:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 0/0/0, punch: 0/0/0, quota 7/225/0 [ 672.188962] Lustre: 23637:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 67 previous similar messages [ 672.188984] Lustre: 23637:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 672.188988] Lustre: 23637:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 67 previous similar messages [ 672.188993] Lustre: 23637:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 672.189023] Lustre: 23637:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 67 previous similar messages [ 672.278075] Lustre: 23418:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 67 previous similar messages [ 675.296156] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 675.308854] 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 [ 675.329468] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 677.345965] 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 [ 677.350688] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 677.370029] Lustre: Skipped 2 previous similar messages [ 677.387718] Lustre: Skipped 3 previous similar messages [ 681.007378] Lustre: server umount lustre-MDT0000 complete [ 685.353762] LustreError: 19257:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788925385 with bad export cookie 11056826400836238738 [ 685.361262] LustreError: MGC192.168.201.103@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 685.362710] LustreError: 19257:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 685.737575] Lustre: server umount lustre-MDT0001 complete [ 701.078934] Lustre: server umount lustre-OST0000 complete [ 702.943169] Lustre: 16422:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788925387/real 1788925387] req@ffff9a9a49d43480 x1875823981345792/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788925403 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 703.001827] 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 [ 706.282597] Lustre: server umount lustre-OST0001 complete [ 717.798138] Lustre: DEBUG MARKER: == sanity-lfsck test 1a: LFSCK can find out and repair crashed FID-in-dirent ========================================================== 23:43:36 (1788925416) [ 735.180508] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing load_modules_local [ 747.541817] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 747.927235] LustreError: 26242:0:(ldlm_lib.c:1199: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. [ 747.951786] LustreError: 26242:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 5 previous similar messages [ 748.067075] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 753.130807] LustreError: 26243:0:(ldlm_lib.c:1199: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. [ 753.157750] LustreError: 26243:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 1 previous similar message [ 753.552635] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 758.240587] LustreError: 26242:0:(ldlm_lib.c:1199: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. [ 763.370143] LustreError: 26243:0:(ldlm_lib.c:1199: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. [ 764.343855] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 764.654498] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 770.150795] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 773.543661] Lustre: 27382:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 781.766573] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 782.054873] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 789.002308] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 789.228033] LustreError: 27735:0:(ldlm_lib.c:1199: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. [ 793.328384] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:40 to 0x280000401:65) [ 798.000857] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 803.303261] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:41 to 0x2c0000401:65) [ 804.837963] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 813.177978] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 817.463599] Lustre: 29253:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 819.549473] Lustre: 28561:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 819.557524] Lustre: 28561:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 819.562785] Lustre: 28561:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 819.568514] Lustre: 28561:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1 previous similar message [ 819.573480] Lustre: 28561:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 819.578598] Lustre: 28561:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1 previous similar message [ 819.584210] Lustre: 28561:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 819.589472] Lustre: 28561:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1 previous similar message [ 819.594436] Lustre: 28561:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 819.599944] Lustre: 28561:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1 previous similar message [ 826.046674] Lustre: *** cfs_fail_loc=1501, val=0*** [ 837.072276] Lustre: Failing over lustre-MDT0000 [ 837.445775] Lustre: server umount lustre-MDT0000 complete [ 839.140077] 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 [ 839.155057] LustreError: 26238:0:(ldlm_lib.c:1199: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. [ 839.166147] Lustre: Skipped 2 previous similar messages [ 839.200947] LustreError: 26238:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 5 previous similar messages [ 849.828906] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 850.009828] LustreError: MGC192.168.201.103@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 850.220685] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 850.226537] Lustre: Skipped 1 previous similar message [ 850.255290] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 855.194726] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 855.530460] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 855.541535] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 855.562561] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 855.615318] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:105 to 0x2c0000401:129) [ 855.616905] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:105 to 0x280000401:129) [ 859.106094] Lustre: *** cfs_fail_loc=1505, val=0*** [ 869.134512] Lustre: DEBUG MARKER: == sanity-lfsck test 1b: LFSCK can find out and repair the missing FID-in-LMA ========================================================== 23:46:07 (1788925567) [ 870.617962] Lustre: 26239:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 870.630624] Lustre: 26239:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 322 previous similar messages [ 870.638070] Lustre: 26239:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 870.643971] Lustre: 26239:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 870.655357] Lustre: 26239:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 870.662410] Lustre: 26239:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 870.667663] Lustre: 26239:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 870.672460] Lustre: 26239:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 870.676715] Lustre: 26239:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 870.683690] Lustre: 26239:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 870.691137] Lustre: 26239:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 870.701011] Lustre: 26239:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 875.305623] Lustre: *** cfs_fail_loc=1502, val=0*** [ 884.592849] Lustre: Failing over lustre-MDT0000 [ 884.841327] Lustre: server umount lustre-MDT0000 complete [ 886.242401] 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 [ 886.254670] Lustre: Skipped 3 previous similar messages [ 886.258413] LustreError: 26237:0:(ldlm_lib.c:1199: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. [ 886.272462] LustreError: 26237:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 11 previous similar messages [ 896.535714] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 896.642777] LustreError: MGC192.168.201.103@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 896.897956] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 901.583625] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 902.115283] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 902.126642] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 902.135670] Lustre: Skipped 3 previous similar messages [ 902.150248] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 902.187441] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:169 to 0x2c0000401:193) [ 902.188297] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:169 to 0x280000401:193) [ 905.258391] Lustre: *** cfs_fail_loc=1505, val=0*** [ 914.015872] Lustre: DEBUG MARKER: == sanity-lfsck test 1c: LFSCK can find out and repair lost FID-in-dirent ========================================================== 23:46:53 (1788925613) [ 920.326531] Lustre: *** cfs_fail_loc=1504, val=0*** [ 920.337661] Lustre: *** cfs_fail_loc=1504, val=0*** [ 920.344562] Lustre: Skipped 1 previous similar message [ 929.633741] Lustre: Failing over lustre-MDT0000 [ 929.945442] Lustre: server umount lustre-MDT0000 complete [ 932.834062] 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 [ 932.845054] LustreError: 29116:0:(ldlm_lib.c:1199: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.854447] Lustre: Skipped 3 previous similar messages [ 932.871762] LustreError: 29116:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 11 previous similar messages [ 941.785257] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 941.894268] LustreError: MGC192.168.201.103@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 942.135384] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 942.140234] Lustre: Skipped 1 previous similar message [ 942.169876] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 946.999798] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 947.176593] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 947.182410] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 947.190247] Lustre: Skipped 3 previous similar messages [ 947.204967] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 947.245109] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:233 to 0x2c0000401:257) [ 947.245230] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:233 to 0x280000401:257) [ 950.192898] Lustre: *** cfs_fail_loc=1505, val=0*** [ 957.543110] Lustre: DEBUG MARKER: == sanity-lfsck test 2a: LFSCK can find out and repair crashed linkEA entry ========================================================== 23:47:36 (1788925656) [ 958.849673] Lustre: 29116:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 958.859560] Lustre: 29116:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 644 previous similar messages [ 958.864512] Lustre: 29116:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 958.868458] Lustre: 29116:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 958.878176] Lustre: 29116:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 958.882133] Lustre: 29116:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 958.887806] Lustre: 29116:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 958.895377] Lustre: 29116:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 958.904279] Lustre: 29116:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 958.915589] Lustre: 29116:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 958.927812] Lustre: 29116:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 958.935775] Lustre: 29116:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 964.175938] Lustre: *** cfs_fail_loc=1603, val=0*** [ 973.369269] Lustre: Failing over lustre-MDT0000 [ 973.632044] Lustre: server umount lustre-MDT0000 complete [ 977.890115] 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 [ 977.891146] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 977.903493] Lustre: Skipped 3 previous similar messages [ 985.099909] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 985.237709] LustreError: MGC192.168.201.103@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 985.451327] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 989.753754] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 990.687963] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 990.693457] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 990.702717] Lustre: Skipped 3 previous similar messages [ 990.729842] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 990.805592] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:297 to 0x280000401:321) [ 990.807404] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:297 to 0x2c0000401:321) [ 999.458359] Lustre: DEBUG MARKER: == sanity-lfsck test 2b: LFSCK can find out and remove invalid linkEA entry ========================================================== 23:48:18 (1788925698) [ 1005.552479] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1014.825149] Lustre: Failing over lustre-MDT0000 [ 1016.288563] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1016.299109] 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 [ 1016.305093] LustreError: 26238:0:(ldlm_lib.c:1199: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. [ 1016.325079] Lustre: Skipped 4 previous similar messages [ 1016.342966] LustreError: 26238:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 14 previous similar messages [ 1017.337776] Lustre: server umount lustre-MDT0000 complete [ 1029.760050] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1029.876224] LustreError: MGC192.168.201.103@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1030.235194] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1035.237668] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1035.258472] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1035.263181] Lustre: Skipped 3 previous similar messages [ 1035.274061] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1035.335279] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:361 to 0x2c0000401:385) [ 1035.338556] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:361 to 0x280000401:385) [ 1035.391942] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1044.597968] Lustre: DEBUG MARKER: == sanity-lfsck test 2c: LFSCK can find out and remove repeated linkEA entry ========================================================== 23:49:03 (1788925743) [ 1050.961778] Lustre: *** cfs_fail_loc=1605, val=0*** [ 1059.638282] Lustre: Failing over lustre-MDT0000 [ 1060.834322] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1061.915976] Lustre: server umount lustre-MDT0000 complete [ 1074.441283] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1074.602668] LustreError: MGC192.168.201.103@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1074.851430] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1074.854819] Lustre: Skipped 2 previous similar messages [ 1074.887765] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1079.726572] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1080.302042] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1080.302819] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1080.339533] Lustre: Skipped 3 previous similar messages [ 1080.394933] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1080.433296] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:425 to 0x280000401:449) [ 1080.434053] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:425 to 0x2c0000401:449) [ 1089.419950] Lustre: DEBUG MARKER: == sanity-lfsck test 2d: LFSCK can recover the missing linkEA entry ========================================================== 23:49:48 (1788925788) [ 1091.052118] Lustre: 26239:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 1091.060222] Lustre: 26239:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 967 previous similar messages [ 1091.066330] Lustre: 26239:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 1091.070418] Lustre: 26239:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 968 previous similar messages [ 1091.077449] Lustre: 26239:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 1091.086296] Lustre: 26239:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 968 previous similar messages [ 1091.094258] Lustre: 26239:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 1091.102878] Lustre: 26239:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 968 previous similar messages [ 1091.116987] Lustre: 26239:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 1091.121501] Lustre: 26239:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 968 previous similar messages [ 1091.133867] Lustre: 26239:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 1091.140819] Lustre: 26239:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 968 previous similar messages [ 1096.650132] Lustre: *** cfs_fail_loc=161d, val=0*** [ 1105.100059] Lustre: Failing over lustre-MDT0000 [ 1105.594947] Lustre: server umount lustre-MDT0000 complete [ 1105.891431] 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 [ 1105.909577] Lustre: Skipped 7 previous similar messages [ 1117.134199] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1117.410593] LustreError: MGC192.168.201.103@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1117.817380] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1122.786307] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1122.788801] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1122.824777] Lustre: Skipped 3 previous similar messages [ 1122.866788] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1122.955885] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:489 to 0x280000401:513) [ 1122.957415] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:489 to 0x2c0000401:513) [ 1123.703773] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1134.985217] Lustre: DEBUG MARKER: == sanity-lfsck test 2e: namespace LFSCK can verify remote object linkEA ========================================================== 23:50:33 (1788925833) [ 1137.370945] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1149.440674] Lustre: DEBUG MARKER: == sanity-lfsck test 3: LFSCK can verify multiple-linked objects ========================================================== 23:50:48 (1788925848) [ 1156.180654] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1157.043895] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1168.070140] Lustre: DEBUG MARKER: == sanity-lfsck test 4: FID-in-dirent can be rebuilt after MDT file-level backup/restore ========================================================== 23:51:07 (1788925867) [ 1203.388487] Lustre: Failing over lustre-MDT0000 [ 1203.848258] Lustre: server umount lustre-MDT0000 complete [ 1204.706073] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1204.709708] LustreError: 28561:0:(ldlm_lib.c:1199: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. [ 1204.747020] LustreError: 28561:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 36 previous similar messages [ 1210.962788] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1221.088726] Lustre: 16422:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788925904/real 1788925904] req@ffff9a9b7be49180 x1875823981988096/t0(0) o400->MGC192.168.201.103@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1788925920 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1221.129722] LustreError: MGC192.168.201.103@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1222.777921] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1236.220606] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1236.258642] Lustre: lustre-MDT0000: reset Object Index mappings [ 1247.139764] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1252.337896] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1252.352993] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1252.364273] Lustre: Skipped 3 previous similar messages [ 1252.378235] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1252.418121] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:592 to 0x2c0000401:609) [ 1252.425566] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:592 to 0x280000401:609) [ 1252.510598] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1256.859447] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1261.024782] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1261.028898] Lustre: Skipped 3 previous similar messages [ 1266.877724] Lustre: Failing over lustre-MDT0000 [ 1267.153536] Lustre: server umount lustre-MDT0000 complete [ 1267.680109] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1267.689226] 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 [ 1267.709511] Lustre: Skipped 4 previous similar messages [ 1278.249830] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1283.638877] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:592 to 0x2c0000401:641) [ 1283.641648] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:592 to 0x280000401:641) [ 1283.646852] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1287.162707] Lustre: *** cfs_fail_loc=1505, val=0*** [ 1296.419569] Lustre: DEBUG MARKER: == sanity-lfsck test 5: LFSCK can handle IGIF object upgrading ========================================================== 23:53:15 (1788925995) [ 1300.094919] Lustre: *** cfs_fail_loc=1504, val=0*** [ 1310.478508] Lustre: Failing over lustre-MDT0000 [ 1310.907938] Lustre: server umount lustre-MDT0000 complete [ 1314.271561] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1316.351623] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1326.936833] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1330.127145] Lustre: 16425:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788926014/real 1788926014] req@ffff9a9a43c4e680 x1875823982090368/t0(0) o400->MGC192.168.201.103@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1788926030 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1340.319032] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1340.346485] Lustre: lustre-MDT0000: reset Object Index mappings [ 1355.779369] LustreError: 16421:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9a9b7bde3100 x1875823982103808/t0(0) o250->MGC192.168.201.103@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 [ 1356.272746] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1356.277413] Lustre: Skipped 3 previous similar messages [ 1356.333632] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1356.341133] Lustre: Skipped 1 previous similar message [ 1361.410216] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1361.413316] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1361.421114] Lustre: Skipped 1 previous similar message [ 1361.453552] Lustre: Skipped 7 previous similar messages [ 1361.479211] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1361.491717] Lustre: Skipped 1 previous similar message [ 1361.564281] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:681 to 0x2c0000401:705) [ 1361.565120] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:681 to 0x280000401:705) [ 1362.629135] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1366.678067] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1381.334673] Lustre: Failing over lustre-MDT0000 [ 1381.584745] Lustre: server umount lustre-MDT0000 complete [ 1393.087847] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1393.182729] LustreError: MGC192.168.201.103@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1393.192945] LustreError: Skipped 2 previous similar messages [ 1398.435260] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1398.831329] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:681 to 0x2c0000401:737) [ 1398.833604] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:681 to 0x280000401:737) [ 1401.779464] Lustre: *** cfs_fail_loc=1505, val=0*** [ 1401.786737] Lustre: Skipped 84 previous similar messages [ 1410.263723] Lustre: DEBUG MARKER: == sanity-lfsck test 6a: LFSCK resumes from last checkpoint (1) ========================================================== 23:55:09 (1788926109) [ 1411.887863] Lustre: 29116:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 255 < left 278, rollback = 2 [ 1411.897898] Lustre: 29116:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 1306 previous similar messages [ 1411.903109] Lustre: 29116:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/2, destroy: 0/0/0 [ 1411.908087] Lustre: 29116:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1306 previous similar messages [ 1411.911905] Lustre: 29116:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 1411.916950] Lustre: 29116:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1306 previous similar messages [ 1411.922380] Lustre: 29116:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 1411.928832] Lustre: 29116:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1306 previous similar messages [ 1411.934557] Lustre: 29116:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 1411.939276] Lustre: 29116:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1306 previous similar messages [ 1411.943575] Lustre: 29116:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 1411.948330] Lustre: 29116:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1306 previous similar messages [ 1417.639395] Lustre: *** cfs_fail_loc=1600, val=1*** [ 1417.641194] Lustre: Skipped 8 previous similar messages [ 1436.701814] Lustre: DEBUG MARKER: == sanity-lfsck test 6b: LFSCK resumes from last checkpoint (2) ========================================================== 23:55:36 (1788926136) [ 1450.530291] Lustre: *** cfs_fail_loc=1609, val=1*** [ 1450.534107] Lustre: Skipped 15 previous similar messages [ 1466.297804] Lustre: DEBUG MARKER: == sanity-lfsck test 7a: non-stopped LFSCK should auto restarts after MDS remount (1) ========================================================== 23:56:05 (1788926165) [ 1481.748891] Lustre: Failing over lustre-MDT0000 [ 1483.988886] Lustre: server umount lustre-MDT0000 complete [ 1485.792174] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1485.801189] LustreError: 29116:0:(ldlm_lib.c:1199: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. [ 1485.852408] LustreError: 29116:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 103 previous similar messages [ 1493.619572] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1494.266316] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1494.275958] Lustre: Skipped 1 previous similar message [ 1499.619770] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1499.625570] Lustre: Skipped 1 previous similar message [ 1499.630395] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1499.645061] Lustre: Skipped 7 previous similar messages [ 1499.676736] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1499.687538] Lustre: Skipped 1 previous similar message [ 1499.731454] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1499.743306] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:853 to 0x2c0000401:897) [ 1499.745521] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:854 to 0x280000401:897) [ 1511.741469] Lustre: DEBUG MARKER: == sanity-lfsck test 7b: non-stopped LFSCK should auto restarts after MDS remount (2) ========================================================== 23:56:50 (1788926210) [ 1531.431888] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing load_modules_local [ 1552.155621] Lustre: 52919:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 1577.919426] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1581.785353] Lustre: 54055:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 1592.181719] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1592.188640] Lustre: Skipped 81 previous similar messages [ 1595.328309] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1596.385555] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1597.407211] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1599.455199] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1599.456978] Lustre: Skipped 1 previous similar message [ 1602.312556] Lustre: Failing over lustre-MDT0000 [ 1602.566328] Lustre: server umount lustre-MDT0000 complete [ 1607.150562] 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 [ 1607.154732] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1607.165874] Lustre: Skipped 18 previous similar messages [ 1613.311652] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1619.034963] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:947 to 0x280000401:993) [ 1619.035530] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:946 to 0x2c0000401:961) [ 1619.615893] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1632.120877] Lustre: DEBUG MARKER: == sanity-lfsck test 8: LFSCK state machine ============== 23:58:51 (1788926331) [ 1639.393028] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1639.407397] Lustre: Skipped 3 previous similar messages [ 1642.019584] Lustre: server umount lustre-MDT0000 complete [ 1646.505728] LustreError: 29275:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788926346 with bad export cookie 11056826400836453183 [ 1646.753471] Lustre: server umount lustre-MDT0001 complete [ 1660.618875] Lustre: server umount lustre-OST0000 complete [ 1675.552397] Lustre: server umount lustre-OST0001 complete [ 1684.164796] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_hostid [ 1694.718579] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing load_modules_local [ 1741.174365] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing load_modules_local [ 1751.301156] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1751.623566] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 1751.652743] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 1751.722227] Lustre: lustre-MDT0000: new disk, initializing [ 1751.791899] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 1756.719424] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1768.662556] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1768.779264] Lustre: 59123:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 1768.811127] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 1768.814327] Lustre: Skipped 1 previous similar message [ 1768.921648] Lustre: lustre-MDT0001: new disk, initializing [ 1769.005682] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 1769.015299] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 1773.982671] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1779.399929] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 1786.707063] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 1786.994719] Lustre: lustre-OST0000: new disk, initializing [ 1786.998439] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 1787.003709] Lustre: 60769:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 1788.418045] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 1788.437642] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 1788.490537] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 1794.340802] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1804.687468] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 1804.799861] Lustre: lustre-OST0001: new disk, initializing [ 1804.803327] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 1804.807585] Lustre: 61637:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 1806.390402] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 1806.409164] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 1806.505458] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 1811.304684] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1822.053363] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1826.372350] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 1838.188627] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1839.452682] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1839.454769] Lustre: Skipped 19 previous similar messages [ 1844.125985] Lustre: *** cfs_fail_loc=1601, val=2*** [ 1844.130372] Lustre: Skipped 10 previous similar messages [ 1864.725592] Lustre: Failing over lustre-MDT0000 [ 1865.435865] Lustre: server umount lustre-MDT0000 complete [ 1866.208820] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1866.232338] LustreError: Skipped 1 previous similar message [ 1875.540918] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1875.668470] LustreError: MGC192.168.201.103@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1875.674865] LustreError: Skipped 3 previous similar messages [ 1875.923276] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1875.930895] Lustre: Skipped 7 previous similar messages [ 1875.976530] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1875.990423] Lustre: Skipped 1 previous similar message [ 1880.953623] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1881.066535] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1881.078801] Lustre: Skipped 1 previous similar message [ 1881.079990] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1881.096449] Lustre: Skipped 7 previous similar messages [ 1881.125840] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1881.135246] Lustre: Skipped 1 previous similar message [ 1881.169287] Lustre: *** cfs_fail_loc=160b, val=2*** [ 1881.175130] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:65) [ 1881.178927] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:65) [ 1889.245996] Lustre: Failing over lustre-MDT0000 [ 1891.596184] Lustre: server umount lustre-MDT0000 complete [ 1905.339176] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1911.380119] Lustre: *** cfs_fail_loc=160b, val=2*** [ 1911.394483] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:97) [ 1911.396414] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:97) [ 1913.131234] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1919.914408] Lustre: Failing over lustre-MDT0000 [ 1920.259399] Lustre: server umount lustre-MDT0000 complete [ 1930.700162] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1936.429042] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:129) [ 1936.429499] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:129) [ 1937.295675] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1944.993792] Lustre: *** cfs_fail_loc=1602, val=2*** [ 1944.998034] Lustre: Skipped 2 previous similar messages [ 1957.909151] Lustre: DEBUG MARKER: == sanity-lfsck test 9a: LFSCK speed control (1) ========= 00:04:17 (1788926657) [ 1975.959429] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing load_modules_local [ 1997.378436] Lustre: 68547:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 2027.031213] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 2030.645924] Lustre: 69684:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 2040.354234] Lustre: 62166:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 2040.359319] Lustre: 62166:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 2759 previous similar messages [ 2040.362235] Lustre: 62166:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 2040.364669] Lustre: 62166:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 2759 previous similar messages [ 2040.367243] Lustre: 62166:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 2040.369909] Lustre: 62166:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 2759 previous similar messages [ 2040.373795] Lustre: 62166:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 2040.377995] Lustre: 62166:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 2759 previous similar messages [ 2040.382424] Lustre: 62166:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 2040.386475] Lustre: 62166:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 2759 previous similar messages [ 2040.391687] Lustre: 62166:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 2040.398346] Lustre: 62166:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 2759 previous similar messages [ 2155.335990] Lustre: DEBUG MARKER: == sanity-lfsck test 9b: LFSCK speed control (2) ========= 00:07:34 (1788926854) [ 2209.633746] Lustre: *** cfs_fail_loc=1604, val=0*** [ 2209.635785] Lustre: Skipped 4 previous similar messages [ 2234.718397] Lustre: *** cfs_fail_loc=160c, val=0*** [ 2234.720457] Lustre: Skipped 10 previous similar messages [ 2276.058546] Lustre: DEBUG MARKER: == sanity-lfsck test 10: System is available during LFSCK scanning ========================================================== 00:09:35 (1788926975) [ 2334.576368] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2335.623118] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2335.624979] Lustre: Skipped 29 previous similar messages [ 2337.626810] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2337.630166] Lustre: Skipped 69 previous similar messages [ 2341.674654] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2341.677855] Lustre: Skipped 167 previous similar messages [ 2349.677791] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2349.680072] Lustre: Skipped 358 previous similar messages [ 2365.679241] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2365.681761] Lustre: Skipped 785 previous similar messages [ 2397.799309] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2397.809175] Lustre: Skipped 1332 previous similar messages [ 2414.293071] Lustre: *** cfs_fail_loc=1604, val=0*** [ 2414.297312] Lustre: Skipped 2599 previous similar messages [ 2672.214483] Lustre: DEBUG MARKER: == sanity-lfsck test 11a: LFSCK can rebuild lost last_id ========================================================== 00:16:11 (1788927371) [ 2720.149901] Lustre: 59129:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 320, rollback = 2 [ 2720.158934] Lustre: 59129:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 36831 previous similar messages [ 2720.166094] Lustre: 59129:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 1/4/0 [ 2720.176136] Lustre: 59129:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 36831 previous similar messages [ 2720.182567] Lustre: 59129:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 5/5/0, xattr_set: 7/320/0 [ 2720.189529] Lustre: 59129:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 36831 previous similar messages [ 2720.200432] Lustre: 59129:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 6/46/0, punch: 0/0/0, quota 1/3/0 [ 2720.206445] Lustre: 59129:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 36831 previous similar messages [ 2720.216645] Lustre: 59129:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 2/5/1 [ 2720.233339] Lustre: 59129:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 36831 previous similar messages [ 2720.246320] Lustre: 59129:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 1/1/0, ref_del: 2/2/1 [ 2720.251991] Lustre: 59129:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 36831 previous similar messages [ 2845.670037] 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 [ 2845.683854] Lustre: Skipped 17 previous similar messages [ 2845.688290] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2850.786725] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2850.789475] Lustre: Skipped 3 previous similar messages [ 2852.010230] Lustre: server umount lustre-MDT0000 complete [ 2855.905610] LustreError: 70123:0:(ldlm_lib.c:1199: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. [ 2855.945980] LustreError: 70123:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 48 previous similar messages [ 2856.034164] LustreError: 59115:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788927556 with bad export cookie 11056826400836472279 [ 2856.043669] LustreError: 59115:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 2856.046567] LustreError: MGC192.168.201.103@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2856.080577] LustreError: Skipped 2 previous similar messages [ 2856.449495] Lustre: server umount lustre-MDT0001 complete [ 2870.413814] Lustre: server umount lustre-OST0000 complete [ 2884.633434] Lustre: server umount lustre-OST0001 complete [ 2891.701911] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: (null) [ 2899.791506] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 2915.359744] LustreError: Failed to get MGS log lustre-sptlrpc and no local copy. [ 2920.479463] LustreError: 75144:0:(mgc_request.c:233:do_config_log_add()) MGC192.168.201.103@tcp: failed processing log, type 4: rc = -110 [ 2946.079265] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 2946.082279] Lustre: Skipped 2 previous similar messages [ 2953.153201] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2957.091050] Lustre: 75728: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. [ 2957.118973] Lustre: *** cfs_fail_loc=160e, val=3*** [ 2960.168638] Lustre: 75728:0:(ofd_dev.c:573:ofd_lfsck_out_notify()) lustre-OST0000: Rebuilt crashed LAST_ID files successfully. [ 2969.178334] Lustre: DEBUG MARKER: == sanity-lfsck test 11b: LFSCK can rebuild crashed last_id ========================================================== 00:21:08 (1788927668) [ 2983.864202] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing load_modules_local [ 2993.890041] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2994.280123] LustreError: 75169:0:(ldlm_lib.c:1199: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. [ 2994.381854] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3272 to 0x280000401:3297) [ 2999.234904] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3008.921233] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3014.133906] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3017.270342] Lustre: 78395:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3034.459137] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3039.730303] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3207 to 0x2c0000401:3233) [ 3042.281680] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3050.747079] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3055.856168] Lustre: 79894:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 3062.885475] Lustre: *** cfs_fail_loc=160d, val=0*** [ 3063.470064] Lustre: *** cfs_fail_loc=160d, val=0*** [ 3063.471789] Lustre: Skipped 3 previous similar messages [ 3071.841570] Lustre: Failing over lustre-OST0000 [ 3071.975405] Lustre: server umount lustre-OST0000 complete [ 3075.553706] Lustre: lustre-OST0000-osc-MDT0001: Connection to lustre-OST0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 3075.570321] Lustre: Skipped 3 previous similar messages [ 3082.674714] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3082.874309] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 3082.881250] Lustre: Skipped 2 previous similar messages [ 3084.842605] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 3084.855657] Lustre: Skipped 2 previous similar messages [ 3084.889109] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 3084.889770] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 3084.895279] Lustre: *** cfs_fail_loc=215, val=0*** [ 3084.904025] Lustre: Skipped 2 previous similar messages [ 3084.933210] Lustre: Skipped 11 previous similar messages [ 3089.757995] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3090.402750] Lustre: *** cfs_fail_loc=215, val=0*** [ 3090.404396] Lustre: Skipped 1 previous similar message [ 3093.977406] Lustre: 81295: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. [ 3094.006493] Lustre: 81295:0:(ofd_dev.c:573:ofd_lfsck_out_notify()) lustre-OST0000: Rebuilt crashed LAST_ID files successfully. [ 3095.522778] Lustre: *** cfs_fail_loc=215, val=0*** [ 3095.524731] Lustre: Skipped 1 previous similar message [ 3096.906319] Lustre: Failing over lustre-OST0000 [ 3096.996359] Lustre: server umount lustre-OST0000 complete [ 3105.991526] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3107.442210] Lustre: *** cfs_fail_loc=215, val=0*** [ 3112.267199] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3112.942986] Lustre: *** cfs_fail_loc=215, val=0*** [ 3112.947188] Lustre: Skipped 2 previous similar messages [ 3121.632730] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3121.639129] Lustre: Skipped 3 previous similar messages [ 3124.968323] Lustre: server umount lustre-MDT0000 complete [ 3126.756404] LustreError: 77247:0:(ldlm_lib.c:1199: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. [ 3126.775803] LustreError: 77247:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 29 previous similar messages [ 3129.146412] LustreError: 75150:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788927829 with bad export cookie 11056826400838039936 [ 3129.164028] LustreError: 75150:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 3129.630078] Lustre: server umount lustre-MDT0001 complete [ 3143.995509] Lustre: server umount lustre-OST0000 complete [ 3147.871338] Lustre: 16425:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788927832/real 1788927832] req@ffff9a9b7d76c700 x1875823986411392/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788927848 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3148.866400] Lustre: server umount lustre-OST0001 complete [ 3158.441793] Lustre: DEBUG MARKER: == sanity-lfsck test 12a: single command to trigger LFSCK on all devices ========================================================== 00:24:17 (1788927857) [ 3174.638205] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing load_modules_local [ 3185.650240] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3190.753908] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3204.160774] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3209.687444] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3213.631491] Lustre: 85679:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3221.498357] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3230.429503] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3231.141928] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3362 to 0x280000401:3393) [ 3239.063367] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3244.536405] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3207 to 0x2c0000401:3265) [ 3245.959121] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3253.749227] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3257.626328] Lustre: 87545:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 3301.608559] Lustre: DEBUG MARKER: == sanity-lfsck test 12b: auto detect Lustre device ====== 00:26:40 (1788928000) [ 3318.924702] Lustre: DEBUG MARKER: == sanity-lfsck test 13: LFSCK can repair crashed lmm_oi ========================================================== 00:26:57 (1788928017) [ 3320.700442] Lustre: *** cfs_fail_loc=160f, val=0*** [ 3320.714507] Lustre: 84533:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 257 < left 278, rollback = 2 [ 3320.730728] Lustre: 84533:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 1005 previous similar messages [ 3320.746141] Lustre: 84533:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/2, destroy: 0/0/0 [ 3320.758467] Lustre: 84533:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1005 previous similar messages [ 3320.771539] Lustre: 84533:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3320.790304] Lustre: 84533:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1005 previous similar messages [ 3320.801659] Lustre: 84533:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/1, punch: 0/0/0, quota 1/3/0 [ 3320.810679] Lustre: 84533:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1005 previous similar messages [ 3320.820733] Lustre: 84533:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 3320.835890] Lustre: 84533:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1005 previous similar messages [ 3320.853578] Lustre: 84533:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3320.863391] Lustre: 84533:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1005 previous similar messages [ 3338.277306] Lustre: DEBUG MARKER: == sanity-lfsck test 14a: LFSCK can repair MDT-object with dangling LOV EA reference (1) ========================================================== 00:27:16 (1788928036) [ 3342.863570] Lustre: *** cfs_fail_loc=1610, val=0*** [ 3342.865571] Lustre: Skipped 3 previous similar messages [ 3398.113156] 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 [ 3398.114946] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3398.138493] Lustre: Skipped 9 previous similar messages [ 3398.150488] Lustre: Skipped 3 previous similar messages [ 3400.716137] Lustre: server umount lustre-MDT0000 complete [ 3403.233640] LustreError: 84537:0:(ldlm_lib.c:1199: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. [ 3403.252918] LustreError: 84537:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 12 previous similar messages [ 3404.585761] LustreError: 84519:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788928104 with bad export cookie 11056826400838048392 [ 3404.609976] LustreError: 84519:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 3404.920984] Lustre: server umount lustre-MDT0001 complete [ 3418.890429] Lustre: server umount lustre-OST0000 complete [ 3433.556809] Lustre: server umount lustre-OST0001 complete [ 3452.212964] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing load_modules_local [ 3465.611720] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3472.816853] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3483.375548] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3488.081708] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3490.917041] Lustre: 93467:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3497.835788] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3504.048083] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3508.414217] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:116 to 0x280000400:161) [ 3511.471979] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3554 to 0x280000401:3585) [ 3513.941077] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3519.477757] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3317 to 0x2c0000401:3361) [ 3519.497887] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:116 to 0x2c0000400:161) [ 3522.348039] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3531.624951] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3536.251929] Lustre: 95345:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 3543.924753] Lustre: DEBUG MARKER: == sanity-lfsck test 14b: LFSCK can repair MDT-object with dangling LOV EA reference (2) ========================================================== 00:30:43 (1788928243) [ 3549.481558] Lustre: *** cfs_fail_loc=1610, val=0*** [ 3549.485522] Lustre: Skipped 63 previous similar messages [ 3575.782503] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3575.797838] Lustre: Skipped 3 previous similar messages [ 3579.149261] Lustre: server umount lustre-MDT0000 complete [ 3582.879255] LustreError: 92309:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788928283 with bad export cookie 11056826400838076791 [ 3582.886814] LustreError: MGC192.168.201.103@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3582.898709] LustreError: 92309:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 3582.919429] LustreError: Skipped 2 previous similar messages [ 3583.298739] Lustre: server umount lustre-MDT0001 complete [ 3598.459345] Lustre: server umount lustre-OST0000 complete [ 3602.400902] Lustre: 16423:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788928286/real 1788928286] req@ffff9a9a4c5f8e00 x1875823986782720/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788928302 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3603.485252] Lustre: server umount lustre-OST0001 complete [ 3625.620319] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing load_modules_local [ 3640.495708] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3641.206919] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3641.214969] Lustre: Skipped 13 previous similar messages [ 3645.817989] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3659.001952] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3666.356976] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3670.814655] Lustre: 99387:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3678.714270] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3684.277230] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:116 to 0x280000400:193) [ 3686.312707] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3682 to 0x280000401:3713) [ 3686.767163] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3698.997522] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3704.837158] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3317 to 0x2c0000401:3393) [ 3704.841630] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:116 to 0x2c0000400:193) [ 3711.032936] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3725.407772] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3740.111473] Lustre: DEBUG MARKER: == sanity-lfsck test 15a: LFSCK can repair unmatched MDT-object/OST-object pairs (1) ========================================================== 00:33:59 (1788928439) [ 3744.082296] Lustre: *** cfs_fail_loc=1611, val=0*** [ 3744.086161] Lustre: Skipped 63 previous similar messages [ 3744.438898] Lustre: *** cfs_fail_loc=1611, val=0*** [ 3758.150402] Lustre: DEBUG MARKER: == sanity-lfsck test 15b: LFSCK can repair unmatched MDT-object/OST-object pairs (2) ========================================================== 00:34:17 (1788928457) [ 3761.302390] Lustre: *** cfs_fail_loc=1612, val=0*** [ 3761.411562] Lustre: *** cfs_fail_loc=1612, val=0*** [ 3761.413527] Lustre: Skipped 2 previous similar messages [ 3778.612983] Lustre: DEBUG MARKER: == sanity-lfsck test 15c: LFSCK can repair unmatched MDT-object/OST-object pairs (3) ========================================================== 00:34:36 (1788928476) [ 3781.721914] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_15c MDS newer than 2.7.55, LU-6475 [ 3784.201151] Lustre: DEBUG MARKER: == sanity-lfsck test 15d: LFSCK don't crash upon dir migration failure ========================================================== 00:34:43 (1788928483) [ 3791.866275] Lustre: *** cfs_fail_loc=1709, val=0*** [ 3791.986328] LustreError: 98255:0:(mdt_reint.c:2644:mdt_reint_migrate()) lustre-MDT0000: migrate [0x240002340:0x6c:0x0]/f45 failed: rc = -5 [ 3804.328654] LustreError: 98239:0:(lod_object.c:945:lod_load_lmv_shards()) lustre-MDT0001-mdtlov: the shard [0x200003ab1:0x6b:0x0]:1 for the striped directory [0x240002340:0x7d:0x0] is out of the known LMV EA range [0 - 0], failout [ 3812.040412] LustreError: 102462:0:(lod_object.c:945:lod_load_lmv_shards()) lustre-MDT0001-mdtlov: the shard [0x200003ab1:0x6b:0x0]:1 for the striped directory [0x240002340:0x7d:0x0] is out of the known LMV EA range [0 - 0], failout [ 3812.051318] LustreError: 102462:0:(mdt_handler.c:1498:mdt_getattr_internal()) lustre-MDT0001: getattr error for [0x240002340:0x7d:0x0]: rc = -5 [ 3848.177569] 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 [ 3848.190772] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3848.195416] Lustre: Skipped 8 previous similar messages [ 3848.221736] Lustre: Skipped 3 previous similar messages [ 3852.567342] Lustre: server umount lustre-MDT0000 complete [ 3860.645071] LustreError: 98225:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788928560 with bad export cookie 11056826400838091512 [ 3860.655075] LustreError: 98225:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 3861.003889] Lustre: server umount lustre-MDT0001 complete [ 3879.712190] Lustre: 16422:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788928563/real 1788928563] req@ffff9a9a48dec000 x1875823987149056/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788928579 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3881.465416] Lustre: server umount lustre-OST0000 complete [ 3884.001305] Lustre: 16423:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788928568/real 1788928568] req@ffff9a9a48dece00 x1875823987149568/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788928584 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3884.043419] Lustre: 16423:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 3892.204436] Lustre: 16423:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788928576/real 1788928576] req@ffff9a9b795d1880 x1875823987150208/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788928592 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3892.261276] Lustre: 16423:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 3894.058640] Lustre: server umount lustre-OST0001 complete [ 3916.730257] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing unload_modules_local [ 3919.355729] Key type lgssc unregistered [ 3919.732464] LNet: 105095:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 3919.739485] LNetError: 105095:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 3919.767194] LNet: Removed LNI 192.168.201.103@tcp [ 3920.676221] Key type .llcrypt unregistered [ 3920.677684] Key type ._llcrypt unregistered [ 3945.147372] Key type ._llcrypt registered [ 3945.149970] Key type .llcrypt registered [ 3945.269243] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_hostid [ 3959.956473] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing load_modules_local [ 3961.180636] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 3961.231267] alg: No test for adler32 (adler32-zlib) [ 3962.339569] Lustre: Lustre: Build Version: 2.17.58_39_gf1a8369 [ 3962.532810] LNet: Added LNI 192.168.201.103@tcp [8/256/0/180] [ 3964.351262] Key type lgssc registered [ 3965.673819] Lustre: Echo OBD driver; http://www.lustre.org/ [ 4025.065939] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing load_modules_local [ 4041.839937] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 4041.875489] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4043.088934] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 4043.111489] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 4043.192638] Lustre: lustre-MDT0000: new disk, initializing [ 4043.255737] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4043.268958] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 4048.027838] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4063.797244] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4063.895517] Lustre: 109548:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 4063.927323] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 4063.933112] Lustre: Skipped 1 previous similar message [ 4064.008458] Lustre: lustre-MDT0001: new disk, initializing [ 4064.074724] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 4064.100157] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 4064.113879] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 4068.870725] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4074.008831] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 4086.803783] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4087.177905] Lustre: lustre-OST0000: new disk, initializing [ 4087.182090] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 4087.191357] Lustre: 111487:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 4087.272341] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 4089.778307] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 4089.788831] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 4089.922795] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 4094.561839] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4109.271958] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4109.437740] Lustre: lustre-OST0001: new disk, initializing [ 4109.445474] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 4109.454513] Lustre: 112512:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 4109.565956] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 4115.861677] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4117.123345] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 4117.129558] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 4117.227910] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 4128.906977] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4134.769638] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 4142.247638] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 00:40:41 (1788928841) === [ 4150.224742] Lustre: DEBUG MARKER: == sanity-lfsck test 16: LFSCK can repair inconsistent MDT-object/OST-object owner ========================================================== 00:40:48 (1788928848) [ 4150.521630] Lustre: 109554:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 251 < left 278, rollback = 2 [ 4150.538110] Lustre: 109554:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4150.543676] Lustre: 109554:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4150.548159] Lustre: 109554:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 4150.554118] Lustre: 109554:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 4150.559097] Lustre: 109554:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4151.072756] Lustre: 109556:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 252 < left 278, rollback = 2 [ 4151.091301] Lustre: 109556:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 9 previous similar messages [ 4151.098150] Lustre: 109556:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4151.102863] Lustre: 109556:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 4151.107140] Lustre: 109556:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4151.114798] Lustre: 109556:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 4151.126433] Lustre: 109556:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/1, punch: 0/0/0, quota 7/369/2 [ 4151.133788] Lustre: 109556:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 4151.142120] Lustre: 109556:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/1, delete: 0/0/0 [ 4151.148982] Lustre: 109556:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 4151.165619] Lustre: 109556:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 4151.179336] Lustre: 109556:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 4152.081783] Lustre: 109556:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 4152.088075] Lustre: 109556:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 149 previous similar messages [ 4152.103228] Lustre: 109555:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 4152.108226] Lustre: 109555:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 152 previous similar messages [ 4152.114300] Lustre: 109555:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4152.120885] Lustre: 109555:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 152 previous similar messages [ 4152.126602] Lustre: 109555:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 7/369/0 [ 4152.136489] Lustre: 109555:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 153 previous similar messages [ 4152.140706] Lustre: 109555:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 4152.144815] Lustre: 109555:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 153 previous similar messages [ 4152.172290] Lustre: 109554:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 4152.174482] Lustre: 109554:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 161 previous similar messages [ 4153.817720] Lustre: *** cfs_fail_loc=1613, val=0*** [ 4167.304242] Lustre: DEBUG MARKER: == sanity-lfsck test 17: LFSCK can repair multiple references ========================================================== 00:41:05 (1788928865) [ 4169.222044] Lustre: 109556:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 257 < left 278, rollback = 2 [ 4169.244384] Lustre: 109556:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 149 previous similar messages [ 4169.261341] Lustre: 109556:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 4169.277335] Lustre: 109556:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 146 previous similar messages [ 4169.296676] Lustre: 109556:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4169.315025] Lustre: 109556:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 146 previous similar messages [ 4169.332403] Lustre: 109556:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 4169.340252] Lustre: 109556:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 145 previous similar messages [ 4169.348728] Lustre: 109556:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 4169.360449] Lustre: 109556:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 145 previous similar messages [ 4169.366459] Lustre: 109556:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4169.377322] Lustre: 109556:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 137 previous similar messages [ 4170.408951] Lustre: *** cfs_fail_loc=1614, val=0*** [ 4175.163883] Lustre: 111477:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 259 < left 275, rollback = 2 [ 4175.172274] Lustre: 111477:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 11 previous similar messages [ 4175.201322] Lustre: 111477:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 4175.223916] Lustre: 111477:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 4175.241938] Lustre: 111477:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/1, xattr_set: 3/275/0 [ 4175.254138] Lustre: 111477:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 4175.266772] Lustre: 111477:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/9/0, punch: 1/4/0, quota 7/225/0 [ 4175.275990] Lustre: 111477:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 4175.283710] Lustre: 111477:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 4175.292338] Lustre: 111477:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 4175.298291] Lustre: 111477:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 4175.304646] Lustre: 111477:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 4186.108888] Lustre: DEBUG MARKER: == sanity-lfsck test 18a: Find out orphan OST-object and repair it (1) ========================================================== 00:41:25 (1788928885) [ 4186.672718] Lustre: 109554:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 252 < left 278, rollback = 2 [ 4186.693418] Lustre: 109554:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 1 previous similar message [ 4186.706933] Lustre: 109554:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4186.738879] Lustre: 109554:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1 previous similar message [ 4186.754405] Lustre: 109554:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4186.770419] Lustre: 109554:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1 previous similar message [ 4186.778611] Lustre: 109554:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 4186.782123] Lustre: 109554:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1 previous similar message [ 4186.802636] Lustre: 109554:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 4186.825153] Lustre: 109554:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1 previous similar message [ 4186.852103] Lustre: 109554:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4186.871711] Lustre: 109554:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1 previous similar message [ 4191.527468] Lustre: *** cfs_fail_loc=1615, val=0*** [ 4191.541268] Lustre: Skipped 1 previous similar message [ 4193.647359] Lustre: *** cfs_fail_loc=1615, val=0*** [ 4193.657304] Lustre: Skipped 1 previous similar message [ 4220.353670] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_18b skipping excluded test 18b [ 4222.472193] Lustre: DEBUG MARKER: == sanity-lfsck test 18c: Find out orphan OST-object and repair it (3) ========================================================== 00:42:01 (1788928921) [ 4223.094601] Lustre: 112293:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 4223.101387] Lustre: 112293:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 21 previous similar messages [ 4223.108500] Lustre: 112293:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 4223.113123] Lustre: 112293:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4223.121777] Lustre: 112293:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4223.127980] Lustre: 112293:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4223.134099] Lustre: 112293:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 4223.138978] Lustre: 112293:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4223.144994] Lustre: 112293:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 4223.151509] Lustre: 112293:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4223.158976] Lustre: 112293:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4223.164035] Lustre: 112293:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4225.683554] Lustre: *** cfs_fail_loc=1617, val=0*** [ 4225.751439] Lustre: *** cfs_fail_loc=1617, val=0*** [ 4227.881493] Lustre: *** cfs_fail_loc=1616, val=0*** [ 4227.887351] Lustre: Skipped 3 previous similar messages [ 4250.118585] Lustre: DEBUG MARKER: == sanity-lfsck test 18d: Find out orphan OST-object and repair it (4) ========================================================== 00:42:29 (1788928949) [ 4252.271052] Lustre: *** cfs_fail_loc=1618, val=0*** [ 4252.276901] Lustre: Skipped 5 previous similar messages [ 4286.432145] 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 [ 4286.444274] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4286.452739] Lustre: Skipped 2 previous similar messages [ 4286.461022] Lustre: Skipped 1 previous similar message [ 4291.557964] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4291.569846] Lustre: Skipped 5 previous similar messages [ 4292.306681] Lustre: server umount lustre-MDT0000 complete [ 4296.378517] LustreError: 109538:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788928996 with bad export cookie 5325497220613238102 [ 4296.387112] LustreError: MGC192.168.201.103@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4296.389221] LustreError: 109538:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 4296.683561] Lustre: server umount lustre-MDT0001 complete [ 4310.864463] Lustre: server umount lustre-OST0000 complete [ 4312.543791] Lustre: 106707:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788928996/real 1788928996] req@ffff9a9b65f71500 x1875827660905344/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788929012 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4312.583777] 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 [ 4312.601465] Lustre: Skipped 1 previous similar message [ 4315.659882] Lustre: server umount lustre-OST0001 complete [ 4335.702609] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing load_modules_local [ 4345.775438] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4346.236646] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4351.204922] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4351.457555] LustreError: 118231:0:(ldlm_lib.c:1199: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. [ 4351.481490] LustreError: 118231:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 2 previous similar messages [ 4356.581333] LustreError: 118232:0:(ldlm_lib.c:1199: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. [ 4361.727607] LustreError: 118231:0:(ldlm_lib.c:1199: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. [ 4363.189478] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4363.855145] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 4370.055071] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4375.165741] Lustre: 119372:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 4387.398122] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4387.935561] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 4388.911877] LustreError: 119727:0:(ldlm_lib.c:1199: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. [ 4388.970397] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:4 to 0x280000400:33) [ 4391.006427] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:116 to 0x280000401:161) [ 4396.003728] LustreError: 119775:0:(ldlm_lib.c:1199: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. [ 4396.023235] LustreError: 119775:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 3 previous similar messages [ 4396.463851] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4405.250149] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4410.867683] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:33) [ 4410.890961] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:4 to 0x2c0000401:33) [ 4412.379995] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4420.115515] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4424.237053] Lustre: 121244:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 4439.450033] Lustre: DEBUG MARKER: == sanity-lfsck test 18e: Find out orphan OST-object and repair it (5) ========================================================== 00:45:38 (1788929138) [ 4440.090196] Lustre: 118226:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 251 < left 278, rollback = 2 [ 4440.096563] Lustre: 118226:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 46 previous similar messages [ 4440.101912] Lustre: 118226:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4440.106967] Lustre: 118226:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4440.111843] Lustre: 118226:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4440.118798] Lustre: 118226:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4440.125265] Lustre: 118226:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 4440.135261] Lustre: 118226:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4440.140653] Lustre: 118226:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 4440.149569] Lustre: 118226:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4440.156593] Lustre: 118226:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4440.161536] Lustre: 118226:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4442.077651] Lustre: *** cfs_fail_loc=1618, val=0*** [ 4442.082176] Lustre: Skipped 3 previous similar messages [ 4476.385172] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4476.395775] 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 [ 4476.409419] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4482.184982] Lustre: server umount lustre-MDT0000 complete [ 4482.533437] LustreError: 118232:0:(ldlm_lib.c:1199: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. [ 4482.548536] LustreError: 118232:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 5 previous similar messages [ 4485.763834] LustreError: 118212:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788929185 with bad export cookie 5325497220613253355 [ 4485.780931] LustreError: MGC192.168.201.103@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4486.130866] Lustre: server umount lustre-MDT0001 complete [ 4501.004202] Lustre: server umount lustre-OST0000 complete [ 4502.820517] Lustre: 106705:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788929187/real 1788929187] req@ffff9a9a4a839880 x1875827660987392/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788929203 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4502.874113] 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 [ 4502.897448] Lustre: Skipped 3 previous similar messages [ 4506.156414] Lustre: server umount lustre-OST0001 complete [ 4526.696711] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing load_modules_local [ 4537.393139] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4538.028298] LustreError: 123811:0:(ldlm_lib.c:1199: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. [ 4538.089129] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4538.092909] Lustre: Skipped 1 previous similar message [ 4543.068611] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4553.314115] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4559.300444] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4563.439692] Lustre: 124951:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 4572.755638] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4578.211574] LustreError: 125308:0:(ldlm_lib.c:1199: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. [ 4578.244532] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:4 to 0x280000400:65) [ 4578.245769] LustreError: 125308:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 2 previous similar messages [ 4580.940082] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4583.339969] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:166 to 0x280000401:193) [ 4589.694983] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4595.202817] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:4 to 0x2c0000401:65) [ 4595.205774] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:65) [ 4597.205749] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4606.848744] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4612.493181] Lustre: 126824:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 4620.305107] Lustre: 123812:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 252 < left 260, rollback = 2 [ 4620.308469] Lustre: 123812:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 21 previous similar messages [ 4620.311028] Lustre: 123812:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4620.314328] Lustre: 123812:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4620.316957] Lustre: 123812:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 0/0/0, xattr_set: 1/260/0 [ 4620.319552] Lustre: 123812:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4620.322417] Lustre: 123812:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/9/0, punch: 0/0/0, quota 4/150/2 [ 4620.324970] Lustre: 123812:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4620.327848] Lustre: 123812:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 1/17/2, delete: 0/0/0 [ 4620.330203] Lustre: 123812:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4620.344078] Lustre: 123812:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 4620.374067] Lustre: 123812:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4620.778076] Lustre: *** cfs_fail_loc=1602, val=10*** [ 4621.799291] Lustre: *** cfs_fail_loc=1602, val=10*** [ 4650.134176] Lustre: DEBUG MARKER: == sanity-lfsck test 18f: Skip the failed OST(s) when handle orphan OST-objects ========================================================== 00:49:09 (1788929349) [ 4653.920285] Lustre: *** cfs_fail_loc=1616, val=0*** [ 4653.922180] Lustre: Skipped 3 previous similar messages [ 4663.252298] Lustre: *** cfs_fail_loc=161c, val=0*** [ 4686.835842] Lustre: DEBUG MARKER: == sanity-lfsck test 18g: Find out orphan OST-object and repair it (7) ========================================================== 00:49:46 (1788929386) [ 4689.011038] Lustre: *** cfs_fail_loc=162e, val=0*** [ 4689.012778] Lustre: *** cfs_fail_loc=162e, val=0*** [ 4689.014450] Lustre: Skipped 7 previous similar messages [ 4704.962000] Lustre: DEBUG MARKER: == sanity-lfsck test 18h: LFSCK can repair crashed PFL extent range ========================================================== 00:50:03 (1788929403) [ 4727.913791] Lustre: DEBUG MARKER: == sanity-lfsck test 19a: OST-object inconsistency self detect ========================================================== 00:50:27 (1788929427) [ 4740.850586] Lustre: DEBUG MARKER: == sanity-lfsck test 19b: OST-object inconsistency self repair ========================================================== 00:50:40 (1788929440) [ 4743.924868] Lustre: *** cfs_fail_loc=1611, val=0*** [ 4743.965133] Lustre: *** cfs_fail_loc=1611, val=0*** [ 4743.966839] Lustre: Skipped 3 previous similar messages [ 4749.863506] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.201.3@tcp inode [0x2000013a1:0x1f:0x0] object 0x280000401:202 extent [0-4095], client returned csum 0 (type 4), server csum 703fb3ad (type 4) [ 4750.952344] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.201.3@tcp inode [0x2000013a1:0x20:0x0] object 0x280000401:203 extent [0-4095], client returned csum 0 (type 4), server csum 7cbb935c (type 4) [ 4760.308512] Lustre: DEBUG MARKER: == sanity-lfsck test 20a: Handle the orphan with dummy LOV EA slot properly ========================================================== 00:50:59 (1788929459) [ 4760.679575] Lustre: 123807:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 252 < left 278, rollback = 2 [ 4760.698849] Lustre: 123807:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 104 previous similar messages [ 4760.710287] Lustre: 123807:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4760.724629] Lustre: 123807:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 4760.742496] Lustre: 123807:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4760.757397] Lustre: 123807:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 4760.766549] Lustre: 123807:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 4760.778165] Lustre: 123807:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 4760.790116] Lustre: 123807:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 4760.804868] Lustre: 123807:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 4760.824936] Lustre: 123807:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4760.843175] Lustre: 123807:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 4764.211702] Lustre: *** cfs_fail_loc=1616, val=0*** [ 4764.214369] Lustre: Skipped 3 previous similar messages [ 4795.739608] Lustre: DEBUG MARKER: == sanity-lfsck test 20b: Handle the orphan with dummy LOV EA slot properly - PFL case ========================================================== 00:51:34 (1788929494) [ 4805.167625] Lustre: DEBUG MARKER: == sanity-lfsck test 21: run all LFSCK components by default ========================================================== 00:51:44 (1788929504) [ 4825.727631] Lustre: DEBUG MARKER: == sanity-lfsck test 22a: LFSCK can repair unmatched pairs (1) ========================================================== 00:52:04 (1788929524) [ 4828.501503] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4828.509154] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4828.511074] Lustre: Skipped 1 previous similar message [ 4841.150447] Lustre: DEBUG MARKER: == sanity-lfsck test 22b: LFSCK can repair unmatched pairs (2) ========================================================== 00:52:20 (1788929540) [ 4843.410237] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4843.418300] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4856.159672] Lustre: DEBUG MARKER: == sanity-lfsck test 23a: LFSCK can repair dangling name entry (1) ========================================================== 00:52:34 (1788929554) [ 4857.769323] Lustre: *** cfs_fail_loc=1620, val=0*** [ 4874.976892] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_23b skipping excluded test 23b [ 4877.841543] Lustre: DEBUG MARKER: == sanity-lfsck test 23c: LFSCK can repair dangling name entry (3) ========================================================== 00:52:56 (1788929576) [ 4884.777547] Lustre: *** cfs_fail_loc=1621, val=127*** [ 4884.784953] Lustre: Skipped 1 previous similar message [ 4888.462318] Lustre: *** cfs_fail_loc=1602, val=10*** [ 4912.475609] Lustre: DEBUG MARKER: == sanity-lfsck test 23d: LFSCK can repair a dangling name entry to a remote object ========================================================== 00:53:31 (1788929611) [ 4916.039078] Lustre: Failing over lustre-MDT0000 [ 4916.507233] Lustre: server umount lustre-MDT0000 complete [ 4917.730621] 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 [ 4917.735711] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4917.747644] LustreError: 123806:0:(ldlm_lib.c:1199: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. [ 4917.747658] LustreError: 123806:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 4 previous similar messages [ 4917.751796] Lustre: Skipped 3 previous similar messages [ 4927.126711] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4927.254710] LustreError: MGC192.168.201.103@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4927.728681] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4927.736762] Lustre: Skipped 3 previous similar messages [ 4927.810482] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4928.427112] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4932.893763] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4933.104714] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4933.155567] Lustre: lustre-MDT0000: Recovery over after 0:05, of 2 clients 2 recovered and 0 were evicted. [ 4933.254572] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:265 to 0x280000401:289) [ 4933.263815] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:130 to 0x2c0000401:161) [ 4935.087588] LustreError: 123806:0:(mdt_open.c:1324:mdt_cross_open()) lustre-MDT0000: [0x2000013a3:0x82:0x0] doesn't exist!: rc = -14 [ 4948.432598] Lustre: DEBUG MARKER: == sanity-lfsck test 24: LFSCK can repair multiple-referenced name entry ========================================================== 00:54:07 (1788929647) [ 4950.623209] Lustre: *** cfs_fail_loc=1622, val=0*** [ 4950.841478] Lustre: *** cfs_fail_loc=1622, val=0*** [ 4950.844643] Lustre: Skipped 1 previous similar message [ 4964.582634] Lustre: DEBUG MARKER: == sanity-lfsck test 25: LFSCK can repair bad file type in the name entry ========================================================== 00:54:23 (1788929663) [ 4966.297854] Lustre: *** cfs_fail_loc=1623, val=0*** [ 4978.646262] Lustre: DEBUG MARKER: == sanity-lfsck test 26a: LFSCK can add the missing local name entry back to the namespace ========================================================== 00:54:37 (1788929677) [ 4980.774863] Lustre: *** cfs_fail_loc=1624, val=0*** [ 4995.783641] Lustre: DEBUG MARKER: == sanity-lfsck test 26b: LFSCK can add the missing remote name entry back to the namespace ========================================================== 00:54:54 (1788929694) [ 4997.553860] Lustre: *** cfs_fail_loc=1624, val=0*** [ 5010.966734] Lustre: DEBUG MARKER: == sanity-lfsck test 27a: LFSCK can recreate the lost local parent directory as orphan ========================================================== 00:55:10 (1788929710) [ 5028.705822] Lustre: DEBUG MARKER: == sanity-lfsck test 27b: LFSCK can recreate the lost remote parent directory as orphan ========================================================== 00:55:27 (1788929727) [ 5029.061150] Lustre: 123807:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 253 < left 278, rollback = 2 [ 5029.065844] Lustre: 123807:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 487 previous similar messages [ 5029.075405] Lustre: 123807:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 5029.078984] Lustre: 123807:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 487 previous similar messages [ 5029.084719] Lustre: 123807:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 5029.092611] Lustre: 123807:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 487 previous similar messages [ 5029.102448] Lustre: 123807:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/1 [ 5029.109084] Lustre: 123807:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 487 previous similar messages [ 5029.113712] Lustre: 123807:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 5029.124863] Lustre: 123807:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 487 previous similar messages [ 5029.138934] Lustre: 123807:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 5029.152858] Lustre: 123807:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 487 previous similar messages [ 5030.745254] Lustre: *** cfs_fail_loc=1624, val=0*** [ 5030.759437] Lustre: Skipped 2 previous similar messages [ 5045.456545] Lustre: DEBUG MARKER: == sanity-lfsck test 28: Skip the failed MDT(s) when handle orphan MDT-objects ========================================================== 00:55:44 (1788929744) [ 5053.443961] Lustre: *** cfs_fail_loc=161c, val=0*** [ 5053.446768] Lustre: Skipped 1 previous similar message [ 5075.868305] Lustre: DEBUG MARKER: == sanity-lfsck test 29b: LFSCK can repair bad nlink count (2) ========================================================== 00:56:14 (1788929774) [ 5093.255070] Lustre: DEBUG MARKER: == sanity-lfsck test 29c: verify linkEA size limitation == 00:56:32 (1788929792) [ 5130.738098] Lustre: DEBUG MARKER: == sanity-lfsck test 29d: accessing non-existing inode shouldn't turn fs read-only (ldiskfs) ========================================================== 00:57:09 (1788929829) [ 5133.113885] Lustre: *** cfs_fail_loc=1626, val=0*** [ 5133.117212] Lustre: Skipped 3 previous similar messages [ 5134.477960] LustreError: 123808:0:(osd_handler.c:284:osd_idc_find_or_init()) lustre-MDT0000: cannot lookup FID [0x2000013a3:0x9e:0x0]: rc = -2 [ 5144.205450] Lustre: DEBUG MARKER: == sanity-lfsck test 30: LFSCK can recover the orphans from backend /lost+found ========================================================== 00:57:22 (1788929842) [ 5180.054315] Lustre: Failing over lustre-MDT0000 [ 5181.192523] Lustre: server umount lustre-MDT0000 complete [ 5183.972772] 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 [ 5183.973272] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 5184.009769] LustreError: 126946:0:(ldlm_lib.c:1199: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. [ 5184.048170] LustreError: 126946:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 12 previous similar messages [ 5195.796091] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 5195.902642] LustreError: MGC192.168.201.103@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5196.112107] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 5196.149079] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 5201.385136] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 5201.392672] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 5201.408057] Lustre: Skipped 3 previous similar messages [ 5201.457972] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 5201.529575] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:166 to 0x2c0000401:193) [ 5201.531281] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:295 to 0x280000401:321) [ 5201.727907] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5217.432932] Lustre: DEBUG MARKER: == sanity-lfsck test 31a: The LFSCK can find/repair the name entry with bad name hash (1) ========================================================== 00:58:36 (1788929916) [ 5235.185895] Lustre: DEBUG MARKER: == sanity-lfsck test 31b: The LFSCK can find/repair the name entry with bad name hash (2) ========================================================== 00:58:54 (1788929934) [ 5256.249389] Lustre: DEBUG MARKER: == sanity-lfsck test 31c: Re-generate the lost master LMV EA for striped directory ========================================================== 00:59:14 (1788929954) [ 5258.029639] Lustre: *** cfs_fail_loc=1629, val=0*** [ 5258.033182] Lustre: Skipped 5 previous similar messages [ 5286.603473] Lustre: DEBUG MARKER: == sanity-lfsck test 31d: Set broken striped directory (modified after broken) as read-only ========================================================== 00:59:45 (1788929985) [ 5293.163723] Lustre: Failing over lustre-MDT0000 [ 5293.541964] 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 [ 5293.567817] Lustre: Skipped 3 previous similar messages [ 5293.573217] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 5293.793357] Lustre: server umount lustre-MDT0000 complete [ 5307.020898] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5307.251827] LustreError: MGC192.168.201.103@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5307.629519] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 5312.997560] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 5312.998630] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 5313.007905] Lustre: Skipped 3 previous similar messages [ 5313.049284] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 5313.084825] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:295 to 0x280000401:353) [ 5313.086155] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:166 to 0x2c0000401:225) [ 5313.284657] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5325.359745] Lustre: Failing over lustre-MDT0000 [ 5325.646845] Lustre: server umount lustre-MDT0000 complete [ 5328.359273] 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 [ 5328.363825] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 5328.381115] Lustre: Skipped 5 previous similar messages [ 5336.450932] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5336.608932] LustreError: MGC192.168.201.103@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5336.921670] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 5337.032402] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 5342.204407] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 5342.211470] Lustre: Skipped 3 previous similar messages [ 5342.255293] Lustre: lustre-MDT0000: Recovery over after 0:05, of 2 clients 2 recovered and 0 were evicted. [ 5342.320428] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:166 to 0x2c0000401:257) [ 5342.323657] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:355 to 0x280000401:385) [ 5343.034792] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5352.901982] Lustre: DEBUG MARKER: == sanity-lfsck test 31e: Re-generate the lost slave LMV EA for striped directory (1) ========================================================== 01:00:52 (1788930052) [ 5369.410365] Lustre: DEBUG MARKER: == sanity-lfsck test 31f: Re-generate the lost slave LMV EA for striped directory (2) ========================================================== 01:01:08 (1788930068) [ 5384.865974] Lustre: DEBUG MARKER: == sanity-lfsck test 31g: Repair the corrupted slave LMV EA ========================================================== 01:01:24 (1788930084) [ 5426.076704] Lustre: DEBUG MARKER: == sanity-lfsck test 31h: Repair the corrupted shard's name entry ========================================================== 01:02:05 (1788930125) [ 5444.996112] Lustre: DEBUG MARKER: == sanity-lfsck test 32a: stop LFSCK when some OST failed ========================================================== 01:02:24 (1788930144) [ 5454.938376] LustreError: 148122:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d sleeping for 3000ms [ 5457.788139] Lustre: Failing over lustre-OST0000 [ 5457.983117] LustreError: 148122:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d awake [ 5457.993713] LustreError: 148122:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d sleeping for 3000ms [ 5458.046867] Lustre: server umount lustre-OST0000 complete [ 5458.926868] LustreError: lustre-OST0000-osc-MDT0001: operation ost_statfs to node 0@lo failed: rc = -107 [ 5458.938730] Lustre: lustre-OST0000-osc-MDT0001: Connection to lustre-OST0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 5458.958356] Lustre: Skipped 1 previous similar message [ 5458.973501] LustreError: 125306:0:(ldlm_lib.c:1199: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. [ 5458.991479] LustreError: 125306:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 30 previous similar messages [ 5460.815133] LustreError: 148122:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout interrupted [ 5472.175582] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 5472.435418] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 5472.445358] Lustre: Skipped 2 previous similar messages [ 5472.463295] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 5474.221842] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 5474.280616] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 5474.280720] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 5474.300620] Lustre: Skipped 3 previous similar messages [ 5480.894415] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5491.382512] Lustre: DEBUG MARKER: == sanity-lfsck test 32b: stop LFSCK when some MDT failed ========================================================== 01:03:10 (1788930190) [ 5508.434922] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing load_modules_local [ 5529.103457] Lustre: 150927:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 5554.713448] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5558.288648] Lustre: 152062:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 5560.132591] Lustre: 123808:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 5560.144488] Lustre: 123808:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 840 previous similar messages [ 5560.150033] Lustre: 123808:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 5560.155631] Lustre: 123808:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 840 previous similar messages [ 5560.161319] Lustre: 123808:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 5560.167105] Lustre: 123808:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 840 previous similar messages [ 5560.171695] Lustre: 123808:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 5560.177113] Lustre: 123808:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 840 previous similar messages [ 5560.184017] Lustre: 123808:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 5560.192727] Lustre: 123808:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 840 previous similar messages [ 5560.200844] Lustre: 123808:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 5560.209468] Lustre: 123808:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 840 previous similar messages [ 5571.069504] LustreError: 152199:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d sleeping for 3000ms [ 5571.090446] LustreError: 152199:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) Skipped 1 previous similar message [ 5574.100327] LustreError: 152199:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d awake [ 5574.108669] LustreError: 152199:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d sleeping for 3000ms [ 5574.179518] Lustre: Failing over lustre-MDT0001 [ 5575.136301] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 5575.151047] Lustre: Skipped 6 previous similar messages [ 5577.111133] LustreError: 152199:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d awake [ 5577.128082] LustreError: 152199:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) Skipped 1 previous similar message [ 5577.474491] Lustre: server umount lustre-MDT0001 complete [ 5594.313973] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 5594.858772] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 5600.228915] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 1 client reconnects [ 5600.239051] Lustre: lustre-MDT0001-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 5600.258904] Lustre: Skipped 1 previous similar message [ 5600.289770] Lustre: lustre-MDT0001: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 5600.421923] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:70 to 0x280000400:97) [ 5600.422659] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:69 to 0x2c0000400:97) [ 5600.809397] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5613.067732] Lustre: DEBUG MARKER: == sanity-lfsck test 33: check LFSCK paramters =========== 01:05:12 (1788930312) [ 5634.871561] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing load_modules_local [ 5656.966951] Lustre: 154921:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 5682.612466] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5686.505516] Lustre: 156056:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 5710.748651] Lustre: DEBUG MARKER: == sanity-lfsck test 34: LFSCK can rebuild the lost agent object ========================================================== 01:06:50 (1788930410) [ 5712.583832] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_34 Only valid for ZFS backend [ 5715.168454] Lustre: DEBUG MARKER: == sanity-lfsck test 35: LFSCK can rebuild the lost agent entry ========================================================== 01:06:53 (1788930413) [ 5722.392814] Lustre: *** cfs_fail_loc=1631, val=0*** [ 5737.952963] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 5737.969470] 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 [ 5737.975304] Lustre: Skipped 4 previous similar messages [ 5737.980302] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5740.417241] Lustre: server umount lustre-MDT0000 complete [ 5744.316869] LustreError: 123793:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788930444 with bad export cookie 5325497220613326337 [ 5744.325102] LustreError: MGC192.168.201.103@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5744.339912] LustreError: 123793:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 8 previous similar messages [ 5744.520209] Lustre: server umount lustre-MDT0001 complete [ 5758.095668] Lustre: server umount lustre-OST0000 complete [ 5764.076178] Lustre: 106706:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788930448/real 1788930448] req@ffff9a9a463fbb80 x1875827662463360/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788930464 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5764.717382] Lustre: server umount lustre-OST0001 complete [ 5787.774844] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing load_modules_local [ 5797.985048] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5804.131961] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5815.048275] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5820.133904] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5823.407891] Lustre: 159953:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 5831.668326] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5838.480892] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5840.426233] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:70 to 0x280000400:129) [ 5843.503393] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:540 to 0x280000401:577) [ 5846.223686] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5851.624385] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:412 to 0x2c0000401:449) [ 5851.749924] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:69 to 0x2c0000400:129) [ 5852.884793] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5860.577252] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5864.111654] Lustre: 161826:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 5873.422820] Lustre: DEBUG MARKER: == sanity-lfsck test 36a: rebuild LOV EA for mirrored file (1) ========================================================== 01:09:32 (1788930572) [ 5874.986846] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36a needs >= 3 OSTs [ 5876.957274] Lustre: DEBUG MARKER: == sanity-lfsck test 36b: rebuild LOV EA for mirrored file (2) ========================================================== 01:09:36 (1788930576) [ 5878.393460] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36b needs >= 3 OSTs [ 5880.260221] Lustre: DEBUG MARKER: == sanity-lfsck test 36c: rebuild LOV EA for mirrored file (3) ========================================================== 01:09:39 (1788930579) [ 5882.087658] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36c needs >= 3 OSTs [ 5884.054449] Lustre: DEBUG MARKER: == sanity-lfsck test 37: LFSCK must skip a ORPHAN ======== 01:09:43 (1788930583) [ 5895.613258] Lustre: DEBUG MARKER: == sanity-lfsck test 38: LFSCK does not break foreign file and reverse is also true ========================================================== 01:09:54 (1788930594) [ 5910.901803] Lustre: DEBUG MARKER: == sanity-lfsck test 39: LFSCK does not break foreign dir and reverse is also true ========================================================== 01:10:10 (1788930610) [ 5927.058153] Lustre: DEBUG MARKER: == sanity-lfsck test 40a: LFSCK correctly fixes lmm_oi in composite layout ========================================================== 01:10:26 (1788930626) [ 5945.731185] Lustre: DEBUG MARKER: == sanity-lfsck test 41: SEL support in LFSCK ============ 01:10:44 (1788930644) [ 5971.757835] Lustre: DEBUG MARKER: == sanity-lfsck test 42: LFSCK repairs inconsistent MDT-object/OST-object encryption flags ========================================================== 01:11:10 (1788930670) [ 6005.847563] Lustre: *** cfs_fail_loc=1632, val=0*** [ 6025.677546] Lustre: DEBUG MARKER: == sanity-lfsck test 43: LFSCK does not loop endlessly on iget failure in scanning-phase1 ========================================================== 01:12:04 (1788930724) [ 6029.997260] Lustre: Failing over lustre-MDT0001 [ 6030.513842] Lustre: server umount lustre-MDT0001 complete [ 6030.816232] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 6030.818536] 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 [ 6030.827612] LustreError: 158808:0:(ldlm_lib.c:1199: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. [ 6030.833767] Lustre: Skipped 6 previous similar messages [ 6030.846494] LustreError: 158808:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 28 previous similar messages [ 6039.574283] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 6039.989680] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 6040.002721] Lustre: Skipped 5 previous similar messages [ 6040.031673] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 6040.041365] Lustre: lustre-MDT0001: Aborting client recovery [ 6040.055065] LustreError: 165615:0:(ldlm_lib.c:3038:target_stop_recovery_thread()) lustre-MDT0001: Aborting recovery [ 6040.058434] LustreError: 165637:0:(lod_dev.c:511:lod_sub_recovery_thread()) lustre-MDT0001-osd: get update log duration 0, retries 0, failed: rc = -108 [ 6040.066343] Lustre: 165639:0:(ldlm_lib.c:2438:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 6040.088811] LustreError: 165637:0:(lod_dev.c:511:lod_sub_recovery_thread()) Skipped 1 previous similar message [ 6040.097121] Lustre: 165639:0:(genops.c:1600:class_disconnect_stale_exports()) lustre-MDT0001: disconnect stale client d1c5de59-a2a9-40b8-803b-27cffce68078@ [ 6040.106454] Lustre: lustre-MDT0001: disconnecting 2 stale clients [ 6040.119448] Lustre: lustre-MDT0001-osd: cancel update llog [0x240000400:0x1:0x0] [ 6040.139947] Lustre: lustre-MDT0000-osp-MDT0001: cancel update llog [0x200000401:0x1:0x0] [ 6040.194214] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:70 to 0x280000400:161) [ 6040.201416] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:131 to 0x2c0000400:161) [ 6045.165815] LustreError: lustre-MDT0001-osp-MDT0000: This client was evicted by lustre-MDT0001; in progress operations using this service will fail. [ 6045.191826] Lustre: lustre-MDT0001-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 6045.197271] Lustre: Skipped 3 previous similar messages [ 6045.363877] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6049.124728] Lustre: *** cfs_fail_loc=1e2, val=483*** [ 6053.365361] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing wait_import_state FULL osp.lustre-MDT0001-os[pc]-MDT0000.*_server_uuid [ 6053.614480] Lustre: DEBUG MARKER: osp.lustre-MDT0001-os[pc]-MDT0000.*_server_uuid in FULL state after 0 sec [ 6061.102583] Lustre: DEBUG MARKER: == sanity-lfsck test 44: umount while lfsck is stopping == 01:12:40 (1788930760) [ 6068.683738] Lustre: *** cfs_fail_loc=1600, val=3*** [ 6071.609932] Lustre: Failing over lustre-MDT0000 [ 6072.028688] Lustre: server umount lustre-MDT0000 complete [ 6083.531669] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 6083.753439] LustreError: MGC192.168.201.103@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 6084.013774] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 6084.025493] Lustre: Skipped 2 previous similar messages [ 6087.604055] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 6089.024895] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6089.210680] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 6089.223038] Lustre: Skipped 1 previous similar message [ 6089.260592] Lustre: lustre-MDT0000: Recovery over after 0:02, of 2 clients 2 recovered and 0 were evicted. [ 6089.328361] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:621 to 0x280000401:641) [ 6089.333340] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:489 to 0x2c0000401:513) [ 6100.698621] Lustre: DEBUG MARKER: == sanity-lfsck test 45: LFSCK should fix UID/GID/PROJID of OST object ========================================================== 01:13:19 (1788930799) [ 6152.151449] Lustre: Failing over lustre-OST0001 [ 6152.277160] Lustre: server umount lustre-OST0001 complete [ 6152.671843] LustreError: lustre-OST0001-osc-MDT0001: operation ost_statfs to node 0@lo failed: rc = -107 [ 6152.682548] LustreError: Skipped 1 previous similar message [ 6159.741528] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: (null) [ 6171.391465] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 6171.546154] Lustre: lustre-OST0001: in recovery but waiting for the first client to connect [ 6173.234927] Lustre: lustre-OST0001: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 6173.476653] Lustre: lustre-OST0001: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [ 6173.477187] Lustre: lustre-OST0001-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 6173.510582] Lustre: Skipped 3 previous similar messages [ 6177.957345] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6185.729333] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing wait_import_state (FULL|IDLE) os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid 50 [ 6186.217989] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid in FULL state after 0 sec [ 6192.719512] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing wait_import_state (FULL|IDLE) os[cp].lustre-OST0000-osc-MDT0001.ost_server_uuid 50 [ 6192.983815] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0001.ost_server_uuid in FULL state after 0 sec [ 6199.252767] Lustre: DEBUG MARKER: oleg103-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0000-osc-ffff987d58a8a800.ost_server_uuid 50 [ 6200.810863] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff987d58a8a800.ost_server_uuid in FULL state after 0 sec [ 6288.863989] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 6288.877582] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 6288.880173] Lustre: Skipped 4 previous similar messages [ 6292.657394] Lustre: server umount lustre-MDT0000 complete [ 6301.738951] LustreError: 160330:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788931001 with bad export cookie 5325497220613409364 [ 6301.749883] LustreError: MGC192.168.201.103@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 6301.750874] LustreError: 160330:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 6302.249367] Lustre: server umount lustre-MDT0001 complete [ 6319.903129] Lustre: 106705:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788931004/real 1788931004] req@ffff9a9b8179d180 x1875827662885248/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788931020 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6321.070928] Lustre: server umount lustre-OST0000 complete [ 6323.167952] Lustre: 106708:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788931007/real 1788931007] req@ffff9a9b8179c700 x1875827662885504/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788931023 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6326.111225] Lustre: 106705:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788931010/real 1788931010] req@ffff9a9a47262680 x1875827662885760/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788931026 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6330.771585] Lustre: server umount lustre-OST0001 complete [ 6348.710456] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing unload_modules_local [ 6351.305905] Key type lgssc unregistered [ 6351.578112] LNet: 175360:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 6351.587781] LNetError: 175360:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 6351.615298] LNet: Removed LNI 192.168.201.103@tcp [ 6352.291653] Key type .llcrypt unregistered [ 6352.294907] Key type ._llcrypt unregistered [ 6378.510598] Key type ._llcrypt registered [ 6378.513150] Key type .llcrypt registered [ 6378.609598] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_hostid [ 6397.214814] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing load_modules_local [ 6398.664394] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 6398.725844] alg: No test for adler32 (adler32-zlib) [ 6399.910296] Lustre: Lustre: Build Version: 2.17.58_39_gf1a8369 [ 6400.214658] LNet: Added LNI 192.168.201.103@tcp [8/256/0/180] [ 6401.895360] Key type lgssc registered [ 6403.166250] Lustre: Echo OBD driver; http://www.lustre.org/ [ 6463.181608] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing load_modules_local [ 6481.055757] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 6481.107752] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 6482.616825] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 6482.711667] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 6482.870377] Lustre: lustre-MDT0000: new disk, initializing [ 6483.121349] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 6483.166364] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 6490.019577] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6506.175094] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 6506.315793] Lustre: 179811:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 6506.336930] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 6506.339302] Lustre: Skipped 1 previous similar message [ 6506.396350] Lustre: lustre-MDT0001: new disk, initializing [ 6506.457818] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 6506.503034] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 6506.512471] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 6511.740685] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6517.036695] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 6527.959929] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 6528.333902] Lustre: lustre-OST0000: new disk, initializing [ 6528.343613] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 6528.355376] Lustre: 181750:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 6528.428719] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 6528.993272] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 6529.007516] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 6529.087224] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 6535.059385] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6549.907558] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 6550.090828] Lustre: lustre-OST0001: new disk, initializing [ 6550.097816] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 6550.104834] Lustre: 182775:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 6550.177551] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 6556.901750] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6558.330018] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 6558.336249] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 6558.426748] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 6568.540366] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 6573.871154] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 6581.692206] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 01:21:20 (1788931280) === [ 6583.867478] Lustre: DEBUG MARKER: == sanity-lfsck test complete, duration 6290 sec ========= 01:21:22 (1788931282) [ 6586.084891] Lustre: DEBUG MARKER: === sanity-lfsck: start cleanup 01:21:24 (1788931284) === [ 6589.930377] Lustre: DEBUG MARKER: === sanity-lfsck: finish cleanup 01:21:29 (1788931289) === [ 6594.531792] 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 [ 6594.535921] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 6594.553084] Lustre: Skipped 1 previous similar message [ 6594.565026] Lustre: Skipped 3 previous similar messages [ 6599.649268] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 6600.550601] Lustre: server umount lustre-MDT0000 complete [ 6609.096618] LustreError: 179805:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788931309 with bad export cookie 3271095538124784055 [ 6609.100435] LustreError: MGC192.168.201.103@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 6609.108152] LustreError: 179805:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 6609.393495] Lustre: server umount lustre-MDT0001 complete [ 6626.271172] Lustre: 176971:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788931310/real 1788931310] req@ffff9a9b66c97b80 x1875830217197696/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788931326 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6626.302772] 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 [ 6626.310363] Lustre: Skipped 2 previous similar messages [ 6629.746653] Lustre: server umount lustre-OST0000 complete [ 6631.397197] Lustre: 176969:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788931315/real 1788931315] req@ffff9a9a463fb100 x1875830217197952/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788931331 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6636.000103] Lustre: 176970:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788931320/real 1788931320] req@ffff9a9b4486ea00 x1875830217198336/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788931336 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6638.329808] Lustre: server umount lustre-OST0001 complete [ 6656.345703] Lustre: DEBUG MARKER: oleg103-server.virtnet: executing unload_modules_local [ 6659.687427] Key type lgssc unregistered [ 6660.062677] LNet: 186253:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 6660.083212] LNetError: 186253:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 6660.113910] LNet: Removed LNI 192.168.201.103@tcp [ 6661.058297] Key type .llcrypt unregistered [ 6661.060898] Key type ._llcrypt unregistered