[ 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 476377458 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2399.998 MHz processor [ 0.000000] last_pfn = 0x146e00 max_arch_pfn = 0x400000000 [ 0.000000] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT [ 0.000000] last_pfn = 0xbffce max_arch_pfn = 0x400000000 [ 0.000000] found SMP MP-table at [mem 0x000f54b0-0x000f54bf] [ 0.000000] RAMDISK: [mem 0xbcc54000-0xbffbffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F52D0 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE247C 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE2318 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 0022D8 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE238C 000090 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE241C 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE2454 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe2318-0xbffe238b] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe2317] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe238c-0xbffe241b] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe241c-0xbffe2453] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe2454-0xbffe247b] [ 0.000000] No NUMA configuration found [ 0.000000] Faking a node at [mem 0x0000000000000000-0x0000000146dfffff] [ 0.000000] NODE_DATA(0) allocated [mem 0x1465a3000-0x1465cdfff] [ 0.000000] Reserving 256MB of memory at 2752MB for crashkernel (System RAM: 4205MB) [ 0.000000] Zone ranges: [ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.000000] DMA32 [mem 0x0000000001000000-0x00000000ffffffff] [ 0.000000] Normal [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Device empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff] [ 0.000000] node 0: [mem 0x0000000000100000-0x00000000bffcdfff] [ 0.000000] node 0: [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Zeroed struct page in unavailable ranges: 4756 pages [ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x0000000146dfffff] [ 0.000000] ACPI: PM-Timer IO Port: 0x608 [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) [ 0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) [ 0.000000] Using ACPI (MADT) for SMP configuration information [ 0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000] TSC deadline timer available [ 0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs [ 0.000000] kvm-guest: KVM setup pv remote TLB flush [ 0.000000] kvm-guest: setup PV sched yield [ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff] [ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff] [ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff] [ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff] [ 0.000000] PM: Registered nosave memory: [mem 0xbffce000-0xbfffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xc0000000-0xfeffbfff] [ 0.000000] PM: Registered nosave memory: [mem 0xfeffc000-0xfeffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xff000000-0xfffbffff] [ 0.000000] PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff] [ 0.000000] [mem 0xc0000000-0xfeffbfff] available for PCI devices [ 0.000000] Booting paravirtualized kernel on KVM [ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns [ 0.000000] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1 [ 0.000000] percpu: Embedded 63 pages/cpu s221184 r8192 d28672 u524288 [ 0.000000] kvm-guest: PV spinlocks enabled [ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1059606 [ 0.000000] Policy zone: Normal [ 0.000000] Kernel command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] Specific versions of hardware are certified with Red Hat Enterprise Linux 8. Please see the list of hardware certified with Red Hat Enterprise Linux 8 at https://catalog.redhat.com. [ 0.000000] audit: disabled (until reboot) [ 0.000000] software IO TLB: area num 4. [ 0.000000] Memory: 2829652K/4306352K available (18435K kernel code, 11221K rwdata, 7248K rodata, 2908K init, 18040K bss, 524588K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] ftrace: allocating 41240 entries in 162 pages [ 0.000000] ftrace: allocated 162 pages with 3 groups [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] rcu: RCU event tracing is enabled. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ 0.000000] rcu: RCU callback double-/use-after-free debug enabled. [ 0.000000] Rude variant of Tasks RCU enabled. [ 0.000000] Tracing variant of Tasks RCU enabled. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 0.000000] NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16 [ 0.000000] random: get_random_bytes called from start_kernel+0x622/0x9a8 with crng_init=0 [ 0.001000] Console: colour *CGA 80x25 [ 0.001000] printk: console [ttyS1] enabled [ 0.001000] ACPI: Core revision 20220331 [ 0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.001012] APIC: Switch to symmetric I/O mode setup [ 0.002406] x2apic enabled [ 0.003012] Switched APIC routing to physical x2apic. [ 0.004011] kvm-guest: setup PV IPIs [ 0.007495] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.008000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.008022] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.009018] pid_max: default: 32768 minimum: 301 [ 0.011113] LSM: Security Framework initializing [ 0.012065] Yama: becoming mindful. [ 0.013041] SELinux: Initializing. [ 0.014138] *** VALIDATE selinux *** [ 0.023693] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.029443] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.030179] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.031129] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.032123] *** VALIDATE tmpfs *** [ 0.034408] *** VALIDATE proc *** [ 0.035223] *** VALIDATE cgroup *** [ 0.036053] *** VALIDATE cgroup2 *** [ 0.038165] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.039245] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.040014] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.041044] Spectre V2 : User space: Vulnerable [ 0.043004] Speculative Store Bypass: Vulnerable [ 0.047008] debug: unmapping init [mem 0xffffffff8b659000-0xffffffff8b660fff] [ 0.049970] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.050854] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.051025] ... version: 2 [ 0.052013] ... bit width: 48 [ 0.053013] ... generic registers: 4 [ 0.054013] ... value mask: 0000ffffffffffff [ 0.055019] ... max period: 00007fffffffffff [ 0.056023] ... fixed-purpose events: 3 [ 0.057013] ... event mask: 000000070000000f [ 0.058346] rcu: Hierarchical SRCU implementation. [ 0.061275] smp: Bringing up secondary CPUs ... [ 0.062701] x86: Booting SMP configuration: [ 0.063052] .... node #0, CPUs: #1 #2 #3 [ 0.067130] smp: Brought up 1 node, 4 CPUs [ 0.069075] smpboot: Max logical packages: 1 [ 0.070015] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.148290] node 0 deferred pages initialised in 76ms [ 0.151087] devtmpfs: initialized [ 0.153055] x86/mm: Memory block size: 128MB [ 0.155396] gcov: version magic: 0x41383552 [ 0.157271] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.159075] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.160265] pinctrl core: initialized pinctrl subsystem [ 0.161164] [ 0.161711] ************************************************************* [ 0.162026] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.163018] ** ** [ 0.164014] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.165019] ** ** [ 0.166018] ** This means that this kernel is built to expose internal ** [ 0.167015] ** IOMMU data structures, which may compromise security on ** [ 0.168020] ** your system. ** [ 0.169030] ** ** [ 0.170015] ** If you see this message and you are not debugging the ** [ 0.171024] ** kernel, report this immediately to your vendor! ** [ 0.172017] ** ** [ 0.173018] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.174016] ************************************************************* [ 0.175737] NET: Registered protocol family 16 [ 0.176441] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.177065] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.178083] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.180052] cpuidle: using governor menu [ 0.182778] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.185545] PCI: Using configuration type 1 for base access [ 0.188136] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.198140] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.199044] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.201077] cryptd: max_cpu_qlen set to 1000 [ 0.204112] ACPI: Added _OSI(Module Device) [ 0.205012] ACPI: Added _OSI(Processor Device) [ 0.206014] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.207013] ACPI: Added _OSI(Processor Aggregator Device) [ 0.211194] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.213605] ACPI: Interpreter enabled [ 0.214071] ACPI: PM: (supports S0 S3 S4 S5) [ 0.215017] ACPI: Using IOAPIC for interrupt routing [ 0.216129] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.217431] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.226560] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.227049] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.228020] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.229082] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.231438] acpiphp: Slot [2] registered [ 0.232139] acpiphp: Slot [5] registered [ 0.233117] acpiphp: Slot [6] registered [ 0.234157] acpiphp: Slot [7] registered [ 0.235146] acpiphp: Slot [8] registered [ 0.236117] acpiphp: Slot [9] registered [ 0.237085] acpiphp: Slot [10] registered [ 0.238108] acpiphp: Slot [3] registered [ 0.239086] acpiphp: Slot [4] registered [ 0.240064] acpiphp: Slot [11] registered [ 0.241125] acpiphp: Slot [12] registered [ 0.242072] acpiphp: Slot [13] registered [ 0.243095] acpiphp: Slot [14] registered [ 0.244111] acpiphp: Slot [15] registered [ 0.245101] acpiphp: Slot [16] registered [ 0.246066] acpiphp: Slot [17] registered [ 0.246968] acpiphp: Slot [18] registered [ 0.247099] acpiphp: Slot [19] registered [ 0.247917] acpiphp: Slot [20] registered [ 0.248056] acpiphp: Slot [21] registered [ 0.248845] acpiphp: Slot [22] registered [ 0.249059] acpiphp: Slot [23] registered [ 0.249947] acpiphp: Slot [24] registered [ 0.251059] acpiphp: Slot [25] registered [ 0.252057] acpiphp: Slot [26] registered [ 0.252884] acpiphp: Slot [27] registered [ 0.253075] acpiphp: Slot [28] registered [ 0.254063] acpiphp: Slot [29] registered [ 0.255087] acpiphp: Slot [30] registered [ 0.256086] acpiphp: Slot [31] registered [ 0.257071] PCI host bridge to bus 0000:00 [ 0.258018] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.259021] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.260022] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.261026] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.262029] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.263029] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.264193] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.265938] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.267368] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.273014] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.276074] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.277020] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.278017] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.279020] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.280672] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.284885] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.287050] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.291943] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.296020] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.310026] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.316016] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.322252] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.337017] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.351016] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.376015] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.385627] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.396018] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.402016] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.423017] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.431421] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.441018] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.453020] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.468018] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.476740] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.482019] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.489020] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.506028] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.515594] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.524018] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.533023] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.548016] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 0.555679] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.562021] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.570018] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.587015] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 0.602000] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.605441] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.608409] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.610397] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.613250] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.619247] iommu: Default domain type: Passthrough [ 0.621505] SCSI subsystem initialized [ 0.623130] ACPI: bus type USB registered [ 0.624079] usbcore: registered new interface driver usbfs [ 0.625105] usbcore: registered new interface driver hub [ 0.627082] usbcore: registered new device driver usb [ 0.629180] pps_core: LinuxPPS API ver. 1 registered [ 0.631011] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.633060] PTP clock support registered [ 0.635132] EDAC MC: Ver: 3.0.0 [ 0.637263] PCI: Using ACPI for IRQ routing [ 0.638722] NetLabel: Initializing [ 0.638967] NetLabel: domain hash size = 128 [ 0.639000] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.642075] NetLabel: unlabeled traffic allowed by default [ 0.643093] vgaarb: loaded [ 0.644277] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.646016] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.652292] clocksource: Switched to clocksource kvm-clock [ 0.756331] VFS: Disk quotas dquot_6.6.0 [ 0.758059] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.760577] *** VALIDATE ramfs *** [ 0.761811] *** VALIDATE hugetlbfs *** [ 0.762917] pnp: PnP ACPI init [ 0.764960] pnp: PnP ACPI: found 6 devices [ 0.782992] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.786415] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.788888] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.791165] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.793500] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.796021] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.798942] NET: Registered protocol family 2 [ 0.801447] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.806407] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.810144] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.815740] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.819240] TCP: Hash tables configured (established 65536 bind 65536) [ 0.821846] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.826751] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.829984] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.832806] NET: Registered protocol family 1 [ 0.835705] RPC: Registered named UNIX socket transport module. [ 0.839906] RPC: Registered udp transport module. [ 0.841719] RPC: Registered tcp transport module. [ 0.842979] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.845092] NET: Registered protocol family 44 [ 0.846596] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.848572] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.850351] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.852163] PCI: CLS 0 bytes, default 64 [ 0.853861] Unpacking initramfs... [ 2.301682] debug: unmapping init [mem 0xffff8e8d7cc54000-0xffff8e8d7ffbffff] [ 2.305603] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.307714] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.310653] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 2.822972] Initialise system trusted keyrings [ 2.824659] Key type blacklist registered [ 2.826642] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.841258] zbud: loaded [ 2.845039] *** VALIDATE nfs *** [ 2.846802] *** VALIDATE nfs4 *** [ 2.848869] pstore: using deflate compression [ 2.853377] Platform Keyring initialized [ 2.955251] NET: Registered protocol family 38 [ 2.957095] Key type asymmetric registered [ 2.958468] Asymmetric key parser 'x509' registered [ 2.960077] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 2.962839] io scheduler mq-deadline registered [ 2.964485] io scheduler kyber registered [ 2.966209] io scheduler bfq registered [ 2.967977] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 2.970985] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 2.974026] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 2.976787] ACPI: Power Button [PWRF] [ 2.984779] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 2.991752] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 3.003619] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 3.008900] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 3.022135] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 3.049606] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.079608] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.084701] Non-volatile memory driver v1.3 [ 3.086072] Linux agpgart interface v0.103 [ 3.122625] virtio_blk virtio1: [vda] 149768 512-byte logical blocks (76.7 MB/73.1 MiB) [ 3.125021] vda: detected capacity change from 0 to 76681216 [ 3.140941] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.143364] vdb: detected capacity change from 0 to 1073741824 [ 3.156977] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.159304] vdc: detected capacity change from 0 to 2621440000 [ 3.176771] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.180410] vdd: detected capacity change from 0 to 2621440000 [ 3.200467] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.203543] vde: detected capacity change from 0 to 4294967296 [ 3.221989] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.224546] vdf: detected capacity change from 0 to 4294967296 [ 3.235176] libphy: Fixed MDIO Bus: probed [ 3.242838] usbcore: registered new interface driver usbserial_generic [ 3.245286] usbserial: USB Serial support registered for generic [ 3.247410] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.250666] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.252060] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.255155] mousedev: PS/2 mouse device common for all mice [ 3.259062] rtc_cmos 00:05: RTC can wake from S4 [ 3.261822] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.263362] rtc_cmos 00:05: registered as rtc0 [ 3.268215] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.270781] intel_pstate: CPU model not supported [ 3.273227] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.275628] hid: raw HID events driver (C) Jiri Kosina [ 3.279552] usbcore: registered new interface driver usbhid [ 3.281208] usbhid: USB HID core driver [ 3.282703] drop_monitor: Initializing network drop monitor service [ 3.282757] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.284465] Initializing XFRM netlink socket [ 3.289492] NET: Registered protocol family 10 [ 3.292489] Segment Routing with IPv6 [ 3.293537] NET: Registered protocol family 17 [ 3.295253] mpls_gso: MPLS GSO support [ 3.300305] RAS: Correctable Errors collector initialized. [ 3.302510] AVX version of gcm_enc/dec engaged. [ 3.304168] AES CTR mode by8 optimization enabled [ 3.381200] sched_clock: Marking stable (3381159255, 0)->(4370512972, -989353717) [ 3.385175] registered taskstats version 1 [ 3.388018] Loading compiled-in X.509 certificates [ 3.389857] zswap: loaded using pool lzo/zbud [ 3.416994] Key type big_key registered [ 3.431305] Key type encrypted registered [ 3.432806] ima: No TPM chip found, activating TPM-bypass! [ 3.434670] ima: Allocated hash algorithm: sha1 [ 3.436558] ima: No architecture policies found [ 3.438390] evm: Initialising EVM extended attributes: [ 3.439741] evm: security.selinux [ 3.440698] evm: security.ima [ 3.441733] evm: security.capability [ 3.442826] evm: HMAC attrs: 0x1 [ 3.444852] rtc_cmos 00:05: setting system clock to 2026-09-05 16:04:24 UTC (1788624264) [ 3.451176] debug: unmapping init [mem 0xffffffff8c603000-0xffffffff8c7fffff] [ 3.454108] debug: unmapping init [mem 0xffffffff8b382000-0xffffffff8b658fff] [ 3.462276] Write protecting the kernel read-only data: 28672k [ 3.465566] debug: unmapping init [mem 0xffffffff89a03000-0xffffffff89bfffff] [ 3.469050] debug: unmapping init [mem 0xffffffff8a314000-0xffffffff8a3fffff] [ 3.509458] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 3.519034] systemd[1]: Detected virtualization kvm. [ 3.521180] systemd[1]: Detected architecture x86-64. [ 3.523308] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.551406] systemd[1]: No hostname configured. [ 3.553316] systemd[1]: Set hostname to . [ 3.555453] random: systemd: uninitialized urandom read (16 bytes read) [ 3.557789] systemd[1]: Initializing machine ID from random generator. [ 3.702631] random: systemd: uninitialized urandom read (16 bytes read) [ 3.704600] systemd[1]: Listening on udev Kernel Socket. [ OK ] Listening on udev Kernel Socket. [ 3.707640] random: systemd: uninitialized urandom read (16 bytes read) [ 3.709388] systemd[1]: Reached target Slices. [ OK ] Reached target Slices. [ 3.712152] systemd[1]: Listening on udev Control Socket. [ OK ] Listening on udev Control Socket. [ OK ] Reached target Local File Systems. [ OK ] Reached target Initrd Root Device. [ OK ] Listening on Journal Socket. Starting Setup Virtual Console... Starting Create Volatile Files and Directories... Starting Create list of required st…ce nodes for the current kernel... [ OK ] Started Memstrack Anylazing Service. [ OK ] Reached target Swap. [ OK ] Reached target Timers. Starting Apply Kernel Variables... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. [ OK ] Listening on Journal Socket (/dev/log). Starting Journal Service... [ OK ] Reached target Sockets. [ OK ] Started Setup Virtual Console. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Apply Kernel Variables. Starting Create Static Device Nodes in /dev... Starting dracut cmdline hook... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started Journal Service. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 4.366996] device-mapper: uevent: version 1.0.3 [ 4.368878] 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... [ 5.177910] virtio_net virtio0 ens2: renamed from eth0 [ 5.185367] random: fast init done [ 5.237275] scsi host0: ata_piix [ 5.254420] scsi host1: ata_piix [ 5.255964] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 5.258680] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 8.995109] dracut-initqueue[580]: RTNETLINK answers: File exists [ 9.947997] random: crng init done [ 9.949405] random: 7 urandom warning(s) missed due to ratelimiting Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Mounting /sysroot... [ 10.436833] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped target Timers. [ OK ] Stopped dracut pre-pivot and cleanup hook. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Paths. [ OK ] Stopped target System Initialization. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped target Swap. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped target Local File Systems. Stopping udev Kernel Device Manager... [ OK ] Stopped target Sockets. [ OK ] Stopped target Slices. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Closed udev Control Socket. [ OK ] Closed udev Kernel Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 11.672361] printk: systemd: 26 output lines suppressed due to ratelimiting [ 11.942976] SELinux: Disabled at runtime. [ 12.009122] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 12.017312] systemd[1]: Detected virtualization kvm. [ 12.019354] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 12.553340] systemd[1]: initrd-switch-root.service: Succeeded. [ 12.556991] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 12.563870] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 12.566535] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 12.568878] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 12.575307] systemd[1]: Starting Journal Service... Starting Journal Service... [ 12.578209] systemd[1]: proc-sys-fs-binfmt_misc.automount: Refusing to start, unit to trigger not loaded. [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. Mounting Kernel Debug File System... [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Reached target rpc_pipefs.target. [ OK ] Listening on Process Core Dump Socket. Starting Apply Kernel Variables... Activating swap /dev/disk/by-label/SWAP... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Created slice User and Session Slice. [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Created slice system-getty.slice. [ OK ] Reached target Slices. [ OK ] Listening on udev Kernel Socket. [ 12.680291] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS Starting udev Coldplug all Devices... [ OK ] Stopped target Initrd File Systems. Starting Remount Root and Kernel File Systems... [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Stopped target Initrd Root File System. Mounting POSIX Message Queue File System... Mounting Huge Pages File System... [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Reached target RPC Port Mapper. [ OK ] Started Journal Service. [ OK ] Mounted Kernel Debug File System. [ OK ] Started Apply Kernel Variables. [ OK ] Activated swap /dev/disk/by-label/SWAP. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Mounted Huge Pages File System. Starting Create Static Device Nodes in /dev... Starting Configure read-only root support... [ OK ] Reached target Swap. Starting Flush Journal to Persistent Storage... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. Starting udev Kernel Device Manager... [ OK ] Reached target Local File Systems (Pre). Mounting /mnt... Mounting /home/green/git/lustre-release... [ OK ] Mounted /mnt. [ OK ] Started udev Coldplug all Devices. [ 13.007493] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 13.290453] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 13.321179] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 13.436653] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 13.448899] EDAC sbridge: Ver: 1.1.2 [ 15.177492] Key type dns_resolver registered [ 15.473588] NFS: Registering the id_resolver key type [ 15.474925] Key type id_resolver registered [ 15.476493] Key type id_legacy registered [ OK ] Started Configure read-only root support. [ OK ] Reached target Local File Systems. Starting Rebuild Dynamic Linker Cache... Starting Mark the need to relabel after reboot... Starting Create Volatile Files and Directories... Starting Load/Save Random Seed... [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Load/Save Random Seed. [ 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 ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Reached target Basic System. Starting Login Service... [ OK ] Started D-Bus System Message Bus. Starting Network Manager... Starting Restore /run/initramfs on shutdown... [ OK ] Started dnf makecache --timer. [ OK ] Reached target Timers. [ OK ] Started irqbalance daemon. [ OK ] Reached target sshd-keygen.target. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Login Service. [ OK ] Started Network Manager. Starting Network Manager Wait Online... [ OK ] Reached target Network. Starting Dynamic System Tuning Daemon... Starting GSSAPI Proxy Daemon... Starting OpenSSH server daemon... Starting Hostname Service... [ OK ] Started OpenSSH server daemon. [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... [ OK ] Started Permit User Sessions. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Getty on tty1. [ 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 Crash recovery kernel arming... Starting Notify NFS peers of a restart... Starting System Logging Service... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Starting Authorization Manager... [ OK ] Started Authorization Manager. [ OK ] Started Dynamic System Tuning Daemon. [ OK ] Reached target Multi-User System. [ OK ] Reached target Graphical Interface. Starting Update UTMP about System Runlevel Changes... [ OK ] Started Update UTMP about System Runlevel Changes. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg117-server login: [ 50.186362] libcfs: loading out-of-tree module taints kernel. [ 50.231863] Key type ._llcrypt registered [ 50.234399] Key type .llcrypt registered [ 50.358952] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_hostid [ 69.625480] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing load_modules_local [ 71.717367] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 71.735247] alg: No test for adler32 (adler32-zlib) [ 73.754370] Lustre: Lustre: Build Version: 2.17.58_2_g69c2166 [ 74.875290] LNet: Added LNI 192.168.201.117@tcp [8/256/0/180] [ 76.687252] Key type lgssc registered [ 78.349937] Lustre: Echo OBD driver; http://www.lustre.org/ [ 95.187594] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 103.218383] hrtimer: interrupt took 3220209 ns [ 142.606082] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing load_modules_local [ 157.611708] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 157.653308] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 159.029301] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 159.127937] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 159.362823] Lustre: lustre-MDT0000: new disk, initializing [ 159.486594] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 159.511875] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 163.981896] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 180.362946] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 180.424508] Lustre: 6504: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 [ 180.447646] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 180.454706] Lustre: Skipped 1 previous similar message [ 180.515141] Lustre: lustre-MDT0001: new disk, initializing [ 180.558466] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 180.572778] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 180.579056] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 185.369617] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 189.970504] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 199.073497] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 199.396879] Lustre: lustre-OST0000: new disk, initializing [ 199.401828] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 199.410194] Lustre: 8442:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 199.462531] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 205.243442] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 206.401963] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 206.413992] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 206.494132] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 217.422269] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 217.525511] Lustre: lustre-OST0001: new disk, initializing [ 217.527849] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 217.530710] Lustre: 9513:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 217.564036] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 223.995088] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 227.408323] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 227.422127] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 227.474377] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 236.342135] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 244.956470] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 251.532463] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing check_logdir /tmp/testlogs/ [ 256.225281] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing yml_node [ 260.250131] Lustre: DEBUG MARKER: Client: 2.17.58.2 [ 262.876313] Lustre: DEBUG MARKER: MDS: 2.17.58.2 [ 265.598198] Lustre: DEBUG MARKER: OSS: 2.17.58.2 [ 267.372093] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity-lfsck ============----- Sat Sep 5 12:08:46 EDT 2026 [ 284.144612] Lustre: DEBUG MARKER: excepting tests: 18b 23b [ 294.152780] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing load_modules_local [ 303.585311] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 303.599533] 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 [ 303.637578] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 304.608684] 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 [ 304.611684] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 304.621534] Lustre: Skipped 1 previous similar message [ 304.642985] Lustre: Skipped 3 previous similar messages [ 308.663520] Lustre: server umount lustre-MDT0000 complete [ 314.849289] LustreError: 6510:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 314.873028] LustreError: 6510:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 8 previous similar messages [ 316.787126] LustreError: 6496:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788624577 with bad export cookie 17247675621966971714 [ 316.787835] LustreError: MGC192.168.201.117@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 316.806224] LustreError: 6496:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 317.006598] Lustre: server umount lustre-MDT0001 complete [ 336.223254] Lustre: 3636:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788624581/real 1788624581] req@ffff8e8dc5979c00 x1875508550793984/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788624597 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 336.254086] 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 [ 336.264585] Lustre: Skipped 1 previous similar message [ 336.423230] Lustre: server umount lustre-OST0000 complete [ 338.208090] Lustre: 3635:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788624583/real 1788624583] req@ffff8e8cc2946300 x1875508550794240/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788624599 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 340.453579] Lustre: 3637:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788624585/real 1788624585] req@ffff8e8dc4001180 x1875508550794496/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788624601 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 343.584885] Lustre: 3637:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788624588/real 1788624588] req@ffff8e8cc2945500 x1875508550794880/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788624604 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 345.356434] Lustre: server umount lustre-OST0001 complete [ 364.128976] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing unload_modules_local [ 367.520130] Key type lgssc unregistered [ 367.827864] LNet: 14783:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 367.835540] LNetError: 14783:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 367.850340] LNet: Removed LNI 192.168.201.117@tcp [ 369.140318] Key type .llcrypt unregistered [ 369.145090] Key type ._llcrypt unregistered [ 394.754652] Key type ._llcrypt registered [ 394.755681] Key type .llcrypt registered [ 394.797962] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_hostid [ 410.900659] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing load_modules_local [ 411.988838] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 412.085052] alg: No test for adler32 (adler32-zlib) [ 413.354732] Lustre: Lustre: Build Version: 2.17.58_2_g69c2166 [ 413.644882] LNet: Added LNI 192.168.201.117@tcp [8/256/0/180] [ 415.535857] Key type lgssc registered [ 416.311899] Lustre: Echo OBD driver; http://www.lustre.org/ [ 469.921421] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing load_modules_local [ 483.273489] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 483.290484] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 484.613995] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 484.658606] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 484.753768] Lustre: lustre-MDT0000: new disk, initializing [ 484.891826] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 484.909485] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 489.975646] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 505.414093] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 505.531987] Lustre: 19236: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 [ 505.607509] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 505.614202] Lustre: Skipped 1 previous similar message [ 505.718303] Lustre: lustre-MDT0001: new disk, initializing [ 505.861834] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 505.906774] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 505.932517] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 511.882660] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 518.107223] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 527.967503] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 528.261376] Lustre: lustre-OST0000: new disk, initializing [ 528.264577] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 528.270330] Lustre: 21176:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 528.325860] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 534.027682] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 534.037491] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 534.116877] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 534.377678] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 547.920979] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 548.147948] Lustre: lustre-OST0001: new disk, initializing [ 548.151626] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 548.159123] Lustre: 22199:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 548.227307] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 554.984559] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 558.160401] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 558.180482] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 558.226112] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 566.825651] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 572.357616] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 579.408980] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 12:13:59 (1788624839) === [ 582.094984] Lustre: DEBUG MARKER: == sanity-lfsck test 0: Control LFSCK manually =========== 12:14:01 (1788624841) [ 582.247992] Lustre: 19242:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 251 < left 278, rollback = 2 [ 582.252757] Lustre: 19242:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 582.256255] Lustre: 19242:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 582.260067] Lustre: 19242:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 582.263599] Lustre: 19242:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 582.283376] Lustre: 19242:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 582.780655] Lustre: 19243:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 582.788427] Lustre: 19243:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 20 previous similar messages [ 582.793529] Lustre: 19243:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 582.797907] Lustre: 19243:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 20 previous similar messages [ 582.804061] Lustre: 19243:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 582.807697] Lustre: 19243:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 20 previous similar messages [ 582.811128] Lustre: 19243:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 582.819461] Lustre: 19243:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 20 previous similar messages [ 582.825534] Lustre: 19243:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 582.829542] Lustre: 19243:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 20 previous similar messages [ 582.833289] Lustre: 19243:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 582.836723] Lustre: 19243:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 20 previous similar messages [ 583.801593] Lustre: 19243:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 583.808081] Lustre: 19243:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 59 previous similar messages [ 583.813137] Lustre: 19243:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 583.823178] Lustre: 19243:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 59 previous similar messages [ 583.827986] Lustre: 19243:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 583.836651] Lustre: 19243:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 59 previous similar messages [ 583.841947] Lustre: 19243:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 583.847889] Lustre: 19243:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 59 previous similar messages [ 583.854986] Lustre: 19243:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 583.860905] Lustre: 19243:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 59 previous similar messages [ 583.865989] Lustre: 19243:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 583.869263] Lustre: 19243:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 59 previous similar messages [ 585.839708] Lustre: 19242:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 585.848456] Lustre: 19242:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 113 previous similar messages [ 585.857580] Lustre: 19242:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 585.861660] Lustre: 19242:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 113 previous similar messages [ 585.867589] Lustre: 19242:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 585.871088] Lustre: 19242:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 113 previous similar messages [ 585.875398] Lustre: 19242:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 585.879710] Lustre: 19242:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 113 previous similar messages [ 585.883535] Lustre: 19242:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 585.887083] Lustre: 19242:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 113 previous similar messages [ 585.891609] Lustre: 19242:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 585.894879] Lustre: 19242:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 113 previous similar messages [ 587.950477] Lustre: *** cfs_fail_loc=1600, val=3*** [ 591.458684] Lustre: *** cfs_fail_loc=1600, val=3*** [ 592.480372] Lustre: 21167:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-OST0001: opcode 2: before 259 < left 274, rollback = 2 [ 592.487939] Lustre: 21167:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 82 previous similar messages [ 592.502750] Lustre: 21167:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 592.516435] Lustre: 21167:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 82 previous similar messages [ 592.529731] Lustre: 21167:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/1, xattr_set: 2/274/0 [ 592.546257] Lustre: 21167:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 82 previous similar messages [ 592.563301] Lustre: 21167:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 0/0/0, punch: 0/0/0, quota 7/225/0 [ 592.566149] Lustre: 21167:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 82 previous similar messages [ 592.572126] Lustre: 21167:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 592.580093] Lustre: 21167:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 82 previous similar messages [ 592.586254] Lustre: 21167:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 592.597034] Lustre: 21167:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 82 previous similar messages [ 608.224124] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 608.231184] 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 [ 608.246227] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 609.766600] 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 [ 609.769403] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 614.074249] Lustre: server umount lustre-MDT0000 complete [ 617.773805] LustreError: 19229:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788624878 with bad export cookie 10554036923038762879 [ 617.776890] LustreError: MGC192.168.201.117@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 617.782210] LustreError: 19229:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 618.296780] Lustre: server umount lustre-MDT0001 complete [ 632.047847] Lustre: server umount lustre-OST0000 complete [ 646.539137] Lustre: server umount lustre-OST0001 complete [ 655.313621] Lustre: DEBUG MARKER: == sanity-lfsck test 1a: LFSCK can find out and repair crashed FID-in-dirent ========================================================== 12:15:14 (1788624914) [ 670.055667] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing load_modules_local [ 680.810984] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 681.168407] LustreError: 26258:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 681.177971] LustreError: 26258:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 5 previous similar messages [ 681.261466] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 685.993620] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 686.565879] LustreError: 26259:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 691.687491] LustreError: 26258:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 694.831319] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 695.136335] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 699.768244] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 702.846242] Lustre: 27398:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 709.325699] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 715.558799] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 720.813241] LustreError: 27751:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 724.614523] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 724.782413] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 724.789859] Lustre: Skipped 1 previous similar message [ 726.828890] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:41 to 0x280000401:65) [ 726.828933] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:40 to 0x2c0000401:65) [ 731.178558] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 739.202923] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 743.221888] Lustre: 29268:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 744.743893] Lustre: 26255:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 744.749139] Lustre: 26255:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 68 previous similar messages [ 744.755092] Lustre: 26255:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 744.758712] Lustre: 26255:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 68 previous similar messages [ 744.765138] Lustre: 26255:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 744.768796] Lustre: 26255:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 68 previous similar messages [ 744.773092] Lustre: 26255:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 744.777455] Lustre: 26255:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 68 previous similar messages [ 744.781327] Lustre: 26255:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 744.786392] Lustre: 26255:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 68 previous similar messages [ 744.791509] Lustre: 26255:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 744.795491] Lustre: 26255:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 68 previous similar messages [ 749.844278] Lustre: *** cfs_fail_loc=1501, val=0*** [ 757.521708] Lustre: Failing over lustre-MDT0000 [ 757.728596] 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 [ 757.740258] Lustre: Skipped 2 previous similar messages [ 757.748941] LustreError: 29283:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 757.763391] LustreError: 29283:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 3 previous similar messages [ 757.860099] Lustre: server umount lustre-MDT0000 complete [ 767.973946] LustreError: 29291:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 768.014661] LustreError: 29291:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 7 previous similar messages [ 768.905385] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 769.097718] LustreError: MGC192.168.201.117@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 769.497564] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 769.557606] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 774.349281] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 774.635247] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 774.639198] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 774.685342] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 774.726471] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:105 to 0x2c0000401:129) [ 774.727557] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:105 to 0x280000401:129) [ 777.585739] Lustre: *** cfs_fail_loc=1505, val=0*** [ 785.143581] Lustre: DEBUG MARKER: == sanity-lfsck test 1b: LFSCK can find out and repair the missing FID-in-LMA ========================================================== 12:17:24 (1788625044) [ 786.721984] Lustre: 26253:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 786.734560] Lustre: 26253:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 322 previous similar messages [ 786.740844] Lustre: 26253:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 786.745911] Lustre: 26253:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 786.751751] Lustre: 26253:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 786.757456] Lustre: 26253:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 786.764755] Lustre: 26253:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 786.770623] Lustre: 26253:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 786.780330] Lustre: 26253:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 786.792494] Lustre: 26253:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 786.801335] Lustre: 26253:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 786.813777] Lustre: 26253:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 792.132684] Lustre: *** cfs_fail_loc=1502, val=0*** [ 802.799878] Lustre: Failing over lustre-MDT0000 [ 803.119794] Lustre: server umount lustre-MDT0000 complete [ 805.357202] 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 [ 805.364111] LustreError: 26254:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 805.390067] Lustre: Skipped 6 previous similar messages [ 805.390237] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 805.424210] LustreError: 26254:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 3 previous similar messages [ 814.986778] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 815.151689] LustreError: MGC192.168.201.117@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 815.602274] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 820.706653] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 820.717255] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 820.726569] Lustre: Skipped 3 previous similar messages [ 820.746187] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 820.825146] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:169 to 0x280000401:193) [ 820.827112] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:169 to 0x2c0000401:193) [ 821.152964] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 824.990816] Lustre: *** cfs_fail_loc=1505, val=0*** [ 831.786529] Lustre: DEBUG MARKER: == sanity-lfsck test 1c: LFSCK can find out and repair lost FID-in-dirent ========================================================== 12:18:11 (1788625091) [ 832.890356] Lustre: 26255:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 832.897476] Lustre: 26255:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 322 previous similar messages [ 832.902430] Lustre: 26255:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 832.905584] Lustre: 26255:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 832.914549] Lustre: 26255:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 832.920962] Lustre: 26255:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 832.926242] Lustre: 26255:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 832.932963] Lustre: 26255:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 832.938151] Lustre: 26255:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 832.941808] Lustre: 26255:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 832.949679] Lustre: 26255:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 832.954684] Lustre: 26255:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 837.778948] Lustre: *** cfs_fail_loc=1504, val=0*** [ 837.780907] Lustre: *** cfs_fail_loc=1504, val=0*** [ 837.786914] Lustre: Skipped 1 previous similar message [ 848.054527] Lustre: Failing over lustre-MDT0000 [ 848.604665] Lustre: server umount lustre-MDT0000 complete [ 851.425530] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 851.431674] 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 [ 851.450062] LustreError: 26253:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 851.450076] LustreError: 26253:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 4 previous similar messages [ 851.548515] Lustre: Skipped 3 previous similar messages [ 862.353170] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 862.432814] LustreError: MGC192.168.201.117@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 862.577176] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 862.581929] Lustre: Skipped 1 previous similar message [ 862.617616] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 867.481318] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 867.814634] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 867.823678] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 867.828431] Lustre: Skipped 3 previous similar messages [ 867.852279] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 867.907736] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:233 to 0x2c0000401:257) [ 867.912737] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:233 to 0x280000401:257) [ 870.971652] Lustre: *** cfs_fail_loc=1505, val=0*** [ 878.864655] Lustre: DEBUG MARKER: == sanity-lfsck test 2a: LFSCK can find out and repair crashed linkEA entry ========================================================== 12:18:58 (1788625138) [ 885.339391] Lustre: *** cfs_fail_loc=1603, val=0*** [ 893.404427] Lustre: Failing over lustre-MDT0000 [ 893.408816] 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 [ 893.416304] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -19 [ 893.419730] Lustre: Skipped 1 previous similar message [ 893.426075] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 893.436559] Lustre: Skipped 4 previous similar messages [ 893.635281] Lustre: server umount lustre-MDT0000 complete [ 903.469342] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 903.552912] LustreError: MGC192.168.201.117@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 903.655868] Lustre: lustre-MDT0000: Not available for connect from 0@lo (not set up) [ 903.673376] Lustre: Skipped 3 previous similar messages [ 903.861467] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 908.212536] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 909.281819] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 909.306927] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 909.319065] Lustre: Skipped 3 previous similar messages [ 909.357715] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 909.452463] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:297 to 0x2c0000401:321) [ 909.453091] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:297 to 0x280000401:321) [ 919.368560] Lustre: DEBUG MARKER: == sanity-lfsck test 2b: LFSCK can find out and remove invalid linkEA entry ========================================================== 12:19:38 (1788625178) [ 920.541374] Lustre: 26255:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 920.551294] Lustre: 26255:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 644 previous similar messages [ 920.556575] Lustre: 26255:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 920.562615] Lustre: 26255:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 920.570504] Lustre: 26255:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 920.576469] Lustre: 26255:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 920.578936] Lustre: 26255:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 920.585686] Lustre: 26255:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 920.602387] Lustre: 26255:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 920.606330] Lustre: 26255:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 920.613274] Lustre: 26255:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 920.622820] Lustre: 26255:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 926.059825] Lustre: *** cfs_fail_loc=1604, val=0*** [ 933.167820] Lustre: Failing over lustre-MDT0000 [ 933.426607] Lustre: server umount lustre-MDT0000 complete [ 934.880720] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 934.884559] 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 [ 934.890582] LustreError: 26990:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 934.900342] Lustre: Skipped 4 previous similar messages [ 934.936794] LustreError: 26990:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 18 previous similar messages [ 943.801577] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 943.934587] LustreError: MGC192.168.201.117@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 944.304830] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 948.945411] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 949.741405] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 949.752434] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 949.756459] Lustre: Skipped 3 previous similar messages [ 949.781269] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 949.831642] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:361 to 0x280000401:385) [ 949.833337] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:361 to 0x2c0000401:385) [ 958.303760] Lustre: DEBUG MARKER: == sanity-lfsck test 2c: LFSCK can find out and remove repeated linkEA entry ========================================================== 12:20:17 (1788625217) [ 964.393545] Lustre: *** cfs_fail_loc=1605, val=0*** [ 972.211729] Lustre: Failing over lustre-MDT0000 [ 972.493672] Lustre: server umount lustre-MDT0000 complete [ 975.328059] 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 [ 975.357090] Lustre: Skipped 1 previous similar message [ 983.805991] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 983.962838] LustreError: MGC192.168.201.117@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 984.237471] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 989.009553] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 989.665349] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 989.679476] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 989.685633] Lustre: Skipped 3 previous similar messages [ 989.706597] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 989.752264] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:425 to 0x280000401:449) [ 989.753745] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:425 to 0x2c0000401:449) [ 998.323318] Lustre: DEBUG MARKER: == sanity-lfsck test 2d: LFSCK can recover the missing linkEA entry ========================================================== 12:20:58 (1788625258) [ 1005.547926] Lustre: *** cfs_fail_loc=161d, val=0*** [ 1013.840886] Lustre: Failing over lustre-MDT0000 [ 1014.343405] Lustre: server umount lustre-MDT0000 complete [ 1015.263435] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1025.412476] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1025.651204] LustreError: MGC192.168.201.117@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1026.016493] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1026.024807] Lustre: Skipped 3 previous similar messages [ 1026.056988] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1031.016372] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1031.145625] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1031.160116] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 1031.168638] Lustre: Skipped 3 previous similar messages [ 1031.189453] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1031.235370] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:489 to 0x2c0000401:513) [ 1031.235971] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:489 to 0x280000401:513) [ 1040.124798] Lustre: DEBUG MARKER: == sanity-lfsck test 2e: namespace LFSCK can verify remote object linkEA ========================================================== 12:21:39 (1788625299) [ 1042.560891] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1053.622352] Lustre: DEBUG MARKER: == sanity-lfsck test 3: LFSCK can verify multiple-linked objects ========================================================== 12:21:53 (1788625313) [ 1054.004501] Lustre: 29291:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 1054.015950] Lustre: 29291:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 976 previous similar messages [ 1054.021486] Lustre: 29291:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 1054.027115] Lustre: 29291:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 976 previous similar messages [ 1054.031645] Lustre: 29291:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 1054.035633] Lustre: 29291:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 976 previous similar messages [ 1054.038351] Lustre: 29291:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 1054.043500] Lustre: 29291:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 976 previous similar messages [ 1054.052507] Lustre: 29291:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 1054.057612] Lustre: 29291:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 976 previous similar messages [ 1054.064429] Lustre: 29291:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 1054.069354] Lustre: 29291:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 976 previous similar messages [ 1058.800974] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1059.735769] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1070.547928] Lustre: DEBUG MARKER: == sanity-lfsck test 4: FID-in-dirent can be rebuilt after MDT file-level backup/restore ========================================================== 12:22:10 (1788625330) [ 1106.278078] Lustre: Failing over lustre-MDT0000 [ 1106.736090] Lustre: server umount lustre-MDT0000 complete [ 1107.935856] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1107.938603] 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 [ 1107.961290] Lustre: Skipped 7 previous similar messages [ 1107.979236] LustreError: 26255:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1108.010187] LustreError: 26255:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 24 previous similar messages [ 1112.458313] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1122.299909] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1123.298559] Lustre: 16396:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788625368/real 1788625368] req@ffff8e8de9fdd180 x1875508906911872/t0(0) o400->MGC192.168.201.117@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1788625384 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1123.323245] LustreError: MGC192.168.201.117@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1133.548822] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1133.573408] Lustre: lustre-MDT0000: reset Object Index mappings [ 1148.898688] LustreError: 16394:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8e8cc53a1f80 x1875508906924928/t0(0) o250->MGC192.168.201.117@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 [ 1149.354687] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1153.907830] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1154.530209] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1154.533704] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 1154.537269] Lustre: Skipped 3 previous similar messages [ 1154.578136] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1154.628619] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:592 to 0x280000401:609) [ 1154.629097] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:592 to 0x2c0000401:609) [ 1157.652649] LustreError: 42913:0:(lfsck_engine.c:1018:lfsck_master_engine()) lustre-MDT0000-osd: master engine fail to verify the .lustre/lost+found/, go ahead: rc = -115 [ 1157.679597] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1159.779778] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1159.784889] Lustre: Skipped 1 previous similar message [ 1165.704424] Lustre: Failing over lustre-MDT0000 [ 1165.885209] Lustre: server umount lustre-MDT0000 complete [ 1169.909402] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1177.370438] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1180.709770] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1182.413381] Lustre: lustre-MDT0000: Denying connection for new client a88cb024-3803-417e-8cd5-2c88eceac31e (at 192.168.201.17@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 1:00 [ 1183.258463] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:592 to 0x2c0000401:641) [ 1183.259188] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:592 to 0x280000401:641) [ 1189.348466] Lustre: *** cfs_fail_loc=1505, val=0*** [ 1199.562909] Lustre: DEBUG MARKER: == sanity-lfsck test 5: LFSCK can handle IGIF object upgrading ========================================================== 12:24:18 (1788625458) [ 1202.075143] Lustre: *** cfs_fail_loc=1504, val=0*** [ 1211.090901] Lustre: Failing over lustre-MDT0000 [ 1211.539145] Lustre: server umount lustre-MDT0000 complete [ 1218.152283] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1229.469980] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1230.306478] Lustre: 16397:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788625474/real 1788625474] req@ffff8e8dcf7d1500 x1875508907013248/t0(0) o400->MGC192.168.201.117@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1788625490 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1241.478717] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1241.511547] Lustre: lustre-MDT0000: reset Object Index mappings [ 1256.259905] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1256.274359] Lustre: Skipped 1 previous similar message [ 1261.252935] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1261.543264] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1261.554201] Lustre: Skipped 1 previous similar message [ 1261.589597] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1261.597223] Lustre: Skipped 7 previous similar messages [ 1261.623763] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1261.634061] Lustre: Skipped 1 previous similar message [ 1261.689317] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:681 to 0x2c0000401:705) [ 1261.697830] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:681 to 0x280000401:705) [ 1265.754587] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1265.756604] Lustre: Skipped 1 previous similar message [ 1273.952450] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1273.956810] Lustre: Skipped 7 previous similar messages [ 1280.078608] Lustre: Failing over lustre-MDT0000 [ 1282.037191] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1282.044447] 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 [ 1282.049158] LustreError: Skipped 1 previous similar message [ 1282.064789] Lustre: Skipped 14 previous similar messages [ 1282.338577] Lustre: server umount lustre-MDT0000 complete [ 1294.027795] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1294.225421] LustreError: MGC192.168.201.117@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1294.233436] LustreError: Skipped 2 previous similar messages [ 1294.601969] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1294.605162] Lustre: Skipped 3 previous similar messages [ 1299.226661] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1300.027482] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:681 to 0x2c0000401:737) [ 1300.031070] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:681 to 0x280000401:737) [ 1302.867817] Lustre: *** cfs_fail_loc=1505, val=0*** [ 1302.875158] Lustre: Skipped 84 previous similar messages [ 1311.305040] Lustre: DEBUG MARKER: == sanity-lfsck test 6a: LFSCK resumes from last checkpoint (1) ========================================================== 12:26:11 (1788625571) [ 1312.721377] Lustre: 26255:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 255 < left 278, rollback = 2 [ 1312.737655] Lustre: 26255:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 934 previous similar messages [ 1312.744249] Lustre: 26255:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/2, destroy: 0/0/0 [ 1312.748384] Lustre: 26255:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 934 previous similar messages [ 1312.753347] Lustre: 26255:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 1312.759224] Lustre: 26255:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 934 previous similar messages [ 1312.762517] Lustre: 26255:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 1312.765699] Lustre: 26255:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 934 previous similar messages [ 1312.769020] Lustre: 26255:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 1312.772125] Lustre: 26255:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 934 previous similar messages [ 1312.777151] Lustre: 26255:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 1312.782238] Lustre: 26255:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 934 previous similar messages [ 1318.971816] Lustre: *** cfs_fail_loc=1600, val=1*** [ 1338.341562] Lustre: DEBUG MARKER: == sanity-lfsck test 6b: LFSCK resumes from last checkpoint (2) ========================================================== 12:26:37 (1788625597) [ 1351.649395] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1351.653746] Lustre: Skipped 14 previous similar messages [ 1369.269837] Lustre: DEBUG MARKER: == sanity-lfsck test 7a: non-stopped LFSCK should auto restarts after MDS remount (1) ========================================================== 12:27:08 (1788625628) [ 1384.824493] Lustre: Failing over lustre-MDT0000 [ 1385.077892] Lustre: server umount lustre-MDT0000 complete [ 1386.981205] LustreError: 26253:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1386.999381] LustreError: 26253:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 98 previous similar messages [ 1394.402948] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1394.897515] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1394.906935] Lustre: Skipped 1 previous similar message [ 1398.882809] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1400.295769] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1400.310870] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1400.310878] Lustre: Skipped 7 previous similar messages [ 1400.330743] Lustre: Skipped 1 previous similar message [ 1400.374649] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1400.387704] Lustre: Skipped 1 previous similar message [ 1400.542845] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:853 to 0x2c0000401:897) [ 1400.546582] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:854 to 0x280000401:897) [ 1408.861503] Lustre: DEBUG MARKER: == sanity-lfsck test 7b: non-stopped LFSCK should auto restarts after MDS remount (2) ========================================================== 12:27:48 (1788625668) [ 1427.112440] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing load_modules_local [ 1445.612141] Lustre: 52932:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 1467.928193] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1471.036395] Lustre: 54068:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 1478.442645] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1478.450533] Lustre: Skipped 81 previous similar messages [ 1480.625963] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1481.631129] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1482.657026] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1484.703177] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1484.710789] Lustre: Skipped 1 previous similar message [ 1484.741794] Lustre: Failing over lustre-MDT0000 [ 1485.036762] Lustre: server umount lustre-MDT0000 complete [ 1487.327517] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1487.339191] LustreError: Skipped 1 previous similar message [ 1494.247978] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1499.310714] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1499.720066] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:947 to 0x2c0000401:993) [ 1499.720443] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:946 to 0x280000401:961) [ 1508.432612] Lustre: DEBUG MARKER: == sanity-lfsck test 8: LFSCK state machine ============== 12:29:28 (1788625768) [ 1514.976476] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1518.863990] Lustre: server umount lustre-MDT0000 complete [ 1522.794831] LustreError: 29290:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788625783 with bad export cookie 10554036923038977737 [ 1522.801549] LustreError: 29290:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 1523.222269] Lustre: server umount lustre-MDT0001 complete [ 1536.131139] Lustre: server umount lustre-OST0000 complete [ 1550.331397] Lustre: server umount lustre-OST0001 complete [ 1557.143934] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_hostid [ 1566.782718] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing load_modules_local [ 1612.342963] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing load_modules_local [ 1624.009595] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1624.344243] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 1624.376953] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 1624.509071] Lustre: lustre-MDT0000: new disk, initializing [ 1624.654972] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 1629.607322] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1641.033329] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1641.180766] Lustre: 59129: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 [ 1641.213695] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 1641.217857] Lustre: Skipped 1 previous similar message [ 1641.312292] Lustre: lustre-MDT0001: new disk, initializing [ 1641.492465] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 1641.509075] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 1647.399075] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1652.071312] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 1660.453549] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 1660.998347] Lustre: lustre-OST0000: new disk, initializing [ 1661.006212] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 1661.019671] Lustre: 60761:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 1662.171129] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 1662.180702] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 1662.377768] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 1671.154201] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1683.022737] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 1683.166412] Lustre: lustre-OST0001: new disk, initializing [ 1683.170263] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 1683.174982] Lustre: 61634:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 1684.877986] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 1684.888871] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 1685.037475] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 1690.795675] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1700.340739] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1704.205406] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 1713.699667] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1714.645170] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1714.647926] Lustre: Skipped 19 previous similar messages [ 1719.318439] Lustre: *** cfs_fail_loc=1601, val=2*** [ 1719.324314] Lustre: Skipped 12 previous similar messages [ 1736.390034] Lustre: Failing over lustre-MDT0000 [ 1736.604468] Lustre: server umount lustre-MDT0000 complete [ 1738.720022] 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 [ 1738.739849] Lustre: Skipped 12 previous similar messages [ 1745.965607] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1746.127248] LustreError: MGC192.168.201.117@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1746.140757] LustreError: Skipped 3 previous similar messages [ 1746.495569] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1746.499432] Lustre: Skipped 1 previous similar message [ 1751.361248] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1751.523308] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1751.527706] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1751.531685] Lustre: Skipped 1 previous similar message [ 1751.555498] Lustre: Skipped 7 previous similar messages [ 1751.588458] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1751.592801] Lustre: Skipped 1 previous similar message [ 1751.666843] Lustre: *** cfs_fail_loc=160b, val=2*** [ 1751.675286] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:65) [ 1751.677183] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:65) [ 1759.503943] Lustre: Failing over lustre-MDT0000 [ 1761.760972] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1761.765929] Lustre: server umount lustre-MDT0000 complete [ 1761.768331] LustreError: Skipped 2 previous similar messages [ 1770.947395] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1776.482763] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1776.723743] Lustre: *** cfs_fail_loc=160b, val=2*** [ 1776.729082] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:97) [ 1776.732491] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:97) [ 1782.315548] Lustre: Failing over lustre-MDT0000 [ 1782.770191] Lustre: server umount lustre-MDT0000 complete [ 1792.220853] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1798.210434] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:129) [ 1798.230752] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:129) [ 1798.250641] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1803.907503] Lustre: *** cfs_fail_loc=1602, val=2*** [ 1815.422634] Lustre: DEBUG MARKER: == sanity-lfsck test 9a: LFSCK speed control (1) ========= 12:34:35 (1788626075) [ 1828.917066] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing load_modules_local [ 1845.467564] Lustre: 68586:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 1868.418990] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1872.307933] Lustre: 69722:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 1879.421498] Lustre: 59136:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 1879.427343] Lustre: 59136:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 2693 previous similar messages [ 1879.432634] Lustre: 59136:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 1879.437389] Lustre: 59136:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 2693 previous similar messages [ 1879.441802] Lustre: 59136:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 1879.448638] Lustre: 59136:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 2693 previous similar messages [ 1879.452604] Lustre: 59136:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 1879.457087] Lustre: 59136:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 2693 previous similar messages [ 1879.462126] Lustre: 59136:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 1879.466273] Lustre: 59136:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 2693 previous similar messages [ 1879.472320] Lustre: 59136:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 1879.477550] Lustre: 59136:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 2693 previous similar messages [ 1977.578629] Lustre: DEBUG MARKER: == sanity-lfsck test 9b: LFSCK speed control (2) ========= 12:37:17 (1788626237) [ 2026.317479] Lustre: *** cfs_fail_loc=1604, val=0*** [ 2026.320206] Lustre: Skipped 4 previous similar messages [ 2049.092588] Lustre: *** cfs_fail_loc=160c, val=0*** [ 2049.094136] Lustre: Skipped 7 previous similar messages [ 2087.023952] Lustre: DEBUG MARKER: == sanity-lfsck test 10: System is available during LFSCK scanning ========================================================== 12:39:06 (1788626346) [ 2130.470980] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2131.566615] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2131.569737] Lustre: Skipped 50 previous similar messages [ 2133.594698] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2133.596492] Lustre: Skipped 118 previous similar messages [ 2137.626493] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2137.628908] Lustre: Skipped 251 previous similar messages [ 2145.627454] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2145.629165] Lustre: Skipped 334 previous similar messages [ 2161.651658] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2161.657375] Lustre: Skipped 859 previous similar messages [ 2193.654107] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2193.657979] Lustre: Skipped 1766 previous similar messages [ 2198.029303] Lustre: *** cfs_fail_loc=1604, val=0*** [ 2198.040030] Lustre: Skipped 2599 previous similar messages [ 2439.895648] Lustre: DEBUG MARKER: == sanity-lfsck test 11a: LFSCK can rebuild lost last_id ========================================================== 12:44:59 (1788626699) [ 2577.996954] Lustre: 59135:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 2578.016151] Lustre: 59135:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 36832 previous similar messages [ 2578.021950] Lustre: 59135:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 2578.029109] Lustre: 59135:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 36832 previous similar messages [ 2578.033643] Lustre: 59135:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 2578.038441] Lustre: 59135:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 36832 previous similar messages [ 2578.044217] Lustre: 59135:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 2578.049448] Lustre: 59135:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 36832 previous similar messages [ 2578.053582] Lustre: 59135:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 2578.057846] Lustre: 59135:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 36832 previous similar messages [ 2578.063979] Lustre: 59135:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 2578.067015] Lustre: 59135:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 36832 previous similar messages [ 2584.545541] 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 [ 2584.547855] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2584.572067] Lustre: Skipped 13 previous similar messages [ 2584.595073] Lustre: Skipped 6 previous similar messages [ 2589.630586] Lustre: server umount lustre-MDT0000 complete [ 2589.696061] LustreError: 60755:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 2589.718178] LustreError: 60755:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 40 previous similar messages [ 2593.353045] LustreError: 59121:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788626854 with bad export cookie 10554036923038996833 [ 2593.355700] LustreError: MGC192.168.201.117@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2593.368106] LustreError: Skipped 2 previous similar messages [ 2593.368989] LustreError: 59121:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 7 previous similar messages [ 2593.742381] Lustre: server umount lustre-MDT0001 complete [ 2608.950810] Lustre: server umount lustre-OST0000 complete [ 2610.655083] Lustre: 16398:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788626855/real 1788626855] req@ffff8e8df6ad4000 x1875508911142912/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788626871 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2613.928390] Lustre: server umount lustre-OST0001 complete [ 2620.830840] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: (null) [ 2629.209439] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 2644.833727] LustreError: Failed to get MGS log lustre-sptlrpc and no local copy. [ 2649.951457] LustreError: 75461:0:(mgc_request.c:233:do_config_log_add()) MGC192.168.201.117@tcp: failed processing log, type 4: rc = -110 [ 2675.679514] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 2675.691538] Lustre: Skipped 9 previous similar messages [ 2682.673643] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2686.745590] Lustre: 76046:0:(ofd_dev.c:561:ofd_lfsck_out_notify()) lustre-OST0000: Found crashed LAST_ID, deny creating new OST-object on the device until the LAST_ID rebuilt successfully. [ 2686.783344] Lustre: *** cfs_fail_loc=160e, val=3*** [ 2689.838890] Lustre: 76046:0:(ofd_dev.c:573:ofd_lfsck_out_notify()) lustre-OST0000: Rebuilt crashed LAST_ID files successfully. [ 2698.863413] Lustre: DEBUG MARKER: == sanity-lfsck test 11b: LFSCK can rebuild crashed last_id ========================================================== 12:49:18 (1788626958) [ 2715.228628] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing load_modules_local [ 2727.390185] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2727.744877] LustreError: 75486:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 2727.879379] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3272 to 0x280000401:3297) [ 2733.721902] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2743.415550] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2743.737362] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 2743.751473] Lustre: Skipped 1 previous similar message [ 2748.867916] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2752.605682] Lustre: 78713:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 2773.391596] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2779.114386] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3207 to 0x2c0000401:3233) [ 2781.707102] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2792.389935] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 2797.123566] Lustre: 80215:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 2802.002898] Lustre: *** cfs_fail_loc=160d, val=0*** [ 2802.558221] Lustre: *** cfs_fail_loc=160d, val=0*** [ 2802.560105] Lustre: Skipped 3 previous similar messages [ 2808.273823] Lustre: Failing over lustre-OST0000 [ 2808.364222] Lustre: server umount lustre-OST0000 complete [ 2809.826847] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 2809.839813] LustreError: Skipped 1 previous similar message [ 2817.648570] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2817.782903] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 2817.796246] Lustre: Skipped 2 previous similar messages [ 2819.558341] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 2819.578675] Lustre: Skipped 2 previous similar messages [ 2819.651252] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 2819.660992] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 2819.664307] Lustre: *** cfs_fail_loc=215, val=0*** [ 2819.676369] Lustre: Skipped 2 previous similar messages [ 2819.704172] Lustre: Skipped 11 previous similar messages [ 2824.679380] Lustre: *** cfs_fail_loc=215, val=0*** [ 2824.685396] Lustre: Skipped 2 previous similar messages [ 2825.413703] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2829.310614] Lustre: 81611:0:(ofd_dev.c:561:ofd_lfsck_out_notify()) lustre-OST0000: Found crashed LAST_ID, deny creating new OST-object on the device until the LAST_ID rebuilt successfully. [ 2829.329928] Lustre: 81611:0:(ofd_dev.c:573:ofd_lfsck_out_notify()) lustre-OST0000: Rebuilt crashed LAST_ID files successfully. [ 2829.800084] Lustre: *** cfs_fail_loc=215, val=0*** [ 2829.806984] Lustre: Skipped 1 previous similar message [ 2832.476100] Lustre: Failing over lustre-OST0000 [ 2832.678340] Lustre: server umount lustre-OST0000 complete [ 2842.431086] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2844.435645] Lustre: *** cfs_fail_loc=215, val=0*** [ 2844.442403] Lustre: Skipped 1 previous similar message [ 2849.523595] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2849.760824] Lustre: *** cfs_fail_loc=215, val=0*** [ 2856.417055] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2858.469935] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2858.475231] Lustre: Skipped 2 previous similar messages [ 2863.584467] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2863.587439] Lustre: Skipped 3 previous similar messages [ 2870.239446] Lustre: lustre-MDT0000 is waiting for obd_unlinked_exports more than 8 seconds. The obd refcount = 3. Is it stuck? [ 2870.516764] Lustre: server umount lustre-MDT0000 complete [ 2873.827762] LustreError: 75487:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 2873.856915] LustreError: 75487:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 29 previous similar messages [ 2874.628492] LustreError: 78715:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788627135 with bad export cookie 10554036923040561004 [ 2874.637850] LustreError: 78715:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 2875.079198] Lustre: server umount lustre-MDT0001 complete [ 2889.884575] Lustre: server umount lustre-OST0000 complete [ 2904.239405] Lustre: server umount lustre-OST0001 complete [ 2913.090547] Lustre: DEBUG MARKER: == sanity-lfsck test 12a: single command to trigger LFSCK on all devices ========================================================== 12:52:52 (1788627172) [ 2929.440275] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing load_modules_local [ 2940.490021] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2940.929414] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 2940.932362] Lustre: Skipped 3 previous similar messages [ 2945.364517] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2954.578581] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2960.397802] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2963.513978] Lustre: 86002:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 2971.516249] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2978.384756] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2985.068387] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3362 to 0x280000401:3393) [ 2988.577199] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2994.166434] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3207 to 0x2c0000401:3265) [ 2996.984659] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3004.843826] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3008.794458] Lustre: 87872:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 3044.074284] Lustre: DEBUG MARKER: == sanity-lfsck test 12b: auto detect Lustre device ====== 12:55:03 (1788627303) [ 3059.529884] Lustre: DEBUG MARKER: == sanity-lfsck test 13: LFSCK can repair crashed lmm_oi ========================================================== 12:55:19 (1788627319) [ 3061.062109] Lustre: *** cfs_fail_loc=160f, val=0*** [ 3073.370696] Lustre: DEBUG MARKER: == sanity-lfsck test 14a: LFSCK can repair MDT-object with dangling LOV EA reference (1) ========================================================== 12:55:32 (1788627332) [ 3077.872424] Lustre: *** cfs_fail_loc=1610, val=0*** [ 3077.875556] Lustre: Skipped 3 previous similar messages [ 3132.388482] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3132.403084] Lustre: Skipped 7 previous similar messages [ 3137.504937] LustreError: 84857:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3137.527622] LustreError: 84857:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 9 previous similar messages [ 3139.158158] Lustre: server umount lustre-MDT0000 complete [ 3143.695973] LustreError: 84844:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788627404 with bad export cookie 10554036923040569495 [ 3143.715056] LustreError: 84844:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 3144.321720] Lustre: server umount lustre-MDT0001 complete [ 3159.657266] Lustre: server umount lustre-OST0000 complete [ 3163.105798] Lustre: 16398:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788627408/real 1788627408] req@ffff8e8dc7b97100 x1875508911483776/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788627424 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3164.179422] Lustre: server umount lustre-OST0001 complete [ 3182.244702] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing load_modules_local [ 3194.668730] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3201.218574] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3212.287426] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3212.521861] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 3212.525069] Lustre: Skipped 4 previous similar messages [ 3217.954516] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3221.641653] Lustre: 93792:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3230.398666] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3237.113356] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:116 to 0x280000400:161) [ 3239.712602] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3241.217756] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3554 to 0x280000401:3585) [ 3250.601279] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3256.308340] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3317 to 0x2c0000401:3361) [ 3256.314970] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:116 to 0x2c0000400:161) [ 3258.926928] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3266.758338] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3270.288570] Lustre: 95664:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 3279.528905] Lustre: DEBUG MARKER: == sanity-lfsck test 14b: LFSCK can repair MDT-object with dangling LOV EA reference (2) ========================================================== 12:58:58 (1788627538) [ 3282.183986] Lustre: 95497:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 256 < left 278, rollback = 2 [ 3282.196866] Lustre: 95497:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 1370 previous similar messages [ 3282.208914] Lustre: 95497:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 3282.223867] Lustre: 95497:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1370 previous similar messages [ 3282.234996] Lustre: 95497:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3282.250445] Lustre: 95497:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1370 previous similar messages [ 3282.262684] Lustre: 95497:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 3282.285407] Lustre: 95497:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1370 previous similar messages [ 3282.306498] Lustre: 95497:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 3282.317677] Lustre: 95497:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1370 previous similar messages [ 3282.325607] Lustre: 95497:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3282.340719] Lustre: 95497:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1370 previous similar messages [ 3286.921890] Lustre: *** cfs_fail_loc=1610, val=0*** [ 3286.937908] Lustre: Skipped 63 previous similar messages [ 3315.172363] 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 [ 3315.192680] Lustre: Skipped 15 previous similar messages [ 3315.221070] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3319.326715] Lustre: server umount lustre-MDT0000 complete [ 3323.458034] LustreError: 92632:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788627584 with bad export cookie 10554036923040597908 [ 3323.465965] LustreError: MGC192.168.201.117@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3323.484462] LustreError: 92632:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 3323.508665] LustreError: Skipped 2 previous similar messages [ 3323.990137] Lustre: server umount lustre-MDT0001 complete [ 3338.860476] Lustre: server umount lustre-OST0000 complete [ 3354.121640] Lustre: server umount lustre-OST0001 complete [ 3373.583449] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing load_modules_local [ 3385.375865] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3391.100314] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3401.939583] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3408.425594] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3412.268761] Lustre: 99715:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3419.683530] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3427.250631] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3428.278215] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:116 to 0x280000400:193) [ 3430.322749] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3682 to 0x280000401:3713) [ 3437.350936] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3442.671949] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:116 to 0x2c0000400:193) [ 3442.678296] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3317 to 0x2c0000401:3393) [ 3445.893857] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3454.690472] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3467.551906] Lustre: DEBUG MARKER: == sanity-lfsck test 15a: LFSCK can repair unmatched MDT-object/OST-object pairs (1) ========================================================== 13:02:07 (1788627727) [ 3473.223480] Lustre: *** cfs_fail_loc=1611, val=0*** [ 3473.231726] Lustre: Skipped 63 previous similar messages [ 3473.552338] Lustre: *** cfs_fail_loc=1611, val=0*** [ 3488.354515] Lustre: DEBUG MARKER: == sanity-lfsck test 15b: LFSCK can repair unmatched MDT-object/OST-object pairs (2) ========================================================== 13:02:27 (1788627747) [ 3491.005052] Lustre: *** cfs_fail_loc=1612, val=0*** [ 3491.080558] Lustre: *** cfs_fail_loc=1612, val=0*** [ 3491.085275] Lustre: Skipped 3 previous similar messages [ 3502.790227] Lustre: DEBUG MARKER: == sanity-lfsck test 15c: LFSCK can repair unmatched MDT-object/OST-object pairs (3) ========================================================== 13:02:42 (1788627762) [ 3504.936522] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_15c MDS newer than 2.7.55, LU-6475 [ 3506.748921] Lustre: DEBUG MARKER: == sanity-lfsck test 15d: LFSCK don't crash upon dir migration failure ========================================================== 13:02:46 (1788627766) [ 3512.881085] Lustre: *** cfs_fail_loc=1709, val=0*** [ 3512.922922] LustreError: 98568:0:(osp_object.c:618:osp_attr_get()) lustre-MDT0001-osp-MDT0000: osp_attr_get update error [0x240002340:0x88:0x0]: rc = -5 [ 3512.941959] LustreError: 98568:0:(mdt_reint.c:2644:mdt_reint_migrate()) lustre-MDT0000: migrate [0x240002340:0x6c:0x0]/f21 failed: rc = -5 [ 3580.913698] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3580.920706] Lustre: Skipped 7 previous similar messages [ 3584.337456] Lustre: server umount lustre-MDT0000 complete [ 3593.982530] LustreError: 98541:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788627855 with bad export cookie 10554036923040612643 [ 3593.999378] LustreError: 98541:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 3594.495253] Lustre: server umount lustre-MDT0001 complete [ 3612.255564] Lustre: 16397:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788627857/real 1788627857] req@ffff8e8ccf28e300 x1875508912271488/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788627873 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3614.627296] Lustre: server umount lustre-OST0000 complete [ 3614.688565] Lustre: 16396:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788627859/real 1788627859] req@ffff8e8ccf28d180 x1875508912271744/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788627875 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3620.324122] Lustre: 16395:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788627865/real 1788627865] req@ffff8e8ccf9a1f80 x1875508912272256/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788627881 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3620.351567] Lustre: 16395:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 3623.309356] Lustre: server umount lustre-OST0001 complete [ 3641.948598] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing unload_modules_local [ 3645.184976] Key type lgssc unregistered [ 3645.516609] LNet: 105420:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 3645.526288] LNetError: 105420:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 3645.552246] LNet: Removed LNI 192.168.201.117@tcp [ 3646.883456] Key type .llcrypt unregistered [ 3646.889601] Key type ._llcrypt unregistered [ 3672.875408] Key type ._llcrypt registered [ 3672.876563] Key type .llcrypt registered [ 3672.961118] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_hostid [ 3687.379715] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing load_modules_local [ 3688.634590] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 3688.753947] alg: No test for adler32 (adler32-zlib) [ 3690.084486] Lustre: Lustre: Build Version: 2.17.58_2_g69c2166 [ 3690.417128] LNet: Added LNI 192.168.201.117@tcp [8/256/0/180] [ 3692.063305] Key type lgssc registered [ 3693.594853] Lustre: Echo OBD driver; http://www.lustre.org/ [ 3745.227748] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing load_modules_local [ 3759.753924] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 3759.806685] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3761.134366] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 3761.175766] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 3761.287555] Lustre: lustre-MDT0000: new disk, initializing [ 3761.363825] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3761.390373] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 3766.661479] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3780.536056] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3780.612364] Lustre: 109874: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 [ 3780.655970] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 3780.660431] Lustre: Skipped 1 previous similar message [ 3780.730896] Lustre: lustre-MDT0001: new disk, initializing [ 3780.855604] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 3780.910399] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 3780.927534] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 3786.229215] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3791.069954] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 3800.536169] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3800.854497] Lustre: lustre-OST0000: new disk, initializing [ 3800.857912] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 3800.867569] Lustre: 111812:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 3800.945442] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 3804.128901] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 3804.146701] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 3804.219770] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 3806.979524] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3820.859314] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3821.027682] Lustre: lustre-OST0001: new disk, initializing [ 3821.034521] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 3821.041990] Lustre: 112836:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 3821.117401] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 3827.509721] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3830.398141] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 3830.405764] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 3830.506613] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 3840.803555] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3850.065667] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 3857.070675] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 13:08:36 (1788628116) === [ 3865.208943] Lustre: DEBUG MARKER: == sanity-lfsck test 16: LFSCK can repair inconsistent MDT-object/OST-object owner ========================================================== 13:08:44 (1788628124) [ 3865.511737] Lustre: 109880:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 251 < left 278, rollback = 2 [ 3865.527789] Lustre: 109880:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 3865.537380] Lustre: 109880:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3865.548664] Lustre: 109880:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 3865.556741] Lustre: 109880:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 3865.565714] Lustre: 109880:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3866.141852] Lustre: 110826:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 252 < left 278, rollback = 2 [ 3866.156974] Lustre: 110826:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 9 previous similar messages [ 3866.164046] Lustre: 110826:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 3866.175212] Lustre: 110826:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3866.180650] Lustre: 110826:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3866.188684] Lustre: 110826:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3866.197300] Lustre: 110826:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/1, punch: 0/0/0, quota 7/369/2 [ 3866.204468] Lustre: 110826:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3866.209344] Lustre: 110826:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/1, delete: 0/0/0 [ 3866.216266] Lustre: 110826:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3866.227770] Lustre: 110826:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3866.232956] Lustre: 110826:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3867.142333] Lustre: 109880:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 3867.173404] Lustre: 109880:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 194 previous similar messages [ 3867.182994] Lustre: 109880:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 3867.197778] Lustre: 109880:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 194 previous similar messages [ 3867.203888] Lustre: 109880:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3867.210465] Lustre: 109880:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 194 previous similar messages [ 3867.216851] Lustre: 109880:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 7/369/0 [ 3867.225545] Lustre: 109880:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 194 previous similar messages [ 3867.235685] Lustre: 109880:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 3867.255723] Lustre: 109880:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 194 previous similar messages [ 3867.275059] Lustre: 109880:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3867.296748] Lustre: 109880:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 194 previous similar messages [ 3869.030673] Lustre: *** cfs_fail_loc=1613, val=0*** [ 3879.328532] Lustre: DEBUG MARKER: == sanity-lfsck test 17: LFSCK can repair multiple references ========================================================== 13:08:59 (1788628139) [ 3880.880162] Lustre: 109879:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 257 < left 278, rollback = 2 [ 3880.891458] Lustre: 109879:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 104 previous similar messages [ 3880.903383] Lustre: 109879:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 3880.907324] Lustre: 109879:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 3880.914697] Lustre: 109879:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3880.925687] Lustre: 109879:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 3880.952247] Lustre: 109879:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 3880.963845] Lustre: 109879:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 3880.973691] Lustre: 109879:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 3880.982358] Lustre: 109879:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 3880.987712] Lustre: 109879:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3880.992335] Lustre: 109879:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 3882.831659] Lustre: *** cfs_fail_loc=1614, val=0*** [ 3883.418511] Lustre: *** cfs_fail_loc=1614, val=103*** [ 3883.423287] Lustre: Skipped 1 previous similar message [ 3887.957747] Lustre: 111802:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 259 < left 275, rollback = 2 [ 3887.966129] Lustre: 111802:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 11 previous similar messages [ 3887.973898] Lustre: 111802:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 3887.982692] Lustre: 111802:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3887.989311] Lustre: 111802:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/1, xattr_set: 3/275/0 [ 3887.997820] Lustre: 111802:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3888.009686] Lustre: 111802:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/9/0, punch: 1/4/0, quota 7/225/0 [ 3888.019266] Lustre: 111802:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3888.025228] Lustre: 111802:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 3888.030603] Lustre: 111802:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3888.041466] Lustre: 111802:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3888.053926] Lustre: 111802:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3898.636339] Lustre: DEBUG MARKER: == sanity-lfsck test 18a: Find out orphan OST-object and repair it (1) ========================================================== 13:09:17 (1788628157) [ 3899.214713] Lustre: 109879:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 256 < left 278, rollback = 2 [ 3899.227235] Lustre: 109879:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 1 previous similar message [ 3899.235916] Lustre: 109879:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/2, destroy: 0/0/0 [ 3899.243672] Lustre: 109879:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1 previous similar message [ 3899.259882] Lustre: 109879:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3899.265218] Lustre: 109879:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1 previous similar message [ 3899.274069] Lustre: 109879:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 3899.285260] Lustre: 109879:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1 previous similar message [ 3899.290097] Lustre: 109879:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 3899.300053] Lustre: 109879:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1 previous similar message [ 3899.312408] Lustre: 109879:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3899.324282] Lustre: 109879:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1 previous similar message [ 3902.794712] Lustre: *** cfs_fail_loc=1615, val=0*** [ 3902.804681] Lustre: Skipped 1 previous similar message [ 3904.125745] Lustre: *** cfs_fail_loc=1615, val=0*** [ 3904.137823] Lustre: Skipped 1 previous similar message [ 3925.529949] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_18b skipping excluded test 18b [ 3927.728543] Lustre: DEBUG MARKER: == sanity-lfsck test 18c: Find out orphan OST-object and repair it (3) ========================================================== 13:09:46 (1788628186) [ 3928.308434] Lustre: 109880:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 3928.326284] Lustre: 109880:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 21 previous similar messages [ 3928.344977] Lustre: 109880:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 3928.351167] Lustre: 109880:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3928.355564] Lustre: 109880:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3928.360252] Lustre: 109880:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3928.366987] Lustre: 109880:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 3928.373172] Lustre: 109880:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3928.379600] Lustre: 109880:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 3928.386742] Lustre: 109880:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3928.390967] Lustre: 109880:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3928.395370] Lustre: 109880:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3930.707370] Lustre: *** cfs_fail_loc=1617, val=0*** [ 3930.784368] Lustre: *** cfs_fail_loc=1617, val=0*** [ 3933.433382] Lustre: *** cfs_fail_loc=1616, val=0*** [ 3933.437391] Lustre: Skipped 3 previous similar messages [ 3952.495432] Lustre: DEBUG MARKER: == sanity-lfsck test 18d: Find out orphan OST-object and repair it (4) ========================================================== 13:10:12 (1788628212) [ 3954.800786] Lustre: *** cfs_fail_loc=1618, val=0*** [ 3954.804504] Lustre: Skipped 5 previous similar messages [ 3989.471841] 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 [ 3989.474315] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3989.482406] Lustre: Skipped 1 previous similar message [ 3989.489723] Lustre: Skipped 3 previous similar messages [ 3994.595822] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3994.606633] Lustre: Skipped 3 previous similar messages [ 3994.896510] Lustre: server umount lustre-MDT0000 complete [ 3998.647893] LustreError: 109866:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788628259 with bad export cookie 2730095595440632343 [ 3998.649101] LustreError: MGC192.168.201.117@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3998.659472] LustreError: 109866:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 3998.982198] Lustre: server umount lustre-MDT0001 complete [ 4013.668133] Lustre: server umount lustre-OST0000 complete [ 4015.586731] Lustre: 107031:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788628260/real 1788628260] req@ffff8e8ccd4dea00 x1875512342561408/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788628276 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4015.665708] 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 [ 4015.673813] Lustre: Skipped 2 previous similar messages [ 4018.802681] Lustre: server umount lustre-OST0001 complete [ 4037.505441] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing load_modules_local [ 4049.505529] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4050.068441] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4053.946226] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4055.522199] LustreError: 118553:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4055.534310] LustreError: 118553:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 3 previous similar messages [ 4060.644306] LustreError: 118554:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4063.447413] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4063.778450] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 4070.144813] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4074.071822] Lustre: 119693:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 4081.577930] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4082.057897] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 4089.249698] LustreError: 120045:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4089.282689] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:4 to 0x280000400:33) [ 4089.285932] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4094.436813] LustreError: 120048:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4095.478772] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:116 to 0x280000401:161) [ 4098.168354] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4103.667380] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:33) [ 4103.693687] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:4 to 0x2c0000401:33) [ 4105.100502] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4113.503749] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4117.503427] Lustre: 121562:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 4133.135318] Lustre: DEBUG MARKER: == sanity-lfsck test 18e: Find out orphan OST-object and repair it (5) ========================================================== 13:13:12 (1788628392) [ 4133.697680] Lustre: 118550:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 252 < left 278, rollback = 2 [ 4133.704101] Lustre: 118550:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 46 previous similar messages [ 4133.707798] Lustre: 118550:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4133.715981] Lustre: 118550:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4133.723388] Lustre: 118550:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4133.728379] Lustre: 118550:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4133.734794] Lustre: 118550:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/1 [ 4133.739853] Lustre: 118550:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4133.744321] Lustre: 118550:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 4133.748049] Lustre: 118550:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4133.754436] Lustre: 118550:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4133.759810] Lustre: 118550:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4135.723301] Lustre: *** cfs_fail_loc=1618, val=0*** [ 4135.737808] Lustre: Skipped 3 previous similar messages [ 4170.223142] 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 [ 4170.236940] Lustre: Skipped 2 previous similar messages [ 4170.237535] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4170.246658] Lustre: Skipped 3 previous similar messages [ 4175.328596] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4175.333798] Lustre: Skipped 1 previous similar message [ 4175.811177] Lustre: server umount lustre-MDT0000 complete [ 4180.079348] LustreError: 118535:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788628441 with bad export cookie 2730095595440647596 [ 4180.090792] LustreError: MGC192.168.201.117@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4180.099482] LustreError: 118535:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 4180.477602] Lustre: server umount lustre-MDT0001 complete [ 4194.201225] Lustre: server umount lustre-OST0000 complete [ 4196.831098] Lustre: 107029:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788628441/real 1788628441] req@ffff8e8ccfc0f800 x1875512342641024/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788628457 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4196.870095] Lustre: lustre-MDT0001-lwp-OST0001: Connection to lustre-MDT0001 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 4196.880949] Lustre: Skipped 1 previous similar message [ 4199.035526] Lustre: server umount lustre-OST0001 complete [ 4219.103263] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing load_modules_local [ 4232.051535] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4232.452145] LustreError: 124130:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4232.469116] LustreError: 124130:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 2 previous similar messages [ 4232.545383] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4232.550061] Lustre: Skipped 1 previous similar message [ 4238.018443] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4242.922078] LustreError: 124131:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4242.935987] LustreError: 124131:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 1 previous similar message [ 4247.620699] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4253.357438] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4256.777898] Lustre: 125271:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 4264.937240] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4272.547790] LustreError: 125625:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4272.550401] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:4 to 0x280000400:65) [ 4274.085785] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4277.675069] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:166 to 0x280000401:193) [ 4283.217215] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4288.508946] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:4 to 0x2c0000401:65) [ 4288.527370] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:65) [ 4290.495492] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4298.466468] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4302.860844] Lustre: 127143:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 4309.338642] Lustre: 125103:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 252 < left 260, rollback = 2 [ 4309.358587] Lustre: 125103:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 21 previous similar messages [ 4309.378089] Lustre: 125103:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4309.383236] Lustre: 125103:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4309.396151] Lustre: 125103:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 0/0/0, xattr_set: 1/260/0 [ 4309.400748] Lustre: 125103:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4309.421230] Lustre: *** cfs_fail_loc=1602, val=10*** [ 4309.422252] Lustre: 125103:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/9/0, punch: 0/0/0, quota 4/150/2 [ 4309.422259] Lustre: 125103:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4309.422265] Lustre: 125103:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 1/17/2, delete: 0/0/0 [ 4309.422269] Lustre: 125103:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4309.422274] Lustre: 125103:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 4309.422277] Lustre: 125103:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4309.521112] Lustre: Skipped 1 previous similar message [ 4335.984534] Lustre: DEBUG MARKER: == sanity-lfsck test 18f: Skip the failed OST(s) when handle orphan OST-objects ========================================================== 13:16:35 (1788628595) [ 4338.906742] Lustre: *** cfs_fail_loc=1616, val=0*** [ 4338.908466] Lustre: Skipped 3 previous similar messages [ 4346.187610] Lustre: *** cfs_fail_loc=161c, val=0*** [ 4366.895614] Lustre: DEBUG MARKER: == sanity-lfsck test 18g: Find out orphan OST-object and repair it (7) ========================================================== 13:17:06 (1788628626) [ 4369.309761] Lustre: *** cfs_fail_loc=162e, val=0*** [ 4383.043563] Lustre: DEBUG MARKER: == sanity-lfsck test 18h: LFSCK can repair crashed PFL extent range ========================================================== 13:17:22 (1788628642) [ 4388.040499] Lustre: *** cfs_fail_loc=162f, val=0*** [ 4388.042414] Lustre: Skipped 9 previous similar messages [ 4408.150348] Lustre: DEBUG MARKER: == sanity-lfsck test 19a: OST-object inconsistency self detect ========================================================== 13:17:47 (1788628667) [ 4420.101686] Lustre: DEBUG MARKER: == sanity-lfsck test 19b: OST-object inconsistency self repair ========================================================== 13:17:59 (1788628679) [ 4423.783447] Lustre: *** cfs_fail_loc=1611, val=0*** [ 4423.827329] Lustre: *** cfs_fail_loc=1611, val=0*** [ 4423.830665] Lustre: Skipped 3 previous similar messages [ 4429.516753] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.201.17@tcp inode [0x2000013a1:0x1f:0x0] object 0x280000401:202 extent [0-4095], client returned csum 0 (type 4), server csum 703fb3ad (type 4) [ 4430.673943] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.201.17@tcp inode [0x2000013a1:0x20:0x0] object 0x280000401:203 extent [0-4095], client returned csum 0 (type 4), server csum 7cbb935c (type 4) [ 4439.023613] Lustre: DEBUG MARKER: == sanity-lfsck test 20a: Handle the orphan with dummy LOV EA slot properly ========================================================== 13:18:18 (1788628698) [ 4439.339935] Lustre: 125647:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 252 < left 278, rollback = 2 [ 4439.345533] Lustre: 125647:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 104 previous similar messages [ 4439.362753] Lustre: 125647:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4439.373189] Lustre: 125647:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 4439.388777] Lustre: 125647:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4439.395363] Lustre: 125647:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 4439.401256] Lustre: 125647:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 4439.411020] Lustre: 125647:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 4439.421317] Lustre: 125647:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 4439.425514] Lustre: 125647:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 4439.435259] Lustre: 125647:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4439.441061] Lustre: 125647:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 4468.362293] Lustre: DEBUG MARKER: == sanity-lfsck test 20b: Handle the orphan with dummy LOV EA slot properly - PFL case ========================================================== 13:18:47 (1788628727) [ 4476.240300] Lustre: DEBUG MARKER: == sanity-lfsck test 21: run all LFSCK components by default ========================================================== 13:18:55 (1788628735) [ 4490.216376] Lustre: DEBUG MARKER: == sanity-lfsck test 22a: LFSCK can repair unmatched pairs (1) ========================================================== 13:19:09 (1788628749) [ 4492.893276] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4492.900768] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4492.907888] Lustre: Skipped 1 previous similar message [ 4506.477123] Lustre: DEBUG MARKER: == sanity-lfsck test 22b: LFSCK can repair unmatched pairs (2) ========================================================== 13:19:25 (1788628765) [ 4508.462578] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4508.476120] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4520.187487] Lustre: DEBUG MARKER: == sanity-lfsck test 23a: LFSCK can repair dangling name entry (1) ========================================================== 13:19:39 (1788628779) [ 4522.089627] Lustre: *** cfs_fail_loc=1620, val=0*** [ 4538.756527] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_23b skipping excluded test 23b [ 4540.887495] Lustre: DEBUG MARKER: == sanity-lfsck test 23c: LFSCK can repair dangling name entry (3) ========================================================== 13:20:00 (1788628800) [ 4548.215903] Lustre: *** cfs_fail_loc=1621, val=127*** [ 4548.218134] Lustre: Skipped 1 previous similar message [ 4551.376255] Lustre: *** cfs_fail_loc=1602, val=10*** [ 4572.805762] Lustre: DEBUG MARKER: == sanity-lfsck test 23d: LFSCK can repair a dangling name entry to a remote object ========================================================== 13:20:31 (1788628831) [ 4575.701330] Lustre: Failing over lustre-MDT0000 [ 4575.714668] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -19 [ 4575.726254] 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 [ 4575.764236] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4576.134896] Lustre: server umount lustre-MDT0000 complete [ 4579.454352] LustreError: 125647:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.201.17@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4579.488286] LustreError: 125647:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 4 previous similar messages [ 4587.940845] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4588.105522] LustreError: MGC192.168.201.117@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4588.489346] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4588.498900] Lustre: Skipped 3 previous similar messages [ 4588.542887] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4589.653439] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4593.638349] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4593.695016] Lustre: lustre-MDT0000: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 4593.733724] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:265 to 0x280000401:289) [ 4593.734628] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:130 to 0x2c0000401:161) [ 4594.502835] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4596.668848] LustreError: 125647:0:(mdt_open.c:1324:mdt_cross_open()) lustre-MDT0000: [0x2000013a3:0x82:0x0] doesn't exist!: rc = -14 [ 4609.274344] Lustre: DEBUG MARKER: == sanity-lfsck test 24: LFSCK can repair multiple-referenced name entry ========================================================== 13:21:08 (1788628868) [ 4611.370159] Lustre: *** cfs_fail_loc=1622, val=0*** [ 4611.501982] Lustre: *** cfs_fail_loc=1622, val=0*** [ 4611.504631] Lustre: Skipped 1 previous similar message [ 4623.135993] Lustre: DEBUG MARKER: == sanity-lfsck test 25: LFSCK can repair bad file type in the name entry ========================================================== 13:21:22 (1788628882) [ 4624.612881] Lustre: *** cfs_fail_loc=1623, val=0*** [ 4635.288251] Lustre: DEBUG MARKER: == sanity-lfsck test 26a: LFSCK can add the missing local name entry back to the namespace ========================================================== 13:21:34 (1788628894) [ 4637.010914] Lustre: *** cfs_fail_loc=1624, val=0*** [ 4648.203128] Lustre: DEBUG MARKER: == sanity-lfsck test 26b: LFSCK can add the missing remote name entry back to the namespace ========================================================== 13:21:47 (1788628907) [ 4661.172314] Lustre: DEBUG MARKER: == sanity-lfsck test 27a: LFSCK can recreate the lost local parent directory as orphan ========================================================== 13:22:00 (1788628920) [ 4662.735885] Lustre: *** cfs_fail_loc=1624, val=0*** [ 4662.742976] Lustre: Skipped 1 previous similar message [ 4675.621486] Lustre: DEBUG MARKER: == sanity-lfsck test 27b: LFSCK can recreate the lost remote parent directory as orphan ========================================================== 13:22:14 (1788628934) [ 4691.995495] Lustre: DEBUG MARKER: == sanity-lfsck test 28: Skip the failed MDT(s) when handle orphan MDT-objects ========================================================== 13:22:31 (1788628951) [ 4695.970167] Lustre: *** cfs_fail_loc=1624, val=0*** [ 4695.973895] Lustre: Skipped 2 previous similar messages [ 4699.946651] Lustre: *** cfs_fail_loc=161c, val=0*** [ 4699.948130] Lustre: Skipped 1 previous similar message [ 4718.730600] Lustre: DEBUG MARKER: == sanity-lfsck test 29b: LFSCK can repair bad nlink count (2) ========================================================== 13:22:58 (1788628978) [ 4719.587973] Lustre: 124127:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 4719.597089] Lustre: 124127:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 518 previous similar messages [ 4719.605228] Lustre: 124127:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 4719.612452] Lustre: 124127:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 518 previous similar messages [ 4719.618755] Lustre: 124127:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4719.627050] Lustre: 124127:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 518 previous similar messages [ 4719.640045] Lustre: 124127:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 4719.650948] Lustre: 124127:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 518 previous similar messages [ 4719.657250] Lustre: 124127:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 4719.670657] Lustre: 124127:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 518 previous similar messages [ 4719.678606] Lustre: 124127:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4719.684320] Lustre: 124127:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 518 previous similar messages [ 4733.179398] Lustre: DEBUG MARKER: == sanity-lfsck test 29c: verify linkEA size limitation == 13:23:12 (1788628992) [ 4762.441938] Lustre: DEBUG MARKER: == sanity-lfsck test 29d: accessing non-existing inode shouldn't turn fs read-only (ldiskfs) ========================================================== 13:23:42 (1788629022) [ 4764.023403] Lustre: *** cfs_fail_loc=1626, val=0*** [ 4764.025202] Lustre: Skipped 2 previous similar messages [ 4765.236941] LustreError: 124127:0:(osd_handler.c:284:osd_idc_find_or_init()) lustre-MDT0000: cannot lookup FID [0x2000013a3:0x9e:0x0]: rc = -2 [ 4772.147745] Lustre: DEBUG MARKER: == sanity-lfsck test 30: LFSCK can recover the orphans from backend /lost+found ========================================================== 13:23:51 (1788629031) [ 4795.493644] Lustre: Failing over lustre-MDT0000 [ 4795.970700] Lustre: server umount lustre-MDT0000 complete [ 4798.451175] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4798.457677] 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 [ 4798.474230] LustreError: 124126:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4798.481993] Lustre: Skipped 5 previous similar messages [ 4798.503733] LustreError: 124126:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 12 previous similar messages [ 4808.458192] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 4808.643621] LustreError: MGC192.168.201.117@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4808.677374] LustreError: 107027:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff8e8ccad4bb80 x1875512343506304/t0(0) o250->MGC192.168.201.117@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 [ 4809.024836] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4809.082225] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4814.250249] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4814.307472] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4814.326250] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4814.342972] Lustre: Skipped 3 previous similar messages [ 4814.379842] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4814.458137] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:294 to 0x280000401:321) [ 4814.460031] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:167 to 0x2c0000401:193) [ 4827.419869] Lustre: DEBUG MARKER: == sanity-lfsck test 31a: The LFSCK can find/repair the name entry with bad name hash (1) ========================================================== 13:24:46 (1788629086) [ 4841.303623] Lustre: DEBUG MARKER: == sanity-lfsck test 31b: The LFSCK can find/repair the name entry with bad name hash (2) ========================================================== 13:25:00 (1788629100) [ 4854.839894] Lustre: DEBUG MARKER: == sanity-lfsck test 31c: Re-generate the lost master LMV EA for striped directory ========================================================== 13:25:14 (1788629114) [ 4856.232741] Lustre: *** cfs_fail_loc=1629, val=0*** [ 4856.237761] Lustre: Skipped 7 previous similar messages [ 4871.254091] Lustre: DEBUG MARKER: == sanity-lfsck test 31d: Set broken striped directory (modified after broken) as read-only ========================================================== 13:25:30 (1788629130) [ 4878.490927] Lustre: Failing over lustre-MDT0000 [ 4878.728271] Lustre: server umount lustre-MDT0000 complete [ 4880.867494] 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 [ 4880.875264] Lustre: Skipped 1 previous similar message [ 4880.879927] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4888.209170] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4888.281949] LustreError: MGC192.168.201.117@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4888.683976] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4893.488371] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4893.665840] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4893.689089] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4893.700289] Lustre: Skipped 3 previous similar messages [ 4893.740107] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4893.830435] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:294 to 0x280000401:353) [ 4893.839504] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:167 to 0x2c0000401:225) [ 4904.256300] Lustre: Failing over lustre-MDT0000 [ 4904.515049] Lustre: server umount lustre-MDT0000 complete [ 4909.036077] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4913.015617] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4913.135510] LustreError: MGC192.168.201.117@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4913.368649] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4916.810842] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4918.050485] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4918.771536] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4918.779929] Lustre: Skipped 3 previous similar messages [ 4918.813616] Lustre: lustre-MDT0000: Recovery over after 0:02, of 2 clients 2 recovered and 0 were evicted. [ 4918.860114] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:227 to 0x2c0000401:257) [ 4918.860866] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:294 to 0x280000401:385) [ 4927.782596] Lustre: DEBUG MARKER: == sanity-lfsck test 31e: Re-generate the lost slave LMV EA for striped directory (1) ========================================================== 13:26:27 (1788629187) [ 4940.737238] Lustre: DEBUG MARKER: == sanity-lfsck test 31f: Re-generate the lost slave LMV EA for striped directory (2) ========================================================== 13:26:40 (1788629200) [ 4953.660912] Lustre: DEBUG MARKER: == sanity-lfsck test 31g: Repair the corrupted slave LMV EA ========================================================== 13:26:53 (1788629213) [ 4993.796804] Lustre: DEBUG MARKER: == sanity-lfsck test 31h: Repair the corrupted shard's name entry ========================================================== 13:27:33 (1788629253) [ 4995.339320] Lustre: *** cfs_fail_loc=162c, val=0*** [ 4995.341188] Lustre: Skipped 13 previous similar messages [ 5010.030427] Lustre: DEBUG MARKER: == sanity-lfsck test 32a: stop LFSCK when some OST failed ========================================================== 13:27:49 (1788629269) [ 5018.592072] LustreError: 148491:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d sleeping for 3000ms [ 5021.388392] Lustre: Failing over lustre-OST0000 [ 5021.478521] Lustre: server umount lustre-OST0000 complete [ 5021.665761] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 5021.681264] Lustre: lustre-OST0000-osc-MDT0000: Connection to lustre-OST0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 5021.682197] LustreError: 148491:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d awake [ 5021.689583] Lustre: Skipped 7 previous similar messages [ 5021.697728] LustreError: 125627:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 5021.699335] LustreError: 148491:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d sleeping for 3000ms [ 5021.733674] LustreError: 125627:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 22 previous similar messages [ 5024.439957] LustreError: 148491:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout interrupted [ 5035.113573] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 5035.249256] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 5037.224706] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 5037.257719] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 5037.261311] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 5037.271236] Lustre: Skipped 3 previous similar messages [ 5043.297283] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5053.898567] Lustre: DEBUG MARKER: == sanity-lfsck test 32b: stop LFSCK when some MDT failed ========================================================== 13:28:33 (1788629313) [ 5070.563459] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing load_modules_local [ 5089.801180] Lustre: 151297:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 5114.389226] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5118.066911] Lustre: 152432:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 5129.231823] LustreError: 152547:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d sleeping for 3000ms [ 5132.165810] Lustre: Failing over lustre-MDT0001 [ 5132.305346] LustreError: 152546:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d awake [ 5132.322251] LustreError: 152546:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) Skipped 1 previous similar message [ 5132.333318] LustreError: lustre-MDT0001-osp-MDT0000: operation out_update to node 0@lo failed: rc = -107 [ 5132.334190] LustreError: 152546:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d sleeping for 3000ms [ 5132.338041] LustreError: Skipped 1 previous similar message [ 5132.338079] 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 [ 5132.338083] Lustre: Skipped 1 previous similar message [ 5132.338756] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 5132.400773] LustreError: 152546:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) Skipped 1 previous similar message [ 5132.593400] Lustre: server umount lustre-MDT0001 complete [ 5135.378815] LustreError: 152546:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d awake [ 5147.689926] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 5147.988974] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 5147.991906] Lustre: Skipped 3 previous similar messages [ 5148.017604] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 5153.261224] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 1 client reconnects [ 5153.269419] Lustre: lustre-MDT0001-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 5153.292699] Lustre: Skipped 1 previous similar message [ 5153.314232] Lustre: lustre-MDT0001: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 5153.384374] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:69 to 0x2c0000400:97) [ 5153.385481] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:70 to 0x280000400:97) [ 5153.773911] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5164.665445] Lustre: DEBUG MARKER: == sanity-lfsck test 33: check LFSCK paramters =========== 13:30:23 (1788629423) [ 5178.078516] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing load_modules_local [ 5197.807137] Lustre: 155267:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 5221.182817] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5225.456987] Lustre: 156402:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 5231.596603] Lustre: 124126:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 256 < left 264, rollback = 2 [ 5231.605097] Lustre: 124126:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 1462 previous similar messages [ 5231.611404] Lustre: 124126:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/2, destroy: 0/0/0 [ 5231.616850] Lustre: 124126:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1462 previous similar messages [ 5231.624079] Lustre: 124126:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 3/264/0 [ 5231.630630] Lustre: 124126:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1462 previous similar messages [ 5231.643090] Lustre: 124127:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 5231.649823] Lustre: 124127:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1464 previous similar messages [ 5231.660074] Lustre: 132649:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 5231.666036] Lustre: 132649:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1466 previous similar messages [ 5231.685297] Lustre: 124127:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 5231.692270] Lustre: 124127:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1470 previous similar messages [ 5245.402158] Lustre: DEBUG MARKER: == sanity-lfsck test 34: LFSCK can rebuild the lost agent object ========================================================== 13:31:45 (1788629505) [ 5247.057762] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_34 Only valid for ZFS backend [ 5249.229505] Lustre: DEBUG MARKER: == sanity-lfsck test 35: LFSCK can rebuild the lost agent entry ========================================================== 13:31:48 (1788629508) [ 5256.213986] Lustre: *** cfs_fail_loc=1631, val=0*** [ 5271.013841] 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 [ 5271.025853] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 5271.029906] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5271.033444] Lustre: Skipped 4 previous similar messages [ 5282.272522] Lustre: lustre-MDT0000 is waiting for obd_unlinked_exports more than 8 seconds. The obd refcount = 3. Is it stuck? [ 5282.543173] Lustre: server umount lustre-MDT0000 complete [ 5286.069380] LustreError: 140749:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788629547 with bad export cookie 2730095595440720382 [ 5286.070165] LustreError: MGC192.168.201.117@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5286.080453] LustreError: 140749:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 5286.301404] Lustre: server umount lustre-MDT0001 complete [ 5300.242231] Lustre: server umount lustre-OST0000 complete [ 5302.735281] Lustre: 107028:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788629547/real 1788629547] req@ffff8e8ccad50000 x1875512344041728/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788629563 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5304.300845] Lustre: server umount lustre-OST0001 complete [ 5322.592481] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing load_modules_local [ 5334.467434] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5335.051627] LustreError: 159160:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 5335.089126] LustreError: 159160:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 13 previous similar messages [ 5340.402709] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5350.648081] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5350.880669] Lustre: lustre-MDT0001: Not available for connect from 0@lo (not set up) [ 5350.926125] Lustre: Skipped 11 previous similar messages [ 5357.178247] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5360.502407] Lustre: 160300:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 5368.569831] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5375.771936] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5376.108646] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:70 to 0x280000400:129) [ 5380.207990] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:540 to 0x280000401:577) [ 5384.851861] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5390.328551] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:412 to 0x2c0000401:449) [ 5390.331262] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:69 to 0x2c0000400:129) [ 5392.005908] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5399.551456] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5402.923099] Lustre: 162168:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 5414.155716] Lustre: DEBUG MARKER: == sanity-lfsck test 36a: rebuild LOV EA for mirrored file (1) ========================================================== 13:34:33 (1788629673) [ 5415.982886] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36a needs >= 3 OSTs [ 5418.760599] Lustre: DEBUG MARKER: == sanity-lfsck test 36b: rebuild LOV EA for mirrored file (2) ========================================================== 13:34:37 (1788629677) [ 5420.377384] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36b needs >= 3 OSTs [ 5422.249902] Lustre: DEBUG MARKER: == sanity-lfsck test 36c: rebuild LOV EA for mirrored file (3) ========================================================== 13:34:41 (1788629681) [ 5423.586450] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36c needs >= 3 OSTs [ 5425.578048] Lustre: DEBUG MARKER: == sanity-lfsck test 37: LFSCK must skip a ORPHAN ======== 13:34:44 (1788629684) [ 5438.282586] Lustre: DEBUG MARKER: == sanity-lfsck test 38: LFSCK does not break foreign file and reverse is also true ========================================================== 13:34:57 (1788629697) [ 5454.058564] Lustre: DEBUG MARKER: == sanity-lfsck test 39: LFSCK does not break foreign dir and reverse is also true ========================================================== 13:35:13 (1788629713) [ 5468.828236] Lustre: DEBUG MARKER: == sanity-lfsck test 40a: LFSCK correctly fixes lmm_oi in composite layout ========================================================== 13:35:28 (1788629728) [ 5485.081843] Lustre: DEBUG MARKER: == sanity-lfsck test 41: SEL support in LFSCK ============ 13:35:44 (1788629744) [ 5507.347747] Lustre: DEBUG MARKER: == sanity-lfsck test 42: LFSCK repairs inconsistent MDT-object/OST-object encryption flags ========================================================== 13:36:06 (1788629766) [ 5541.795294] Lustre: *** cfs_fail_loc=1632, val=0*** [ 5560.027345] Lustre: DEBUG MARKER: == sanity-lfsck test 43: LFSCK does not loop endlessly on iget failure in scanning-phase1 ========================================================== 13:36:58 (1788629818) [ 5563.451131] Lustre: Failing over lustre-MDT0001 [ 5563.869796] Lustre: server umount lustre-MDT0001 complete [ 5564.385475] Lustre: lustre-MDT0001-lwp-OST0000: Connection to lustre-MDT0001 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 5564.406255] Lustre: Skipped 3 previous similar messages [ 5572.678060] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5573.075089] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 5573.075810] Lustre: lustre-MDT0001: Aborting client recovery [ 5573.095963] LustreError: 165958:0:(ldlm_lib.c:3029:target_stop_recovery_thread()) lustre-MDT0001: Aborting recovery [ 5573.098323] LustreError: 165980:0:(lod_dev.c:511:lod_sub_recovery_thread()) lustre-MDT0001-osd: get update log duration 0, retries 0, failed: rc = -108 [ 5573.104111] Lustre: 165982:0:(ldlm_lib.c:2429:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 5573.138993] Lustre: 165982:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0001: disconnect stale client 65ac48e3-9dae-410a-b499-7f9667d7399e@ [ 5573.147781] Lustre: lustre-MDT0001: disconnecting 2 stale clients [ 5573.157522] Lustre: lustre-MDT0001-osd: cancel update llog [0x240000400:0x1:0x0] [ 5573.170788] Lustre: lustre-MDT0000-osp-MDT0001: cancel update llog [0x200000401:0x1:0x0] [ 5573.217871] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:131 to 0x280000400:161) [ 5573.228411] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:69 to 0x2c0000400:161) [ 5578.214058] LustreError: lustre-MDT0001-osp-MDT0000: This client was evicted by lustre-MDT0001; in progress operations using this service will fail. [ 5578.221635] Lustre: lustre-MDT0001-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 5578.224506] Lustre: Skipped 2 previous similar messages [ 5578.555332] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5588.195805] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing wait_import_state FULL osp.lustre-MDT0001-os[pc]-MDT0000.*_server_uuid [ 5588.651645] Lustre: DEBUG MARKER: osp.lustre-MDT0001-os[pc]-MDT0000.*_server_uuid in FULL state after 0 sec [ 5596.816537] Lustre: DEBUG MARKER: == sanity-lfsck test 44: umount while lfsck is stopping == 13:37:36 (1788629856) [ 5605.904549] Lustre: *** cfs_fail_loc=1600, val=3*** [ 5609.280130] Lustre: Failing over lustre-MDT0000 [ 5609.300910] LustreError: lustre-MDT0000-osp-MDT0001: operation out_update to node 0@lo failed: rc = -107 [ 5609.310279] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5611.707929] Lustre: server umount lustre-MDT0000 complete [ 5623.311789] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5623.640558] LustreError: MGC192.168.201.117@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5624.215410] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 5624.228942] Lustre: Skipped 2 previous similar messages [ 5627.478923] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 5629.424755] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 5629.435047] Lustre: Skipped 2 previous similar messages [ 5629.485075] Lustre: lustre-MDT0000: Recovery over after 0:02, of 2 clients 2 recovered and 0 were evicted. [ 5629.592199] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:489 to 0x2c0000401:513) [ 5629.594797] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:621 to 0x280000401:641) [ 5630.063502] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5641.078802] Lustre: DEBUG MARKER: == sanity-lfsck test 45: LFSCK should fix UID/GID/PROJID of OST object ========================================================== 13:38:20 (1788629900) [ 5688.834722] Lustre: Failing over lustre-OST0001 [ 5688.918637] Lustre: server umount lustre-OST0001 complete [ 5690.848459] LustreError: lustre-OST0001-osc-MDT0001: operation ost_statfs to node 0@lo failed: rc = -107 [ 5695.858510] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: (null) [ 5708.283770] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5708.584308] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 5708.591790] Lustre: Skipped 6 previous similar messages [ 5708.602553] Lustre: lustre-OST0001: in recovery but waiting for the first client to connect [ 5709.417533] Lustre: lustre-OST0001: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 5710.279685] Lustre: lustre-OST0001: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [ 5710.290154] Lustre: lustre-OST0001-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 5710.307203] Lustre: Skipped 3 previous similar messages [ 5715.730118] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5723.103966] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing wait_import_state (FULL|IDLE) os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid 50 [ 5723.470281] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid in FULL state after 0 sec [ 5727.920542] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing wait_import_state (FULL|IDLE) os[cp].lustre-OST0000-osc-MDT0001.ost_server_uuid 50 [ 5728.105692] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0001.ost_server_uuid in FULL state after 0 sec [ 5734.137769] Lustre: DEBUG MARKER: oleg117-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0000-osc-ffff9d64c98d8800.ost_server_uuid 50 [ 5735.698729] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9d64c98d8800.ost_server_uuid in FULL state after 0 sec [ 5821.408597] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5821.412600] Lustre: Skipped 1 previous similar message [ 5825.452292] Lustre: server umount lustre-MDT0000 complete [ 5834.243410] LustreError: 159141:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788630095 with bad export cookie 2730095595440803332 [ 5834.250752] LustreError: MGC192.168.201.117@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5834.254402] LustreError: 159141:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 5834.590328] Lustre: server umount lustre-MDT0001 complete [ 5852.127917] Lustre: 107028:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788630097/real 1788630097] req@ffff8e8ccd5e2680 x1875512344468992/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788630113 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5853.407725] Lustre: server umount lustre-OST0000 complete [ 5855.200406] Lustre: 107030:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788630100/real 1788630100] req@ffff8e8cc3b2fb80 x1875512344469248/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788630116 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5857.319799] Lustre: 107028:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788630102/real 1788630102] req@ffff8e8ccf273800 x1875512344469504/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788630118 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5861.684376] Lustre: server umount lustre-OST0001 complete [ 5879.050217] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing unload_modules_local [ 5881.856093] Key type lgssc unregistered [ 5882.110723] LNet: 175708:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 5882.116319] LNetError: 175708:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 5882.141992] LNet: Removed LNI 192.168.201.117@tcp [ 5883.081142] Key type .llcrypt unregistered [ 5883.082784] Key type ._llcrypt unregistered [ 5906.899516] Key type ._llcrypt registered [ 5906.901863] Key type .llcrypt registered [ 5907.010642] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_hostid [ 5922.825536] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing load_modules_local [ 5923.471629] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 5923.492477] alg: No test for adler32 (adler32-zlib) [ 5924.792634] Lustre: Lustre: Build Version: 2.17.58_2_g69c2166 [ 5925.142979] LNet: Added LNI 192.168.201.117@tcp [8/256/0/180] [ 5926.847327] Key type lgssc registered [ 5927.933612] Lustre: Echo OBD driver; http://www.lustre.org/ [ 5978.909633] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing load_modules_local [ 5993.155869] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 5993.194985] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5994.386697] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 5994.481621] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 5994.630992] Lustre: lustre-MDT0000: new disk, initializing [ 5994.740489] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 5994.786356] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 5999.438699] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6013.458197] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 6013.653531] Lustre: 180160: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 [ 6013.753202] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 6013.775222] Lustre: Skipped 1 previous similar message [ 6013.998509] Lustre: lustre-MDT0001: new disk, initializing [ 6014.144093] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 6014.216284] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 6014.269134] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 6019.235202] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6025.040425] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 6035.158514] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 6035.530628] Lustre: lustre-OST0000: new disk, initializing [ 6035.534934] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 6035.546074] Lustre: 182098:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 6035.670205] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 6042.787419] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6045.242512] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 6045.254081] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 6045.329959] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 6058.239292] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 6058.539402] Lustre: lustre-OST0001: new disk, initializing [ 6058.542934] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 6058.551250] Lustre: 183122:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 6058.668126] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 6065.708256] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 6065.716528] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 6065.820158] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 6067.254252] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6080.104520] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 6086.223069] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 6093.423537] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 13:45:52 (1788630352) === [ 6095.364939] Lustre: DEBUG MARKER: == sanity-lfsck test complete, duration 5826 sec ========= 13:45:54 (1788630354) [ 6097.196647] Lustre: DEBUG MARKER: === sanity-lfsck: start cleanup 13:45:56 (1788630356) === [ 6101.061054] Lustre: DEBUG MARKER: === sanity-lfsck: finish cleanup 13:46:00 (1788630360) === [ 6106.633884] 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 [ 6106.644640] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 6106.645068] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 6106.649989] Lustre: Skipped 2 previous similar messages [ 6111.712228] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 6111.725510] Lustre: Skipped 6 previous similar messages [ 6112.267467] Lustre: server umount lustre-MDT0000 complete [ 6121.210458] LustreError: 180152:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788630382 with bad export cookie 18266819925440038930 [ 6121.228274] LustreError: MGC192.168.201.117@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 6121.656068] Lustre: server umount lustre-MDT0001 complete [ 6138.271530] Lustre: 177320:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788630383/real 1788630383] req@ffff8e8ccaccad80 x1875514686000512/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788630399 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6138.322844] 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 [ 6141.503857] Lustre: server umount lustre-OST0000 complete [ 6143.455183] Lustre: 177317:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788630388/real 1788630388] req@ffff8e8ccd85b480 x1875514686000768/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788630404 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6147.488280] Lustre: 177320:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788630392/real 1788630392] req@ffff8e8ccdf74a80 x1875514686001152/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788630408 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6150.300860] Lustre: server umount lustre-OST0001 complete [ 6168.328203] Lustre: DEBUG MARKER: oleg117-server.virtnet: executing unload_modules_local [ 6171.465946] Key type lgssc unregistered [ 6171.710587] LNet: 186595:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 6171.736138] LNetError: 186595:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 6172.776525] LNet: Removed LNI 192.168.201.117@tcp [ 6174.151310] Key type .llcrypt unregistered [ 6174.154714] Key type ._llcrypt unregistered