[ 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 508690140 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, 524580K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] ftrace: allocating 41240 entries in 162 pages [ 0.000000] ftrace: allocated 162 pages with 3 groups [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] rcu: RCU event tracing is enabled. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ 0.000000] rcu: RCU callback double-/use-after-free debug enabled. [ 0.000000] Rude variant of Tasks RCU enabled. [ 0.000000] Tracing variant of Tasks RCU enabled. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 0.000000] NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16 [ 0.000000] random: get_random_bytes called from start_kernel+0x622/0x9a8 with crng_init=0 [ 0.001000] Console: colour *CGA 80x25 [ 0.001000] printk: console [ttyS1] enabled [ 0.001000] ACPI: Core revision 20220331 [ 0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.001012] APIC: Switch to symmetric I/O mode setup [ 0.002356] x2apic enabled [ 0.003009] Switched APIC routing to physical x2apic. [ 0.004015] kvm-guest: setup PV IPIs [ 0.007501] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.008000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.008029] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.009013] pid_max: default: 32768 minimum: 301 [ 0.010149] LSM: Security Framework initializing [ 0.011078] Yama: becoming mindful. [ 0.012036] SELinux: Initializing. [ 0.014067] *** VALIDATE selinux *** [ 0.022778] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.026619] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.027156] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.028112] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.030037] *** VALIDATE tmpfs *** [ 0.031465] *** VALIDATE proc *** [ 0.033068] *** VALIDATE cgroup *** [ 0.034008] *** VALIDATE cgroup2 *** [ 0.035265] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.036146] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.037013] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.038027] Spectre V2 : User space: Vulnerable [ 0.039009] Speculative Store Bypass: Vulnerable [ 0.042688] debug: unmapping init [mem 0xffffffffb5459000-0xffffffffb5460fff] [ 0.045173] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.046666] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.047027] ... version: 2 [ 0.048012] ... bit width: 48 [ 0.049010] ... generic registers: 4 [ 0.050012] ... value mask: 0000ffffffffffff [ 0.051014] ... max period: 00007fffffffffff [ 0.052011] ... fixed-purpose events: 3 [ 0.052974] ... event mask: 000000070000000f [ 0.053320] rcu: Hierarchical SRCU implementation. [ 0.055392] smp: Bringing up secondary CPUs ... [ 0.056505] x86: Booting SMP configuration: [ 0.057022] .... node #0, CPUs: #1 #2 #3 [ 0.060408] smp: Brought up 1 node, 4 CPUs [ 0.062013] smpboot: Max logical packages: 1 [ 0.063018] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.147282] node 0 deferred pages initialised in 81ms [ 0.151173] devtmpfs: initialized [ 0.152257] x86/mm: Memory block size: 128MB [ 0.154934] gcov: version magic: 0x41383552 [ 0.156300] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.157093] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.158278] pinctrl core: initialized pinctrl subsystem [ 0.159208] [ 0.159584] ************************************************************* [ 0.160015] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.161014] ** ** [ 0.162030] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.163014] ** ** [ 0.164013] ** This means that this kernel is built to expose internal ** [ 0.165016] ** IOMMU data structures, which may compromise security on ** [ 0.166016] ** your system. ** [ 0.167017] ** ** [ 0.168014] ** If you see this message and you are not debugging the ** [ 0.169013] ** kernel, report this immediately to your vendor! ** [ 0.170016] ** ** [ 0.171018] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.172011] ************************************************************* [ 0.173637] NET: Registered protocol family 16 [ 0.174436] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.175074] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.176061] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.177441] cpuidle: using governor menu [ 0.179497] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.182558] PCI: Using configuration type 1 for base access [ 0.184139] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.194058] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.195022] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.197080] cryptd: max_cpu_qlen set to 1000 [ 0.200274] ACPI: Added _OSI(Module Device) [ 0.201014] ACPI: Added _OSI(Processor Device) [ 0.202014] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.203013] ACPI: Added _OSI(Processor Aggregator Device) [ 0.207027] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.210575] ACPI: Interpreter enabled [ 0.211061] ACPI: PM: (supports S0 S3 S4 S5) [ 0.212012] ACPI: Using IOAPIC for interrupt routing [ 0.213101] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.214366] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.223368] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.224047] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.225022] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.226088] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.228297] acpiphp: Slot [2] registered [ 0.229110] acpiphp: Slot [5] registered [ 0.230143] acpiphp: Slot [6] registered [ 0.231128] acpiphp: Slot [7] registered [ 0.232182] acpiphp: Slot [8] registered [ 0.233125] acpiphp: Slot [9] registered [ 0.235103] acpiphp: Slot [10] registered [ 0.236128] acpiphp: Slot [3] registered [ 0.237116] acpiphp: Slot [4] registered [ 0.238138] acpiphp: Slot [11] registered [ 0.239082] acpiphp: Slot [12] registered [ 0.240095] acpiphp: Slot [13] registered [ 0.241107] acpiphp: Slot [14] registered [ 0.242091] acpiphp: Slot [15] registered [ 0.243085] acpiphp: Slot [16] registered [ 0.244077] acpiphp: Slot [17] registered [ 0.245096] acpiphp: Slot [18] registered [ 0.247102] acpiphp: Slot [19] registered [ 0.249146] acpiphp: Slot [20] registered [ 0.250100] acpiphp: Slot [21] registered [ 0.251155] acpiphp: Slot [22] registered [ 0.253106] acpiphp: Slot [23] registered [ 0.254086] acpiphp: Slot [24] registered [ 0.255146] acpiphp: Slot [25] registered [ 0.256119] acpiphp: Slot [26] registered [ 0.258165] acpiphp: Slot [27] registered [ 0.260105] acpiphp: Slot [28] registered [ 0.261111] acpiphp: Slot [29] registered [ 0.263171] acpiphp: Slot [30] registered [ 0.265125] acpiphp: Slot [31] registered [ 0.267109] PCI host bridge to bus 0000:00 [ 0.269021] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.271032] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.273053] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.276041] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.279024] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.281047] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.283200] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.286048] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.289377] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.300010] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.306067] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.308020] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.311019] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.314019] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.317365] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.320933] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.323045] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.325986] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.332023] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.346840] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.352018] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.358269] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.366018] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.373016] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.393020] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.403813] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.410016] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.416018] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.433020] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.447000] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.452017] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.459015] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.477020] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.485929] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.494018] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.501018] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.519021] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.530822] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.542019] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.550019] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.563023] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 0.570587] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.577016] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.583024] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.598026] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 0.609166] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.612406] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.615446] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.617900] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.621351] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.625109] iommu: Default domain type: Passthrough [ 0.627458] SCSI subsystem initialized [ 0.628143] ACPI: bus type USB registered [ 0.630119] usbcore: registered new interface driver usbfs [ 0.631076] usbcore: registered new interface driver hub [ 0.633081] usbcore: registered new device driver usb [ 0.634217] pps_core: LinuxPPS API ver. 1 registered [ 0.636010] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.638061] PTP clock support registered [ 0.641054] EDAC MC: Ver: 3.0.0 [ 0.642097] PCI: Using ACPI for IRQ routing [ 0.645092] NetLabel: Initializing [ 0.647013] NetLabel: domain hash size = 128 [ 0.649013] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.651101] NetLabel: unlabeled traffic allowed by default [ 0.654043] vgaarb: loaded [ 0.655282] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.657015] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.661729] clocksource: Switched to clocksource kvm-clock [ 0.768908] VFS: Disk quotas dquot_6.6.0 [ 0.770696] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.773572] *** VALIDATE ramfs *** [ 0.775048] *** VALIDATE hugetlbfs *** [ 0.777969] pnp: PnP ACPI init [ 0.780507] pnp: PnP ACPI: found 6 devices [ 0.815401] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.819087] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.821510] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.824103] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.827047] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.829806] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.833264] NET: Registered protocol family 2 [ 0.836183] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.842278] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.846871] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.853094] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.856908] TCP: Hash tables configured (established 65536 bind 65536) [ 0.860184] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.863628] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.866913] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.870183] NET: Registered protocol family 1 [ 0.873048] RPC: Registered named UNIX socket transport module. [ 0.875737] RPC: Registered udp transport module. [ 0.877729] RPC: Registered tcp transport module. [ 0.879709] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.882403] NET: Registered protocol family 44 [ 0.884357] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.886274] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.888530] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.890520] PCI: CLS 0 bytes, default 64 [ 0.892676] Unpacking initramfs... [ 2.322837] debug: unmapping init [mem 0xffff9ae2bcc54000-0xffff9ae2bffbffff] [ 2.327228] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.329410] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.331826] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 2.818715] Initialise system trusted keyrings [ 2.820122] Key type blacklist registered [ 2.822190] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.831734] zbud: loaded [ 2.834473] *** VALIDATE nfs *** [ 2.835619] *** VALIDATE nfs4 *** [ 2.837151] pstore: using deflate compression [ 2.841577] Platform Keyring initialized [ 2.958641] NET: Registered protocol family 38 [ 2.960148] Key type asymmetric registered [ 2.962099] Asymmetric key parser 'x509' registered [ 2.964308] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 2.967256] io scheduler mq-deadline registered [ 2.969230] io scheduler kyber registered [ 2.971109] io scheduler bfq registered [ 2.973618] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 2.977132] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 2.980556] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 2.985270] ACPI: Power Button [PWRF] [ 2.990129] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 2.997081] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 3.014459] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 3.024884] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 3.041972] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 3.071051] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.101881] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.109299] Non-volatile memory driver v1.3 [ 3.111052] Linux agpgart interface v0.103 [ 3.147282] virtio_blk virtio1: [vda] 149952 512-byte logical blocks (76.8 MB/73.2 MiB) [ 3.150255] vda: detected capacity change from 0 to 76775424 [ 3.165357] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.168847] vdb: detected capacity change from 0 to 1073741824 [ 3.183895] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.186861] vdc: detected capacity change from 0 to 2621440000 [ 3.205803] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.209208] vdd: detected capacity change from 0 to 2621440000 [ 3.228933] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.231932] vde: detected capacity change from 0 to 4294967296 [ 3.245883] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.249041] vdf: detected capacity change from 0 to 4294967296 [ 3.255180] libphy: Fixed MDIO Bus: probed [ 3.264450] usbcore: registered new interface driver usbserial_generic [ 3.266902] usbserial: USB Serial support registered for generic [ 3.271137] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.276163] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.278481] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.281307] mousedev: PS/2 mouse device common for all mice [ 3.284262] rtc_cmos 00:05: RTC can wake from S4 [ 3.285670] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.289481] rtc_cmos 00:05: registered as rtc0 [ 3.294105] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.294411] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.297043] intel_pstate: CPU model not supported [ 3.302638] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.306857] hid: raw HID events driver (C) Jiri Kosina [ 3.309288] usbcore: registered new interface driver usbhid [ 3.311682] usbhid: USB HID core driver [ 3.313594] drop_monitor: Initializing network drop monitor service [ 3.316498] Initializing XFRM netlink socket [ 3.318875] NET: Registered protocol family 10 [ 3.322519] Segment Routing with IPv6 [ 3.324139] NET: Registered protocol family 17 [ 3.326373] mpls_gso: MPLS GSO support [ 3.331966] RAS: Correctable Errors collector initialized. [ 3.333918] AVX version of gcm_enc/dec engaged. [ 3.335348] AES CTR mode by8 optimization enabled [ 3.422573] sched_clock: Marking stable (3422551929, 0)->(4375696992, -953145063) [ 3.426209] registered taskstats version 1 [ 3.428947] Loading compiled-in X.509 certificates [ 3.431225] zswap: loaded using pool lzo/zbud [ 3.459578] Key type big_key registered [ 3.472976] Key type encrypted registered [ 3.475017] ima: No TPM chip found, activating TPM-bypass! [ 3.477672] ima: Allocated hash algorithm: sha1 [ 3.480927] ima: No architecture policies found [ 3.482929] evm: Initialising EVM extended attributes: [ 3.485092] evm: security.selinux [ 3.486610] evm: security.ima [ 3.487887] evm: security.capability [ 3.489481] evm: HMAC attrs: 0x1 [ 3.492852] rtc_cmos 00:05: setting system clock to 2026-09-10 17:32:41 UTC (1789061561) [ 3.499776] debug: unmapping init [mem 0xffffffffb6403000-0xffffffffb65fffff] [ 3.503354] debug: unmapping init [mem 0xffffffffb5182000-0xffffffffb5458fff] [ 3.513112] Write protecting the kernel read-only data: 28672k [ 3.517494] debug: unmapping init [mem 0xffffffffb3803000-0xffffffffb39fffff] [ 3.520980] debug: unmapping init [mem 0xffffffffb4114000-0xffffffffb41fffff] [ 3.560744] 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.570302] systemd[1]: Detected virtualization kvm. [ 3.572511] systemd[1]: Detected architecture x86-64. [ 3.574547] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.601432] systemd[1]: No hostname configured. [ 3.603075] systemd[1]: Set hostname to . [ 3.605080] random: systemd: uninitialized urandom read (16 bytes read) [ 3.607252] systemd[1]: Initializing machine ID from random generator. [ 3.666893] random: ln: uninitialized urandom read (6 bytes read) [ 3.759142] random: systemd: uninitialized urandom read (16 bytes read) [ 3.762167] systemd[1]: Reached target Swap. [ OK ] Reached target Swap. [ 3.766687] systemd[1]: Started Dispatch Password Requests to Console Directory Watch. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ 3.774413] systemd[1]: Reached target Paths. [ OK ] Reached target Paths. [ OK ] Listening on Journal Socket. [ OK ] Reached target Initrd Root Device. Starting Setup Virtual Console... [ OK ] Listening on udev Kernel Socket. [ OK ] Reached target Timers. [ OK ] Reached target Local File Systems. [ OK ] Listening on udev Control Socket. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Listening on Journal Socket (/dev/log). [ OK ] Reached target Sockets. Starting Apply Kernel Variables... [ OK ] Started Memstrack Anylazing Service. [ OK ] Reached target Local Encrypted Volumes. Starting Create Volatile Files and Directories... Starting Journal Service... [ OK ] Reached target Slices. [ 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 ] Started Journal Service. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 4.520961] device-mapper: uevent: version 1.0.3 [ 4.523562] 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.259639] virtio_net virtio0 ens2: renamed from eth0 [ 5.276616] random: fast init done [ 5.301574] scsi host0: ata_piix [ 5.324198] scsi host1: ata_piix [ 5.326171] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 5.327949] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 9.706309] dracut-initqueue[586]: RTNETLINK answers: File exists [ 9.995644] random: crng init done [ 9.997993] random: 7 urandom warning(s) missed due to ratelimiting Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. Mounting /sysroot... [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. [ 10.465254] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Initrd Default Target. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped target Timers. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Sockets. [ OK ] Stopped target Paths. [ OK ] Stopped target Slices. [ OK ] Stopped target System Initialization. [ OK ] Stopped target Swap. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. Stopping udev Kernel Device Manager... [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Closed udev Kernel Socket. [ OK ] Closed udev Control Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 11.648559] printk: systemd: 26 output lines suppressed due to ratelimiting [ 11.913030] SELinux: Disabled at runtime. [ 11.979069] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 11.988155] systemd[1]: Detected virtualization kvm. [ 11.990117] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 12.500403] systemd[1]: initrd-switch-root.service: Succeeded. [ 12.503675] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 12.508784] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 12.513414] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 12.518299] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 12.526986] systemd[1]: Starting Journal Service... Starting Journal Service... [ 12.535323] systemd[1]: Starting Create list of required static device nodes for the current kernel... Starting Create list of required st…ce nodes for the current kernel... [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Created slice system-sshd\x2dkeygen.slice. Mounting POSIX Message Queue File System... Activating swap /dev/disk/by-label/SWAP... [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target rpc_pipefs.target. [ OK ] Listening on RPCbind Server Activation Socket. [ 12.600978] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS Starting Apply Kernel Variables... Mounting Kernel Debug File System... Starting Remount Root and Kernel File Systems... [ OK ] Created slice system-getty.slice. [ OK ] Listening on udev Control Socket. [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd Root File System. [ OK ] Reached target RPC Port Mapper. Mounting Huge Pages File System... [ OK ] Listening on Process Core Dump Socket. [ OK ] Stopped target Initrd File Systems. [ OK ] Listening on udev Kernel Socket. [ OK ] Created slice User and Session Slice. [ OK ] Reached target Slices. Starting udev Coldplug all Devices... [ OK ] Reached target Paths. [ OK ] Started Journal Service. [ 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 Kernel Debug File System. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Mounted Huge Pages File System. Starting Configure read-only root support... [ OK ] Reached target Swap. Starting Create Static Device Nodes in /dev... Starting Flush Journal to Persistent Storage... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. Starting udev Kernel Device Manager... [ OK ] Reached target Local File Systems (Pre). Mounting /home/green/git/lustre-release... Mounting /mnt... [ OK ] Mounted /mnt. [ 13.013182] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Coldplug all Devices. [ OK ] Started udev Kernel Device Manager. [ 13.284970] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 13.395796] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 13.461540] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 13.470824] EDAC sbridge: Ver: 1.1.2 [ 15.238935] Key type dns_resolver registered [ 15.543128] NFS: Registering the id_resolver key type [ 15.546794] Key type id_resolver registered [ 15.548399] Key type id_legacy registered [ OK ] Started Configure read-only root support. Starting Load/Save Random Seed... [ OK ] Reached target Local File Systems. Starting Mark the need to relabel after reboot... Starting Rebuild Dynamic Linker Cache... Starting Create Volatile Files and Directories... [ OK ] Started Load/Save Random Seed. [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Create Volatile Files and Directories. Starting RPC Bind... Starting Update UTMP about System Boot/Shutdown... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Started dnf makecache --timer. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Started D-Bus System Message Bus. Starting Network Manager... Starting Login Service... [ OK ] Started irqbalance daemon. [ OK ] Reached target sshd-keygen.target. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Reached target Timers. Starting Restore /run/initramfs on shutdown... [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Login Service. [ 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 OpenSSH server daemon. [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... Starting Hostname Service... [ OK ] Started Permit User Sessions. [ OK ] Started Getty on tty1. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Serial Getty on ttyS1. [ OK ] Reached target Login Prompts. [ OK ] Started Command Scheduler. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting System Logging Service... Starting Crash recovery kernel arming... Starting Notify NFS peers of a restart... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Starting Authorization Manager... [ OK ] Started Authorization Manager. [ OK ] Started Dynamic System Tuning Daemon. [ OK ] Reached target Multi-User System. [ OK ] Reached target Graphical Interface. Starting Update UTMP about System Runlevel Changes... [ OK ] Started Update UTMP about System Runlevel Changes. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg444-server login: [ 39.809744] hrtimer: interrupt took 3685556 ns [ 47.340102] libcfs: loading out-of-tree module taints kernel. [ 47.447611] Key type ._llcrypt registered [ 47.450110] Key type .llcrypt registered [ 47.637364] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_hostid [ 69.403040] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing load_modules_local [ 71.265426] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 71.288450] alg: No test for adler32 (adler32-zlib) [ 72.832241] Lustre: Lustre: Build Version: 2.17.58_39_ga794951 [ 74.123359] LNet: Added LNI 192.168.204.144@tcp [8/256/0/180] [ 76.048389] Key type lgssc registered [ 77.820338] Lustre: Echo OBD driver; http://www.lustre.org/ [ 100.313110] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 147.866219] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing load_modules_local [ 161.901708] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 161.990335] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 163.288719] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 163.345704] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 163.456828] Lustre: lustre-MDT0000: new disk, initializing [ 163.573200] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 163.614863] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 168.517548] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 182.942038] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 183.089780] Lustre: 6511: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 [ 183.125494] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 183.129516] Lustre: Skipped 1 previous similar message [ 183.240892] Lustre: lustre-MDT0001: new disk, initializing [ 183.306043] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 183.329629] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 183.344314] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 188.442510] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 193.162601] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 203.001548] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 203.442402] Lustre: lustre-OST0000: new disk, initializing [ 203.450908] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 203.463581] Lustre: 8448:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 203.560355] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 206.046877] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 206.054455] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 206.109996] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 210.982152] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 227.657218] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 227.803830] Lustre: lustre-OST0001: new disk, initializing [ 227.807330] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 227.816810] Lustre: 9521:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 227.898864] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 233.984564] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 236.128751] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 236.147103] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 236.241756] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 248.590579] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 255.998300] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 263.761180] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing check_logdir /tmp/testlogs/ [ 269.700815] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing yml_node [ 274.976561] Lustre: DEBUG MARKER: Client: 2.17.58.39 [ 277.894968] Lustre: DEBUG MARKER: MDS: 2.17.58.39 [ 280.613595] Lustre: DEBUG MARKER: OSS: 2.17.58.39 [ 282.492241] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity-lfsck ============----- Thu Sep 10 13:37:18 EDT 2026 [ 304.215607] Lustre: DEBUG MARKER: excepting tests: 18b 23b [ 318.405467] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing load_modules_local [ 331.745343] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 331.751223] 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 [ 331.776276] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 333.795151] 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 [ 333.809110] Lustre: Skipped 2 previous similar messages [ 333.809818] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 333.819810] Lustre: Skipped 3 previous similar messages [ 335.977431] Lustre: server umount lustre-MDT0000 complete [ 344.039033] LustreError: 6521:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 344.064571] LustreError: 6521:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 8 previous similar messages [ 345.064169] LustreError: 7459:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1789061903 with bad export cookie 314483296477333445 [ 345.077994] LustreError: MGC192.168.204.144@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 345.079391] LustreError: 7459:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 345.378806] Lustre: server umount lustre-MDT0001 complete [ 365.536184] Lustre: 3643:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789061907/real 1789061907] req@ffff9ae32c88dc00 x1875967089947264/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1789061923 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 365.566423] 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 [ 366.433706] Lustre: 3640:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789061908/real 1789061908] req@ffff9ae32c88ca80 x1875967089947520/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1789061924 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 366.925268] Lustre: server umount lustre-OST0000 complete [ 370.724870] Lustre: 3643:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789061912/real 1789061912] req@ffff9ae207cc1880 x1875967089947776/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1789061928 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 376.800637] Lustre: 3641:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789061918/real 1789061918] req@ffff9ae207cc3b80 x1875967089948416/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1789061934 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 376.868293] Lustre: 3641:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 377.895970] Lustre: server umount lustre-OST0001 complete [ 396.092534] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing unload_modules_local [ 399.490847] Key type lgssc unregistered [ 399.843725] LNet: 14799:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 399.853252] LNetError: 14799:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 399.876080] LNet: Removed LNI 192.168.204.144@tcp [ 401.235144] Key type .llcrypt unregistered [ 401.236715] Key type ._llcrypt unregistered [ 428.614417] Key type ._llcrypt registered [ 428.618806] Key type .llcrypt registered [ 428.782838] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_hostid [ 446.111417] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing load_modules_local [ 447.336989] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 447.437075] alg: No test for adler32 (adler32-zlib) [ 448.548146] Lustre: Lustre: Build Version: 2.17.58_39_ga794951 [ 448.959138] LNet: Added LNI 192.168.204.144@tcp [8/256/0/180] [ 450.680657] Key type lgssc registered [ 452.137347] Lustre: Echo OBD driver; http://www.lustre.org/ [ 515.864223] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing load_modules_local [ 531.756846] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 531.814001] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 533.207815] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 533.276219] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 533.416376] Lustre: lustre-MDT0000: new disk, initializing [ 533.536177] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 533.601204] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 538.799443] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 553.937640] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 554.087199] Lustre: 19274: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 [ 554.114256] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 554.119732] Lustre: Skipped 1 previous similar message [ 554.194221] Lustre: lustre-MDT0001: new disk, initializing [ 554.279538] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 554.330982] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 554.350750] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 559.495765] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 564.995839] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 575.916456] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 576.152911] Lustre: lustre-OST0000: new disk, initializing [ 576.163199] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 576.172716] Lustre: 21210:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 576.250797] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 583.606019] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 584.226159] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 584.254757] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 584.321534] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 598.543515] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 598.675474] Lustre: lustre-OST0001: new disk, initializing [ 598.679876] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 598.691848] Lustre: 22234:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 598.773421] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 605.456853] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 607.806726] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 607.820579] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 607.939137] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 617.690271] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 625.871456] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 636.331680] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 13:43:12 (1789062192) === [ 639.681900] Lustre: DEBUG MARKER: == sanity-lfsck test 0: Control LFSCK manually =========== 13:43:15 (1789062195) [ 639.884037] Lustre: 19281:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 251 < left 278, rollback = 2 [ 639.897159] Lustre: 19281:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 639.907190] Lustre: 19281:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 639.917903] Lustre: 19281:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 639.929110] Lustre: 19281:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 639.935884] Lustre: 19281:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 640.407181] Lustre: 21218:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 640.430141] Lustre: 21218:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 8 previous similar messages [ 640.435171] Lustre: 21218:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 640.441630] Lustre: 21218:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 8 previous similar messages [ 640.450229] Lustre: 21218:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 640.459772] Lustre: 21218:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 8 previous similar messages [ 640.469894] Lustre: 21218:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 640.478404] Lustre: 21218:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 8 previous similar messages [ 640.488622] Lustre: 21218:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 640.494679] Lustre: 21218:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 8 previous similar messages [ 640.509643] Lustre: 21218:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 640.520793] Lustre: 21218:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 8 previous similar messages [ 641.460929] Lustre: 19279:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 641.469821] Lustre: 19279:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 29 previous similar messages [ 641.475645] Lustre: 19279:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 641.484891] Lustre: 19279:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 29 previous similar messages [ 641.489686] Lustre: 19279:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 641.494820] Lustre: 19279:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 29 previous similar messages [ 641.505730] Lustre: 19279:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 641.512222] Lustre: 19279:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 29 previous similar messages [ 641.520544] Lustre: 19279:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 641.526321] Lustre: 19279:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 29 previous similar messages [ 641.532579] Lustre: 19279:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 641.538812] Lustre: 19279:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 29 previous similar messages [ 643.511068] Lustre: 19280:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 643.519748] Lustre: 19280:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 86 previous similar messages [ 643.532646] Lustre: 19280:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 643.544224] Lustre: 19280:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 86 previous similar messages [ 643.563619] Lustre: 19280:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 643.576372] Lustre: 19280:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 86 previous similar messages [ 643.582728] Lustre: 19280:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 643.595093] Lustre: 19280:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 86 previous similar messages [ 643.599523] Lustre: 19280:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 643.603647] Lustre: 19280:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 86 previous similar messages [ 643.609529] Lustre: 19280:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 643.615486] Lustre: 19280:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 86 previous similar messages [ 649.200862] Lustre: *** cfs_fail_loc=1600, val=3*** [ 650.254215] Lustre: 21200:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-OST0001: opcode 2: before 259 < left 274, rollback = 2 [ 650.270392] Lustre: 21200:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 150 previous similar messages [ 650.297731] Lustre: 21200:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 650.310351] Lustre: 21200:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 150 previous similar messages [ 650.320379] Lustre: 21200:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/1, xattr_set: 2/274/0 [ 650.333169] Lustre: 21200:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 150 previous similar messages [ 650.346655] Lustre: 21200:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 0/0/0, punch: 0/0/0, quota 7/225/0 [ 650.359229] Lustre: 21200:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 150 previous similar messages [ 650.365356] Lustre: 21200:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 650.371389] Lustre: 21200:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 150 previous similar messages [ 650.376618] Lustre: 21200:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 650.380738] Lustre: 21200:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 150 previous similar messages [ 654.073984] Lustre: *** cfs_fail_loc=1600, val=3*** [ 667.572606] Lustre: 21201:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-OST0001: opcode 2: before 259 < left 274, rollback = 2 [ 667.589650] Lustre: 21201:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 53 previous similar messages [ 667.602129] Lustre: 23423:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 667.623095] Lustre: 21201:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/1, xattr_set: 2/274/0 [ 667.623108] Lustre: 21201:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 53 previous similar messages [ 667.623114] Lustre: 21201:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 0/0/0, punch: 0/0/0, quota 7/225/0 [ 667.623117] Lustre: 21201:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 53 previous similar messages [ 667.623123] Lustre: 21201:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 667.623125] Lustre: 21201:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 53 previous similar messages [ 667.623130] Lustre: 21201:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 667.623133] Lustre: 21201:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 53 previous similar messages [ 667.742458] Lustre: 23423:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 61 previous similar messages [ 672.226742] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 672.241140] 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 [ 672.271197] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 674.786108] 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 [ 674.786709] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 674.814304] Lustre: Skipped 1 previous similar message [ 674.836466] Lustre: Skipped 3 previous similar messages [ 676.763198] Lustre: server umount lustre-MDT0000 complete [ 681.096148] LustreError: 19265:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1789062239 with bad export cookie 11197016835463258431 [ 681.098429] LustreError: MGC192.168.204.144@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 681.106321] LustreError: 19265:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 681.574519] Lustre: server umount lustre-MDT0001 complete [ 696.947206] Lustre: server umount lustre-OST0000 complete [ 701.409524] Lustre: 16412:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789062243/real 1789062243] req@ffff9ae20cd62d80 x1875967482119424/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1789062259 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 701.465142] 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 [ 701.487864] Lustre: Skipped 1 previous similar message [ 702.218425] Lustre: server umount lustre-OST0001 complete [ 712.517144] Lustre: DEBUG MARKER: == sanity-lfsck test 1a: LFSCK can find out and repair crashed FID-in-dirent ========================================================== 13:44:28 (1789062268) [ 729.023563] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing load_modules_local [ 741.546953] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 741.895752] LustreError: 26295:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 741.909995] LustreError: 26295:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 5 previous similar messages [ 741.976255] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 746.933667] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 746.985177] LustreError: 26296:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 751.102275] LustreError: 26295:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 756.195788] LustreError: 26296:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 757.849045] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 758.075777] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 762.988221] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 766.596488] Lustre: 27435:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 776.140601] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 776.727345] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 783.906614] LustreError: 27789:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 787.000657] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:41 to 0x280000401:65) [ 787.881931] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 792.034181] LustreError: 27790:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 792.085396] LustreError: 27790:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 3 previous similar messages [ 800.897517] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 806.379981] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:40 to 0x2c0000401:65) [ 808.077633] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 818.041960] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 822.626437] Lustre: 29307:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 824.618670] Lustre: 27703:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 824.625146] Lustre: 27703:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 14 previous similar messages [ 824.629362] Lustre: 27703:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 824.633731] Lustre: 27703:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 7 previous similar messages [ 824.638817] Lustre: 27703:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 824.644508] Lustre: 27703:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 15 previous similar messages [ 824.648572] Lustre: 27703:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 824.653842] Lustre: 27703:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 15 previous similar messages [ 824.661095] Lustre: 27703:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 824.665206] Lustre: 27703:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 15 previous similar messages [ 824.673387] Lustre: 27703:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 824.677139] Lustre: 27703:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 15 previous similar messages [ 830.563051] Lustre: *** cfs_fail_loc=1501, val=0*** [ 839.496951] Lustre: Failing over lustre-MDT0000 [ 839.993691] Lustre: server umount lustre-MDT0000 complete [ 840.167439] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 840.172847] 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 [ 840.183322] LustreError: 29320:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 840.202624] LustreError: 29320:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 2 previous similar messages [ 850.969779] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 851.098816] LustreError: MGC192.168.204.144@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 851.518693] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 851.528180] Lustre: Skipped 1 previous similar message [ 851.575146] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 856.549482] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 856.573885] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 856.608055] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 856.651783] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:105 to 0x280000401:129) [ 856.658201] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:105 to 0x2c0000401:129) [ 856.813357] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 860.860517] Lustre: *** cfs_fail_loc=1505, val=0*** [ 869.096167] Lustre: DEBUG MARKER: == sanity-lfsck test 1b: LFSCK can find out and repair the missing FID-in-LMA ========================================================== 13:47:05 (1789062425) [ 870.595947] Lustre: 26291:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 870.603843] Lustre: 26291:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 322 previous similar messages [ 870.609697] Lustre: 26291:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 870.616601] Lustre: 26291:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 870.621375] Lustre: 26291:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 870.626274] Lustre: 26291:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 870.634361] Lustre: 26291:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 870.639686] Lustre: 26291:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 870.645208] Lustre: 26291:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 870.649409] Lustre: 26291:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 870.655205] Lustre: 26291:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 870.664751] Lustre: 26291:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 877.748721] Lustre: *** cfs_fail_loc=1502, val=0*** [ 889.329400] Lustre: Failing over lustre-MDT0000 [ 889.779434] Lustre: server umount lustre-MDT0000 complete [ 892.384593] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 892.386774] 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 [ 892.409545] LustreError: 26291:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 892.423467] Lustre: Skipped 5 previous similar messages [ 892.454234] LustreError: 26291:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 11 previous similar messages [ 902.981679] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 903.164564] LustreError: MGC192.168.204.144@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 903.459596] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 907.937216] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 908.779505] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 908.807111] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 908.812810] Lustre: Skipped 3 previous similar messages [ 908.843863] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 908.897187] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:169 to 0x280000401:193) [ 908.897308] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:169 to 0x2c0000401:193) [ 912.258654] Lustre: *** cfs_fail_loc=1505, val=0*** [ 920.407882] Lustre: DEBUG MARKER: == sanity-lfsck test 1c: LFSCK can find out and repair lost FID-in-dirent ========================================================== 13:47:56 (1789062476) [ 927.835892] Lustre: *** cfs_fail_loc=1504, val=0*** [ 927.838182] Lustre: *** cfs_fail_loc=1504, val=0*** [ 927.850699] Lustre: Skipped 1 previous similar message [ 936.771287] Lustre: Failing over lustre-MDT0000 [ 937.079024] Lustre: server umount lustre-MDT0000 complete [ 939.489206] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 939.490496] 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 [ 939.525175] Lustre: Skipped 3 previous similar messages [ 948.780456] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 948.961100] LustreError: MGC192.168.204.144@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 949.191644] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 949.197902] Lustre: Skipped 1 previous similar message [ 949.244261] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 954.345087] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 954.361400] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 954.374451] Lustre: Skipped 3 previous similar messages [ 954.388226] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 954.428808] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:233 to 0x2c0000401:257) [ 954.429558] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:233 to 0x280000401:257) [ 954.754754] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 958.409322] Lustre: *** cfs_fail_loc=1505, val=0*** [ 969.213277] Lustre: DEBUG MARKER: == sanity-lfsck test 2a: LFSCK can find out and repair crashed linkEA entry ========================================================== 13:48:44 (1789062524) [ 970.373386] Lustre: 26291:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 256 < left 278, rollback = 2 [ 970.381731] Lustre: 26291:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 644 previous similar messages [ 970.387541] Lustre: 26291:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 970.391693] Lustre: 26291:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 970.397481] Lustre: 26291:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 970.403076] Lustre: 26291:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 970.409340] Lustre: 26291:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 970.415963] Lustre: 26291:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 970.421213] Lustre: 26291:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 970.425216] Lustre: 26291:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 970.431569] Lustre: 26291:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 970.436908] Lustre: 26291:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 976.536066] Lustre: *** cfs_fail_loc=1603, val=0*** [ 985.245767] Lustre: Failing over lustre-MDT0000 [ 985.478371] Lustre: server umount lustre-MDT0000 complete [ 990.181515] 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 [ 990.187364] LustreError: 26296:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 990.187595] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 990.207749] Lustre: Skipped 3 previous similar messages [ 990.218493] LustreError: 26296:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 17 previous similar messages [ 996.971507] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 997.097486] LustreError: MGC192.168.204.144@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 997.377963] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1002.466438] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1002.474159] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1002.479913] Lustre: Skipped 3 previous similar messages [ 1002.504949] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1002.562073] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:297 to 0x280000401:321) [ 1002.565425] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:297 to 0x2c0000401:321) [ 1002.871666] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1014.212858] Lustre: DEBUG MARKER: == sanity-lfsck test 2b: LFSCK can find out and remove invalid linkEA entry ========================================================== 13:49:30 (1789062570) [ 1023.153531] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1034.509191] Lustre: Failing over lustre-MDT0000 [ 1035.003355] Lustre: server umount lustre-MDT0000 complete [ 1038.318471] 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 [ 1038.319424] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1038.344713] Lustre: Skipped 3 previous similar messages [ 1048.479290] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1048.641945] LustreError: MGC192.168.204.144@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1048.942228] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1054.185202] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1054.190299] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1054.204128] Lustre: Skipped 3 previous similar messages [ 1054.242531] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1054.298162] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:361 to 0x2c0000401:385) [ 1054.298548] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:361 to 0x280000401:385) [ 1054.649527] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1065.707468] Lustre: DEBUG MARKER: == sanity-lfsck test 2c: LFSCK can find out and remove repeated linkEA entry ========================================================== 13:50:21 (1789062621) [ 1073.157297] Lustre: *** cfs_fail_loc=1605, val=0*** [ 1082.324628] Lustre: Failing over lustre-MDT0000 [ 1082.668880] Lustre: server umount lustre-MDT0000 complete [ 1084.897471] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1094.562973] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1094.760948] LustreError: MGC192.168.204.144@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1095.031663] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1095.041701] Lustre: Skipped 2 previous similar messages [ 1095.096855] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1100.068681] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1100.270777] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1100.283167] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1100.292673] Lustre: Skipped 3 previous similar messages [ 1100.321910] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1100.364413] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:425 to 0x2c0000401:449) [ 1100.364594] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:425 to 0x280000401:449) [ 1110.524273] Lustre: DEBUG MARKER: == sanity-lfsck test 2d: LFSCK can recover the missing linkEA entry ========================================================== 13:51:06 (1789062666) [ 1111.964554] Lustre: 26291:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 1111.978518] Lustre: 26291:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 968 previous similar messages [ 1111.986735] Lustre: 26291:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 1112.001707] Lustre: 26291:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 968 previous similar messages [ 1112.008176] Lustre: 26291:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 1112.014201] Lustre: 26291:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 968 previous similar messages [ 1112.025815] Lustre: 26291:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 1112.038777] Lustre: 26291:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 968 previous similar messages [ 1112.043644] Lustre: 26291:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 1112.048391] Lustre: 26291:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 968 previous similar messages [ 1112.052912] Lustre: 26291:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 1112.057146] Lustre: 26291:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 968 previous similar messages [ 1117.602157] Lustre: *** cfs_fail_loc=161d, val=0*** [ 1126.938165] Lustre: Failing over lustre-MDT0000 [ 1127.551661] Lustre: server umount lustre-MDT0000 complete [ 1130.978021] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1130.978724] Lustre: lustre-MDT0000-lwp-MDT0001: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 1130.986824] LustreError: 27703:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1130.986836] LustreError: 27703:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 26 previous similar messages [ 1131.050019] Lustre: Skipped 7 previous similar messages [ 1139.584706] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1139.726408] LustreError: MGC192.168.204.144@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1140.144337] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1145.181908] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1145.315495] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1145.325589] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1145.344107] Lustre: Skipped 3 previous similar messages [ 1145.367310] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1145.409202] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:489 to 0x2c0000401:513) [ 1145.410224] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:489 to 0x280000401:513) [ 1155.237789] Lustre: DEBUG MARKER: == sanity-lfsck test 2e: namespace LFSCK can verify remote object linkEA ========================================================== 13:51:51 (1789062711) [ 1157.935556] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1170.723294] Lustre: DEBUG MARKER: == sanity-lfsck test 3: LFSCK can verify multiple-linked objects ========================================================== 13:52:06 (1789062726) [ 1177.984190] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1179.081548] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1193.087554] Lustre: DEBUG MARKER: == sanity-lfsck test 4: FID-in-dirent can be rebuilt after MDT file-level backup/restore ========================================================== 13:52:28 (1789062748) [ 1228.979250] Lustre: Failing over lustre-MDT0000 [ 1229.251152] Lustre: server umount lustre-MDT0000 complete [ 1232.353667] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1236.061640] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1247.959151] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1248.737375] Lustre: 16412:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789062790/real 1789062790] req@ffff9ae20523c000 x1875967482785664/t0(0) o400->MGC192.168.204.144@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789062806 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1248.776945] LustreError: MGC192.168.204.144@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1261.109707] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1261.132820] Lustre: lustre-MDT0000: reset Object Index mappings [ 1273.325690] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x9b63cb7ccddd3ebc [ 1273.350040] Lustre: MGC192.168.204.144@tcp: Connection restored to 0@lo (at 0@lo) [ 1273.356216] Lustre: Skipped 3 previous similar messages [ 1273.903133] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1278.948362] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1279.015757] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1279.079631] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:592 to 0x2c0000401:609) [ 1279.086639] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:592 to 0x280000401:609) [ 1279.297664] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1283.740883] LustreError: 42966:0:(lfsck_engine.c:1018:lfsck_master_engine()) lustre-MDT0000-osd: master engine fail to verify the .lustre/lost+found/, go ahead: rc = -115 [ 1283.769527] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1284.833190] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1285.856235] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1293.247376] Lustre: Failing over lustre-MDT0000 [ 1293.915965] Lustre: server umount lustre-MDT0000 complete [ 1294.307374] 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 [ 1294.332678] Lustre: Skipped 5 previous similar messages [ 1308.019292] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1313.846575] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:592 to 0x2c0000401:641) [ 1313.850529] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:592 to 0x280000401:641) [ 1314.255266] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1318.556113] Lustre: *** cfs_fail_loc=1505, val=0*** [ 1330.143570] Lustre: DEBUG MARKER: == sanity-lfsck test 5: LFSCK can handle IGIF object upgrading ========================================================== 13:54:45 (1789062885) [ 1334.495829] Lustre: *** cfs_fail_loc=1504, val=0*** [ 1348.667791] Lustre: Failing over lustre-MDT0000 [ 1349.110909] Lustre: server umount lustre-MDT0000 complete [ 1356.430951] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1365.992445] Lustre: 16412:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789062907/real 1789062907] req@ffff9ae205dd0700 x1875967482891648/t0(0) o400->MGC192.168.204.144@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1789062923 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1370.742078] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1386.111414] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1386.153716] Lustre: lustre-MDT0000: reset Object Index mappings [ 1391.585273] LustreError: 16408:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9ae20cd62d80 x1875967482903808/t0(0) o250->MGC192.168.204.144@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 [ 1391.628205] LustreError: 26292:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1391.657077] LustreError: 26292:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 98 previous similar messages [ 1392.164599] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1392.186165] Lustre: Skipped 3 previous similar messages [ 1392.268304] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1392.283232] Lustre: Skipped 1 previous similar message [ 1397.227321] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1397.242672] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1397.244257] Lustre: Skipped 1 previous similar message [ 1397.273559] Lustre: Skipped 8 previous similar messages [ 1397.315623] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1397.337061] Lustre: Skipped 1 previous similar message [ 1397.414797] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:681 to 0x280000401:705) [ 1397.415164] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:681 to 0x2c0000401:705) [ 1399.902923] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1406.743321] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1406.761710] Lustre: Skipped 1 previous similar message [ 1410.925826] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1410.936509] Lustre: Skipped 3 previous similar messages [ 1422.416369] Lustre: Failing over lustre-MDT0000 [ 1422.956393] Lustre: server umount lustre-MDT0000 complete [ 1436.702851] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1436.807866] LustreError: MGC192.168.204.144@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1436.821643] LustreError: Skipped 2 previous similar messages [ 1442.389768] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:681 to 0x2c0000401:737) [ 1442.402825] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:681 to 0x280000401:737) [ 1443.282297] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1448.484026] Lustre: *** cfs_fail_loc=1505, val=0*** [ 1448.509833] Lustre: Skipped 84 previous similar messages [ 1461.138519] Lustre: DEBUG MARKER: == sanity-lfsck test 6a: LFSCK resumes from last checkpoint (1) ========================================================== 13:56:55 (1789063015) [ 1463.303604] Lustre: 26291:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 1463.309186] Lustre: 26291:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 1306 previous similar messages [ 1463.312944] Lustre: 26291:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 1463.316738] Lustre: 26291:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1306 previous similar messages [ 1463.320739] Lustre: 26291:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 1463.324924] Lustre: 26291:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1306 previous similar messages [ 1463.329615] Lustre: 26291:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 1463.333874] Lustre: 26291:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1306 previous similar messages [ 1463.337983] Lustre: 26291:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 1463.344802] Lustre: 26291:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1306 previous similar messages [ 1463.348506] Lustre: 26291:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 1463.352470] Lustre: 26291:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1306 previous similar messages [ 1471.810550] Lustre: *** cfs_fail_loc=1600, val=1*** [ 1471.812526] Lustre: Skipped 4 previous similar messages [ 1495.356980] Lustre: DEBUG MARKER: == sanity-lfsck test 6b: LFSCK resumes from last checkpoint (2) ========================================================== 13:57:31 (1789063051) [ 1505.797972] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1505.812319] Lustre: Skipped 10 previous similar messages [ 1534.218910] Lustre: DEBUG MARKER: == sanity-lfsck test 7a: non-stopped LFSCK should auto restarts after MDS remount (1) ========================================================== 13:58:10 (1789063090) [ 1550.772495] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1550.775254] Lustre: Skipped 13 previous similar messages [ 1557.773828] Lustre: Failing over lustre-MDT0000 [ 1558.195178] Lustre: server umount lustre-MDT0000 complete [ 1560.042580] 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 [ 1560.061940] Lustre: Skipped 14 previous similar messages [ 1569.470206] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1569.988686] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1570.008529] Lustre: Skipped 1 previous similar message [ 1575.395130] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1575.405134] Lustre: Skipped 1 previous similar message [ 1575.406049] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1575.425713] Lustre: Skipped 7 previous similar messages [ 1575.460518] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1575.475311] Lustre: Skipped 1 previous similar message [ 1575.552713] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:853 to 0x280000401:897) [ 1575.553158] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:854 to 0x2c0000401:897) [ 1576.663314] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1588.967350] Lustre: DEBUG MARKER: == sanity-lfsck test 7b: non-stopped LFSCK should auto restarts after MDS remount (2) ========================================================== 13:59:04 (1789063144) [ 1607.446114] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing load_modules_local [ 1631.282926] Lustre: 52917:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 1657.475971] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1661.861760] Lustre: 54053:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 1670.358652] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1670.361561] Lustre: Skipped 81 previous similar messages [ 1674.238609] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1675.297360] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1676.321053] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1678.369821] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1678.380781] Lustre: Skipped 1 previous similar message [ 1681.685440] Lustre: Failing over lustre-MDT0000 [ 1682.212911] Lustre: server umount lustre-MDT0000 complete [ 1693.287459] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1693.503457] LustreError: MGC192.168.204.144@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1693.525779] LustreError: Skipped 1 previous similar message [ 1699.458488] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:946 to 0x280000401:961) [ 1699.459229] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:947 to 0x2c0000401:993) [ 1699.864250] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1711.406394] Lustre: DEBUG MARKER: == sanity-lfsck test 8: LFSCK state machine ============== 14:01:07 (1789063267) [ 1714.657816] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1714.664541] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1714.669188] LustreError: Skipped 2 previous similar messages [ 1714.685425] Lustre: Skipped 3 previous similar messages [ 1719.779517] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1719.791693] Lustre: Skipped 3 previous similar messages [ 1720.460179] Lustre: server umount lustre-MDT0000 complete [ 1724.587238] LustreError: 26275:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1789063282 with bad export cookie 11197016835463473618 [ 1724.611467] LustreError: 26275:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 1724.901422] Lustre: server umount lustre-MDT0001 complete [ 1739.993478] Lustre: server umount lustre-OST0000 complete [ 1740.240149] Lustre: 16409:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789063282/real 1789063282] req@ffff9ae20ff8e680 x1875967483261952/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1789063298 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1745.225956] Lustre: server umount lustre-OST0001 complete [ 1753.770573] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_hostid [ 1764.225564] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing load_modules_local [ 1814.230603] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing load_modules_local [ 1826.129144] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1826.561223] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 1826.611540] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 1826.817443] Lustre: lustre-MDT0000: new disk, initializing [ 1827.021791] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 1833.465882] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1846.842862] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1847.064135] Lustre: 59130: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 [ 1847.106708] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 1847.111054] Lustre: Skipped 1 previous similar message [ 1847.186528] Lustre: lustre-MDT0001: new disk, initializing [ 1847.272763] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 1847.297113] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 1852.789417] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1859.000960] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 1866.034639] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 1866.309577] Lustre: lustre-OST0000: new disk, initializing [ 1866.322027] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 1866.331311] Lustre: 60765:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 1867.685400] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 1867.709238] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 1867.840874] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 1874.631628] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1887.571382] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 1887.674208] Lustre: lustre-OST0001: new disk, initializing [ 1887.677661] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 1887.685763] Lustre: 61638:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 1888.907848] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 1888.923338] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 1889.064057] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 1895.849050] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1907.099096] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1911.451565] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 1923.004681] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1924.012211] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1924.015934] Lustre: Skipped 19 previous similar messages [ 1929.112579] Lustre: *** cfs_fail_loc=1601, val=2*** [ 1929.118449] Lustre: Skipped 6 previous similar messages [ 1950.941260] Lustre: Failing over lustre-MDT0000 [ 1951.405841] Lustre: server umount lustre-MDT0000 complete [ 1954.808183] LustreError: 59142:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1954.849579] LustreError: 59142:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 32 previous similar messages [ 1965.641660] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1966.049497] Lustre: lustre-MDT0000: Not available for connect from 0@lo (not set up) [ 1966.061675] Lustre: Skipped 3 previous similar messages [ 1966.286887] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1966.291270] Lustre: Skipped 7 previous similar messages [ 1966.345813] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1966.372967] Lustre: Skipped 1 previous similar message [ 1971.680644] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1971.693795] Lustre: Skipped 1 previous similar message [ 1971.697801] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1971.716516] Lustre: Skipped 7 previous similar messages [ 1971.749777] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1971.760975] Lustre: Skipped 1 previous similar message [ 1971.870776] Lustre: *** cfs_fail_loc=160b, val=2*** [ 1971.903039] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:65) [ 1971.911786] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:65) [ 1972.886722] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1984.287185] Lustre: Failing over lustre-MDT0000 [ 1984.678767] Lustre: server umount lustre-MDT0000 complete [ 1987.042435] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1987.058659] LustreError: Skipped 1 previous similar message [ 1996.840706] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 2002.476219] Lustre: *** cfs_fail_loc=160b, val=2*** [ 2002.491621] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:97) [ 2002.494411] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:97) [ 2003.154574] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2010.676332] Lustre: Failing over lustre-MDT0000 [ 2013.132498] Lustre: server umount lustre-MDT0000 complete [ 2024.497088] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 2030.141994] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:129) [ 2030.147447] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:129) [ 2031.067475] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2038.423628] Lustre: *** cfs_fail_loc=1602, val=2*** [ 2038.435578] Lustre: Skipped 3 previous similar messages [ 2053.787139] Lustre: DEBUG MARKER: == sanity-lfsck test 9a: LFSCK speed control (1) ========= 14:06:49 (1789063609) [ 2072.615386] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing load_modules_local [ 2095.163928] Lustre: 68545:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 2121.349398] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 2125.339093] Lustre: 69682:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 2145.352257] Lustre: 60772:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 2145.369400] Lustre: 60772:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 2836 previous similar messages [ 2145.382295] Lustre: 60772:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 2145.395016] Lustre: 60772:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 2836 previous similar messages [ 2145.404941] Lustre: 60772:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 2145.416295] Lustre: 60772:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 2836 previous similar messages [ 2145.426103] Lustre: 60772:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 2145.437386] Lustre: 60772:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 2836 previous similar messages [ 2145.449120] Lustre: 60772:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 2145.481594] Lustre: 60772:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 2836 previous similar messages [ 2145.491225] Lustre: 60772:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 2145.497563] Lustre: 60772:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 2836 previous similar messages [ 2273.213519] Lustre: DEBUG MARKER: == sanity-lfsck test 9b: LFSCK speed control (2) ========= 14:10:29 (1789063829) [ 2336.797926] Lustre: *** cfs_fail_loc=1604, val=0*** [ 2336.800015] Lustre: Skipped 4 previous similar messages [ 2365.633188] Lustre: *** cfs_fail_loc=160c, val=0*** [ 2365.640076] Lustre: Skipped 10 previous similar messages [ 2407.368743] Lustre: DEBUG MARKER: == sanity-lfsck test 10: System is available during LFSCK scanning ========================================================== 14:12:43 (1789063963) [ 2460.266710] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2461.287906] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2461.290456] Lustre: Skipped 43 previous similar messages [ 2463.293358] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2463.295756] Lustre: Skipped 97 previous similar messages [ 2467.298213] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2467.306146] Lustre: Skipped 194 previous similar messages [ 2475.325250] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2475.332988] Lustre: Skipped 335 previous similar messages [ 2491.336142] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2491.342763] Lustre: Skipped 628 previous similar messages [ 2523.446092] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2523.451207] Lustre: Skipped 1373 previous similar messages [ 2543.685896] Lustre: *** cfs_fail_loc=1604, val=0*** [ 2543.691488] Lustre: Skipped 2599 previous similar messages [ 2777.319566] Lustre: 59136:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 252 < left 278, rollback = 2 [ 2777.334743] Lustre: 59136:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 36821 previous similar messages [ 2777.341417] Lustre: 59136:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 2777.347215] Lustre: 59136:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 36821 previous similar messages [ 2777.355429] Lustre: 59136:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 2777.364891] Lustre: 59136:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 36821 previous similar messages [ 2777.371824] Lustre: 59136:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/1, punch: 0/0/0, quota 1/3/2 [ 2777.383625] Lustre: 59136:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 36821 previous similar messages [ 2777.393657] Lustre: 59136:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/1, delete: 0/0/0 [ 2777.398977] Lustre: 59136:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 36821 previous similar messages [ 2777.406685] Lustre: 59136:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 2777.415589] Lustre: 59136:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 36821 previous similar messages [ 2837.354387] Lustre: DEBUG MARKER: == sanity-lfsck test 11a: LFSCK can rebuild lost last_id ========================================================== 14:19:53 (1789064393) [ 3023.334167] 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 [ 3023.335202] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3023.335701] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3023.350604] Lustre: Skipped 23 previous similar messages [ 3023.381507] LustreError: Skipped 1 previous similar message [ 3028.451041] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3028.462217] Lustre: Skipped 6 previous similar messages [ 3033.569215] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3033.580821] Lustre: Skipped 2 previous similar messages [ 3035.104444] Lustre: lustre-MDT0000 is waiting for obd_unlinked_exports more than 8 seconds. The obd refcount = 3. Is it stuck? [ 3035.486930] Lustre: server umount lustre-MDT0000 complete [ 3038.692975] LustreError: 67369:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3038.724351] LustreError: 67369:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 31 previous similar messages [ 3039.967075] LustreError: 68547:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1789064597 with bad export cookie 11197016835463492707 [ 3039.970042] LustreError: MGC192.168.204.144@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3039.990553] LustreError: 68547:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 3040.016581] LustreError: Skipped 4 previous similar messages [ 3040.360892] Lustre: server umount lustre-MDT0001 complete [ 3056.058753] Lustre: server umount lustre-OST0000 complete [ 3059.176305] Lustre: 16411:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789064601/real 1789064601] req@ffff9ae2144ff100 x1875967487162112/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1789064617 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3060.193500] Lustre: 16409:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789064602/real 1789064602] req@ffff9ae31e2ed500 x1875967487162368/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1789064618 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3060.840915] Lustre: server umount lustre-OST0001 complete [ 3069.298097] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: (null) [ 3080.771075] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 3096.416677] LustreError: Failed to get MGS log lustre-sptlrpc and no local copy. [ 3101.540812] LustreError: 74726:0:(mgc_request.c:233:do_config_log_add()) MGC192.168.204.144@tcp: failed processing log, type 4: rc = -110 [ 3127.266195] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 3127.272290] Lustre: Skipped 2 previous similar messages [ 3135.725139] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3140.927859] Lustre: 75311:0:(ofd_dev.c:561:ofd_lfsck_out_notify()) lustre-OST0000: Found crashed LAST_ID, deny creating new OST-object on the device until the LAST_ID rebuilt successfully. [ 3140.952646] Lustre: *** cfs_fail_loc=160e, val=3*** [ 3143.978162] Lustre: 75311:0:(ofd_dev.c:573:ofd_lfsck_out_notify()) lustre-OST0000: Rebuilt crashed LAST_ID files successfully. [ 3154.239720] Lustre: DEBUG MARKER: == sanity-lfsck test 11b: LFSCK can rebuild crashed last_id ========================================================== 14:25:09 (1789064709) [ 3171.122666] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing load_modules_local [ 3183.304538] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3183.668775] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3272 to 0x280000401:3297) [ 3188.997429] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3198.643973] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3203.882997] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3207.723253] Lustre: 77929:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3226.833617] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3232.263469] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3207 to 0x2c0000401:3233) [ 3236.350885] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3244.927996] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3249.740039] Lustre: 79428:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 3256.062274] Lustre: *** cfs_fail_loc=160d, val=0*** [ 3256.770481] Lustre: *** cfs_fail_loc=160d, val=0*** [ 3256.780604] Lustre: Skipped 3 previous similar messages [ 3267.714522] Lustre: Failing over lustre-OST0000 [ 3267.836225] Lustre: server umount lustre-OST0000 complete [ 3268.069832] 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 [ 3268.109255] Lustre: Skipped 2 previous similar messages [ 3282.265983] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3282.477524] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 3282.481685] Lustre: Skipped 2 previous similar messages [ 3284.516053] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 3284.539425] Lustre: Skipped 2 previous similar messages [ 3284.570471] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 3284.583382] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 3284.600086] Lustre: Skipped 2 previous similar messages [ 3284.604423] Lustre: Skipped 11 previous similar messages [ 3284.604583] Lustre: *** cfs_fail_loc=215, val=0*** [ 3289.204728] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3290.083253] Lustre: *** cfs_fail_loc=215, val=0*** [ 3290.089687] Lustre: Skipped 1 previous similar message [ 3294.006523] Lustre: 80827:0:(ofd_dev.c:561:ofd_lfsck_out_notify()) lustre-OST0000: Found crashed LAST_ID, deny creating new OST-object on the device until the LAST_ID rebuilt successfully. [ 3294.028482] Lustre: 80827:0:(ofd_dev.c:573:ofd_lfsck_out_notify()) lustre-OST0000: Rebuilt crashed LAST_ID files successfully. [ 3295.206634] Lustre: *** cfs_fail_loc=215, val=0*** [ 3295.214152] Lustre: Skipped 1 previous similar message [ 3297.110229] Lustre: Failing over lustre-OST0000 [ 3297.278731] Lustre: server umount lustre-OST0000 complete [ 3307.356399] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3309.598367] Lustre: *** cfs_fail_loc=215, val=0*** [ 3314.656964] Lustre: *** cfs_fail_loc=215, val=0*** [ 3314.665450] Lustre: Skipped 2 previous similar messages [ 3315.150643] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3322.850620] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3322.864221] Lustre: Skipped 4 previous similar messages [ 3327.973049] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3327.997730] Lustre: Skipped 3 previous similar messages [ 3329.011303] Lustre: server umount lustre-MDT0000 complete [ 3333.024803] LustreError: 74732:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1789064891 with bad export cookie 11197016835465073055 [ 3333.029929] LustreError: MGC192.168.204.144@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3333.033054] LustreError: 74732:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 3333.568516] Lustre: server umount lustre-MDT0001 complete [ 3340.895480] Lustre: server umount lustre-OST0000 complete [ 3345.230580] Lustre: server umount lustre-OST0001 complete [ 3356.138168] Lustre: DEBUG MARKER: == sanity-lfsck test 12a: single command to trigger LFSCK on all devices ========================================================== 14:28:31 (1789064911) [ 3372.811546] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing load_modules_local [ 3385.209803] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3390.865811] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3400.913776] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3406.649911] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3409.685911] Lustre: 85219:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3416.985615] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3424.094123] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3430.699709] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3362 to 0x280000401:3393) [ 3433.795156] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3439.114455] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3207 to 0x2c0000401:3265) [ 3442.231943] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3452.085773] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3457.037789] Lustre: 87088:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 3458.878543] Lustre: 84073:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 256 < left 278, rollback = 2 [ 3458.893414] Lustre: 84073:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 400 previous similar messages [ 3458.904852] Lustre: 84073:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 3458.926285] Lustre: 84073:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 400 previous similar messages [ 3458.947571] Lustre: 84073:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3458.960398] Lustre: 84073:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 400 previous similar messages [ 3458.979069] Lustre: 84073:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 3459.010065] Lustre: 84073:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 400 previous similar messages [ 3459.041751] Lustre: 84073:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 3459.073898] Lustre: 84073:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 400 previous similar messages [ 3459.096658] Lustre: 84073:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3459.109351] Lustre: 84073:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 400 previous similar messages [ 3498.330863] Lustre: DEBUG MARKER: == sanity-lfsck test 12b: auto detect Lustre device ====== 14:30:54 (1789065054) [ 3517.922769] Lustre: DEBUG MARKER: == sanity-lfsck test 13: LFSCK can repair crashed lmm_oi ========================================================== 14:31:13 (1789065073) [ 3519.843078] Lustre: *** cfs_fail_loc=160f, val=0*** [ 3536.609275] Lustre: DEBUG MARKER: == sanity-lfsck test 14a: LFSCK can repair MDT-object with dangling LOV EA reference (1) ========================================================== 14:31:32 (1789065092) [ 3541.834964] Lustre: *** cfs_fail_loc=1610, val=0*** [ 3541.840262] Lustre: Skipped 3 previous similar messages [ 3596.257842] 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 [ 3596.283489] Lustre: Skipped 8 previous similar messages [ 3596.294855] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3596.297064] Lustre: Skipped 2 previous similar messages [ 3598.307159] Lustre: server umount lustre-MDT0000 complete [ 3603.427568] LustreError: 84058:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1789065161 with bad export cookie 11197016835465081504 [ 3603.444788] LustreError: MGC192.168.204.144@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3603.452732] LustreError: 84058:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 3604.143606] Lustre: server umount lustre-MDT0001 complete [ 3618.275944] Lustre: server umount lustre-OST0000 complete [ 3633.626954] Lustre: server umount lustre-OST0001 complete [ 3651.749201] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing load_modules_local [ 3666.563350] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3667.515626] LustreError: 91818:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3667.550362] LustreError: 91818:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 50 previous similar messages [ 3673.449370] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3685.676681] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3693.244527] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3697.235036] Lustre: 92959:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3706.224104] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3711.940127] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:116 to 0x280000400:161) [ 3712.947481] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3554 to 0x280000401:3585) [ 3714.965559] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3725.251716] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3730.923473] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3317 to 0x2c0000401:3361) [ 3730.934155] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:116 to 0x2c0000400:161) [ 3731.951583] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3740.329668] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3744.180631] Lustre: 94832:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 3752.535896] Lustre: DEBUG MARKER: == sanity-lfsck test 14b: LFSCK can repair MDT-object with dangling LOV EA reference (2) ========================================================== 14:35:08 (1789065308) [ 3758.652450] Lustre: *** cfs_fail_loc=1610, val=0*** [ 3758.660377] Lustre: Skipped 63 previous similar messages [ 3788.769980] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3788.775737] LustreError: Skipped 1 previous similar message [ 3788.781066] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3788.784630] Lustre: Skipped 4 previous similar messages [ 3793.931544] Lustre: server umount lustre-MDT0000 complete [ 3799.098545] LustreError: 91800:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1789065357 with bad export cookie 11197016835465109910 [ 3799.121876] LustreError: 91800:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 3 previous similar messages [ 3799.630389] Lustre: server umount lustre-MDT0001 complete [ 3814.344738] Lustre: server umount lustre-OST0000 complete [ 3818.278696] Lustre: 16411:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789065360/real 1789065360] req@ffff9ae20142df80 x1875967487651712/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1789065376 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3819.051772] Lustre: server umount lustre-OST0001 complete [ 3843.624552] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing load_modules_local [ 3856.307548] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3856.738308] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3856.748634] Lustre: Skipped 13 previous similar messages [ 3861.350190] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3870.085750] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3875.193502] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3878.483419] Lustre: 98867:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3886.053874] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3893.517886] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3895.672781] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:116 to 0x280000400:193) [ 3901.943792] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3682 to 0x280000401:3713) [ 3905.731270] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3911.147760] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3317 to 0x2c0000401:3393) [ 3911.155841] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:116 to 0x2c0000400:193) [ 3914.056602] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3923.174350] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3935.032375] Lustre: DEBUG MARKER: == sanity-lfsck test 15a: LFSCK can repair unmatched MDT-object/OST-object pairs (1) ========================================================== 14:38:11 (1789065491) [ 3940.040100] Lustre: *** cfs_fail_loc=1611, val=0*** [ 3940.043241] Lustre: Skipped 63 previous similar messages [ 3940.284572] Lustre: *** cfs_fail_loc=1611, val=0*** [ 3956.405395] Lustre: DEBUG MARKER: == sanity-lfsck test 15b: LFSCK can repair unmatched MDT-object/OST-object pairs (2) ========================================================== 14:38:32 (1789065512) [ 3959.462039] Lustre: *** cfs_fail_loc=1612, val=0*** [ 3959.520089] Lustre: *** cfs_fail_loc=1612, val=0*** [ 3959.521451] Lustre: Skipped 2 previous similar messages [ 3974.792507] Lustre: DEBUG MARKER: == sanity-lfsck test 15c: LFSCK can repair unmatched MDT-object/OST-object pairs (3) ========================================================== 14:38:50 (1789065530) [ 3976.660733] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_15c MDS newer than 2.7.55, LU-6475 [ 3978.696631] Lustre: DEBUG MARKER: == sanity-lfsck test 15d: LFSCK don't crash upon dir migration failure ========================================================== 14:38:54 (1789065534) [ 3985.567623] Lustre: *** cfs_fail_loc=1709, val=0*** [ 3985.573963] LustreError: 97735:0:(mdt_reint.c:2644:mdt_reint_migrate()) lustre-MDT0000: migrate [0x240002340:0x6c:0x0]/f60 failed: rc = -5 [ 4069.861065] 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 [ 4069.862746] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4069.885644] Lustre: Skipped 11 previous similar messages [ 4069.898586] Lustre: Skipped 7 previous similar messages [ 4075.686931] Lustre: server umount lustre-MDT0000 complete [ 4085.578035] LustreError: 102244:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1789065643 with bad export cookie 11197016835465124631 [ 4085.581906] LustreError: MGC192.168.204.144@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4085.586711] LustreError: 102244:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 4085.594138] LustreError: Skipped 1 previous similar message [ 4085.841615] Lustre: server umount lustre-MDT0001 complete [ 4105.471147] Lustre: server umount lustre-OST0000 complete [ 4106.785760] Lustre: 16412:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789065648/real 1789065648] req@ffff9ae31e2efb80 x1875967488298240/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1789065664 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4111.866000] Lustre: 16410:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789065653/real 1789065653] req@ffff9ae31e2eed80 x1875967488298624/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1789065669 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4116.003796] Lustre: 16411:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789065658/real 1789065658] req@ffff9ae207911c00 x1875967488298880/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1789065674 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4118.716493] Lustre: server umount lustre-OST0001 complete [ 4138.761371] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing unload_modules_local [ 4143.249433] Key type lgssc unregistered [ 4143.694152] LNet: 104579:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 4143.724403] LNetError: 104579:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 4143.749174] LNet: Removed LNI 192.168.204.144@tcp [ 4144.914167] Key type .llcrypt unregistered [ 4144.918231] Key type ._llcrypt unregistered [ 4174.911623] Key type ._llcrypt registered [ 4174.914316] Key type .llcrypt registered [ 4175.048500] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_hostid [ 4189.444175] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing load_modules_local [ 4190.567496] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 4190.650970] alg: No test for adler32 (adler32-zlib) [ 4191.997386] Lustre: Lustre: Build Version: 2.17.58_39_ga794951 [ 4192.462031] LNet: Added LNI 192.168.204.144@tcp [8/256/0/180] [ 4194.288481] Key type lgssc registered [ 4195.611276] Lustre: Echo OBD driver; http://www.lustre.org/ [ 4263.039577] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing load_modules_local [ 4281.844066] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 4281.875448] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4283.276112] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 4283.328336] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 4283.487376] Lustre: lustre-MDT0000: new disk, initializing [ 4283.625402] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4283.652830] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 4288.365878] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4306.327788] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4306.446808] Lustre: 109048: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 [ 4306.478327] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 4306.484977] Lustre: Skipped 1 previous similar message [ 4306.559106] Lustre: lustre-MDT0001: new disk, initializing [ 4306.626823] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 4306.669654] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 4306.692144] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 4312.556972] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4318.441612] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 4330.183666] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4330.494218] Lustre: lustre-OST0000: new disk, initializing [ 4330.503736] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 4330.509571] Lustre: 110987:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 4330.582545] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 4338.470868] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4338.753262] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 4338.763672] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 4338.926927] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 4352.516961] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4352.678042] Lustre: lustre-OST0001: new disk, initializing [ 4352.686810] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 4352.699148] Lustre: 112009:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 4352.775361] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 4360.071703] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4361.765738] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 4361.780443] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 4361.911942] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 4371.488898] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4380.032670] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 4386.209401] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 14:45:42 (1789065942) === [ 4393.282205] Lustre: DEBUG MARKER: == sanity-lfsck test 16: LFSCK can repair inconsistent MDT-object/OST-object owner ========================================================== 14:45:49 (1789065949) [ 4393.470801] Lustre: 109054:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 251 < left 278, rollback = 2 [ 4393.481444] Lustre: 109054:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4393.486690] Lustre: 109054:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4393.492183] Lustre: 109054:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 4393.503619] Lustre: 109054:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 4393.513241] Lustre: 109054:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4394.021513] Lustre: 109054:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 4394.031201] Lustre: 109054:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 6 previous similar messages [ 4394.036166] Lustre: 109054:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 4394.040646] Lustre: 109054:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 6 previous similar messages [ 4394.044337] Lustre: 109054:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4394.048638] Lustre: 109054:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 6 previous similar messages [ 4394.052178] Lustre: 109054:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 4394.059355] Lustre: 109054:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 6 previous similar messages [ 4394.067046] Lustre: 109054:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 4394.072947] Lustre: 109054:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 6 previous similar messages [ 4394.080559] Lustre: 109054:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4394.091663] Lustre: 109054:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 6 previous similar messages [ 4395.021936] Lustre: 109053:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 4395.030887] Lustre: 109053:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 146 previous similar messages [ 4395.047702] Lustre: 109053:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 4395.067717] Lustre: 109053:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 146 previous similar messages [ 4395.081478] Lustre: 109053:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4395.092506] Lustre: 109053:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 146 previous similar messages [ 4395.106806] Lustre: 109053:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 7/369/0 [ 4395.113677] Lustre: 109053:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 146 previous similar messages [ 4395.120521] Lustre: 109053:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 4395.130666] Lustre: 109053:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 146 previous similar messages [ 4395.138169] Lustre: 109053:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 4395.145473] Lustre: 109053:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 146 previous similar messages [ 4397.404572] Lustre: *** cfs_fail_loc=1613, val=0*** [ 4411.088943] Lustre: DEBUG MARKER: == sanity-lfsck test 17: LFSCK can repair multiple references ========================================================== 14:46:07 (1789065967) [ 4412.722721] Lustre: 109054:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 257 < left 278, rollback = 2 [ 4412.742530] Lustre: 109054:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 155 previous similar messages [ 4412.752363] Lustre: 109054:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 4412.762730] Lustre: 109054:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 155 previous similar messages [ 4412.769339] Lustre: 109054:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4412.782624] Lustre: 109054:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 155 previous similar messages [ 4412.786417] Lustre: 109054:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 4412.801634] Lustre: 109054:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 155 previous similar messages [ 4412.813323] Lustre: 109054:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 4412.821994] Lustre: 109054:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 155 previous similar messages [ 4412.833076] Lustre: 109054:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4412.842275] Lustre: 109054:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 155 previous similar messages [ 4414.623700] Lustre: *** cfs_fail_loc=1614, val=0*** [ 4415.390881] Lustre: *** cfs_fail_loc=1614, val=103*** [ 4415.397879] Lustre: Skipped 1 previous similar message [ 4421.162633] Lustre: 110976:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 259 < left 275, rollback = 2 [ 4421.168626] Lustre: 110976:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 11 previous similar messages [ 4421.175208] Lustre: 110976:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 4421.187654] Lustre: 110976:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 4421.203721] Lustre: 110976:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/1, xattr_set: 3/275/0 [ 4421.215761] Lustre: 110976:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 4421.230327] Lustre: 110976:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/9/0, punch: 1/4/0, quota 7/225/0 [ 4421.243082] Lustre: 110976:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 4421.263817] Lustre: 110976:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 4421.283610] Lustre: 110976:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 4421.302234] Lustre: 110976:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 4421.320800] Lustre: 110976:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 4430.246738] Lustre: DEBUG MARKER: == sanity-lfsck test 18a: Find out orphan OST-object and repair it (1) ========================================================== 14:46:25 (1789065985) [ 4430.664326] Lustre: 109055:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 253 < left 278, rollback = 2 [ 4430.672988] Lustre: 109055:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 1 previous similar message [ 4430.685135] Lustre: 109055:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4430.695389] Lustre: 109055:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1 previous similar message [ 4430.700495] Lustre: 109055:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4430.705723] Lustre: 109055:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1 previous similar message [ 4430.709405] Lustre: 109055:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/1 [ 4430.714488] Lustre: 109055:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1 previous similar message [ 4430.719944] Lustre: 109055:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 4430.725520] Lustre: 109055:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1 previous similar message [ 4430.730181] Lustre: 109055:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4430.734526] Lustre: 109055:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1 previous similar message [ 4433.615386] Lustre: *** cfs_fail_loc=1615, val=0*** [ 4433.618557] Lustre: Skipped 1 previous similar message [ 4434.676541] Lustre: *** cfs_fail_loc=1615, val=0*** [ 4434.692678] Lustre: Skipped 3 previous similar messages [ 4455.231387] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_18b skipping excluded test 18b [ 4457.409267] Lustre: DEBUG MARKER: == sanity-lfsck test 18c: Find out orphan OST-object and repair it (3) ========================================================== 14:46:53 (1789066013) [ 4457.918824] Lustre: 109055:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 4457.936490] Lustre: 109055:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 21 previous similar messages [ 4457.943261] Lustre: 109055:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 4457.952022] Lustre: 109055:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4457.961876] Lustre: 109055:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4457.968693] Lustre: 109055:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4457.973444] Lustre: 109055:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 4457.981391] Lustre: 109055:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4457.989482] Lustre: 109055:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 4457.997221] Lustre: 109055:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4458.011993] Lustre: 109055:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4458.024377] Lustre: 109055:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4460.699322] Lustre: *** cfs_fail_loc=1617, val=0*** [ 4460.783361] Lustre: *** cfs_fail_loc=1617, val=0*** [ 4463.667711] Lustre: *** cfs_fail_loc=1616, val=0*** [ 4463.677872] Lustre: Skipped 1 previous similar message [ 4485.457143] Lustre: DEBUG MARKER: == sanity-lfsck test 18d: Find out orphan OST-object and repair it (4) ========================================================== 14:47:21 (1789066041) [ 4488.225757] Lustre: *** cfs_fail_loc=1618, val=0*** [ 4488.244066] Lustre: Skipped 5 previous similar messages [ 4526.063180] 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 [ 4526.070808] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4526.076808] Lustre: Skipped 3 previous similar messages [ 4526.098791] Lustre: Skipped 3 previous similar messages [ 4528.889737] Lustre: server umount lustre-MDT0000 complete [ 4533.906048] LustreError: 109039:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1789066091 with bad export cookie 5054847642612847912 [ 4533.917568] LustreError: MGC192.168.204.144@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4533.933901] LustreError: 109039:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 4534.357876] Lustre: server umount lustre-MDT0001 complete [ 4549.541946] Lustre: server umount lustre-OST0000 complete [ 4552.359563] Lustre: 106191:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789066094/real 1789066094] req@ffff9ae2146f2a00 x1875971408088448/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1789066110 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4552.400529] 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 [ 4553.817201] Lustre: server umount lustre-OST0001 complete [ 4574.614057] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing load_modules_local [ 4587.501417] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4587.833140] LustreError: 117728:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4587.859469] LustreError: 117728:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 5 previous similar messages [ 4587.937160] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4593.127913] LustreError: 117729:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4593.147670] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4597.219257] LustreError: 117728:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4602.342911] LustreError: 117729:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4604.939832] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4605.527410] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 4611.166507] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4615.761713] Lustre: 118870:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 4626.371974] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4626.785104] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 4630.894078] LustreError: 119224:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4630.908661] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:4 to 0x280000400:33) [ 4632.986880] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:116 to 0x280000401:161) [ 4635.912274] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4643.301058] LustreError: 119406:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4643.316351] LustreError: 119406:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 5 previous similar messages [ 4646.128888] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4651.518703] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:4 to 0x2c0000401:33) [ 4651.522729] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:33) [ 4654.046649] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4662.698174] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4666.680502] Lustre: 120740:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 4682.218954] Lustre: DEBUG MARKER: == sanity-lfsck test 18e: Find out orphan OST-object and repair it (5) ========================================================== 14:50:38 (1789066238) [ 4682.614541] Lustre: 117723:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 252 < left 278, rollback = 2 [ 4682.643653] Lustre: 117723:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 46 previous similar messages [ 4682.654658] Lustre: 117723:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4682.662185] Lustre: 117723:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4682.669626] Lustre: 117723:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4682.688581] Lustre: 117723:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4682.693271] Lustre: 117723:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/1 [ 4682.700953] Lustre: 117723:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4682.709187] Lustre: 117723:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 4682.717632] Lustre: 117723:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4682.725676] Lustre: 117723:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4682.730546] Lustre: 117723:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4684.791796] Lustre: *** cfs_fail_loc=1618, val=0*** [ 4684.798412] Lustre: Skipped 3 previous similar messages [ 4723.171730] 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 [ 4723.174143] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4723.175036] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4723.194273] Lustre: Skipped 2 previous similar messages [ 4723.217040] Lustre: Skipped 3 previous similar messages [ 4725.011881] Lustre: server umount lustre-MDT0000 complete [ 4728.303181] LustreError: 117724:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4728.323036] LustreError: 117724:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 3 previous similar messages [ 4729.329331] LustreError: 117708:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1789066287 with bad export cookie 5054847642612863165 [ 4729.329835] LustreError: MGC192.168.204.144@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4729.338773] LustreError: 117708:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 4729.866434] Lustre: server umount lustre-MDT0001 complete [ 4743.491427] Lustre: server umount lustre-OST0000 complete [ 4757.326803] Lustre: server umount lustre-OST0001 complete [ 4775.873929] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing load_modules_local [ 4787.267787] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4787.863130] LustreError: 123308:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4787.961204] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4787.974798] Lustre: Skipped 1 previous similar message [ 4793.661838] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4803.536184] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4808.878964] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4812.101460] Lustre: 124447:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 4820.362993] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4828.755238] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4828.845931] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:4 to 0x280000400:65) [ 4832.933827] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:166 to 0x280000401:193) [ 4838.611038] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4844.019930] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:4 to 0x2c0000401:65) [ 4844.022815] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:65) [ 4845.596344] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4854.257647] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4859.290565] Lustre: 126319:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 4865.754582] Lustre: 123308:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 252 < left 260, rollback = 2 [ 4865.766565] Lustre: 123308:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 21 previous similar messages [ 4865.775705] Lustre: 123308:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4865.779257] Lustre: *** cfs_fail_loc=1602, val=10*** [ 4865.782460] Lustre: 123308:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4865.791263] Lustre: 123308:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 0/0/0, xattr_set: 1/260/0 [ 4865.796190] Lustre: 123308:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4865.800026] Lustre: 123308:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/9/0, punch: 0/0/0, quota 4/150/2 [ 4865.804453] Lustre: 123308:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4865.809080] Lustre: 123308:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 1/17/2, delete: 0/0/0 [ 4865.813433] Lustre: 123308:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4865.816898] Lustre: 123308:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 4865.821481] Lustre: 123308:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4896.105326] Lustre: DEBUG MARKER: == sanity-lfsck test 18f: Skip the failed OST(s) when handle orphan OST-objects ========================================================== 14:54:11 (1789066451) [ 4900.750430] Lustre: *** cfs_fail_loc=1616, val=0*** [ 4900.761875] Lustre: Skipped 3 previous similar messages [ 4909.173854] Lustre: *** cfs_fail_loc=161c, val=0*** [ 4932.194857] Lustre: DEBUG MARKER: == sanity-lfsck test 18g: Find out orphan OST-object and repair it (7) ========================================================== 14:54:48 (1789066488) [ 4935.010536] Lustre: *** cfs_fail_loc=162e, val=0*** [ 4935.014356] Lustre: *** cfs_fail_loc=162e, val=0*** [ 4935.018252] Lustre: Skipped 7 previous similar messages [ 4948.867700] Lustre: DEBUG MARKER: == sanity-lfsck test 18h: LFSCK can repair crashed PFL extent range ========================================================== 14:55:04 (1789066504) [ 4973.908854] Lustre: DEBUG MARKER: == sanity-lfsck test 19a: OST-object inconsistency self detect ========================================================== 14:55:30 (1789066530) [ 4987.824103] Lustre: DEBUG MARKER: == sanity-lfsck test 19b: OST-object inconsistency self repair ========================================================== 14:55:44 (1789066544) [ 4990.900479] Lustre: *** cfs_fail_loc=1611, val=0*** [ 4990.948915] Lustre: *** cfs_fail_loc=1611, val=0*** [ 4990.961423] Lustre: Skipped 3 previous similar messages [ 4996.759538] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.204.44@tcp inode [0x2000013a1:0x1f:0x0] object 0x280000401:202 extent [0-4095], client returned csum 0 (type 4), server csum 703fb3ad (type 4) [ 4997.835388] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.204.44@tcp inode [0x2000013a1:0x20:0x0] object 0x280000401:203 extent [0-4095], client returned csum 0 (type 4), server csum 7cbb935c (type 4) [ 5006.206891] Lustre: DEBUG MARKER: == sanity-lfsck test 20a: Handle the orphan with dummy LOV EA slot properly ========================================================== 14:56:02 (1789066562) [ 5006.542702] Lustre: 123305:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 253 < left 278, rollback = 2 [ 5006.555051] Lustre: 123305:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 104 previous similar messages [ 5006.563042] Lustre: 123305:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 5006.578741] Lustre: 123305:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 5006.592579] Lustre: 123305:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 5006.602802] Lustre: 123305:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 5006.608472] Lustre: 123305:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/1 [ 5006.615160] Lustre: 123305:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 5006.624102] Lustre: 123305:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 5006.634240] Lustre: 123305:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 5006.641283] Lustre: 123305:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 5006.647482] Lustre: 123305:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 5009.178180] Lustre: *** cfs_fail_loc=1616, val=0*** [ 5009.187982] Lustre: Skipped 3 previous similar messages [ 5034.243701] Lustre: DEBUG MARKER: == sanity-lfsck test 20b: Handle the orphan with dummy LOV EA slot properly - PFL case ========================================================== 14:56:30 (1789066590) [ 5042.368366] Lustre: DEBUG MARKER: == sanity-lfsck test 21: run all LFSCK components by default ========================================================== 14:56:38 (1789066598) [ 5055.443930] Lustre: DEBUG MARKER: == sanity-lfsck test 22a: LFSCK can repair unmatched pairs (1) ========================================================== 14:56:51 (1789066611) [ 5058.539986] Lustre: *** cfs_fail_loc=161e, val=0*** [ 5058.549712] Lustre: *** cfs_fail_loc=161e, val=0*** [ 5058.566205] Lustre: Skipped 1 previous similar message [ 5071.747693] Lustre: DEBUG MARKER: == sanity-lfsck test 22b: LFSCK can repair unmatched pairs (2) ========================================================== 14:57:07 (1789066627) [ 5073.728666] Lustre: *** cfs_fail_loc=161e, val=0*** [ 5073.731086] Lustre: *** cfs_fail_loc=161e, val=0*** [ 5086.564968] Lustre: DEBUG MARKER: == sanity-lfsck test 23a: LFSCK can repair dangling name entry (1) ========================================================== 14:57:22 (1789066642) [ 5088.450757] Lustre: *** cfs_fail_loc=1620, val=0*** [ 5103.485847] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_23b skipping excluded test 23b [ 5105.366978] Lustre: DEBUG MARKER: == sanity-lfsck test 23c: LFSCK can repair dangling name entry (3) ========================================================== 14:57:41 (1789066661) [ 5111.564605] Lustre: *** cfs_fail_loc=1621, val=127*** [ 5111.569038] Lustre: Skipped 1 previous similar message [ 5114.683577] Lustre: *** cfs_fail_loc=1602, val=10*** [ 5134.701846] Lustre: DEBUG MARKER: == sanity-lfsck test 23d: LFSCK can repair a dangling name entry to a remote object ========================================================== 14:58:11 (1789066691) [ 5137.209616] Lustre: Failing over lustre-MDT0000 [ 5137.590428] Lustre: server umount lustre-MDT0000 complete [ 5139.009895] LustreError: 128473:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.204.44@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 5139.028164] LustreError: 128473:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 8 previous similar messages [ 5140.964133] 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 [ 5140.983194] Lustre: Skipped 3 previous similar messages [ 5147.833345] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5147.968761] LustreError: MGC192.168.204.144@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5148.192383] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 5148.201782] Lustre: Skipped 3 previous similar messages [ 5148.246094] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 5150.735151] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 5152.638885] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5153.274126] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 5153.318064] Lustre: lustre-MDT0000: Recovery over after 0:03, of 2 clients 2 recovered and 0 were evicted. [ 5153.377416] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:130 to 0x2c0000401:161) [ 5153.378382] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:265 to 0x280000401:289) [ 5154.835578] LustreError: 125597:0:(mdt_open.c:1324:mdt_cross_open()) lustre-MDT0000: [0x2000013a3:0x82:0x0] doesn't exist!: rc = -14 [ 5166.179757] Lustre: DEBUG MARKER: == sanity-lfsck test 24: LFSCK can repair multiple-referenced name entry ========================================================== 14:58:42 (1789066722) [ 5168.696143] Lustre: *** cfs_fail_loc=1622, val=0*** [ 5168.853379] Lustre: *** cfs_fail_loc=1622, val=0*** [ 5168.856600] Lustre: Skipped 1 previous similar message [ 5181.924576] Lustre: DEBUG MARKER: == sanity-lfsck test 25: LFSCK can repair bad file type in the name entry ========================================================== 14:58:58 (1789066738) [ 5184.085133] Lustre: *** cfs_fail_loc=1623, val=0*** [ 5196.583390] Lustre: DEBUG MARKER: == sanity-lfsck test 26a: LFSCK can add the missing local name entry back to the namespace ========================================================== 14:59:12 (1789066752) [ 5198.699265] Lustre: *** cfs_fail_loc=1624, val=0*** [ 5212.284691] Lustre: DEBUG MARKER: == sanity-lfsck test 26b: LFSCK can add the missing remote name entry back to the namespace ========================================================== 14:59:28 (1789066768) [ 5226.603648] Lustre: DEBUG MARKER: == sanity-lfsck test 27a: LFSCK can recreate the lost local parent directory as orphan ========================================================== 14:59:42 (1789066782) [ 5228.410092] Lustre: *** cfs_fail_loc=1624, val=0*** [ 5228.420593] Lustre: Skipped 1 previous similar message [ 5240.389787] Lustre: DEBUG MARKER: == sanity-lfsck test 27b: LFSCK can recreate the lost remote parent directory as orphan ========================================================== 14:59:56 (1789066796) [ 5255.796475] Lustre: DEBUG MARKER: == sanity-lfsck test 28: Skip the failed MDT(s) when handle orphan MDT-objects ========================================================== 15:00:11 (1789066811) [ 5262.748983] Lustre: *** cfs_fail_loc=161c, val=0*** [ 5262.754212] Lustre: Skipped 1 previous similar message [ 5279.300984] Lustre: DEBUG MARKER: == sanity-lfsck test 29b: LFSCK can repair bad nlink count (2) ========================================================== 15:00:35 (1789066835) [ 5280.137869] Lustre: 128473:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 5280.155893] Lustre: 128473:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 518 previous similar messages [ 5280.161093] Lustre: 128473:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 5280.166711] Lustre: 128473:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 518 previous similar messages [ 5280.173536] Lustre: 128473:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 5280.186954] Lustre: 128473:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 518 previous similar messages [ 5280.196292] Lustre: 128473:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 5280.208865] Lustre: 128473:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 518 previous similar messages [ 5280.220469] Lustre: 128473:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 5280.227384] Lustre: 128473:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 518 previous similar messages [ 5280.237417] Lustre: 128473:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 5280.242489] Lustre: 128473:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 518 previous similar messages [ 5281.786438] Lustre: *** cfs_fail_loc=1626, val=0*** [ 5281.793843] Lustre: Skipped 4 previous similar messages [ 5294.396738] Lustre: DEBUG MARKER: == sanity-lfsck test 29c: verify linkEA size limitation == 15:00:50 (1789066850) [ 5323.717312] Lustre: DEBUG MARKER: == sanity-lfsck test 29d: accessing non-existing inode shouldn't turn fs read-only (ldiskfs) ========================================================== 15:01:20 (1789066880) [ 5326.740553] LustreError: 123303:0:(osd_handler.c:284:osd_idc_find_or_init()) lustre-MDT0000: cannot lookup FID [0x2000013a3:0x9e:0x0]: rc = -2 [ 5334.960124] Lustre: DEBUG MARKER: == sanity-lfsck test 30: LFSCK can recover the orphans from backend /lost+found ========================================================== 15:01:30 (1789066890) [ 5345.263192] Lustre: Failing over lustre-MDT0000 [ 5345.589085] Lustre: server umount lustre-MDT0000 complete [ 5347.811784] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 5347.819410] 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 [ 5347.822224] LustreError: 128473:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 5347.822236] LustreError: 128473:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 10 previous similar messages [ 5347.898256] Lustre: Skipped 4 previous similar messages [ 5357.438141] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 5357.593508] LustreError: MGC192.168.204.144@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5357.833361] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 5357.873851] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 5363.175339] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 5363.179841] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 5363.190952] Lustre: Skipped 3 previous similar messages [ 5363.235708] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 5363.280750] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:166 to 0x2c0000401:193) [ 5363.283367] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:295 to 0x280000401:321) [ 5363.445416] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5378.864974] Lustre: DEBUG MARKER: == sanity-lfsck test 31a: The LFSCK can find/repair the name entry with bad name hash (1) ========================================================== 15:02:14 (1789066934) [ 5394.955423] Lustre: DEBUG MARKER: == sanity-lfsck test 31b: The LFSCK can find/repair the name entry with bad name hash (2) ========================================================== 15:02:31 (1789066951) [ 5409.845139] Lustre: DEBUG MARKER: == sanity-lfsck test 31c: Re-generate the lost master LMV EA for striped directory ========================================================== 15:02:46 (1789066966) [ 5411.633284] Lustre: *** cfs_fail_loc=1629, val=0*** [ 5411.656738] Lustre: Skipped 5 previous similar messages [ 5441.330206] Lustre: DEBUG MARKER: == sanity-lfsck test 31d: Set broken striped directory (modified after broken) as read-only ========================================================== 15:03:17 (1789066997) [ 5447.648497] Lustre: Failing over lustre-MDT0000 [ 5447.907801] Lustre: server umount lustre-MDT0000 complete [ 5450.211665] 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 [ 5450.223450] Lustre: Skipped 2 previous similar messages [ 5457.432105] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5457.580057] LustreError: MGC192.168.204.144@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5457.861638] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 5462.356919] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5463.010419] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 5463.013419] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 5463.025030] Lustre: Skipped 3 previous similar messages [ 5463.065407] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 5463.115976] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:166 to 0x2c0000401:225) [ 5463.116201] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:295 to 0x280000401:353) [ 5473.222743] Lustre: Failing over lustre-MDT0000 [ 5473.252776] 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 [ 5473.263171] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 5473.273575] Lustre: Skipped 1 previous similar message [ 5473.277770] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5473.299643] Lustre: Skipped 3 previous similar messages [ 5473.515062] Lustre: server umount lustre-MDT0000 complete [ 5484.146153] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5484.269399] LustreError: MGC192.168.204.144@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5484.522129] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 5485.074227] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 5489.442595] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5489.649315] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 5489.654150] Lustre: Skipped 3 previous similar messages [ 5489.686983] Lustre: lustre-MDT0000: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 5489.730715] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:355 to 0x280000401:385) [ 5489.731532] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:166 to 0x2c0000401:257) [ 5499.310276] Lustre: DEBUG MARKER: == sanity-lfsck test 31e: Re-generate the lost slave LMV EA for striped directory (1) ========================================================== 15:04:15 (1789067055) [ 5511.892391] Lustre: DEBUG MARKER: == sanity-lfsck test 31f: Re-generate the lost slave LMV EA for striped directory (2) ========================================================== 15:04:28 (1789067068) [ 5526.050306] Lustre: DEBUG MARKER: == sanity-lfsck test 31g: Repair the corrupted slave LMV EA ========================================================== 15:04:42 (1789067082) [ 5566.286403] Lustre: DEBUG MARKER: == sanity-lfsck test 31h: Repair the corrupted shard's name entry ========================================================== 15:05:22 (1789067122) [ 5581.716876] Lustre: DEBUG MARKER: == sanity-lfsck test 32a: stop LFSCK when some OST failed ========================================================== 15:05:38 (1789067138) [ 5590.716286] LustreError: 147633:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d sleeping for 3000ms [ 5593.732699] LustreError: 147633:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d awake [ 5593.748063] LustreError: 147633:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d sleeping for 3000ms [ 5593.840528] Lustre: Failing over lustre-OST0000 [ 5593.986967] Lustre: server umount lustre-OST0000 complete [ 5596.808201] LustreError: 147633:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d awake [ 5596.829579] LustreError: 147633:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d sleeping for 3000ms [ 5596.952140] LustreError: 147633:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout interrupted [ 5596.974576] LustreError: lustre-OST0000-osc-MDT0000: operation lfsck_notify to node 0@lo failed: rc = -107 [ 5596.987523] Lustre: lustre-OST0000-osc-MDT0000: Connection to lustre-OST0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 5597.008989] Lustre: Skipped 3 previous similar messages [ 5607.401737] LustreError: 124802:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 5607.419596] LustreError: 124802:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 31 previous similar messages [ 5610.650540] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 5610.920097] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 5612.451794] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 5612.482963] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 5612.483906] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 5612.512436] Lustre: Skipped 3 previous similar messages [ 5618.146770] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5628.657314] Lustre: DEBUG MARKER: == sanity-lfsck test 32b: stop LFSCK when some MDT failed ========================================================== 15:06:24 (1789067184) [ 5645.307148] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing load_modules_local [ 5664.917922] Lustre: 150439:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 5691.579808] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5695.849249] Lustre: 151573:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 5709.713547] LustreError: 151714:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d sleeping for 3000ms [ 5712.717904] Lustre: Failing over lustre-MDT0001 [ 5712.723975] LustreError: 151714:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d awake [ 5712.750943] LustreError: lustre-MDT0001-osp-MDT0000: operation out_update to node 0@lo failed: rc = -107 [ 5712.763575] 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 [ 5712.785159] Lustre: Skipped 1 previous similar message [ 5712.795907] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 5712.997105] Lustre: server umount lustre-MDT0001 complete [ 5715.912331] LustreError: 151713:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d awake [ 5715.923045] LustreError: 151713:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) Skipped 1 previous similar message [ 5729.434236] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 5730.090209] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 5730.094599] Lustre: Skipped 3 previous similar messages [ 5730.166752] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 5735.401475] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 1 client reconnects [ 5735.403158] Lustre: lustre-MDT0001-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 5735.436841] Lustre: Skipped 1 previous similar message [ 5735.475317] Lustre: lustre-MDT0001: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 5735.551805] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:68 to 0x2c0000400:97) [ 5735.552644] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:71 to 0x280000400:97) [ 5736.874266] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5750.084181] Lustre: DEBUG MARKER: == sanity-lfsck test 33: check LFSCK paramters =========== 15:08:25 (1789067305) [ 5767.806381] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing load_modules_local [ 5789.248868] Lustre: 154437:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 5814.928611] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5818.885113] Lustre: 155572:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 5821.841348] Lustre: 123304:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 5821.853744] Lustre: 123304:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 1221 previous similar messages [ 5821.863275] Lustre: 123304:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 5821.870909] Lustre: 123304:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1221 previous similar messages [ 5821.876988] Lustre: 123304:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 5821.886177] Lustre: 123304:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1221 previous similar messages [ 5821.892639] Lustre: 123304:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 5821.898717] Lustre: 123304:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1221 previous similar messages [ 5821.903725] Lustre: 123304:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 5821.909904] Lustre: 123304:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1221 previous similar messages [ 5821.916056] Lustre: 123304:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 5821.921349] Lustre: 123304:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1221 previous similar messages [ 5841.724428] Lustre: DEBUG MARKER: == sanity-lfsck test 34: LFSCK can rebuild the lost agent object ========================================================== 15:09:58 (1789067398) [ 5843.347147] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_34 Only valid for ZFS backend [ 5845.577984] Lustre: DEBUG MARKER: == sanity-lfsck test 35: LFSCK can rebuild the lost agent entry ========================================================== 15:10:01 (1789067401) [ 5853.832272] Lustre: *** cfs_fail_loc=1631, val=0*** [ 5868.514897] 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 [ 5868.517273] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5868.517481] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 5868.538721] Lustre: Skipped 5 previous similar messages [ 5868.570340] Lustre: Skipped 3 previous similar messages [ 5873.640886] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5873.647492] Lustre: Skipped 2 previous similar messages [ 5874.073578] Lustre: server umount lustre-MDT0000 complete [ 5878.080544] LustreError: 123290:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1789067436 with bad export cookie 5054847642612936021 [ 5878.084362] LustreError: MGC192.168.204.144@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5878.093496] LustreError: 123290:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 5878.583448] Lustre: server umount lustre-MDT0001 complete [ 5892.099654] Lustre: server umount lustre-OST0000 complete [ 5895.139641] Lustre: 106191:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789067436/real 1789067436] req@ffff9ae205fddf80 x1875971409591936/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1789067452 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5895.920304] Lustre: server umount lustre-OST0001 complete [ 5915.730060] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing load_modules_local [ 5926.809037] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5932.327737] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5941.161054] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5946.084530] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5949.454917] Lustre: 159470:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 5957.534643] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5964.260895] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5966.973251] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:71 to 0x280000400:129) [ 5973.505787] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:540 to 0x280000401:577) [ 5975.090121] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5980.656619] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:412 to 0x2c0000401:449) [ 5980.668739] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:68 to 0x2c0000400:129) [ 5982.875230] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5991.988219] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5996.403770] Lustre: 161341:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 6009.035910] Lustre: DEBUG MARKER: == sanity-lfsck test 36a: rebuild LOV EA for mirrored file (1) ========================================================== 15:12:45 (1789067565) [ 6011.073841] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36a needs >= 3 OSTs [ 6013.299699] Lustre: DEBUG MARKER: == sanity-lfsck test 36b: rebuild LOV EA for mirrored file (2) ========================================================== 15:12:49 (1789067569) [ 6015.597786] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36b needs >= 3 OSTs [ 6017.623402] Lustre: DEBUG MARKER: == sanity-lfsck test 36c: rebuild LOV EA for mirrored file (3) ========================================================== 15:12:53 (1789067573) [ 6019.560094] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36c needs >= 3 OSTs [ 6021.710568] Lustre: DEBUG MARKER: == sanity-lfsck test 37: LFSCK must skip a ORPHAN ======== 15:12:57 (1789067577) [ 6035.155238] Lustre: DEBUG MARKER: == sanity-lfsck test 38: LFSCK does not break foreign file and reverse is also true ========================================================== 15:13:11 (1789067591) [ 6052.318632] Lustre: DEBUG MARKER: == sanity-lfsck test 39: LFSCK does not break foreign dir and reverse is also true ========================================================== 15:13:27 (1789067607) [ 6068.756076] Lustre: DEBUG MARKER: == sanity-lfsck test 40a: LFSCK correctly fixes lmm_oi in composite layout ========================================================== 15:13:44 (1789067624) [ 6087.070775] Lustre: DEBUG MARKER: == sanity-lfsck test 41: SEL support in LFSCK ============ 15:14:03 (1789067643) [ 6113.151797] Lustre: DEBUG MARKER: == sanity-lfsck test 42: LFSCK repairs inconsistent MDT-object/OST-object encryption flags ========================================================== 15:14:29 (1789067669) [ 6148.471684] Lustre: *** cfs_fail_loc=1632, val=0*** [ 6167.477543] Lustre: DEBUG MARKER: == sanity-lfsck test 43: LFSCK does not loop endlessly on iget failure in scanning-phase1 ========================================================== 15:15:23 (1789067723) [ 6171.000734] Lustre: Failing over lustre-MDT0001 [ 6171.357425] Lustre: server umount lustre-MDT0001 complete [ 6172.132508] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 6172.142805] 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 [ 6172.154665] Lustre: Skipped 1 previous similar message [ 6172.158504] LustreError: 158331:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 6172.167342] LustreError: 158331:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 19 previous similar messages [ 6181.382562] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 6181.746309] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 6181.746640] Lustre: lustre-MDT0001: Aborting client recovery [ 6181.755240] LustreError: 165134:0:(ldlm_lib.c:3038:target_stop_recovery_thread()) lustre-MDT0001: Aborting recovery [ 6181.762577] Lustre: 165158:0:(ldlm_lib.c:2438:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 6181.767387] LustreError: 165156:0:(lod_dev.c:511:lod_sub_recovery_thread()) lustre-MDT0001-osd: get update log duration 0, retries 0, failed: rc = -108 [ 6181.780448] Lustre: 165158:0:(genops.c:1600:class_disconnect_stale_exports()) lustre-MDT0001: disconnect stale client 7d17b248-bd9b-4bda-b066-a50bd2406a9e@ [ 6181.794975] Lustre: lustre-MDT0001: disconnecting 2 stale clients [ 6181.814419] Lustre: lustre-MDT0001-osd: cancel update llog [0x240000400:0x1:0x0] [ 6181.825049] Lustre: lustre-MDT0000-osp-MDT0001: cancel update llog [0x200000401:0x1:0x0] [ 6181.872720] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:131 to 0x2c0000400:161) [ 6181.875682] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:71 to 0x280000400:161) [ 6186.983575] LustreError: lustre-MDT0001-osp-MDT0000: This client was evicted by lustre-MDT0001; in progress operations using this service will fail. [ 6187.013134] Lustre: lustre-MDT0001-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 6187.021281] Lustre: Skipped 3 previous similar messages [ 6187.925901] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6192.838211] Lustre: *** cfs_fail_loc=1e2, val=483*** [ 6197.909761] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing wait_import_state FULL osp.lustre-MDT0001-os[pc]-MDT0000.*_server_uuid [ 6198.297457] Lustre: DEBUG MARKER: osp.lustre-MDT0001-os[pc]-MDT0000.*_server_uuid in FULL state after 0 sec [ 6207.262576] Lustre: DEBUG MARKER: == sanity-lfsck test 44: umount while lfsck is stopping == 15:16:02 (1789067762) [ 6218.556121] Lustre: *** cfs_fail_loc=1600, val=3*** [ 6221.576550] Lustre: Failing over lustre-MDT0000 [ 6221.901363] Lustre: server umount lustre-MDT0000 complete [ 6222.827451] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 6232.490828] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 6232.653085] LustreError: MGC192.168.204.144@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 6232.911879] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 6232.929636] Lustre: Skipped 2 previous similar messages [ 6234.638974] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 6237.569617] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6238.186493] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 6238.201488] Lustre: Skipped 1 previous similar message [ 6238.238034] Lustre: lustre-MDT0000: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 6238.295406] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:621 to 0x280000401:641) [ 6238.297467] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:489 to 0x2c0000401:513) [ 6248.792280] Lustre: DEBUG MARKER: == sanity-lfsck test 45: LFSCK should fix UID/GID/PROJID of OST object ========================================================== 15:16:44 (1789067804) [ 6297.355846] Lustre: Failing over lustre-OST0001 [ 6297.507630] Lustre: server umount lustre-OST0001 complete [ 6303.604318] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: (null) [ 6315.810442] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 6316.072984] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 6316.088683] Lustre: Skipped 6 previous similar messages [ 6316.101378] Lustre: lustre-OST0001: in recovery but waiting for the first client to connect [ 6316.555421] Lustre: lustre-OST0001: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 6317.163716] Lustre: lustre-OST0001: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [ 6317.172091] Lustre: lustre-OST0001-osc-MDT0001: Connection restored to 0@lo (at 0@lo) [ 6317.176560] Lustre: Skipped 3 previous similar messages [ 6322.063443] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6328.773175] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing wait_import_state (FULL|IDLE) os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid 50 [ 6329.019956] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid in FULL state after 0 sec [ 6333.846013] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing wait_import_state (FULL|IDLE) os[cp].lustre-OST0000-osc-MDT0001.ost_server_uuid 50 [ 6334.022645] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0001.ost_server_uuid in FULL state after 0 sec [ 6340.085399] Lustre: DEBUG MARKER: oleg444-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0000-osc-ffff9b9b11232000.ost_server_uuid 50 [ 6341.671695] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9b9b11232000.ost_server_uuid in FULL state after 0 sec [ 6432.736970] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 6432.748424] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 6432.759488] Lustre: Skipped 1 previous similar message [ 6435.554634] Lustre: server umount lustre-MDT0000 complete [ 6445.122097] LustreError: 158312:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1789068003 with bad export cookie 5054847642613018684 [ 6445.127630] LustreError: MGC192.168.204.144@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 6445.134467] LustreError: 158312:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 6445.757906] Lustre: server umount lustre-MDT0001 complete [ 6464.715963] Lustre: server umount lustre-OST0000 complete [ 6464.997587] Lustre: 106189:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789068007/real 1789068007] req@ffff9ae307327800 x1875971410027776/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1789068023 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6466.337693] Lustre: 106190:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789068008/real 1789068008] req@ffff9ae20554e300 x1875971410028032/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1789068024 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6470.563070] Lustre: 106188:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789068012/real 1789068012] req@ffff9ae30734c380 x1875971410028288/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1789068028 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6473.519660] Lustre: server umount lustre-OST0001 complete [ 6491.212458] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing unload_modules_local [ 6494.135820] Key type lgssc unregistered [ 6494.496733] LNet: 174879:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 6494.510824] LNetError: 174879:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 6494.526656] LNet: Removed LNI 192.168.204.144@tcp [ 6495.398170] Key type .llcrypt unregistered [ 6495.403697] Key type ._llcrypt unregistered [ 6521.302902] Key type ._llcrypt registered [ 6521.306675] Key type .llcrypt registered [ 6521.414587] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_hostid [ 6537.581755] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing load_modules_local [ 6538.720305] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 6538.758219] alg: No test for adler32 (adler32-zlib) [ 6539.854486] Lustre: Lustre: Build Version: 2.17.58_39_ga794951 [ 6540.250461] LNet: Added LNI 192.168.204.144@tcp [8/256/0/180] [ 6541.936342] Key type lgssc registered [ 6543.335727] Lustre: Echo OBD driver; http://www.lustre.org/ [ 6596.803271] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing load_modules_local [ 6611.287308] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 6611.340696] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 6612.735847] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 6612.818599] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 6612.981348] Lustre: lustre-MDT0000: new disk, initializing [ 6613.116664] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 6613.136278] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 6618.544154] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6633.892139] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 6634.017199] Lustre: 179332: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 [ 6634.129655] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 6634.139834] Lustre: Skipped 1 previous similar message [ 6634.279713] Lustre: lustre-MDT0001: new disk, initializing [ 6634.416746] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 6634.451971] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 6634.472622] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 6639.512649] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6644.570655] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 6655.774800] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 6656.118551] Lustre: lustre-OST0000: new disk, initializing [ 6656.129299] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 6656.137434] Lustre: 181271:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 6656.265375] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 6663.095092] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6665.759945] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 6665.769925] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 6665.857825] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 6677.369731] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 6677.545413] Lustre: lustre-OST0001: new disk, initializing [ 6677.552483] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 6677.560793] Lustre: 182295:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 6677.634195] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 6683.967359] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6686.811758] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 6686.829449] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 6686.883964] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 6696.943110] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 6707.718315] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 6714.299149] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 15:24:30 (1789068270) === [ 6716.122087] Lustre: DEBUG MARKER: == sanity-lfsck test complete, duration 6432 sec ========= 15:24:32 (1789068272) [ 6718.128190] Lustre: DEBUG MARKER: === sanity-lfsck: start cleanup 15:24:34 (1789068274) === [ 6722.999770] Lustre: DEBUG MARKER: === sanity-lfsck: finish cleanup 15:24:38 (1789068278) === [ 6728.161133] 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 [ 6728.164043] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 6728.188045] Lustre: Skipped 1 previous similar message [ 6733.289113] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 6733.296022] Lustre: Skipped 6 previous similar messages [ 6733.901908] Lustre: server umount lustre-MDT0000 complete [ 6743.526773] LustreError: 179337:0:(ldlm_lib.c:1199:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 6743.556873] LustreError: 179337:0:(ldlm_lib.c:1199:target_handle_connect()) Skipped 8 previous similar messages [ 6744.982767] LustreError: 179322:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1789068302 with bad export cookie 16981180522563348530 [ 6744.990877] LustreError: MGC192.168.204.144@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 6745.003624] LustreError: 179322:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 6745.411827] Lustre: server umount lustre-MDT0001 complete [ 6764.577270] Lustre: 176490:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789068306/real 1789068306] req@ffff9ae213e55180 x1875973870013568/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1789068322 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6764.614934] 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 [ 6764.640964] Lustre: Skipped 2 previous similar messages [ 6764.717872] Lustre: server umount lustre-OST0000 complete [ 6769.760540] Lustre: 176490:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789068311/real 1789068311] req@ffff9ae204c86d80 x1875973870014080/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1789068327 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6769.799928] Lustre: 176490:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 6771.877708] Lustre: 176490:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789068313/real 1789068313] req@ffff9ae309bbb100 x1875973870014464/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1789068329 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6775.498433] Lustre: server umount lustre-OST0001 complete [ 6795.209378] Lustre: DEBUG MARKER: oleg444-server.virtnet: executing unload_modules_local [ 6799.025939] Key type lgssc unregistered [ 6799.382046] LNet: 185773:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 6799.387895] LNetError: 185773:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 6799.410953] LNet: Removed LNI 192.168.204.144@tcp [ 6800.357200] Key type .llcrypt unregistered [ 6800.363527] Key type ._llcrypt unregistered