[ 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 477423355 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: 2895240K/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.001013] APIC: Switch to symmetric I/O mode setup [ 0.003188] x2apic enabled [ 0.004021] Switched APIC routing to physical x2apic. [ 0.005018] kvm-guest: setup PV IPIs [ 0.008496] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.009000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.009023] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.010017] pid_max: default: 32768 minimum: 301 [ 0.012147] LSM: Security Framework initializing [ 0.013058] Yama: becoming mindful. [ 0.014045] SELinux: Initializing. [ 0.015082] *** VALIDATE selinux *** [ 0.024119] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.029527] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.030151] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.031123] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.033071] *** VALIDATE tmpfs *** [ 0.034454] *** VALIDATE proc *** [ 0.035257] *** VALIDATE cgroup *** [ 0.036011] *** VALIDATE cgroup2 *** [ 0.037221] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.038157] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.039009] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.040028] Spectre V2 : User space: Vulnerable [ 0.041007] Speculative Store Bypass: Vulnerable [ 0.044420] debug: unmapping init [mem 0xffffffffab459000-0xffffffffab460fff] [ 0.047000] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.047717] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.048028] ... version: 2 [ 0.049011] ... bit width: 48 [ 0.050015] ... generic registers: 4 [ 0.051012] ... value mask: 0000ffffffffffff [ 0.052014] ... max period: 00007fffffffffff [ 0.053015] ... fixed-purpose events: 3 [ 0.054012] ... event mask: 000000070000000f [ 0.055296] rcu: Hierarchical SRCU implementation. [ 0.057428] smp: Bringing up secondary CPUs ... [ 0.058503] x86: Booting SMP configuration: [ 0.059015] .... node #0, CPUs: #1 #2 #3 [ 0.068077] smp: Brought up 1 node, 4 CPUs [ 0.070028] smpboot: Max logical packages: 1 [ 0.071012] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.130552] node 0 deferred pages initialised in 58ms [ 0.134163] devtmpfs: initialized [ 0.135234] x86/mm: Memory block size: 128MB [ 0.138066] gcov: version magic: 0x41383552 [ 0.139695] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.140090] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.141234] pinctrl core: initialized pinctrl subsystem [ 0.142175] [ 0.142753] ************************************************************* [ 0.143013] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.144013] ** ** [ 0.145018] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.146014] ** ** [ 0.147013] ** This means that this kernel is built to expose internal ** [ 0.148013] ** IOMMU data structures, which may compromise security on ** [ 0.149014] ** your system. ** [ 0.150025] ** ** [ 0.151013] ** If you see this message and you are not debugging the ** [ 0.152014] ** kernel, report this immediately to your vendor! ** [ 0.153014] ** ** [ 0.154016] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.155014] ************************************************************* [ 0.156689] NET: Registered protocol family 16 [ 0.157472] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.158058] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.159060] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.160463] cpuidle: using governor menu [ 0.162298] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.164417] PCI: Using configuration type 1 for base access [ 0.166094] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.175052] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.176044] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.178100] cryptd: max_cpu_qlen set to 1000 [ 0.179281] ACPI: Added _OSI(Module Device) [ 0.182018] ACPI: Added _OSI(Processor Device) [ 0.183014] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.185013] ACPI: Added _OSI(Processor Aggregator Device) [ 0.191896] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.197783] ACPI: Interpreter enabled [ 0.199065] ACPI: PM: (supports S0 S3 S4 S5) [ 0.201069] ACPI: Using IOAPIC for interrupt routing [ 0.202103] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.206485] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.219114] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.221089] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.222013] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.224089] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.227944] acpiphp: Slot [2] registered [ 0.229067] acpiphp: Slot [5] registered [ 0.230000] acpiphp: Slot [6] registered [ 0.230000] acpiphp: Slot [7] registered [ 0.230000] acpiphp: Slot [8] registered [ 0.231075] acpiphp: Slot [9] registered [ 0.231890] acpiphp: Slot [10] registered [ 0.233062] acpiphp: Slot [3] registered [ 0.233971] acpiphp: Slot [4] registered [ 0.234052] acpiphp: Slot [11] registered [ 0.234995] acpiphp: Slot [12] registered [ 0.236056] acpiphp: Slot [13] registered [ 0.236957] acpiphp: Slot [14] registered [ 0.238070] acpiphp: Slot [15] registered [ 0.238931] acpiphp: Slot [16] registered [ 0.240048] acpiphp: Slot [17] registered [ 0.240959] acpiphp: Slot [18] registered [ 0.241062] acpiphp: Slot [19] registered [ 0.241853] acpiphp: Slot [20] registered [ 0.243051] acpiphp: Slot [21] registered [ 0.244099] acpiphp: Slot [22] registered [ 0.246061] acpiphp: Slot [23] registered [ 0.246917] acpiphp: Slot [24] registered [ 0.248098] acpiphp: Slot [25] registered [ 0.248889] acpiphp: Slot [26] registered [ 0.249052] acpiphp: Slot [27] registered [ 0.249885] acpiphp: Slot [28] registered [ 0.251072] acpiphp: Slot [29] registered [ 0.251980] acpiphp: Slot [30] registered [ 0.253052] acpiphp: Slot [31] registered [ 0.253905] PCI host bridge to bus 0000:00 [ 0.254012] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.256022] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.257015] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.259023] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.263026] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.266024] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.268185] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.272503] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.276339] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.284013] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.287163] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.289017] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.291012] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.292014] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.294472] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.296583] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.298036] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.300524] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.303808] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.312027] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.318016] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.322169] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.329021] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.336019] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.350026] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.358082] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.366014] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.372014] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.384032] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.391601] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.399021] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.405017] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.417025] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.427155] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.433022] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.443012] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.465019] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.477921] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.483020] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.489017] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.505020] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 0.517368] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.524017] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.530018] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.544020] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 0.554627] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.557357] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.559265] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.561312] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.563247] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.569553] iommu: Default domain type: Passthrough [ 0.570430] SCSI subsystem initialized [ 0.571090] ACPI: bus type USB registered [ 0.572091] usbcore: registered new interface driver usbfs [ 0.573060] usbcore: registered new interface driver hub [ 0.575059] usbcore: registered new device driver usb [ 0.576159] pps_core: LinuxPPS API ver. 1 registered [ 0.577008] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.580046] PTP clock support registered [ 0.581062] EDAC MC: Ver: 3.0.0 [ 0.582465] PCI: Using ACPI for IRQ routing [ 0.583745] NetLabel: Initializing [ 0.585011] NetLabel: domain hash size = 128 [ 0.587011] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.589080] NetLabel: unlabeled traffic allowed by default [ 0.590226] vgaarb: loaded [ 0.591164] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.592007] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.601149] clocksource: Switched to clocksource kvm-clock [ 0.693093] VFS: Disk quotas dquot_6.6.0 [ 0.694079] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.695581] *** VALIDATE ramfs *** [ 0.696335] *** VALIDATE hugetlbfs *** [ 0.697294] pnp: PnP ACPI init [ 0.698875] pnp: PnP ACPI: found 6 devices [ 0.717985] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.721750] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.723696] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.725261] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.727711] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.730399] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.732786] NET: Registered protocol family 2 [ 0.735047] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.739657] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.742473] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.746909] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.750618] TCP: Hash tables configured (established 65536 bind 65536) [ 0.752919] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.754898] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.758106] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.761545] NET: Registered protocol family 1 [ 0.764675] RPC: Registered named UNIX socket transport module. [ 0.767405] RPC: Registered udp transport module. [ 0.769506] RPC: Registered tcp transport module. [ 0.771357] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.774194] NET: Registered protocol family 44 [ 0.775897] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.777838] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.779993] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.782587] PCI: CLS 0 bytes, default 64 [ 0.785217] Unpacking initramfs... [ 2.229329] debug: unmapping init [mem 0xffff958dfcc54000-0xffff958dfffbffff] [ 2.234553] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.237835] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.241878] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 2.761386] Initialise system trusted keyrings [ 2.763420] Key type blacklist registered [ 2.765979] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.774094] zbud: loaded [ 2.777456] *** VALIDATE nfs *** [ 2.779124] *** VALIDATE nfs4 *** [ 2.781089] pstore: using deflate compression [ 2.784687] Platform Keyring initialized [ 2.888904] NET: Registered protocol family 38 [ 2.890702] Key type asymmetric registered [ 2.892159] Asymmetric key parser 'x509' registered [ 2.893990] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 2.896640] io scheduler mq-deadline registered [ 2.898287] io scheduler kyber registered [ 2.899811] io scheduler bfq registered [ 2.901932] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 2.904831] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 2.910617] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 2.913164] ACPI: Power Button [PWRF] [ 2.917517] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 2.922740] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 2.936756] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 2.941646] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 2.957859] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 2.984094] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.011751] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.016948] Non-volatile memory driver v1.3 [ 3.018660] Linux agpgart interface v0.103 [ 3.049935] virtio_blk virtio1: [vda] 150056 512-byte logical blocks (76.8 MB/73.3 MiB) [ 3.053027] vda: detected capacity change from 0 to 76828672 [ 3.070202] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.073365] vdb: detected capacity change from 0 to 1073741824 [ 3.094625] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.097880] vdc: detected capacity change from 0 to 2621440000 [ 3.115845] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.118746] vdd: detected capacity change from 0 to 2621440000 [ 3.145487] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.148297] vde: detected capacity change from 0 to 4294967296 [ 3.165971] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.172017] vdf: detected capacity change from 0 to 4294967296 [ 3.180152] libphy: Fixed MDIO Bus: probed [ 3.187431] usbcore: registered new interface driver usbserial_generic [ 3.189826] usbserial: USB Serial support registered for generic [ 3.192097] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.196824] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.198630] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.201231] mousedev: PS/2 mouse device common for all mice [ 3.204205] rtc_cmos 00:05: RTC can wake from S4 [ 3.207566] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.211315] rtc_cmos 00:05: registered as rtc0 [ 3.215381] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.215433] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.221915] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.222923] intel_pstate: CPU model not supported [ 3.230363] hid: raw HID events driver (C) Jiri Kosina [ 3.232920] usbcore: registered new interface driver usbhid [ 3.235475] usbhid: USB HID core driver [ 3.237617] drop_monitor: Initializing network drop monitor service [ 3.239943] Initializing XFRM netlink socket [ 3.241801] NET: Registered protocol family 10 [ 3.245483] Segment Routing with IPv6 [ 3.247718] NET: Registered protocol family 17 [ 3.252153] mpls_gso: MPLS GSO support [ 3.260098] RAS: Correctable Errors collector initialized. [ 3.262363] AVX version of gcm_enc/dec engaged. [ 3.264017] AES CTR mode by8 optimization enabled [ 3.349951] sched_clock: Marking stable (3349930177, 0)->(4311175389, -961245212) [ 3.353428] registered taskstats version 1 [ 3.355534] Loading compiled-in X.509 certificates [ 3.358648] zswap: loaded using pool lzo/zbud [ 3.388063] Key type big_key registered [ 3.401770] Key type encrypted registered [ 3.403896] ima: No TPM chip found, activating TPM-bypass! [ 3.406926] ima: Allocated hash algorithm: sha1 [ 3.409427] ima: No architecture policies found [ 3.412116] evm: Initialising EVM extended attributes: [ 3.414670] evm: security.selinux [ 3.416274] evm: security.ima [ 3.417358] evm: security.capability [ 3.418394] evm: HMAC attrs: 0x1 [ 3.420225] rtc_cmos 00:05: setting system clock to 2026-09-07 01:25:04 UTC (1788744304) [ 3.424957] debug: unmapping init [mem 0xffffffffac403000-0xffffffffac5fffff] [ 3.429538] debug: unmapping init [mem 0xffffffffab182000-0xffffffffab458fff] [ 3.439463] Write protecting the kernel read-only data: 28672k [ 3.443024] debug: unmapping init [mem 0xffffffffa9803000-0xffffffffa99fffff] [ 3.446014] debug: unmapping init [mem 0xffffffffaa114000-0xffffffffaa1fffff] [ 3.473861] 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.482573] systemd[1]: Detected virtualization kvm. [ 3.484870] systemd[1]: Detected architecture x86-64. [ 3.487041] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.519164] systemd[1]: No hostname configured. [ 3.521271] systemd[1]: Set hostname to . [ 3.523751] random: systemd: uninitialized urandom read (16 bytes read) [ 3.526751] systemd[1]: Initializing machine ID from random generator. [ 3.662091] random: systemd: uninitialized urandom read (16 bytes read) [ 3.666422] systemd[1]: Listening on Journal Socket (/dev/log). [ OK ] Listening on Journal Socket (/dev/log). [ 3.673471] random: systemd: uninitialized urandom read (16 bytes read) [ 3.676275] systemd[1]: Reached target Swap. [ OK ] Reached target Swap. [ 3.681281] systemd[1]: Reached target Timers. [ OK ] Reached target Timers. [ OK ] Listening on Journal Socket. Starting Setup Virtual Console... [ OK ] Started Memstrack Anylazing Service. [ OK ] Reached target Slices. [ OK ] Reached target Initrd Root Device. Starting Create list of required st…ce nodes for the current kernel... Starting Apply Kernel Variables... Starting Journal Service... [ OK ] Reached target Local File Systems. Starting Create Volatile Files and Directories... [ OK ] Listening on udev Control Socket. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Paths. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Listening on udev Kernel Socket. [ OK ] Reached target Sockets. [ OK ] Started 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. Starting Create Static Device Nodes in /dev... Starting dracut cmdline hook... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] [ 3.937696] random: fast init done Started Journal Service. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 4.297280] device-mapper: uevent: version 1.0.3 [ 4.299537] device-mapper: ioctl: 4.46.0-ioctl (2022-02-22) initialised: dm-devel@redhat.com [ OK ] Started dracut pre-udev hook. Starting udev Kernel Device Manager... [ OK ] Started udev Kernel Device Manager. Starting dracut pre-trigger hook... [ OK ] Started dracut pre-trigger hook. Starting udev Coldplug all Devices... Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. Starting dracut initqueue hook... [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ 5.044599] virtio_net virtio0 ens2: renamed from eth0 [ 5.211342] scsi host0: ata_piix [ 5.277350] scsi host1: ata_piix [ 5.278974] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 5.281600] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 9.922804] random: crng init done [ 9.924346] random: 7 urandom warning(s) missed due to ratelimiting [ 9.935711] dracut-initqueue[586]: RTNETLINK answers: File exists 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.568976] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped target Timers. [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Paths. [ OK ] Stopped target System Initialization. [ OK ] Stopped target Swap. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped target Local File Systems. Stopping udev Kernel Device Manager... [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped target Slices. [ OK ] Stopped target Sockets. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Closed udev 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.925884] printk: systemd: 26 output lines suppressed due to ratelimiting [ 12.226665] SELinux: Disabled at runtime. [ 12.294405] 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.303273] systemd[1]: Detected virtualization kvm. [ 12.305396] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 12.995420] systemd[1]: initrd-switch-root.service: Succeeded. [ 12.999597] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 13.006855] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 13.011134] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 13.014676] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 13.025122] systemd[1]: Starting Journal Service... Starting Journal Service... [ 13.030590] systemd[1]: Created slice system-getty.slice. [ OK ] Created slice system-getty.slice. [ OK ] Created slice system-serial\x2dgetty.slice. Mounting Kernel Debug File System... [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Listening on udev Control Socket. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Created slice system-sshd\x2dkeygen.slice. Starting Remount Root and Kernel File Systems... [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd Root File System. [ OK ] Listening on udev Kernel Socket. Starting udev Coldplug all Devices... [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Reached target RPC Port Mapper. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Reached target Local Encrypted Volumes. Mounting POSIX Message Queue File System... [ OK ] Reached target rpc_pipefs.target. Activating swap /dev/disk/by-label/SWAP... [ OK ] Created slice User and Session Slice. [ OK ] Reached target Slices. [ OK ] Reached target Paths. [ OK ] Listening on initctl Compatibility Named Pipe. Starting Apply Kernel Variables... [ 13.224343] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS Mounting Huge Pages File System... [ OK ] Stopped target Initrd File Systems. [ OK ] Listening on Process Core Dump Socket. [ OK ] Started Journal Service. [ OK ] Mounted Kernel Debug File System. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Started Apply Kernel Variables. [ OK ] Mounted Huge Pages File System. [ OK ] Reached target Swap. Starting Configure read-only root support... Starting Create Static Device Nodes in /dev... Starting Flush Journal to Persistent Storage... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started udev Coldplug all Devices. [ 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 ] Mounted /mnt. [ 13.650573] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 14.075086] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 14.098962] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 14.275506] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 14.301956] EDAC sbridge: Ver: 1.1.2 [ 16.579527] Key type dns_resolver registered [ 17.469865] NFS: Registering the id_resolver key type [ 17.475381] Key type id_resolver registered [ 17.478249] 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 Load/Save Random Seed. [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Create Volatile Files and Directories. Starting RPC Bind... Starting Update UTMP about System Boot/Shutdown... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Started dnf makecache --timer. [ OK ] Reached target Timers. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. Starting Restore /run/initramfs on shutdown... [ OK ] Started D-Bus System Message Bus. Starting Network Manager... [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Started irqbalance daemon. Starting Login Service... [ OK ] Reached target sshd-keygen.target. [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Network Manager. [ OK ] Reached target Network. Starting Dynamic System Tuning Daemon... Starting OpenSSH server daemon... Starting GSSAPI Proxy Daemon... Starting Network Manager Wait Online... [ OK ] Started Login Service. Starting Hostname Service... [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... [ OK ] Started OpenSSH server daemon. [ OK ] Started Permit User Sessions. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Command Scheduler. [ OK ] Started Getty on tty1. [ OK ] Started Serial Getty on ttyS1. [ OK ] Reached target Login Prompts. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting Crash recovery kernel arming... Starting Notify NFS peers of a restart... Starting System Logging Service... [ OK ] Started Notify NFS peers of a restart. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg243-server login: [ 34.819755] hrtimer: interrupt took 7743494 ns [ 91.270528] libcfs: loading out-of-tree module taints kernel. [ 91.312245] Key type ._llcrypt registered [ 91.315354] Key type .llcrypt registered [ 91.441577] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_hostid [ 112.037346] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing load_modules_local [ 113.842071] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 113.881260] alg: No test for adler32 (adler32-zlib) [ 115.637586] Lustre: Lustre: Build Version: 2.17.58_40_g869f601 [ 116.923738] LNet: Added LNI 192.168.202.143@tcp [8/256/0/180] [ 118.743230] Key type lgssc registered [ 120.949817] Lustre: Echo OBD driver; http://www.lustre.org/ [ 141.936138] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 192.663661] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing load_modules_local [ 207.105756] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 207.145365] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 208.510217] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 208.568580] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 208.656483] Lustre: lustre-MDT0000: new disk, initializing [ 208.721041] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 208.736643] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 213.879719] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 228.814880] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 228.919334] Lustre: 6509: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 [ 228.950868] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 228.955197] Lustre: Skipped 1 previous similar message [ 229.078971] Lustre: lustre-MDT0001: new disk, initializing [ 229.191198] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 229.253985] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 229.260651] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 234.492579] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 239.973781] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 251.076948] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 251.393542] Lustre: lustre-OST0000: new disk, initializing [ 251.404944] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 251.411121] Lustre: 8446:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 251.484306] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 258.091256] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 258.109361] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 258.217270] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 258.647452] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 275.981173] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 276.168022] Lustre: lustre-OST0001: new disk, initializing [ 276.172407] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 276.178942] Lustre: 9517:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 276.255595] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 283.074687] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 283.720994] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 283.738877] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 283.807392] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 296.423803] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 307.413443] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 314.830626] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing check_logdir /tmp/testlogs/ [ 321.688666] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing yml_node [ 326.760718] Lustre: DEBUG MARKER: Client: 2.17.58.40 [ 329.481309] Lustre: DEBUG MARKER: MDS: 2.17.58.40 [ 332.202409] Lustre: DEBUG MARKER: OSS: 2.17.58.40 [ 333.988604] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity-lfsck ============----- Sun Sep 6 21:30:33 EDT 2026 [ 353.979254] Lustre: DEBUG MARKER: excepting tests: 18b 23b [ 367.128495] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing load_modules_local [ 376.290079] 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 [ 376.291727] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 376.313041] Lustre: Skipped 2 previous similar messages [ 376.322925] Lustre: Skipped 3 previous similar messages [ 381.471573] Lustre: server umount lustre-MDT0000 complete [ 386.528965] LustreError: 6517:0:(ldlm_lib.c:1202: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. [ 386.545582] LustreError: 6517:0:(ldlm_lib.c:1202:target_handle_connect()) Skipped 8 previous similar messages [ 391.176267] LustreError: 6502:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788744692 with bad export cookie 11550092987920491098 [ 391.178663] LustreError: MGC192.168.202.143@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 391.190241] LustreError: 6502:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 391.649700] LustreError: 6515:0:(ldlm_lib.c:1202: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. [ 391.679054] 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 [ 391.694481] Lustre: Skipped 1 previous similar message [ 391.894459] Lustre: server umount lustre-MDT0001 complete [ 403.374188] Lustre: server umount lustre-OST0000 complete [ 413.224802] Lustre: server umount lustre-OST0001 complete [ 432.428441] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing unload_modules_local [ 435.572617] Key type lgssc unregistered [ 435.912191] LNet: 14793:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 435.922361] LNetError: 14793:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 435.939650] LNet: Removed LNI 192.168.202.143@tcp [ 437.139424] Key type .llcrypt unregistered [ 437.144592] Key type ._llcrypt unregistered [ 463.378651] Key type ._llcrypt registered [ 463.385449] Key type .llcrypt registered [ 463.563744] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_hostid [ 480.815656] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing load_modules_local [ 482.004356] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 482.196756] alg: No test for adler32 (adler32-zlib) [ 483.340340] Lustre: Lustre: Build Version: 2.17.58_40_g869f601 [ 483.665768] LNet: Added LNI 192.168.202.143@tcp [8/256/0/180] [ 485.384723] Key type lgssc registered [ 486.654820] Lustre: Echo OBD driver; http://www.lustre.org/ [ 541.837826] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing load_modules_local [ 559.585548] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 559.634619] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 561.016669] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 561.059235] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 561.177563] Lustre: lustre-MDT0000: new disk, initializing [ 561.306034] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 561.336224] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 566.107584] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 582.893511] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 583.067878] Lustre: 19249: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 [ 583.097382] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 583.102342] Lustre: Skipped 1 previous similar message [ 583.273075] Lustre: lustre-MDT0001: new disk, initializing [ 583.404651] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 583.465474] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 583.482542] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 590.672557] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 597.089874] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 607.010600] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 607.350507] Lustre: lustre-OST0000: new disk, initializing [ 607.354888] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 607.363454] Lustre: 21191:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 607.492872] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 608.654977] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 608.667565] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 608.736157] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 614.298545] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 630.214148] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 630.360486] Lustre: lustre-OST0001: new disk, initializing [ 630.363929] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 630.370073] Lustre: 22215:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 630.438881] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 638.498712] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 639.606491] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 639.623971] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 639.728056] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 651.725524] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 663.034538] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 672.006202] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 21:36:11 (1788744971) === [ 674.655788] Lustre: DEBUG MARKER: == sanity-lfsck test 0: Control LFSCK manually =========== 21:36:15 (1788744975) [ 674.792050] Lustre: 19258:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 251 < left 278, rollback = 2 [ 674.803238] Lustre: 19258:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 674.810396] Lustre: 19258:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 674.819120] Lustre: 19258:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 674.828275] Lustre: 19258:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 674.834661] Lustre: 19258:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 675.318828] Lustre: 19256:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 675.326758] Lustre: 19256:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 14 previous similar messages [ 675.332986] Lustre: 19256:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 675.337938] Lustre: 19256:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 14 previous similar messages [ 675.347738] Lustre: 19256:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 675.358607] Lustre: 19256:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 14 previous similar messages [ 675.365309] Lustre: 19256:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 675.370988] Lustre: 19256:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 14 previous similar messages [ 675.378276] Lustre: 19256:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 675.383086] Lustre: 19256:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 14 previous similar messages [ 675.387228] Lustre: 19256:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 675.390423] Lustre: 19256:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 14 previous similar messages [ 676.324684] Lustre: 19256:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 676.339883] Lustre: 19256:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 59 previous similar messages [ 676.351251] Lustre: 19256:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 676.360633] Lustre: 19256:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 59 previous similar messages [ 676.367531] Lustre: 19256:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 676.370943] Lustre: 19256:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 59 previous similar messages [ 676.376287] Lustre: 19256:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 676.381672] Lustre: 19256:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 59 previous similar messages [ 676.387300] Lustre: 19256:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 676.394236] Lustre: 19256:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 59 previous similar messages [ 676.399672] Lustre: 19256:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 676.404503] Lustre: 19256:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 59 previous similar messages [ 678.327100] Lustre: 19256:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 678.334497] Lustre: 19256:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 98 previous similar messages [ 678.405916] Lustre: 19258:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 678.411053] Lustre: 19258:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 101 previous similar messages [ 678.416195] Lustre: 19258:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 678.421301] Lustre: 19258:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 101 previous similar messages [ 678.426816] Lustre: 19258:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 678.433693] Lustre: 19258:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 101 previous similar messages [ 678.440415] Lustre: 19258:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 678.446836] Lustre: 19258:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 101 previous similar messages [ 678.451447] Lustre: 19258:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 678.456242] Lustre: 19258:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 101 previous similar messages [ 682.339233] Lustre: *** cfs_fail_loc=1600, val=3*** [ 685.360281] Lustre: 21178:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 260 < left 274, rollback = 2 [ 685.365272] Lustre: 21179:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 685.381291] Lustre: 21178:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 106 previous similar messages [ 685.392540] Lustre: 21179:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 102 previous similar messages [ 685.392564] Lustre: 21179:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/1, xattr_set: 2/274/0 [ 685.392567] Lustre: 21179:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 102 previous similar messages [ 685.392573] Lustre: 21179:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 0/0/0, punch: 0/0/0, quota 7/225/0 [ 685.392576] Lustre: 21179:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 102 previous similar messages [ 685.392581] Lustre: 21179:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 685.392584] Lustre: 21179:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 102 previous similar messages [ 685.392589] Lustre: 21179:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 685.392591] Lustre: 21179:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 102 previous similar messages [ 685.412506] Lustre: *** cfs_fail_loc=1600, val=3*** [ 687.477746] Lustre: *** cfs_fail_loc=1600, val=3*** [ 706.529982] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 706.532559] 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 [ 706.536411] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 706.553717] Lustre: Skipped 1 previous similar message [ 711.659183] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 711.662339] Lustre: Skipped 6 previous similar messages [ 716.771541] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 716.781761] Lustre: Skipped 3 previous similar messages [ 717.279161] Lustre: lustre-MDT0000 is waiting for obd_unlinked_exports more than 8 seconds. The obd refcount = 3. Is it stuck? [ 717.865097] Lustre: server umount lustre-MDT0000 complete [ 722.772898] LustreError: 19242:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788745023 with bad export cookie 16136216582742831 [ 722.787548] LustreError: MGC192.168.202.143@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 723.200154] Lustre: server umount lustre-MDT0001 complete [ 738.363291] Lustre: server umount lustre-OST0000 complete [ 753.571735] Lustre: server umount lustre-OST0001 complete [ 763.363684] Lustre: DEBUG MARKER: == sanity-lfsck test 1a: LFSCK can find out and repair crashed FID-in-dirent ========================================================== 21:37:42 (1788745062) [ 780.322529] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing load_modules_local [ 792.524666] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 792.977413] LustreError: 26227:0:(ldlm_lib.c:1202: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. [ 793.010306] LustreError: 26227:0:(ldlm_lib.c:1202:target_handle_connect()) Skipped 5 previous similar messages [ 793.127738] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 798.177014] LustreError: 26228:0:(ldlm_lib.c:1202: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. [ 798.192769] LustreError: 26228:0:(ldlm_lib.c:1202:target_handle_connect()) Skipped 1 previous similar message [ 798.584592] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 803.302076] LustreError: 26227:0:(ldlm_lib.c:1202: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. [ 808.417850] LustreError: 26228:0:(ldlm_lib.c:1202: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. [ 808.869519] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 809.395758] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 814.307439] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 818.081406] Lustre: 27368:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 825.860902] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 826.288266] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 834.486258] LustreError: 27720:0:(ldlm_lib.c:1202: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. [ 834.634858] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 838.568136] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:41 to 0x280000401:65) [ 843.747080] LustreError: 27720:0:(ldlm_lib.c:1202: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. [ 843.760744] LustreError: 27720:0:(ldlm_lib.c:1202:target_handle_connect()) Skipped 2 previous similar messages [ 845.803803] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 851.446458] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:40 to 0x2c0000401:65) [ 854.176743] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 863.170324] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 867.251857] Lustre: 29242:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 868.718136] Lustre: 26224:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 868.723972] Lustre: 26224:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 63 previous similar messages [ 868.728909] Lustre: 26224:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 868.733436] Lustre: 26224:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 66 previous similar messages [ 868.738420] Lustre: 26224:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 868.747519] Lustre: 26224:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 66 previous similar messages [ 868.751611] Lustre: 26224:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 868.756866] Lustre: 26224:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 66 previous similar messages [ 868.761417] Lustre: 26224:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 868.771323] Lustre: 26224:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 66 previous similar messages [ 868.775946] Lustre: 26224:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 868.780514] Lustre: 26224:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 66 previous similar messages [ 873.905539] Lustre: *** cfs_fail_loc=1501, val=0*** [ 882.674041] Lustre: Failing over lustre-MDT0000 [ 883.090187] Lustre: server umount lustre-MDT0000 complete [ 886.239863] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 886.249611] Lustre: lustre-MDT0000-osp-MDT0001: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 886.262166] Lustre: Skipped 2 previous similar messages [ 886.271157] LustreError: 26228:0:(ldlm_lib.c:1202:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 886.296071] LustreError: 26228:0:(ldlm_lib.c:1202:target_handle_connect()) Skipped 1 previous similar message [ 887.266904] 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 [ 887.295142] Lustre: Skipped 2 previous similar messages [ 895.379578] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 895.589334] LustreError: MGC192.168.202.143@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 896.025945] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 896.034183] Lustre: Skipped 1 previous similar message [ 896.081092] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 901.098022] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 901.099291] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 901.144804] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 901.222963] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:105 to 0x2c0000401:129) [ 901.228119] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:105 to 0x280000401:129) [ 901.335712] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 904.664130] Lustre: *** cfs_fail_loc=1505, val=0*** [ 915.082681] Lustre: DEBUG MARKER: == sanity-lfsck test 1b: LFSCK can find out and repair the missing FID-in-LMA ========================================================== 21:40:14 (1788745214) [ 917.169866] Lustre: 28755:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 256 < left 278, rollback = 2 [ 917.189072] Lustre: 28755:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 322 previous similar messages [ 917.196824] Lustre: 28755:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 917.209032] Lustre: 28755:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 917.227320] Lustre: 28755:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 917.234812] Lustre: 28755:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 917.247532] Lustre: 28755:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 917.256582] Lustre: 28755:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 917.269069] Lustre: 28755:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 917.279902] Lustre: 28755:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 917.292601] Lustre: 28755:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 917.299300] Lustre: 28755:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 923.541951] Lustre: *** cfs_fail_loc=1502, val=0*** [ 934.623054] Lustre: Failing over lustre-MDT0000 [ 935.002808] Lustre: server umount lustre-MDT0000 complete [ 936.928615] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 936.931360] 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 [ 936.941161] LustreError: 26224:0:(ldlm_lib.c:1202: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. [ 936.941174] LustreError: 26224:0:(ldlm_lib.c:1202:target_handle_connect()) Skipped 8 previous similar messages [ 937.014611] Lustre: Skipped 3 previous similar messages [ 946.955321] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 947.166785] LustreError: MGC192.168.202.143@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 947.182325] LustreError: 16405:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff958d4d2adf80 x1875634850907648/t0(0) o250->MGC192.168.202.143@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 [ 947.438088] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 952.809867] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 952.819043] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 952.834426] Lustre: Skipped 3 previous similar messages [ 952.872975] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 952.961453] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:169 to 0x2c0000401:193) [ 952.992889] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:169 to 0x280000401:193) [ 953.001618] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 956.883818] Lustre: *** cfs_fail_loc=1505, val=0*** [ 965.479564] Lustre: DEBUG MARKER: == sanity-lfsck test 1c: LFSCK can find out and repair lost FID-in-dirent ========================================================== 21:41:05 (1788745265) [ 967.186286] Lustre: 28755:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 256 < left 278, rollback = 2 [ 967.193766] Lustre: 28755:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 322 previous similar messages [ 967.198351] Lustre: 28755:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 967.202906] Lustre: 28755:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 967.207628] Lustre: 28755:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 967.212955] Lustre: 28755:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 967.215815] Lustre: 28755:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 967.225259] Lustre: 28755:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 967.230924] Lustre: 28755:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 967.234807] Lustre: 28755:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 967.239319] Lustre: 28755:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 967.243927] Lustre: 28755:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 972.861601] Lustre: *** cfs_fail_loc=1504, val=0*** [ 972.863807] Lustre: *** cfs_fail_loc=1504, val=0*** [ 972.870843] Lustre: Skipped 1 previous similar message [ 981.238597] Lustre: Failing over lustre-MDT0000 [ 981.629826] Lustre: server umount lustre-MDT0000 complete [ 983.521278] 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 [ 983.557799] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 993.387414] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 993.482178] LustreError: MGC192.168.202.143@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 993.716572] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 993.720685] Lustre: Skipped 1 previous similar message [ 993.751731] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 998.432111] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 998.912054] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 998.920762] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 998.931871] Lustre: Skipped 3 previous similar messages [ 998.981615] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 999.041441] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:233 to 0x2c0000401:257) [ 999.053171] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:233 to 0x280000401:257) [ 1001.998479] Lustre: *** cfs_fail_loc=1505, val=0*** [ 1010.525082] Lustre: DEBUG MARKER: == sanity-lfsck test 2a: LFSCK can find out and repair crashed linkEA entry ========================================================== 21:41:50 (1788745310) [ 1016.669810] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1025.678908] Lustre: Failing over lustre-MDT0000 [ 1026.014021] Lustre: server umount lustre-MDT0000 complete [ 1029.600489] 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 [ 1029.608119] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1029.623734] Lustre: Skipped 5 previous similar messages [ 1029.623912] LustreError: 28755:0:(ldlm_lib.c:1202: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. [ 1029.623919] LustreError: 28755:0:(ldlm_lib.c:1202:target_handle_connect()) Skipped 19 previous similar messages [ 1036.800187] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1036.944201] LustreError: MGC192.168.202.143@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1037.246843] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1041.436832] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1042.402109] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1042.410953] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1042.426838] Lustre: Skipped 3 previous similar messages [ 1042.457758] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1042.504702] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:297 to 0x280000401:321) [ 1042.504753] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:297 to 0x2c0000401:321) [ 1051.306354] Lustre: DEBUG MARKER: == sanity-lfsck test 2b: LFSCK can find out and remove invalid linkEA entry ========================================================== 21:42:31 (1788745351) [ 1052.644757] Lustre: 26222:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 1052.652293] Lustre: 26222:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 644 previous similar messages [ 1052.659167] Lustre: 26222:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 1052.663687] Lustre: 26222:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 1052.670546] Lustre: 26222:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 1052.677485] Lustre: 26222:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 1052.685287] Lustre: 26222:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 1052.694414] Lustre: 26222:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 1052.702716] Lustre: 26222:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 1052.711371] Lustre: 26222:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 1052.716837] Lustre: 26222:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 1052.727187] Lustre: 26222:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 1057.939307] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1066.734177] Lustre: Failing over lustre-MDT0000 [ 1067.149777] Lustre: server umount lustre-MDT0000 complete [ 1068.000616] 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 [ 1068.015364] Lustre: Skipped 4 previous similar messages [ 1079.273571] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1079.413867] LustreError: MGC192.168.202.143@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1079.826413] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1084.462800] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1084.898223] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1084.898831] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1084.898837] Lustre: Skipped 3 previous similar messages [ 1084.950199] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1085.018312] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:361 to 0x2c0000401:385) [ 1085.019718] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:361 to 0x280000401:385) [ 1093.863695] Lustre: DEBUG MARKER: == sanity-lfsck test 2c: LFSCK can find out and remove repeated linkEA entry ========================================================== 21:43:13 (1788745393) [ 1101.472323] Lustre: *** cfs_fail_loc=1605, val=0*** [ 1110.413029] Lustre: Failing over lustre-MDT0000 [ 1110.508118] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1110.507699] 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 [ 1110.524825] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1110.541363] Lustre: Skipped 3 previous similar messages [ 1112.656165] Lustre: server umount lustre-MDT0000 complete [ 1124.298569] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1124.450928] LustreError: MGC192.168.202.143@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1124.642108] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1124.653053] Lustre: Skipped 2 previous similar messages [ 1124.681646] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1129.952541] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1129.986528] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1129.996951] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1130.012147] Lustre: Skipped 3 previous similar messages [ 1130.067570] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1130.141626] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:425 to 0x2c0000401:449) [ 1130.145397] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:425 to 0x280000401:449) [ 1144.945084] Lustre: DEBUG MARKER: == sanity-lfsck test 2d: LFSCK can recover the missing linkEA entry ========================================================== 21:44:04 (1788745444) [ 1153.383158] Lustre: *** cfs_fail_loc=161d, val=0*** [ 1163.197748] Lustre: Failing over lustre-MDT0000 [ 1163.736076] Lustre: server umount lustre-MDT0000 complete [ 1165.793514] LustreError: 26961:0:(ldlm_lib.c:1202: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. [ 1165.824024] LustreError: 26961:0:(ldlm_lib.c:1202:target_handle_connect()) Skipped 30 previous similar messages [ 1176.203923] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1176.551574] LustreError: MGC192.168.202.143@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1177.021598] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1182.188343] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1182.210719] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1182.214783] Lustre: Skipped 3 previous similar messages [ 1182.250153] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1182.297327] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:489 to 0x2c0000401:513) [ 1182.309456] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:489 to 0x280000401:513) [ 1183.233704] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1194.626220] Lustre: DEBUG MARKER: == sanity-lfsck test 2e: namespace LFSCK can verify remote object linkEA ========================================================== 21:44:53 (1788745493) [ 1196.636702] Lustre: 26222:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 256 < left 278, rollback = 2 [ 1196.648647] Lustre: 26222:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 967 previous similar messages [ 1196.667172] Lustre: 26222:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 1196.677962] Lustre: 26222:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 966 previous similar messages [ 1196.691247] Lustre: 26222:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 1196.702735] Lustre: 26222:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 967 previous similar messages [ 1196.713993] Lustre: 26222:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 1196.721637] Lustre: 26222:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 967 previous similar messages [ 1196.732143] Lustre: 26222:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 1196.738133] Lustre: 26222:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 967 previous similar messages [ 1196.745341] Lustre: 26222:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 1196.750533] Lustre: 26222:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 967 previous similar messages [ 1198.578205] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1217.018413] Lustre: DEBUG MARKER: == sanity-lfsck test 3: LFSCK can verify multiple-linked objects ========================================================== 21:45:15 (1788745515) [ 1224.427699] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1225.485451] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1236.505790] Lustre: DEBUG MARKER: == sanity-lfsck test 4: FID-in-dirent can be rebuilt after MDT file-level backup/restore ========================================================== 21:45:36 (1788745536) [ 1272.430588] Lustre: Failing over lustre-MDT0000 [ 1272.677035] Lustre: server umount lustre-MDT0000 complete [ 1274.337384] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1274.342331] 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 [ 1274.399619] Lustre: Skipped 7 previous similar messages [ 1280.863753] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1290.724702] Lustre: 16409:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788745575/real 1788745575] req@ffff958e807e3480 x1875634851374208/t0(0) o400->MGC192.168.202.143@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1788745591 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1290.770963] LustreError: MGC192.168.202.143@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1291.513028] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1302.420357] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1302.457845] Lustre: lustre-MDT0000: reset Object Index mappings [ 1315.300657] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x3953cdb170f958 [ 1315.314302] Lustre: MGC192.168.202.143@tcp: Connection restored to 0@lo (at 0@lo) [ 1315.319773] Lustre: Skipped 3 previous similar messages [ 1315.703807] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1320.940182] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1321.002380] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1321.097527] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:592 to 0x2c0000401:609) [ 1321.098482] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:592 to 0x280000401:609) [ 1321.991473] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1326.010507] LustreError: 42900:0:(lfsck_engine.c:1018:lfsck_master_engine()) lustre-MDT0000-osd: master engine fail to verify the .lustre/lost+found/, go ahead: rc = -115 [ 1326.036333] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1327.072204] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1328.095241] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1330.145271] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1330.151456] Lustre: Skipped 1 previous similar message [ 1334.727827] Lustre: Failing over lustre-MDT0000 [ 1334.985508] Lustre: server umount lustre-MDT0000 complete [ 1344.523192] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1349.611778] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1350.168215] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:592 to 0x2c0000401:641) [ 1350.172910] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:592 to 0x280000401:641) [ 1352.930516] Lustre: *** cfs_fail_loc=1505, val=0*** [ 1359.521523] Lustre: DEBUG MARKER: == sanity-lfsck test 5: LFSCK can handle IGIF object upgrading ========================================================== 21:47:39 (1788745659) [ 1362.418403] Lustre: *** cfs_fail_loc=1504, val=0*** [ 1370.459103] Lustre: Failing over lustre-MDT0000 [ 1370.592932] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1370.604597] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1370.611543] Lustre: Skipped 6 previous similar messages [ 1375.841321] Lustre: server umount lustre-MDT0000 complete [ 1380.713235] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1390.706229] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1397.215592] Lustre: 16406:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788745681/real 1788745681] req@ffff958e659f3b80 x1875634851473024/t0(0) o400->MGC192.168.202.143@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1788745697 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1402.869921] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1402.893864] Lustre: lustre-MDT0000: reset Object Index mappings [ 1407.463508] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x3953cdb17137e1 [ 1407.480522] Lustre: MGC192.168.202.143@tcp: Connection restored to 0@lo (at 0@lo) [ 1407.503819] Lustre: Skipped 8 previous similar messages [ 1407.845899] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1407.848390] Lustre: Skipped 3 previous similar messages [ 1407.901401] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1407.906373] Lustre: Skipped 1 previous similar message [ 1413.088654] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1413.096979] Lustre: Skipped 1 previous similar message [ 1413.120882] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1413.135717] Lustre: Skipped 1 previous similar message [ 1413.176180] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:681 to 0x2c0000401:705) [ 1413.178448] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:681 to 0x280000401:705) [ 1414.263689] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1419.255221] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1427.488180] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1427.490896] Lustre: Skipped 7 previous similar messages [ 1435.172793] Lustre: Failing over lustre-MDT0000 [ 1435.429551] Lustre: server umount lustre-MDT0000 complete [ 1438.694219] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1438.704614] 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 [ 1438.711427] LustreError: 28755:0:(ldlm_lib.c:1202: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. [ 1438.720212] Lustre: Skipped 11 previous similar messages [ 1438.750034] LustreError: 28755:0:(ldlm_lib.c:1202:target_handle_connect()) Skipped 87 previous similar messages [ 1447.831995] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1448.013462] LustreError: MGC192.168.202.143@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1448.019927] LustreError: Skipped 2 previous similar messages [ 1452.999371] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1453.595238] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:681 to 0x280000401:737) [ 1453.597709] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:681 to 0x2c0000401:737) [ 1457.004421] Lustre: *** cfs_fail_loc=1505, val=0*** [ 1457.021144] Lustre: Skipped 84 previous similar messages [ 1464.481693] Lustre: DEBUG MARKER: == sanity-lfsck test 6a: LFSCK resumes from last checkpoint (1) ========================================================== 21:49:24 (1788745764) [ 1465.794706] Lustre: 40003:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 256 < left 278, rollback = 2 [ 1465.803863] Lustre: 40003:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 964 previous similar messages [ 1465.812992] Lustre: 40003:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 1465.822060] Lustre: 40003:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 964 previous similar messages [ 1465.834256] Lustre: 40003:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 1465.843231] Lustre: 40003:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 964 previous similar messages [ 1465.853315] Lustre: 40003:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 1465.861228] Lustre: 40003:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 964 previous similar messages [ 1465.871746] Lustre: 40003:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 1465.876096] Lustre: 40003:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 964 previous similar messages [ 1465.879965] Lustre: 40003:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 1465.882609] Lustre: 40003:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 964 previous similar messages [ 1473.262976] Lustre: *** cfs_fail_loc=1600, val=1*** [ 1473.269450] Lustre: Skipped 2 previous similar messages [ 1495.381130] Lustre: DEBUG MARKER: == sanity-lfsck test 6b: LFSCK resumes from last checkpoint (2) ========================================================== 21:49:54 (1788745794) [ 1505.503185] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1505.510244] Lustre: Skipped 10 previous similar messages [ 1535.762659] Lustre: DEBUG MARKER: == sanity-lfsck test 7a: non-stopped LFSCK should auto restarts after MDS remount (1) ========================================================== 21:50:35 (1788745835) [ 1555.803468] Lustre: Failing over lustre-MDT0000 [ 1555.947191] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1555.958873] Lustre: Skipped 7 previous similar messages [ 1556.413805] Lustre: server umount lustre-MDT0000 complete [ 1568.853708] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1569.385207] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1569.400889] Lustre: Skipped 1 previous similar message [ 1574.373980] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1574.375283] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1574.385796] Lustre: Skipped 1 previous similar message [ 1574.406864] Lustre: Skipped 8 previous similar messages [ 1574.427332] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1574.439273] Lustre: Skipped 1 previous similar message [ 1574.542567] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:854 to 0x280000401:897) [ 1574.546633] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:853 to 0x2c0000401:897) [ 1574.782652] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1585.540524] Lustre: DEBUG MARKER: == sanity-lfsck test 7b: non-stopped LFSCK should auto restarts after MDS remount (2) ========================================================== 21:51:25 (1788745885) [ 1601.367904] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing load_modules_local [ 1626.210614] Lustre: 52989:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 1650.045287] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1654.222867] Lustre: 54124:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 1663.253839] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1663.256804] Lustre: Skipped 81 previous similar messages [ 1666.505899] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1667.552860] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1668.576756] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1670.624093] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1670.636243] Lustre: Skipped 1 previous similar message [ 1673.286269] Lustre: Failing over lustre-MDT0000 [ 1673.754617] Lustre: server umount lustre-MDT0000 complete [ 1676.785366] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1676.803152] LustreError: Skipped 1 previous similar message [ 1684.793895] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1690.583466] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1690.654335] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:947 to 0x280000401:993) [ 1690.661350] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:946 to 0x2c0000401:961) [ 1699.513034] Lustre: DEBUG MARKER: == sanity-lfsck test 8: LFSCK state machine ============== 21:53:19 (1788745999) [ 1705.954235] 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 [ 1705.956986] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1705.986325] Lustre: Skipped 10 previous similar messages [ 1706.004414] Lustre: Skipped 3 previous similar messages [ 1707.954730] Lustre: server umount lustre-MDT0000 complete [ 1712.113226] LustreError: 27746:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788746013 with bad export cookie 16136216582955806 [ 1712.119488] LustreError: MGC192.168.202.143@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1712.124784] LustreError: 27746:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 1712.139948] LustreError: Skipped 2 previous similar messages [ 1712.424877] Lustre: server umount lustre-MDT0001 complete [ 1726.790311] Lustre: server umount lustre-OST0000 complete [ 1740.803660] Lustre: server umount lustre-OST0001 complete [ 1748.659467] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_hostid [ 1758.556101] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing load_modules_local [ 1804.000860] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing load_modules_local [ 1814.141404] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1814.397166] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 1814.445417] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 1814.541372] Lustre: lustre-MDT0000: new disk, initializing [ 1814.631511] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 1819.642689] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1831.099370] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1831.221516] Lustre: 59184: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 [ 1831.259357] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 1831.263452] Lustre: Skipped 1 previous similar message [ 1831.387578] Lustre: lustre-MDT0001: new disk, initializing [ 1831.504523] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 1831.530814] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 1836.338638] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1841.081596] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 1848.239495] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 1848.500376] Lustre: lustre-OST0000: new disk, initializing [ 1848.507163] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 1848.511348] Lustre: 60820:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 1850.270642] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 1850.276458] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 1850.368764] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 1855.645595] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1867.169705] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 1867.321755] Lustre: lustre-OST0001: new disk, initializing [ 1867.325364] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 1867.330378] Lustre: 61688:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 1868.790463] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 1868.799339] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 1868.906179] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 1874.212416] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1885.488951] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1889.776674] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 1900.992355] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1902.177370] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1902.185925] Lustre: Skipped 19 previous similar messages [ 1907.696399] Lustre: *** cfs_fail_loc=1601, val=2*** [ 1907.698473] Lustre: Skipped 21 previous similar messages [ 1924.472723] Lustre: Failing over lustre-MDT0000 [ 1924.763308] Lustre: server umount lustre-MDT0000 complete [ 1934.636926] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1935.046704] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1935.052643] Lustre: Skipped 7 previous similar messages [ 1935.105313] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1935.117175] Lustre: Skipped 1 previous similar message [ 1940.413274] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1940.455324] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1940.460873] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1940.470257] Lustre: Skipped 1 previous similar message [ 1940.493040] Lustre: Skipped 7 previous similar messages [ 1940.520989] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1940.533406] Lustre: Skipped 1 previous similar message [ 1940.556413] Lustre: *** cfs_fail_loc=160b, val=2*** [ 1940.567861] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:65) [ 1940.578983] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:65) [ 1948.434067] Lustre: Failing over lustre-MDT0000 [ 1948.842708] Lustre: server umount lustre-MDT0000 complete [ 1950.690885] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1950.699013] LustreError: Skipped 1 previous similar message [ 1955.811574] LustreError: 60072:0:(ldlm_lib.c:1202: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. [ 1955.825375] LustreError: 60072:0:(ldlm_lib.c:1202:target_handle_connect()) Skipped 39 previous similar messages [ 1959.017272] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1963.896665] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1964.575058] Lustre: *** cfs_fail_loc=160b, val=2*** [ 1964.610711] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:97) [ 1964.614223] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:97) [ 1970.137076] Lustre: Failing over lustre-MDT0000 [ 1970.440875] Lustre: server umount lustre-MDT0000 complete [ 1979.799466] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1985.205916] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1985.579203] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:129) [ 1985.581585] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:129) [ 1991.318174] Lustre: *** cfs_fail_loc=1602, val=2*** [ 1991.319940] Lustre: Skipped 2 previous similar messages [ 2005.451571] Lustre: DEBUG MARKER: == sanity-lfsck test 9a: LFSCK speed control (1) ========= 21:58:25 (1788746305) [ 2021.895227] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing load_modules_local [ 2046.070881] Lustre: 68661:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 2073.654532] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 2077.347694] Lustre: 69798:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 2085.588995] Lustre: 59193:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 2085.592346] Lustre: 59193:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 2795 previous similar messages [ 2085.596246] Lustre: 59193:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 2085.600228] Lustre: 59193:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 2795 previous similar messages [ 2085.603695] Lustre: 59193:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 2085.606977] Lustre: 59193:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 2795 previous similar messages [ 2085.609725] Lustre: 59193:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 2085.613563] Lustre: 59193:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 2795 previous similar messages [ 2085.618994] Lustre: 59193:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 2085.629580] Lustre: 59193:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 2795 previous similar messages [ 2085.635595] Lustre: 59193:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 2085.640529] Lustre: 59193:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 2795 previous similar messages [ 2193.549613] Lustre: DEBUG MARKER: == sanity-lfsck test 9b: LFSCK speed control (2) ========= 22:01:33 (1788746493) [ 2241.370132] Lustre: *** cfs_fail_loc=1604, val=0*** [ 2241.371954] Lustre: Skipped 4 previous similar messages [ 2267.232839] Lustre: *** cfs_fail_loc=160c, val=0*** [ 2267.235581] Lustre: Skipped 7 previous similar messages [ 2307.878587] Lustre: DEBUG MARKER: == sanity-lfsck test 10: System is available during LFSCK scanning ========================================================== 22:03:27 (1788746607) [ 2353.842890] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2354.899815] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2354.901824] Lustre: Skipped 50 previous similar messages [ 2356.912675] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2356.925502] Lustre: Skipped 111 previous similar messages [ 2360.916798] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2360.918435] Lustre: Skipped 222 previous similar messages [ 2368.931248] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2368.935818] Lustre: Skipped 460 previous similar messages [ 2384.952064] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2384.955441] Lustre: Skipped 820 previous similar messages [ 2416.964589] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2416.968504] Lustre: Skipped 1736 previous similar messages [ 2419.607970] Lustre: *** cfs_fail_loc=1604, val=0*** [ 2419.609791] Lustre: Skipped 2599 previous similar messages [ 2649.859707] Lustre: DEBUG MARKER: == sanity-lfsck test 11a: LFSCK can rebuild lost last_id ========================================================== 22:09:10 (1788746950) [ 2785.860284] Lustre: 59191:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 2785.874864] Lustre: 59191:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 36832 previous similar messages [ 2785.881309] Lustre: 59191:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 2785.892457] Lustre: 59191:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 36832 previous similar messages [ 2785.904195] Lustre: 59191:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 2785.912448] Lustre: 59191:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 36832 previous similar messages [ 2785.921649] Lustre: 59191:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 2785.929250] Lustre: 59191:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 36832 previous similar messages [ 2785.941425] Lustre: 59191:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 2785.951071] Lustre: 59191:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 36832 previous similar messages [ 2785.961716] Lustre: 59191:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 2785.968690] Lustre: 59191:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 36832 previous similar messages [ 2794.467453] 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 [ 2794.468904] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2794.488963] Lustre: Skipped 15 previous similar messages [ 2794.489769] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 2794.496896] Lustre: Skipped 2 previous similar messages [ 2794.515649] LustreError: Skipped 1 previous similar message [ 2798.131767] Lustre: server umount lustre-MDT0000 complete [ 2799.585640] LustreError: 59192:0:(ldlm_lib.c:1202: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. [ 2799.595277] LustreError: 59192:0:(ldlm_lib.c:1202:target_handle_connect()) Skipped 11 previous similar messages [ 2801.602152] LustreError: 73542:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788747102 with bad export cookie 16136216582974902 [ 2801.605160] LustreError: MGC192.168.202.143@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2801.613338] LustreError: 73542:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 2801.627556] LustreError: Skipped 3 previous similar messages [ 2801.863371] Lustre: server umount lustre-MDT0001 complete [ 2815.877732] Lustre: server umount lustre-OST0000 complete [ 2829.824535] Lustre: server umount lustre-OST0001 complete [ 2835.763748] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: (null) [ 2845.024900] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 2860.576177] LustreError: Failed to get MGS log lustre-sptlrpc and no local copy. [ 2865.695398] LustreError: 75057:0:(mgc_request.c:233:do_config_log_add()) MGC192.168.202.143@tcp: failed processing log, type 4: rc = -110 [ 2891.359331] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 2891.369076] Lustre: Skipped 2 previous similar messages [ 2896.829953] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2900.686518] Lustre: 75640:0:(ofd_dev.c:563:ofd_lfsck_out_notify()) lustre-OST0000: Found crashed LAST_ID, deny creating new OST-object on the device until the LAST_ID rebuilt successfully. [ 2900.713559] Lustre: *** cfs_fail_loc=160e, val=3*** [ 2903.789759] Lustre: 75640:0:(ofd_dev.c:575:ofd_lfsck_out_notify()) lustre-OST0000: Rebuilt crashed LAST_ID files successfully. [ 2917.789076] Lustre: DEBUG MARKER: == sanity-lfsck test 11b: LFSCK can rebuild crashed last_id ========================================================== 22:13:36 (1788747216) [ 2937.668260] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing load_modules_local [ 2951.512805] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2952.059824] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3272 to 0x280000401:3297) [ 2956.401634] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2965.096629] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2970.118780] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2973.975471] Lustre: 78311:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 2992.469435] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2997.773775] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3207 to 0x2c0000401:3233) [ 3001.621278] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3010.396087] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3014.382961] Lustre: 79810:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 3020.165443] Lustre: *** cfs_fail_loc=160d, val=0*** [ 3020.774926] Lustre: *** cfs_fail_loc=160d, val=0*** [ 3020.777139] Lustre: Skipped 3 previous similar messages [ 3027.989407] Lustre: Failing over lustre-OST0000 [ 3028.107558] Lustre: server umount lustre-OST0000 complete [ 3038.453756] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3038.826719] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 3038.848417] Lustre: Skipped 2 previous similar messages [ 3040.046904] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 3040.060580] Lustre: Skipped 2 previous similar messages [ 3040.079662] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 3040.082828] Lustre: lustre-OST0000-osc-MDT0001: Connection restored to 0@lo (at 0@lo) [ 3040.089269] Lustre: Skipped 2 previous similar messages [ 3040.091828] Lustre: *** cfs_fail_loc=215, val=0*** [ 3040.097160] Lustre: Skipped 11 previous similar messages [ 3040.122411] Lustre: Skipped 1 previous similar message [ 3044.968902] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3045.343641] Lustre: *** cfs_fail_loc=215, val=0*** [ 3048.175604] Lustre: 81210:0:(ofd_dev.c:563:ofd_lfsck_out_notify()) lustre-OST0000: Found crashed LAST_ID, deny creating new OST-object on the device until the LAST_ID rebuilt successfully. [ 3048.211144] Lustre: 81210:0:(ofd_dev.c:575:ofd_lfsck_out_notify()) lustre-OST0000: Rebuilt crashed LAST_ID files successfully. [ 3050.468504] Lustre: *** cfs_fail_loc=215, val=0*** [ 3050.471809] Lustre: Skipped 2 previous similar messages [ 3051.048644] Lustre: Failing over lustre-OST0000 [ 3051.180538] Lustre: server umount lustre-OST0000 complete [ 3060.538263] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3062.343818] Lustre: *** cfs_fail_loc=215, val=0*** [ 3062.350121] Lustre: Skipped 1 previous similar message [ 3067.359457] Lustre: *** cfs_fail_loc=215, val=0*** [ 3068.197610] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3076.064301] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3076.070813] Lustre: Skipped 4 previous similar messages [ 3086.321327] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3086.328907] Lustre: Skipped 7 previous similar messages [ 3089.375218] Lustre: lustre-MDT0000 is waiting for obd_unlinked_exports more than 8 seconds. The obd refcount = 3. Is it stuck? [ 3089.545937] Lustre: server umount lustre-MDT0000 complete [ 3093.731318] LustreError: 78313:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788747394 with bad export cookie 16136216584546647 [ 3093.762534] LustreError: 78313:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 3094.512067] Lustre: server umount lustre-MDT0001 complete [ 3108.930144] Lustre: server umount lustre-OST0000 complete [ 3123.038223] Lustre: server umount lustre-OST0001 complete [ 3131.801763] Lustre: DEBUG MARKER: == sanity-lfsck test 12a: single command to trigger LFSCK on all devices ========================================================== 22:17:12 (1788747432) [ 3145.977201] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing load_modules_local [ 3155.677198] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3159.477958] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3166.870402] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3171.234458] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3173.738407] Lustre: 85593:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3180.186246] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3181.482828] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3362 to 0x280000401:3393) [ 3187.420239] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3196.093717] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3201.513528] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3207 to 0x2c0000401:3265) [ 3202.096424] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3208.769533] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3212.062931] Lustre: 87461:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 3244.996419] Lustre: DEBUG MARKER: == sanity-lfsck test 12b: auto detect Lustre device ====== 22:19:04 (1788747544) [ 3259.417636] Lustre: DEBUG MARKER: == sanity-lfsck test 13: LFSCK can repair crashed lmm_oi ========================================================== 22:19:19 (1788747559) [ 3260.860761] Lustre: *** cfs_fail_loc=160f, val=0*** [ 3270.497743] Lustre: DEBUG MARKER: == sanity-lfsck test 14a: LFSCK can repair MDT-object with dangling LOV EA reference (1) ========================================================== 22:19:30 (1788747570) [ 3273.318975] Lustre: *** cfs_fail_loc=1610, val=0*** [ 3273.323311] Lustre: Skipped 3 previous similar messages [ 3319.266710] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3319.283400] Lustre: Skipped 3 previous similar messages [ 3326.611603] Lustre: server umount lustre-MDT0000 complete [ 3330.265551] LustreError: 84434:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788747631 with bad export cookie 16136216584555103 [ 3330.286377] LustreError: 84434:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 3330.489544] Lustre: server umount lustre-MDT0001 complete [ 3345.105962] Lustre: server umount lustre-OST0000 complete [ 3358.852858] Lustre: server umount lustre-OST0001 complete [ 3376.970860] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing load_modules_local [ 3390.447438] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3396.398365] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3401.714362] LustreError: 92188:0:(ldlm_lib.c:1202: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. [ 3401.743660] LustreError: 92188:0:(ldlm_lib.c:1202:target_handle_connect()) Skipped 51 previous similar messages [ 3405.612249] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3410.600838] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3413.648404] Lustre: 93328:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3420.721553] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3428.186774] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3430.455090] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:116 to 0x280000400:161) [ 3436.520749] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3554 to 0x280000401:3585) [ 3436.931459] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3442.180291] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3317 to 0x2c0000401:3361) [ 3442.313831] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:116 to 0x2c0000400:161) [ 3444.330575] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3452.567509] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3456.494846] Lustre: 95203:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 3464.576602] Lustre: DEBUG MARKER: == sanity-lfsck test 14b: LFSCK can repair MDT-object with dangling LOV EA reference (2) ========================================================== 22:22:44 (1788747764) [ 3466.851940] Lustre: 93217:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 256 < left 278, rollback = 2 [ 3466.859644] Lustre: 93217:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 1359 previous similar messages [ 3466.864283] Lustre: 93217:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 3466.869464] Lustre: 93217:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1359 previous similar messages [ 3466.874192] Lustre: 93217:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3466.877052] Lustre: 93217:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1359 previous similar messages [ 3466.881441] Lustre: 93217:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 3466.885713] Lustre: 93217:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1359 previous similar messages [ 3466.889995] Lustre: 93217:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 3466.898067] Lustre: 93217:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1359 previous similar messages [ 3466.903200] Lustre: 93217:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3466.907857] Lustre: 93217:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1359 previous similar messages [ 3470.552396] Lustre: *** cfs_fail_loc=1610, val=0*** [ 3470.554612] Lustre: Skipped 63 previous similar messages [ 3498.465850] 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 [ 3498.473819] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3498.479702] Lustre: Skipped 16 previous similar messages [ 3498.485070] Lustre: Skipped 6 previous similar messages [ 3504.700488] Lustre: server umount lustre-MDT0000 complete [ 3509.332742] LustreError: 92169:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788747810 with bad export cookie 16136216584583509 [ 3509.351531] LustreError: MGC192.168.202.143@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3509.355853] LustreError: 92169:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 3509.375029] LustreError: Skipped 2 previous similar messages [ 3510.062454] Lustre: server umount lustre-MDT0001 complete [ 3524.965172] Lustre: server umount lustre-OST0000 complete [ 3538.274562] Lustre: server umount lustre-OST0001 complete [ 3554.075238] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing load_modules_local [ 3565.161716] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3565.522844] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3565.537430] Lustre: Skipped 13 previous similar messages [ 3570.306530] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3578.517538] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3582.346263] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3585.235738] Lustre: 99239:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3591.795809] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3598.284429] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3603.330207] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:116 to 0x280000400:193) [ 3606.525807] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3610.801037] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3317 to 0x2c0000401:3393) [ 3610.808971] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3682 to 0x280000401:3713) [ 3610.823425] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:116 to 0x2c0000400:193) [ 3612.967770] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3620.160513] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3635.121468] Lustre: DEBUG MARKER: == sanity-lfsck test 15a: LFSCK can repair unmatched MDT-object/OST-object pairs (1) ========================================================== 22:25:34 (1788747934) [ 3641.221868] Lustre: *** cfs_fail_loc=1611, val=0*** [ 3641.291608] Lustre: *** cfs_fail_loc=1611, val=0*** [ 3641.293452] Lustre: Skipped 63 previous similar messages [ 3641.799984] Lustre: *** cfs_fail_loc=1611, val=0*** [ 3653.787219] Lustre: DEBUG MARKER: == sanity-lfsck test 15b: LFSCK can repair unmatched MDT-object/OST-object pairs (2) ========================================================== 22:25:53 (1788747953) [ 3656.154490] Lustre: *** cfs_fail_loc=1612, val=0*** [ 3656.245257] Lustre: *** cfs_fail_loc=1612, val=0*** [ 3656.251786] Lustre: Skipped 1 previous similar message [ 3666.636592] Lustre: DEBUG MARKER: == sanity-lfsck test 15c: LFSCK can repair unmatched MDT-object/OST-object pairs (3) ========================================================== 22:26:06 (1788747966) [ 3668.548130] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_15c MDS newer than 2.7.55, LU-6475 [ 3670.562967] Lustre: DEBUG MARKER: == sanity-lfsck test 15d: LFSCK don't crash upon dir migration failure ========================================================== 22:26:10 (1788747970) [ 3678.006801] Lustre: *** cfs_fail_loc=1709, val=0*** [ 3678.009306] LustreError: 98106:0:(osp_object.c:618:osp_attr_get()) lustre-MDT0000-osp-MDT0001: osp_attr_get update error [0x200003ab2:0x1:0x0]: rc = -5 [ 3678.045531] LustreError: 98106:0:(mdt_reint.c:2644:mdt_reint_migrate()) lustre-MDT0001: migrate [0x240002340:0x6c:0x0]/s78 failed: rc = -5 [ 3747.808838] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3747.817874] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3747.824760] Lustre: Skipped 4 previous similar messages [ 3751.517368] Lustre: server umount lustre-MDT0000 complete [ 3765.293313] LustreError: 98080:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788748066 with bad export cookie 16136216584598237 [ 3765.308128] LustreError: 98080:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 3765.518358] Lustre: server umount lustre-MDT0001 complete [ 3783.109595] Lustre: server umount lustre-OST0000 complete [ 3785.190269] Lustre: 16408:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788748070/real 1788748070] req@ffff958d4e9c9180 x1875634856704640/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788748086 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3786.213551] Lustre: 16406:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788748071/real 1788748071] req@ffff958d4e9c8e00 x1875634856704896/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788748087 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3790.303177] Lustre: 16407:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788748075/real 1788748075] req@ffff958d4e9cbb80 x1875634856705152/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788748091 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3792.297224] Lustre: server umount lustre-OST0001 complete [ 3812.046640] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing unload_modules_local [ 3815.498734] Key type lgssc unregistered [ 3815.837507] LNet: 104952:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 3815.853300] LNetError: 104952:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 3815.878135] LNet: Removed LNI 192.168.202.143@tcp [ 3817.024256] Key type .llcrypt unregistered [ 3817.026787] Key type ._llcrypt unregistered [ 3844.568849] Key type ._llcrypt registered [ 3844.570789] Key type .llcrypt registered [ 3844.678366] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_hostid [ 3860.027292] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing load_modules_local [ 3861.866907] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 3861.940279] alg: No test for adler32 (adler32-zlib) [ 3862.976666] Lustre: Lustre: Build Version: 2.17.58_40_g869f601 [ 3863.258657] LNet: Added LNI 192.168.202.143@tcp [8/256/0/180] [ 3864.993661] Key type lgssc registered [ 3866.231859] Lustre: Echo OBD driver; http://www.lustre.org/ [ 3923.740676] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing load_modules_local [ 3939.946837] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 3940.022867] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3941.469461] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 3941.520960] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 3941.778805] Lustre: lustre-MDT0000: new disk, initializing [ 3941.891851] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3941.912748] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 3947.324262] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3959.905515] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3960.027757] Lustre: 109402: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 [ 3960.069733] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 3960.078430] Lustre: Skipped 1 previous similar message [ 3960.206682] Lustre: lustre-MDT0001: new disk, initializing [ 3960.317291] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 3960.360698] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 3960.372098] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 3965.105375] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3970.972593] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 3981.898828] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3982.251749] Lustre: lustre-OST0000: new disk, initializing [ 3982.254133] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 3982.274145] Lustre: 111339:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 3982.398618] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 3989.027025] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 3989.045682] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 3989.191903] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 3991.033901] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4005.386885] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4005.510248] Lustre: lustre-OST0001: new disk, initializing [ 4005.513750] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 4005.524063] Lustre: 112368:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 4005.617332] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 4011.099791] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 4011.113568] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 4011.185602] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 4011.792758] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4021.842681] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4030.699317] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 4036.789618] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 22:32:16 (1788748336) === [ 4044.127700] Lustre: DEBUG MARKER: == sanity-lfsck test 16: LFSCK can repair inconsistent MDT-object/OST-object owner ========================================================== 22:32:23 (1788748343) [ 4044.401527] Lustre: 113157:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 251 < left 278, rollback = 2 [ 4044.412908] Lustre: 113157:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4044.422298] Lustre: 113157:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4044.442164] Lustre: 113157:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 4044.459512] Lustre: 113157:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 4044.465062] Lustre: 113157:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4044.921095] Lustre: 113157:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 4044.927264] Lustre: 113157:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 6 previous similar messages [ 4044.933391] Lustre: 113157:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 4044.938553] Lustre: 113157:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 6 previous similar messages [ 4044.942870] Lustre: 113157:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4044.947865] Lustre: 113157:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 6 previous similar messages [ 4044.952093] Lustre: 113157:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 4044.957488] Lustre: 113157:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 6 previous similar messages [ 4044.962923] Lustre: 113157:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 4044.969068] Lustre: 113157:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 6 previous similar messages [ 4044.974366] Lustre: 113157:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4044.978880] Lustre: 113157:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 6 previous similar messages [ 4045.938462] Lustre: 109409:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 4045.957137] Lustre: 109409:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 131 previous similar messages [ 4045.972517] Lustre: 109409:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 4045.986296] Lustre: 109409:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 131 previous similar messages [ 4045.994781] Lustre: 109409:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4046.016741] Lustre: 109409:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 131 previous similar messages [ 4046.035336] Lustre: 109409:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 7/369/0 [ 4046.051879] Lustre: 109409:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 131 previous similar messages [ 4046.064641] Lustre: 109409:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 4046.075569] Lustre: 109409:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 131 previous similar messages [ 4046.102787] Lustre: 109409:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 4046.110658] Lustre: 109409:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 131 previous similar messages [ 4048.340447] Lustre: *** cfs_fail_loc=1613, val=0*** [ 4063.554174] Lustre: DEBUG MARKER: == sanity-lfsck test 17: LFSCK can repair multiple references ========================================================== 22:32:42 (1788748362) [ 4064.856827] Lustre: 111346:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 257 < left 278, rollback = 2 [ 4064.860564] Lustre: 111346:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 170 previous similar messages [ 4064.863811] Lustre: 111346:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 4064.866689] Lustre: 111346:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 170 previous similar messages [ 4064.870276] Lustre: 111346:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4064.873045] Lustre: 111346:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 170 previous similar messages [ 4064.876315] Lustre: 111346:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 4064.878929] Lustre: 111346:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 170 previous similar messages [ 4064.881576] Lustre: 111346:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 4064.884118] Lustre: 111346:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 170 previous similar messages [ 4064.888298] Lustre: 111346:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4064.894636] Lustre: 111346:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 170 previous similar messages [ 4066.399558] Lustre: *** cfs_fail_loc=1614, val=0*** [ 4067.181056] Lustre: *** cfs_fail_loc=1614, val=103*** [ 4067.186444] Lustre: Skipped 1 previous similar message [ 4071.663195] Lustre: 111330:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 259 < left 275, rollback = 2 [ 4071.675143] Lustre: 111330:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 11 previous similar messages [ 4071.684932] Lustre: 111330:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 4071.696642] Lustre: 111330:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 4071.708497] Lustre: 111330:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/1, xattr_set: 3/275/0 [ 4071.713641] Lustre: 111330:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 4071.720586] Lustre: 111330:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/9/0, punch: 1/4/0, quota 7/225/0 [ 4071.734748] Lustre: 111330:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 4071.746622] Lustre: 111330:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 4071.754403] Lustre: 111330:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 4071.772566] Lustre: 111330:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 4071.782035] Lustre: 111330:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 4080.716689] Lustre: DEBUG MARKER: == sanity-lfsck test 18a: Find out orphan OST-object and repair it (1) ========================================================== 22:33:00 (1788748380) [ 4081.159416] Lustre: 109409:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 4081.174555] Lustre: 109409:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 1 previous similar message [ 4081.179765] Lustre: 109409:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 4081.190375] Lustre: 109409:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1 previous similar message [ 4081.203533] Lustre: 109409:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4081.217111] Lustre: 109409:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1 previous similar message [ 4081.228595] Lustre: 109409:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 4081.236660] Lustre: 109409:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1 previous similar message [ 4081.244496] Lustre: 109409:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 4081.252754] Lustre: 109409:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1 previous similar message [ 4081.265235] Lustre: 109409:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4081.274445] Lustre: 109409:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1 previous similar message [ 4083.913948] Lustre: *** cfs_fail_loc=1615, val=0*** [ 4083.916727] Lustre: Skipped 1 previous similar message [ 4084.963287] Lustre: *** cfs_fail_loc=1615, val=0*** [ 4084.965264] Lustre: Skipped 1 previous similar message [ 4103.599628] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_18b skipping excluded test 18b [ 4105.844768] Lustre: DEBUG MARKER: == sanity-lfsck test 18c: Find out orphan OST-object and repair it (3) ========================================================== 22:33:25 (1788748405) [ 4106.379177] Lustre: 109410:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 4106.383434] Lustre: 109410:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 21 previous similar messages [ 4106.386538] Lustre: 109410:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 4106.391199] Lustre: 109410:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4106.394362] Lustre: 109410:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4106.397210] Lustre: 109410:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4106.400945] Lustre: 109410:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 4106.408020] Lustre: 109410:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4106.412240] Lustre: 109410:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 4106.415789] Lustre: 109410:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4106.419634] Lustre: 109410:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4106.423532] Lustre: 109410:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4108.118584] Lustre: *** cfs_fail_loc=1617, val=0*** [ 4108.166411] Lustre: *** cfs_fail_loc=1617, val=0*** [ 4110.153178] Lustre: *** cfs_fail_loc=1616, val=0*** [ 4110.162670] Lustre: Skipped 3 previous similar messages [ 4130.671442] Lustre: DEBUG MARKER: == sanity-lfsck test 18d: Find out orphan OST-object and repair it (4) ========================================================== 22:33:50 (1788748430) [ 4132.688061] Lustre: *** cfs_fail_loc=1618, val=0*** [ 4132.697532] Lustre: Skipped 5 previous similar messages [ 4170.212683] 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 [ 4170.218631] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4171.685428] Lustre: server umount lustre-MDT0000 complete [ 4175.336202] LustreError: 109415:0:(ldlm_lib.c:1202: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. [ 4175.362510] LustreError: 109415:0:(ldlm_lib.c:1202:target_handle_connect()) Skipped 8 previous similar messages [ 4176.809470] LustreError: 109395:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788748477 with bad export cookie 2075166559156761632 [ 4176.817693] LustreError: MGC192.168.202.143@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4176.830744] LustreError: 109395:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 4177.428605] Lustre: server umount lustre-MDT0001 complete [ 4193.070259] Lustre: server umount lustre-OST0000 complete [ 4196.831504] Lustre: 106564:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788748481/real 1788748481] req@ffff958d42637480 x1875638395028736/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788748497 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4196.880306] 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 [ 4196.893610] Lustre: Skipped 3 previous similar messages [ 4198.126941] Lustre: server umount lustre-OST0001 complete [ 4220.261324] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing load_modules_local [ 4234.566244] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4235.033227] LustreError: 118079:0:(ldlm_lib.c:1202: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. [ 4235.165977] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4240.368910] LustreError: 118080:0:(ldlm_lib.c:1202: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. [ 4241.683978] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4245.478299] LustreError: 118079:0:(ldlm_lib.c:1202: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. [ 4250.616836] LustreError: 118080:0:(ldlm_lib.c:1202: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. [ 4252.925780] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4253.416516] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 4258.159792] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4262.000227] Lustre: 119220:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 4269.450632] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4269.874219] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 4276.910756] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4279.093635] LustreError: 119574:0:(ldlm_lib.c:1202: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. [ 4279.131923] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:4 to 0x280000400:33) [ 4280.110898] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:116 to 0x280000401:161) [ 4286.491355] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4292.081710] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:4 to 0x2c0000401:33) [ 4292.094775] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:33) [ 4293.278476] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4301.631433] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4305.859343] Lustre: 121090:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 4321.080612] Lustre: DEBUG MARKER: == sanity-lfsck test 18e: Find out orphan OST-object and repair it (5) ========================================================== 22:37:01 (1788748621) [ 4321.710967] Lustre: 120915:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 251 < left 278, rollback = 2 [ 4321.717541] Lustre: 120915:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 46 previous similar messages [ 4321.723225] Lustre: 120915:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4321.729448] Lustre: 120915:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4321.739622] Lustre: 120915:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4321.744059] Lustre: 120915:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4321.751302] Lustre: 120915:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 4321.766328] Lustre: 120915:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4321.774815] Lustre: 120915:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 4321.783782] Lustre: 120915:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4321.791562] Lustre: 120915:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4321.797782] Lustre: 120915:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4323.879323] Lustre: *** cfs_fail_loc=1618, val=0*** [ 4323.887285] Lustre: Skipped 3 previous similar messages [ 4358.626967] 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 [ 4358.631595] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4358.649524] Lustre: Skipped 2 previous similar messages [ 4358.668951] Lustre: Skipped 3 previous similar messages [ 4360.465647] Lustre: server umount lustre-MDT0000 complete [ 4363.748823] LustreError: 118079:0:(ldlm_lib.c:1202: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. [ 4363.768563] LustreError: 118079:0:(ldlm_lib.c:1202:target_handle_connect()) Skipped 7 previous similar messages [ 4364.273945] LustreError: 121092:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788748665 with bad export cookie 2075166559156776878 [ 4364.279797] LustreError: MGC192.168.202.143@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4364.286592] LustreError: 121092:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 4364.729636] Lustre: server umount lustre-MDT0001 complete [ 4378.202418] Lustre: server umount lustre-OST0000 complete [ 4392.315185] Lustre: server umount lustre-OST0001 complete [ 4409.826286] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing load_modules_local [ 4418.802882] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4419.099268] LustreError: 123661:0:(ldlm_lib.c:1202: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. [ 4419.160732] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4419.167512] Lustre: Skipped 1 previous similar message [ 4423.293604] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4431.323585] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4436.006179] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4438.862833] Lustre: 124801:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 4444.988642] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4451.234378] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4456.557391] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:4 to 0x280000400:65) [ 4459.688340] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4464.947356] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:4 to 0x2c0000401:65) [ 4465.025049] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:65) [ 4465.029020] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:166 to 0x280000401:193) [ 4465.410781] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4472.767404] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4476.179190] Lustre: 126672:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 4482.090435] Lustre: 124393:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 252 < left 260, rollback = 2 [ 4482.105686] Lustre: 124393:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 21 previous similar messages [ 4482.113990] Lustre: 124393:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4482.126132] Lustre: 124393:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4482.136700] Lustre: *** cfs_fail_loc=1602, val=10*** [ 4482.142373] Lustre: 124393:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 0/0/0, xattr_set: 1/260/0 [ 4482.142384] Lustre: 124393:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4482.142390] Lustre: 124393:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/9/0, punch: 0/0/0, quota 4/150/2 [ 4482.142394] Lustre: 124393:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4482.142401] Lustre: 124393:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 1/17/2, delete: 0/0/0 [ 4482.142404] Lustre: 124393:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4482.142409] Lustre: 124393:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 4482.142413] Lustre: 124393:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4482.250992] Lustre: Skipped 1 previous similar message [ 4505.644525] Lustre: DEBUG MARKER: == sanity-lfsck test 18f: Skip the failed OST(s) when handle orphan OST-objects ========================================================== 22:40:06 (1788748806) [ 4508.679416] Lustre: *** cfs_fail_loc=1616, val=0*** [ 4508.685228] Lustre: Skipped 3 previous similar messages [ 4515.478179] Lustre: *** cfs_fail_loc=161c, val=0*** [ 4534.781470] Lustre: DEBUG MARKER: == sanity-lfsck test 18g: Find out orphan OST-object and repair it (7) ========================================================== 22:40:34 (1788748834) [ 4536.736181] Lustre: *** cfs_fail_loc=162e, val=0*** [ 4548.975333] Lustre: DEBUG MARKER: == sanity-lfsck test 18h: LFSCK can repair crashed PFL extent range ========================================================== 22:40:49 (1788748849) [ 4552.831902] Lustre: *** cfs_fail_loc=162f, val=0*** [ 4552.836345] Lustre: Skipped 9 previous similar messages [ 4566.785973] Lustre: DEBUG MARKER: == sanity-lfsck test 19a: OST-object inconsistency self detect ========================================================== 22:41:07 (1788748867) [ 4578.829602] Lustre: DEBUG MARKER: == sanity-lfsck test 19b: OST-object inconsistency self repair ========================================================== 22:41:18 (1788748878) [ 4582.064569] Lustre: *** cfs_fail_loc=1611, val=0*** [ 4582.133304] Lustre: *** cfs_fail_loc=1611, val=0*** [ 4582.139228] Lustre: Skipped 3 previous similar messages [ 4587.053879] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.202.43@tcp inode [0x2000013a1:0x1f:0x0] object 0x280000401:202 extent [0-4095], client returned csum 0 (type 4), server csum 703fb3ad (type 4) [ 4588.211487] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.202.43@tcp inode [0x2000013a1:0x20:0x0] object 0x280000401:203 extent [0-4095], client returned csum 0 (type 4), server csum 7cbb935c (type 4) [ 4594.476745] Lustre: DEBUG MARKER: == sanity-lfsck test 20a: Handle the orphan with dummy LOV EA slot properly ========================================================== 22:41:34 (1788748894) [ 4614.200723] Lustre: 131203:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 253 < left 263, rollback = 2 [ 4614.206626] Lustre: 131203:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 125 previous similar messages [ 4614.211454] Lustre: 131203:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4614.215654] Lustre: 131203:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 125 previous similar messages [ 4614.220274] Lustre: 131203:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 0/0/0, xattr_set: 2/263/0 [ 4614.226015] Lustre: 131203:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 125 previous similar messages [ 4614.235537] Lustre: 131203:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 0/0/0, punch: 0/0/0, quota 1/3/2 [ 4614.241531] Lustre: 131203:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 125 previous similar messages [ 4614.253413] Lustre: 131203:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/1, delete: 0/0/0 [ 4614.260922] Lustre: 131203:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 125 previous similar messages [ 4614.265646] Lustre: 131203:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 4614.270460] Lustre: 131203:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 125 previous similar messages [ 4627.995351] Lustre: DEBUG MARKER: == sanity-lfsck test 20b: Handle the orphan with dummy LOV EA slot properly - PFL case ========================================================== 22:42:07 (1788748927) [ 4633.612861] Lustre: DEBUG MARKER: == sanity-lfsck test 21: run all LFSCK components by default ========================================================== 22:42:14 (1788748934) [ 4645.407407] Lustre: DEBUG MARKER: == sanity-lfsck test 22a: LFSCK can repair unmatched pairs (1) ========================================================== 22:42:25 (1788748945) [ 4647.395833] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4647.403567] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4647.408820] Lustre: Skipped 1 previous similar message [ 4658.512741] Lustre: DEBUG MARKER: == sanity-lfsck test 22b: LFSCK can repair unmatched pairs (2) ========================================================== 22:42:38 (1788748958) [ 4660.130532] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4660.134961] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4671.206202] Lustre: DEBUG MARKER: == sanity-lfsck test 23a: LFSCK can repair dangling name entry (1) ========================================================== 22:42:51 (1788748971) [ 4672.741377] Lustre: *** cfs_fail_loc=1620, val=0*** [ 4686.538818] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_23b skipping excluded test 23b [ 4687.883099] Lustre: DEBUG MARKER: == sanity-lfsck test 23c: LFSCK can repair dangling name entry (3) ========================================================== 22:43:08 (1788748988) [ 4693.740051] Lustre: *** cfs_fail_loc=1621, val=127*** [ 4693.743648] Lustre: Skipped 1 previous similar message [ 4696.766563] Lustre: *** cfs_fail_loc=1602, val=10*** [ 4716.655939] Lustre: DEBUG MARKER: == sanity-lfsck test 23d: LFSCK can repair a dangling name entry to a remote object ========================================================== 22:43:36 (1788749016) [ 4718.481281] Lustre: Failing over lustre-MDT0000 [ 4718.563587] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4718.572371] 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 [ 4718.593975] Lustre: Skipped 1 previous similar message [ 4718.599554] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4718.908036] Lustre: server umount lustre-MDT0000 complete [ 4720.979757] LustreError: 126437:0:(ldlm_lib.c:1202:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.202.43@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4721.007065] LustreError: 126437:0:(ldlm_lib.c:1202:target_handle_connect()) Skipped 3 previous similar messages [ 4727.995829] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4728.072927] LustreError: MGC192.168.202.143@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4728.290301] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4728.293128] Lustre: Skipped 3 previous similar messages [ 4728.328232] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4731.190704] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4732.648972] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4733.421284] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4733.453307] Lustre: lustre-MDT0000: Recovery over after 0:02, of 2 clients 2 recovered and 0 were evicted. [ 4733.505191] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:130 to 0x2c0000401:161) [ 4733.505327] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:265 to 0x280000401:289) [ 4734.550682] LustreError: 123656:0:(mdt_open.c:1324:mdt_cross_open()) lustre-MDT0000: [0x2000013a3:0x82:0x0] doesn't exist!: rc = -14 [ 4743.763645] Lustre: DEBUG MARKER: == sanity-lfsck test 24: LFSCK can repair multiple-referenced name entry ========================================================== 22:44:03 (1788749043) [ 4745.817822] Lustre: *** cfs_fail_loc=1622, val=0*** [ 4745.960232] Lustre: *** cfs_fail_loc=1622, val=0*** [ 4745.965667] Lustre: Skipped 1 previous similar message [ 4756.112817] Lustre: DEBUG MARKER: == sanity-lfsck test 25: LFSCK can repair bad file type in the name entry ========================================================== 22:44:16 (1788749056) [ 4758.141087] Lustre: *** cfs_fail_loc=1623, val=0*** [ 4768.831933] Lustre: DEBUG MARKER: == sanity-lfsck test 26a: LFSCK can add the missing local name entry back to the namespace ========================================================== 22:44:28 (1788749068) [ 4770.233692] Lustre: *** cfs_fail_loc=1624, val=0*** [ 4780.437489] Lustre: DEBUG MARKER: == sanity-lfsck test 26b: LFSCK can add the missing remote name entry back to the namespace ========================================================== 22:44:40 (1788749080) [ 4792.244577] Lustre: DEBUG MARKER: == sanity-lfsck test 27a: LFSCK can recreate the lost local parent directory as orphan ========================================================== 22:44:52 (1788749092) [ 4794.041751] Lustre: *** cfs_fail_loc=1624, val=0*** [ 4794.048538] Lustre: Skipped 1 previous similar message [ 4805.136556] Lustre: DEBUG MARKER: == sanity-lfsck test 27b: LFSCK can recreate the lost remote parent directory as orphan ========================================================== 22:45:05 (1788749105) [ 4817.347889] Lustre: DEBUG MARKER: == sanity-lfsck test 28: Skip the failed MDT(s) when handle orphan MDT-objects ========================================================== 22:45:17 (1788749117) [ 4823.491644] Lustre: *** cfs_fail_loc=161c, val=0*** [ 4823.495024] Lustre: Skipped 1 previous similar message [ 4837.538721] Lustre: DEBUG MARKER: == sanity-lfsck test 29b: LFSCK can repair bad nlink count (2) ========================================================== 22:45:37 (1788749137) [ 4839.282797] Lustre: *** cfs_fail_loc=1626, val=0*** [ 4839.287679] Lustre: Skipped 4 previous similar messages [ 4849.756337] Lustre: DEBUG MARKER: == sanity-lfsck test 29c: verify linkEA size limitation == 22:45:49 (1788749149) [ 4873.445981] Lustre: DEBUG MARKER: == sanity-lfsck test 29d: accessing non-existing inode shouldn't turn fs read-only (ldiskfs) ========================================================== 22:46:13 (1788749173) [ 4873.792195] Lustre: 123655:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 4873.800421] Lustre: 123655:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 752 previous similar messages [ 4873.810722] Lustre: 123655:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 4873.817319] Lustre: 123655:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 752 previous similar messages [ 4873.828228] Lustre: 123655:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4873.838229] Lustre: 123655:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 752 previous similar messages [ 4873.849581] Lustre: 123655:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 4873.861256] Lustre: 123655:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 752 previous similar messages [ 4873.870330] Lustre: 123655:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 4873.876720] Lustre: 123655:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 752 previous similar messages [ 4873.880660] Lustre: 123655:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4873.889631] Lustre: 123655:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 752 previous similar messages [ 4875.786747] LustreError: 127731:0:(osd_handler.c:284:osd_idc_find_or_init()) lustre-MDT0000: cannot lookup FID [0x2000013a3:0x9e:0x0]: rc = -2 [ 4881.210175] Lustre: DEBUG MARKER: == sanity-lfsck test 30: LFSCK can recover the orphans from backend /lost+found ========================================================== 22:46:21 (1788749181) [ 4907.048558] Lustre: Failing over lustre-MDT0000 [ 4907.413454] Lustre: server umount lustre-MDT0000 complete [ 4907.489674] 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 [ 4907.499663] LustreError: 123656:0:(ldlm_lib.c:1202: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. [ 4907.501055] Lustre: Skipped 5 previous similar messages [ 4907.517416] LustreError: 123656:0:(ldlm_lib.c:1202:target_handle_connect()) Skipped 11 previous similar messages [ 4917.464726] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 4917.577645] LustreError: MGC192.168.202.143@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4917.733928] Lustre: lustre-MDT0000: Not available for connect from 0@lo (not set up) [ 4917.748459] Lustre: Skipped 3 previous similar messages [ 4917.833457] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4917.868773] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4921.965376] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4922.848326] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4922.856623] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 4922.862065] Lustre: Skipped 3 previous similar messages [ 4922.901279] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4922.950593] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:166 to 0x2c0000401:193) [ 4922.954539] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:295 to 0x280000401:321) [ 4933.534466] Lustre: DEBUG MARKER: == sanity-lfsck test 31a: The LFSCK can find/repair the name entry with bad name hash (1) ========================================================== 22:47:13 (1788749233) [ 4946.809711] Lustre: DEBUG MARKER: == sanity-lfsck test 31b: The LFSCK can find/repair the name entry with bad name hash (2) ========================================================== 22:47:26 (1788749246) [ 4959.136367] Lustre: DEBUG MARKER: == sanity-lfsck test 31c: Re-generate the lost master LMV EA for striped directory ========================================================== 22:47:39 (1788749259) [ 4960.389095] Lustre: *** cfs_fail_loc=1629, val=0*** [ 4960.392769] Lustre: Skipped 7 previous similar messages [ 4970.385674] Lustre: DEBUG MARKER: == sanity-lfsck test 31d: Set broken striped directory (modified after broken) as read-only ========================================================== 22:47:50 (1788749270) [ 4975.539435] Lustre: Failing over lustre-MDT0000 [ 4975.720554] Lustre: server umount lustre-MDT0000 complete [ 4979.173601] 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 [ 4979.206375] Lustre: Skipped 3 previous similar messages [ 4979.220864] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4982.464033] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4982.524416] LustreError: MGC192.168.202.143@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4982.722209] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4986.168259] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4987.877049] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4987.881415] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4987.902770] Lustre: Skipped 3 previous similar messages [ 4987.939771] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4988.007309] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:295 to 0x280000401:353) [ 4988.011789] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:166 to 0x2c0000401:225) [ 4994.628945] Lustre: Failing over lustre-MDT0000 [ 4994.823412] Lustre: server umount lustre-MDT0000 complete [ 4998.114615] 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 [ 4998.119326] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4998.133634] Lustre: Skipped 3 previous similar messages [ 5002.259164] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5002.356261] LustreError: MGC192.168.202.143@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5002.576925] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 5004.082195] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 5006.358806] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5007.853483] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 5007.858534] Lustre: Skipped 3 previous similar messages [ 5007.877359] Lustre: lustre-MDT0000: Recovery over after 0:03, of 2 clients 2 recovered and 0 were evicted. [ 5007.918597] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:355 to 0x280000401:385) [ 5007.918875] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:166 to 0x2c0000401:257) [ 5013.972625] Lustre: DEBUG MARKER: == sanity-lfsck test 31e: Re-generate the lost slave LMV EA for striped directory (1) ========================================================== 22:48:34 (1788749314) [ 5023.980496] Lustre: DEBUG MARKER: == sanity-lfsck test 31f: Re-generate the lost slave LMV EA for striped directory (2) ========================================================== 22:48:44 (1788749324) [ 5032.938626] Lustre: DEBUG MARKER: == sanity-lfsck test 31g: Repair the corrupted slave LMV EA ========================================================== 22:48:53 (1788749333) [ 5070.271264] Lustre: DEBUG MARKER: == sanity-lfsck test 31h: Repair the corrupted shard's name entry ========================================================== 22:49:30 (1788749370) [ 5083.698245] Lustre: DEBUG MARKER: == sanity-lfsck test 32a: stop LFSCK when some OST failed ========================================================== 22:49:43 (1788749383) [ 5090.638754] LustreError: 148077:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d sleeping for 3000ms [ 5092.745153] Lustre: Failing over lustre-OST0000 [ 5092.844632] Lustre: server umount lustre-OST0000 complete [ 5093.706666] LustreError: 148077:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d awake [ 5093.716840] LustreError: 148077:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d sleeping for 3000ms [ 5094.884875] 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 [ 5094.897540] Lustre: Skipped 1 previous similar message [ 5094.905407] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 5094.999160] LustreError: 148077:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout interrupted [ 5105.455059] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 5105.611067] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 5107.118270] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 5107.126855] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 5107.130723] Lustre: lustre-OST0000-osc-MDT0001: Connection restored to 0@lo (at 0@lo) [ 5107.145984] Lustre: Skipped 3 previous similar messages [ 5110.410107] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5117.845794] Lustre: DEBUG MARKER: == sanity-lfsck test 32b: stop LFSCK when some MDT failed ========================================================== 22:50:18 (1788749418) [ 5129.833975] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing load_modules_local [ 5145.617032] Lustre: 150879:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 5166.046799] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5168.575501] Lustre: 152012:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 5178.797312] LustreError: 152130:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d sleeping for 3000ms [ 5181.093991] Lustre: Failing over lustre-MDT0001 [ 5181.831439] LustreError: 152130:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d awake [ 5181.879370] LustreError: 152129:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d sleeping for 3000ms [ 5181.885780] LustreError: lustre-MDT0001-osp-MDT0000: operation out_update to node 0@lo failed: rc = -107 [ 5181.887123] LustreError: 152129:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) Skipped 1 previous similar message [ 5181.900587] 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 [ 5181.907810] Lustre: Skipped 1 previous similar message [ 5181.910445] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 5182.045149] Lustre: server umount lustre-MDT0001 complete [ 5182.433205] LustreError: 127731:0:(ldlm_lib.c:1202: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. [ 5182.459648] LustreError: 127731:0:(ldlm_lib.c:1202:target_handle_connect()) Skipped 21 previous similar messages [ 5184.471097] LustreError: 152129:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout interrupted [ 5195.113255] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 5195.317265] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 5195.320159] Lustre: Skipped 3 previous similar messages [ 5195.341678] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 5199.594436] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5200.359145] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 1 client reconnects [ 5200.360507] Lustre: lustre-MDT0001-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 5200.368253] Lustre: Skipped 1 previous similar message [ 5200.388771] Lustre: lustre-MDT0001: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 5200.456911] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:70 to 0x280000400:97) [ 5200.461152] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:69 to 0x2c0000400:97) [ 5206.830793] Lustre: DEBUG MARKER: == sanity-lfsck test 33: check LFSCK paramters =========== 22:51:47 (1788749507) [ 5220.294280] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing load_modules_local [ 5237.348933] Lustre: 154848:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 5273.491857] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5278.487543] Lustre: 155986:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 5299.698513] Lustre: DEBUG MARKER: == sanity-lfsck test 34: LFSCK can rebuild the lost agent object ========================================================== 22:53:19 (1788749599) [ 5301.275357] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_34 Only valid for ZFS backend [ 5302.840914] Lustre: DEBUG MARKER: == sanity-lfsck test 35: LFSCK can rebuild the lost agent entry ========================================================== 22:53:22 (1788749602) [ 5310.133713] Lustre: *** cfs_fail_loc=1631, val=0*** [ 5323.232016] 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 [ 5323.237542] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5323.244628] Lustre: Skipped 4 previous similar messages [ 5323.265964] Lustre: Skipped 3 previous similar messages [ 5328.459939] Lustre: server umount lustre-MDT0000 complete [ 5332.700183] LustreError: 123643:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788749633 with bad export cookie 2075166559156849657 [ 5332.705613] LustreError: MGC192.168.202.143@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5332.722153] LustreError: 123643:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 5333.075454] Lustre: server umount lustre-MDT0001 complete [ 5347.471891] Lustre: server umount lustre-OST0000 complete [ 5349.344160] Lustre: 106564:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788749634/real 1788749634] req@ffff958d4c4f5880 x1875638396446464/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788749650 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5351.374461] Lustre: server umount lustre-OST0001 complete [ 5368.676263] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing load_modules_local [ 5377.825237] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5382.314522] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5390.678697] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5395.098876] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5398.258490] Lustre: 159887:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 5404.070343] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5410.185851] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5416.629859] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:70 to 0x280000400:129) [ 5419.017213] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5423.292136] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:540 to 0x280000401:577) [ 5423.323488] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:69 to 0x2c0000400:129) [ 5423.381332] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:412 to 0x2c0000401:449) [ 5426.416077] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5434.582737] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5438.365897] Lustre: 161755:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 5448.027937] Lustre: DEBUG MARKER: == sanity-lfsck test 36a: rebuild LOV EA for mirrored file (1) ========================================================== 22:55:47 (1788749747) [ 5449.787711] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36a needs >= 3 OSTs [ 5451.828775] Lustre: DEBUG MARKER: == sanity-lfsck test 36b: rebuild LOV EA for mirrored file (2) ========================================================== 22:55:51 (1788749751) [ 5453.946711] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36b needs >= 3 OSTs [ 5456.006736] Lustre: DEBUG MARKER: == sanity-lfsck test 36c: rebuild LOV EA for mirrored file (3) ========================================================== 22:55:55 (1788749755) [ 5457.563506] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36c needs >= 3 OSTs [ 5458.999331] Lustre: DEBUG MARKER: == sanity-lfsck test 37: LFSCK must skip a ORPHAN ======== 22:55:59 (1788749759) [ 5460.308236] Lustre: 160822:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 5460.318851] Lustre: 160822:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 1655 previous similar messages [ 5460.323722] Lustre: 160822:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 5460.330112] Lustre: 160822:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1655 previous similar messages [ 5460.335947] Lustre: 160822:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 5460.342116] Lustre: 160822:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1655 previous similar messages [ 5460.347941] Lustre: 160822:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 5460.351200] Lustre: 160822:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1655 previous similar messages [ 5460.354189] Lustre: 160822:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 5460.357236] Lustre: 160822:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1655 previous similar messages [ 5460.361459] Lustre: 160822:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 5460.364951] Lustre: 160822:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1655 previous similar messages [ 5469.715927] Lustre: DEBUG MARKER: == sanity-lfsck test 38: LFSCK does not break foreign file and reverse is also true ========================================================== 22:56:09 (1788749769) [ 5487.065520] Lustre: DEBUG MARKER: == sanity-lfsck test 39: LFSCK does not break foreign dir and reverse is also true ========================================================== 22:56:27 (1788749787) [ 5502.313453] Lustre: DEBUG MARKER: == sanity-lfsck test 40a: LFSCK correctly fixes lmm_oi in composite layout ========================================================== 22:56:42 (1788749802) [ 5516.237344] Lustre: DEBUG MARKER: == sanity-lfsck test 41: SEL support in LFSCK ============ 22:56:56 (1788749816) [ 5538.385737] Lustre: DEBUG MARKER: == sanity-lfsck test 42: LFSCK repairs inconsistent MDT-object/OST-object encryption flags ========================================================== 22:57:18 (1788749838) [ 5574.018414] Lustre: *** cfs_fail_loc=1632, val=0*** [ 5591.077732] Lustre: DEBUG MARKER: == sanity-lfsck test 43: LFSCK does not loop endlessly on iget failure in scanning-phase1 ========================================================== 22:58:10 (1788749890) [ 5593.675466] Lustre: Failing over lustre-MDT0001 [ 5593.855493] Lustre: server umount lustre-MDT0001 complete [ 5596.127666] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 5596.135968] 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 [ 5596.155646] Lustre: Skipped 2 previous similar messages [ 5601.505517] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5601.861325] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 5601.861632] Lustre: lustre-MDT0001: Aborting client recovery [ 5601.869695] LustreError: 165547:0:(ldlm_lib.c:3042:target_stop_recovery_thread()) lustre-MDT0001: Aborting recovery [ 5601.872901] LustreError: 165569:0:(lod_dev.c:511:lod_sub_recovery_thread()) lustre-MDT0001-osd: get update log duration 0, retries 0, failed: rc = -108 [ 5601.877466] Lustre: 165571:0:(ldlm_lib.c:2442:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 5601.900972] Lustre: 165571:0:(genops.c:1600:class_disconnect_stale_exports()) lustre-MDT0001: disconnect stale client f86313f3-8213-4cb8-a5ba-42d74fee870f@ [ 5601.915705] Lustre: lustre-MDT0001: disconnecting 2 stale clients [ 5601.925673] Lustre: lustre-MDT0001-osd: cancel update llog [0x240000400:0x1:0x0] [ 5601.952474] Lustre: lustre-MDT0000-osp-MDT0001: cancel update llog [0x200000401:0x1:0x0] [ 5601.998864] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:131 to 0x2c0000400:161) [ 5602.012353] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:70 to 0x280000400:161) [ 5606.521103] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5606.896351] Lustre: lustre-MDT0001-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 5606.905991] Lustre: Skipped 2 previous similar messages [ 5606.916433] LustreError: lustre-MDT0001-osp-MDT0000: This client was evicted by lustre-MDT0001; in progress operations using this service will fail. [ 5610.354734] Lustre: *** cfs_fail_loc=1e2, val=483*** [ 5615.055521] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing wait_import_state FULL osp.lustre-MDT0001-os[pc]-MDT0000.*_server_uuid [ 5615.361854] Lustre: DEBUG MARKER: osp.lustre-MDT0001-os[pc]-MDT0000.*_server_uuid in FULL state after 0 sec [ 5622.157056] Lustre: DEBUG MARKER: == sanity-lfsck test 44: umount while lfsck is stopping == 22:58:42 (1788749922) [ 5630.002465] Lustre: *** cfs_fail_loc=1600, val=3*** [ 5632.680224] Lustre: Failing over lustre-MDT0000 [ 5633.091201] Lustre: server umount lustre-MDT0000 complete [ 5637.601274] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 5642.396844] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5642.556670] LustreError: MGC192.168.202.143@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5642.726059] Lustre: lustre-MDT0000: Not available for connect from 0@lo (not set up) [ 5642.741439] Lustre: Skipped 3 previous similar messages [ 5642.948536] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 5642.952239] Lustre: Skipped 2 previous similar messages [ 5644.089593] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 5647.998428] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5648.359798] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 5648.371347] Lustre: Skipped 2 previous similar messages [ 5648.414281] Lustre: lustre-MDT0000: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 5648.468640] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:489 to 0x2c0000401:513) [ 5648.470573] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:621 to 0x280000401:641) [ 5658.166433] Lustre: DEBUG MARKER: == sanity-lfsck test 45: LFSCK should fix UID/GID/PROJID of OST object ========================================================== 22:59:18 (1788749958) [ 5700.240053] Lustre: Failing over lustre-OST0001 [ 5700.427705] LustreError: 161256:0:(ldlm_lib.c:1202:target_handle_connect()) lustre-OST0001: not available for connect from 192.168.202.43@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 5700.442022] LustreError: 161256:0:(ldlm_lib.c:1202:target_handle_connect()) Skipped 25 previous similar messages [ 5700.530125] Lustre: server umount lustre-OST0001 complete [ 5704.165612] LustreError: lustre-OST0001-osc-MDT0001: operation ost_statfs to node 0@lo failed: rc = -107 [ 5707.286165] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: (null) [ 5719.458114] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5719.633751] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 5719.637988] Lustre: Skipped 6 previous similar messages [ 5719.645869] Lustre: lustre-OST0001: in recovery but waiting for the first client to connect [ 5720.883585] Lustre: lustre-OST0001: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 5721.264650] Lustre: lustre-OST0001: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [ 5721.265332] Lustre: lustre-OST0001-osc-MDT0001: Connection restored to 0@lo (at 0@lo) [ 5721.299273] Lustre: Skipped 3 previous similar messages [ 5726.117623] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5732.835534] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing wait_import_state (FULL|IDLE) os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid 50 [ 5733.134646] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid in FULL state after 0 sec [ 5738.195579] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing wait_import_state (FULL|IDLE) os[cp].lustre-OST0000-osc-MDT0001.ost_server_uuid 50 [ 5738.437892] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0001.ost_server_uuid in FULL state after 0 sec [ 5745.849785] Lustre: DEBUG MARKER: oleg243-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0000-osc-ffff8d796d944800.ost_server_uuid 50 [ 5747.510536] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff8d796d944800.ost_server_uuid in FULL state after 0 sec [ 5832.161259] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5832.179937] Lustre: Skipped 3 previous similar messages [ 5836.750401] Lustre: server umount lustre-MDT0000 complete [ 5846.420203] LustreError: 158728:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788750147 with bad export cookie 2075166559156932453 [ 5846.427460] LustreError: MGC192.168.202.143@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5846.430283] LustreError: 158728:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 5846.980083] Lustre: server umount lustre-MDT0001 complete [ 5863.711269] Lustre: 106564:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788750148/real 1788750148] req@ffff958e76757480 x1875638396854144/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788750164 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5866.867472] Lustre: server umount lustre-OST0000 complete [ 5867.871128] Lustre: 106561:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788750152/real 1788750152] req@ffff958e77fec700 x1875638396854400/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788750168 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5872.042876] Lustre: 106561:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788750157/real 1788750157] req@ffff958e76756300 x1875638396855040/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788750173 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5872.064113] Lustre: 106561:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 5875.092045] Lustre: server umount lustre-OST0001 complete [ 5893.915296] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing unload_modules_local [ 5897.470591] Key type lgssc unregistered [ 5897.750710] LNet: 175155:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 5897.762598] LNetError: 175155:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 5897.795230] LNet: Removed LNI 192.168.202.143@tcp [ 5898.911275] Key type .llcrypt unregistered [ 5898.915076] Key type ._llcrypt unregistered [ 5927.133144] Key type ._llcrypt registered [ 5927.134337] Key type .llcrypt registered [ 5927.229328] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_hostid [ 5949.973355] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing load_modules_local [ 5951.076570] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 5951.197556] alg: No test for adler32 (adler32-zlib) [ 5952.209572] Lustre: Lustre: Build Version: 2.17.58_40_g869f601 [ 5952.405730] LNet: Added LNI 192.168.202.143@tcp [8/256/0/180] [ 5954.048089] Key type lgssc registered [ 5955.280805] Lustre: Echo OBD driver; http://www.lustre.org/ [ 6010.233783] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing load_modules_local [ 6022.736580] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 6022.769578] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 6024.056763] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 6024.143963] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 6024.280870] Lustre: lustre-MDT0000: new disk, initializing [ 6024.386211] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 6024.407641] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 6029.554357] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6044.819712] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 6044.965869] Lustre: 179609: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 [ 6045.056822] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 6045.071618] Lustre: Skipped 1 previous similar message [ 6045.222653] Lustre: lustre-MDT0001: new disk, initializing [ 6045.295364] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 6045.327548] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 6045.339489] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 6049.305713] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6054.545360] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 6063.636535] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 6063.849214] Lustre: lustre-OST0000: new disk, initializing [ 6063.854379] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 6063.873326] Lustre: 181549:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 6063.978726] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 6069.058278] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6069.776508] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 6069.790285] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 6069.842623] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 6081.538812] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 6081.732584] Lustre: lustre-OST0001: new disk, initializing [ 6081.737470] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 6081.742648] Lustre: 182572:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 6081.826012] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 6087.756539] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6088.736713] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 6088.752950] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 6088.813486] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 6100.521921] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 6108.613199] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 6115.284118] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 23:06:54 (1788750414) === [ 6117.181354] Lustre: DEBUG MARKER: == sanity-lfsck test complete, duration 5781 sec ========= 23:06:56 (1788750416) [ 6118.817068] Lustre: DEBUG MARKER: === sanity-lfsck: start cleanup 23:06:58 (1788750418) === [ 6122.221598] Lustre: DEBUG MARKER: === sanity-lfsck: finish cleanup 23:07:02 (1788750422) === [ 6127.585479] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 6127.599255] 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 [ 6127.618496] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 6129.632505] 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 [ 6129.633376] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 6129.658336] Lustre: Skipped 1 previous similar message [ 6129.663275] Lustre: Skipped 1 previous similar message [ 6133.430334] Lustre: server umount lustre-MDT0000 complete [ 6139.872030] LustreError: 179622:0:(ldlm_lib.c:1202: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. [ 6139.893785] LustreError: 179622:0:(ldlm_lib.c:1202:target_handle_connect()) Skipped 8 previous similar messages [ 6142.303295] LustreError: 179603:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788750443 with bad export cookie 5999268624999117316 [ 6142.304081] LustreError: MGC192.168.202.143@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 6142.312601] LustreError: 179603:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 6142.696712] Lustre: server umount lustre-MDT0001 complete [ 6161.376502] Lustre: 176768:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788750446/real 1788750446] req@ffff958e4ee27100 x1875640585372544/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788750462 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6161.404180] 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 [ 6161.415688] Lustre: Skipped 1 previous similar message [ 6162.761759] Lustre: server umount lustre-OST0000 complete [ 6163.423236] Lustre: 176766:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788750448/real 1788750448] req@ffff958d50311500 x1875640585372800/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788750464 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6166.559506] Lustre: 176768:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788750451/real 1788750451] req@ffff958e5eb97b80 x1875640585373056/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788750467 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6169.640703] Lustre: 176766:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788750454/real 1788750454] req@ffff958d4480ea00 x1875640585373440/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788750470 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6172.070333] Lustre: server umount lustre-OST0001 complete [ 6191.395300] Lustre: DEBUG MARKER: oleg243-server.virtnet: executing unload_modules_local [ 6194.325837] Key type lgssc unregistered [ 6194.668736] LNet: 186047:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 6194.690254] LNetError: 186047:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 6194.721957] LNet: Removed LNI 192.168.202.143@tcp [ 6195.612224] Key type .llcrypt unregistered [ 6195.614161] Key type ._llcrypt unregistered