[ 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 660383191 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2399.998 MHz processor [ 0.000000] last_pfn = 0x146e00 max_arch_pfn = 0x400000000 [ 0.000000] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT [ 0.000000] last_pfn = 0xbffce max_arch_pfn = 0x400000000 [ 0.000000] found SMP MP-table at [mem 0x000f54b0-0x000f54bf] [ 0.000000] RAMDISK: [mem 0xbcc54000-0xbffbffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F52D0 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE247C 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE2318 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 0022D8 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE238C 000090 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE241C 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE2454 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe2318-0xbffe238b] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe2317] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe238c-0xbffe241b] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe241c-0xbffe2453] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe2454-0xbffe247b] [ 0.000000] No NUMA configuration found [ 0.000000] Faking a node at [mem 0x0000000000000000-0x0000000146dfffff] [ 0.000000] NODE_DATA(0) allocated [mem 0x1465a3000-0x1465cdfff] [ 0.000000] Reserving 256MB of memory at 2752MB for crashkernel (System RAM: 4205MB) [ 0.000000] Zone ranges: [ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.000000] DMA32 [mem 0x0000000001000000-0x00000000ffffffff] [ 0.000000] Normal [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Device empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff] [ 0.000000] node 0: [mem 0x0000000000100000-0x00000000bffcdfff] [ 0.000000] node 0: [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Zeroed struct page in unavailable ranges: 4756 pages [ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x0000000146dfffff] [ 0.000000] ACPI: PM-Timer IO Port: 0x608 [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) [ 0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) [ 0.000000] Using ACPI (MADT) for SMP configuration information [ 0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000] TSC deadline timer available [ 0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs [ 0.000000] kvm-guest: KVM setup pv remote TLB flush [ 0.000000] kvm-guest: setup PV sched yield [ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff] [ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff] [ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff] [ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff] [ 0.000000] PM: Registered nosave memory: [mem 0xbffce000-0xbfffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xc0000000-0xfeffbfff] [ 0.000000] PM: Registered nosave memory: [mem 0xfeffc000-0xfeffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xff000000-0xfffbffff] [ 0.000000] PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff] [ 0.000000] [mem 0xc0000000-0xfeffbfff] available for PCI devices [ 0.000000] Booting paravirtualized kernel on KVM [ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns [ 0.000000] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1 [ 0.000000] percpu: Embedded 63 pages/cpu s221184 r8192 d28672 u524288 [ 0.000000] kvm-guest: PV spinlocks enabled [ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1059606 [ 0.000000] Policy zone: Normal [ 0.000000] Kernel command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] Specific versions of hardware are certified with Red Hat Enterprise Linux 8. Please see the list of hardware certified with Red Hat Enterprise Linux 8 at https://catalog.redhat.com. [ 0.000000] audit: disabled (until reboot) [ 0.000000] software IO TLB: area num 4. [ 0.000000] Memory: 2895240K/4306352K available (18435K kernel code, 11221K rwdata, 7248K rodata, 2908K init, 18040K bss, 524584K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] ftrace: allocating 41240 entries in 162 pages [ 0.000000] ftrace: allocated 162 pages with 3 groups [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] rcu: RCU event tracing is enabled. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ 0.000000] rcu: RCU callback double-/use-after-free debug enabled. [ 0.000000] Rude variant of Tasks RCU enabled. [ 0.000000] Tracing variant of Tasks RCU enabled. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 0.000000] NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16 [ 0.000000] random: get_random_bytes called from start_kernel+0x622/0x9a8 with crng_init=0 [ 0.001000] Console: colour *CGA 80x25 [ 0.001000] printk: console [ttyS1] enabled [ 0.001000] ACPI: Core revision 20220331 [ 0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.001011] APIC: Switch to symmetric I/O mode setup [ 0.002422] x2apic enabled [ 0.003011] Switched APIC routing to physical x2apic. [ 0.004015] kvm-guest: setup PV IPIs [ 0.007000] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.007000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.007019] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.008012] pid_max: default: 32768 minimum: 301 [ 0.009139] LSM: Security Framework initializing [ 0.010064] Yama: becoming mindful. [ 0.011047] SELinux: Initializing. [ 0.012083] *** VALIDATE selinux *** [ 0.020651] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.026034] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.027176] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.028117] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.030126] *** VALIDATE tmpfs *** [ 0.032356] *** VALIDATE proc *** [ 0.034054] *** VALIDATE cgroup *** [ 0.035000] *** VALIDATE cgroup2 *** [ 0.036097] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.037160] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.038010] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.039032] Spectre V2 : User space: Vulnerable [ 0.040010] Speculative Store Bypass: Vulnerable [ 0.042092] debug: unmapping init [mem 0xffffffffa0059000-0xffffffffa0060fff] [ 0.044874] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.045746] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.046024] ... version: 2 [ 0.047017] ... bit width: 48 [ 0.048016] ... generic registers: 4 [ 0.049010] ... value mask: 0000ffffffffffff [ 0.050012] ... max period: 00007fffffffffff [ 0.051012] ... fixed-purpose events: 3 [ 0.052012] ... event mask: 000000070000000f [ 0.053276] rcu: Hierarchical SRCU implementation. [ 0.055528] smp: Bringing up secondary CPUs ... [ 0.056635] x86: Booting SMP configuration: [ 0.057029] .... node #0, CPUs: #1 #2 #3 [ 0.062154] smp: Brought up 1 node, 4 CPUs [ 0.064020] smpboot: Max logical packages: 1 [ 0.065075] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.122446] node 0 deferred pages initialised in 55ms [ 0.126012] devtmpfs: initialized [ 0.127286] x86/mm: Memory block size: 128MB [ 0.129549] gcov: version magic: 0x41383552 [ 0.193352] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.201128] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.204600] pinctrl core: initialized pinctrl subsystem [ 0.207173] [ 0.207955] ************************************************************* [ 0.210012] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.213010] ** ** [ 0.215010] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.218020] ** ** [ 0.221013] ** This means that this kernel is built to expose internal ** [ 0.223028] ** IOMMU data structures, which may compromise security on ** [ 0.226014] ** your system. ** [ 0.229017] ** ** [ 0.232011] ** If you see this message and you are not debugging the ** [ 0.234019] ** kernel, report this immediately to your vendor! ** [ 0.238020] ** ** [ 0.242015] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.245013] ************************************************************* [ 0.254263] NET: Registered protocol family 16 [ 0.270479] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.274757] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.280062] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.286103] cpuidle: using governor menu [ 0.288143] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.290413] PCI: Using configuration type 1 for base access [ 0.293195] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.305161] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.308018] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.310271] cryptd: max_cpu_qlen set to 1000 [ 0.312237] ACPI: Added _OSI(Module Device) [ 0.315030] ACPI: Added _OSI(Processor Device) [ 0.318042] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.322033] ACPI: Added _OSI(Processor Aggregator Device) [ 0.333255] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.343124] ACPI: Interpreter enabled [ 0.344204] ACPI: PM: (supports S0 S3 S4 S5) [ 0.346012] ACPI: Using IOAPIC for interrupt routing [ 0.349087] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.353607] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.369283] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.372074] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.377112] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.384173] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.394381] acpiphp: Slot [2] registered [ 0.396217] acpiphp: Slot [5] registered [ 0.398451] acpiphp: Slot [6] registered [ 0.401196] acpiphp: Slot [7] registered [ 0.404232] acpiphp: Slot [8] registered [ 0.406262] acpiphp: Slot [9] registered [ 0.409228] acpiphp: Slot [10] registered [ 0.410160] acpiphp: Slot [3] registered [ 0.412090] acpiphp: Slot [4] registered [ 0.413097] acpiphp: Slot [11] registered [ 0.415143] acpiphp: Slot [12] registered [ 0.416127] acpiphp: Slot [13] registered [ 0.417305] acpiphp: Slot [14] registered [ 0.419099] acpiphp: Slot [15] registered [ 0.421161] acpiphp: Slot [16] registered [ 0.422327] acpiphp: Slot [17] registered [ 0.424134] acpiphp: Slot [18] registered [ 0.426094] acpiphp: Slot [19] registered [ 0.427085] acpiphp: Slot [20] registered [ 0.428119] acpiphp: Slot [21] registered [ 0.430080] acpiphp: Slot [22] registered [ 0.431114] acpiphp: Slot [23] registered [ 0.433169] acpiphp: Slot [24] registered [ 0.434165] acpiphp: Slot [25] registered [ 0.436102] acpiphp: Slot [26] registered [ 0.438169] acpiphp: Slot [27] registered [ 0.440122] acpiphp: Slot [28] registered [ 0.441085] acpiphp: Slot [29] registered [ 0.443124] acpiphp: Slot [30] registered [ 0.444175] acpiphp: Slot [31] registered [ 0.446063] PCI host bridge to bus 0000:00 [ 0.448020] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.451027] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.453023] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.456028] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.459022] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.462024] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.464200] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.467245] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.470506] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.485014] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.491151] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.494019] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.496019] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.500025] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.503721] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.507976] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.511049] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.514978] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.520014] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.536025] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.543015] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.551091] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.578013] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.585012] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.603023] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.614690] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.633015] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.640019] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.653016] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.662012] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.676016] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.686013] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.702015] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.713231] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.717000] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.717000] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.717000] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.728370] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.739014] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.746014] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.771017] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 0.794993] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.810092] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.824016] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.852014] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 0.870000] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.872465] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.875580] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.878559] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.881252] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.886795] iommu: Default domain type: Passthrough [ 0.887000] SCSI subsystem initialized [ 0.887000] ACPI: bus type USB registered [ 0.887000] usbcore: registered new interface driver usbfs [ 0.887000] usbcore: registered new interface driver hub [ 0.887000] usbcore: registered new device driver usb [ 0.887000] pps_core: LinuxPPS API ver. 1 registered [ 0.887000] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.887000] PTP clock support registered [ 0.887250] EDAC MC: Ver: 3.0.0 [ 0.890132] PCI: Using ACPI for IRQ routing [ 0.891000] NetLabel: Initializing [ 0.891000] NetLabel: domain hash size = 128 [ 0.902014] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.904135] NetLabel: unlabeled traffic allowed by default [ 0.906221] vgaarb: loaded [ 0.914033] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.918057] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.928378] clocksource: Switched to clocksource kvm-clock [ 1.047827] VFS: Disk quotas dquot_6.6.0 [ 1.049725] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 1.052932] *** VALIDATE ramfs *** [ 1.054626] *** VALIDATE hugetlbfs *** [ 1.056495] pnp: PnP ACPI init [ 1.059175] pnp: PnP ACPI: found 6 devices [ 1.075533] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 1.079216] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 1.081838] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 1.084298] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 1.087233] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 1.090163] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 1.093339] NET: Registered protocol family 2 [ 1.096287] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 1.101930] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 1.106164] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 1.112129] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 1.116154] TCP: Hash tables configured (established 65536 bind 65536) [ 1.119574] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 1.122645] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 1.125916] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 1.129294] NET: Registered protocol family 1 [ 1.132427] RPC: Registered named UNIX socket transport module. [ 1.136796] RPC: Registered udp transport module. [ 1.138862] RPC: Registered tcp transport module. [ 1.140943] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 1.144393] NET: Registered protocol family 44 [ 1.146459] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 1.148751] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 1.151153] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 1.153807] PCI: CLS 0 bytes, default 64 [ 1.155718] Unpacking initramfs... [ 2.930284] debug: unmapping init [mem 0xffff8be93cc54000-0xffff8be93ffbffff] [ 2.935724] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.938459] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.942020] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 3.554042] Initialise system trusted keyrings [ 3.555946] Key type blacklist registered [ 3.558193] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 3.567915] zbud: loaded [ 3.570946] *** VALIDATE nfs *** [ 3.572209] *** VALIDATE nfs4 *** [ 3.574188] pstore: using deflate compression [ 3.578643] Platform Keyring initialized [ 3.701619] NET: Registered protocol family 38 [ 3.703795] Key type asymmetric registered [ 3.705249] Asymmetric key parser 'x509' registered [ 3.707611] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 3.710888] io scheduler mq-deadline registered [ 3.712494] io scheduler kyber registered [ 3.714601] io scheduler bfq registered [ 3.718746] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 3.722438] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 3.727645] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 3.731444] ACPI: Power Button [PWRF] [ 3.737848] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 3.749126] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 3.823875] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 3.838669] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 3.861927] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 3.894627] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.930785] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.937462] Non-volatile memory driver v1.3 [ 3.940483] Linux agpgart interface v0.103 [ 3.982931] virtio_blk virtio1: [vda] 150080 512-byte logical blocks (76.8 MB/73.3 MiB) [ 3.986636] vda: detected capacity change from 0 to 76840960 [ 4.002798] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 4.006460] vdb: detected capacity change from 0 to 1073741824 [ 4.024202] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 4.026981] vdc: detected capacity change from 0 to 2621440000 [ 4.045224] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 4.048912] vdd: detected capacity change from 0 to 2621440000 [ 4.080442] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 4.085230] vde: detected capacity change from 0 to 4294967296 [ 4.121789] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 4.129579] vdf: detected capacity change from 0 to 4294967296 [ 4.158450] libphy: Fixed MDIO Bus: probed [ 4.168327] usbcore: registered new interface driver usbserial_generic [ 4.172974] usbserial: USB Serial support registered for generic [ 4.177196] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 4.184757] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 4.187285] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 4.190735] mousedev: PS/2 mouse device common for all mice [ 4.195534] rtc_cmos 00:05: RTC can wake from S4 [ 4.201507] rtc_cmos 00:05: registered as rtc0 [ 4.205562] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 4.207216] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 4.210419] intel_pstate: CPU model not supported [ 4.213971] hid: raw HID events driver (C) Jiri Kosina [ 4.227707] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 4.232749] usbcore: registered new interface driver usbhid [ 4.237810] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 4.256902] usbhid: USB HID core driver [ 4.259258] drop_monitor: Initializing network drop monitor service [ 4.263658] Initializing XFRM netlink socket [ 4.265993] NET: Registered protocol family 10 [ 4.270557] Segment Routing with IPv6 [ 4.273097] NET: Registered protocol family 17 [ 4.277903] mpls_gso: MPLS GSO support [ 4.289835] RAS: Correctable Errors collector initialized. [ 4.293853] AVX version of gcm_enc/dec engaged. [ 4.296129] AES CTR mode by8 optimization enabled [ 4.420561] sched_clock: Marking stable (4420542057, 0)->(5824895991, -1404353934) [ 4.427120] registered taskstats version 1 [ 4.430194] Loading compiled-in X.509 certificates [ 4.432625] zswap: loaded using pool lzo/zbud [ 4.460648] Key type big_key registered [ 4.473582] Key type encrypted registered [ 4.475066] ima: No TPM chip found, activating TPM-bypass! [ 4.477346] ima: Allocated hash algorithm: sha1 [ 4.478881] ima: No architecture policies found [ 4.480644] evm: Initialising EVM extended attributes: [ 4.482412] evm: security.selinux [ 4.483513] evm: security.ima [ 4.484634] evm: security.capability [ 4.485854] evm: HMAC attrs: 0x1 [ 4.488330] rtc_cmos 00:05: setting system clock to 2026-09-07 03:43:00 UTC (1788752580) [ 4.495871] debug: unmapping init [mem 0xffffffffa1003000-0xffffffffa11fffff] [ 4.499649] debug: unmapping init [mem 0xffffffff9fd82000-0xffffffffa0058fff] [ 4.519263] Write protecting the kernel read-only data: 28672k [ 4.523989] debug: unmapping init [mem 0xffffffff9e403000-0xffffffff9e5fffff] [ 4.528632] debug: unmapping init [mem 0xffffffff9ed14000-0xffffffff9edfffff] [ 4.588211] 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) [ 4.603675] systemd[1]: Detected virtualization kvm. [ 4.607340] systemd[1]: Detected architecture x86-64. [ 4.611166] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 4.644626] systemd[1]: No hostname configured. [ 4.646816] systemd[1]: Set hostname to . [ 4.649745] random: systemd: uninitialized urandom read (16 bytes read) [ 4.653098] systemd[1]: Initializing machine ID from random generator. [ 4.820310] random: ln: uninitialized urandom read (6 bytes read) [ 5.082540] random: systemd: uninitialized urandom read (16 bytes read) [ 5.086517] systemd[1]: Listening on Journal Socket (/dev/log). [ OK ] Listening on Journal Socket (/dev/log). [ 5.093078] systemd[1]: Reached target Slices. [ OK ] Reached target Slices. [ 5.101306] systemd[1]: Listening on Journal Socket. [ OK ] Listening on Journal Socket. [ OK ] Started Memstrack Anylazing Service. [ OK ] Listening on udev Control Socket. [ OK ] Reached target Swap. [ OK ] Reached target Local File Systems. Starting Setup Virtual Console... [ OK ] Listening on udev Kernel Socket. [ OK ] Reached target Sockets. Starting Create list of required st…ce nodes for the current kernel... Starting Journal Service... Starting Apply Kernel Variables... [ OK ] Reached target Initrd Root Device. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Paths. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Timers. Starting Create Volatile Files and Directories... [ 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... [ 7.954499] device-mapper: uevent: version 1.0.3 [ 7.956643] device-mapper: ioctl: 4.46.0-ioctl (2022-02-22) initialised: dm-devel@redhat.com [ OK ] Started dracut pre-udev hook. Starting udev Kernel Device Manager... [ OK ] Started udev Kernel Device Manager. Starting dracut pre-trigger hook... [ OK ] Started dracut pre-trigger hook. Starting udev Coldplug all Devices... Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting dracut initqueue hook... [ 9.277401] random: fast init done [ 9.618091] virtio_net virtio0 ens2: renamed from eth0 [ 9.756454] scsi host0: ata_piix [ 9.900634] scsi host1: ata_piix [ 9.905477] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 9.969698] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 11.384431] dracut-initqueue[506]: RTNETLINK answers: File exists [ 14.991757] random: crng init done [ 14.993349] random: 7 urandom warning(s) missed due to ratelimiting Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Mounting /sysroot... [ 19.766251] 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... Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped target Timers. [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Slices. [ OK ] Stopped target System Initialization. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped target Swap. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. Stopping udev Kernel Device Manager... [ OK ] Stopped target Paths. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped target Sockets. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Closed udev Kernel Socket. [ OK ] Closed udev Control Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 22.366292] printk: systemd: 26 output lines suppressed due to ratelimiting [ 22.996476] SELinux: Disabled at runtime. [ 23.087694] 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) [ 23.098377] systemd[1]: Detected virtualization kvm. [ 23.101542] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 25.159181] systemd[1]: initrd-switch-root.service: Succeeded. [ 25.186203] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 25.217910] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 25.233899] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 25.261656] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 25.353070] systemd[1]: Starting Journal Service... Starting Journal Service... [ 25.415550] systemd[1]: Mounting POSIX Message Queue File System... Mounting POSIX Message Queue File System... [ OK ] Created slice system-serial\x2dgetty.slice. Activating swap /dev/disk/by-label/SWAP... [ OK ] Created slice system-getty.slice. [ OK ] Started Forward Password Requests to Wall Directory Watch. [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Listening on udev Control Socket. [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd File Systems. Starting Apply K[ 25.616659] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS ernel Variables... [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Reached target rpc_pipefs.target. [ OK ] Listening on udev Kernel Socket. Starting udev Coldplug all Devices... [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Stopped target Initrd Root File System. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Created slice system-sshd\x2dkeygen.slice. Mounting Kernel Debug File System... Starting Create list of required st…ce nodes for the current kernel... Mounting Huge Pages File System... [ OK ] Reached target Paths. [ OK ] Created slice User and Session Slice. [ OK ] Reached target Slices. [ OK ] Reached target RPC Port Mapper. [ OK ] Listening on Process Core Dump Socket. Starting Remount Root and Kernel File Systems... [ OK ] Reached target Local Encrypted Volumes. [ OK ] Started Journal Service. [ 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. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Mounted Huge Pages File System. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. Starting Configure read-only root support... Starting Create Static Device Nodes in /dev... [ OK ] Reached target Swap. Starting Flush Journal to Persistent Storage... [ OK ] Started udev Coldplug all Devices. [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Reached target Local File Systems (Pre). Mounting /home/green/git/lustre-release... Mounting /mnt... Starting udev Kernel Device Manager... [ OK ] Mounted /mnt. [ 27.725820] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 32.647092] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 33.521020] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [* ] A start job is running for Configur…only root support (10s / no limit)[ 35.744428] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [** ] A start job is running for Configur…only root support (10s / no limit)[ 36.165679] EDAC sbridge: Ver: 1.1.2 [*** ] A start job is running for Configur…only root support (11s / no limit) [ *** ] A start job is running for Configur…only root support (11s / no limit) [ *** ] A start job is running for Configur…only root support (12s / no limit) [ ***] A start job is running for Configur…only root support (13s / no limit) [ **] A start job is running for Configur…only root support (13s / no limit) [ *] A start job is running for Configur…only root support (13s / no limit) [ **] A start job is running for Configur…only root support (14s / no limit) [ ***] A start job is running for Configur…only root support (14s / no limit) [ *** ] A start job is running for Configur…only root support (15s / no limit) [ *** ] A start job is running for Configur…only root support (15s / no limit) [*** ] A start job is running for Configur…only root support (16s / no limit) [** ] A start job is running for Configur…only root support (16s / no limit) [* ] A start job is running for Configur…only root support (17s / no limit)[ 42.433643] Key type dns_resolver registered [** ] A start job is running for Configur…only root support (18s / no limit) [*** ] A start job is running for Configur…only root support (18s / no limit) [ *** ] A start job is running for Configur…only root support (19s / no limit) [ *** ] A start job is running for Configur…only root support (19s / no limit) [ ***] A start job is running for Configur…only root support (20s / no limit)[ 45.440578] NFS: Registering the id_resolver key type [ 45.457424] Key type id_resolver registered [ 45.466877] Key type id_legacy registered [ **] A start job is running for Configur…only root support (20s / no limit) [ *] A start job is running for Configur…only root support (21s / no limit) [ **] A start job is running for Configur…only root support (21s / no limit) [ ***] A start job is running for Configur…only root support (22s / no limit) [ 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 dnf makecache --timer. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Reached target Timers. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Started irqbalance daemon. Starting Login Service... [ OK ] Started D-Bus System Message Bus. [ OK ] Reached target sshd-keygen.target. Starting Network Manager... Starting Restore /run/initramfs on shutdown... [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Network Manager. [ OK ] Reached target Network. Starting Dynamic System Tuning Daemon... Starting OpenSSH server daemon... Starting GSSAPI Proxy Daemon... Starting Network Manager Wait Online... [ OK ] Started OpenSSH server daemon. [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Started Login Service. [ 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 Notify NFS peers of a restart... Starting System Logging Service... Starting Crash recovery kernel arming... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg346-server login: [ 81.778088] hrtimer: interrupt took 5774363 ns [ 112.529180] libcfs: loading out-of-tree module taints kernel. [ 112.586243] Key type ._llcrypt registered [ 112.588030] Key type .llcrypt registered [ 112.698689] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_hostid [ 129.141683] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing load_modules_local [ 130.681340] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 130.691778] alg: No test for adler32 (adler32-zlib) [ 132.281583] Lustre: Lustre: Build Version: 2.17.58_43_g6a42d2c [ 133.259166] LNet: Added LNI 192.168.203.146@tcp [8/256/0/180] [ 135.023406] Key type lgssc registered [ 136.449681] Lustre: Echo OBD driver; http://www.lustre.org/ [ 153.397390] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 191.638507] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing load_modules_local [ 203.902125] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 203.928145] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 205.155026] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 205.190253] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 205.294404] Lustre: lustre-MDT0000: new disk, initializing [ 205.399945] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 205.413944] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 209.388400] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 222.005057] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 222.107519] Lustre: 6525: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 [ 222.140647] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 222.149366] Lustre: Skipped 1 previous similar message [ 222.273435] Lustre: lustre-MDT0001: new disk, initializing [ 222.370721] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 222.411765] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 222.424465] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 226.150212] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 230.456739] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 238.439807] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 238.635933] Lustre: lustre-OST0000: new disk, initializing [ 238.640087] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 238.644312] Lustre: 8461:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 238.699246] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 243.227588] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 243.240697] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 243.347405] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 244.055902] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 257.436301] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 257.576133] Lustre: lustre-OST0001: new disk, initializing [ 257.588918] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 257.600149] Lustre: 9533:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 257.670448] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 263.389220] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 265.304096] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 265.311858] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 265.372695] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 275.266725] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 285.967202] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 291.708582] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing check_logdir /tmp/testlogs/ [ 296.282764] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing yml_node [ 300.823403] Lustre: DEBUG MARKER: Client: 2.17.58.43 [ 303.625861] Lustre: DEBUG MARKER: MDS: 2.17.58.43 [ 306.216482] Lustre: DEBUG MARKER: OSS: 2.17.58.43 [ 307.952381] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity-lfsck ============----- Sun Sep 6 23:48:03 EDT 2026 [ 325.651531] Lustre: DEBUG MARKER: excepting tests: 18b 23b [ 335.082434] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing load_modules_local [ 342.499485] 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 [ 342.502434] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 342.518156] Lustre: Skipped 1 previous similar message [ 342.545977] Lustre: Skipped 3 previous similar messages [ 347.616202] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 347.625629] Lustre: Skipped 3 previous similar messages [ 348.140208] Lustre: server umount lustre-MDT0000 complete [ 356.002550] LustreError: 6517:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788752932 with bad export cookie 17022168240404797225 [ 356.013146] LustreError: MGC192.168.203.146@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 356.014450] LustreError: 6517:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 356.295349] Lustre: server umount lustre-MDT0001 complete [ 373.154722] Lustre: 3655:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788752933/real 1788752933] req@ffff8be887ce1c00 x1875643160690432/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788752949 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 373.184749] 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 [ 373.204735] Lustre: Skipped 2 previous similar messages [ 373.395831] Lustre: server umount lustre-OST0000 complete [ 377.055151] Lustre: 3656:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788752937/real 1788752937] req@ffff8be887ce3100 x1875643160690688/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788752953 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 378.336120] Lustre: 3654:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788752938/real 1788752938] req@ffff8be9b7333800 x1875643160690944/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788752954 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 381.306299] Lustre: server umount lustre-OST0001 complete [ 396.085789] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing unload_modules_local [ 399.189065] Key type lgssc unregistered [ 399.614987] LNet: 14806:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 399.628663] LNetError: 14806:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 399.645223] LNet: Removed LNI 192.168.203.146@tcp [ 400.892273] Key type .llcrypt unregistered [ 400.895162] Key type ._llcrypt unregistered [ 424.222059] Key type ._llcrypt registered [ 424.226020] Key type .llcrypt registered [ 424.347969] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_hostid [ 437.587544] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing load_modules_local [ 438.566593] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 438.579148] alg: No test for adler32 (adler32-zlib) [ 439.588789] Lustre: Lustre: Build Version: 2.17.58_43_g6a42d2c [ 439.852618] LNet: Added LNI 192.168.203.146@tcp [8/256/0/180] [ 441.519178] Key type lgssc registered [ 442.452768] Lustre: Echo OBD driver; http://www.lustre.org/ [ 479.739337] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing load_modules_local [ 490.767159] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 490.817937] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 492.022886] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 492.066650] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 492.142789] Lustre: lustre-MDT0000: new disk, initializing [ 492.240306] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 492.255527] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 496.134592] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 506.964345] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 507.083906] Lustre: 19237: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 [ 507.118408] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 507.121467] Lustre: Skipped 1 previous similar message [ 507.190485] Lustre: lustre-MDT0001: new disk, initializing [ 507.263829] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 507.287535] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 507.295667] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 511.182339] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 515.763989] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 523.261757] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 523.523498] Lustre: lustre-OST0000: new disk, initializing [ 523.530045] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 523.534479] Lustre: 21176:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 523.611051] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 528.876462] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 531.481773] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 531.513406] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 531.556361] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 540.600441] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 540.737206] Lustre: lustre-OST0001: new disk, initializing [ 540.742669] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 540.751452] Lustre: 22198:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 540.825035] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 545.502220] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 548.967771] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 548.979475] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 549.046222] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 555.928290] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 561.574775] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 566.948993] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 23:52:23 (1788753143) === [ 568.922093] Lustre: DEBUG MARKER: == sanity-lfsck test 0: Control LFSCK manually =========== 23:52:25 (1788753145) [ 569.082528] Lustre: 19244:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 251 < left 278, rollback = 2 [ 569.090581] Lustre: 19244:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 569.096915] Lustre: 19244:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 569.101832] Lustre: 19244:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 569.107198] Lustre: 19244:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 569.111844] Lustre: 19244:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 569.616993] Lustre: 19244:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 569.622353] Lustre: 19244:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 17 previous similar messages [ 569.626461] Lustre: 19244:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 569.631681] Lustre: 19244:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 17 previous similar messages [ 569.635828] Lustre: 19244:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 569.640785] Lustre: 19244:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 17 previous similar messages [ 569.645400] Lustre: 19244:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 569.651193] Lustre: 19244:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 17 previous similar messages [ 569.655652] Lustre: 19244:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 569.660814] Lustre: 19244:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 17 previous similar messages [ 569.665659] Lustre: 19244:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 569.671035] Lustre: 19244:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 17 previous similar messages [ 570.627114] Lustre: 19243:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 570.632111] Lustre: 19243:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 59 previous similar messages [ 570.636296] Lustre: 19243:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 570.641625] Lustre: 19243:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 59 previous similar messages [ 570.646092] Lustre: 19243:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 570.650867] Lustre: 19243:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 59 previous similar messages [ 570.660876] Lustre: 19243:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 570.671470] Lustre: 19243:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 59 previous similar messages [ 570.678559] Lustre: 19243:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 570.684025] Lustre: 19243:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 59 previous similar messages [ 570.693078] Lustre: 19243:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 570.698251] Lustre: 19243:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 59 previous similar messages [ 572.667331] Lustre: 19242:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 572.676453] Lustre: 19242:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 113 previous similar messages [ 572.682726] Lustre: 19242:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 572.687380] Lustre: 19242:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 113 previous similar messages [ 572.693989] Lustre: 19242:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 572.697806] Lustre: 19242:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 113 previous similar messages [ 572.701876] Lustre: 19242:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 572.706990] Lustre: 19242:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 113 previous similar messages [ 572.715051] Lustre: 19242:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 572.719736] Lustre: 19242:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 113 previous similar messages [ 572.724960] Lustre: 19242:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 572.729775] Lustre: 19242:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 113 previous similar messages [ 575.251915] Lustre: *** cfs_fail_loc=1600, val=3*** [ 578.509337] Lustre: *** cfs_fail_loc=1600, val=3*** [ 579.169292] Lustre: 21165:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-OST0001: opcode 2: before 259 < left 274, rollback = 2 [ 579.176642] Lustre: 21165:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 87 previous similar messages [ 579.181153] Lustre: 21165:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 579.185438] Lustre: 21165:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 87 previous similar messages [ 579.196222] Lustre: 21165:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/1, xattr_set: 2/274/0 [ 579.198746] Lustre: 23769:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 0/0/0, punch: 0/0/0, quota 7/225/0 [ 579.202414] Lustre: 21165:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 88 previous similar messages [ 579.202448] Lustre: 21165:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 579.202451] Lustre: 21165:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 87 previous similar messages [ 579.202457] Lustre: 21165:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 579.202460] Lustre: 21165:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 87 previous similar messages [ 579.256448] Lustre: 23769:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 93 previous similar messages [ 589.280855] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 589.293089] 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 [ 589.309409] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 590.307490] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 590.308759] 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 [ 590.312386] Lustre: Skipped 1 previous similar message [ 590.337878] Lustre: Skipped 2 previous similar messages [ 590.752646] Lustre: server umount lustre-MDT0000 complete [ 593.764113] LustreError: 19228:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788753169 with bad export cookie 16017496920262679174 [ 593.765339] LustreError: MGC192.168.203.146@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 593.774070] LustreError: 19228:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 3 previous similar messages [ 593.985309] Lustre: server umount lustre-MDT0001 complete [ 607.776475] Lustre: server umount lustre-OST0000 complete [ 611.679221] Lustre: 16395:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788753171/real 1788753171] req@ffff8be88cad4000 x1875643481556096/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788753187 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 611.730255] 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 [ 614.012409] Lustre: server umount lustre-OST0001 complete [ 628.191947] Lustre: DEBUG MARKER: == sanity-lfsck test 1a: LFSCK can find out and repair crashed FID-in-dirent ========================================================== 23:53:23 (1788753203) [ 645.508775] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing load_modules_local [ 658.932536] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 659.441951] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 664.184854] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 664.543927] LustreError: 26253:0:(ldlm_lib.c:1202:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 664.569380] LustreError: 26253:0:(ldlm_lib.c:1202:target_handle_connect()) Skipped 2 previous similar messages [ 669.667646] LustreError: 26252:0:(ldlm_lib.c:1202:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 673.668194] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 674.049934] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 678.918416] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 681.795513] Lustre: 27395:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 688.869683] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 695.447641] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 698.469806] LustreError: 27749:0:(ldlm_lib.c:1202:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 703.790296] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 704.050803] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 704.054995] Lustre: Skipped 1 previous similar message [ 705.066885] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:41 to 0x2c0000401:65) [ 705.082201] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:40 to 0x280000401:65) [ 709.808081] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 716.580562] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 720.042033] Lustre: 29266:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 721.785215] Lustre: 26248:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 721.799126] Lustre: 26248:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 66 previous similar messages [ 721.811808] Lustre: 26248:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 721.824609] Lustre: 26248:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 66 previous similar messages [ 721.837845] Lustre: 26248:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 721.852369] Lustre: 26248:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 65 previous similar messages [ 721.860557] Lustre: 26248:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 721.870175] Lustre: 26248:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 60 previous similar messages [ 721.881934] Lustre: 26248:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 721.892105] Lustre: 26248:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 66 previous similar messages [ 721.899656] Lustre: 26248:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 721.910761] Lustre: 26248:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 66 previous similar messages [ 727.704571] Lustre: *** cfs_fail_loc=1501, val=0*** [ 734.983313] Lustre: Failing over lustre-MDT0000 [ 735.243898] Lustre: server umount lustre-MDT0000 complete [ 735.712061] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 735.713876] 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 [ 735.721308] LustreError: 26247:0:(ldlm_lib.c:1202:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 735.754680] Lustre: Skipped 3 previous similar messages [ 740.840331] LustreError: 26248:0:(ldlm_lib.c:1202:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 740.871276] LustreError: 26248:0:(ldlm_lib.c:1202:target_handle_connect()) Skipped 6 previous similar messages [ 744.899499] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 745.003937] LustreError: MGC192.168.203.146@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 745.230945] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 745.274331] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 749.384835] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 750.562347] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 750.568536] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 750.614549] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 750.660910] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:105 to 0x280000401:129) [ 750.662293] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:105 to 0x2c0000401:129) [ 752.791554] Lustre: *** cfs_fail_loc=1505, val=0*** [ 759.819243] Lustre: DEBUG MARKER: == sanity-lfsck test 1b: LFSCK can find out and repair the missing FID-in-LMA ========================================================== 23:55:35 (1788753335) [ 760.979756] Lustre: 26249:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 760.989714] Lustre: 26249:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 322 previous similar messages [ 760.997969] Lustre: 26249:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 761.005135] Lustre: 26249:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 761.013477] Lustre: 26249:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 761.021799] Lustre: 26249:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 761.029377] Lustre: 26249:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 761.034803] Lustre: 26249:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 761.042678] Lustre: 26249:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 761.048495] Lustre: 26249:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 761.054479] Lustre: 26249:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 761.061187] Lustre: 26249:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 766.622386] Lustre: *** cfs_fail_loc=1502, val=0*** [ 776.351626] Lustre: Failing over lustre-MDT0000 [ 776.609550] Lustre: server umount lustre-MDT0000 complete [ 781.279723] 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 [ 781.282501] LustreError: 28572:0:(ldlm_lib.c:1202:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 781.299630] Lustre: Skipped 2 previous similar messages [ 781.322666] LustreError: 28572:0:(ldlm_lib.c:1202:target_handle_connect()) Skipped 3 previous similar messages [ 785.713268] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 785.832142] LustreError: MGC192.168.203.146@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 786.162321] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 790.640949] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 791.528974] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 791.529943] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 791.563251] Lustre: Skipped 3 previous similar messages [ 791.580482] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 791.626356] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:169 to 0x280000401:193) [ 791.627474] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:169 to 0x2c0000401:193) [ 793.762021] Lustre: *** cfs_fail_loc=1505, val=0*** [ 800.617535] Lustre: DEBUG MARKER: == sanity-lfsck test 1c: LFSCK can find out and repair lost FID-in-dirent ========================================================== 23:56:16 (1788753376) [ 801.823703] Lustre: 26248:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 255 < left 278, rollback = 2 [ 801.828616] Lustre: 26248:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 322 previous similar messages [ 801.832534] Lustre: 26248:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/2, destroy: 0/0/0 [ 801.835347] Lustre: 26248:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 801.839611] Lustre: 26248:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 801.845970] Lustre: 26248:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 801.850245] Lustre: 26248:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 801.856233] Lustre: 26248:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 801.860339] Lustre: 26248:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 801.864962] Lustre: 26248:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 801.869159] Lustre: 26248:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 801.875554] Lustre: 26248:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 807.771110] Lustre: *** cfs_fail_loc=1504, val=0*** [ 807.783158] Lustre: *** cfs_fail_loc=1504, val=0*** [ 807.790913] Lustre: Skipped 1 previous similar message [ 815.431564] Lustre: Failing over lustre-MDT0000 [ 815.783262] Lustre: server umount lustre-MDT0000 complete [ 817.120773] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 817.124139] 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 [ 817.138535] LustreError: 26253:0:(ldlm_lib.c:1202:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 817.144552] Lustre: Skipped 3 previous similar messages [ 817.163404] LustreError: 26253:0:(ldlm_lib.c:1202:target_handle_connect()) Skipped 3 previous similar messages [ 826.314915] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 826.442581] LustreError: MGC192.168.203.146@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 826.754368] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 826.764605] Lustre: Skipped 1 previous similar message [ 826.805515] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 830.880783] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 831.980127] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 831.981503] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 832.001129] Lustre: Skipped 3 previous similar messages [ 832.033959] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 832.098770] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:233 to 0x2c0000401:257) [ 832.100965] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:233 to 0x280000401:257) [ 834.612066] Lustre: *** cfs_fail_loc=1505, val=0*** [ 841.833548] Lustre: DEBUG MARKER: == sanity-lfsck test 2a: LFSCK can find out and repair crashed linkEA entry ========================================================== 23:56:57 (1788753417) [ 848.452205] Lustre: *** cfs_fail_loc=1603, val=0*** [ 855.668301] Lustre: Failing over lustre-MDT0000 [ 855.958523] Lustre: server umount lustre-MDT0000 complete [ 857.568206] 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 [ 857.571680] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 857.574741] LustreError: 26248:0:(ldlm_lib.c:1202:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 857.574752] LustreError: 26248:0:(ldlm_lib.c:1202:target_handle_connect()) Skipped 4 previous similar messages [ 857.594535] Lustre: Skipped 3 previous similar messages [ 865.540503] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 865.637520] LustreError: MGC192.168.203.146@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 865.901461] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 870.740450] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 870.883123] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 870.893281] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 870.901855] Lustre: Skipped 3 previous similar messages [ 870.928737] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 870.991953] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:297 to 0x2c0000401:321) [ 870.993186] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:297 to 0x280000401:321) [ 879.086420] Lustre: DEBUG MARKER: == sanity-lfsck test 2b: LFSCK can find out and remove invalid linkEA entry ========================================================== 23:57:34 (1788753454) [ 880.386335] Lustre: 26247:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 880.393718] Lustre: 26247:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 644 previous similar messages [ 880.399127] Lustre: 26247:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 880.404328] Lustre: 26247:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 880.409836] Lustre: 26247:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 880.416034] Lustre: 26247:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 880.421397] Lustre: 26247:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 880.429211] Lustre: 26247:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 880.437026] Lustre: 26247:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 880.448197] Lustre: 26247:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 880.458919] Lustre: 26247:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 880.470582] Lustre: 26247:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 886.452200] Lustre: *** cfs_fail_loc=1604, val=0*** [ 895.297736] Lustre: Failing over lustre-MDT0000 [ 895.587940] Lustre: server umount lustre-MDT0000 complete [ 896.480042] 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 [ 896.501387] Lustre: Skipped 3 previous similar messages [ 905.998889] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 906.093371] LustreError: MGC192.168.203.146@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 906.304478] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 910.631214] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 911.330685] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 911.340605] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 911.359528] Lustre: Skipped 3 previous similar messages [ 911.370889] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 911.403521] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:361 to 0x280000401:385) [ 911.405068] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:361 to 0x2c0000401:385) [ 918.122908] Lustre: DEBUG MARKER: == sanity-lfsck test 2c: LFSCK can find out and remove repeated linkEA entry ========================================================== 23:58:13 (1788753493) [ 924.362687] Lustre: *** cfs_fail_loc=1605, val=0*** [ 932.037770] Lustre: Failing over lustre-MDT0000 [ 932.346363] Lustre: server umount lustre-MDT0000 complete [ 936.927760] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 936.936222] LustreError: 32547:0:(ldlm_lib.c:1202:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 936.955669] LustreError: 32547:0:(ldlm_lib.c:1202:target_handle_connect()) Skipped 18 previous similar messages [ 942.385771] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 942.505716] LustreError: MGC192.168.203.146@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 942.776363] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 946.976537] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 948.201469] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 948.215695] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 948.223501] Lustre: Skipped 3 previous similar messages [ 948.239412] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 948.282767] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:425 to 0x2c0000401:449) [ 948.282888] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:425 to 0x280000401:449) [ 955.209887] Lustre: DEBUG MARKER: == sanity-lfsck test 2d: LFSCK can recover the missing linkEA entry ========================================================== 23:58:51 (1788753531) [ 961.758929] Lustre: *** cfs_fail_loc=161d, val=0*** [ 969.439664] Lustre: Failing over lustre-MDT0000 [ 969.654908] Lustre: server umount lustre-MDT0000 complete [ 973.791643] 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 [ 973.797302] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 973.805566] Lustre: Skipped 7 previous similar messages [ 978.412749] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 978.499569] LustreError: MGC192.168.203.146@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 978.722076] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 978.727366] Lustre: Skipped 3 previous similar messages [ 978.752511] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 983.008081] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 984.032224] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 984.061504] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 984.072862] Lustre: Skipped 3 previous similar messages [ 984.096415] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 984.124242] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:489 to 0x280000401:513) [ 984.128238] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:489 to 0x2c0000401:513) [ 990.841477] Lustre: DEBUG MARKER: == sanity-lfsck test 2e: namespace LFSCK can verify remote object linkEA ========================================================== 23:59:26 (1788753566) [ 993.293633] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1004.377601] Lustre: DEBUG MARKER: == sanity-lfsck test 3: LFSCK can verify multiple-linked objects ========================================================== 23:59:39 (1788753579) [ 1008.438347] Lustre: 26247:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 1008.445071] Lustre: 26247:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 1181 previous similar messages [ 1008.451406] Lustre: 26247:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 1008.455301] Lustre: 26247:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1181 previous similar messages [ 1008.459987] Lustre: 26247:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 1008.464027] Lustre: 26247:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1181 previous similar messages [ 1008.469776] Lustre: 26247:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 1008.478874] Lustre: 26247:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1181 previous similar messages [ 1008.484828] Lustre: 26247:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 1008.488741] Lustre: 26247:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1181 previous similar messages [ 1008.492211] Lustre: 26247:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 1008.497722] Lustre: 26247:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1181 previous similar messages [ 1010.420536] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1011.433087] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1024.226676] Lustre: DEBUG MARKER: == sanity-lfsck test 4: FID-in-dirent can be rebuilt after MDT file-level backup/restore ========================================================== 00:00:00 (1788753600) [ 1058.830254] Lustre: Failing over lustre-MDT0000 [ 1059.048831] Lustre: server umount lustre-MDT0000 complete [ 1060.838156] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1064.310574] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1065.952722] LustreError: 26248:0:(ldlm_lib.c:1202:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1065.960726] LustreError: 26248:0:(ldlm_lib.c:1202:target_handle_connect()) Skipped 13 previous similar messages [ 1072.516187] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1076.687399] Lustre: 16396:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788753636/real 1788753636] req@ffff8be9bdec3800 x1875643482180608/t0(0) o400->MGC192.168.203.146@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1788753652 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1076.706820] LustreError: MGC192.168.203.146@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1082.067876] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1082.081723] Lustre: lustre-MDT0000: reset Object Index mappings [ 1086.944818] LustreError: 16394:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8be9bdcd1180 x1875643482189184/t0(0) o250->MGC192.168.203.146@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 [ 1087.349159] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1091.878406] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1092.619548] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 1092.621194] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1092.626743] Lustre: Skipped 3 previous similar messages [ 1092.654516] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1092.722742] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:592 to 0x280000401:609) [ 1092.722892] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:592 to 0x2c0000401:609) [ 1095.822208] LustreError: 42920:0:(lfsck_engine.c:1018:lfsck_master_engine()) lustre-MDT0000-osd: master engine fail to verify the .lustre/lost+found/, go ahead: rc = -115 [ 1095.844424] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1097.888367] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1097.903408] Lustre: Skipped 1 previous similar message [ 1106.575920] Lustre: Failing over lustre-MDT0000 [ 1107.935681] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1107.937192] 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 [ 1107.967462] Lustre: Skipped 8 previous similar messages [ 1108.824054] Lustre: server umount lustre-MDT0000 complete [ 1118.044218] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1118.181132] Lustre: lustre-MDT0000: Not available for connect from 0@lo (not set up) [ 1118.186937] Lustre: Skipped 5 previous similar messages [ 1123.011530] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1123.909094] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:592 to 0x2c0000401:641) [ 1123.916891] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:592 to 0x280000401:641) [ 1126.695352] Lustre: *** cfs_fail_loc=1505, val=0*** [ 1135.123590] Lustre: DEBUG MARKER: == sanity-lfsck test 5: LFSCK can handle IGIF object upgrading ========================================================== 00:01:50 (1788753710) [ 1137.959775] Lustre: *** cfs_fail_loc=1504, val=0*** [ 1146.670757] Lustre: Failing over lustre-MDT0000 [ 1146.926756] Lustre: server umount lustre-MDT0000 complete [ 1151.568236] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1160.594221] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1165.796187] Lustre: 16398:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788753725/real 1788753725] req@ffff8be9c1fc2680 x1875643482277248/t0(0) o400->MGC192.168.203.146@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1788753741 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1171.467101] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1171.494730] Lustre: lustre-MDT0000: reset Object Index mappings [ 1175.009938] LustreError: 16394:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8be9b7331c00 x1875643482285568/t0(0) o250->MGC192.168.203.146@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 [ 1175.219057] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1175.221976] Lustre: Skipped 1 previous similar message [ 1178.893828] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1180.647326] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1180.653384] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1180.658583] Lustre: Skipped 1 previous similar message [ 1180.668949] Lustre: Skipped 7 previous similar messages [ 1180.686946] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1180.691796] Lustre: Skipped 1 previous similar message [ 1180.716565] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:681 to 0x2c0000401:705) [ 1180.720687] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:681 to 0x280000401:705) [ 1182.068178] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1182.073445] Lustre: Skipped 2 previous similar messages [ 1194.817839] Lustre: Failing over lustre-MDT0000 [ 1195.021344] Lustre: server umount lustre-MDT0000 complete [ 1195.999988] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1196.007130] LustreError: Skipped 1 previous similar message [ 1203.380065] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1207.284765] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1208.849126] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:681 to 0x2c0000401:737) [ 1208.851318] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:681 to 0x280000401:737) [ 1210.254273] Lustre: *** cfs_fail_loc=1505, val=0*** [ 1210.256142] Lustre: Skipped 84 previous similar messages [ 1217.087552] Lustre: DEBUG MARKER: == sanity-lfsck test 6a: LFSCK resumes from last checkpoint (1) ========================================================== 00:03:12 (1788753792) [ 1225.230937] Lustre: *** cfs_fail_loc=1600, val=1*** [ 1225.234883] Lustre: Skipped 7 previous similar messages [ 1242.393961] Lustre: DEBUG MARKER: == sanity-lfsck test 6b: LFSCK resumes from last checkpoint (2) ========================================================== 00:03:38 (1788753818) [ 1250.912342] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1250.921230] Lustre: Skipped 8 previous similar messages [ 1272.954684] Lustre: DEBUG MARKER: == sanity-lfsck test 7a: non-stopped LFSCK should auto restarts after MDS remount (1) ========================================================== 00:04:08 (1788753848) [ 1274.628658] Lustre: 26248:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 1274.641116] Lustre: 26248:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 1435 previous similar messages [ 1274.657436] Lustre: 26248:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 1274.674274] Lustre: 26248:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1435 previous similar messages [ 1274.680108] Lustre: 26248:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 1274.687314] Lustre: 26248:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1435 previous similar messages [ 1274.694747] Lustre: 26248:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 1274.701965] Lustre: 26248:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1435 previous similar messages [ 1274.707463] Lustre: 26248:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 1274.715336] Lustre: 26248:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1435 previous similar messages [ 1274.721348] Lustre: 26248:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 1274.734445] Lustre: 26248:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1435 previous similar messages [ 1283.620685] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1283.623804] Lustre: Skipped 12 previous similar messages [ 1288.857354] Lustre: Failing over lustre-MDT0000 [ 1289.084347] Lustre: server umount lustre-MDT0000 complete [ 1297.617343] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1297.703180] LustreError: MGC192.168.203.146@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1297.710573] LustreError: Skipped 3 previous similar messages [ 1297.927285] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1297.932898] Lustre: Skipped 4 previous similar messages [ 1302.540105] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1303.098709] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:853 to 0x2c0000401:897) [ 1303.100904] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:854 to 0x280000401:897) [ 1310.899849] Lustre: DEBUG MARKER: == sanity-lfsck test 7b: non-stopped LFSCK should auto restarts after MDS remount (2) ========================================================== 00:04:46 (1788753886) [ 1323.853220] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing load_modules_local [ 1340.426402] Lustre: 53032:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 1360.491571] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1363.374602] Lustre: 54168:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 1370.675025] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1370.680389] Lustre: Skipped 81 previous similar messages [ 1373.066138] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1374.112360] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1375.135549] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1377.183146] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1377.190452] Lustre: Skipped 1 previous similar message [ 1377.353508] Lustre: Failing over lustre-MDT0000 [ 1377.653984] Lustre: server umount lustre-MDT0000 complete [ 1379.808331] 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 [ 1379.811286] LustreError: 28572:0:(ldlm_lib.c:1202:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1379.823878] Lustre: Skipped 14 previous similar messages [ 1379.824901] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1379.836635] LustreError: 28572:0:(ldlm_lib.c:1202:target_handle_connect()) Skipped 67 previous similar messages [ 1379.852410] LustreError: Skipped 1 previous similar message [ 1385.493184] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1385.826511] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1385.835846] Lustre: Skipped 2 previous similar messages [ 1389.370919] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1391.073274] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1391.081464] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1391.083261] Lustre: Skipped 2 previous similar messages [ 1391.090507] Lustre: Skipped 11 previous similar messages [ 1391.102919] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1391.120355] Lustre: Skipped 2 previous similar messages [ 1391.162412] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:946 to 0x2c0000401:961) [ 1391.167229] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:947 to 0x280000401:993) [ 1397.729940] Lustre: DEBUG MARKER: == sanity-lfsck test 8: LFSCK state machine ============== 00:06:13 (1788753973) [ 1401.312701] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1401.312701] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1401.327796] Lustre: Skipped 2 previous similar messages [ 1407.782883] Lustre: server umount lustre-MDT0000 complete [ 1411.134658] LustreError: 30876:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788753987 with bad export cookie 16017496920262893794 [ 1411.147644] LustreError: 30876:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 1411.469725] Lustre: server umount lustre-MDT0001 complete [ 1425.080278] Lustre: server umount lustre-OST0000 complete [ 1427.940881] Lustre: 16395:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788753987/real 1788753987] req@ffff8be9be664700 x1875643482585856/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788754003 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1428.258094] Lustre: server umount lustre-OST0001 complete [ 1433.472345] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_hostid [ 1440.379148] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing load_modules_local [ 1478.706748] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing load_modules_local [ 1486.351855] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1486.538381] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 1486.565810] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 1486.630559] Lustre: lustre-MDT0000: new disk, initializing [ 1486.695347] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 1489.880481] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1498.027485] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1498.113400] Lustre: 59227: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 [ 1498.135798] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 1498.139848] Lustre: Skipped 1 previous similar message [ 1498.194627] Lustre: lustre-MDT0001: new disk, initializing [ 1498.272236] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 1498.283064] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 1501.069191] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1504.858531] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 1510.273805] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 1510.392503] Lustre: lustre-OST0000: new disk, initializing [ 1510.397847] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 1510.403189] Lustre: 60857:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 1512.402029] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 1512.415402] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 1512.481680] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 1515.602350] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1524.952289] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 1525.122172] Lustre: lustre-OST0001: new disk, initializing [ 1525.129990] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 1525.140231] Lustre: 61727:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 1526.349355] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 1526.354577] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 1526.379093] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 1529.592150] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1537.478435] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1540.676431] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 1551.331781] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1552.231490] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1552.234338] Lustre: Skipped 19 previous similar messages [ 1556.018648] Lustre: *** cfs_fail_loc=1601, val=2*** [ 1556.023657] Lustre: Skipped 5 previous similar messages [ 1570.334697] Lustre: Failing over lustre-MDT0000 [ 1570.529069] Lustre: server umount lustre-MDT0000 complete [ 1578.717884] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1578.842816] LustreError: MGC192.168.203.146@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1578.852467] LustreError: Skipped 2 previous similar messages [ 1582.985694] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1584.154747] Lustre: *** cfs_fail_loc=160b, val=2*** [ 1584.157892] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:65) [ 1584.159019] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:65) [ 1590.082938] Lustre: Failing over lustre-MDT0000 [ 1590.308433] Lustre: server umount lustre-MDT0000 complete [ 1598.522805] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1602.535721] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1604.156231] Lustre: *** cfs_fail_loc=160b, val=2*** [ 1604.172880] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:97) [ 1604.187266] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:97) [ 1606.589793] Lustre: Failing over lustre-MDT0000 [ 1606.764077] Lustre: server umount lustre-MDT0000 complete [ 1613.637942] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1617.716034] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1619.515203] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:129) [ 1619.518114] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:129) [ 1622.568404] Lustre: *** cfs_fail_loc=1602, val=2*** [ 1636.102488] Lustre: DEBUG MARKER: == sanity-lfsck test 9a: LFSCK speed control (1) ========= 00:10:11 (1788754211) [ 1650.486051] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing load_modules_local [ 1668.546679] Lustre: 68678:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 1691.278344] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1694.885470] Lustre: 69816:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 1811.952825] Lustre: DEBUG MARKER: == sanity-lfsck test 9b: LFSCK speed control (2) ========= 00:13:07 (1788754387) [ 1856.017184] Lustre: 59233:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 251 < left 278, rollback = 2 [ 1856.028350] Lustre: 59233:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 17060 previous similar messages [ 1856.036197] Lustre: 59233:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 1856.045424] Lustre: 59233:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 17060 previous similar messages [ 1856.054255] Lustre: 59233:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 1856.065633] Lustre: 59233:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 17060 previous similar messages [ 1856.074502] Lustre: 59233:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 1856.084186] Lustre: 59233:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 17060 previous similar messages [ 1856.088084] Lustre: 59233:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 1856.092688] Lustre: 59233:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 17060 previous similar messages [ 1856.099938] Lustre: 59233:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 1856.110417] Lustre: 59233:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 17060 previous similar messages [ 1861.901625] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1861.907420] Lustre: Skipped 4 previous similar messages [ 1887.789751] Lustre: *** cfs_fail_loc=160c, val=0*** [ 1887.793189] Lustre: Skipped 7 previous similar messages [ 1921.468462] Lustre: DEBUG MARKER: == sanity-lfsck test 10: System is available during LFSCK scanning ========================================================== 00:14:57 (1788754497) [ 1966.928431] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1974.930762] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1974.936497] Lustre: Skipped 460 previous similar messages [ 1990.934406] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1990.936535] Lustre: Skipped 801 previous similar messages [ 2022.954482] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2022.956858] Lustre: Skipped 1774 previous similar messages [ 2032.737142] Lustre: *** cfs_fail_loc=1604, val=0*** [ 2032.740108] Lustre: Skipped 2599 previous similar messages [ 2258.058659] Lustre: DEBUG MARKER: == sanity-lfsck test 11a: LFSCK can rebuild lost last_id ========================================================== 00:20:33 (1788754833) [ 2418.151508] 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 [ 2418.152465] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2418.185810] Lustre: Skipped 19 previous similar messages [ 2423.267445] LustreError: 60121:0:(ldlm_lib.c:1202:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 2423.307602] LustreError: 60121:0:(ldlm_lib.c:1202:target_handle_connect()) Skipped 27 previous similar messages [ 2423.480431] Lustre: server umount lustre-MDT0000 complete [ 2427.168829] LustreError: 69840:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788755003 with bad export cookie 16017496920262912897 [ 2427.172871] LustreError: MGC192.168.203.146@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2427.180472] LustreError: 69840:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 2427.190503] LustreError: Skipped 2 previous similar messages [ 2427.511696] Lustre: server umount lustre-MDT0001 complete [ 2441.659198] Lustre: server umount lustre-OST0000 complete [ 2444.639239] Lustre: 16398:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788755004/real 1788755004] req@ffff8be890c77800 x1875643486381824/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788755020 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2445.346285] Lustre: server umount lustre-OST0001 complete [ 2451.693658] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: (null) [ 2460.082981] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 2475.681516] LustreError: Failed to get MGS log lustre-sptlrpc and no local copy. [ 2480.799396] LustreError: 75302:0:(mgc_request.c:233:do_config_log_add()) MGC192.168.203.146@tcp: failed processing log, type 4: rc = -110 [ 2506.463311] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 2506.476467] Lustre: Skipped 8 previous similar messages [ 2512.945404] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2516.481982] Lustre: 75886:0:(ofd_dev.c:563:ofd_lfsck_out_notify()) lustre-OST0000: Found crashed LAST_ID, deny creating new OST-object on the device until the LAST_ID rebuilt successfully. [ 2516.501822] Lustre: *** cfs_fail_loc=160e, val=3*** [ 2519.526660] Lustre: 75886:0:(ofd_dev.c:575:ofd_lfsck_out_notify()) lustre-OST0000: Rebuilt crashed LAST_ID files successfully. [ 2529.131558] Lustre: DEBUG MARKER: == sanity-lfsck test 11b: LFSCK can rebuild crashed last_id ========================================================== 00:25:04 (1788755104) [ 2543.038802] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing load_modules_local [ 2552.387410] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2552.775139] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3271 to 0x280000401:3297) [ 2556.986266] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2564.975306] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2568.621375] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2570.827901] Lustre: 78551:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 2584.710097] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2584.978829] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 2584.988114] Lustre: Skipped 2 previous similar messages [ 2590.211407] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3208 to 0x2c0000401:3233) [ 2591.110188] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2597.947430] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 2600.873873] Lustre: 80050:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 2601.912470] Lustre: 78219:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 257 < left 278, rollback = 2 [ 2601.919154] Lustre: 78219:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 22020 previous similar messages [ 2601.924026] Lustre: 78219:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 2601.928148] Lustre: 78219:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 22021 previous similar messages [ 2601.932542] Lustre: 78219:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 2601.937581] Lustre: 78219:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 22021 previous similar messages [ 2601.943342] Lustre: 78219:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 2601.955803] Lustre: 78219:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 22021 previous similar messages [ 2601.961156] Lustre: 78219:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 2601.964212] Lustre: 78219:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 22021 previous similar messages [ 2601.966432] Lustre: 78219:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 2601.969336] Lustre: 78219:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 22021 previous similar messages [ 2604.447566] Lustre: *** cfs_fail_loc=160d, val=0*** [ 2609.934136] Lustre: Failing over lustre-OST0000 [ 2610.031778] Lustre: server umount lustre-OST0000 complete [ 2617.264706] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2617.469961] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 2617.473428] Lustre: Skipped 3 previous similar messages [ 2619.364704] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 2619.383080] Lustre: Skipped 3 previous similar messages [ 2619.413305] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 2619.414277] Lustre: lustre-OST0000-osc-MDT0001: Connection restored to 0@lo (at 0@lo) [ 2619.419258] Lustre: *** cfs_fail_loc=215, val=0*** [ 2619.421088] Lustre: Skipped 3 previous similar messages [ 2619.431869] Lustre: Skipped 15 previous similar messages [ 2622.075599] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2624.479721] Lustre: *** cfs_fail_loc=215, val=0*** [ 2624.482727] Lustre: Skipped 1 previous similar message [ 2624.703882] Lustre: 81450:0:(ofd_dev.c:563:ofd_lfsck_out_notify()) lustre-OST0000: Found crashed LAST_ID, deny creating new OST-object on the device until the LAST_ID rebuilt successfully. [ 2624.731228] Lustre: 81450:0:(ofd_dev.c:575:ofd_lfsck_out_notify()) lustre-OST0000: Rebuilt crashed LAST_ID files successfully. [ 2626.799164] Lustre: Failing over lustre-OST0000 [ 2626.868276] Lustre: server umount lustre-OST0000 complete [ 2634.022205] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2635.772979] Lustre: *** cfs_fail_loc=215, val=0*** [ 2639.902952] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2640.865583] Lustre: *** cfs_fail_loc=215, val=0*** [ 2640.875274] Lustre: Skipped 2 previous similar messages [ 2647.519926] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 2647.526413] LustreError: Skipped 1 previous similar message [ 2647.532910] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2647.535820] Lustre: Skipped 3 previous similar messages [ 2649.570185] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2649.578723] Lustre: Skipped 3 previous similar messages [ 2651.989775] Lustre: server umount lustre-MDT0000 complete [ 2655.317677] LustreError: 75309:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788755231 with bad export cookie 16017496920264475745 [ 2655.338698] LustreError: 75309:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 2655.547902] Lustre: server umount lustre-MDT0001 complete [ 2668.085207] Lustre: server umount lustre-OST0000 complete [ 2682.006403] Lustre: server umount lustre-OST0001 complete [ 2690.130086] Lustre: DEBUG MARKER: == sanity-lfsck test 12a: single command to trigger LFSCK on all devices ========================================================== 00:27:46 (1788755266) [ 2703.008665] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing load_modules_local [ 2712.121255] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2717.668618] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2725.466052] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2725.752225] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 2725.757682] Lustre: Skipped 3 previous similar messages [ 2730.268768] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2733.084165] Lustre: 85834:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 2738.585996] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2744.392821] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2752.816165] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2757.098756] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3362 to 0x280000401:3393) [ 2757.104855] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3208 to 0x2c0000401:3265) [ 2760.215424] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2767.316500] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 2770.573871] Lustre: 87706:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 2803.570898] Lustre: DEBUG MARKER: == sanity-lfsck test 12b: auto detect Lustre device ====== 00:29:39 (1788755379) [ 2818.029150] Lustre: DEBUG MARKER: == sanity-lfsck test 13: LFSCK can repair crashed lmm_oi ========================================================== 00:29:53 (1788755393) [ 2819.295410] Lustre: *** cfs_fail_loc=160f, val=0*** [ 2828.937148] Lustre: DEBUG MARKER: == sanity-lfsck test 14a: LFSCK can repair MDT-object with dangling LOV EA reference (1) ========================================================== 00:30:04 (1788755404) [ 2832.476318] Lustre: *** cfs_fail_loc=1610, val=0*** [ 2832.480883] Lustre: Skipped 7 previous similar messages [ 2879.457577] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 2879.465386] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2883.968368] Lustre: server umount lustre-MDT0000 complete [ 2886.993851] LustreError: 84674:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788755463 with bad export cookie 16017496920264484229 [ 2887.001874] LustreError: 84674:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 2887.197398] Lustre: server umount lustre-MDT0001 complete [ 2900.625228] Lustre: server umount lustre-OST0000 complete [ 2914.849223] Lustre: server umount lustre-OST0001 complete [ 2929.864472] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing load_modules_local [ 2939.294080] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2944.845896] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2954.713777] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2959.738329] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2962.436759] Lustre: 93568:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 2968.388649] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2974.518877] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2980.836092] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:116 to 0x280000400:161) [ 2980.945033] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2984.116660] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3554 to 0x280000401:3585) [ 2984.117173] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3317 to 0x2c0000401:3361) [ 2984.128838] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:116 to 0x2c0000400:161) [ 2985.844594] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2992.566345] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 2996.142892] Lustre: 95439:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 3002.056552] Lustre: DEBUG MARKER: == sanity-lfsck test 14b: LFSCK can repair MDT-object with dangling LOV EA reference (2) ========================================================== 00:32:57 (1788755577) [ 3007.224604] Lustre: *** cfs_fail_loc=1610, val=0*** [ 3007.226984] Lustre: Skipped 63 previous similar messages [ 3030.500422] 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 [ 3030.501287] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3030.529274] Lustre: Skipped 18 previous similar messages [ 3030.537578] Lustre: Skipped 6 previous similar messages [ 3036.940142] Lustre: server umount lustre-MDT0000 complete [ 3040.686370] LustreError: 92409:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788755616 with bad export cookie 16017496920264512642 [ 3040.702209] LustreError: MGC192.168.203.146@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3040.713948] LustreError: Skipped 2 previous similar messages [ 3040.738783] LustreError: 92423:0:(ldlm_lib.c:1202:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3040.758226] LustreError: 92423:0:(ldlm_lib.c:1202:target_handle_connect()) Skipped 43 previous similar messages [ 3041.023496] Lustre: server umount lustre-MDT0001 complete [ 3047.056426] Lustre: server umount lustre-OST0000 complete [ 3050.498641] Lustre: server umount lustre-OST0001 complete [ 3068.564248] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing load_modules_local [ 3078.395808] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3078.741946] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3078.747432] Lustre: Skipped 6 previous similar messages [ 3082.916694] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3090.657273] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3094.656736] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3097.265510] Lustre: 99469:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3103.846387] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3110.012892] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3115.438652] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:116 to 0x280000400:193) [ 3118.065826] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3123.381720] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:116 to 0x2c0000400:193) [ 3123.383569] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3317 to 0x2c0000401:3393) [ 3123.386420] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3682 to 0x280000401:3713) [ 3124.097595] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3130.771278] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3140.828364] Lustre: DEBUG MARKER: == sanity-lfsck test 15a: LFSCK can repair unmatched MDT-object/OST-object pairs (1) ========================================================== 00:35:16 (1788755716) [ 3144.947518] Lustre: *** cfs_fail_loc=1611, val=0*** [ 3144.950342] Lustre: Skipped 63 previous similar messages [ 3145.180315] Lustre: *** cfs_fail_loc=1611, val=0*** [ 3161.293888] Lustre: DEBUG MARKER: == sanity-lfsck test 15b: LFSCK can repair unmatched MDT-object/OST-object pairs (2) ========================================================== 00:35:36 (1788755736) [ 3163.502504] Lustre: *** cfs_fail_loc=1612, val=0*** [ 3163.577922] Lustre: *** cfs_fail_loc=1612, val=0*** [ 3163.580798] Lustre: Skipped 2 previous similar messages [ 3174.906282] Lustre: DEBUG MARKER: == sanity-lfsck test 15c: LFSCK can repair unmatched MDT-object/OST-object pairs (3) ========================================================== 00:35:50 (1788755750) [ 3176.447337] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_15c MDS newer than 2.7.55, LU-6475 [ 3178.317408] Lustre: DEBUG MARKER: == sanity-lfsck test 15d: LFSCK don't crash upon dir migration failure ========================================================== 00:35:54 (1788755754) [ 3184.490159] Lustre: *** cfs_fail_loc=1709, val=0*** [ 3184.544146] LustreError: 98338:0:(mdt_reint.c:2644:mdt_reint_migrate()) lustre-MDT0000: migrate [0x240002340:0x6c:0x0]/f74 failed: rc = -5 [ 3192.706269] LustreError: 98325:0:(lod_object.c:945:lod_load_lmv_shards()) lustre-MDT0001-mdtlov: the shard [0x200003ab1:0x62:0x0]:1 for the striped directory [0x240002340:0x8c:0x0] is out of the known LMV EA range [0 - 0], failout [ 3199.833681] LustreError: 98325:0:(lod_object.c:945:lod_load_lmv_shards()) lustre-MDT0001-mdtlov: the shard [0x200003ab1:0x62:0x0]:1 for the striped directory [0x240002340:0x8c:0x0] is out of the known LMV EA range [0 - 0], failout [ 3199.861756] LustreError: 98325:0:(mdt_handler.c:1498:mdt_getattr_internal()) lustre-MDT0001: getattr error for [0x240002340:0x8c:0x0]: rc = -5 [ 3236.325090] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3236.333816] Lustre: Skipped 9 previous similar messages [ 3237.454043] Lustre: server umount lustre-MDT0000 complete [ 3245.510689] LustreError: 98309:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788755821 with bad export cookie 16017496920264527377 [ 3245.531951] LustreError: 98309:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 7 previous similar messages [ 3246.073114] Lustre: server umount lustre-MDT0001 complete [ 3262.815171] Lustre: 16396:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788755822/real 1788755822] req@ffff8be88ab98e00 x1875643487067264/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788755838 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3266.076742] Lustre: server umount lustre-OST0000 complete [ 3266.527116] Lustre: 16397:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788755826/real 1788755826] req@ffff8be88474a680 x1875643487067520/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788755842 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3268.000101] Lustre: 16396:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788755827/real 1788755827] req@ffff8be8814f0000 x1875643487067776/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788755843 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3272.736096] Lustre: 16397:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788755832/real 1788755832] req@ffff8be8814f1880 x1875643487068160/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788755848 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3274.438435] Lustre: server umount lustre-OST0001 complete [ 3292.703612] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing unload_modules_local [ 3295.998924] Key type lgssc unregistered [ 3296.463876] LNet: 105177:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 3296.472199] LNetError: 105177:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 3297.512296] LNet: Removed LNI 192.168.203.146@tcp [ 3298.596322] Key type .llcrypt unregistered [ 3298.598787] Key type ._llcrypt unregistered [ 3325.528455] Key type ._llcrypt registered [ 3325.530415] Key type .llcrypt registered [ 3325.713745] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_hostid [ 3338.176823] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing load_modules_local [ 3339.410316] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 3339.433684] alg: No test for adler32 (adler32-zlib) [ 3340.592728] Lustre: Lustre: Build Version: 2.17.58_43_g6a42d2c [ 3340.864600] LNet: Added LNI 192.168.203.146@tcp [8/256/0/180] [ 3342.591207] Key type lgssc registered [ 3343.823866] Lustre: Echo OBD driver; http://www.lustre.org/ [ 3391.129474] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing load_modules_local [ 3404.282839] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 3404.312617] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3405.547199] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 3405.600716] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 3405.686174] Lustre: lustre-MDT0000: new disk, initializing [ 3405.785097] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3405.803199] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 3409.883722] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3422.197158] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3422.319140] Lustre: 109615: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 [ 3422.358889] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 3422.364194] Lustre: Skipped 1 previous similar message [ 3422.450081] Lustre: lustre-MDT0001: new disk, initializing [ 3422.517774] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 3422.544943] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 3422.552812] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 3427.529673] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3432.520823] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 3442.392939] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3442.660799] Lustre: lustre-OST0000: new disk, initializing [ 3442.675849] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 3442.683945] Lustre: 111553:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 3442.746336] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 3445.094314] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 3445.109257] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 3445.226150] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 3449.929462] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3463.655536] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3463.784418] Lustre: lustre-OST0001: new disk, initializing [ 3463.788227] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 3463.798794] Lustre: 112576:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 3463.853529] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 3469.362815] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 3469.371774] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 3469.458699] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 3470.852318] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3482.176449] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3488.380968] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 3495.066424] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 00:41:10 (1788756070) === [ 3501.701711] Lustre: DEBUG MARKER: == sanity-lfsck test 16: LFSCK can repair inconsistent MDT-object/OST-object owner ========================================================== 00:41:17 (1788756077) [ 3502.139506] Lustre: 109623:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 251 < left 278, rollback = 2 [ 3502.179336] Lustre: 109623:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 3502.193188] Lustre: 109623:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3502.206584] Lustre: 109623:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 3502.214829] Lustre: 109623:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 3502.221554] Lustre: 109623:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3502.774890] Lustre: 109622:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 252 < left 278, rollback = 2 [ 3502.801254] Lustre: 109622:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 9 previous similar messages [ 3502.811295] Lustre: 109622:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 3502.824062] Lustre: 109622:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3502.848655] Lustre: 109622:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3502.857694] Lustre: 109622:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3502.867343] Lustre: 109622:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/1, punch: 0/0/0, quota 7/369/2 [ 3502.884762] Lustre: 109622:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3502.890877] Lustre: 109622:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/1, delete: 0/0/0 [ 3502.896594] Lustre: 109622:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3502.901462] Lustre: 109622:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3502.907368] Lustre: 109622:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3503.776729] Lustre: 109623:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 3503.790946] Lustre: 109623:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 131 previous similar messages [ 3503.814844] Lustre: 109623:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 3503.825856] Lustre: 109623:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 131 previous similar messages [ 3503.857568] Lustre: 109622:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3503.865355] Lustre: 109622:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 134 previous similar messages [ 3503.875751] Lustre: 109622:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 7/369/0 [ 3503.889296] Lustre: 109622:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 134 previous similar messages [ 3503.906236] Lustre: 109622:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 3503.914253] Lustre: 109622:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 134 previous similar messages [ 3503.924911] Lustre: 109622:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3503.931834] Lustre: 109622:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 134 previous similar messages [ 3506.027587] Lustre: *** cfs_fail_loc=1613, val=0*** [ 3517.517694] Lustre: DEBUG MARKER: == sanity-lfsck test 17: LFSCK can repair multiple references ========================================================== 00:41:33 (1788756093) [ 3518.882076] Lustre: 109622:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 3518.895349] Lustre: 109622:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 167 previous similar messages [ 3518.912653] Lustre: 109622:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 3518.924118] Lustre: 109622:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 167 previous similar messages [ 3518.929785] Lustre: 109622:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3518.936410] Lustre: 109622:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 164 previous similar messages [ 3518.951294] Lustre: 109622:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 3518.960569] Lustre: 109622:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 164 previous similar messages [ 3518.965163] Lustre: 109622:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 3518.973410] Lustre: 109622:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 164 previous similar messages [ 3518.983487] Lustre: 109622:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3518.993138] Lustre: 109622:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 164 previous similar messages [ 3520.089786] Lustre: *** cfs_fail_loc=1614, val=0*** [ 3520.616961] Lustre: *** cfs_fail_loc=1614, val=103*** [ 3520.629072] Lustre: Skipped 1 previous similar message [ 3525.345772] Lustre: 111544:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 259 < left 275, rollback = 2 [ 3525.356699] Lustre: 111544:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 11 previous similar messages [ 3525.364066] Lustre: 111544:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 3525.373469] Lustre: 111544:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3525.382176] Lustre: 111544:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/1, xattr_set: 3/275/0 [ 3525.400953] Lustre: 111544:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3525.407831] Lustre: 111544:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/9/0, punch: 1/4/0, quota 7/225/0 [ 3525.423459] Lustre: 111544:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3525.436548] Lustre: 111544:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 3525.456378] Lustre: 111544:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3525.464474] Lustre: 111544:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3525.472546] Lustre: 111544:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3533.342948] Lustre: DEBUG MARKER: == sanity-lfsck test 18a: Find out orphan OST-object and repair it (1) ========================================================== 00:41:48 (1788756108) [ 3533.763346] Lustre: 109622:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 253 < left 278, rollback = 2 [ 3533.780175] Lustre: 109622:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 1 previous similar message [ 3533.791814] Lustre: 109622:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 3533.805347] Lustre: 109622:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1 previous similar message [ 3533.815531] Lustre: 109622:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3533.821321] Lustre: 109622:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1 previous similar message [ 3533.832141] Lustre: 109622:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/1 [ 3533.841935] Lustre: 109622:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1 previous similar message [ 3533.852143] Lustre: 109622:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 3533.859707] Lustre: 109622:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1 previous similar message [ 3533.867669] Lustre: 109622:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3533.876781] Lustre: 109622:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1 previous similar message [ 3536.553165] Lustre: *** cfs_fail_loc=1615, val=0*** [ 3536.555147] Lustre: Skipped 1 previous similar message [ 3537.846142] Lustre: *** cfs_fail_loc=1615, val=0*** [ 3537.848256] Lustre: Skipped 1 previous similar message [ 3556.542150] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_18b skipping excluded test 18b [ 3558.365592] Lustre: DEBUG MARKER: == sanity-lfsck test 18c: Find out orphan OST-object and repair it (3) ========================================================== 00:42:14 (1788756134) [ 3558.816463] Lustre: 112862:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 3558.822162] Lustre: 112862:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 21 previous similar messages [ 3558.829758] Lustre: 112862:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 3558.840578] Lustre: 112862:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3558.853529] Lustre: 112862:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3558.861193] Lustre: 112862:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3558.869278] Lustre: 112862:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 3558.878594] Lustre: 112862:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3558.894250] Lustre: 112862:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 3558.901204] Lustre: 112862:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3558.909528] Lustre: 112862:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3558.919612] Lustre: 112862:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3561.269716] Lustre: *** cfs_fail_loc=1617, val=0*** [ 3561.371135] Lustre: *** cfs_fail_loc=1617, val=0*** [ 3564.017704] Lustre: *** cfs_fail_loc=1616, val=0*** [ 3564.028614] Lustre: Skipped 3 previous similar messages [ 3583.908349] Lustre: DEBUG MARKER: == sanity-lfsck test 18d: Find out orphan OST-object and repair it (4) ========================================================== 00:42:39 (1788756159) [ 3586.522502] Lustre: *** cfs_fail_loc=1618, val=0*** [ 3586.529710] Lustre: Skipped 5 previous similar messages [ 3622.368169] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3622.385215] 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 [ 3622.404074] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3623.395755] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3623.397457] 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 [ 3623.406060] Lustre: Skipped 1 previous similar message [ 3623.433408] Lustre: Skipped 1 previous similar message [ 3626.838895] Lustre: server umount lustre-MDT0000 complete [ 3631.689630] LustreError: 109607:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788756207 with bad export cookie 2163625679628982146 [ 3631.693920] LustreError: MGC192.168.203.146@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3631.713887] LustreError: 109607:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 3 previous similar messages [ 3632.138393] Lustre: server umount lustre-MDT0001 complete [ 3645.945509] Lustre: server umount lustre-OST0000 complete [ 3648.992108] Lustre: 106773:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788756209/real 1788756209] req@ffff8be891e38a80 x1875646523586432/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788756225 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3649.026132] 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 [ 3649.038620] Lustre: Skipped 1 previous similar message [ 3649.534223] Lustre: server umount lustre-OST0001 complete [ 3665.222354] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing load_modules_local [ 3676.185037] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3676.507439] LustreError: 118287:0:(ldlm_lib.c:1202:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3676.526895] LustreError: 118287:0:(ldlm_lib.c:1202:target_handle_connect()) Skipped 5 previous similar messages [ 3676.581335] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3681.030875] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3681.770766] LustreError: 118288:0:(ldlm_lib.c:1202:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3686.881100] LustreError: 118287:0:(ldlm_lib.c:1202:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3690.177048] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3690.459139] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 3695.474818] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3698.620841] Lustre: 119428:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3705.737430] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3712.014549] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3715.243230] LustreError: 119781:0:(ldlm_lib.c:1202:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3715.248471] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:4 to 0x280000400:33) [ 3720.681374] LustreError: 119783:0:(ldlm_lib.c:1202:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3720.860889] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3721.009926] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 3721.025405] Lustre: Skipped 1 previous similar message [ 3722.049040] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:116 to 0x280000401:161) [ 3722.054283] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:33) [ 3722.080209] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:4 to 0x2c0000401:33) [ 3727.512422] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3734.685729] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3737.751292] Lustre: 121298:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 3749.831716] Lustre: DEBUG MARKER: == sanity-lfsck test 18e: Find out orphan OST-object and repair it (5) ========================================================== 00:45:25 (1788756325) [ 3750.138481] Lustre: 118283:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 252 < left 278, rollback = 2 [ 3750.147534] Lustre: 118283:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 46 previous similar messages [ 3750.152033] Lustre: 118283:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 3750.162870] Lustre: 118283:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 3750.171968] Lustre: 118283:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3750.184945] Lustre: 118283:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 3750.191196] Lustre: 118283:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/1 [ 3750.200150] Lustre: 118283:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 3750.205702] Lustre: 118283:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 3750.214086] Lustre: 118283:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 3750.222802] Lustre: 118283:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3750.227826] Lustre: 118283:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 3751.838565] Lustre: *** cfs_fail_loc=1618, val=0*** [ 3751.840709] Lustre: Skipped 3 previous similar messages [ 3787.743991] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3787.755138] 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 [ 3787.793113] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3787.796053] Lustre: Skipped 2 previous similar messages [ 3791.545659] Lustre: server umount lustre-MDT0000 complete [ 3793.895170] LustreError: 118283:0:(ldlm_lib.c:1202:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3793.919372] LustreError: 118283:0:(ldlm_lib.c:1202:target_handle_connect()) Skipped 3 previous similar messages [ 3795.659597] LustreError: 118269:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788756371 with bad export cookie 2163625679628997392 [ 3795.666464] LustreError: MGC192.168.203.146@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3796.035369] Lustre: server umount lustre-MDT0001 complete [ 3810.640991] Lustre: server umount lustre-OST0000 complete [ 3824.643554] Lustre: server umount lustre-OST0001 complete [ 3842.260882] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing load_modules_local [ 3852.961610] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3853.476961] LustreError: 123870:0:(ldlm_lib.c:1202:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3853.606410] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3858.005331] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3867.251336] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3872.440969] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3875.538813] Lustre: 125010:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3882.451033] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3888.974458] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3892.047777] LustreError: 125364:0:(ldlm_lib.c:1202:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3892.061924] LustreError: 125364:0:(ldlm_lib.c:1202:target_handle_connect()) Skipped 2 previous similar messages [ 3892.074807] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:4 to 0x280000400:65) [ 3898.274659] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3898.349761] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:166 to 0x280000401:193) [ 3903.468664] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:65) [ 3903.481647] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:4 to 0x2c0000401:65) [ 3904.801063] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3914.543556] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3919.642660] Lustre: 126881:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 3925.782558] Lustre: 124602:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 252 < left 260, rollback = 2 [ 3925.790991] Lustre: 124602:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 21 previous similar messages [ 3925.801792] Lustre: 124602:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 3925.810416] Lustre: 124602:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3925.826121] Lustre: 124602:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 0/0/0, xattr_set: 1/260/0 [ 3925.835935] Lustre: 124602:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3925.846716] Lustre: 124602:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/9/0, punch: 0/0/0, quota 4/150/2 [ 3925.853840] Lustre: 124602:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3925.868135] Lustre: 124602:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 1/17/2, delete: 0/0/0 [ 3925.882990] Lustre: 124602:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3925.900655] Lustre: 124602:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3925.912619] Lustre: 124602:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3925.970957] Lustre: *** cfs_fail_loc=1602, val=10*** [ 3951.840572] Lustre: DEBUG MARKER: == sanity-lfsck test 18f: Skip the failed OST(s) when handle orphan OST-objects ========================================================== 00:48:47 (1788756527) [ 3955.087653] Lustre: *** cfs_fail_loc=1616, val=0*** [ 3955.089650] Lustre: Skipped 3 previous similar messages [ 3962.384575] Lustre: *** cfs_fail_loc=161c, val=0*** [ 3962.395229] Lustre: Skipped 1 previous similar message [ 3982.994526] Lustre: DEBUG MARKER: == sanity-lfsck test 18g: Find out orphan OST-object and repair it (7) ========================================================== 00:49:18 (1788756558) [ 3985.113037] Lustre: *** cfs_fail_loc=162e, val=0*** [ 3998.581917] Lustre: DEBUG MARKER: == sanity-lfsck test 18h: LFSCK can repair crashed PFL extent range ========================================================== 00:49:34 (1788756574) [ 4004.083639] Lustre: *** cfs_fail_loc=162f, val=0*** [ 4004.096921] Lustre: Skipped 9 previous similar messages [ 4021.147812] Lustre: DEBUG MARKER: == sanity-lfsck test 19a: OST-object inconsistency self detect ========================================================== 00:49:56 (1788756596) [ 4033.325985] Lustre: DEBUG MARKER: == sanity-lfsck test 19b: OST-object inconsistency self repair ========================================================== 00:50:08 (1788756608) [ 4036.320889] Lustre: *** cfs_fail_loc=1611, val=0*** [ 4036.377193] Lustre: *** cfs_fail_loc=1611, val=0*** [ 4036.379263] Lustre: Skipped 3 previous similar messages [ 4041.326736] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.203.46@tcp inode [0x2000013a1:0x1f:0x0] object 0x280000401:203 extent [0-4095], client returned csum 0 (type 4), server csum 703fb3ad (type 4) [ 4042.460708] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.203.46@tcp inode [0x2000013a1:0x20:0x0] object 0x280000401:204 extent [0-4095], client returned csum 0 (type 4), server csum 7cbb935c (type 4) [ 4050.230649] Lustre: DEBUG MARKER: == sanity-lfsck test 20a: Handle the orphan with dummy LOV EA slot properly ========================================================== 00:50:25 (1788756625) [ 4062.485255] Lustre: 131389:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 253 < left 263, rollback = 2 [ 4062.508120] Lustre: 131389:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 125 previous similar messages [ 4062.528314] Lustre: 131389:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4062.544073] Lustre: 131389:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 125 previous similar messages [ 4062.549090] Lustre: 131389:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 0/0/0, xattr_set: 2/263/0 [ 4062.553372] Lustre: 131389:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 125 previous similar messages [ 4062.557780] Lustre: 131389:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 0/0/0, punch: 0/0/0, quota 1/3/2 [ 4062.562681] Lustre: 131389:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 125 previous similar messages [ 4062.569081] Lustre: 131389:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/1, delete: 0/0/0 [ 4062.572873] Lustre: 131389:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 125 previous similar messages [ 4062.577075] Lustre: 131389:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 4062.580693] Lustre: 131389:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 125 previous similar messages [ 4078.911478] Lustre: DEBUG MARKER: == sanity-lfsck test 20b: Handle the orphan with dummy LOV EA slot properly - PFL case ========================================================== 00:50:54 (1788756654) [ 4086.334335] Lustre: DEBUG MARKER: == sanity-lfsck test 21: run all LFSCK components by default ========================================================== 00:51:01 (1788756661) [ 4101.596764] Lustre: DEBUG MARKER: == sanity-lfsck test 22a: LFSCK can repair unmatched pairs (1) ========================================================== 00:51:17 (1788756677) [ 4104.285335] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4104.296696] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4104.303239] Lustre: Skipped 1 previous similar message [ 4116.581842] Lustre: DEBUG MARKER: == sanity-lfsck test 22b: LFSCK can repair unmatched pairs (2) ========================================================== 00:51:32 (1788756692) [ 4118.465308] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4118.472944] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4130.000266] Lustre: DEBUG MARKER: == sanity-lfsck test 23a: LFSCK can repair dangling name entry (1) ========================================================== 00:51:45 (1788756705) [ 4131.668245] Lustre: *** cfs_fail_loc=1620, val=0*** [ 4145.177956] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_23b skipping excluded test 23b [ 4146.731500] Lustre: DEBUG MARKER: == sanity-lfsck test 23c: LFSCK can repair dangling name entry (3) ========================================================== 00:52:02 (1788756722) [ 4153.072516] Lustre: *** cfs_fail_loc=1621, val=127*** [ 4153.080730] Lustre: Skipped 1 previous similar message [ 4156.032603] Lustre: *** cfs_fail_loc=1602, val=10*** [ 4177.379364] Lustre: DEBUG MARKER: == sanity-lfsck test 23d: LFSCK can repair a dangling name entry to a remote object ========================================================== 00:52:33 (1788756753) [ 4179.725085] Lustre: Failing over lustre-MDT0000 [ 4179.937802] 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 [ 4179.939361] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4179.948570] Lustre: Skipped 5 previous similar messages [ 4179.949324] LustreError: 123867:0:(ldlm_lib.c:1202:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4179.949333] LustreError: 123867:0:(ldlm_lib.c:1202:target_handle_connect()) Skipped 1 previous similar message [ 4180.131404] Lustre: server umount lustre-MDT0000 complete [ 4190.153864] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4190.310790] LustreError: MGC192.168.203.146@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4190.990745] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4190.996295] Lustre: Skipped 3 previous similar messages [ 4191.083459] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4191.331575] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4196.331898] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4196.386903] Lustre: lustre-MDT0000: Recovery over after 0:05, of 2 clients 2 recovered and 0 were evicted. [ 4196.439567] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:265 to 0x280000401:289) [ 4196.441251] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:130 to 0x2c0000401:161) [ 4198.076118] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4200.060104] LustreError: 123867:0:(mdt_open.c:1324:mdt_cross_open()) lustre-MDT0000: [0x2000013a3:0x82:0x0] doesn't exist!: rc = -14 [ 4211.364774] Lustre: DEBUG MARKER: == sanity-lfsck test 24: LFSCK can repair multiple-referenced name entry ========================================================== 00:53:06 (1788756786) [ 4213.767605] Lustre: *** cfs_fail_loc=1622, val=0*** [ 4213.933274] Lustre: *** cfs_fail_loc=1622, val=0*** [ 4213.937869] Lustre: Skipped 1 previous similar message [ 4224.416313] Lustre: DEBUG MARKER: == sanity-lfsck test 25: LFSCK can repair bad file type in the name entry ========================================================== 00:53:20 (1788756800) [ 4225.898366] Lustre: *** cfs_fail_loc=1623, val=0*** [ 4235.923527] Lustre: DEBUG MARKER: == sanity-lfsck test 26a: LFSCK can add the missing local name entry back to the namespace ========================================================== 00:53:31 (1788756811) [ 4237.563813] Lustre: *** cfs_fail_loc=1624, val=0*** [ 4248.689607] Lustre: DEBUG MARKER: == sanity-lfsck test 26b: LFSCK can add the missing remote name entry back to the namespace ========================================================== 00:53:44 (1788756824) [ 4263.671725] Lustre: DEBUG MARKER: == sanity-lfsck test 27a: LFSCK can recreate the lost local parent directory as orphan ========================================================== 00:53:59 (1788756839) [ 4265.670128] Lustre: *** cfs_fail_loc=1624, val=0*** [ 4265.678725] Lustre: Skipped 1 previous similar message [ 4279.331551] Lustre: DEBUG MARKER: == sanity-lfsck test 27b: LFSCK can recreate the lost remote parent directory as orphan ========================================================== 00:54:14 (1788756854) [ 4293.651546] Lustre: DEBUG MARKER: == sanity-lfsck test 28: Skip the failed MDT(s) when handle orphan MDT-objects ========================================================== 00:54:29 (1788756869) [ 4300.185485] Lustre: *** cfs_fail_loc=161c, val=0*** [ 4300.191554] Lustre: Skipped 1 previous similar message [ 4316.778707] Lustre: DEBUG MARKER: == sanity-lfsck test 29b: LFSCK can repair bad nlink count (2) ========================================================== 00:54:52 (1788756892) [ 4319.270095] Lustre: *** cfs_fail_loc=1626, val=0*** [ 4319.272900] Lustre: Skipped 4 previous similar messages [ 4319.285898] Lustre: 125866:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 279, rollback = 2 [ 4319.301484] Lustre: 125866:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 507 previous similar messages [ 4319.319181] Lustre: 125866:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 4319.331759] Lustre: 125866:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 507 previous similar messages [ 4319.339100] Lustre: 125866:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 2/2/0, xattr_set: 4/279/0 [ 4319.349777] Lustre: 125866:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 507 previous similar messages [ 4319.355864] Lustre: 125866:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 4319.364707] Lustre: 125866:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 507 previous similar messages [ 4319.370946] Lustre: 125866:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 1/16/0, delete: 0/0/0 [ 4319.389831] Lustre: 125866:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 507 previous similar messages [ 4319.405836] Lustre: 125866:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 1/1/0, ref_del: 0/0/0 [ 4319.418929] Lustre: 125866:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 507 previous similar messages [ 4330.812956] Lustre: DEBUG MARKER: == sanity-lfsck test 29c: verify linkEA size limitation == 00:55:06 (1788756906) [ 4358.600945] Lustre: DEBUG MARKER: == sanity-lfsck test 29d: accessing non-existing inode shouldn't turn fs read-only (ldiskfs) ========================================================== 00:55:34 (1788756934) [ 4362.186528] LustreError: 137626:0:(osd_handler.c:284:osd_idc_find_or_init()) lustre-MDT0000: cannot lookup FID [0x2000013a3:0x9e:0x0]: rc = -2 [ 4369.278725] Lustre: DEBUG MARKER: == sanity-lfsck test 30: LFSCK can recover the orphans from backend /lost+found ========================================================== 00:55:44 (1788756944) [ 4392.747423] Lustre: Failing over lustre-MDT0000 [ 4393.364854] Lustre: server umount lustre-MDT0000 complete [ 4396.001207] 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 [ 4396.002590] LustreError: 123866:0:(ldlm_lib.c:1202:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4396.015187] Lustre: Skipped 3 previous similar messages [ 4396.039912] LustreError: 123866:0:(ldlm_lib.c:1202:target_handle_connect()) Skipped 17 previous similar messages [ 4405.217712] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 4405.313815] LustreError: MGC192.168.203.146@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4405.610932] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4405.670114] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4410.852968] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4410.870910] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4410.880819] Lustre: Skipped 3 previous similar messages [ 4410.913286] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4410.923599] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4410.972792] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:294 to 0x280000401:321) [ 4410.973383] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:167 to 0x2c0000401:193) [ 4425.267464] Lustre: DEBUG MARKER: == sanity-lfsck test 31a: The LFSCK can find/repair the name entry with bad name hash (1) ========================================================== 00:56:40 (1788757000) [ 4440.201472] Lustre: DEBUG MARKER: == sanity-lfsck test 31b: The LFSCK can find/repair the name entry with bad name hash (2) ========================================================== 00:56:55 (1788757015) [ 4457.884653] Lustre: DEBUG MARKER: == sanity-lfsck test 31c: Re-generate the lost master LMV EA for striped directory ========================================================== 00:57:13 (1788757033) [ 4459.411957] Lustre: *** cfs_fail_loc=1629, val=0*** [ 4459.417183] Lustre: Skipped 7 previous similar messages [ 4480.358867] Lustre: DEBUG MARKER: == sanity-lfsck test 31d: Set broken striped directory (modified after broken) as read-only ========================================================== 00:57:35 (1788757055) [ 4491.107788] Lustre: Failing over lustre-MDT0000 [ 4491.962293] Lustre: server umount lustre-MDT0000 complete [ 4492.768943] 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 [ 4492.775084] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4492.790144] Lustre: Skipped 1 previous similar message [ 4501.665939] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4501.900787] LustreError: MGC192.168.203.146@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4502.186550] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4507.287655] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4507.628300] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4507.651380] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4507.672321] Lustre: Skipped 3 previous similar messages [ 4507.736475] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4507.800928] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:167 to 0x2c0000401:225) [ 4507.801643] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:294 to 0x280000401:353) [ 4518.845959] Lustre: Failing over lustre-MDT0000 [ 4519.299683] Lustre: server umount lustre-MDT0000 complete [ 4527.679706] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4527.847719] LustreError: MGC192.168.203.146@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4528.140432] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4530.784952] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4532.374304] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4533.229511] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4533.237992] Lustre: Skipped 3 previous similar messages [ 4533.266870] Lustre: lustre-MDT0000: Recovery over after 0:03, of 2 clients 2 recovered and 0 were evicted. [ 4533.327795] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:355 to 0x280000401:385) [ 4533.328187] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:167 to 0x2c0000401:257) [ 4541.429779] Lustre: DEBUG MARKER: == sanity-lfsck test 31e: Re-generate the lost slave LMV EA for striped directory (1) ========================================================== 00:58:37 (1788757117) [ 4554.964365] Lustre: DEBUG MARKER: == sanity-lfsck test 31f: Re-generate the lost slave LMV EA for striped directory (2) ========================================================== 00:58:50 (1788757130) [ 4568.808611] Lustre: DEBUG MARKER: == sanity-lfsck test 31g: Repair the corrupted slave LMV EA ========================================================== 00:59:04 (1788757144) [ 4608.355548] Lustre: DEBUG MARKER: == sanity-lfsck test 31h: Repair the corrupted shard's name entry ========================================================== 00:59:43 (1788757183) [ 4610.044490] Lustre: *** cfs_fail_loc=162c, val=0*** [ 4610.046665] Lustre: Skipped 13 previous similar messages [ 4626.195364] Lustre: DEBUG MARKER: == sanity-lfsck test 32a: stop LFSCK when some OST failed ========================================================== 01:00:01 (1788757201) [ 4640.411520] LustreError: 148300:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d sleeping for 3000ms [ 4643.434253] Lustre: Failing over lustre-OST0000 [ 4643.495086] LustreError: 148300:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d awake [ 4643.505253] LustreError: 148300:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d sleeping for 3000ms [ 4643.574397] Lustre: server umount lustre-OST0000 complete [ 4644.833966] LustreError: lustre-OST0000-osc-MDT0001: operation ost_statfs to node 0@lo failed: rc = -107 [ 4644.852689] 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 [ 4644.878773] Lustre: Skipped 7 previous similar messages [ 4646.594299] LustreError: 148300:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d awake [ 4646.616362] LustreError: 148300:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d sleeping for 3000ms [ 4647.399743] LustreError: 148300:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout interrupted [ 4656.110930] LustreError: 128230:0:(ldlm_lib.c:1202: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. [ 4656.145593] LustreError: 128230:0:(ldlm_lib.c:1202:target_handle_connect()) Skipped 23 previous similar messages [ 4661.210990] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 4661.480842] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 4663.148238] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4663.188238] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 4663.188561] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 4663.223490] Lustre: Skipped 3 previous similar messages [ 4667.773834] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4676.774943] Lustre: DEBUG MARKER: == sanity-lfsck test 32b: stop LFSCK when some MDT failed ========================================================== 01:00:52 (1788757252) [ 4691.169768] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing load_modules_local [ 4709.873747] Lustre: 151115:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 4735.604480] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4739.312828] Lustre: 152249:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 4752.810332] LustreError: 152385:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d sleeping for 3000ms [ 4752.816826] LustreError: 152385:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) Skipped 1 previous similar message [ 4755.864233] LustreError: 152384:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d awake [ 4756.034280] Lustre: Failing over lustre-MDT0001 [ 4758.505742] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 4758.527873] 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 [ 4758.548305] Lustre: Skipped 1 previous similar message [ 4758.552547] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 4758.561745] Lustre: Skipped 4 previous similar messages [ 4758.919321] LustreError: 152384:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d awake [ 4758.938481] LustreError: 152384:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) Skipped 1 previous similar message [ 4759.373475] Lustre: server umount lustre-MDT0001 complete [ 4776.981641] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 4777.282703] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 4777.285993] Lustre: Skipped 3 previous similar messages [ 4777.314179] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 4782.568941] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4782.573235] Lustre: lustre-MDT0001-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 4782.595465] Lustre: Skipped 1 previous similar message [ 4782.635275] Lustre: lustre-MDT0001: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4782.695317] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:71 to 0x280000400:97) [ 4782.701705] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:68 to 0x2c0000400:97) [ 4783.095340] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4792.893793] Lustre: DEBUG MARKER: == sanity-lfsck test 33: check LFSCK paramters =========== 01:02:48 (1788757368) [ 4807.148605] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing load_modules_local [ 4825.455882] Lustre: 155105:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 4853.575619] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4858.122834] Lustre: 156241:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 4861.005549] Lustre: 125866:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 4861.016240] Lustre: 125866:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 1209 previous similar messages [ 4861.021873] Lustre: 125866:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 4861.034940] Lustre: 125866:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1209 previous similar messages [ 4861.051408] Lustre: 125866:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4861.058162] Lustre: 125866:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1209 previous similar messages [ 4861.065281] Lustre: 125866:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 4861.071663] Lustre: 125866:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1209 previous similar messages [ 4861.078053] Lustre: 125866:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 4861.083595] Lustre: 125866:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1209 previous similar messages [ 4861.088231] Lustre: 125866:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4861.093606] Lustre: 125866:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1209 previous similar messages [ 4881.989541] Lustre: DEBUG MARKER: == sanity-lfsck test 34: LFSCK can rebuild the lost agent object ========================================================== 01:04:17 (1788757457) [ 4883.677434] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_34 Only valid for ZFS backend [ 4885.527342] Lustre: DEBUG MARKER: == sanity-lfsck test 35: LFSCK can rebuild the lost agent entry ========================================================== 01:04:21 (1788757461) [ 4893.448682] Lustre: *** cfs_fail_loc=1631, val=0*** [ 4905.445341] 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 [ 4905.447483] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4905.459347] Lustre: Skipped 4 previous similar messages [ 4905.460433] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4905.477537] Lustre: Skipped 6 previous similar messages [ 4910.562201] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4910.570279] Lustre: Skipped 3 previous similar messages [ 4911.821106] Lustre: server umount lustre-MDT0000 complete [ 4915.749305] LustreError: 156265:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788757491 with bad export cookie 2163625679629070157 [ 4915.752808] LustreError: MGC192.168.203.146@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4915.756631] LustreError: 156265:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 7 previous similar messages [ 4916.059495] Lustre: server umount lustre-MDT0001 complete [ 4930.137227] Lustre: server umount lustre-OST0000 complete [ 4943.758157] Lustre: server umount lustre-OST0001 complete [ 4959.762379] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing load_modules_local [ 4970.728788] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4976.153725] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4985.148711] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4989.396808] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4992.538390] Lustre: 160141:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 4999.465652] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5006.370147] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5011.023784] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:71 to 0x280000400:129) [ 5015.558186] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5016.822090] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:540 to 0x280000401:577) [ 5016.829366] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:412 to 0x2c0000401:449) [ 5016.913943] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:68 to 0x2c0000400:129) [ 5022.512853] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5030.226048] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5034.241737] Lustre: 162009:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 5044.140268] Lustre: DEBUG MARKER: == sanity-lfsck test 36a: rebuild LOV EA for mirrored file (1) ========================================================== 01:06:59 (1788757619) [ 5046.329856] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36a needs >= 3 OSTs [ 5048.705398] Lustre: DEBUG MARKER: == sanity-lfsck test 36b: rebuild LOV EA for mirrored file (2) ========================================================== 01:07:03 (1788757623) [ 5050.795976] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36b needs >= 3 OSTs [ 5053.038380] Lustre: DEBUG MARKER: == sanity-lfsck test 36c: rebuild LOV EA for mirrored file (3) ========================================================== 01:07:08 (1788757628) [ 5055.305641] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36c needs >= 3 OSTs [ 5057.845127] Lustre: DEBUG MARKER: == sanity-lfsck test 37: LFSCK must skip a ORPHAN ======== 01:07:12 (1788757632) [ 5071.060503] Lustre: DEBUG MARKER: == sanity-lfsck test 38: LFSCK does not break foreign file and reverse is also true ========================================================== 01:07:26 (1788757646) [ 5087.568879] Lustre: DEBUG MARKER: == sanity-lfsck test 39: LFSCK does not break foreign dir and reverse is also true ========================================================== 01:07:42 (1788757662) [ 5105.879789] Lustre: DEBUG MARKER: == sanity-lfsck test 40a: LFSCK correctly fixes lmm_oi in composite layout ========================================================== 01:08:01 (1788757681) [ 5122.757408] Lustre: DEBUG MARKER: == sanity-lfsck test 41: SEL support in LFSCK ============ 01:08:18 (1788757698) [ 5144.613756] Lustre: DEBUG MARKER: == sanity-lfsck test 42: LFSCK repairs inconsistent MDT-object/OST-object encryption flags ========================================================== 01:08:40 (1788757720) [ 5178.781760] Lustre: *** cfs_fail_loc=1632, val=0*** [ 5195.572571] Lustre: DEBUG MARKER: == sanity-lfsck test 43: LFSCK does not loop endlessly on iget failure in scanning-phase1 ========================================================== 01:09:30 (1788757770) [ 5198.236773] Lustre: Failing over lustre-MDT0001 [ 5198.461974] Lustre: server umount lustre-MDT0001 complete [ 5200.863995] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 5200.870224] 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 [ 5200.886669] Lustre: Skipped 1 previous similar message [ 5200.895305] LustreError: 160070:0:(ldlm_lib.c:1202:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 5200.918325] LustreError: 160070:0:(ldlm_lib.c:1202:target_handle_connect()) Skipped 20 previous similar messages [ 5206.259256] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5206.548785] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 5206.549154] Lustre: lustre-MDT0001: Aborting client recovery [ 5206.555223] LustreError: 165804:0:(ldlm_lib.c:3042:target_stop_recovery_thread()) lustre-MDT0001: Aborting recovery [ 5206.559060] Lustre: 165828:0:(ldlm_lib.c:2442:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 5206.563386] Lustre: 165828:0:(genops.c:1600:class_disconnect_stale_exports()) lustre-MDT0001: disconnect stale client 5c8bb79d-e74c-4114-8464-116c6aeac20f@ [ 5206.569202] Lustre: lustre-MDT0001: disconnecting 2 stale clients [ 5206.576237] Lustre: lustre-MDT0001-osd: cancel update llog [0x240000400:0x1:0x0] [ 5206.588356] Lustre: lustre-MDT0000-osp-MDT0001: cancel update llog [0x200000401:0x1:0x0] [ 5206.634787] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:68 to 0x2c0000400:161) [ 5206.637437] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:131 to 0x280000400:161) [ 5210.823658] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5211.619783] LustreError: lustre-MDT0001-osp-MDT0000: This client was evicted by lustre-MDT0001; in progress operations using this service will fail. [ 5211.652163] Lustre: lustre-MDT0001-osp-MDT0000: Connection restored to 0@lo (at 0@lo) [ 5211.663279] Lustre: Skipped 4 previous similar messages [ 5214.329532] Lustre: *** cfs_fail_loc=1e2, val=483*** [ 5219.616795] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing wait_import_state FULL osp.lustre-MDT0001-os[pc]-MDT0000.*_server_uuid [ 5219.976104] Lustre: DEBUG MARKER: osp.lustre-MDT0001-os[pc]-MDT0000.*_server_uuid in FULL state after 0 sec [ 5227.306233] Lustre: DEBUG MARKER: == sanity-lfsck test 44: umount while lfsck is stopping == 01:10:03 (1788757803) [ 5236.748018] Lustre: *** cfs_fail_loc=1600, val=3*** [ 5239.550523] Lustre: Failing over lustre-MDT0000 [ 5241.803474] Lustre: server umount lustre-MDT0000 complete [ 5251.345363] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5251.483387] LustreError: MGC192.168.203.146@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5251.755475] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 5251.766706] Lustre: Skipped 2 previous similar messages [ 5253.220768] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 5256.587032] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5257.198150] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 5257.242738] Lustre: lustre-MDT0000: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 5257.290098] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:621 to 0x280000401:641) [ 5257.295141] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:489 to 0x2c0000401:513) [ 5266.013135] Lustre: DEBUG MARKER: == sanity-lfsck test 45: LFSCK should fix UID/GID/PROJID of OST object ========================================================== 01:10:41 (1788757841) [ 5310.739850] Lustre: Failing over lustre-OST0001 [ 5310.922530] Lustre: server umount lustre-OST0001 complete [ 5317.337835] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: (null) [ 5328.244155] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5328.444682] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 5328.449288] Lustre: Skipped 6 previous similar messages [ 5328.461982] Lustre: lustre-OST0001: in recovery but waiting for the first client to connect [ 5329.661477] Lustre: lustre-OST0001: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 5329.794506] Lustre: lustre-OST0001: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [ 5329.799336] Lustre: lustre-OST0001-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 5329.809516] Lustre: Skipped 3 previous similar messages [ 5334.705571] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5341.799897] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing wait_import_state (FULL|IDLE) os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid 50 [ 5342.044232] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid in FULL state after 0 sec [ 5346.328743] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing wait_import_state (FULL|IDLE) os[cp].lustre-OST0000-osc-MDT0001.ost_server_uuid 50 [ 5346.496484] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0001.ost_server_uuid in FULL state after 0 sec [ 5351.878629] Lustre: DEBUG MARKER: oleg346-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0000-osc-ffff8d36d0b59000.ost_server_uuid 50 [ 5353.676512] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff8d36d0b59000.ost_server_uuid in FULL state after 0 sec [ 5435.873276] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5435.888546] Lustre: Skipped 3 previous similar messages [ 5440.930149] Lustre: server umount lustre-MDT0000 complete [ 5450.863781] LustreError: 162720:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788758026 with bad export cookie 2163625679629152974 [ 5450.871819] LustreError: MGC192.168.203.146@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5450.877732] LustreError: 162720:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 5451.305712] Lustre: server umount lustre-MDT0001 complete [ 5462.370816] Lustre: server umount lustre-OST0000 complete [ 5470.602230] Lustre: server umount lustre-OST0001 complete [ 5486.247774] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing unload_modules_local [ 5488.590339] Key type lgssc unregistered [ 5488.898193] LNet: 175492:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 5488.913461] LNetError: 175492:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 5488.945385] LNet: Removed LNI 192.168.203.146@tcp [ 5489.710352] Key type .llcrypt unregistered [ 5489.712375] Key type ._llcrypt unregistered [ 5512.901582] Key type ._llcrypt registered [ 5512.904305] Key type .llcrypt registered [ 5513.031537] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_hostid [ 5529.114181] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing load_modules_local [ 5530.011836] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 5530.276700] alg: No test for adler32 (adler32-zlib) [ 5531.422848] Lustre: Lustre: Build Version: 2.17.58_43_g6a42d2c [ 5531.690871] LNet: Added LNI 192.168.203.146@tcp [8/256/0/180] [ 5533.375204] Key type lgssc registered [ 5534.368239] Lustre: Echo OBD driver; http://www.lustre.org/ [ 5580.094750] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing load_modules_local [ 5592.823613] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 5592.856942] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5594.045785] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 5594.069656] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 5594.161925] Lustre: lustre-MDT0000: new disk, initializing [ 5594.211280] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 5594.227417] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 5599.174955] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5615.315680] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5615.391621] Lustre: 179944: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 [ 5615.413740] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 5615.416526] Lustre: Skipped 1 previous similar message [ 5615.478471] Lustre: lustre-MDT0001: new disk, initializing [ 5615.538298] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 5615.557684] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 5615.563564] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 5622.154621] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5627.445823] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 5635.989367] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5636.190308] Lustre: lustre-OST0000: new disk, initializing [ 5636.193519] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 5636.199453] Lustre: 181882:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 5636.261803] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 5640.047139] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 5640.081343] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 5640.193805] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 5641.544839] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5653.797864] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5653.908547] Lustre: lustre-OST0001: new disk, initializing [ 5653.911763] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 5653.918427] Lustre: 182907:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 5653.995924] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 5659.249144] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5662.788717] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 5662.807019] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 5662.863271] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 5669.682674] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5676.498318] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 5681.293233] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 01:17:37 (1788758257) === [ 5682.659269] Lustre: DEBUG MARKER: == sanity-lfsck test complete, duration 5373 sec ========= 01:17:38 (1788758258) [ 5684.025637] Lustre: DEBUG MARKER: === sanity-lfsck: start cleanup 01:17:40 (1788758260) === [ 5686.826846] Lustre: DEBUG MARKER: === sanity-lfsck: finish cleanup 01:17:42 (1788758262) === [ 5692.393727] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 5692.402533] 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 [ 5692.421548] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5693.415108] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5693.417914] 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 [ 5693.436672] Lustre: Skipped 2 previous similar messages [ 5696.593154] Lustre: server umount lustre-MDT0000 complete [ 5703.655635] LustreError: 181258:0:(ldlm_lib.c:1202:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 5703.684733] LustreError: 181258:0:(ldlm_lib.c:1202:target_handle_connect()) Skipped 8 previous similar messages [ 5703.862835] LustreError: 179937:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788758279 with bad export cookie 14416122288447692636 [ 5703.872232] LustreError: MGC192.168.203.146@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5703.879854] LustreError: 179937:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 5704.119398] Lustre: server umount lustre-MDT0001 complete [ 5721.931293] Lustre: server umount lustre-OST0000 complete [ 5724.127159] Lustre: 177103:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788758284/real 1788758284] req@ffff8be89390c000 x1875648820885376/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788758300 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5724.153701] 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 [ 5729.311245] Lustre: 177103:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788758289/real 1788758289] req@ffff8be88a124700 x1875648820885760/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788758305 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5729.651921] Lustre: server umount lustre-OST0001 complete [ 5746.138904] Lustre: DEBUG MARKER: oleg346-server.virtnet: executing unload_modules_local [ 5749.875397] Key type lgssc unregistered [ 5750.339637] LNet: 186379:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 5750.359208] LNetError: 186379:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 5750.378721] LNet: Removed LNI 192.168.203.146@tcp [ 5751.648529] Key type .llcrypt unregistered [ 5751.653982] Key type ._llcrypt unregistered