[ 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 499006515 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2399.998 MHz processor [ 0.000000] last_pfn = 0x146e00 max_arch_pfn = 0x400000000 [ 0.000000] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT [ 0.000000] last_pfn = 0xbffce max_arch_pfn = 0x400000000 [ 0.000000] found SMP MP-table at [mem 0x000f54b0-0x000f54bf] [ 0.000000] RAMDISK: [mem 0xbcc54000-0xbffbffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F52D0 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE247C 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE2318 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 0022D8 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE238C 000090 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE241C 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE2454 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe2318-0xbffe238b] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe2317] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe238c-0xbffe241b] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe241c-0xbffe2453] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe2454-0xbffe247b] [ 0.000000] No NUMA configuration found [ 0.000000] Faking a node at [mem 0x0000000000000000-0x0000000146dfffff] [ 0.000000] NODE_DATA(0) allocated [mem 0x1465a3000-0x1465cdfff] [ 0.000000] Reserving 256MB of memory at 2752MB for crashkernel (System RAM: 4205MB) [ 0.000000] Zone ranges: [ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.000000] DMA32 [mem 0x0000000001000000-0x00000000ffffffff] [ 0.000000] Normal [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Device empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff] [ 0.000000] node 0: [mem 0x0000000000100000-0x00000000bffcdfff] [ 0.000000] node 0: [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Zeroed struct page in unavailable ranges: 4756 pages [ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x0000000146dfffff] [ 0.000000] ACPI: PM-Timer IO Port: 0x608 [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) [ 0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) [ 0.000000] Using ACPI (MADT) for SMP configuration information [ 0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000] TSC deadline timer available [ 0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs [ 0.000000] kvm-guest: KVM setup pv remote TLB flush [ 0.000000] kvm-guest: setup PV sched yield [ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff] [ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff] [ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff] [ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff] [ 0.000000] PM: Registered nosave memory: [mem 0xbffce000-0xbfffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xc0000000-0xfeffbfff] [ 0.000000] PM: Registered nosave memory: [mem 0xfeffc000-0xfeffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xff000000-0xfffbffff] [ 0.000000] PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff] [ 0.000000] [mem 0xc0000000-0xfeffbfff] available for PCI devices [ 0.000000] Booting paravirtualized kernel on KVM [ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns [ 0.000000] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1 [ 0.000000] percpu: Embedded 63 pages/cpu s221184 r8192 d28672 u524288 [ 0.000000] kvm-guest: PV spinlocks enabled [ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1059606 [ 0.000000] Policy zone: Normal [ 0.000000] Kernel command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] Specific versions of hardware are certified with Red Hat Enterprise Linux 8. Please see the list of hardware certified with Red Hat Enterprise Linux 8 at https://catalog.redhat.com. [ 0.000000] audit: disabled (until reboot) [ 0.000000] software IO TLB: area num 4. [ 0.000000] Memory: 2829652K/4306352K available (18435K kernel code, 11221K rwdata, 7248K rodata, 2908K init, 18040K bss, 524584K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] ftrace: allocating 41240 entries in 162 pages [ 0.000000] ftrace: allocated 162 pages with 3 groups [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] rcu: RCU event tracing is enabled. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ 0.000000] rcu: RCU callback double-/use-after-free debug enabled. [ 0.000000] Rude variant of Tasks RCU enabled. [ 0.000000] Tracing variant of Tasks RCU enabled. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 0.000000] NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16 [ 0.000000] random: get_random_bytes called from start_kernel+0x622/0x9a8 with crng_init=0 [ 0.001000] Console: colour *CGA 80x25 [ 0.001000] printk: console [ttyS1] enabled [ 0.001000] ACPI: Core revision 20220331 [ 0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.001010] APIC: Switch to symmetric I/O mode setup [ 0.002348] x2apic enabled [ 0.003008] Switched APIC routing to physical x2apic. [ 0.004013] kvm-guest: setup PV IPIs [ 0.007000] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.007000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.008017] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.009010] pid_max: default: 32768 minimum: 301 [ 0.010126] LSM: Security Framework initializing [ 0.011049] Yama: becoming mindful. [ 0.012030] SELinux: Initializing. [ 0.013057] *** VALIDATE selinux *** [ 0.021416] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.025586] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.027122] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.028104] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.030084] *** VALIDATE tmpfs *** [ 0.032102] *** VALIDATE proc *** [ 0.033228] *** VALIDATE cgroup *** [ 0.034008] *** VALIDATE cgroup2 *** [ 0.035255] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.036146] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.037007] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.038026] Spectre V2 : User space: Vulnerable [ 0.039007] Speculative Store Bypass: Vulnerable [ 0.041872] debug: unmapping init [mem 0xffffffff96459000-0xffffffff96460fff] [ 0.043155] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.044623] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.045021] ... version: 2 [ 0.046010] ... bit width: 48 [ 0.047010] ... generic registers: 4 [ 0.048013] ... value mask: 0000ffffffffffff [ 0.049012] ... max period: 00007fffffffffff [ 0.050013] ... fixed-purpose events: 3 [ 0.051010] ... event mask: 000000070000000f [ 0.052283] rcu: Hierarchical SRCU implementation. [ 0.054466] smp: Bringing up secondary CPUs ... [ 0.055551] x86: Booting SMP configuration: [ 0.056022] .... node #0, CPUs: #1 #2 #3 [ 0.059066] smp: Brought up 1 node, 4 CPUs [ 0.061012] smpboot: Max logical packages: 1 [ 0.062016] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.098441] node 0 deferred pages initialised in 34ms [ 0.102154] devtmpfs: initialized [ 0.103272] x86/mm: Memory block size: 128MB [ 0.105800] gcov: version magic: 0x41383552 [ 0.107324] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.108076] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.109266] pinctrl core: initialized pinctrl subsystem [ 0.110211] [ 0.110823] ************************************************************* [ 0.111016] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.112015] ** ** [ 0.113014] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.114015] ** ** [ 0.115013] ** This means that this kernel is built to expose internal ** [ 0.116014] ** IOMMU data structures, which may compromise security on ** [ 0.117011] ** your system. ** [ 0.118012] ** ** [ 0.119012] ** If you see this message and you are not debugging the ** [ 0.120011] ** kernel, report this immediately to your vendor! ** [ 0.121011] ** ** [ 0.122010] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.123046] ************************************************************* [ 0.124612] NET: Registered protocol family 16 [ 0.125449] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.126063] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.127057] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.128492] cpuidle: using governor menu [ 0.129676] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.132530] PCI: Using configuration type 1 for base access [ 0.134133] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.143062] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.144018] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.146037] cryptd: max_cpu_qlen set to 1000 [ 0.148268] ACPI: Added _OSI(Module Device) [ 0.149016] ACPI: Added _OSI(Processor Device) [ 0.150013] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.151013] ACPI: Added _OSI(Processor Aggregator Device) [ 0.155084] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.158588] ACPI: Interpreter enabled [ 0.159053] ACPI: PM: (supports S0 S3 S4 S5) [ 0.160024] ACPI: Using IOAPIC for interrupt routing [ 0.161780] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.165425] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.175848] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.178038] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.180018] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.183073] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.187459] acpiphp: Slot [2] registered [ 0.189179] acpiphp: Slot [5] registered [ 0.190152] acpiphp: Slot [6] registered [ 0.192126] acpiphp: Slot [7] registered [ 0.193125] acpiphp: Slot [8] registered [ 0.194123] acpiphp: Slot [9] registered [ 0.196130] acpiphp: Slot [10] registered [ 0.197145] acpiphp: Slot [3] registered [ 0.198088] acpiphp: Slot [4] registered [ 0.200098] acpiphp: Slot [11] registered [ 0.201089] acpiphp: Slot [12] registered [ 0.202086] acpiphp: Slot [13] registered [ 0.204096] acpiphp: Slot [14] registered [ 0.205086] acpiphp: Slot [15] registered [ 0.206106] acpiphp: Slot [16] registered [ 0.207105] acpiphp: Slot [17] registered [ 0.209093] acpiphp: Slot [18] registered [ 0.210114] acpiphp: Slot [19] registered [ 0.212091] acpiphp: Slot [20] registered [ 0.213080] acpiphp: Slot [21] registered [ 0.214079] acpiphp: Slot [22] registered [ 0.216145] acpiphp: Slot [23] registered [ 0.218101] acpiphp: Slot [24] registered [ 0.219096] acpiphp: Slot [25] registered [ 0.221100] acpiphp: Slot [26] registered [ 0.223115] acpiphp: Slot [27] registered [ 0.225157] acpiphp: Slot [28] registered [ 0.226180] acpiphp: Slot [29] registered [ 0.228107] acpiphp: Slot [30] registered [ 0.230099] acpiphp: Slot [31] registered [ 0.232082] PCI host bridge to bus 0000:00 [ 0.234020] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.236084] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.239023] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.242081] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.245037] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.249030] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.251297] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.254083] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.258445] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.269966] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.276056] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.279017] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.282022] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.285019] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.288574] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.291851] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.294046] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.298811] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.304017] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.320017] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.325015] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.332684] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.339028] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.346033] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.366029] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.376606] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.387018] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.395018] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.411022] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.422114] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.432016] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.441015] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.466018] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.480650] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.495024] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.500022] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.515024] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.525514] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.533017] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.541022] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.562014] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 0.573172] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.582023] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.587024] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.599038] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 0.610056] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.612376] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.616376] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.618359] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.621235] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.627169] iommu: Default domain type: Passthrough [ 0.629622] SCSI subsystem initialized [ 0.631195] ACPI: bus type USB registered [ 0.633122] usbcore: registered new interface driver usbfs [ 0.635115] usbcore: registered new interface driver hub [ 0.639166] usbcore: registered new device driver usb [ 0.641173] pps_core: LinuxPPS API ver. 1 registered [ 0.642014] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.645089] PTP clock support registered [ 0.648084] EDAC MC: Ver: 3.0.0 [ 0.650136] PCI: Using ACPI for IRQ routing [ 0.652853] NetLabel: Initializing [ 0.654012] NetLabel: domain hash size = 128 [ 0.656013] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.658074] NetLabel: unlabeled traffic allowed by default [ 0.660116] vgaarb: loaded [ 0.662272] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.664016] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.668309] clocksource: Switched to clocksource kvm-clock [ 0.781041] VFS: Disk quotas dquot_6.6.0 [ 0.782315] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.784840] *** VALIDATE ramfs *** [ 0.786106] *** VALIDATE hugetlbfs *** [ 0.787858] pnp: PnP ACPI init [ 0.790470] pnp: PnP ACPI: found 6 devices [ 0.807847] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.811461] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.813497] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.815405] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.817501] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.819727] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.822351] NET: Registered protocol family 2 [ 0.824746] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.829243] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.832575] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.837525] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.840729] TCP: Hash tables configured (established 65536 bind 65536) [ 0.843521] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.846730] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.849731] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.853209] NET: Registered protocol family 1 [ 0.856702] RPC: Registered named UNIX socket transport module. [ 0.859122] RPC: Registered udp transport module. [ 0.860684] RPC: Registered tcp transport module. [ 0.862302] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.865163] NET: Registered protocol family 44 [ 0.866965] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.869281] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.871696] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.874238] PCI: CLS 0 bytes, default 64 [ 0.876122] Unpacking initramfs... [ 2.382972] debug: unmapping init [mem 0xffff94883cc54000-0xffff94883ffbffff] [ 2.388981] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.390660] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.394039] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 2.915866] Initialise system trusted keyrings [ 2.917908] Key type blacklist registered [ 2.923546] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.933898] zbud: loaded [ 2.937116] *** VALIDATE nfs *** [ 2.938485] *** VALIDATE nfs4 *** [ 2.940369] pstore: using deflate compression [ 2.943777] Platform Keyring initialized [ 3.074431] NET: Registered protocol family 38 [ 3.078788] Key type asymmetric registered [ 3.080059] Asymmetric key parser 'x509' registered [ 3.081669] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 3.084163] io scheduler mq-deadline registered [ 3.086532] io scheduler kyber registered [ 3.088359] io scheduler bfq registered [ 3.090377] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 3.093635] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 3.097688] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 3.101442] ACPI: Power Button [PWRF] [ 3.109131] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 3.116243] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 3.132143] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 3.138966] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 3.162894] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 3.191459] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.222624] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.228335] Non-volatile memory driver v1.3 [ 3.230227] Linux agpgart interface v0.103 [ 3.268136] virtio_blk virtio1: [vda] 146216 512-byte logical blocks (74.9 MB/71.4 MiB) [ 3.271502] vda: detected capacity change from 0 to 74862592 [ 3.287356] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.290784] vdb: detected capacity change from 0 to 1073741824 [ 3.305730] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.308982] vdc: detected capacity change from 0 to 2621440000 [ 3.324097] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.327563] vdd: detected capacity change from 0 to 2621440000 [ 3.344658] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.348046] vde: detected capacity change from 0 to 4294967296 [ 3.363149] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.366361] vdf: detected capacity change from 0 to 4294967296 [ 3.374417] libphy: Fixed MDIO Bus: probed [ 3.381137] usbcore: registered new interface driver usbserial_generic [ 3.384420] usbserial: USB Serial support registered for generic [ 3.386914] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.391185] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.393194] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.396937] mousedev: PS/2 mouse device common for all mice [ 3.401029] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.401584] rtc_cmos 00:05: RTC can wake from S4 [ 3.408696] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.415406] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.415761] rtc_cmos 00:05: registered as rtc0 [ 3.420026] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.422211] intel_pstate: CPU model not supported [ 3.425262] hid: raw HID events driver (C) Jiri Kosina [ 3.427140] usbcore: registered new interface driver usbhid [ 3.429086] usbhid: USB HID core driver [ 3.430412] drop_monitor: Initializing network drop monitor service [ 3.432579] Initializing XFRM netlink socket [ 3.434635] NET: Registered protocol family 10 [ 3.437616] Segment Routing with IPv6 [ 3.438940] NET: Registered protocol family 17 [ 3.440783] mpls_gso: MPLS GSO support [ 3.446964] RAS: Correctable Errors collector initialized. [ 3.448726] AVX version of gcm_enc/dec engaged. [ 3.450584] AES CTR mode by8 optimization enabled [ 3.546683] sched_clock: Marking stable (3546595563, 0)->(4500172819, -953577256) [ 3.552864] registered taskstats version 1 [ 3.555392] Loading compiled-in X.509 certificates [ 3.557684] zswap: loaded using pool lzo/zbud [ 3.584369] Key type big_key registered [ 3.596750] Key type encrypted registered [ 3.598538] ima: No TPM chip found, activating TPM-bypass! [ 3.600734] ima: Allocated hash algorithm: sha1 [ 3.602548] ima: No architecture policies found [ 3.604414] evm: Initialising EVM extended attributes: [ 3.606609] evm: security.selinux [ 3.608038] evm: security.ima [ 3.609137] evm: security.capability [ 3.610824] evm: HMAC attrs: 0x1 [ 3.615243] rtc_cmos 00:05: setting system clock to 2026-08-24 05:10:21 UTC (1787548221) [ 3.622840] debug: unmapping init [mem 0xffffffff97403000-0xffffffff975fffff] [ 3.626294] debug: unmapping init [mem 0xffffffff96182000-0xffffffff96458fff] [ 3.635164] Write protecting the kernel read-only data: 28672k [ 3.639035] debug: unmapping init [mem 0xffffffff94803000-0xffffffff949fffff] [ 3.642023] debug: unmapping init [mem 0xffffffff95114000-0xffffffff951fffff] [ 3.684567] 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.693929] systemd[1]: Detected virtualization kvm. [ 3.696312] systemd[1]: Detected architecture x86-64. [ 3.698412] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.725970] systemd[1]: No hostname configured. [ 3.727545] systemd[1]: Set hostname to . [ 3.729678] random: systemd: uninitialized urandom read (16 bytes read) [ 3.732555] systemd[1]: Initializing machine ID from random generator. [ 3.768331] random: ln: uninitialized urandom read (6 bytes read) [ 3.856153] random: systemd: uninitialized urandom read (16 bytes read) [ 3.859319] systemd[1]: Reached target Slices. [ OK ] Reached target Slices. [ 3.864480] systemd[1]: Reached target Swap. [ OK ] Reached target Swap. [ 3.869446] systemd[1]: Listening on udev Control Socket. [ OK ] Listening on udev Control Socket. [ OK ] Reached target Initrd Root Device. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Listening on udev Kernel Socket. [ OK ] Listening on Journal Socket (/dev/log). [ OK ] Listening on Journal Socket. [ OK ] Started Memstrack Anylazing Service. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Reached target Sockets. Starting Journal Service... Starting Apply Kernel Variables... [ OK ] Reached target Local File Systems. Starting Create Volatile Files and Directories... [ OK ] Reached target Timers. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. Starting Setup Virtual Console... [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Apply Kernel Variables. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Setup Virtual Console. Starting dracut cmdline hook... Starting Create Static Device Nodes in /dev... [ OK ] Started Journal Service. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 4.482220] device-mapper: uevent: version 1.0.3 [ 4.484305] device-mapper: ioctl: 4.46.0-ioctl (2022-02-22) initialised: dm-devel@redhat.com [ OK ] Started dracut pre-udev hook. Starting udev Kernel Device Manager... [ OK ] Started udev Kernel Device Manager. Starting dracut pre-trigger hook... [ OK ] Started dracut pre-trigger hook. Starting udev Coldplug all Devices... Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. [ OK ] Reached target System Initialization.[ 5.177380] random: fast init done [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting dracut initqueue hook... [ 5.230121] virtio_net virtio0 ens2: renamed from eth0 [ 5.314290] scsi host0: ata_piix [ 5.338595] scsi host1: ata_piix [ 5.340529] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 5.343193] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 9.100697] dracut-initqueue[583]: RTNETLINK answers: File exists [ 10.118768] random: crng init done [ 10.120448] 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.545278] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped target Timers. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped target Basic System. [ OK ] Stopped target Slices. [ OK ] Stopped target Sockets. [ OK ] Stopped target System Initialization. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. Stopping udev Kernel Device Manager... [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Swap. [ OK ] Stopped target Local File Systems. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped target Paths. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ 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 Kernel Socket. [ OK ] Closed udev Control Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 11.708243] printk: systemd: 25 output lines suppressed due to ratelimiting [ 11.965534] SELinux: Disabled at runtime. [ 12.025471] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 12.034810] systemd[1]: Detected virtualization kvm. [ 12.036285] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 12.523799] systemd[1]: initrd-switch-root.service: Succeeded. [ 12.527871] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 12.536851] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 12.543512] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 12.546943] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 12.554065] systemd[1]: Starting Journal Service... Starting Journal Service... [ 12.562063] systemd[1]: Mounting Kernel Debug File System... Mounting Kernel Debug File System... Starting Create list of required st…ce nodes for the current kernel... Activating swap /dev/disk/by-label/SWAP... [ OK ] Listening on udev Kernel Socket. [ OK ] Stopped target Switch Root. [ OK ] Reached target rpc_pipefs.target. [ OK ] Listening on udev Control Socket. [ 12.610971] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS [ OK ] Listening on Process Core Dump Socket. [ OK ] Created slice system-getty.slice. [ OK ] Created slice User and Session Slice. [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Reached target RPC Port Mapper. Starting udev Coldplug all Devices... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. Mounting POSIX Message Queue File System... [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Reached target Slices. [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. [ OK ] Stopped target Initrd File Systems. [ OK ] Stopped target Initrd Root File System. [ OK ] Listening on initctl Compatibility Named Pipe. Mounting Huge Pages File System... Starting Remount Root and Kernel File Systems... Starting Apply Kernel Variables... [ OK ] Started Journal Service. [ OK ] Mounted Kernel Debug File System. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Mounted Huge Pages File System. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Started Apply Kernel Variables. Starting Configure read-only root support... [ OK ] Reached target Swap. Starting Create Static Device Nodes in /dev... Starting Flush Journal to Persistent Storage... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. Starting udev Kernel Device Manager... [ OK ] Reached target Local File Systems (Pre). Mounting /home/green/git/lustre-release... Mounting /mnt... [ OK ] Started udev Coldplug all Devices. [ OK ] Mounted /mnt. [ 12.985987] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 13.314448] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 13.339833] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 13.443048] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 13.510336] EDAC sbridge: Ver: 1.1.2 [ 15.322959] Key type dns_resolver registered [ 15.650158] NFS: Registering the id_resolver key type [ 15.652417] Key type id_resolver registered [ 15.653934] Key type id_legacy registered [ OK ] Started Configure read-only root support. Starting Load/Save Random Seed... [ OK ] Reached target Local File Systems. Starting Rebuild Dynamic Linker Cache... Starting Mark the need to relabel after reboot... Starting Create Volatile Files and Directories... [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Load/Save Random Seed. [ OK ] Started Create Volatile Files and Directories. Starting Update UTMP about System Boot/Shutdown... Starting RPC Bind... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Started dnf makecache --timer. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. [ OK ] Started D-Bus System Message Bus. Starting Restore /run/initramfs on shutdown... Starting Network Manager... Starting Login Service... [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Reached target sshd-keygen.target. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Reached target Timers. [ OK ] Started irqbalance daemon. [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Login Service. [ OK ] Started Network Manager. [ OK ] Reached target Network. Starting OpenSSH server daemon... Starting GSSAPI Proxy Daemon... Starting Dynamic System Tuning Daemon... Starting Network Manager Wait Online... [ OK ] Started OpenSSH server daemon. [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... Starting Hostname Service... [ OK ] Started Permit User Sessions. [ OK ] Started Getty on tty1. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Serial Getty on ttyS1. [ OK ] Reached target Login Prompts. [ OK ] Started Command Scheduler. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting System Logging Service... Starting Crash recovery kernel arming... Starting Notify NFS peers of a restart... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Starting Authorization Manager... [ OK ] Started Authorization Manager. [ OK ] Started Dynamic System Tuning Daemon. [ OK ] Reached target Multi-User System. [ OK ] Reached target Graphical Interface. Starting Update UTMP about System Runlevel Changes... [ OK ] Started Update UTMP about System Runlevel Changes. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg459-server login: [ 48.927120] libcfs: loading out-of-tree module taints kernel. [ 48.955461] Key type ._llcrypt registered [ 48.957686] Key type .llcrypt registered [ 49.044037] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_hostid [ 70.915881] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing load_modules_local [ 73.583530] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 73.612591] alg: No test for adler32 (adler32-zlib) [ 75.159328] Lustre: Lustre: Build Version: 2.17.57_83_g6b3cfd8 [ 76.716918] LNet: Added LNI 192.168.204.159@tcp [8/256/0/180] [ 76.740444] hrtimer: interrupt took 8275523 ns [ 78.489711] Key type lgssc registered [ 81.425838] Lustre: Echo OBD driver; http://www.lustre.org/ [ 101.372828] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 144.727183] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing load_modules_local [ 158.791255] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 158.856686] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 160.242161] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 160.331651] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 160.494240] Lustre: lustre-MDT0000: new disk, initializing [ 160.598431] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 160.613235] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 165.638526] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 181.935862] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 182.099971] Lustre: 6510: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 [ 182.155514] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 182.160947] Lustre: Skipped 1 previous similar message [ 182.233398] Lustre: lustre-MDT0001: new disk, initializing [ 182.343456] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 182.386414] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 182.400104] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 187.355635] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 193.073472] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 205.583439] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 205.850302] Lustre: lustre-OST0000: new disk, initializing [ 205.858502] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 205.864797] Lustre: 8450:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 205.950559] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 207.333971] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 207.356120] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 207.406571] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 212.576229] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 229.539407] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 229.672376] Lustre: lustre-OST0001: new disk, initializing [ 229.676514] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 229.685083] Lustre: 9524:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 229.776205] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 236.208819] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 239.715277] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 239.756267] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 239.862775] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 249.200345] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 257.701146] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 266.927855] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing check_logdir /tmp/testlogs/ [ 273.509780] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing yml_node [ 278.473973] Lustre: DEBUG MARKER: Client: 2.17.57.83 [ 281.163837] Lustre: DEBUG MARKER: MDS: 2.17.57.83 [ 284.191209] Lustre: DEBUG MARKER: OSS: 2.17.57.83 [ 286.281936] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity-lfsck ============----- Mon Aug 24 01:15:01 EDT 2026 [ 305.264701] Lustre: DEBUG MARKER: excepting tests: 18b 23b [ 315.971783] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing load_modules_local [ 325.602503] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 325.615238] 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 [ 325.626765] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 327.137755] 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 [ 327.142356] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 327.154017] Lustre: Skipped 1 previous similar message [ 327.179499] Lustre: Skipped 3 previous similar messages [ 331.012419] Lustre: server umount lustre-MDT0000 complete [ 337.384733] LustreError: 6518:0:(ldlm_lib.c:1190: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. [ 337.419499] LustreError: 6518:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 8 previous similar messages [ 342.185714] LustreError: 6503:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787548560 with bad export cookie 6661665550927681686 [ 342.186786] LustreError: MGC192.168.204.159@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 342.203706] LustreError: 6503:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 342.438825] Lustre: server umount lustre-MDT0001 complete [ 358.881101] Lustre: 3642:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787548560/real 1787548560] req@ffff9488b203c000 x1874380240037504/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787548576 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 358.926949] 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 [ 358.940145] Lustre: Skipped 1 previous similar message [ 363.809702] Lustre: 3644:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787548565/real 1787548565] req@ffff948782d30e00 x1874380240037760/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787548581 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 364.178861] Lustre: server umount lustre-OST0000 complete [ 369.123686] Lustre: 3642:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787548570/real 1787548570] req@ffff9488b7e68700 x1874380240038016/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787548586 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 373.252072] Lustre: server umount lustre-OST0001 complete [ 391.497501] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing unload_modules_local [ 395.028483] Key type lgssc unregistered [ 395.355646] LNet: 14802:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 395.359166] LNetError: 14802:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 395.378338] LNet: Removed LNI 192.168.204.159@tcp [ 396.693207] Key type .llcrypt unregistered [ 396.696751] Key type ._llcrypt unregistered [ 423.201228] Key type ._llcrypt registered [ 423.203725] Key type .llcrypt registered [ 423.344482] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_hostid [ 438.567449] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing load_modules_local [ 439.928377] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 439.955118] alg: No test for adler32 (adler32-zlib) [ 441.136645] Lustre: Lustre: Build Version: 2.17.57_83_g6b3cfd8 [ 441.444680] LNet: Added LNI 192.168.204.159@tcp [8/256/0/180] [ 443.181905] Key type lgssc registered [ 444.372726] Lustre: Echo OBD driver; http://www.lustre.org/ [ 500.085553] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing load_modules_local [ 514.256836] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 514.288176] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 515.661513] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 515.741239] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 515.904124] Lustre: lustre-MDT0000: new disk, initializing [ 515.964108] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 515.978405] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 521.649270] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 535.624848] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 535.720761] Lustre: 19260: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 [ 535.742107] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 535.748084] Lustre: Skipped 1 previous similar message [ 535.808589] Lustre: lustre-MDT0001: new disk, initializing [ 535.864059] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 535.890680] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 535.909945] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 541.186932] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 546.071334] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 556.645060] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 557.025701] Lustre: lustre-OST0000: new disk, initializing [ 557.032259] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 557.044606] Lustre: 21199:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 557.136852] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 557.340907] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 557.350993] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 557.406075] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000400 [ 563.831358] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 578.293548] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 578.527102] Lustre: lustre-OST0001: new disk, initializing [ 578.538045] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 578.550089] Lustre: 22222:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 578.659835] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 586.332146] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 586.352444] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 586.427047] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 587.395376] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 602.196479] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 609.516607] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 618.149911] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 01:20:33 (1787548833) === [ 621.066255] Lustre: DEBUG MARKER: == sanity-lfsck test 0: Control LFSCK manually =========== 01:20:36 (1787548836) [ 621.347474] Lustre: 19267:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 251 < left 278, rollback = 2 [ 621.364858] Lustre: 19267:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 621.373452] Lustre: 19267:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 621.389848] Lustre: 19267:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 621.404644] Lustre: 19267:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 621.411775] Lustre: 19267:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 621.924355] Lustre: 19267:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 621.933764] Lustre: 19267:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 11 previous similar messages [ 621.941092] Lustre: 19267:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 621.950410] Lustre: 19267:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 621.963403] Lustre: 19267:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 621.976223] Lustre: 19267:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 621.988902] Lustre: 19267:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 621.996555] Lustre: 19267:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 622.007033] Lustre: 19267:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 622.020142] Lustre: 19267:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 622.028921] Lustre: 19267:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 622.036542] Lustre: 19267:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 622.953103] Lustre: 19267:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 622.964371] Lustre: 19267:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 44 previous similar messages [ 622.977470] Lustre: 19267:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 622.984223] Lustre: 19267:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 44 previous similar messages [ 622.990610] Lustre: 19267:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 622.995772] Lustre: 19267:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 44 previous similar messages [ 623.000634] Lustre: 19267:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 623.005940] Lustre: 19267:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 44 previous similar messages [ 623.010575] Lustre: 19267:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 623.015570] Lustre: 19267:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 44 previous similar messages [ 623.056835] Lustre: 21499:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 623.067173] Lustre: 21499:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 47 previous similar messages [ 624.973626] Lustre: 19269:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 624.981481] Lustre: 19269:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 116 previous similar messages [ 624.992461] Lustre: 19269:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 625.002979] Lustre: 19269:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 116 previous similar messages [ 625.010626] Lustre: 19269:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 625.028815] Lustre: 19269:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 116 previous similar messages [ 625.037495] Lustre: 19269:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 625.050542] Lustre: 19269:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 116 previous similar messages [ 625.057066] Lustre: 19269:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 625.062650] Lustre: 19269:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 116 previous similar messages [ 625.068210] Lustre: 19269:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 625.072743] Lustre: 19269:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 113 previous similar messages [ 629.096268] Lustre: *** cfs_fail_loc=1600, val=3*** [ 631.682779] Lustre: 23410:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-OST0001: opcode 2: before 260 < left 274, rollback = 2 [ 631.708545] Lustre: 23410:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 102 previous similar messages [ 631.719886] Lustre: 23410:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 631.738801] Lustre: 23410:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 102 previous similar messages [ 631.748070] Lustre: 23410:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 2/274/0 [ 631.766813] Lustre: 23410:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 102 previous similar messages [ 631.782686] Lustre: 23410:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 0/0/0, punch: 0/0/0, quota 7/225/0 [ 631.802684] Lustre: 23410:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 102 previous similar messages [ 631.823642] Lustre: 23410:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 631.835201] Lustre: 23410:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 102 previous similar messages [ 631.853077] Lustre: 23410:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 631.868942] Lustre: 23410:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 102 previous similar messages [ 632.172604] Lustre: *** cfs_fail_loc=1600, val=3*** [ 634.990959] Lustre: *** cfs_fail_loc=1600, val=3*** [ 648.161869] 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 [ 648.169451] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 648.180961] Lustre: Skipped 3 previous similar messages [ 648.184230] Lustre: Skipped 2 previous similar messages [ 653.282418] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 653.296922] Lustre: Skipped 3 previous similar messages [ 653.508353] Lustre: server umount lustre-MDT0000 complete [ 657.079683] LustreError: 19254:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787548874 with bad export cookie 4496218354990109395 [ 657.090461] LustreError: MGC192.168.204.159@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 657.096686] LustreError: 19254:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 657.406668] Lustre: server umount lustre-MDT0001 complete [ 670.382632] Lustre: server umount lustre-OST0000 complete [ 674.272519] Lustre: 16420:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787548876/real 1787548876] req@ffff94878973bb80 x1874380622771200/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787548892 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 674.302218] 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 [ 675.427374] Lustre: server umount lustre-OST0001 complete [ 687.272192] Lustre: DEBUG MARKER: == sanity-lfsck test 1a: LFSCK can find out and repair crashed FID-in-dirent ========================================================== 01:21:41 (1787548901) [ 706.848905] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing load_modules_local [ 720.231115] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 720.672366] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 725.812577] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 725.998169] LustreError: 26234:0:(ldlm_lib.c:1190: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. [ 726.023033] LustreError: 26234:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 2 previous similar messages [ 731.108628] LustreError: 26235:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 735.439131] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 735.911503] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 740.366568] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 743.581751] Lustre: 27375:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 750.666396] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 758.266356] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 760.171523] LustreError: 27728:0:(ldlm_lib.c:1190: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. [ 765.416632] LustreError: 27729:0:(ldlm_lib.c:1190: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. [ 766.454508] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:40 to 0x280000400:65) [ 767.965131] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 768.246784] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 768.259337] Lustre: Skipped 1 previous similar message [ 773.630303] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:41 to 0x2c0000401:65) [ 775.778145] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 784.581459] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 789.425356] Lustre: 29244:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 791.726174] Lustre: 26229:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 791.753372] Lustre: 26229:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 69 previous similar messages [ 791.764050] Lustre: 26229:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 791.773061] Lustre: 26229:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 69 previous similar messages [ 791.785863] Lustre: 26229:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 791.791971] Lustre: 26229:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 69 previous similar messages [ 791.796717] Lustre: 26229:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 791.803113] Lustre: 26229:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 69 previous similar messages [ 791.808458] Lustre: 26229:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 791.814095] Lustre: 26229:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 69 previous similar messages [ 791.819470] Lustre: 26229:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 791.824470] Lustre: 26229:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 69 previous similar messages [ 799.041817] Lustre: *** cfs_fail_loc=1501, val=0*** [ 808.431160] Lustre: Failing over lustre-MDT0000 [ 808.901759] Lustre: server umount lustre-MDT0000 complete [ 809.447076] 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 [ 809.452079] LustreError: 26229:0:(ldlm_lib.c:1190: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. [ 809.469818] Lustre: Skipped 3 previous similar messages [ 809.502653] LustreError: 26229:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 5 previous similar messages [ 819.684669] LustreError: 27750:0:(ldlm_lib.c:1190: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. [ 819.712644] LustreError: 27750:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 7 previous similar messages [ 821.448759] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 821.706671] LustreError: MGC192.168.204.159@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 822.117364] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 822.185977] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 826.551115] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 827.371982] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 827.378358] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 827.412177] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 827.487478] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:105 to 0x280000400:129) [ 827.490311] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:105 to 0x2c0000401:129) [ 830.806051] Lustre: *** cfs_fail_loc=1505, val=0*** [ 840.353092] Lustre: DEBUG MARKER: == sanity-lfsck test 1b: LFSCK can find out and repair the missing FID-in-LMA ========================================================== 01:24:15 (1787549055) [ 841.646052] Lustre: 26230:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 841.656263] Lustre: 26230:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 322 previous similar messages [ 841.664053] Lustre: 26230:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 841.677683] Lustre: 26230:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 841.691124] Lustre: 26230:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 841.700059] Lustre: 26230:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 841.710387] Lustre: 26230:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 841.715047] Lustre: 26230:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 841.720250] Lustre: 26230:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 841.726431] Lustre: 26230:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 841.733477] Lustre: 26230:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 841.741272] Lustre: 26230:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 321 previous similar messages [ 846.395903] Lustre: *** cfs_fail_loc=1502, val=0*** [ 856.496340] Lustre: Failing over lustre-MDT0000 [ 856.815407] Lustre: server umount lustre-MDT0000 complete [ 858.084394] 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 [ 858.085164] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 858.110261] LustreError: 26234:0:(ldlm_lib.c:1190: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. [ 858.155439] LustreError: 26234:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 3 previous similar messages [ 868.293995] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 868.374586] LustreError: MGC192.168.204.159@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 868.585587] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 873.073597] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 873.956292] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 873.972669] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 873.980636] Lustre: Skipped 3 previous similar messages [ 874.014886] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 874.060772] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:169 to 0x2c0000401:193) [ 874.062733] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:169 to 0x280000400:193) [ 876.432083] Lustre: *** cfs_fail_loc=1505, val=0*** [ 884.658613] Lustre: DEBUG MARKER: == sanity-lfsck test 1c: LFSCK can find out and repair lost FID-in-dirent ========================================================== 01:24:59 (1787549099) [ 885.852148] Lustre: 27750:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 255 < left 278, rollback = 2 [ 885.865134] Lustre: 27750:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 322 previous similar messages [ 885.881516] Lustre: 27750:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/2, destroy: 0/0/0 [ 885.886672] Lustre: 27750:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 885.896190] Lustre: 27750:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 885.901582] Lustre: 27750:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 885.907129] Lustre: 27750:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 885.912178] Lustre: 27750:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 885.916829] Lustre: 27750:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 885.922221] Lustre: 27750:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 885.927511] Lustre: 27750:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 885.931665] Lustre: 27750:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 890.601643] Lustre: *** cfs_fail_loc=1504, val=0*** [ 890.603882] Lustre: *** cfs_fail_loc=1504, val=0*** [ 890.610019] Lustre: Skipped 1 previous similar message [ 898.922730] Lustre: Failing over lustre-MDT0000 [ 899.102178] Lustre: server umount lustre-MDT0000 complete [ 899.556059] 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 [ 899.558921] LustreError: 26966:0:(ldlm_lib.c:1190: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. [ 899.565653] Lustre: Skipped 5 previous similar messages [ 899.579167] LustreError: 26966:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 9 previous similar messages [ 899.595189] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 909.720564] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 909.819658] LustreError: MGC192.168.204.159@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 910.086121] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 910.091745] Lustre: Skipped 1 previous similar message [ 910.141205] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 914.331831] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 915.430860] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 915.433058] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 915.454506] Lustre: Skipped 3 previous similar messages [ 915.470804] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 915.508344] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:233 to 0x280000400:257) [ 915.509019] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:233 to 0x2c0000401:257) [ 917.483256] Lustre: *** cfs_fail_loc=1505, val=0*** [ 924.142464] Lustre: DEBUG MARKER: == sanity-lfsck test 2a: LFSCK can find out and repair crashed linkEA entry ========================================================== 01:25:39 (1787549139) [ 931.039642] Lustre: *** cfs_fail_loc=1603, val=0*** [ 937.393473] Lustre: Failing over lustre-MDT0000 [ 939.593455] Lustre: server umount lustre-MDT0000 complete [ 941.024640] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 941.029598] 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 [ 941.044125] Lustre: Skipped 3 previous similar messages [ 949.495966] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 949.659496] LustreError: MGC192.168.204.159@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 949.954882] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 954.626221] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 955.370195] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 955.371930] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 955.375829] Lustre: Skipped 3 previous similar messages [ 955.410586] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 955.435918] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:297 to 0x2c0000401:321) [ 955.436973] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:297 to 0x280000400:321) [ 963.524349] Lustre: DEBUG MARKER: == sanity-lfsck test 2b: LFSCK can find out and remove invalid linkEA entry ========================================================== 01:26:18 (1787549178) [ 964.673272] Lustre: 27750:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 255 < left 278, rollback = 2 [ 964.680798] Lustre: 27750:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 644 previous similar messages [ 964.685583] Lustre: 27750:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/2, destroy: 0/0/0 [ 964.690611] Lustre: 27750:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 964.695381] Lustre: 27750:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 964.700509] Lustre: 27750:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 964.705990] Lustre: 27750:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 964.710719] Lustre: 27750:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 964.715788] Lustre: 27750:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 964.719844] Lustre: 27750:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 964.725226] Lustre: 27750:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 964.729761] Lustre: 27750:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 971.378040] Lustre: *** cfs_fail_loc=1604, val=0*** [ 979.874433] Lustre: Failing over lustre-MDT0000 [ 980.381958] Lustre: server umount lustre-MDT0000 complete [ 980.966177] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 980.973921] 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 [ 980.980618] LustreError: 26229:0:(ldlm_lib.c:1190: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. [ 980.980630] LustreError: 26229:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 18 previous similar messages [ 981.026695] Lustre: Skipped 2 previous similar messages [ 992.649216] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 992.883933] LustreError: MGC192.168.204.159@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 993.117109] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 998.374519] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 998.383827] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 998.388216] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 998.402937] Lustre: Skipped 3 previous similar messages [ 998.430275] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 998.490214] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:361 to 0x2c0000401:385) [ 998.490885] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:361 to 0x280000400:385) [ 1010.420395] Lustre: DEBUG MARKER: == sanity-lfsck test 2c: LFSCK can find out and remove repeated linkEA entry ========================================================== 01:27:05 (1787549225) [ 1017.101804] Lustre: *** cfs_fail_loc=1605, val=0*** [ 1025.219635] Lustre: Failing over lustre-MDT0000 [ 1025.489787] Lustre: server umount lustre-MDT0000 complete [ 1029.095001] 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 [ 1029.101431] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1029.114159] Lustre: Skipped 3 previous similar messages [ 1035.566895] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1035.649291] LustreError: MGC192.168.204.159@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1035.913868] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1040.402438] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1040.880662] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1040.891522] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 1040.904662] Lustre: Skipped 3 previous similar messages [ 1040.937540] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1041.000225] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:425 to 0x280000400:449) [ 1041.000303] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:425 to 0x2c0000401:449) [ 1050.588891] Lustre: DEBUG MARKER: == sanity-lfsck test 2d: LFSCK can recover the missing linkEA entry ========================================================== 01:27:45 (1787549265) [ 1056.708741] Lustre: *** cfs_fail_loc=161d, val=0*** [ 1065.044280] Lustre: Failing over lustre-MDT0000 [ 1065.803817] Lustre: server umount lustre-MDT0000 complete [ 1066.465437] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1080.474548] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1080.604891] LustreError: MGC192.168.204.159@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1080.903139] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1080.909397] Lustre: Skipped 3 previous similar messages [ 1080.937822] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1085.576911] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1085.924155] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1085.928952] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1085.939755] Lustre: Skipped 3 previous similar messages [ 1085.957522] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1085.985178] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:489 to 0x280000400:513) [ 1085.986435] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:489 to 0x2c0000401:513) [ 1094.226191] Lustre: DEBUG MARKER: == sanity-lfsck test 2e: namespace LFSCK can verify remote object linkEA ========================================================== 01:28:29 (1787549309) [ 1095.521482] Lustre: 26229:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 256 < left 278, rollback = 2 [ 1095.527805] Lustre: 26229:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 967 previous similar messages [ 1095.532056] Lustre: 26229:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 1095.536120] Lustre: 26229:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 967 previous similar messages [ 1095.541643] Lustre: 26229:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 1095.547279] Lustre: 26229:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 967 previous similar messages [ 1095.552356] Lustre: 26229:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 1095.557677] Lustre: 26229:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 967 previous similar messages [ 1095.562749] Lustre: 26229:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 1095.566876] Lustre: 26229:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 967 previous similar messages [ 1095.572429] Lustre: 26229:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 1095.578657] Lustre: 26229:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 967 previous similar messages [ 1096.938284] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1107.713881] Lustre: DEBUG MARKER: == sanity-lfsck test 3: LFSCK can verify multiple-linked objects ========================================================== 01:28:43 (1787549323) [ 1113.888120] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1115.026951] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1126.605789] Lustre: DEBUG MARKER: == sanity-lfsck test 4: FID-in-dirent can be rebuilt after MDT file-level backup/restore ========================================================== 01:29:02 (1787549342) [ 1162.668338] Lustre: Failing over lustre-MDT0000 [ 1162.723502] 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 [ 1162.728964] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1162.750527] Lustre: Skipped 8 previous similar messages [ 1162.793944] Lustre: Skipped 3 previous similar messages [ 1163.045347] Lustre: server umount lustre-MDT0000 complete [ 1167.845644] LustreError: 26966:0:(ldlm_lib.c:1190: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. [ 1167.861796] LustreError: 26966:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 34 previous similar messages [ 1170.237763] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1181.536538] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1183.137080] Lustre: 16421:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787549385/real 1787549385] req@ffff9488bd701180 x1874380623403776/t0(0) o400->MGC192.168.204.159@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1787549401 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1183.163832] LustreError: MGC192.168.204.159@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1191.383341] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1191.415980] Lustre: lustre-MDT0000: reset Object Index mappings [ 1193.452440] LustreError: 16419:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9488a73e8e00 x1874380623411712/t0(0) o250->MGC192.168.204.159@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 [ 1193.765854] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1198.373417] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1199.080333] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1199.088286] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 1199.101776] Lustre: Skipped 3 previous similar messages [ 1199.142316] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1199.218462] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:592 to 0x2c0000401:609) [ 1199.219294] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:592 to 0x280000400:609) [ 1202.281148] LustreError: 42890:0:(lfsck_engine.c:1018:lfsck_master_engine()) lustre-MDT0000-osd: master engine fail to verify the .lustre/lost+found/, go ahead: rc = -115 [ 1202.305370] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1206.444232] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1206.455711] Lustre: Skipped 3 previous similar messages [ 1212.156153] Lustre: Failing over lustre-MDT0000 [ 1212.592574] Lustre: server umount lustre-MDT0000 complete [ 1222.749349] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1228.012364] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1228.329784] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:592 to 0x280000400:641) [ 1228.332254] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:592 to 0x2c0000401:641) [ 1231.422191] Lustre: *** cfs_fail_loc=1505, val=0*** [ 1238.072745] Lustre: DEBUG MARKER: == sanity-lfsck test 5: LFSCK can handle IGIF object upgrading ========================================================== 01:30:53 (1787549453) [ 1241.137882] Lustre: *** cfs_fail_loc=1504, val=0*** [ 1252.994342] Lustre: Failing over lustre-MDT0000 [ 1253.458988] Lustre: server umount lustre-MDT0000 complete [ 1253.867035] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1260.097043] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1269.216647] Lustre: 16421:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787549471/real 1787549471] req@ffff9488ae2dbb80 x1874380623493504/t0(0) o400->MGC192.168.204.159@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1787549487 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1270.277616] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1281.075865] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1281.100958] Lustre: lustre-MDT0000: reset Object Index mappings [ 1295.183833] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1295.195298] Lustre: Skipped 1 previous similar message [ 1300.063367] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1300.459983] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1300.487665] Lustre: Skipped 1 previous similar message [ 1300.488452] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1300.507615] Lustre: Skipped 7 previous similar messages [ 1300.525628] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1300.534587] Lustre: Skipped 1 previous similar message [ 1300.567801] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:681 to 0x280000400:705) [ 1300.569452] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:681 to 0x2c0000401:705) [ 1304.384240] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1318.692280] Lustre: Failing over lustre-MDT0000 [ 1318.978532] Lustre: server umount lustre-MDT0000 complete [ 1320.933768] 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 [ 1320.957178] Lustre: Skipped 11 previous similar messages [ 1320.965513] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1330.293712] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1330.493415] LustreError: MGC192.168.204.159@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1330.506104] LustreError: Skipped 2 previous similar messages [ 1335.638817] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1336.353388] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:681 to 0x2c0000401:737) [ 1336.353426] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:681 to 0x280000400:737) [ 1339.292144] Lustre: *** cfs_fail_loc=1505, val=0*** [ 1339.297279] Lustre: Skipped 84 previous similar messages [ 1347.280547] Lustre: DEBUG MARKER: == sanity-lfsck test 6a: LFSCK resumes from last checkpoint (1) ========================================================== 01:32:42 (1787549562) [ 1351.524608] Lustre: 29323:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 1351.532341] Lustre: 29323:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 1119 previous similar messages [ 1351.538843] Lustre: 29323:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 1351.546873] Lustre: 29323:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1119 previous similar messages [ 1351.561983] Lustre: 29323:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 1351.576527] Lustre: 29323:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1119 previous similar messages [ 1351.585714] Lustre: 29323:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 1351.595622] Lustre: 29323:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1119 previous similar messages [ 1351.601368] Lustre: 29323:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 1351.608551] Lustre: 29323:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1119 previous similar messages [ 1351.615467] Lustre: 29323:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 1351.622734] Lustre: 29323:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1119 previous similar messages [ 1356.129710] Lustre: *** cfs_fail_loc=1600, val=1*** [ 1356.143034] Lustre: Skipped 8 previous similar messages [ 1378.681149] Lustre: DEBUG MARKER: == sanity-lfsck test 6b: LFSCK resumes from last checkpoint (2) ========================================================== 01:33:13 (1787549593) [ 1389.025939] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1389.028064] Lustre: Skipped 11 previous similar messages [ 1410.166443] Lustre: DEBUG MARKER: == sanity-lfsck test 7a: non-stopped LFSCK should auto restarts after MDS remount (1) ========================================================== 01:33:45 (1787549625) [ 1425.658219] Lustre: Failing over lustre-MDT0000 [ 1425.927154] Lustre: server umount lustre-MDT0000 complete [ 1428.458491] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1428.458967] LustreError: 26230:0:(ldlm_lib.c:1190: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. [ 1428.479329] LustreError: 26230:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 77 previous similar messages [ 1434.971421] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1435.369916] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1435.379919] Lustre: Skipped 4 previous similar messages [ 1435.411161] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1435.422046] Lustre: Skipped 1 previous similar message [ 1439.540284] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1440.745765] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1440.754639] Lustre: Skipped 1 previous similar message [ 1440.756462] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1440.775221] Lustre: Skipped 7 previous similar messages [ 1440.794112] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1440.804615] Lustre: Skipped 1 previous similar message [ 1440.860918] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:854 to 0x280000400:897) [ 1440.861714] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:853 to 0x2c0000401:897) [ 1449.480800] Lustre: DEBUG MARKER: == sanity-lfsck test 7b: non-stopped LFSCK should auto restarts after MDS remount (2) ========================================================== 01:34:24 (1787549664) [ 1463.614608] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing load_modules_local [ 1484.857183] Lustre: 52906:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 1509.014617] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1512.414980] Lustre: 54043:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 1519.136651] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1519.144665] Lustre: Skipped 81 previous similar messages [ 1521.970976] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1522.976125] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1524.000291] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1526.051204] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1526.055394] Lustre: Skipped 1 previous similar message [ 1526.637652] Lustre: Failing over lustre-MDT0000 [ 1526.900625] Lustre: server umount lustre-MDT0000 complete [ 1535.684978] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1540.325409] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1541.199541] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:946 to 0x280000400:961) [ 1541.203054] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:947 to 0x2c0000401:993) [ 1550.108092] Lustre: DEBUG MARKER: == sanity-lfsck test 8: LFSCK state machine ============== 01:36:05 (1787549765) [ 1556.449962] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1556.456862] Lustre: Skipped 3 previous similar messages [ 1561.577167] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1561.589873] Lustre: Skipped 3 previous similar messages [ 1566.176519] Lustre: lustre-MDT0000 is waiting for obd_unlinked_exports more than 8 seconds. The obd refcount = 3. Is it stuck? [ 1566.424680] Lustre: server umount lustre-MDT0000 complete [ 1569.717341] LustreError: 29264:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787549787 with bad export cookie 4496218354990323252 [ 1569.724529] LustreError: 29264:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 1570.079988] Lustre: server umount lustre-MDT0001 complete [ 1583.779399] Lustre: server umount lustre-OST0000 complete [ 1596.377228] Lustre: server umount lustre-OST0001 complete [ 1602.760884] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_hostid [ 1611.081163] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing load_modules_local [ 1653.865130] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing load_modules_local [ 1666.145457] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1666.448693] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 1666.475576] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 1666.607740] Lustre: lustre-MDT0000: new disk, initializing [ 1666.722825] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 1671.597212] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1682.574335] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1682.766687] Lustre: 59101: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 [ 1682.829501] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 1682.838464] Lustre: Skipped 1 previous similar message [ 1682.922482] Lustre: lustre-MDT0001: new disk, initializing [ 1683.081926] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 1683.097117] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 1687.740406] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1692.284866] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 1699.211218] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 1699.484919] Lustre: lustre-OST0000: new disk, initializing [ 1699.494866] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 1699.508504] Lustre: 60733:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 1701.387205] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 1701.398276] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 1701.490138] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 1706.453305] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1718.160210] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 1718.308359] Lustre: lustre-OST0001: new disk, initializing [ 1718.311858] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 1718.318685] Lustre: 61603:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 1720.071165] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 1720.081351] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 1720.112081] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 1725.010779] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1735.547759] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1741.088442] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 1751.916786] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1752.973728] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1752.975630] Lustre: Skipped 19 previous similar messages [ 1757.808563] Lustre: *** cfs_fail_loc=1601, val=2*** [ 1757.815775] Lustre: Skipped 17 previous similar messages [ 1774.949037] Lustre: Failing over lustre-MDT0000 [ 1775.080272] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1775.094501] LustreError: Skipped 2 previous similar messages [ 1775.099804] 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 [ 1775.112882] Lustre: Skipped 12 previous similar messages [ 1775.333606] Lustre: server umount lustre-MDT0000 complete [ 1784.662083] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1784.776644] LustreError: MGC192.168.204.159@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1784.783740] LustreError: Skipped 3 previous similar messages [ 1785.040878] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1785.050333] Lustre: Skipped 1 previous similar message [ 1789.280363] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1790.433269] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1790.438464] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1790.442071] Lustre: Skipped 1 previous similar message [ 1790.458168] Lustre: Skipped 7 previous similar messages [ 1790.475712] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1790.490957] Lustre: Skipped 1 previous similar message [ 1790.525370] Lustre: *** cfs_fail_loc=160b, val=2*** [ 1790.533095] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:65) [ 1790.533492] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:65) [ 1797.873161] Lustre: Failing over lustre-MDT0000 [ 1798.391063] Lustre: server umount lustre-MDT0000 complete [ 1810.846536] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1816.633483] Lustre: *** cfs_fail_loc=160b, val=2*** [ 1816.647587] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:97) [ 1816.647619] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:97) [ 1816.797352] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1823.990504] Lustre: Failing over lustre-MDT0000 [ 1824.146796] Lustre: server umount lustre-MDT0000 complete [ 1836.648587] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1842.242670] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:129) [ 1842.245218] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:129) [ 1843.347786] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1849.284426] Lustre: *** cfs_fail_loc=1602, val=2*** [ 1862.146341] Lustre: DEBUG MARKER: == sanity-lfsck test 9a: LFSCK speed control (1) ========= 01:41:17 (1787550077) [ 1876.542178] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing load_modules_local [ 1896.194327] Lustre: 68562:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 1924.140876] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1927.653760] Lustre: 69699:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 1935.996334] Lustre: 59107:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 1936.001443] Lustre: 59107:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 2594 previous similar messages [ 1936.006297] Lustre: 59107:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 1936.012032] Lustre: 59107:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 2594 previous similar messages [ 1936.015681] Lustre: 59107:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 1936.020936] Lustre: 59107:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 2594 previous similar messages [ 1936.025947] Lustre: 59107:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 1936.031378] Lustre: 59107:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 2594 previous similar messages [ 1936.037343] Lustre: 59107:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 1936.040801] Lustre: 59107:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 2594 previous similar messages [ 1936.046628] Lustre: 59107:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 1936.051328] Lustre: 59107:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 2594 previous similar messages [ 2042.366230] Lustre: DEBUG MARKER: == sanity-lfsck test 9b: LFSCK speed control (2) ========= 01:44:17 (1787550257) [ 2098.116661] Lustre: *** cfs_fail_loc=1604, val=0*** [ 2098.126247] Lustre: Skipped 4 previous similar messages [ 2123.227592] Lustre: *** cfs_fail_loc=160c, val=0*** [ 2123.230225] Lustre: Skipped 7 previous similar messages [ 2162.415811] Lustre: DEBUG MARKER: == sanity-lfsck test 10: System is available during LFSCK scanning ========================================================== 01:46:17 (1787550377) [ 2209.096928] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2210.127475] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2210.137152] Lustre: Skipped 43 previous similar messages [ 2212.131983] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2212.139038] Lustre: Skipped 127 previous similar messages [ 2216.132935] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2216.134890] Lustre: Skipped 185 previous similar messages [ 2224.163547] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2224.165751] Lustre: Skipped 476 previous similar messages [ 2240.211243] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2240.215482] Lustre: Skipped 811 previous similar messages [ 2272.848086] Lustre: *** cfs_fail_loc=1604, val=0*** [ 2272.850827] Lustre: Skipped 2599 previous similar messages [ 2519.127603] Lustre: DEBUG MARKER: == sanity-lfsck test 11a: LFSCK can rebuild lost last_id ========================================================== 01:52:14 (1787550734) [ 2593.897243] Lustre: 59108:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 320, rollback = 2 [ 2593.908300] Lustre: 59108:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 36831 previous similar messages [ 2593.914729] Lustre: 59108:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 1/4/0 [ 2593.921982] Lustre: 59108:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 36831 previous similar messages [ 2593.931665] Lustre: 59108:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 5/5/0, xattr_set: 7/320/0 [ 2593.945947] Lustre: 59108:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 36831 previous similar messages [ 2593.960170] Lustre: 59108:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 6/46/0, punch: 0/0/0, quota 1/3/0 [ 2593.971169] Lustre: 59108:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 36831 previous similar messages [ 2593.983737] Lustre: 59108:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 2/5/0 [ 2593.993996] Lustre: 59108:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 36831 previous similar messages [ 2594.003354] Lustre: 59108:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 1/1/0, ref_del: 2/2/1 [ 2594.012510] Lustre: 59108:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 36831 previous similar messages [ 2676.717712] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 2676.721430] 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 [ 2676.730184] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2676.741538] LustreError: Skipped 2 previous similar messages [ 2676.814729] Lustre: Skipped 14 previous similar messages [ 2681.825033] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2681.836867] Lustre: Skipped 6 previous similar messages [ 2683.216823] Lustre: server umount lustre-MDT0000 complete [ 2686.946704] LustreError: 59109:0:(ldlm_lib.c:1190: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. [ 2686.992723] LustreError: 59109:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 49 previous similar messages [ 2688.791110] LustreError: 59094:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787550906 with bad export cookie 4496218354990342355 [ 2688.792170] LustreError: MGC192.168.204.159@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2688.811230] LustreError: 59094:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 2688.843347] LustreError: Skipped 2 previous similar messages [ 2689.265159] Lustre: server umount lustre-MDT0001 complete [ 2704.720433] Lustre: server umount lustre-OST0000 complete [ 2707.937229] Lustre: 16423:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787550909/real 1787550909] req@ffff94878aeac380 x1874380627649152/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787550925 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2708.449392] Lustre: 16420:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787550910/real 1787550910] req@ffff94878aeac700 x1874380627649408/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787550926 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2709.600088] Lustre: server umount lustre-OST0001 complete [ 2717.106632] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: (null) [ 2727.154199] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 2742.816625] LustreError: Failed to get MGS log lustre-sptlrpc and no local copy. [ 2747.936376] LustreError: 74737:0:(mgc_request.c:233:do_config_log_add()) MGC192.168.204.159@tcp: failed processing log, type 4: rc = -110 [ 2773.601536] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 2773.610341] Lustre: Skipped 8 previous similar messages [ 2780.817155] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2784.935628] Lustre: 75322: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. [ 2784.955197] Lustre: *** cfs_fail_loc=160e, val=3*** [ 2788.007315] Lustre: 75322:0:(ofd_dev.c:573:ofd_lfsck_out_notify()) lustre-OST0000: Rebuilt crashed LAST_ID files successfully. [ 2796.832561] Lustre: DEBUG MARKER: == sanity-lfsck test 11b: LFSCK can rebuild crashed last_id ========================================================== 01:56:52 (1787551012) [ 2811.743956] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing load_modules_local [ 2824.035997] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2824.627366] LustreError: 74763:0:(ldlm_lib.c:1190: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. [ 2824.928711] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3272 to 0x280000401:3297) [ 2831.159548] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2841.407441] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2841.991094] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 2841.999871] Lustre: Skipped 1 previous similar message [ 2848.924993] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2853.204411] Lustre: 77940:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 2875.087278] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2880.507966] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3207 to 0x2c0000401:3233) [ 2884.203816] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2894.190329] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 2898.153653] Lustre: 79439:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 2903.937112] Lustre: *** cfs_fail_loc=160d, val=0*** [ 2912.321180] Lustre: Failing over lustre-OST0000 [ 2912.780765] Lustre: server umount lustre-OST0000 complete [ 2913.760820] LustreError: lustre-OST0000-osc-MDT0001: operation ost_statfs to node 0@lo failed: rc = -107 [ 2928.100620] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2928.491809] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 2928.509935] Lustre: Skipped 2 previous similar messages [ 2930.092514] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 2930.116188] Lustre: Skipped 2 previous similar messages [ 2930.164491] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 2930.169281] Lustre: lustre-OST0000-osc-MDT0001: Connection restored to 0@lo (at 0@lo) [ 2930.169986] Lustre: *** cfs_fail_loc=215, val=0*** [ 2930.181568] Lustre: Skipped 2 previous similar messages [ 2930.221832] Lustre: Skipped 11 previous similar messages [ 2935.264827] Lustre: *** cfs_fail_loc=215, val=0*** [ 2935.277586] Lustre: Skipped 3 previous similar messages [ 2938.076245] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2940.384619] Lustre: *** cfs_fail_loc=215, val=0*** [ 2940.393874] Lustre: Skipped 1 previous similar message [ 2942.145234] Lustre: 80841: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. [ 2942.220783] Lustre: 80841:0:(ofd_dev.c:573:ofd_lfsck_out_notify()) lustre-OST0000: Rebuilt crashed LAST_ID files successfully. [ 2945.031813] Lustre: Failing over lustre-OST0000 [ 2945.361800] Lustre: server umount lustre-OST0000 complete [ 2954.220055] LustreError: 77908:0:(ldlm_lib.c:1190: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. [ 2954.233578] LustreError: 77908:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 35 previous similar messages [ 2954.930266] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2956.490541] Lustre: *** cfs_fail_loc=215, val=0*** [ 2956.496931] Lustre: Skipped 3 previous similar messages [ 2961.809977] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2961.890489] Lustre: *** cfs_fail_loc=215, val=0*** [ 2970.085392] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2975.717064] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2975.723156] Lustre: Skipped 6 previous similar messages [ 2982.368245] Lustre: lustre-MDT0000 is waiting for obd_unlinked_exports more than 8 seconds. The obd refcount = 3. Is it stuck? [ 2982.708257] Lustre: server umount lustre-MDT0000 complete [ 2987.215883] LustreError: 74743:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787551205 with bad export cookie 4496218354991920820 [ 2987.250620] LustreError: 74743:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 3 previous similar messages [ 2987.733993] Lustre: server umount lustre-MDT0001 complete [ 3002.381361] Lustre: server umount lustre-OST0000 complete [ 3006.452564] Lustre: 16423:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787551208/real 1787551208] req@ffff948789860380 x1874380627759488/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787551224 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3007.103213] Lustre: server umount lustre-OST0001 complete [ 3017.826238] Lustre: DEBUG MARKER: == sanity-lfsck test 12a: single command to trigger LFSCK on all devices ========================================================== 02:00:33 (1787551233) [ 3034.171185] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing load_modules_local [ 3047.761736] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3048.825302] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3048.839708] Lustre: Skipped 3 previous similar messages [ 3055.819885] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3068.792132] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3075.402462] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3078.865802] Lustre: 85247:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3087.001574] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3093.610663] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3362 to 0x280000401:3393) [ 3094.588845] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3105.539743] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3110.898488] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3207 to 0x2c0000401:3265) [ 3114.482083] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3123.445401] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3127.220513] Lustre: 87114:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 3163.308297] Lustre: DEBUG MARKER: == sanity-lfsck test 12b: auto detect Lustre device ====== 02:02:58 (1787551378) [ 3182.690453] Lustre: DEBUG MARKER: == sanity-lfsck test 13: LFSCK can repair crashed lmm_oi ========================================================== 02:03:17 (1787551397) [ 3184.799174] Lustre: *** cfs_fail_loc=160f, val=0*** [ 3197.042274] Lustre: DEBUG MARKER: == sanity-lfsck test 14a: LFSCK can repair MDT-object with dangling LOV EA reference (1) ========================================================== 02:03:32 (1787551412) [ 3197.540744] Lustre: 84097:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 253 < left 278, rollback = 2 [ 3197.553852] Lustre: 84097:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 1010 previous similar messages [ 3197.563804] Lustre: 84097:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 3197.571155] Lustre: 84097:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1010 previous similar messages [ 3197.586548] Lustre: 84097:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3197.593461] Lustre: 84097:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1010 previous similar messages [ 3197.600253] Lustre: 84097:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/1 [ 3197.606897] Lustre: 84097:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1010 previous similar messages [ 3197.619058] Lustre: 84097:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 3197.628369] Lustre: 84097:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1010 previous similar messages [ 3197.634138] Lustre: 84097:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3197.637910] Lustre: 84097:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1010 previous similar messages [ 3201.426575] Lustre: *** cfs_fail_loc=1610, val=0*** [ 3201.434279] Lustre: Skipped 7 previous similar messages [ 3252.194464] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3252.199561] Lustre: Skipped 7 previous similar messages [ 3257.823613] Lustre: server umount lustre-MDT0000 complete [ 3262.073480] LustreError: 84082:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787551479 with bad export cookie 4496218354991929276 [ 3262.104241] LustreError: 84082:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 3262.447544] LustreError: 87748:0:(ldlm_lib.c:1190: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. [ 3262.478938] LustreError: 87748:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 16 previous similar messages [ 3262.613814] Lustre: server umount lustre-MDT0001 complete [ 3269.071014] Lustre: server umount lustre-OST0000 complete [ 3273.617669] Lustre: server umount lustre-OST0001 complete [ 3296.035598] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing load_modules_local [ 3309.788309] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3310.339364] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3310.346958] Lustre: Skipped 3 previous similar messages [ 3315.701667] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3325.233281] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3330.877511] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3334.212927] Lustre: 92985:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3341.441968] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3348.457622] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3350.959800] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:116 to 0x280000400:161) [ 3356.090050] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3554 to 0x280000401:3585) [ 3359.209497] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3364.883571] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:116 to 0x2c0000400:161) [ 3364.903937] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3317 to 0x2c0000401:3361) [ 3366.597316] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3376.895713] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3381.552441] Lustre: 94857:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 3391.041768] Lustre: DEBUG MARKER: == sanity-lfsck test 14b: LFSCK can repair MDT-object with dangling LOV EA reference (2) ========================================================== 02:06:45 (1787551605) [ 3398.482648] Lustre: *** cfs_fail_loc=1610, val=0*** [ 3398.488821] Lustre: Skipped 63 previous similar messages [ 3436.519595] 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 [ 3436.523146] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3436.571421] Lustre: Skipped 18 previous similar messages [ 3436.600547] Lustre: Skipped 7 previous similar messages [ 3440.656301] Lustre: server umount lustre-MDT0000 complete [ 3446.380247] LustreError: 91824:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787551664 with bad export cookie 4496218354991957703 [ 3446.394177] LustreError: MGC192.168.204.159@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3446.409201] LustreError: 91824:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 3446.449975] LustreError: Skipped 2 previous similar messages [ 3447.081560] Lustre: server umount lustre-MDT0001 complete [ 3453.282278] Lustre: server umount lustre-OST0000 complete [ 3459.933565] Lustre: server umount lustre-OST0001 complete [ 3486.243263] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing load_modules_local [ 3501.304321] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3508.689473] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3520.163207] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3525.948366] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3529.017798] Lustre: 98895:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3536.282178] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3542.929170] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3545.905734] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:116 to 0x280000400:193) [ 3546.956951] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3682 to 0x280000401:3713) [ 3553.846859] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3559.397133] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3317 to 0x2c0000401:3393) [ 3559.556527] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:116 to 0x2c0000400:193) [ 3560.850606] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3568.877536] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3581.445810] Lustre: DEBUG MARKER: == sanity-lfsck test 15a: LFSCK can repair unmatched MDT-object/OST-object pairs (1) ========================================================== 02:09:56 (1787551796) [ 3585.405540] Lustre: *** cfs_fail_loc=1611, val=0*** [ 3585.407788] Lustre: Skipped 63 previous similar messages [ 3585.698612] Lustre: *** cfs_fail_loc=1611, val=0*** [ 3598.967308] Lustre: DEBUG MARKER: == sanity-lfsck test 15b: LFSCK can repair unmatched MDT-object/OST-object pairs (2) ========================================================== 02:10:13 (1787551813) [ 3601.926553] Lustre: *** cfs_fail_loc=1612, val=0*** [ 3602.044739] Lustre: *** cfs_fail_loc=1612, val=0*** [ 3602.046823] Lustre: Skipped 2 previous similar messages [ 3616.175805] Lustre: DEBUG MARKER: == sanity-lfsck test 15c: LFSCK can repair unmatched MDT-object/OST-object pairs (3) ========================================================== 02:10:30 (1787551830) [ 3618.250956] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_15c MDS newer than 2.7.55, LU-6475 [ 3620.271447] Lustre: DEBUG MARKER: == sanity-lfsck test 15d: LFSCK don't crash upon dir migration failure ========================================================== 02:10:35 (1787551835) [ 3626.369761] Lustre: *** cfs_fail_loc=1709, val=0*** [ 3626.372532] LustreError: 97763:0:(mdt_reint.c:2644:mdt_reint_migrate()) lustre-MDT0000: migrate [0x240002340:0x6c:0x0]/f36 failed: rc = -5 [ 3694.562199] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3694.577752] LustreError: Skipped 3 previous similar messages [ 3694.588497] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3700.882407] Lustre: server umount lustre-MDT0000 complete [ 3712.417870] LustreError: 102272:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787551930 with bad export cookie 4496218354991972452 [ 3712.442722] LustreError: 102272:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 3713.046703] Lustre: server umount lustre-MDT0001 complete [ 3728.160134] Lustre: 16421:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787551930/real 1787551930] req@ffff948786070a80 x1874380628777600/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787551946 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3734.308749] Lustre: 16422:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787551936/real 1787551936] req@ffff948786072a00 x1874380628777856/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787551952 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3735.715511] Lustre: server umount lustre-OST0000 complete [ 3738.594970] Lustre: 16420:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787551940/real 1787551940] req@ffff948783a8c700 x1874380628778240/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787551956 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3743.727231] Lustre: 16423:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787551945/real 1787551945] req@ffff94878a4bd880 x1874380628778496/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787551961 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3746.606730] Lustre: server umount lustre-OST0001 complete [ 3771.127848] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing unload_modules_local [ 3774.865288] Key type lgssc unregistered [ 3775.513573] LNet: 104614:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 3775.528560] LNetError: 104614:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 3775.548296] LNet: Removed LNI 192.168.204.159@tcp [ 3777.193184] Key type .llcrypt unregistered [ 3777.195502] Key type ._llcrypt unregistered [ 3809.362215] Key type ._llcrypt registered [ 3809.374040] Key type .llcrypt registered [ 3809.524916] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_hostid [ 3824.854592] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing load_modules_local [ 3826.084054] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 3826.120464] alg: No test for adler32 (adler32-zlib) [ 3827.357869] Lustre: Lustre: Build Version: 2.17.57_83_g6b3cfd8 [ 3827.625691] LNet: Added LNI 192.168.204.159@tcp [8/256/0/180] [ 3829.304545] Key type lgssc registered [ 3830.989163] Lustre: Echo OBD driver; http://www.lustre.org/ [ 3889.216421] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing load_modules_local [ 3905.271509] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 3905.301531] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3906.676522] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 3906.725667] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 3906.851864] Lustre: lustre-MDT0000: new disk, initializing [ 3906.942416] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3906.969845] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 3912.930412] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3928.499996] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3928.613560] Lustre: 109076: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 [ 3928.648762] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 3928.653595] Lustre: Skipped 1 previous similar message [ 3928.720400] Lustre: lustre-MDT0001: new disk, initializing [ 3928.836556] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 3928.901361] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 3928.916792] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 3934.165968] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3939.483156] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 3951.245663] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3951.720396] Lustre: lustre-OST0000: new disk, initializing [ 3951.724599] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 3951.736240] Lustre: 111014:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 3951.873757] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 3957.831074] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 3957.838471] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 3957.928246] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 3959.845246] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3974.870569] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3975.099098] Lustre: lustre-OST0001: new disk, initializing [ 3975.101897] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 3975.107214] Lustre: 112039:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 3975.209404] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 3981.331995] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 3981.354764] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 3981.433855] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 3984.396621] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4000.216374] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4010.281612] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 4017.674804] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 02:17:12 (1787552232) === [ 4026.699686] Lustre: DEBUG MARKER: == sanity-lfsck test 16: LFSCK can repair inconsistent MDT-object/OST-object owner ========================================================== 02:17:21 (1787552241) [ 4026.942713] Lustre: 112047:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 251 < left 278, rollback = 2 [ 4026.953144] Lustre: 112047:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4026.965404] Lustre: 112047:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4026.976698] Lustre: 112047:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 4026.988732] Lustre: 112047:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 4027.015707] Lustre: 112047:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4027.587225] Lustre: 109083:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 252 < left 278, rollback = 2 [ 4027.594752] Lustre: 109083:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 9 previous similar messages [ 4027.600959] Lustre: 109083:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4027.608270] Lustre: 109083:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 4027.613410] Lustre: 109083:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4027.620923] Lustre: 109083:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 4027.632840] Lustre: 109083:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/1, punch: 0/0/0, quota 7/369/2 [ 4027.644599] Lustre: 109083:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 4027.653881] Lustre: 109083:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/1, delete: 0/0/0 [ 4027.668023] Lustre: 109083:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 4027.676495] Lustre: 109083:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 4027.687622] Lustre: 109083:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 4028.591920] Lustre: 112047:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 4028.599731] Lustre: 112047:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 152 previous similar messages [ 4028.623340] Lustre: 112047:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 4028.633748] Lustre: 112047:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 152 previous similar messages [ 4028.644340] Lustre: 112047:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4028.651995] Lustre: 112047:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 152 previous similar messages [ 4028.663519] Lustre: 112047:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 7/369/0 [ 4028.671234] Lustre: 112047:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 152 previous similar messages [ 4028.685177] Lustre: 112047:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 4028.693633] Lustre: 112047:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 152 previous similar messages [ 4028.704692] Lustre: 112047:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 4028.729637] Lustre: 112047:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 152 previous similar messages [ 4030.176290] Lustre: *** cfs_fail_loc=1613, val=0*** [ 4042.792655] Lustre: DEBUG MARKER: == sanity-lfsck test 17: LFSCK can repair multiple references ========================================================== 02:17:37 (1787552257) [ 4044.086199] Lustre: 109082:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 256 < left 278, rollback = 2 [ 4044.106847] Lustre: 109082:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 146 previous similar messages [ 4044.127850] Lustre: 109082:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/2, destroy: 0/0/0 [ 4044.140616] Lustre: 109082:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 146 previous similar messages [ 4044.152611] Lustre: 109082:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4044.168125] Lustre: 109082:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 146 previous similar messages [ 4044.177995] Lustre: 109082:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 4044.183325] Lustre: 109082:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 146 previous similar messages [ 4044.192688] Lustre: 109082:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 4044.200884] Lustre: 109082:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 146 previous similar messages [ 4044.208390] Lustre: 109082:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4044.215877] Lustre: 109082:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 146 previous similar messages [ 4045.384805] Lustre: *** cfs_fail_loc=1614, val=0*** [ 4046.008307] Lustre: *** cfs_fail_loc=1614, val=103*** [ 4046.012466] Lustre: Skipped 1 previous similar message [ 4050.422748] Lustre: 111005:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 259 < left 275, rollback = 2 [ 4050.430739] Lustre: 111005:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 11 previous similar messages [ 4050.444161] Lustre: 111005:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 4050.455899] Lustre: 111005:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 4050.468132] Lustre: 111005:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/1, xattr_set: 3/275/0 [ 4050.485751] Lustre: 111005:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 4050.506755] Lustre: 111005:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/9/0, punch: 1/4/0, quota 7/225/0 [ 4050.519926] Lustre: 111005:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 4050.541127] Lustre: 111005:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 4050.552056] Lustre: 111005:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 4050.562072] Lustre: 111005:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 4050.579402] Lustre: 111005:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 4059.569791] Lustre: DEBUG MARKER: == sanity-lfsck test 18a: Find out orphan OST-object and repair it (1) ========================================================== 02:17:54 (1787552274) [ 4060.037767] Lustre: 109083:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 4060.044166] Lustre: 109083:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 1 previous similar message [ 4060.047973] Lustre: 109083:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 4060.053210] Lustre: 109083:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1 previous similar message [ 4060.059414] Lustre: 109083:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4060.066761] Lustre: 109083:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1 previous similar message [ 4060.078990] Lustre: 109083:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 4060.086161] Lustre: 109083:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1 previous similar message [ 4060.093115] Lustre: 109083:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 4060.101176] Lustre: 109083:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1 previous similar message [ 4060.110167] Lustre: 109083:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4060.119353] Lustre: 109083:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1 previous similar message [ 4062.369434] Lustre: *** cfs_fail_loc=1615, val=0*** [ 4062.374302] Lustre: Skipped 1 previous similar message [ 4063.475849] Lustre: *** cfs_fail_loc=1615, val=0*** [ 4063.484223] Lustre: Skipped 3 previous similar messages [ 4083.706351] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_18b skipping excluded test 18b [ 4086.382811] Lustre: DEBUG MARKER: == sanity-lfsck test 18c: Find out orphan OST-object and repair it (3) ========================================================== 02:18:20 (1787552300) [ 4087.006776] Lustre: 109081:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 4087.023826] Lustre: 109081:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 21 previous similar messages [ 4087.044116] Lustre: 109081:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 4087.060596] Lustre: 109081:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4087.075554] Lustre: 109081:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4087.087782] Lustre: 109081:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4087.098264] Lustre: 109081:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 4087.113792] Lustre: 109081:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4087.122887] Lustre: 109081:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 4087.132739] Lustre: 109081:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4087.140537] Lustre: 109081:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4087.155525] Lustre: 109081:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4089.968390] Lustre: *** cfs_fail_loc=1617, val=0*** [ 4090.159131] Lustre: *** cfs_fail_loc=1617, val=0*** [ 4093.363441] Lustre: *** cfs_fail_loc=1616, val=0*** [ 4093.370040] Lustre: Skipped 1 previous similar message [ 4115.476217] Lustre: DEBUG MARKER: == sanity-lfsck test 18d: Find out orphan OST-object and repair it (4) ========================================================== 02:18:50 (1787552330) [ 4117.684620] Lustre: *** cfs_fail_loc=1618, val=0*** [ 4117.690402] Lustre: Skipped 5 previous similar messages [ 4154.339342] 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 [ 4154.339684] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4154.340403] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4154.382195] Lustre: Skipped 1 previous similar message [ 4157.788689] Lustre: server umount lustre-MDT0000 complete [ 4163.447654] LustreError: 109067:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787552381 with bad export cookie 6230463216969669530 [ 4163.458748] LustreError: MGC192.168.204.159@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4163.463381] LustreError: 109067:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 4164.024510] Lustre: server umount lustre-MDT0001 complete [ 4179.028947] Lustre: server umount lustre-OST0000 complete [ 4180.835701] Lustre: 106236:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787552382/real 1787552382] req@ffff94878a8cf800 x1874384173360000/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787552398 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4180.867660] 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 [ 4180.888928] Lustre: Skipped 2 previous similar messages [ 4184.504473] Lustre: server umount lustre-OST0001 complete [ 4205.789804] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing load_modules_local [ 4218.210731] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4218.794840] LustreError: 117757:0:(ldlm_lib.c:1190: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. [ 4218.827375] LustreError: 117757:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 5 previous similar messages [ 4218.927672] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4223.983112] LustreError: 117758:0:(ldlm_lib.c:1190: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. [ 4224.525104] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4229.089757] LustreError: 117757:0:(ldlm_lib.c:1190: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. [ 4233.479083] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4233.713271] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 4239.109602] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4242.007501] Lustre: 118898:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 4248.966188] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4256.670379] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4258.342382] LustreError: 119253:0:(ldlm_lib.c:1190: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. [ 4258.355245] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:4 to 0x280000400:33) [ 4263.402467] LustreError: 119253:0:(ldlm_lib.c:1190: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. [ 4264.451662] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:116 to 0x280000401:161) [ 4267.334055] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4267.542755] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 4267.552114] Lustre: Skipped 1 previous similar message [ 4272.627986] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:4 to 0x2c0000401:33) [ 4272.632103] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:33) [ 4274.080494] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4281.931570] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4285.943126] Lustre: 120772:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 4302.897850] Lustre: DEBUG MARKER: == sanity-lfsck test 18e: Find out orphan OST-object and repair it (5) ========================================================== 02:21:57 (1787552517) [ 4303.470667] Lustre: 117752:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 252 < left 278, rollback = 2 [ 4303.478161] Lustre: 117752:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 46 previous similar messages [ 4303.486755] Lustre: 117752:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4303.492158] Lustre: 117752:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4303.513109] Lustre: 117752:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4303.528640] Lustre: 117752:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4303.537426] Lustre: 117752:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/1 [ 4303.548194] Lustre: 117752:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4303.559037] Lustre: 117752:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 4303.569742] Lustre: 117752:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4303.575655] Lustre: 117752:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4303.588085] Lustre: 117752:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4305.912635] Lustre: *** cfs_fail_loc=1618, val=0*** [ 4305.918914] Lustre: Skipped 3 previous similar messages [ 4341.222861] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4341.242882] 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 [ 4341.328159] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4341.344217] Lustre: Skipped 3 previous similar messages [ 4343.189571] Lustre: server umount lustre-MDT0000 complete [ 4344.300322] LustreError: 117757:0:(ldlm_lib.c:1190: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. [ 4344.300440] 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 [ 4344.360167] LustreError: 117757:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 4 previous similar messages [ 4344.382406] Lustre: Skipped 2 previous similar messages [ 4347.759561] LustreError: 118900:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787552565 with bad export cookie 6230463216969684783 [ 4347.766453] LustreError: MGC192.168.204.159@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4347.772170] LustreError: 118900:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 4348.124853] Lustre: server umount lustre-MDT0001 complete [ 4362.932343] Lustre: server umount lustre-OST0000 complete [ 4365.729705] Lustre: 106235:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787552567/real 1787552567] req@ffff94878b244a80 x1874384173437824/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787552583 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4365.774367] 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 [ 4368.213496] Lustre: server umount lustre-OST0001 complete [ 4384.936678] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing load_modules_local [ 4396.113489] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4396.544197] LustreError: 123335:0:(ldlm_lib.c:1190: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. [ 4396.566893] LustreError: 123335:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 1 previous similar message [ 4396.623734] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4401.787960] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4411.247434] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4417.059257] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4420.183140] Lustre: 124478:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 4427.294422] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4434.662783] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4437.986415] LustreError: 124831:0:(ldlm_lib.c:1190: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. [ 4437.998884] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:4 to 0x280000400:65) [ 4438.010644] LustreError: 124831:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 2 previous similar messages [ 4443.116494] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:166 to 0x280000401:193) [ 4443.361040] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4448.754583] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:4 to 0x2c0000401:65) [ 4448.769549] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:65) [ 4450.649478] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4459.133830] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4462.805405] Lustre: 126349:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 4469.839058] Lustre: 123336:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 252 < left 260, rollback = 2 [ 4469.851131] Lustre: 123336:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 21 previous similar messages [ 4469.860062] Lustre: 123336:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4469.864666] Lustre: 123336:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4469.873562] Lustre: 123336:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 0/0/0, xattr_set: 1/260/0 [ 4469.880684] Lustre: 123336:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4469.889715] Lustre: *** cfs_fail_loc=1602, val=10*** [ 4469.890679] Lustre: 123336:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/9/0, punch: 0/0/0, quota 4/150/2 [ 4469.890686] Lustre: 123336:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4469.890693] Lustre: 123336:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 1/17/2, delete: 0/0/0 [ 4469.890696] Lustre: 123336:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4469.890702] Lustre: 123336:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 4469.890705] Lustre: 123336:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4469.959957] Lustre: Skipped 1 previous similar message [ 4498.519420] Lustre: DEBUG MARKER: == sanity-lfsck test 18f: Skip the failed OST(s) when handle orphan OST-objects ========================================================== 02:25:13 (1787552713) [ 4502.300574] Lustre: *** cfs_fail_loc=1616, val=0*** [ 4502.303863] Lustre: Skipped 3 previous similar messages [ 4509.607478] Lustre: *** cfs_fail_loc=161c, val=0*** [ 4532.342384] Lustre: DEBUG MARKER: == sanity-lfsck test 18g: Find out orphan OST-object and repair it (7) ========================================================== 02:25:47 (1787552747) [ 4534.765906] Lustre: *** cfs_fail_loc=162e, val=0*** [ 4534.767945] Lustre: *** cfs_fail_loc=162e, val=0*** [ 4534.778289] Lustre: Skipped 7 previous similar messages [ 4552.065124] Lustre: DEBUG MARKER: == sanity-lfsck test 18h: LFSCK can repair crashed PFL extent range ========================================================== 02:26:06 (1787552766) [ 4577.747526] Lustre: DEBUG MARKER: == sanity-lfsck test 19a: OST-object inconsistency self detect ========================================================== 02:26:32 (1787552792) [ 4590.974230] Lustre: DEBUG MARKER: == sanity-lfsck test 19b: OST-object inconsistency self repair ========================================================== 02:26:46 (1787552806) [ 4593.912900] Lustre: *** cfs_fail_loc=1611, val=0*** [ 4593.953921] Lustre: *** cfs_fail_loc=1611, val=0*** [ 4593.955420] Lustre: Skipped 3 previous similar messages [ 4598.965859] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.204.59@tcp inode [0x2000013a1:0x1f:0x0] object 0x280000401:202 extent [0-4095], client returned csum 0 (type 4), server csum 703fb3ad (type 4) [ 4600.113594] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.204.59@tcp inode [0x2000013a1:0x20:0x0] object 0x280000401:203 extent [0-4095], client returned csum 0 (type 4), server csum 7cbb935c (type 4) [ 4609.726582] Lustre: DEBUG MARKER: == sanity-lfsck test 20a: Handle the orphan with dummy LOV EA slot properly ========================================================== 02:27:04 (1787552824) [ 4610.184759] Lustre: 123331:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 253 < left 278, rollback = 2 [ 4610.189135] Lustre: 123331:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 104 previous similar messages [ 4610.192756] Lustre: 123331:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4610.202297] Lustre: 123331:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 4610.211029] Lustre: 123331:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4610.217090] Lustre: 123331:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 4610.227087] Lustre: 123331:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/1 [ 4610.234245] Lustre: 123331:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 4610.239272] Lustre: 123331:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 4610.247868] Lustre: 123331:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 4610.254853] Lustre: 123331:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4610.260061] Lustre: 123331:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 4613.571056] Lustre: *** cfs_fail_loc=1616, val=0*** [ 4613.574546] Lustre: Skipped 3 previous similar messages [ 4640.387701] Lustre: DEBUG MARKER: == sanity-lfsck test 20b: Handle the orphan with dummy LOV EA slot properly - PFL case ========================================================== 02:27:35 (1787552855) [ 4648.883463] Lustre: DEBUG MARKER: == sanity-lfsck test 21: run all LFSCK components by default ========================================================== 02:27:43 (1787552863) [ 4660.939299] Lustre: DEBUG MARKER: == sanity-lfsck test 22a: LFSCK can repair unmatched pairs (1) ========================================================== 02:27:55 (1787552875) [ 4663.554071] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4663.562086] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4663.563901] Lustre: Skipped 1 previous similar message [ 4674.559348] Lustre: DEBUG MARKER: == sanity-lfsck test 22b: LFSCK can repair unmatched pairs (2) ========================================================== 02:28:09 (1787552889) [ 4676.278878] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4676.284300] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4687.383876] Lustre: DEBUG MARKER: == sanity-lfsck test 23a: LFSCK can repair dangling name entry (1) ========================================================== 02:28:22 (1787552902) [ 4688.895854] Lustre: *** cfs_fail_loc=1620, val=0*** [ 4705.083332] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_23b skipping excluded test 23b [ 4707.300117] Lustre: DEBUG MARKER: == sanity-lfsck test 23c: LFSCK can repair dangling name entry (3) ========================================================== 02:28:42 (1787552922) [ 4713.037125] Lustre: *** cfs_fail_loc=1621, val=127*** [ 4713.041651] Lustre: Skipped 1 previous similar message [ 4715.857938] Lustre: *** cfs_fail_loc=1602, val=10*** [ 4738.662249] Lustre: DEBUG MARKER: == sanity-lfsck test 23d: LFSCK can repair a dangling name entry to a remote object ========================================================== 02:29:13 (1787552953) [ 4741.270850] Lustre: Failing over lustre-MDT0000 [ 4741.579197] Lustre: server umount lustre-MDT0000 complete [ 4744.675605] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4744.693208] 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 [ 4744.720176] LustreError: 123335:0:(ldlm_lib.c:1190: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. [ 4744.756039] LustreError: 123335:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 2 previous similar messages [ 4753.462212] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4753.546216] LustreError: MGC192.168.204.159@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4753.703368] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4753.708076] Lustre: Skipped 3 previous similar messages [ 4753.753537] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4756.358482] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4759.032482] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4759.064879] Lustre: lustre-MDT0000: Recovery over after 0:03, of 2 clients 2 recovered and 0 were evicted. [ 4759.143106] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:130 to 0x2c0000401:161) [ 4759.144468] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:265 to 0x280000401:289) [ 4759.357325] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4761.544646] LustreError: 123332:0:(mdt_open.c:1324:mdt_cross_open()) lustre-MDT0000: [0x2000013a3:0x82:0x0] doesn't exist!: rc = -14 [ 4772.043811] Lustre: DEBUG MARKER: == sanity-lfsck test 24: LFSCK can repair multiple-referenced name entry ========================================================== 02:29:47 (1787552987) [ 4773.936374] Lustre: *** cfs_fail_loc=1622, val=0*** [ 4774.080467] Lustre: *** cfs_fail_loc=1622, val=0*** [ 4774.083071] Lustre: Skipped 1 previous similar message [ 4786.107309] Lustre: DEBUG MARKER: == sanity-lfsck test 25: LFSCK can repair bad file type in the name entry ========================================================== 02:30:01 (1787553001) [ 4787.994032] Lustre: *** cfs_fail_loc=1623, val=0*** [ 4798.511818] Lustre: DEBUG MARKER: == sanity-lfsck test 26a: LFSCK can add the missing local name entry back to the namespace ========================================================== 02:30:13 (1787553013) [ 4799.854299] Lustre: *** cfs_fail_loc=1624, val=0*** [ 4811.797340] Lustre: DEBUG MARKER: == sanity-lfsck test 26b: LFSCK can add the missing remote name entry back to the namespace ========================================================== 02:30:26 (1787553026) [ 4824.316594] Lustre: DEBUG MARKER: == sanity-lfsck test 27a: LFSCK can recreate the lost local parent directory as orphan ========================================================== 02:30:39 (1787553039) [ 4825.965131] Lustre: *** cfs_fail_loc=1624, val=0*** [ 4825.973914] Lustre: Skipped 1 previous similar message [ 4835.984214] Lustre: DEBUG MARKER: == sanity-lfsck test 27b: LFSCK can recreate the lost remote parent directory as orphan ========================================================== 02:30:51 (1787553051) [ 4848.719846] Lustre: DEBUG MARKER: == sanity-lfsck test 28: Skip the failed MDT(s) when handle orphan MDT-objects ========================================================== 02:31:04 (1787553064) [ 4854.385142] Lustre: *** cfs_fail_loc=161c, val=0*** [ 4854.386837] Lustre: Skipped 1 previous similar message [ 4867.570659] Lustre: DEBUG MARKER: == sanity-lfsck test 29b: LFSCK can repair bad nlink count (2) ========================================================== 02:31:22 (1787553082) [ 4868.517692] Lustre: 127409:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 4868.526727] Lustre: 127409:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 518 previous similar messages [ 4868.529897] Lustre: 127409:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 4868.533228] Lustre: 127409:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 518 previous similar messages [ 4868.546079] Lustre: 127409:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4868.554119] Lustre: 127409:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 518 previous similar messages [ 4868.560392] Lustre: 127409:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 4868.573954] Lustre: 127409:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 518 previous similar messages [ 4868.579000] Lustre: 127409:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 4868.585864] Lustre: 127409:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 518 previous similar messages [ 4868.589115] Lustre: 127409:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4868.593420] Lustre: 127409:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 518 previous similar messages [ 4869.710407] Lustre: *** cfs_fail_loc=1626, val=0*** [ 4869.712369] Lustre: Skipped 4 previous similar messages [ 4883.563489] Lustre: DEBUG MARKER: == sanity-lfsck test 29c: verify linkEA size limitation == 02:31:38 (1787553098) [ 4910.903476] Lustre: DEBUG MARKER: == sanity-lfsck test 29d: accessing non-existing inode shouldn't turn fs read-only (ldiskfs) ========================================================== 02:32:05 (1787553125) [ 4913.739911] LustreError: 123330:0:(osd_handler.c:284:osd_idc_find_or_init()) lustre-MDT0000: cannot lookup FID [0x2000013a3:0x9e:0x0]: rc = -2 [ 4920.904560] Lustre: DEBUG MARKER: == sanity-lfsck test 30: LFSCK can recover the orphans from backend /lost+found ========================================================== 02:32:16 (1787553136) [ 4944.732096] Lustre: Failing over lustre-MDT0000 [ 4945.172950] Lustre: server umount lustre-MDT0000 complete [ 4948.449481] 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 [ 4948.452166] LustreError: 124326:0:(ldlm_lib.c:1190: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. [ 4948.467629] Lustre: Skipped 6 previous similar messages [ 4948.490666] LustreError: 124326:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 13 previous similar messages [ 4957.310245] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 4957.463371] LustreError: MGC192.168.204.159@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4957.668434] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4957.704337] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4962.536408] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4962.788726] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4962.825089] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4962.840457] Lustre: Skipped 3 previous similar messages [ 4962.905402] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4962.997957] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:166 to 0x2c0000401:193) [ 4963.000187] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:295 to 0x280000401:321) [ 4978.100762] Lustre: DEBUG MARKER: == sanity-lfsck test 31a: The LFSCK can find/repair the name entry with bad name hash (1) ========================================================== 02:33:13 (1787553193) [ 4992.878628] Lustre: DEBUG MARKER: == sanity-lfsck test 31b: The LFSCK can find/repair the name entry with bad name hash (2) ========================================================== 02:33:27 (1787553207) [ 5009.391731] Lustre: DEBUG MARKER: == sanity-lfsck test 31c: Re-generate the lost master LMV EA for striped directory ========================================================== 02:33:44 (1787553224) [ 5011.156798] Lustre: *** cfs_fail_loc=1629, val=0*** [ 5011.160974] Lustre: Skipped 5 previous similar messages [ 5040.180925] Lustre: DEBUG MARKER: == sanity-lfsck test 31d: Set broken striped directory (modified after broken) as read-only ========================================================== 02:34:15 (1787553255) [ 5047.029854] Lustre: Failing over lustre-MDT0000 [ 5047.410871] Lustre: server umount lustre-MDT0000 complete [ 5049.826581] 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 [ 5049.836426] Lustre: Skipped 1 previous similar message [ 5056.062583] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5056.160353] LustreError: MGC192.168.204.159@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5056.466609] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 5060.646237] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5061.604461] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 5061.616475] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 5061.620437] Lustre: Skipped 3 previous similar messages [ 5061.646450] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 5061.688063] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:166 to 0x2c0000401:225) [ 5061.689818] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:295 to 0x280000401:353) [ 5069.827698] Lustre: Failing over lustre-MDT0000 [ 5070.055552] Lustre: server umount lustre-MDT0000 complete [ 5071.850302] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 5078.255634] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5078.347677] LustreError: MGC192.168.204.159@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5078.393138] Lustre: lustre-MDT0000: Not available for connect from 192.168.204.59@tcp (not set up) [ 5078.570968] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 5079.617598] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 5082.895593] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5083.632918] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 5083.638055] Lustre: Skipped 3 previous similar messages [ 5083.683763] Lustre: lustre-MDT0000: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 5083.723083] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:295 to 0x280000401:385) [ 5083.723335] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:227 to 0x2c0000401:257) [ 5091.308686] Lustre: DEBUG MARKER: == sanity-lfsck test 31e: Re-generate the lost slave LMV EA for striped directory (1) ========================================================== 02:35:06 (1787553306) [ 5103.514400] Lustre: DEBUG MARKER: == sanity-lfsck test 31f: Re-generate the lost slave LMV EA for striped directory (2) ========================================================== 02:35:18 (1787553318) [ 5115.904641] Lustre: DEBUG MARKER: == sanity-lfsck test 31g: Repair the corrupted slave LMV EA ========================================================== 02:35:31 (1787553331) [ 5155.755339] Lustre: DEBUG MARKER: == sanity-lfsck test 31h: Repair the corrupted shard's name entry ========================================================== 02:36:11 (1787553371) [ 5171.735696] Lustre: DEBUG MARKER: == sanity-lfsck test 32a: stop LFSCK when some OST failed ========================================================== 02:36:26 (1787553386) [ 5181.807123] LustreError: 147763:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d sleeping for 3000ms [ 5184.771616] Lustre: Failing over lustre-OST0000 [ 5184.882757] LustreError: 147763:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d awake [ 5184.893790] LustreError: 147763:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d sleeping for 3000ms [ 5184.957205] Lustre: server umount lustre-OST0000 complete [ 5185.511425] LustreError: lustre-OST0000-osc-MDT0001: operation ost_statfs to node 0@lo failed: rc = -107 [ 5185.522085] 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 [ 5185.545366] Lustre: Skipped 6 previous similar messages [ 5187.914603] LustreError: 147763:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d awake [ 5187.929250] LustreError: 147763:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d sleeping for 3000ms [ 5188.475456] LustreError: 147763:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout interrupted [ 5200.490484] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 5200.822960] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 5202.472163] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 5202.488830] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 5202.488992] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 5202.511936] Lustre: Skipped 3 previous similar messages [ 5208.402753] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5218.189364] Lustre: DEBUG MARKER: == sanity-lfsck test 32b: stop LFSCK when some MDT failed ========================================================== 02:37:12 (1787553432) [ 5231.420787] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing load_modules_local [ 5250.494643] Lustre: 150567:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 5273.989203] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5277.735474] Lustre: 151703:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 5289.915126] LustreError: 151818:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d sleeping for 3000ms [ 5292.988431] Lustre: Failing over lustre-MDT0001 [ 5293.002239] LustreError: 151818:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d awake [ 5293.012616] LustreError: lustre-MDT0001-osp-MDT0000: operation out_update to node 0@lo failed: rc = -107 [ 5293.013517] LustreError: 151818:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) Skipped 1 previous similar message [ 5293.032631] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 5293.233387] Lustre: server umount lustre-MDT0001 complete [ 5296.049612] LustreError: 151817:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d awake [ 5298.144855] LustreError: 127409:0:(ldlm_lib.c:1190: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. [ 5298.168405] LustreError: 127409:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 30 previous similar messages [ 5309.750645] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 5310.187080] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 5310.200078] Lustre: Skipped 3 previous similar messages [ 5310.237968] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 5314.820437] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5315.555889] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 1 client reconnects [ 5315.565089] Lustre: lustre-MDT0001-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 5315.571215] Lustre: Skipped 1 previous similar message [ 5315.598307] Lustre: lustre-MDT0001: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 5315.688289] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:70 to 0x280000400:97) [ 5315.689832] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:69 to 0x2c0000400:97) [ 5324.265891] Lustre: DEBUG MARKER: == sanity-lfsck test 33: check LFSCK paramters =========== 02:38:59 (1787553539) [ 5340.782222] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing load_modules_local [ 5361.986199] Lustre: 154538:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 5385.248841] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5388.863469] Lustre: 155673:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 5391.075967] Lustre: 123332:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 5391.084994] Lustre: 123332:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 1222 previous similar messages [ 5391.092746] Lustre: 123332:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 5391.096698] Lustre: 123332:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1221 previous similar messages [ 5391.106460] Lustre: 123332:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 5391.117547] Lustre: 123332:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1222 previous similar messages [ 5391.126862] Lustre: 123332:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 5391.132588] Lustre: 123332:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1222 previous similar messages [ 5391.138229] Lustre: 123332:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 5391.149171] Lustre: 123332:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1221 previous similar messages [ 5391.160233] Lustre: 123332:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 5391.168257] Lustre: 123332:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1221 previous similar messages [ 5407.597651] Lustre: DEBUG MARKER: == sanity-lfsck test 34: LFSCK can rebuild the lost agent object ========================================================== 02:40:22 (1787553622) [ 5409.055686] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_34 Only valid for ZFS backend [ 5410.887504] Lustre: DEBUG MARKER: == sanity-lfsck test 35: LFSCK can rebuild the lost agent entry ========================================================== 02:40:26 (1787553626) [ 5417.450831] Lustre: *** cfs_fail_loc=1631, val=0*** [ 5433.321771] 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 [ 5433.323451] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5433.343067] Lustre: Skipped 6 previous similar messages [ 5433.344699] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 5433.375378] Lustre: Skipped 5 previous similar messages [ 5436.813107] Lustre: server umount lustre-MDT0000 complete [ 5440.541862] LustreError: 123318:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787553658 with bad export cookie 6230463216969757688 [ 5440.553119] LustreError: MGC192.168.204.159@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5440.560501] LustreError: 123318:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 5440.833862] Lustre: server umount lustre-MDT0001 complete [ 5455.055973] Lustre: server umount lustre-OST0000 complete [ 5469.112306] Lustre: server umount lustre-OST0001 complete [ 5484.725908] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing load_modules_local [ 5496.956874] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5501.471801] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5508.954242] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5513.137587] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5515.725423] Lustre: 159567:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 5521.668133] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5522.931321] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:540 to 0x280000401:577) [ 5528.071920] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5534.200825] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:70 to 0x280000400:129) [ 5537.986829] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5543.405580] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:69 to 0x2c0000400:129) [ 5543.407037] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:412 to 0x2c0000401:449) [ 5544.620663] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5553.095581] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5556.527734] Lustre: 161437:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 5566.319961] Lustre: DEBUG MARKER: == sanity-lfsck test 36a: rebuild LOV EA for mirrored file (1) ========================================================== 02:43:01 (1787553781) [ 5567.866797] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36a needs >= 3 OSTs [ 5570.214807] Lustre: DEBUG MARKER: == sanity-lfsck test 36b: rebuild LOV EA for mirrored file (2) ========================================================== 02:43:05 (1787553785) [ 5571.785317] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36b needs >= 3 OSTs [ 5575.310596] Lustre: DEBUG MARKER: == sanity-lfsck test 36c: rebuild LOV EA for mirrored file (3) ========================================================== 02:43:09 (1787553789) [ 5577.205641] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36c needs >= 3 OSTs [ 5580.003495] Lustre: DEBUG MARKER: == sanity-lfsck test 37: LFSCK must skip a ORPHAN ======== 02:43:14 (1787553794) [ 5596.015290] Lustre: DEBUG MARKER: == sanity-lfsck test 38: LFSCK does not break foreign file and reverse is also true ========================================================== 02:43:30 (1787553810) [ 5614.622581] Lustre: DEBUG MARKER: == sanity-lfsck test 39: LFSCK does not break foreign dir and reverse is also true ========================================================== 02:43:49 (1787553829) [ 5630.217275] Lustre: DEBUG MARKER: == sanity-lfsck test 40a: LFSCK correctly fixes lmm_oi in composite layout ========================================================== 02:44:05 (1787553845) [ 5645.313261] Lustre: DEBUG MARKER: == sanity-lfsck test 41: SEL support in LFSCK ============ 02:44:20 (1787553860) [ 5664.623857] Lustre: DEBUG MARKER: == sanity-lfsck test 42: LFSCK repairs inconsistent MDT-object/OST-object encryption flags ========================================================== 02:44:39 (1787553879) [ 5698.202180] Lustre: *** cfs_fail_loc=1632, val=0*** [ 5713.215959] Lustre: DEBUG MARKER: == sanity-lfsck test 43: LFSCK does not loop endlessly on iget failure in scanning-phase1 ========================================================== 02:45:28 (1787553928) [ 5716.461028] Lustre: Failing over lustre-MDT0001 [ 5716.673377] Lustre: server umount lustre-MDT0001 complete [ 5719.523800] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 5719.533780] Lustre: lustre-MDT0001-osp-MDT0000: Connection to lustre-MDT0001 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 5719.547845] Lustre: Skipped 1 previous similar message [ 5723.843780] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5724.262858] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 5724.264545] Lustre: lustre-MDT0001: Aborting client recovery [ 5724.277934] LustreError: 165239:0:(ldlm_lib.c:3029:target_stop_recovery_thread()) lustre-MDT0001: Aborting recovery [ 5724.279889] Lustre: 165263:0:(ldlm_lib.c:2429:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 5724.296501] Lustre: 165263:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0001: disconnect stale client 3dc8f2f0-c6e8-4d6e-906c-42e1bb041b14@ [ 5724.306374] Lustre: lustre-MDT0001: disconnecting 2 stale clients [ 5724.310755] Lustre: lustre-MDT0001-osd: cancel update llog [0x240000400:0x1:0x0] [ 5724.319301] Lustre: lustre-MDT0000-osp-MDT0001: cancel update llog [0x200000401:0x1:0x0] [ 5724.386993] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:69 to 0x2c0000400:161) [ 5724.389886] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:131 to 0x280000400:161) [ 5729.259652] Lustre: lustre-MDT0001-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 5729.279770] Lustre: Skipped 2 previous similar messages [ 5729.294346] LustreError: lustre-MDT0001-osp-MDT0000: This client was evicted by lustre-MDT0001; in progress operations using this service will fail. [ 5729.522639] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5733.742123] Lustre: *** cfs_fail_loc=1e2, val=483*** [ 5738.883617] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing wait_import_state FULL osp.lustre-MDT0001-os[pc]-MDT0000.*_server_uuid [ 5739.186882] Lustre: DEBUG MARKER: osp.lustre-MDT0001-os[pc]-MDT0000.*_server_uuid in FULL state after 0 sec [ 5746.233821] Lustre: DEBUG MARKER: == sanity-lfsck test 44: umount while lfsck is stopping == 02:46:01 (1787553961) [ 5753.824705] Lustre: *** cfs_fail_loc=1600, val=3*** [ 5756.460149] Lustre: Failing over lustre-MDT0000 [ 5756.892493] Lustre: server umount lustre-MDT0000 complete [ 5767.940314] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5768.033269] LustreError: MGC192.168.204.159@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5768.363572] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 5768.371585] Lustre: Skipped 2 previous similar messages [ 5771.632783] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 5773.168178] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5773.803095] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 5773.810890] Lustre: Skipped 2 previous similar messages [ 5773.843464] Lustre: lustre-MDT0000: Recovery over after 0:02, of 2 clients 2 recovered and 0 were evicted. [ 5773.917984] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:621 to 0x280000401:641) [ 5773.919198] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:489 to 0x2c0000401:513) [ 5783.446602] Lustre: DEBUG MARKER: == sanity-lfsck test 45: LFSCK should fix UID/GID/PROJID of OST object ========================================================== 02:46:38 (1787553998) [ 5828.493821] Lustre: Failing over lustre-OST0001 [ 5828.636723] Lustre: server umount lustre-OST0001 complete [ 5830.117987] LustreError: 162141:0:(ldlm_lib.c:1190: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. [ 5830.131417] LustreError: 162141:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 34 previous similar messages [ 5836.794331] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: (null) [ 5850.338557] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5850.710138] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 5850.739116] Lustre: Skipped 6 previous similar messages [ 5850.767369] Lustre: lustre-OST0001: in recovery but waiting for the first client to connect [ 5852.463988] Lustre: lustre-OST0001: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 5852.745352] Lustre: lustre-OST0001: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [ 5852.745751] Lustre: lustre-OST0001-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 5852.772193] Lustre: Skipped 3 previous similar messages [ 5858.940861] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5865.510428] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing wait_import_state (FULL|IDLE) os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid 50 [ 5865.760701] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid in FULL state after 0 sec [ 5870.728311] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing wait_import_state (FULL|IDLE) os[cp].lustre-OST0000-osc-MDT0001.ost_server_uuid 50 [ 5870.949616] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0001.ost_server_uuid in FULL state after 0 sec [ 5876.996357] Lustre: DEBUG MARKER: oleg459-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0000-osc-ffff9268d7e3c800.ost_server_uuid 50 [ 5878.689956] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9268d7e3c800.ost_server_uuid in FULL state after 0 sec [ 5958.113123] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 5958.122515] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5958.135466] LustreError: Skipped 1 previous similar message [ 5958.150514] Lustre: Skipped 2 previous similar messages [ 5963.150565] Lustre: server umount lustre-MDT0000 complete [ 5972.459913] LustreError: 162150:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787554190 with bad export cookie 6230463216969840652 [ 5972.465267] LustreError: MGC192.168.204.159@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5972.472579] LustreError: 162150:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 5972.816524] Lustre: server umount lustre-MDT0001 complete [ 5989.347450] Lustre: 106234:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787554191/real 1787554191] req@ffff9487832de300 x1874384175247360/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787554207 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5990.563263] Lustre: server umount lustre-OST0000 complete [ 5993.443130] Lustre: 106235:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787554195/real 1787554195] req@ffff9488889cb800 x1874384175247616/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787554211 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5994.720156] Lustre: 106233:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787554196/real 1787554196] req@ffff9487832dc700 x1874384175247872/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787554212 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5998.462701] Lustre: server umount lustre-OST0001 complete [ 6015.323871] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing unload_modules_local [ 6018.633389] Key type lgssc unregistered [ 6018.893670] LNet: 174939:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 6018.902918] LNetError: 174939:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 6018.918842] LNet: Removed LNI 192.168.204.159@tcp [ 6020.028173] Key type .llcrypt unregistered [ 6020.030237] Key type ._llcrypt unregistered [ 6046.335763] Key type ._llcrypt registered [ 6046.338594] Key type .llcrypt registered [ 6046.427632] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_hostid [ 6063.382567] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing load_modules_local [ 6064.647054] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 6064.666579] alg: No test for adler32 (adler32-zlib) [ 6065.739493] Lustre: Lustre: Build Version: 2.17.57_83_g6b3cfd8 [ 6066.140896] LNet: Added LNI 192.168.204.159@tcp [8/256/0/180] [ 6067.904147] Key type lgssc registered [ 6069.285596] Lustre: Echo OBD driver; http://www.lustre.org/ [ 6114.198873] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing load_modules_local [ 6126.053566] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 6126.080937] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 6127.394370] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 6127.446593] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 6127.541147] Lustre: lustre-MDT0000: new disk, initializing [ 6127.612165] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 6127.623896] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 6131.848452] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6145.269039] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 6145.366401] Lustre: 179393: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 [ 6145.423294] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 6145.427173] Lustre: Skipped 1 previous similar message [ 6145.560380] Lustre: lustre-MDT0001: new disk, initializing [ 6145.626688] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 6145.655532] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 6145.672027] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 6149.953396] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6155.151697] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 6165.932469] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 6166.153839] Lustre: lustre-OST0000: new disk, initializing [ 6166.157358] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 6166.162433] Lustre: 181332:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 6166.217471] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 6166.416467] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 6166.426122] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 6166.535255] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 6172.636500] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6186.558196] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 6186.709977] Lustre: lustre-OST0001: new disk, initializing [ 6186.714121] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 6186.724547] Lustre: 182356:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 6186.818354] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 6194.216931] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 6194.226278] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 6194.362716] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 6194.554182] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6206.943548] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 6213.586238] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 6219.774350] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 02:53:54 (1787554434) === [ 6221.323831] Lustre: DEBUG MARKER: == sanity-lfsck test complete, duration 5933 sec ========= 02:53:56 (1787554436) [ 6223.230671] Lustre: DEBUG MARKER: === sanity-lfsck: start cleanup 02:53:58 (1787554438) === [ 6227.458637] Lustre: DEBUG MARKER: === sanity-lfsck: finish cleanup 02:54:02 (1787554442) === [ 6232.546029] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 6232.557142] 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 [ 6232.587774] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 6235.626814] 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 [ 6235.628917] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 6235.640284] Lustre: Skipped 1 previous similar message [ 6235.651643] Lustre: Skipped 1 previous similar message [ 6238.364473] Lustre: server umount lustre-MDT0000 complete [ 6245.865568] LustreError: 179401:0:(ldlm_lib.c:1190: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. [ 6245.896559] LustreError: 179401:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 8 previous similar messages [ 6246.649577] LustreError: 179388:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787554464 with bad export cookie 1212002728694531495 [ 6246.652643] LustreError: MGC192.168.204.159@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 6246.659091] LustreError: 179388:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 6246.955561] Lustre: server umount lustre-MDT0001 complete [ 6265.300958] Lustre: server umount lustre-OST0000 complete [ 6266.337240] Lustre: 176555:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787554468/real 1787554468] req@ffff94878e9ce300 x1874386520983552/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787554484 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6266.378652] 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 [ 6266.398354] Lustre: Skipped 1 previous similar message [ 6268.064152] Lustre: 176556:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787554469/real 1787554469] req@ffff94878acfb100 x1874386520983808/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787554485 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6270.432658] Lustre: 176554:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787554472/real 1787554472] req@ffff94878acf8380 x1874386520984064/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787554488 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6274.377924] Lustre: server umount lustre-OST0001 complete [ 6292.269806] Lustre: DEBUG MARKER: oleg459-server.virtnet: executing unload_modules_local [ 6295.263922] Key type lgssc unregistered [ 6295.639704] LNet: 185833:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 6295.656648] LNetError: 185833:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 6295.682110] LNet: Removed LNI 192.168.204.159@tcp [ 6296.880300] Key type .llcrypt unregistered [ 6296.886434] Key type ._llcrypt unregistered