[ 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 547309169 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2399.980 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, 524580K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] ftrace: allocating 41240 entries in 162 pages [ 0.000000] ftrace: allocated 162 pages with 3 groups [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] rcu: RCU event tracing is enabled. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ 0.000000] rcu: RCU callback double-/use-after-free debug enabled. [ 0.000000] Rude variant of Tasks RCU enabled. [ 0.000000] Tracing variant of Tasks RCU enabled. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 0.000000] NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16 [ 0.000000] random: get_random_bytes called from start_kernel+0x622/0x9a8 with crng_init=0 [ 0.001000] Console: colour *CGA 80x25 [ 0.001000] printk: console [ttyS1] enabled [ 0.001000] ACPI: Core revision 20220331 [ 0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.001009] APIC: Switch to symmetric I/O mode setup [ 0.002370] x2apic enabled [ 0.003010] Switched APIC routing to physical x2apic. [ 0.004015] kvm-guest: setup PV IPIs [ 0.006995] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.007000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x22982479f67, max_idle_ns: 440795221274 ns [ 0.007020] Calibrating delay loop (skipped) preset value.. 4799.96 BogoMIPS (lpj=2399980) [ 0.008015] pid_max: default: 32768 minimum: 301 [ 0.009129] LSM: Security Framework initializing [ 0.010059] Yama: becoming mindful. [ 0.011031] SELinux: Initializing. [ 0.013073] *** VALIDATE selinux *** [ 0.023514] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.028507] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.029140] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.030112] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.031111] *** VALIDATE tmpfs *** [ 0.033039] *** VALIDATE proc *** [ 0.034390] *** VALIDATE cgroup *** [ 0.035010] *** VALIDATE cgroup2 *** [ 0.036259] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.037152] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.038009] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.039028] Spectre V2 : User space: Vulnerable [ 0.040008] Speculative Store Bypass: Vulnerable [ 0.043612] debug: unmapping init [mem 0xffffffffab859000-0xffffffffab860fff] [ 0.046000] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.046901] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.047023] ... version: 2 [ 0.048013] ... bit width: 48 [ 0.049011] ... generic registers: 4 [ 0.050010] ... value mask: 0000ffffffffffff [ 0.051014] ... max period: 00007fffffffffff [ 0.052013] ... fixed-purpose events: 3 [ 0.053012] ... event mask: 000000070000000f [ 0.054296] rcu: Hierarchical SRCU implementation. [ 0.056378] smp: Bringing up secondary CPUs ... [ 0.057938] x86: Booting SMP configuration: [ 0.058026] .... node #0, CPUs: #1 #2 #3 [ 0.069275] smp: Brought up 1 node, 4 CPUs [ 0.071015] smpboot: Max logical packages: 1 [ 0.072013] smpboot: Total of 4 processors activated (19199.84 BogoMIPS) [ 0.101784] node 0 deferred pages initialised in 28ms [ 0.106035] devtmpfs: initialized [ 0.107249] x86/mm: Memory block size: 128MB [ 0.110296] gcov: version magic: 0x41383552 [ 0.112070] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.113070] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.114235] pinctrl core: initialized pinctrl subsystem [ 0.115301] [ 0.115854] ************************************************************* [ 0.116013] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.117013] ** ** [ 0.118012] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.119015] ** ** [ 0.120015] ** This means that this kernel is built to expose internal ** [ 0.121013] ** IOMMU data structures, which may compromise security on ** [ 0.122015] ** your system. ** [ 0.123014] ** ** [ 0.124010] ** If you see this message and you are not debugging the ** [ 0.125062] ** kernel, report this immediately to your vendor! ** [ 0.126013] ** ** [ 0.127012] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.128011] ************************************************************* [ 0.129860] NET: Registered protocol family 16 [ 0.132423] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.135056] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.138070] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.143008] cpuidle: using governor menu [ 0.145000] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.148856] PCI: Using configuration type 1 for base access [ 0.151122] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.159019] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.160019] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.162018] cryptd: max_cpu_qlen set to 1000 [ 0.164354] ACPI: Added _OSI(Module Device) [ 0.165000] ACPI: Added _OSI(Processor Device) [ 0.165000] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.167015] ACPI: Added _OSI(Processor Aggregator Device) [ 0.172557] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.181607] ACPI: Interpreter enabled [ 0.183059] ACPI: PM: (supports S0 S3 S4 S5) [ 0.184013] ACPI: Using IOAPIC for interrupt routing [ 0.187132] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.191718] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.207498] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.210043] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.213018] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.217079] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.222613] acpiphp: Slot [2] registered [ 0.225156] acpiphp: Slot [5] registered [ 0.226169] acpiphp: Slot [6] registered [ 0.228351] acpiphp: Slot [7] registered [ 0.230144] acpiphp: Slot [8] registered [ 0.231249] acpiphp: Slot [9] registered [ 0.233139] acpiphp: Slot [10] registered [ 0.235143] acpiphp: Slot [3] registered [ 0.237090] acpiphp: Slot [4] registered [ 0.239091] acpiphp: Slot [11] registered [ 0.240279] acpiphp: Slot [12] registered [ 0.242136] acpiphp: Slot [13] registered [ 0.244118] acpiphp: Slot [14] registered [ 0.246121] acpiphp: Slot [15] registered [ 0.248128] acpiphp: Slot [16] registered [ 0.250096] acpiphp: Slot [17] registered [ 0.252091] acpiphp: Slot [18] registered [ 0.253101] acpiphp: Slot [19] registered [ 0.255110] acpiphp: Slot [20] registered [ 0.257087] acpiphp: Slot [21] registered [ 0.258107] acpiphp: Slot [22] registered [ 0.260103] acpiphp: Slot [23] registered [ 0.262102] acpiphp: Slot [24] registered [ 0.263118] acpiphp: Slot [25] registered [ 0.265124] acpiphp: Slot [26] registered [ 0.267150] acpiphp: Slot [27] registered [ 0.269065] acpiphp: Slot [28] registered [ 0.269893] acpiphp: Slot [29] registered [ 0.270068] acpiphp: Slot [30] registered [ 0.270958] acpiphp: Slot [31] registered [ 0.272067] PCI host bridge to bus 0000:00 [ 0.273011] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.276224] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.279022] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.281022] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.284024] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.287026] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.289171] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.292045] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.295502] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.304012] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.309752] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.312015] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.313011] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.315012] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.317528] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.321080] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.323087] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.326686] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.332013] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.349016] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.356013] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.362405] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.372016] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.380022] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.396017] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.414266] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.425016] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.437397] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.459024] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.468701] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.483016] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.493019] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.529016] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.544998] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.554017] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.561017] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.577019] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.587000] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.602221] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.613017] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.631016] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 0.653000] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.665017] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.694020] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.745020] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 0.771607] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.774399] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.777381] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.779364] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.782233] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.787107] iommu: Default domain type: Passthrough [ 0.788413] SCSI subsystem initialized [ 0.789183] ACPI: bus type USB registered [ 0.790095] usbcore: registered new interface driver usbfs [ 0.793081] usbcore: registered new interface driver hub [ 0.795099] usbcore: registered new device driver usb [ 0.797612] pps_core: LinuxPPS API ver. 1 registered [ 0.800013] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.804064] PTP clock support registered [ 0.805393] EDAC MC: Ver: 3.0.0 [ 0.806144] PCI: Using ACPI for IRQ routing [ 0.807000] NetLabel: Initializing [ 0.809013] NetLabel: domain hash size = 128 [ 0.812013] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.815085] NetLabel: unlabeled traffic allowed by default [ 0.818066] vgaarb: loaded [ 0.819613] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.822014] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.829188] clocksource: Switched to clocksource kvm-clock [ 0.950328] VFS: Disk quotas dquot_6.6.0 [ 0.952282] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.955372] *** VALIDATE ramfs *** [ 0.956787] *** VALIDATE hugetlbfs *** [ 0.958329] pnp: PnP ACPI init [ 0.960931] pnp: PnP ACPI: found 6 devices [ 0.979900] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.984293] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.987185] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.989828] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.992691] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.995396] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.998361] NET: Registered protocol family 2 [ 1.000993] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 1.006540] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 1.010886] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 1.016172] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 1.020807] TCP: Hash tables configured (established 65536 bind 65536) [ 1.023366] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 1.026739] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 1.030503] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 1.034098] NET: Registered protocol family 1 [ 1.036832] RPC: Registered named UNIX socket transport module. [ 1.039268] RPC: Registered udp transport module. [ 1.041470] RPC: Registered tcp transport module. [ 1.043521] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 1.046173] NET: Registered protocol family 44 [ 1.048338] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 1.051225] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 1.054255] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 1.057299] PCI: CLS 0 bytes, default 64 [ 1.059514] Unpacking initramfs... [ 2.906549] debug: unmapping init [mem 0xffff9c8f7cc54000-0xffff9c8f7ffbffff] [ 2.911720] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.914219] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.917467] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x22982479f67, max_idle_ns: 440795221274 ns [ 3.706728] Initialise system trusted keyrings [ 3.708649] Key type blacklist registered [ 3.714723] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 3.725786] zbud: loaded [ 3.729619] *** VALIDATE nfs *** [ 3.732026] *** VALIDATE nfs4 *** [ 3.737055] pstore: using deflate compression [ 3.773035] Platform Keyring initialized [ 3.927797] NET: Registered protocol family 38 [ 3.930094] Key type asymmetric registered [ 3.932148] Asymmetric key parser 'x509' registered [ 3.934660] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 3.938883] io scheduler mq-deadline registered [ 3.940782] io scheduler kyber registered [ 3.942834] io scheduler bfq registered [ 3.945211] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 3.949577] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 3.952856] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 3.955955] ACPI: Power Button [PWRF] [ 3.962731] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 3.971712] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 3.986544] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 3.995557] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 4.015587] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 4.048644] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 4.081262] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 4.086628] Non-volatile memory driver v1.3 [ 4.089099] Linux agpgart interface v0.103 [ 4.124471] virtio_blk virtio1: [vda] 134768 512-byte logical blocks (69.0 MB/65.8 MiB) [ 4.127583] vda: detected capacity change from 0 to 69001216 [ 4.147530] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 4.150801] vdb: detected capacity change from 0 to 1073741824 [ 4.183786] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 4.187317] vdc: detected capacity change from 0 to 2621440000 [ 4.211903] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 4.215785] vdd: detected capacity change from 0 to 2621440000 [ 4.235463] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 4.240028] vde: detected capacity change from 0 to 4294967296 [ 4.259539] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 4.263845] vdf: detected capacity change from 0 to 4294967296 [ 4.273427] libphy: Fixed MDIO Bus: probed [ 4.287209] usbcore: registered new interface driver usbserial_generic [ 4.290321] usbserial: USB Serial support registered for generic [ 4.293412] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 4.305905] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 4.308828] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 4.314323] mousedev: PS/2 mouse device common for all mice [ 4.318430] rtc_cmos 00:05: RTC can wake from S4 [ 4.323276] rtc_cmos 00:05: registered as rtc0 [ 4.326485] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 4.330024] intel_pstate: CPU model not supported [ 4.331954] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 4.341350] hid: raw HID events driver (C) Jiri Kosina [ 4.348745] usbcore: registered new interface driver usbhid [ 4.349820] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 4.353047] usbhid: USB HID core driver [ 4.353209] drop_monitor: Initializing network drop monitor service [ 4.353345] Initializing XFRM netlink socket [ 4.353822] NET: Registered protocol family 10 [ 4.357415] Segment Routing with IPv6 [ 4.360285] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 4.362043] NET: Registered protocol family 17 [ 4.362789] mpls_gso: MPLS GSO support [ 4.376338] RAS: Correctable Errors collector initialized. [ 4.378461] AVX version of gcm_enc/dec engaged. [ 4.379903] AES CTR mode by8 optimization enabled [ 4.468633] sched_clock: Marking stable (4468613187, 0)->(5630181002, -1161567815) [ 4.472523] registered taskstats version 1 [ 4.474863] Loading compiled-in X.509 certificates [ 4.478178] zswap: loaded using pool lzo/zbud [ 4.519847] Key type big_key registered [ 4.535802] Key type encrypted registered [ 4.537635] ima: No TPM chip found, activating TPM-bypass! [ 4.539659] ima: Allocated hash algorithm: sha1 [ 4.541658] ima: No architecture policies found [ 4.543898] evm: Initialising EVM extended attributes: [ 4.545927] evm: security.selinux [ 4.547256] evm: security.ima [ 4.548497] evm: security.capability [ 4.550354] evm: HMAC attrs: 0x1 [ 4.553525] rtc_cmos 00:05: setting system clock to 2026-05-25 05:34:36 UTC (1779687276) [ 4.562648] debug: unmapping init [mem 0xffffffffac803000-0xffffffffac9fffff] [ 4.566111] debug: unmapping init [mem 0xffffffffab582000-0xffffffffab858fff] [ 4.574353] Write protecting the kernel read-only data: 28672k [ 4.578935] debug: unmapping init [mem 0xffffffffa9c03000-0xffffffffa9dfffff] [ 4.582288] debug: unmapping init [mem 0xffffffffaa514000-0xffffffffaa5fffff] [ 4.620936] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 4.630330] systemd[1]: Detected virtualization kvm. [ 4.632552] systemd[1]: Detected architecture x86-64. [ 4.634925] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 4.666347] systemd[1]: No hostname configured. [ 4.668186] systemd[1]: Set hostname to . [ 4.670351] random: systemd: uninitialized urandom read (16 bytes read) [ 4.673112] systemd[1]: Initializing machine ID from random generator. [ 4.823236] random: ln: uninitialized urandom read (6 bytes read) [ 5.012300] random: systemd: uninitialized urandom read (16 bytes read) [ 5.015341] systemd[1]: Listening on udev Kernel Socket. [ OK ] Listening on udev Kernel Socket. [ 5.020512] systemd[1]: Reached target Local File Systems. [ OK ] Reached target Local File Systems. [ 5.029399] systemd[1]: Listening on Journal Socket. [ OK ] Listening on Journal Socket. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Reached target Initrd Root Device. [ OK ] Reached target Slices. [ OK ] Listening on udev Control Socket. [ OK ] Reached target Timers. [ OK ] Listening on Journal Socket (/dev/log). [ OK ] Reached target Sockets. Starting Create Volatile Files and Directories... Starting Journal Service... [ OK ] Started Memstrack Anylazing Service. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. Starting Setup Virtual Console... Starting Apply Kernel Variables... [ OK ] Reached target Swap. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Setup Virtual Console. [ OK ] Started Apply Kernel Variables. Starting dracut cmdline hook... Starting Create Static Device Nodes in /dev... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started Journal Service. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 6.223524] device-mapper: uevent: version 1.0.3 [ 6.226367] device-mapper: ioctl: 4.46.0-ioctl (2022-02-22) initialised: dm-devel@redhat.com [ OK ] Started dracut pre-udev hook. Starting udev Kernel Device Manager... [ OK ] Started udev Kernel Device Manager. Starting dracut pre-trigger hook... [ OK ] Started dracut pre-trigger hook. Starting udev Coldplug all Devices... Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. Starting dracut initqueue hook... [ 7.773383] random: fast init done [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ 7.916156] virtio_net virtio0 ens2: renamed from eth0 [ 8.884367] scsi host0: ata_piix [ 8.901280] scsi host1: ata_piix [ 8.909394] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 8.919606] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 15.152792] random: crng init done [ 15.154653] random: 7 urandom warning(s) missed due to ratelimiting [ 16.056918] dracut-initqueue[587]: RTNETLINK answers: File exists Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Mounting /sysroot... [ 18.162389] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped target Timers. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Slices. [ OK ] Stopped target Paths. [ OK ] Stopped target Sockets. [ OK ] Stopped target System Initialization. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped target Swap. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. Stopping udev Kernel Device Manager... [ OK ] Stopped target Local File Systems. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Closed udev Kernel Socket. [ OK ] Closed udev Control Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 20.405588] printk: systemd: 26 output lines suppressed due to ratelimiting [ 20.807477] SELinux: Disabled at runtime. [ 20.872503] 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) [ 20.881712] systemd[1]: Detected virtualization kvm. [ 20.883592] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 21.871820] systemd[1]: initrd-switch-root.service: Succeeded. [ 21.911378] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 21.927655] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 21.932588] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 21.937666] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 21.953273] systemd[1]: Starting Journal Service... Starting Journal Service... [ 21.966298] systemd[1]: Listening on initctl Compatibility Named Pipe. [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Created slice system-getty.slice. [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Listening on Process Core Dump Socket. [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Reached target RPC Port Mapper. Mounting POSIX Message Queue File System... Activating swap /dev/disk/by-label/SWAP... Starting Remount Root and Kernel File Systems... Starting Apply Kernel Variables... Mounting Huge Pages File System... [ 22.839304] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS Mounting Kernel Debug File System... [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Reached target Paths. [ OK ] Listening on udev Kernel Socket. [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd File Systems. [ OK ] Stopped target Initrd Root File System. [ OK ] Created slice User and Session Slice. [ OK ] Reached target Slices. [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target rpc_pipefs.target. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Listening on udev Control Socket. Starting udev Coldplug all Devices... [ OK ] Started Journal Service. [ OK ] Mounted POSIX Message Queue File System. [ 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 Apply Kernel Variables. [ OK ] Mounted Huge Pages File System. [ OK ] Mounted Kernel Debug File System. [ OK ] Started Create list of required sta…vice nodes for the current kernel. 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 udev Coldplug all Devices. [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. Starting udev Kernel Device Manager... [ OK ] Reached target Local File Systems (Pre). Mounting /home/green/git/lustre-release... Mounting /mnt... [ OK ] Mounted /mnt. [ 24.660346] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 26.859087] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 26.950934] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 27.753404] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 28.089184] EDAC sbridge: Ver: 1.1.2 [* ] A start job is running for Configur…-only root support (9s / no limit) [** ] A start job is running for Configur…only root support (10s / no limit) [*** ] A start job is running for Configur…only root support (11s / no limit)[ 33.010479] Key type dns_resolver registered [ 33.404428] NFS: Registering the id_resolver key type [ 33.406775] Key type id_resolver registered [ 33.408972] Key type id_legacy registered [ *** ] A start job is running for Configur…only root support (11s / no limit) [ OK ] Started Configure read-only root support. [ OK ] Reached target Local File Systems. Starting Mark the need to relabel after reboot... Starting Rebuild Dynamic Linker Cache... Starting Create Volatile Files and Directories... Starting Load/Save Random Seed... [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Load/Save Random Seed. Starting RPC Bind... Starting Update UTMP about System Boot/Shutdown... [ OK ] Started RPC Bind. [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Started dnf makecache --timer. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Reached target Timers. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. Starting Restore /run/initramfs on shutdown... [ OK ] Started irqbalance daemon. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Reached target sshd-keygen.target. [ OK ] Started D-Bus System Message Bus. Starting Network Manager... Starting Login Service... [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Network Manager. [ OK ] Started Login Service. Starting Hostname Service... [ OK ] Reached target Network. Starting GSSAPI Proxy Daemon... Starting Dynamic System Tuning Daemon... Starting OpenSSH server daemon... Starting Network Manager Wait Online... [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Started OpenSSH server 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 Command Scheduler. [ OK ] Started Getty on tty1. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Serial Getty on ttyS1. [ OK ] Reached target Login Prompts. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting System Logging Service... Starting Crash recovery kernel arming... Starting Notify NFS peers of a restart... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg122-server login: [ 87.077481] hrtimer: interrupt took 9532404 ns [ 112.722375] libcfs: loading out-of-tree module taints kernel. [ 112.814535] Key type ._llcrypt registered [ 112.818808] Key type .llcrypt registered [ 112.929450] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_hostid [ 137.472324] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing load_modules_local [ 139.699937] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 139.726726] alg: No test for adler32 (adler32-zlib) [ 141.394964] Lustre: Lustre: Build Version: 2.17.53_24_g1d9adb4 [ 142.719792] LNet: Added LNI 192.168.201.122@tcp [8/256/0/180] [ 144.615760] Key type lgssc registered [ 146.919124] Lustre: Echo OBD driver; http://www.lustre.org/ [ 169.564360] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 224.759480] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing load_modules_local [ 241.929647] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 241.973472] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 243.398853] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 243.466143] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 243.621485] Lustre: lustre-MDT0000: new disk, initializing [ 243.760604] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 243.794689] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 249.444105] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 266.194776] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 266.394612] Lustre: 6519:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 266.436188] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 266.448571] Lustre: Skipped 1 previous similar message [ 266.585593] Lustre: lustre-MDT0001: new disk, initializing [ 266.680050] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 266.723511] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 266.739395] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 272.641357] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 278.075597] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 289.396447] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 289.705873] Lustre: lustre-OST0000: new disk, initializing [ 289.709439] Lustre: lustre-OST0000: Not available for connect from 0@lo (not set up) [ 289.713644] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 289.720660] Lustre: 8426:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 289.770647] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 294.969927] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 294.986666] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 295.020755] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000400 [ 297.151624] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 314.881028] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 314.987811] Lustre: lustre-OST0001: new disk, initializing [ 314.992723] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 315.003697] Lustre: 9483:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 315.090289] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 322.600731] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 322.617954] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 322.730689] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 322.872260] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 337.534433] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 348.813941] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 357.314770] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing check_logdir /tmp/testlogs/ [ 364.462723] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing yml_node [ 369.739884] Lustre: DEBUG MARKER: Client: 2.17.53.24 [ 373.473727] Lustre: DEBUG MARKER: MDS: 2.17.53.24 [ 377.925796] Lustre: DEBUG MARKER: OSS: 2.17.53.24 [ 380.674425] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity-lfsck ============----- Mon May 25 01:40:49 EDT 2026 [ 409.289074] Lustre: DEBUG MARKER: excepting tests: 18b 23b [ 422.765829] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing load_modules_local [ 435.681496] 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 [ 435.685197] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 435.727685] Lustre: Skipped 3 previous similar messages [ 435.739163] Lustre: Skipped 2 previous similar messages [ 435.744696] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 440.818640] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 440.839993] Lustre: Skipped 3 previous similar messages [ 441.352558] Lustre: server umount lustre-MDT0000 complete [ 451.042562] LustreError: 10144:0:(ldlm_lib.c:1179: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. [ 451.075251] LustreError: 10144:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 8 previous similar messages [ 452.953924] LustreError: 7450:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1779687724 with bad export cookie 17163832051262165183 [ 452.968306] LustreError: MGC192.168.201.122@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 452.972067] LustreError: 7450:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 453.596101] Lustre: server umount lustre-MDT0001 complete [ 472.735327] Lustre: 3664:0:(client.c:2480:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1779687728/real 1779687728] req@ffff9c8ff6a4ed80 x1866137509940864/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1779687744 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 472.778572] 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 [ 473.759386] Lustre: 3667:0:(client.c:2480:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1779687729/real 1779687729] req@ffff9c8fc4aef800 x1866137509941120/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1779687745 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 475.298619] Lustre: server umount lustre-OST0000 complete [ 477.919526] Lustre: 3664:0:(client.c:2480:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1779687733/real 1779687733] req@ffff9c8fc4aefb80 x1866137509941376/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1779687749 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 480.995649] Lustre: 3667:0:(client.c:2480:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1779687736/real 1779687736] req@ffff9c8ff69a3100 x1866137509942016/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1779687752 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 481.057942] Lustre: 3667:0:(client.c:2480:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 492.558765] Lustre: server umount lustre-OST0001 complete [ 515.583625] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing unload_modules_local [ 520.032704] Key type lgssc unregistered [ 520.448786] LNet: 14729:0:(lib-ptl.c:967:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 520.458842] LNetError: 14729:0:(acceptor.c:246:lnet_acceptor_remove_socket()) Interface ens2 not found [ 520.489317] LNet: Removed LNI 192.168.201.122@tcp [ 521.914301] Key type .llcrypt unregistered [ 521.920585] Key type ._llcrypt unregistered [ 553.731242] Key type ._llcrypt registered [ 553.733872] Key type .llcrypt registered [ 553.837357] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_hostid [ 573.742739] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing load_modules_local [ 575.146379] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 575.557354] alg: No test for adler32 (adler32-zlib) [ 576.816821] Lustre: Lustre: Build Version: 2.17.53_24_g1d9adb4 [ 577.202311] LNet: Added LNI 192.168.201.122@tcp [8/256/0/180] [ 578.975470] Key type lgssc registered [ 580.575725] Lustre: Echo OBD driver; http://www.lustre.org/ [ 647.538515] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing load_modules_local [ 665.417351] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 665.501755] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 666.985408] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 667.053323] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 667.185326] Lustre: lustre-MDT0000: new disk, initializing [ 667.369129] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 667.412535] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 672.689107] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 690.826288] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 691.024422] Lustre: 19141:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 691.084238] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 691.094635] Lustre: Skipped 1 previous similar message [ 691.317823] Lustre: lustre-MDT0001: new disk, initializing [ 691.449730] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 691.487942] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 691.510321] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 698.774985] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 706.634932] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 719.247632] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 719.521319] Lustre: lustre-OST0000: new disk, initializing [ 719.526543] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 719.534896] Lustre: 21048:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 719.672272] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 725.592874] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 725.618094] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 725.785307] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 729.204365] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 751.355369] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 751.550674] Lustre: lustre-OST0001: new disk, initializing [ 751.564107] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 751.582543] Lustre: 22057:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 751.685215] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 756.815117] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 756.844921] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 756.986900] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 760.916993] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 776.869505] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 786.272694] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 798.977249] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 01:47:47 (1779688067) === [ 805.270292] Lustre: DEBUG MARKER: == sanity-lfsck test 0: Control LFSCK manually =========== 01:47:52 (1779688072) [ 806.092167] Lustre: 19146:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 251 < left 278, rollback = 2 [ 806.110298] Lustre: 19146:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 806.134884] Lustre: 19146:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 806.155217] Lustre: 19146:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 806.171494] Lustre: 19146:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 806.191739] Lustre: 19146:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 806.696582] Lustre: 19146:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 806.705212] Lustre: 19146:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 5 previous similar messages [ 806.709675] Lustre: 19146:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 806.714198] Lustre: 19146:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 5 previous similar messages [ 806.719566] Lustre: 19146:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 806.726401] Lustre: 19146:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 5 previous similar messages [ 806.735228] Lustre: 19146:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 806.741359] Lustre: 19146:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 5 previous similar messages [ 806.746953] Lustre: 19146:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 806.757594] Lustre: 19146:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 5 previous similar messages [ 806.767102] Lustre: 19146:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 806.780436] Lustre: 19146:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 5 previous similar messages [ 807.707879] Lustre: 19147:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 807.728499] Lustre: 19147:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 29 previous similar messages [ 807.738791] Lustre: 19147:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 807.754640] Lustre: 19147:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 29 previous similar messages [ 807.770432] Lustre: 19147:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 807.786197] Lustre: 19147:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 29 previous similar messages [ 807.796645] Lustre: 19147:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 807.806816] Lustre: 19147:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 29 previous similar messages [ 807.816684] Lustre: 19147:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 807.834860] Lustre: 19147:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 29 previous similar messages [ 807.844367] Lustre: 19147:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 807.852629] Lustre: 19147:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 29 previous similar messages [ 809.730098] Lustre: 19148:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 809.741336] Lustre: 19148:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 104 previous similar messages [ 809.752202] Lustre: 19148:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 809.762730] Lustre: 19148:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 809.783752] Lustre: 19148:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 809.792118] Lustre: 19148:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 809.801184] Lustre: 19148:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 809.815710] Lustre: 19148:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 809.828056] Lustre: 19148:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 809.839672] Lustre: 19148:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 809.847884] Lustre: 19148:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 809.850862] Lustre: 19148:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 816.006192] Lustre: *** cfs_fail_loc=1600, val=3*** [ 816.967582] Lustre: 23229:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-OST0001: opcode 2: before 259 < left 274, rollback = 2 [ 816.977985] Lustre: 23229:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 140 previous similar messages [ 816.994119] Lustre: 23358:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 817.006551] Lustre: 23229:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/1, xattr_set: 2/274/0 [ 817.006563] Lustre: 23229:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 140 previous similar messages [ 817.006569] Lustre: 23229:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 0/0/0, punch: 0/0/0, quota 7/225/0 [ 817.006571] Lustre: 23229:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 140 previous similar messages [ 817.006577] Lustre: 23229:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 817.006579] Lustre: 23229:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 140 previous similar messages [ 817.006584] Lustre: 23229:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 817.006587] Lustre: 23229:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 140 previous similar messages [ 817.155554] Lustre: 23358:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 146 previous similar messages [ 819.042449] Lustre: *** cfs_fail_loc=1600, val=3*** [ 822.627263] Lustre: *** cfs_fail_loc=1600, val=3*** [ 833.460341] Lustre: 21038:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-OST0001: opcode 2: before 259 < left 274, rollback = 2 [ 833.479210] Lustre: 23355:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 833.480822] Lustre: 21038:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 49 previous similar messages [ 833.480859] Lustre: 21038:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/1, xattr_set: 2/274/0 [ 833.480878] Lustre: 21038:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 49 previous similar messages [ 833.480887] Lustre: 21038:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 0/0/0, punch: 0/0/0, quota 7/225/0 [ 833.480891] Lustre: 21038:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 49 previous similar messages [ 833.480899] Lustre: 21038:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 833.480904] Lustre: 21038:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 49 previous similar messages [ 833.480911] Lustre: 21038:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 833.480919] Lustre: 21038:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 49 previous similar messages [ 833.566076] Lustre: 23355:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 51 previous similar messages [ 839.139159] 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 [ 839.145467] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 839.183421] Lustre: Skipped 1 previous similar message [ 843.183193] Lustre: server umount lustre-MDT0000 complete [ 849.055910] LustreError: 22056:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1779688121 with bad export cookie 6820915656890558329 [ 849.057870] LustreError: MGC192.168.201.122@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 849.073045] LustreError: 22056:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 849.379304] LustreError: 21000:0:(ldlm_lib.c:1179: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. [ 849.380111] 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 [ 849.406370] LustreError: 21000:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 6 previous similar messages [ 849.421517] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 849.447311] Lustre: Skipped 3 previous similar messages [ 849.471762] Lustre: Skipped 4 previous similar messages [ 849.986526] Lustre: server umount lustre-MDT0001 complete [ 857.621264] Lustre: server umount lustre-OST0000 complete [ 863.685514] Lustre: server umount lustre-OST0001 complete [ 879.195363] Lustre: DEBUG MARKER: == sanity-lfsck test 1a: LFSCK can find out and repair crashed FID-in-dirent ========================================================== 01:49:07 (1779688147) [ 897.945428] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing load_modules_local [ 913.380983] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 914.229848] LustreError: 26037:0:(ldlm_lib.c:1179: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. [ 914.368436] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 919.522350] LustreError: 26038:0:(ldlm_lib.c:1179: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. [ 920.362288] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 924.647878] LustreError: 26037:0:(ldlm_lib.c:1179: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. [ 929.760652] LustreError: 26038:0:(ldlm_lib.c:1179: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. [ 932.436643] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 932.991068] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 938.536632] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 942.686739] Lustre: 27143:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 951.787809] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 952.282516] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 957.424273] LustreError: 27496:0:(ldlm_lib.c:1179: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. [ 959.476706] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:40 to 0x280000401:65) [ 960.884789] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 972.446971] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 977.908892] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:41 to 0x2c0000401:65) [ 981.503545] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 992.200618] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 997.752763] Lustre: 28980:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 1000.481110] Lustre: 28993:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 1000.500621] Lustre: 28993:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 13 previous similar messages [ 1000.521623] Lustre: 28993:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 1000.533021] Lustre: 28993:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 6 previous similar messages [ 1000.539864] Lustre: 28993:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 1000.556351] Lustre: 28993:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 14 previous similar messages [ 1000.569727] Lustre: 28993:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 1000.588106] Lustre: 28993:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 14 previous similar messages [ 1000.602112] Lustre: 28993:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 1000.611754] Lustre: 28993:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 14 previous similar messages [ 1000.626624] Lustre: 28993:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 1000.632340] Lustre: 28993:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 14 previous similar messages [ 1008.257290] Lustre: *** cfs_fail_loc=1501, val=0*** [ 1020.835445] Lustre: Failing over lustre-MDT0000 [ 1021.206444] Lustre: server umount lustre-MDT0000 complete [ 1023.969157] 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 [ 1023.971540] LustreError: 26033:0:(ldlm_lib.c:1179: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. [ 1023.996942] Lustre: Skipped 2 previous similar messages [ 1024.041408] LustreError: 26033:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 7 previous similar messages [ 1035.419757] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1035.616414] LustreError: MGC192.168.201.122@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1035.980694] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1035.992510] Lustre: Skipped 1 previous similar message [ 1036.045833] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1041.389225] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1041.395692] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1041.454560] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1041.536858] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:105 to 0x280000401:129) [ 1041.543784] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:105 to 0x2c0000401:129) [ 1042.090722] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1047.737817] Lustre: *** cfs_fail_loc=1505, val=0*** [ 1059.456777] Lustre: DEBUG MARKER: == sanity-lfsck test 1b: LFSCK can find out and repair the missing FID-in-LMA ========================================================== 01:52:08 (1779688328) [ 1060.986235] Lustre: 26032:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 1061.001960] Lustre: 26032:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 322 previous similar messages [ 1061.012516] Lustre: 26032:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 1061.023176] Lustre: 26032:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 1061.030630] Lustre: 26032:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 1061.036214] Lustre: 26032:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 1061.043211] Lustre: 26032:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 1061.049108] Lustre: 26032:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 1061.054462] Lustre: 26032:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 1061.057888] Lustre: 26032:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 1061.066731] Lustre: 26032:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 1061.074781] Lustre: 26032:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 1067.526060] Lustre: *** cfs_fail_loc=1502, val=0*** [ 1081.874237] Lustre: Failing over lustre-MDT0000 [ 1082.232524] Lustre: server umount lustre-MDT0000 complete [ 1082.336210] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1082.338085] 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 [ 1082.341489] LustreError: 26032:0:(ldlm_lib.c:1179: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. [ 1082.341501] LustreError: 26032:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 10 previous similar messages [ 1082.381544] Lustre: Skipped 3 previous similar messages [ 1098.193347] Lustre: 16312:0:(client.c:2480:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1779688354/real 1779688354] req@ffff9c8ffba9dc00 x1866137966242816/t0(0) o400->MGC192.168.201.122@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1779688370 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1098.244368] LustreError: MGC192.168.201.122@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1099.132825] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1108.804530] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1108.896407] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1114.086788] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1114.115619] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1114.129050] Lustre: Skipped 3 previous similar messages [ 1114.182986] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1114.272543] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:169 to 0x280000401:193) [ 1114.273564] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:169 to 0x2c0000401:193) [ 1114.385688] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1118.776323] Lustre: *** cfs_fail_loc=1505, val=0*** [ 1127.985040] Lustre: DEBUG MARKER: == sanity-lfsck test 1c: LFSCK can find out and repair lost FID-in-dirent ========================================================== 01:53:17 (1779688397) [ 1129.322438] Lustre: 28993:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 1129.332059] Lustre: 28993:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 322 previous similar messages [ 1129.338301] Lustre: 28993:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 1129.343525] Lustre: 28993:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 1129.349150] Lustre: 28993:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 1129.354543] Lustre: 28993:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 1129.360813] Lustre: 28993:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 1129.372106] Lustre: 28993:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 1129.380384] Lustre: 28993:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 1129.395135] Lustre: 28993:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 1129.406664] Lustre: 28993:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 1129.413185] Lustre: 28993:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 1136.413939] Lustre: *** cfs_fail_loc=1504, val=0*** [ 1136.420121] Lustre: *** cfs_fail_loc=1504, val=0*** [ 1136.425880] Lustre: Skipped 1 previous similar message [ 1148.124536] Lustre: Failing over lustre-MDT0000 [ 1148.643205] Lustre: server umount lustre-MDT0000 complete [ 1149.928233] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1149.930711] 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 [ 1149.941099] LustreError: 28993:0:(ldlm_lib.c:1179: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. [ 1149.955679] Lustre: Skipped 2 previous similar messages [ 1149.984035] LustreError: 28993:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 30 previous similar messages [ 1160.818603] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1160.992629] LustreError: MGC192.168.201.122@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1161.456199] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1166.818810] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1166.839140] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1166.846365] Lustre: Skipped 3 previous similar messages [ 1166.874486] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1166.934052] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:233 to 0x280000401:257) [ 1166.936156] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:233 to 0x2c0000401:257) [ 1167.067272] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1170.828022] Lustre: *** cfs_fail_loc=1505, val=0*** [ 1179.472976] Lustre: DEBUG MARKER: == sanity-lfsck test 2a: LFSCK can find out and repair crashed linkEA entry ========================================================== 01:54:08 (1779688448) [ 1187.912265] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1195.456250] Lustre: Failing over lustre-MDT0000 [ 1195.701453] Lustre: server umount lustre-MDT0000 complete [ 1197.540608] 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 [ 1197.575811] Lustre: Skipped 5 previous similar messages [ 1207.800719] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1207.966069] LustreError: MGC192.168.201.122@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1208.353483] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1213.413459] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1213.417981] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1213.429980] Lustre: Skipped 3 previous similar messages [ 1213.444950] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1213.504100] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:297 to 0x2c0000401:321) [ 1213.505804] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:297 to 0x280000401:321) [ 1213.974883] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1225.120559] Lustre: DEBUG MARKER: == sanity-lfsck test 2b: LFSCK can find out and remove invalid linkEA entry ========================================================== 01:54:54 (1779688494) [ 1233.102779] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1244.202976] Lustre: Failing over lustre-MDT0000 [ 1244.588166] Lustre: server umount lustre-MDT0000 complete [ 1249.249050] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1249.256800] 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 [ 1249.333188] Lustre: Skipped 2 previous similar messages [ 1258.197496] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1258.317672] LustreError: MGC192.168.201.122@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1258.578458] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1258.586267] Lustre: Skipped 2 previous similar messages [ 1258.635753] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1263.593554] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1263.594699] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1263.637892] Lustre: Skipped 3 previous similar messages [ 1263.674504] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1263.706051] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:361 to 0x2c0000401:385) [ 1263.715592] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:361 to 0x280000401:385) [ 1264.210313] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1276.616393] Lustre: DEBUG MARKER: == sanity-lfsck test 2c: LFSCK can find out and remove repeated linkEA entry ========================================================== 01:55:45 (1779688545) [ 1278.499360] Lustre: 26033:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 1278.509698] Lustre: 26033:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 967 previous similar messages [ 1278.518451] Lustre: 26033:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 1278.525277] Lustre: 26033:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 967 previous similar messages [ 1278.535199] Lustre: 26033:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 1278.545519] Lustre: 26033:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 967 previous similar messages [ 1278.554420] Lustre: 26033:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 1278.564204] Lustre: 26033:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 967 previous similar messages [ 1278.570827] Lustre: 26033:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 1278.583396] Lustre: 26033:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 967 previous similar messages [ 1278.599030] Lustre: 26033:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 1278.615697] Lustre: 26033:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 967 previous similar messages [ 1285.339780] Lustre: *** cfs_fail_loc=1605, val=0*** [ 1295.395731] Lustre: Failing over lustre-MDT0000 [ 1295.753853] Lustre: server umount lustre-MDT0000 complete [ 1299.424495] 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 [ 1299.426943] LustreError: 34696:0:(ldlm_lib.c:1179: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. [ 1299.436336] Lustre: Skipped 3 previous similar messages [ 1299.452346] LustreError: 34696:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 31 previous similar messages [ 1308.702427] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1308.974671] LustreError: MGC192.168.201.122@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1309.643265] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1314.792637] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1314.798550] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1314.805919] Lustre: Skipped 3 previous similar messages [ 1314.862792] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1314.922815] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:425 to 0x280000401:449) [ 1314.923201] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:425 to 0x2c0000401:449) [ 1315.085060] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1325.818226] Lustre: DEBUG MARKER: == sanity-lfsck test 2d: LFSCK can recover the missing linkEA entry ========================================================== 01:56:35 (1779688595) [ 1332.976151] Lustre: *** cfs_fail_loc=161d, val=0*** [ 1342.350795] Lustre: Failing over lustre-MDT0000 [ 1342.752256] Lustre: server umount lustre-MDT0000 complete [ 1355.301196] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1355.462428] LustreError: MGC192.168.201.122@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1355.771984] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1360.876156] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1360.882610] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1360.908306] Lustre: Skipped 3 previous similar messages [ 1360.929034] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1360.981766] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:489 to 0x2c0000401:513) [ 1360.987900] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:489 to 0x280000401:513) [ 1361.293569] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1373.198600] Lustre: DEBUG MARKER: == sanity-lfsck test 2e: namespace LFSCK can verify remote object linkEA ========================================================== 01:57:22 (1779688642) [ 1376.729558] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1388.755340] Lustre: DEBUG MARKER: == sanity-lfsck test 3: LFSCK can verify multiple-linked objects ========================================================== 01:57:37 (1779688657) [ 1396.112395] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1397.033063] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1410.499916] Lustre: DEBUG MARKER: == sanity-lfsck test 4: FID-in-dirent can be rebuilt after MDT file-level backup/restore ========================================================== 01:57:59 (1779688679) [ 1446.241967] Lustre: Failing over lustre-MDT0000 [ 1446.792628] Lustre: server umount lustre-MDT0000 complete [ 1447.904990] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1447.916191] 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 [ 1447.980713] Lustre: Skipped 7 previous similar messages [ 1452.805395] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1462.873262] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1463.263784] Lustre: 16315:0:(client.c:2480:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1779688719/real 1779688719] req@ffff9c8fff072a00 x1866137966723456/t0(0) o400->MGC192.168.201.122@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1779688735 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1463.307072] LustreError: MGC192.168.201.122@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1479.728081] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1479.760144] Lustre: lustre-MDT0000: reset Object Index mappings [ 1488.868399] LustreError: 16311:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9c8ff95d4700 x1866137966736128/t0(0) o250->MGC192.168.201.122@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 [ 1489.231815] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1494.496869] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1494.507396] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1494.519246] Lustre: Skipped 3 previous similar messages [ 1494.564376] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1494.630354] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:592 to 0x2c0000401:609) [ 1494.634885] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:592 to 0x280000401:609) [ 1495.107482] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1499.451475] LustreError: 42503:0:(lfsck_engine.c:1018:lfsck_master_engine()) lustre-MDT0000-osd: master engine fail to verify the .lustre/lost+found/, go ahead: rc = -115 [ 1499.481264] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1500.511116] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1501.535616] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1503.585697] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1503.589439] Lustre: Skipped 1 previous similar message [ 1510.757643] Lustre: Failing over lustre-MDT0000 [ 1511.141228] Lustre: server umount lustre-MDT0000 complete [ 1522.814983] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1523.113719] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1523.121473] Lustre: Skipped 3 previous similar messages [ 1527.965787] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1528.379280] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:592 to 0x2c0000401:641) [ 1528.384698] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:592 to 0x280000401:641) [ 1532.538741] Lustre: *** cfs_fail_loc=1505, val=0*** [ 1542.538090] Lustre: DEBUG MARKER: == sanity-lfsck test 5: LFSCK can handle IGIF object upgrading ========================================================== 02:00:11 (1779688811) [ 1544.934633] Lustre: 28993:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 1544.944817] Lustre: 28993:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 1380 previous similar messages [ 1544.950715] Lustre: 28993:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 1544.961467] Lustre: 28993:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1381 previous similar messages [ 1544.970679] Lustre: 28993:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 1544.977030] Lustre: 28993:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1381 previous similar messages [ 1544.985673] Lustre: 28993:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 1544.991845] Lustre: 28993:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1381 previous similar messages [ 1544.999715] Lustre: 28993:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 1545.007789] Lustre: 28993:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1381 previous similar messages [ 1545.012605] Lustre: 28993:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 1545.017776] Lustre: 28993:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1381 previous similar messages [ 1546.572437] Lustre: *** cfs_fail_loc=1504, val=0*** [ 1557.012816] Lustre: Failing over lustre-MDT0000 [ 1557.277431] Lustre: server umount lustre-MDT0000 complete [ 1559.011872] LustreError: 26032:0:(ldlm_lib.c:1179: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. [ 1559.013145] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1559.047486] LustreError: 26032:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 56 previous similar messages [ 1564.860509] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1574.367279] Lustre: 16312:0:(client.c:2480:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1779688830/real 1779688830] req@ffff9c8ec99bc700 x1866137966828032/t0(0) o400->MGC192.168.201.122@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1779688846 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1576.422372] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1589.371767] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1589.428875] Lustre: lustre-MDT0000: reset Object Index mappings [ 1599.983867] LustreError: 16311:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9c8fc41cc380 x1866137966840704/t0(0) o250->MGC192.168.201.122@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 [ 1600.393183] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1600.402364] Lustre: Skipped 1 previous similar message [ 1605.608550] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1605.626740] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 1605.628424] Lustre: Skipped 1 previous similar message [ 1605.649430] Lustre: Skipped 7 previous similar messages [ 1605.680604] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1605.693575] Lustre: Skipped 1 previous similar message [ 1605.761576] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:681 to 0x280000401:705) [ 1605.761952] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:681 to 0x2c0000401:705) [ 1605.865868] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1609.865288] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1609.874629] Lustre: Skipped 1 previous similar message [ 1618.083156] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1618.098510] Lustre: Skipped 7 previous similar messages [ 1625.736647] Lustre: Failing over lustre-MDT0000 [ 1626.096067] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1626.103338] 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 [ 1626.117429] Lustre: Skipped 10 previous similar messages [ 1626.222902] Lustre: server umount lustre-MDT0000 complete [ 1637.429353] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1637.512890] LustreError: MGC192.168.201.122@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1637.530255] LustreError: Skipped 2 previous similar messages [ 1642.374813] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1643.091368] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:681 to 0x280000401:737) [ 1643.091562] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:681 to 0x2c0000401:737) [ 1646.223686] Lustre: *** cfs_fail_loc=1505, val=0*** [ 1646.226955] Lustre: Skipped 84 previous similar messages [ 1654.145527] Lustre: DEBUG MARKER: == sanity-lfsck test 6a: LFSCK resumes from last checkpoint (1) ========================================================== 02:02:03 (1779688923) [ 1662.819651] Lustre: *** cfs_fail_loc=1600, val=1*** [ 1662.831826] Lustre: Skipped 1 previous similar message [ 1684.567866] Lustre: DEBUG MARKER: == sanity-lfsck test 6b: LFSCK resumes from last checkpoint (2) ========================================================== 02:02:33 (1779688953) [ 1695.011125] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1695.016048] Lustre: Skipped 10 previous similar messages [ 1721.867899] Lustre: DEBUG MARKER: == sanity-lfsck test 7a: non-stopped LFSCK should auto restarts after MDS remount (1) ========================================================== 02:03:11 (1779688991) [ 1738.759110] Lustre: Failing over lustre-MDT0000 [ 1739.258636] Lustre: server umount lustre-MDT0000 complete [ 1750.084920] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1750.491202] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1750.516058] Lustre: Skipped 1 previous similar message [ 1755.503539] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1755.616607] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1755.631120] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1755.633488] Lustre: Skipped 1 previous similar message [ 1755.640850] Lustre: Skipped 7 previous similar messages [ 1755.671543] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1755.683742] Lustre: Skipped 1 previous similar message [ 1755.770370] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:854 to 0x2c0000401:897) [ 1755.771182] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:853 to 0x280000401:897) [ 1766.812205] Lustre: DEBUG MARKER: == sanity-lfsck test 7b: non-stopped LFSCK should auto restarts after MDS remount (2) ========================================================== 02:03:56 (1779689036) [ 1783.221179] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing load_modules_local [ 1804.059454] Lustre: 52451:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 1832.975997] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1836.548861] Lustre: 53589:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 1844.191702] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1844.193496] Lustre: Skipped 81 previous similar messages [ 1847.839237] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1848.864088] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1849.888798] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1851.941061] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1851.944828] Lustre: Skipped 1 previous similar message [ 1853.365566] Lustre: Failing over lustre-MDT0000 [ 1853.782448] Lustre: server umount lustre-MDT0000 complete [ 1858.017087] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1866.145511] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1871.532339] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1871.896895] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:946 to 0x280000401:961) [ 1871.906646] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:947 to 0x2c0000401:993) [ 1882.498934] Lustre: DEBUG MARKER: == sanity-lfsck test 8: LFSCK state machine ============== 02:05:51 (1779689151) [ 1887.199923] 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 [ 1887.228651] Lustre: Skipped 10 previous similar messages [ 1887.259460] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1887.267455] Lustre: Skipped 3 previous similar messages [ 1891.489567] Lustre: server umount lustre-MDT0000 complete [ 1895.704296] LustreError: 26017:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1779689167 with bad export cookie 6820915656890771675 [ 1895.707812] LustreError: MGC192.168.201.122@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1895.710812] LustreError: 26017:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 1895.721667] LustreError: Skipped 2 previous similar messages [ 1895.990384] Lustre: server umount lustre-MDT0001 complete [ 1910.017219] Lustre: server umount lustre-OST0000 complete [ 1913.329070] Lustre: 16312:0:(client.c:2480:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1779689169/real 1779689169] req@ffff9c8fffddf480 x1866137967178880/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1779689185 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1915.312461] Lustre: server umount lustre-OST0001 complete [ 1922.611908] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_hostid [ 1930.764974] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing load_modules_local [ 1974.889448] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing load_modules_local [ 1985.741489] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1986.096867] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 1986.124162] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 1986.189492] Lustre: lustre-MDT0000: new disk, initializing [ 1986.278440] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 1992.051567] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2006.440302] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2006.518824] Lustre: 58580:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 2006.552644] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 2006.559325] Lustre: Skipped 1 previous similar message [ 2006.633693] Lustre: lustre-MDT0001: new disk, initializing [ 2006.740638] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 2006.755927] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 2012.014690] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2017.221996] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 2025.391340] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2025.651603] Lustre: lustre-OST0000: new disk, initializing [ 2025.656631] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 2025.662833] Lustre: 60179:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 2027.029272] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 2027.053991] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 2027.203635] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 2032.395592] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2045.143879] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2045.308453] Lustre: lustre-OST0001: new disk, initializing [ 2045.313793] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 2045.329585] Lustre: 61033:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 2045.487832] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 2045.496873] Lustre: Skipped 7 previous similar messages [ 2047.036059] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 2047.049235] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 2047.266440] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 2052.863777] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2063.408887] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 2067.219934] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 2067.424310] Lustre: 58588:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 251 < left 278, rollback = 2 [ 2067.431834] Lustre: 58588:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 1739 previous similar messages [ 2067.438158] Lustre: 58588:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 2067.445633] Lustre: 58588:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1739 previous similar messages [ 2067.458691] Lustre: 58588:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 2067.469252] Lustre: 58588:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1738 previous similar messages [ 2067.485396] Lustre: 58588:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 2067.500585] Lustre: 58588:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1739 previous similar messages [ 2067.516138] Lustre: 58588:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 2067.521963] Lustre: 58588:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1739 previous similar messages [ 2067.530569] Lustre: 58588:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 2067.543103] Lustre: 58588:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1739 previous similar messages [ 2080.351466] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2081.317953] Lustre: *** cfs_fail_loc=1604, val=0*** [ 2081.322984] Lustre: Skipped 19 previous similar messages [ 2086.275988] Lustre: *** cfs_fail_loc=1601, val=2*** [ 2086.284887] Lustre: Skipped 17 previous similar messages [ 2104.147669] Lustre: Failing over lustre-MDT0000 [ 2104.301334] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 2104.322076] LustreError: Skipped 1 previous similar message [ 2104.327488] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2104.589711] Lustre: server umount lustre-MDT0000 complete [ 2108.899676] LustreError: 58593:0:(ldlm_lib.c:1179: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. [ 2108.928774] LustreError: 58593:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 74 previous similar messages [ 2114.921263] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 2115.408815] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 2115.420860] Lustre: Skipped 1 previous similar message [ 2120.674490] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 2120.689139] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 2120.692597] Lustre: Skipped 1 previous similar message [ 2120.709279] Lustre: Skipped 7 previous similar messages [ 2120.747228] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 2120.756232] Lustre: Skipped 1 previous similar message [ 2120.801465] Lustre: *** cfs_fail_loc=160b, val=2*** [ 2120.813368] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:65) [ 2120.814705] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:65) [ 2121.018974] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2130.663547] Lustre: Failing over lustre-MDT0000 [ 2130.945152] Lustre: server umount lustre-MDT0000 complete [ 2140.822144] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 2141.152407] Lustre: lustre-MDT0000: Not available for connect from 0@lo (not set up) [ 2141.168446] Lustre: Skipped 1 previous similar message [ 2146.793798] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2146.835709] Lustre: *** cfs_fail_loc=160b, val=2*** [ 2146.844608] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:97) [ 2146.852017] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:97) [ 2154.071865] Lustre: Failing over lustre-MDT0000 [ 2154.540951] Lustre: server umount lustre-MDT0000 complete [ 2164.861875] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 2170.536157] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2170.996498] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:129) [ 2170.996544] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:129) [ 2177.566756] Lustre: *** cfs_fail_loc=1602, val=2*** [ 2177.574393] Lustre: Skipped 1 previous similar message [ 2190.449596] Lustre: DEBUG MARKER: == sanity-lfsck test 9a: LFSCK speed control (1) ========= 02:10:59 (1779689459) [ 2205.057542] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing load_modules_local [ 2230.743852] Lustre: 67877:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 2258.500676] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 2263.073571] Lustre: 69015:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 2387.514102] Lustre: DEBUG MARKER: == sanity-lfsck test 9b: LFSCK speed control (2) ========= 02:14:16 (1779689656) [ 2439.223508] Lustre: *** cfs_fail_loc=1604, val=0*** [ 2439.228186] Lustre: Skipped 4 previous similar messages [ 2465.624435] Lustre: *** cfs_fail_loc=160c, val=0*** [ 2465.632843] Lustre: Skipped 7 previous similar messages [ 2505.945209] Lustre: DEBUG MARKER: == sanity-lfsck test 10: System is available during LFSCK scanning ========================================================== 02:16:15 (1779689775) [ 2550.674387] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2551.689633] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2551.692883] Lustre: Skipped 69 previous similar messages [ 2553.702605] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2553.704499] Lustre: Skipped 132 previous similar messages [ 2557.778761] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2557.781911] Lustre: Skipped 218 previous similar messages [ 2565.795722] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2565.798328] Lustre: Skipped 404 previous similar messages [ 2581.820488] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2581.825495] Lustre: Skipped 812 previous similar messages [ 2613.854097] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2613.858910] Lustre: Skipped 1581 previous similar messages [ 2620.446748] Lustre: *** cfs_fail_loc=1604, val=0*** [ 2620.453089] Lustre: Skipped 2599 previous similar messages [ 2667.433967] Lustre: 58587:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 264, rollback = 2 [ 2667.447939] Lustre: 58587:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 35907 previous similar messages [ 2667.460039] Lustre: 58587:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 2667.475086] Lustre: 58587:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 35908 previous similar messages [ 2667.491512] Lustre: 58587:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 3/264/0 [ 2667.501151] Lustre: 58587:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 35909 previous similar messages [ 2667.511781] Lustre: 58587:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 2667.518269] Lustre: 58587:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 35909 previous similar messages [ 2667.525593] Lustre: 58587:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 2667.529330] Lustre: 58587:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 35909 previous similar messages [ 2667.534648] Lustre: 58587:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 2667.540563] Lustre: 58587:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 35909 previous similar messages [ 2852.333725] Lustre: DEBUG MARKER: == sanity-lfsck test 11a: LFSCK can rebuild lost last_id ========================================================== 02:22:01 (1779690121) [ 2990.058643] 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 [ 2990.066689] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2990.072380] Lustre: Skipped 17 previous similar messages [ 2990.094064] Lustre: Skipped 3 previous similar messages [ 2995.177927] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2995.188327] Lustre: Skipped 3 previous similar messages [ 3000.293386] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3000.306073] Lustre: Skipped 3 previous similar messages [ 3002.335137] Lustre: lustre-MDT0000 is waiting for obd_unlinked_exports more than 8 seconds. The obd refcount = 3. Is it stuck? [ 3002.592944] Lustre: server umount lustre-MDT0000 complete [ 3005.409401] LustreError: 65303:0:(ldlm_lib.c:1179: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. [ 3005.416424] LustreError: 65303:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 22 previous similar messages [ 3006.204781] LustreError: 58571:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1779690278 with bad export cookie 6820915656890790771 [ 3006.210471] LustreError: MGC192.168.201.122@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3006.218821] LustreError: 58571:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 3006.233822] LustreError: Skipped 3 previous similar messages [ 3006.623340] Lustre: server umount lustre-MDT0001 complete [ 3022.145947] Lustre: server umount lustre-OST0000 complete [ 3035.898351] Lustre: server umount lustre-OST0001 complete [ 3042.074474] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: (null) [ 3049.372653] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 3064.927560] LustreError: Failed to get MGS log lustre-sptlrpc and no local copy. [ 3070.047638] LustreError: 74484:0:(mgc_request.c:233:do_config_log_add()) MGC192.168.201.122@tcp: failed processing log, type 4: rc = -110 [ 3095.775174] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 3095.782044] Lustre: Skipped 3 previous similar messages [ 3100.914553] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3104.909867] Lustre: 75050:0:(ofd_dev.c:560:ofd_lfsck_out_notify()) lustre-OST0000: Found crashed LAST_ID, deny creating new OST-object on the device until the LAST_ID rebuilt successfully. [ 3104.936119] Lustre: *** cfs_fail_loc=160e, val=3*** [ 3108.035324] Lustre: 75050:0:(ofd_dev.c:572:ofd_lfsck_out_notify()) lustre-OST0000: Rebuilt crashed LAST_ID files successfully. [ 3117.888857] Lustre: DEBUG MARKER: == sanity-lfsck test 11b: LFSCK can rebuild crashed last_id ========================================================== 02:26:27 (1779690387) [ 3130.816090] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing load_modules_local [ 3139.974857] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3140.430803] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3271 to 0x280000401:3297) [ 3143.839118] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3150.735523] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3154.569801] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3157.123868] Lustre: 77664:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3170.489304] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3175.943622] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3208 to 0x2c0000401:3233) [ 3176.508885] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3183.101893] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3186.252518] Lustre: 79148:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 3190.385020] Lustre: *** cfs_fail_loc=160d, val=0*** [ 3196.358963] Lustre: Failing over lustre-OST0000 [ 3196.389140] Lustre: lustre-OST0000: Not available for connect from 0@lo (stopping) [ 3196.480769] Lustre: server umount lustre-OST0000 complete [ 3205.077505] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3205.262861] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 3205.274027] Lustre: Skipped 2 previous similar messages [ 3207.267061] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 3207.276813] Lustre: Skipped 2 previous similar messages [ 3207.297508] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 3207.300170] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 3207.301698] Lustre: *** cfs_fail_loc=215, val=0*** [ 3207.304880] Lustre: Skipped 2 previous similar messages [ 3207.326633] Lustre: Skipped 11 previous similar messages [ 3210.531252] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3212.767886] Lustre: *** cfs_fail_loc=215, val=0*** [ 3212.773566] Lustre: Skipped 15 previous similar messages [ 3213.758787] Lustre: 80531:0:(ofd_dev.c:560:ofd_lfsck_out_notify()) lustre-OST0000: Found crashed LAST_ID, deny creating new OST-object on the device until the LAST_ID rebuilt successfully. [ 3213.777411] Lustre: 80531:0:(ofd_dev.c:572:ofd_lfsck_out_notify()) lustre-OST0000: Rebuilt crashed LAST_ID files successfully. [ 3216.356024] Lustre: Failing over lustre-OST0000 [ 3216.448289] Lustre: server umount lustre-OST0000 complete [ 3217.889776] LustreError: lustre-OST0000-osc-MDT0001: operation ost_statfs to node 0@lo failed: rc = -107 [ 3217.903838] LustreError: Skipped 3 previous similar messages [ 3224.214330] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3225.662141] Lustre: *** cfs_fail_loc=215, val=0*** [ 3225.667249] Lustre: Skipped 2 previous similar messages [ 3229.684358] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3230.700124] Lustre: *** cfs_fail_loc=215, val=0*** [ 3230.700124] Lustre: *** cfs_fail_loc=215, val=0*** [ 3234.787075] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3234.793796] Lustre: Skipped 1 previous similar message [ 3240.643730] Lustre: server umount lustre-MDT0000 complete [ 3243.645949] LustreError: 74492:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1779690515 with bad export cookie 6820915656892359023 [ 3243.658861] LustreError: 74492:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 3243.949092] Lustre: server umount lustre-MDT0001 complete [ 3256.332848] Lustre: server umount lustre-OST0000 complete [ 3269.734381] Lustre: server umount lustre-OST0001 complete [ 3276.379417] Lustre: DEBUG MARKER: == sanity-lfsck test 12a: single command to trigger LFSCK on all devices ========================================================== 02:29:06 (1779690546) [ 3287.481652] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing load_modules_local [ 3295.109403] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3298.364427] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3305.104759] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3309.214669] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3311.371036] Lustre: 84846:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3315.545813] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3319.592877] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3321.908191] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3362 to 0x280000401:3393) [ 3326.737611] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3331.046201] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3208 to 0x2c0000401:3265) [ 3331.471600] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3337.002609] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3339.935775] Lustre: 86678:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 3341.093283] Lustre: 84531:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 256 < left 278, rollback = 2 [ 3341.101621] Lustre: 84531:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 2565 previous similar messages [ 3341.106906] Lustre: 84531:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 3341.112438] Lustre: 84531:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 2565 previous similar messages [ 3341.119283] Lustre: 84531:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3341.126053] Lustre: 84531:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 2565 previous similar messages [ 3341.132728] Lustre: 84531:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 3341.140072] Lustre: 84531:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 2565 previous similar messages [ 3341.146070] Lustre: 84531:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 3341.153526] Lustre: 84531:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 2565 previous similar messages [ 3341.159980] Lustre: 84531:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3341.164831] Lustre: 84531:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 2565 previous similar messages [ 3363.515835] Lustre: DEBUG MARKER: == sanity-lfsck test 12b: auto detect Lustre device ====== 02:30:33 (1779690633) [ 3374.141961] Lustre: DEBUG MARKER: == sanity-lfsck test 13: LFSCK can repair crashed lmm_oi ========================================================== 02:30:44 (1779690644) [ 3375.240110] Lustre: *** cfs_fail_loc=160f, val=0*** [ 3382.760348] Lustre: DEBUG MARKER: == sanity-lfsck test 14a: LFSCK can repair MDT-object with dangling LOV EA reference (1) ========================================================== 02:30:52 (1779690652) [ 3385.362257] Lustre: *** cfs_fail_loc=1610, val=0*** [ 3385.364375] Lustre: Skipped 7 previous similar messages [ 3428.322851] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3428.324488] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3428.328938] Lustre: Skipped 9 previous similar messages [ 3434.558235] Lustre: server umount lustre-MDT0000 complete [ 3437.709496] LustreError: 84465:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1779690709 with bad export cookie 6820915656892367479 [ 3437.721762] LustreError: 84465:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 3438.026985] Lustre: server umount lustre-MDT0001 complete [ 3451.895364] Lustre: server umount lustre-OST0000 complete [ 3454.944125] Lustre: 16314:0:(client.c:2480:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1779690710/real 1779690710] req@ffff9c8fc40ed500 x1866137971244672/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1779690726 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3455.115333] Lustre: server umount lustre-OST0001 complete [ 3467.345942] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing load_modules_local [ 3474.660176] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3477.796175] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3483.808055] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3486.474881] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3488.427706] Lustre: 92492:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3493.251908] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3496.859224] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3500.722682] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3554 to 0x280000401:3585) [ 3501.970697] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3505.628514] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3507.173271] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3317 to 0x2c0000401:3361) [ 3508.201171] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:116 to 0x2c0000400:161) [ 3508.202421] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:116 to 0x280000400:161) [ 3513.654255] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3515.642643] Lustre: 94325:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 3519.558916] Lustre: DEBUG MARKER: == sanity-lfsck test 14b: LFSCK can repair MDT-object with dangling LOV EA reference (2) ========================================================== 02:33:09 (1779690789) [ 3522.477078] Lustre: *** cfs_fail_loc=1610, val=0*** [ 3522.479436] Lustre: Skipped 63 previous similar messages [ 3535.328993] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3535.352248] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3535.355473] Lustre: Skipped 5 previous similar messages [ 3536.099528] Lustre: server umount lustre-MDT0000 complete [ 3538.366812] LustreError: 91365:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1779690810 with bad export cookie 6820915656892395885 [ 3538.376809] LustreError: 91365:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 3538.574418] Lustre: server umount lustre-MDT0001 complete [ 3554.271669] Lustre: 16312:0:(client.c:2480:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1779690810/real 1779690810] req@ffff9c8ec682c700 x1866137971358720/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1779690826 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3559.263167] Lustre: 16315:0:(client.c:2480:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1779690815/real 1779690815] req@ffff9c8ec645f800 x1866137971359104/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1779690831 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3559.274470] Lustre: 16315:0:(client.c:2480:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 3560.463508] Lustre: server umount lustre-OST0000 complete [ 3562.274710] Lustre: server umount lustre-OST0001 complete [ 3569.520476] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing load_modules_local [ 3574.924627] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3577.540902] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3582.460470] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3584.635403] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3586.322984] Lustre: 98308:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3589.532888] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3592.646586] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3592.748221] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:116 to 0x280000400:193) [ 3597.747665] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3600.932556] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:116 to 0x2c0000400:193) [ 3600.940080] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3317 to 0x2c0000401:3393) [ 3600.941944] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3682 to 0x280000401:3713) [ 3601.245333] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3605.872372] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3611.973925] Lustre: DEBUG MARKER: == sanity-lfsck test 15a: LFSCK can repair unmatched MDT-object/OST-object pairs (1) ========================================================== 02:34:42 (1779690882) [ 3614.182915] Lustre: *** cfs_fail_loc=1611, val=0*** [ 3614.184512] Lustre: Skipped 63 previous similar messages [ 3614.295085] Lustre: *** cfs_fail_loc=1611, val=0*** [ 3620.491991] Lustre: DEBUG MARKER: == sanity-lfsck test 15b: LFSCK can repair unmatched MDT-object/OST-object pairs (2) ========================================================== 02:34:50 (1779690890) [ 3621.717588] Lustre: *** cfs_fail_loc=1612, val=0*** [ 3621.748839] Lustre: *** cfs_fail_loc=1612, val=0*** [ 3621.752110] Lustre: Skipped 2 previous similar messages [ 3627.672330] Lustre: DEBUG MARKER: == sanity-lfsck test 15c: LFSCK can repair unmatched MDT-object/OST-object pairs (3) ========================================================== 02:34:57 (1779690897) [ 3628.613368] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_15c MDS newer than 2.7.55, LU-6475 [ 3629.685283] Lustre: DEBUG MARKER: == sanity-lfsck test 15d: LFSCK don't crash upon dir migration failure ========================================================== 02:34:59 (1779690899) [ 3634.075380] Lustre: *** cfs_fail_loc=1709, val=0*** [ 3634.079459] LustreError: 97211:0:(osp_object.c:617:osp_attr_get()) lustre-MDT0000-osp-MDT0001: osp_attr_get update error [0x200003ab2:0x1:0x0]: rc = -5 [ 3634.090132] LustreError: 97211:0:(mdt_reint.c:2636:mdt_reint_migrate()) lustre-MDT0001: migrate [0x240002340:0x6c:0x0]/s57 failed: rc = -5 [ 3687.904054] 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 [ 3687.909177] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3687.913948] Lustre: Skipped 21 previous similar messages [ 3687.922465] Lustre: Skipped 3 previous similar messages [ 3692.147228] Lustre: server umount lustre-MDT0000 complete [ 3693.024684] LustreError: 97196:0:(ldlm_lib.c:1179: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. [ 3693.037580] LustreError: 97196:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 33 previous similar messages [ 3696.896370] LustreError: 100145:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1779690968 with bad export cookie 6820915656892410627 [ 3696.897275] LustreError: MGC192.168.201.122@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3696.903985] LustreError: 100145:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 3696.919334] LustreError: Skipped 3 previous similar messages [ 3697.096740] Lustre: server umount lustre-MDT0001 complete [ 3711.239368] Lustre: server umount lustre-OST0000 complete [ 3714.400078] Lustre: 16315:0:(client.c:2480:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1779690970/real 1779690970] req@ffff9c8ecc8ad180 x1866137971973376/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1779690986 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3714.417632] Lustre: 16315:0:(client.c:2480:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 3716.590623] Lustre: server umount lustre-OST0001 complete [ 3726.492877] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing unload_modules_local [ 3728.115242] Key type lgssc unregistered [ 3728.305553] LNet: 103952:0:(lib-ptl.c:967:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 3728.312531] LNetError: 103952:0:(acceptor.c:246:lnet_acceptor_remove_socket()) Interface ens2 not found [ 3728.329869] LNet: Removed LNI 192.168.201.122@tcp [ 3728.917116] Key type .llcrypt unregistered [ 3728.918670] Key type ._llcrypt unregistered [ 3753.921608] Key type ._llcrypt registered [ 3753.925691] Key type .llcrypt registered [ 3754.099107] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_hostid [ 3771.324965] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing load_modules_local [ 3772.362730] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 3772.372608] alg: No test for adler32 (adler32-zlib) [ 3773.540206] Lustre: Lustre: Build Version: 2.17.53_24_g1d9adb4 [ 3773.812981] LNet: Added LNI 192.168.201.122@tcp [8/256/0/180] [ 3775.607161] Key type lgssc registered [ 3776.875659] Lustre: Echo OBD driver; http://www.lustre.org/ [ 3840.634272] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing load_modules_local [ 3854.553659] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 3854.583993] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3855.882184] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 3855.903400] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 3855.983342] Lustre: lustre-MDT0000: new disk, initializing [ 3856.062695] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3856.079914] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 3859.639836] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3871.357373] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3871.494333] Lustre: 108365:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 3871.554342] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 3871.562613] Lustre: Skipped 1 previous similar message [ 3871.692929] Lustre: lustre-MDT0001: new disk, initializing [ 3871.798733] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 3871.820370] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 3871.824633] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 3876.067552] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3880.918289] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 3889.462106] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3889.625529] Lustre: lustre-OST0000: new disk, initializing [ 3889.632615] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 3889.639442] Lustre: 110268:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 3889.696187] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 3894.303629] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 3894.309771] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 3894.399340] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 3894.806494] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3908.103846] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3908.270834] Lustre: lustre-OST0001: new disk, initializing [ 3908.274963] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 3908.282495] Lustre: 111273:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 3908.362360] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 3914.613559] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3915.820419] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 3915.833444] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 3915.883589] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 3925.467829] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3931.003327] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 3935.817608] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 02:40:05 (1779691205) === [ 3941.872429] Lustre: DEBUG MARKER: == sanity-lfsck test 16: LFSCK can repair inconsistent MDT-object/OST-object owner ========================================================== 02:40:11 (1779691211) [ 3942.041871] Lustre: 111686:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 251 < left 278, rollback = 2 [ 3942.048917] Lustre: 111686:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 3942.053693] Lustre: 111686:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3942.059045] Lustre: 111686:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 3942.063837] Lustre: 111686:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 3942.067380] Lustre: 111686:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3942.557237] Lustre: 108372:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 252 < left 278, rollback = 2 [ 3942.571990] Lustre: 108372:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 9 previous similar messages [ 3942.577512] Lustre: 108372:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 3942.581050] Lustre: 108372:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3942.586078] Lustre: 108372:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3942.588497] Lustre: 108372:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3942.594009] Lustre: 108372:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/1, punch: 0/0/0, quota 7/369/2 [ 3942.602331] Lustre: 108372:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3942.609866] Lustre: 108372:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/1, delete: 0/0/0 [ 3942.615059] Lustre: 108372:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3942.622351] Lustre: 108372:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3942.628358] Lustre: 108372:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3943.565987] Lustre: 108371:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 3943.580099] Lustre: 108371:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 161 previous similar messages [ 3943.585560] Lustre: 108371:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 3943.592257] Lustre: 108371:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 161 previous similar messages [ 3943.599848] Lustre: 108371:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3943.608170] Lustre: 108371:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 161 previous similar messages [ 3943.619623] Lustre: 108371:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 7/369/0 [ 3943.627664] Lustre: 108371:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 161 previous similar messages [ 3943.633193] Lustre: 108371:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 3943.636261] Lustre: 108371:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 161 previous similar messages [ 3943.641700] Lustre: 108371:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3943.647906] Lustre: 108371:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 161 previous similar messages [ 3945.084790] Lustre: *** cfs_fail_loc=1613, val=0*** [ 3954.235693] Lustre: DEBUG MARKER: == sanity-lfsck test 17: LFSCK can repair multiple references ========================================================== 02:40:24 (1779691224) [ 3955.130371] Lustre: 108371:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 256 < left 278, rollback = 2 [ 3955.139266] Lustre: 108371:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 137 previous similar messages [ 3955.160841] Lustre: 108371:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/2, destroy: 0/0/0 [ 3955.169814] Lustre: 108371:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 137 previous similar messages [ 3955.176579] Lustre: 108371:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3955.181017] Lustre: 108371:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 137 previous similar messages [ 3955.189393] Lustre: 108371:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 3955.196609] Lustre: 108371:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 137 previous similar messages [ 3955.201993] Lustre: 108371:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 3955.206730] Lustre: 108371:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 137 previous similar messages [ 3955.211056] Lustre: 108371:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3955.218290] Lustre: 108371:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 137 previous similar messages [ 3956.064547] Lustre: *** cfs_fail_loc=1614, val=0*** [ 3959.737348] Lustre: 110259:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 259 < left 275, rollback = 2 [ 3959.750148] Lustre: 110259:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 11 previous similar messages [ 3959.754802] Lustre: 110259:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 3959.758839] Lustre: 110259:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3959.769356] Lustre: 110259:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/1, xattr_set: 3/275/0 [ 3959.778846] Lustre: 110259:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3959.787801] Lustre: 110259:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/9/0, punch: 1/4/0, quota 7/225/0 [ 3959.797792] Lustre: 110259:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3959.806506] Lustre: 110259:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 3959.816554] Lustre: 110259:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3959.825156] Lustre: 110259:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3959.829312] Lustre: 110259:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3966.058571] Lustre: DEBUG MARKER: == sanity-lfsck test 18a: Find out orphan OST-object and repair it (1) ========================================================== 02:40:35 (1779691235) [ 3967.785111] Lustre: 110258:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 259 < left 274, rollback = 2 [ 3967.800753] Lustre: 110258:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 19 previous similar messages [ 3967.809171] Lustre: 113340:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 3967.809751] Lustre: 110258:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/1, xattr_set: 2/274/0 [ 3967.809757] Lustre: 110258:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 19 previous similar messages [ 3967.809763] Lustre: 110258:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 0/0/0, punch: 0/0/0, quota 7/225/0 [ 3967.809766] Lustre: 110258:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 19 previous similar messages [ 3967.809771] Lustre: 110258:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 3967.809775] Lustre: 110258:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 19 previous similar messages [ 3967.861832] Lustre: 110259:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3967.864015] Lustre: 113340:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3967.896188] Lustre: 110259:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3968.631667] Lustre: *** cfs_fail_loc=1615, val=0*** [ 3968.639274] Lustre: Skipped 1 previous similar message [ 3974.254621] LustreError: 113579:0:(lfsck_layout.c:2103:lfsck_layout_add_comp()) five: Five five five five five five file Hello [0x280000401:0x6d:0x0] and [0x280000401:0x6d:0x0]d: rc = 0 [ 3987.619944] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_18b skipping excluded test 18b [ 3989.483520] Lustre: DEBUG MARKER: == sanity-lfsck test 18c: Find out orphan OST-object and repair it (3) ========================================================== 02:40:58 (1779691258) [ 3990.003732] Lustre: 108372:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 3990.018198] Lustre: 108372:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 2 previous similar messages [ 3990.027892] Lustre: 108372:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 3990.041665] Lustre: 108372:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1 previous similar message [ 3990.048350] Lustre: 108372:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3990.054604] Lustre: 108372:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 3 previous similar messages [ 3990.063446] Lustre: 108372:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 3990.073626] Lustre: 108372:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 3 previous similar messages [ 3990.081211] Lustre: 108372:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 3990.089943] Lustre: 108372:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 3 previous similar messages [ 3990.096709] Lustre: 108372:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3992.303381] Lustre: *** cfs_fail_loc=1617, val=0*** [ 3992.372918] Lustre: *** cfs_fail_loc=1617, val=0*** [ 3994.323089] Lustre: *** cfs_fail_loc=1616, val=0*** [ 3994.329952] Lustre: Skipped 5 previous similar messages [ 4012.686175] Lustre: DEBUG MARKER: == sanity-lfsck test 18d: Find out orphan OST-object and repair it (4) ========================================================== 02:41:22 (1779691282) [ 4014.543705] Lustre: *** cfs_fail_loc=1618, val=0*** [ 4014.548827] Lustre: Skipped 5 previous similar messages [ 4048.868661] 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 [ 4048.869361] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4048.890508] Lustre: Skipped 3 previous similar messages [ 4048.903541] Lustre: Skipped 2 previous similar messages [ 4053.988250] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4053.998500] Lustre: Skipped 4 previous similar messages [ 4054.427457] Lustre: server umount lustre-MDT0000 complete [ 4058.151646] LustreError: 108353:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1779691330 with bad export cookie 8196449645909456701 [ 4058.153338] LustreError: MGC192.168.201.122@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4058.163921] LustreError: 108353:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 4058.519459] Lustre: server umount lustre-MDT0001 complete [ 4072.577942] Lustre: server umount lustre-OST0000 complete [ 4075.488148] Lustre: 105533:0:(client.c:2480:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1779691331/real 1779691331] req@ffff9c8ec695ad80 x1866141317400448/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1779691347 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4075.526400] 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 [ 4076.670631] Lustre: server umount lustre-OST0001 complete [ 4092.645863] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing load_modules_local [ 4102.093361] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4102.596836] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4107.161798] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4107.745760] LustreError: 116951:0:(ldlm_lib.c:1179: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. [ 4107.764994] LustreError: 116951:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 2 previous similar messages [ 4112.864569] LustreError: 116950:0:(ldlm_lib.c:1179: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. [ 4114.994836] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4115.279210] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 4119.766758] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4122.733430] Lustre: 118057:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 4129.071935] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4135.438885] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4140.577680] LustreError: 118411:0:(ldlm_lib.c:1179: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. [ 4140.601801] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:4 to 0x280000400:33) [ 4145.122498] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4145.301701] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 4145.315728] Lustre: Skipped 1 previous similar message [ 4147.384367] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:4 to 0x2c0000401:33) [ 4147.391204] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:33) [ 4147.391269] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:116 to 0x280000401:161) [ 4151.274349] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4159.002740] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4162.016946] Lustre: 119895:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 4172.868346] Lustre: DEBUG MARKER: == sanity-lfsck test 18e: Find out orphan OST-object and repair it (5) ========================================================== 02:44:02 (1779691442) [ 4173.122290] Lustre: 116946:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 252 < left 278, rollback = 2 [ 4173.130400] Lustre: 116946:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 46 previous similar messages [ 4173.134659] Lustre: 116946:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4173.141843] Lustre: 116946:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4173.146645] Lustre: 116946:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4173.151511] Lustre: 116946:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4173.157214] Lustre: 116946:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/1 [ 4173.167611] Lustre: 116946:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4173.175061] Lustre: 116946:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 4173.179879] Lustre: 116946:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4173.185923] Lustre: 116946:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4173.192489] Lustre: 116946:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4174.348081] Lustre: *** cfs_fail_loc=1618, val=0*** [ 4174.351573] Lustre: Skipped 3 previous similar messages [ 4207.583611] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4207.600567] 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 [ 4207.611980] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4212.668259] Lustre: server umount lustre-MDT0000 complete [ 4214.247266] LustreError: 117666:0:(ldlm_lib.c:1179: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. [ 4214.256681] LustreError: 117666:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 3 previous similar messages [ 4214.751420] LustreError: 116931:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1779691486 with bad export cookie 8196449645909471940 [ 4214.752242] LustreError: MGC192.168.201.122@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4214.757140] LustreError: 116931:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 4214.904604] Lustre: server umount lustre-MDT0001 complete [ 4227.605731] Lustre: server umount lustre-OST0000 complete [ 4239.900245] Lustre: server umount lustre-OST0001 complete [ 4248.426645] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing load_modules_local [ 4254.296195] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4254.538383] LustreError: 122444:0:(ldlm_lib.c:1179: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. [ 4254.581525] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4256.675927] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4261.770948] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4264.029675] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4265.497937] Lustre: 123550:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 4268.832080] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4271.072960] LustreError: 123904:0:(ldlm_lib.c:1179: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. [ 4271.074351] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:4 to 0x280000400:65) [ 4271.086181] LustreError: 123904:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 1 previous similar message [ 4271.933940] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4277.002120] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4279.206065] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:65) [ 4279.206524] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:166 to 0x280000401:193) [ 4279.241865] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:4 to 0x2c0000401:65) [ 4280.371840] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4285.666340] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4288.074119] Lustre: 125384:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 4292.339775] Lustre: 122445:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 252 < left 260, rollback = 2 [ 4292.351589] Lustre: 122445:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 21 previous similar messages [ 4292.362033] Lustre: 122445:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4292.370085] Lustre: 122445:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4292.379151] Lustre: 122445:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 0/0/0, xattr_set: 1/260/0 [ 4292.389932] Lustre: 122445:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4292.390939] Lustre: *** cfs_fail_loc=1602, val=10*** [ 4292.400467] Lustre: 122445:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/9/0, punch: 0/0/0, quota 4/150/2 [ 4292.421968] Lustre: 122445:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4292.428942] Lustre: 122445:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 1/17/2, delete: 0/0/0 [ 4292.433634] Lustre: 122445:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4292.439053] Lustre: 122445:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 4292.442027] Lustre: 122445:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4312.304697] Lustre: DEBUG MARKER: == sanity-lfsck test 18f: Skip the failed OST(s) when handle orphan OST-objects ========================================================== 02:46:22 (1779691582) [ 4313.997158] Lustre: *** cfs_fail_loc=1616, val=0*** [ 4313.999312] Lustre: Skipped 3 previous similar messages [ 4319.007799] Lustre: *** cfs_fail_loc=161c, val=0*** [ 4319.011580] Lustre: Skipped 1 previous similar message [ 4331.988390] Lustre: DEBUG MARKER: == sanity-lfsck test 18g: Find out orphan OST-object and repair it (7) ========================================================== 02:46:42 (1779691602) [ 4333.248485] Lustre: *** cfs_fail_loc=162e, val=0*** [ 4333.250741] Lustre: *** cfs_fail_loc=162e, val=0*** [ 4333.252995] Lustre: Skipped 7 previous similar messages [ 4340.133592] Lustre: DEBUG MARKER: == sanity-lfsck test 18h: LFSCK can repair crashed PFL extent range ========================================================== 02:46:50 (1779691610) [ 4343.637400] LustreError: 128471:0:(lfsck_layout.c:2103:lfsck_layout_add_comp()) five: Five five five five five five file Hello [0x2c0000401:0x44:0x0] and [0x2c0000401:0x44:0x0]d: rc = 0 [ 4352.026791] Lustre: DEBUG MARKER: == sanity-lfsck test 19a: OST-object inconsistency self detect ========================================================== 02:47:02 (1779691622) [ 4359.843307] Lustre: DEBUG MARKER: == sanity-lfsck test 19b: OST-object inconsistency self repair ========================================================== 02:47:10 (1779691630) [ 4361.688978] Lustre: *** cfs_fail_loc=1611, val=0*** [ 4361.717250] Lustre: *** cfs_fail_loc=1611, val=0*** [ 4361.720369] Lustre: Skipped 3 previous similar messages [ 4364.965298] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.201.22@tcp inode [0x2000013a1:0x1f:0x0] object 0x280000401:203 extent [0-4095], client returned csum 0 (type 4), server csum 703fb3ad (type 4) [ 4366.053764] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.201.22@tcp inode [0x2000013a1:0x20:0x0] object 0x280000401:204 extent [0-4095], client returned csum 0 (type 4), server csum 7cbb935c (type 4) [ 4369.922630] Lustre: DEBUG MARKER: == sanity-lfsck test 20a: Handle the orphan with dummy LOV EA slot properly ========================================================== 02:47:20 (1779691640) [ 4371.318802] Lustre: *** cfs_fail_loc=1616, val=0*** [ 4371.321852] Lustre: Skipped 3 previous similar messages [ 4411.263513] Lustre: DEBUG MARKER: == sanity-lfsck test 20b: Handle the orphan with dummy LOV EA slot properly - PFL case ========================================================== 02:48:01 (1779691681) [ 4414.752143] Lustre: DEBUG MARKER: == sanity-lfsck test 21: run all LFSCK components by default ========================================================== 02:48:05 (1779691685) [ 4420.312986] Lustre: DEBUG MARKER: == sanity-lfsck test 22a: LFSCK can repair unmatched pairs (1) ========================================================== 02:48:10 (1779691690) [ 4420.857674] Lustre: 126415:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 257 < left 278, rollback = 2 [ 4420.863365] Lustre: 126415:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 438 previous similar messages [ 4420.866668] Lustre: 126415:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 4420.869700] Lustre: 126415:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 438 previous similar messages [ 4420.872369] Lustre: 126415:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4420.875261] Lustre: 126415:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 438 previous similar messages [ 4420.878104] Lustre: 126415:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 4420.881591] Lustre: 126415:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 438 previous similar messages [ 4420.884880] Lustre: 126415:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 4420.887823] Lustre: 126415:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 438 previous similar messages [ 4420.891262] Lustre: 126415:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4420.894130] Lustre: 126415:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 438 previous similar messages [ 4421.431456] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4421.434621] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4421.436646] Lustre: Skipped 1 previous similar message [ 4426.355231] Lustre: DEBUG MARKER: == sanity-lfsck test 22b: LFSCK can repair unmatched pairs (2) ========================================================== 02:48:16 (1779691696) [ 4427.108388] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4427.111690] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4432.122292] Lustre: DEBUG MARKER: == sanity-lfsck test 23a: LFSCK can repair dangling name entry (1) ========================================================== 02:48:22 (1779691702) [ 4432.865360] Lustre: *** cfs_fail_loc=1620, val=0*** [ 4439.350867] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_23b skipping excluded test 23b [ 4440.198496] Lustre: DEBUG MARKER: == sanity-lfsck test 23c: LFSCK can repair dangling name entry (3) ========================================================== 02:48:30 (1779691710) [ 4443.369218] Lustre: *** cfs_fail_loc=1621, val=127*** [ 4443.371808] Lustre: Skipped 1 previous similar message [ 4444.604601] Lustre: *** cfs_fail_loc=1602, val=10*** [ 4459.996944] Lustre: DEBUG MARKER: == sanity-lfsck test 23d: LFSCK can repair a dangling name entry to a remote object ========================================================== 02:48:50 (1779691730) [ 4461.078924] Lustre: Failing over lustre-MDT0000 [ 4461.397136] Lustre: server umount lustre-MDT0000 complete [ 4461.535780] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4461.539511] 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 [ 4461.545052] Lustre: Skipped 3 previous similar messages [ 4461.547282] LustreError: 123174:0:(ldlm_lib.c:1179: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. [ 4461.554084] LustreError: 123174:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 1 previous similar message [ 4466.219702] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4466.299313] LustreError: MGC192.168.201.122@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4466.427199] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4466.430795] Lustre: Skipped 3 previous similar messages [ 4466.451743] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4468.005586] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4468.400993] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4471.778169] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 4471.794724] Lustre: lustre-MDT0000: Recovery over after 0:03, of 2 clients 2 recovered and 0 were evicted. [ 4471.818045] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:265 to 0x280000401:289) [ 4471.818098] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:130 to 0x2c0000401:161) [ 4471.832595] LustreError: 122439:0:(mdt_open.c:1324:mdt_cross_open()) lustre-MDT0000: [0x2000013a3:0x82:0x0] doesn't exist!: rc = -14 [ 4477.098952] Lustre: DEBUG MARKER: == sanity-lfsck test 24: LFSCK can repair multiple-referenced name entry ========================================================== 02:49:07 (1779691747) [ 4478.170154] Lustre: *** cfs_fail_loc=1622, val=0*** [ 4478.255255] Lustre: *** cfs_fail_loc=1622, val=0*** [ 4478.260968] Lustre: Skipped 1 previous similar message [ 4484.358372] Lustre: DEBUG MARKER: == sanity-lfsck test 25: LFSCK can repair bad file type in the name entry ========================================================== 02:49:14 (1779691754) [ 4485.282415] Lustre: *** cfs_fail_loc=1623, val=0*** [ 4490.783498] Lustre: DEBUG MARKER: == sanity-lfsck test 26a: LFSCK can add the missing local name entry back to the namespace ========================================================== 02:49:20 (1779691760) [ 4491.703419] Lustre: *** cfs_fail_loc=1624, val=0*** [ 4497.277746] Lustre: DEBUG MARKER: == sanity-lfsck test 26b: LFSCK can add the missing remote name entry back to the namespace ========================================================== 02:49:27 (1779691767) [ 4503.309503] Lustre: DEBUG MARKER: == sanity-lfsck test 27a: LFSCK can recreate the lost local parent directory as orphan ========================================================== 02:49:33 (1779691773) [ 4509.770307] Lustre: DEBUG MARKER: == sanity-lfsck test 27b: LFSCK can recreate the lost remote parent directory as orphan ========================================================== 02:49:40 (1779691780) [ 4510.492346] Lustre: *** cfs_fail_loc=1624, val=0*** [ 4510.494825] Lustre: Skipped 3 previous similar messages [ 4516.106891] Lustre: DEBUG MARKER: == sanity-lfsck test 28: Skip the failed MDT(s) when handle orphan MDT-objects ========================================================== 02:49:46 (1779691786) [ 4519.268351] Lustre: *** cfs_fail_loc=161c, val=0*** [ 4519.275737] Lustre: Skipped 2 previous similar messages [ 4526.909560] Lustre: DEBUG MARKER: == sanity-lfsck test 29b: LFSCK can repair bad nlink count (2) ========================================================== 02:49:57 (1779691797) [ 4534.054696] Lustre: DEBUG MARKER: == sanity-lfsck test 29c: verify linkEA size limitation == 02:50:04 (1779691804) [ 4550.353487] Lustre: DEBUG MARKER: == sanity-lfsck test 29d: accessing non-existing inode shouldn't turn fs read-only (ldiskfs) ========================================================== 02:50:20 (1779691820) [ 4551.193254] Lustre: *** cfs_fail_loc=1626, val=0*** [ 4551.194835] Lustre: Skipped 3 previous similar messages [ 4551.782041] LustreError: 122441:0:(osd_handler.c:284:osd_idc_find_or_init()) lustre-MDT0000: cannot lookup FID [0x2000013a3:0x9e:0x0]: rc = -2 [ 4554.962536] Lustre: DEBUG MARKER: == sanity-lfsck test 30: LFSCK can recover the orphans from backend /lost+found ========================================================== 02:50:25 (1779691825) [ 4582.011541] Lustre: Failing over lustre-MDT0000 [ 4582.203695] Lustre: server umount lustre-MDT0000 complete [ 4584.416430] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4584.421045] 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 [ 4584.421726] LustreError: 122439:0:(ldlm_lib.c:1179: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. [ 4584.421820] LustreError: 122439:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 6 previous similar messages [ 4584.441121] Lustre: Skipped 6 previous similar messages [ 4586.968964] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 4587.025956] LustreError: MGC192.168.201.122@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4587.150356] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4588.879059] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4592.607840] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4592.610330] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4592.612973] Lustre: Skipped 3 previous similar messages [ 4592.622781] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4592.643531] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:295 to 0x280000401:321) [ 4592.643581] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:166 to 0x2c0000401:193) [ 4597.202237] Lustre: DEBUG MARKER: == sanity-lfsck test 31a: The LFSCK can find/repair the name entry with bad name hash (1) ========================================================== 02:51:07 (1779691867) [ 4602.561609] Lustre: DEBUG MARKER: == sanity-lfsck test 31b: The LFSCK can find/repair the name entry with bad name hash (2) ========================================================== 02:51:12 (1779691872) [ 4607.771270] Lustre: DEBUG MARKER: == sanity-lfsck test 31c: Re-generate the lost master LMV EA for striped directory ========================================================== 02:51:18 (1779691878) [ 4608.342133] Lustre: *** cfs_fail_loc=1629, val=0*** [ 4608.344455] Lustre: Skipped 5 previous similar messages [ 4613.156226] Lustre: DEBUG MARKER: == sanity-lfsck test 31d: Set broken striped directory (modified after broken) as read-only ========================================================== 02:51:23 (1779691883) [ 4615.066339] Lustre: Failing over lustre-MDT0000 [ 4618.208302] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4618.208870] 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 [ 4618.209286] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4618.209291] Lustre: Skipped 4 previous similar messages [ 4618.221184] Lustre: Skipped 3 previous similar messages [ 4620.852964] Lustre: server umount lustre-MDT0000 complete [ 4623.944911] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4623.983737] LustreError: MGC192.168.201.122@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4624.061737] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4624.065048] Lustre: Skipped 1 previous similar message [ 4624.078436] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4625.576607] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4626.477988] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4626.481288] Lustre: lustre-MDT0000: Denying connection for new client 3b916624-ff0a-4e72-8298-caeee6a724da (at 192.168.201.22@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 1:00 [ 4629.476318] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4629.478839] Lustre: Skipped 3 previous similar messages [ 4629.484925] Lustre: lustre-MDT0000: Recovery over after 0:03, of 1 clients 1 recovered and 0 were evicted. [ 4629.500514] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:295 to 0x280000401:353) [ 4629.500514] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:166 to 0x2c0000401:225) [ 4634.986980] Lustre: Failing over lustre-MDT0000 [ 4635.284365] Lustre: server umount lustre-MDT0000 complete [ 4638.996264] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4639.057179] LustreError: MGC192.168.201.122@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4639.125875] 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 [ 4639.138424] Lustre: Skipped 3 previous similar messages [ 4639.173602] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4641.081051] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4642.084604] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4644.322369] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4644.325269] Lustre: Skipped 3 previous similar messages [ 4644.337639] Lustre: lustre-MDT0000: Recovery over after 0:02, of 2 clients 2 recovered and 0 were evicted. [ 4644.358102] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:355 to 0x280000401:385) [ 4644.358160] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:166 to 0x2c0000401:257) [ 4647.436090] Lustre: DEBUG MARKER: == sanity-lfsck test 31e: Re-generate the lost slave LMV EA for striped directory (1) ========================================================== 02:51:57 (1779691917) [ 4652.708217] Lustre: DEBUG MARKER: == sanity-lfsck test 31f: Re-generate the lost slave LMV EA for striped directory (2) ========================================================== 02:52:03 (1779691923) [ 4658.264341] Lustre: DEBUG MARKER: == sanity-lfsck test 31g: Repair the corrupted slave LMV EA ========================================================== 02:52:08 (1779691928) [ 4689.060673] Lustre: 122439:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0001: opcode 2: before 252 < left 278, rollback = 2 [ 4689.064316] Lustre: 122439:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 578 previous similar messages [ 4689.068339] Lustre: 122439:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4689.072014] Lustre: 122439:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 578 previous similar messages [ 4689.075754] Lustre: 122439:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4689.079596] Lustre: 122439:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 578 previous similar messages [ 4689.083698] Lustre: 122439:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/1, punch: 0/0/0, quota 1/3/2 [ 4689.087985] Lustre: 122439:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 578 previous similar messages [ 4689.091762] Lustre: 122439:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/1, delete: 0/0/0 [ 4689.094951] Lustre: 122439:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 578 previous similar messages [ 4689.099371] Lustre: 122439:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 4689.102989] Lustre: 122439:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 578 previous similar messages [ 4692.195320] Lustre: DEBUG MARKER: == sanity-lfsck test 31h: Repair the corrupted shard's name entry ========================================================== 02:52:42 (1779691962) [ 4697.769364] Lustre: DEBUG MARKER: == sanity-lfsck test 32a: stop LFSCK when some OST failed ========================================================== 02:52:48 (1779691968) [ 4700.650188] LustreError: 146987:0:(lfsck_layout.c:4532:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d sleeping for 3000ms [ 4701.877799] Lustre: Failing over lustre-OST0000 [ 4701.925039] Lustre: server umount lustre-OST0000 complete [ 4703.255145] LustreError: 146987:0:(lfsck_layout.c:4532:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout interrupted [ 4703.271814] LustreError: lustre-OST0000-osc-MDT0000: operation lfsck_notify to node 0@lo failed: rc = -107 [ 4703.276141] 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 [ 4703.283144] LustreError: 124896:0:(ldlm_lib.c:1179: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. [ 4703.291703] LustreError: 124896:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 7 previous similar messages [ 4711.090409] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 4711.211323] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 4712.612617] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4712.625224] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 4712.628672] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 4712.633830] Lustre: Skipped 3 previous similar messages [ 4714.681919] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4720.050348] Lustre: DEBUG MARKER: == sanity-lfsck test 32b: stop LFSCK when some MDT failed ========================================================== 02:53:10 (1779691990) [ 4727.664634] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing load_modules_local [ 4736.078916] Lustre: 149754:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 4747.821009] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4754.725630] LustreError: 150996:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d sleeping for 3000ms [ 4755.936298] Lustre: Failing over lustre-MDT0001 [ 4756.961218] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 4756.966733] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 4756.972324] Lustre: Skipped 3 previous similar messages [ 4757.743135] LustreError: 150995:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d awake [ 4757.748782] LustreError: 150995:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d sleeping for 3000ms [ 4757.753887] LustreError: 150995:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) Skipped 1 previous similar message [ 4757.929084] Lustre: server umount lustre-MDT0001 complete [ 4759.320055] LustreError: 150995:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout interrupted [ 4766.940626] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 4767.139800] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 4768.894318] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4772.320139] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4772.321750] Lustre: lustre-MDT0001-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 4772.326239] Lustre: Skipped 1 previous similar message [ 4772.333560] Lustre: lustre-MDT0001: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4772.360019] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:71 to 0x280000400:97) [ 4772.360270] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:68 to 0x2c0000400:97) [ 4773.006422] Lustre: DEBUG MARKER: == sanity-lfsck test 33: check LFSCK paramters =========== 02:54:03 (1779692043) [ 4779.234676] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing load_modules_local [ 4787.127110] Lustre: 153678:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 4787.130750] Lustre: 153678:0:(mgs_llog.c:1437:mgs_modify_param()) Skipped 1 previous similar message [ 4796.886509] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4805.823337] Lustre: DEBUG MARKER: == sanity-lfsck test 34: LFSCK can rebuild the lost agent object ========================================================== 02:54:36 (1779692076) [ 4806.550291] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_34 Only valid for ZFS backend [ 4807.340358] Lustre: DEBUG MARKER: == sanity-lfsck test 35: LFSCK can rebuild the lost agent entry ========================================================== 02:54:37 (1779692077) [ 4810.012628] Lustre: *** cfs_fail_loc=1631, val=0*** [ 4818.400444] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4818.401209] 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 [ 4818.401683] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4818.401690] Lustre: Skipped 3 previous similar messages [ 4818.415505] Lustre: Skipped 6 previous similar messages [ 4822.068464] Lustre: server umount lustre-MDT0000 complete [ 4823.714203] LustreError: 139213:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1779692095 with bad export cookie 8196449645909544656 [ 4823.715451] LustreError: MGC192.168.201.122@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4823.719643] LustreError: 139213:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 4823.867264] Lustre: server umount lustre-MDT0001 complete [ 4835.858411] Lustre: server umount lustre-OST0000 complete [ 4847.728931] Lustre: server umount lustre-OST0001 complete [ 4855.082874] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing load_modules_local [ 4859.514554] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4859.701412] LustreError: 157543:0:(ldlm_lib.c:1179: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. [ 4859.714058] LustreError: 157543:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 11 previous similar messages [ 4861.366716] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4864.757176] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4866.501205] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4867.627572] Lustre: 158650:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 4867.631925] Lustre: 158650:0:(mgs_llog.c:1437:mgs_modify_param()) Skipped 1 previous similar message [ 4870.262479] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4872.698327] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4874.467849] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:71 to 0x280000400:129) [ 4876.383822] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4878.919106] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4881.900692] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:68 to 0x2c0000400:129) [ 4884.962293] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:412 to 0x2c0000401:449) [ 4884.962335] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:540 to 0x280000401:577) [ 4888.208577] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4894.657206] Lustre: DEBUG MARKER: == sanity-lfsck test 36a: rebuild LOV EA for mirrored file (1) ========================================================== 02:56:04 (1779692164) [ 4895.576607] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36a needs >= 3 OSTs [ 4896.609103] Lustre: DEBUG MARKER: == sanity-lfsck test 36b: rebuild LOV EA for mirrored file (2) ========================================================== 02:56:06 (1779692166) [ 4897.609638] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36b needs >= 3 OSTs [ 4898.795938] Lustre: DEBUG MARKER: == sanity-lfsck test 36c: rebuild LOV EA for mirrored file (3) ========================================================== 02:56:08 (1779692168) [ 4899.803336] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36c needs >= 3 OSTs [ 4900.786107] Lustre: DEBUG MARKER: == sanity-lfsck test 37: LFSCK must skip a ORPHAN ======== 02:56:11 (1779692171) [ 4907.368743] Lustre: DEBUG MARKER: == sanity-lfsck test 38: LFSCK does not break foreign file and reverse is also true ========================================================== 02:56:17 (1779692177) [ 4955.366402] Lustre: DEBUG MARKER: == sanity-lfsck test 39: LFSCK does not break foreign dir and reverse is also true ========================================================== 02:57:03 (1779692223) [ 4973.471221] Lustre: DEBUG MARKER: == sanity-lfsck test 40a: LFSCK correctly fixes lmm_oi in composite layout ========================================================== 02:57:22 (1779692242) [ 4996.257265] Lustre: DEBUG MARKER: == sanity-lfsck test 41: SEL support in LFSCK ============ 02:57:45 (1779692265) [ 5014.486929] Lustre: DEBUG MARKER: == sanity-lfsck test 42: LFSCK repairs inconsistent MDT-object/OST-object encryption flags ========================================================== 02:58:04 (1779692284) [ 5047.493521] Lustre: *** cfs_fail_loc=1632, val=0*** [ 5058.780169] Lustre: DEBUG MARKER: == sanity-lfsck test 43: LFSCK does not loop endlessly on iget failure in scanning-phase1 ========================================================== 02:58:48 (1779692328) [ 5061.161750] Lustre: Failing over lustre-MDT0001 [ 5061.316206] Lustre: server umount lustre-MDT0001 complete [ 5064.159688] 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 [ 5064.168587] Lustre: Skipped 2 previous similar messages [ 5066.090346] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5066.293769] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 5066.299680] Lustre: Skipped 7 previous similar messages [ 5066.316403] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 5066.316898] Lustre: lustre-MDT0001: Aborting client recovery [ 5066.322528] LustreError: 165176:0:(ldlm_lib.c:2985:target_stop_recovery_thread()) lustre-MDT0001: Aborting recovery [ 5066.329066] Lustre: 165200:0:(ldlm_lib.c:2388:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 5066.336253] Lustre: 165200:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0001: disconnect stale client fad4927c-8c65-467c-9201-882ea92eca58@ [ 5066.343839] Lustre: lustre-MDT0001: disconnecting 2 stale clients [ 5066.350291] Lustre: lustre-MDT0001-osd: cancel update llog [0x240000400:0x1:0x0] [ 5066.359097] Lustre: lustre-MDT0000-osp-MDT0001: cancel update llog [0x200000401:0x1:0x0] [ 5066.386791] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:68 to 0x2c0000400:161) [ 5066.386846] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:131 to 0x280000400:161) [ 5069.424457] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5071.349806] LustreError: lustre-MDT0001-osp-MDT0000: This client was evicted by lustre-MDT0001; in progress operations using this service will fail. [ 5071.377629] Lustre: lustre-MDT0001-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 5071.380826] Lustre: Skipped 3 previous similar messages [ 5075.453139] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing wait_import_state FULL osp.lustre-MDT0001-os[pc]-MDT0000.*_server_uuid [ 5075.713514] Lustre: DEBUG MARKER: osp.lustre-MDT0001-os[pc]-MDT0000.*_server_uuid in FULL state after 0 sec [ 5081.002943] Lustre: DEBUG MARKER: == sanity-lfsck test 44: umount while lfsck is stopping == 02:59:11 (1779692351) [ 5087.084037] Lustre: *** cfs_fail_loc=1600, val=3*** [ 5089.596847] Lustre: Failing over lustre-MDT0000 [ 5089.769789] Lustre: server umount lustre-MDT0000 complete [ 5097.246711] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5097.371646] LustreError: MGC192.168.201.122@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5100.806388] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5101.865570] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 5103.093514] Lustre: lustre-MDT0000: Recovery over after 0:02, of 2 clients 2 recovered and 0 were evicted. [ 5103.117124] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:489 to 0x2c0000401:513) [ 5103.120433] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:621 to 0x280000401:641) [ 5108.118144] Lustre: DEBUG MARKER: == sanity-lfsck test 45: LFSCK should fix UID/GID/PROJID of OST object ========================================================== 02:59:38 (1779692378) [ 5128.139668] Lustre: Failing over lustre-OST0000 [ 5128.242651] Lustre: server umount lustre-OST0000 complete [ 5128.677315] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 5128.677635] LustreError: 159554:0:(ldlm_lib.c:1179: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. [ 5128.702490] LustreError: 159554:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 16 previous similar messages [ 5132.517503] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: (null) [ 5139.611504] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5139.775114] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 5139.785096] Lustre: Skipped 3 previous similar messages [ 5141.605908] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 5141.727785] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 5141.728224] Lustre: lustre-OST0000: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [ 5141.736459] Lustre: Skipped 5 previous similar messages [ 5144.044286] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5147.865505] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing wait_import_state FULL os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid 50 [ 5147.968855] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid in FULL state after 0 sec [ 5150.379927] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing wait_import_state FULL os[cp].lustre-OST0000-osc-MDT0001.ost_server_uuid 50 [ 5150.538734] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0001.ost_server_uuid in FULL state after 0 sec [ 5152.750281] Lustre: DEBUG MARKER: oleg122-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9aa343570000.ost_server_uuid 50 [ 5153.641419] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9aa343570000.ost_server_uuid in FULL state after 0 sec [ 5186.018095] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5186.022638] Lustre: Skipped 6 previous similar messages [ 5186.114779] Lustre: server umount lustre-MDT0000 complete [ 5193.047128] LustreError: 158652:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1779692464 with bad export cookie 8196449645909627277 [ 5193.051169] LustreError: MGC192.168.201.122@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5193.058731] LustreError: 158652:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 5193.234752] Lustre: server umount lustre-MDT0001 complete [ 5209.176079] Lustre: server umount lustre-OST0000 complete [ 5212.383088] Lustre: 105535:0:(client.c:2480:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1779692468/real 1779692468] req@ffff9c8ecc89d880 x1866141319024384/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1779692484 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5214.495402] Lustre: 105533:0:(client.c:2480:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1779692470/real 1779692470] req@ffff9c8ec921d880 x1866141319024768/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1779692486 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5215.453496] Lustre: server umount lustre-OST0001 complete [ 5228.727575] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing unload_modules_local [ 5230.885511] Key type lgssc unregistered [ 5231.133077] LNet: 174093:0:(lib-ptl.c:967:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 5231.144853] LNetError: 174093:0:(acceptor.c:246:lnet_acceptor_remove_socket()) Interface ens2 not found [ 5231.166599] LNet: Removed LNI 192.168.201.122@tcp [ 5231.778222] Key type .llcrypt unregistered [ 5231.781885] Key type ._llcrypt unregistered [ 5251.067192] Key type ._llcrypt registered [ 5251.069180] Key type .llcrypt registered [ 5251.158275] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_hostid [ 5263.735673] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing load_modules_local [ 5264.627311] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 5264.641370] alg: No test for adler32 (adler32-zlib) [ 5265.623694] Lustre: Lustre: Build Version: 2.17.53_24_g1d9adb4 [ 5265.829451] LNet: Added LNI 192.168.201.122@tcp [8/256/0/180] [ 5267.488951] Key type lgssc registered [ 5268.235839] Lustre: Echo OBD driver; http://www.lustre.org/ [ 5306.434803] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing load_modules_local [ 5317.498944] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 5317.531832] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5318.855923] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 5318.890134] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 5318.968773] Lustre: lustre-MDT0000: new disk, initializing [ 5319.030913] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 5319.054988] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 5322.811637] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5332.866025] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5332.953843] Lustre: 178499:0:(mgs_llog.c:1437:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 5332.977753] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 5332.986756] Lustre: Skipped 1 previous similar message [ 5333.057203] Lustre: lustre-MDT0001: new disk, initializing [ 5333.133819] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 5333.177663] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 5333.195350] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 5336.984783] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5341.355255] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 5349.928490] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5350.192186] Lustre: lustre-OST0000: new disk, initializing [ 5350.198250] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 5350.214457] Lustre: 180403:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 5350.326483] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 5355.460602] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5357.094222] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 5357.118470] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 5357.169244] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 5365.266541] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5365.368517] Lustre: lustre-OST0001: new disk, initializing [ 5365.375412] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 5365.379990] Lustre: 181408:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 5365.432632] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 5365.911479] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 5365.918779] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 5365.969179] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 5369.910087] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5378.355131] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5382.651440] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 5386.039235] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 03:04:16 (1779692656) === [ 5386.945325] Lustre: DEBUG MARKER: == sanity-lfsck test complete, duration 5006 sec ========= 03:04:17 (1779692657) [ 5387.985964] Lustre: DEBUG MARKER: === sanity-lfsck: start cleanup 03:04:18 (1779692658) === [ 5389.905868] Lustre: DEBUG MARKER: === sanity-lfsck: finish cleanup 03:04:20 (1779692660) === [ 5394.913184] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 5394.919445] 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 [ 5394.929353] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5396.960943] 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 [ 5396.961293] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5396.968707] Lustre: Skipped 2 previous similar messages [ 5396.971618] Lustre: Skipped 2 previous similar messages [ 5398.025390] Lustre: server umount lustre-MDT0000 complete [ 5402.859902] LustreError: 178492:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1779692674 with bad export cookie 5715275199593771335 [ 5402.863320] LustreError: MGC192.168.201.122@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5402.868571] LustreError: 178492:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 3 previous similar messages [ 5403.076608] Lustre: server umount lustre-MDT0001 complete [ 5418.162496] Lustre: server umount lustre-OST0000 complete [ 5423.584266] Lustre: 175682:0:(client.c:2480:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1779692679/real 1779692679] req@ffff9c8ec9175500 x1866142881750144/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1779692695 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5423.605821] 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 [ 5423.950062] Lustre: server umount lustre-OST0001 complete [ 5433.131516] Lustre: DEBUG MARKER: oleg122-server.virtnet: executing unload_modules_local [ 5434.938312] Key type lgssc unregistered [ 5435.120513] LNet: 184848:0:(lib-ptl.c:967:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 5435.125639] LNetError: 184848:0:(acceptor.c:246:lnet_acceptor_remove_socket()) Interface ens2 not found [ 5435.137975] LNet: Removed LNI 192.168.201.122@tcp [ 5435.572190] Key type .llcrypt unregistered [ 5435.573859] Key type ._llcrypt unregistered