[ 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 3.0.0 present. [ 0.000000] DMI: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.16.3-2.fc40 04/01/2014 [ 0.000000] Hypervisor detected: KVM [ 0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00 [ 0.000000] kvm-clock: using sched offset of 467079877 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2399.998 MHz processor [ 0.000000] last_pfn = 0x146e00 max_arch_pfn = 0x400000000 [ 0.000000] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT [ 0.000000] last_pfn = 0xbffce max_arch_pfn = 0x400000000 [ 0.000000] found SMP MP-table at [mem 0x000f53f0-0x000f53ff] [ 0.000000] RAMDISK: [mem 0xbcc54000-0xbffbffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F5200 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE1D87 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE1C23 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 001BE3 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE1C97 000090 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE1D27 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE1D5F 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe1c23-0xbffe1c96] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe1c22] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe1c97-0xbffe1d26] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe1d27-0xbffe1d5e] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe1d5f-0xbffe1d86] [ 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, 524584K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] ftrace: allocating 41240 entries in 162 pages [ 0.000000] ftrace: allocated 162 pages with 3 groups [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] rcu: RCU event tracing is enabled. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ 0.000000] rcu: RCU callback double-/use-after-free debug enabled. [ 0.000000] Rude variant of Tasks RCU enabled. [ 0.000000] Tracing variant of Tasks RCU enabled. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 0.000000] NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16 [ 0.000000] random: get_random_bytes called from start_kernel+0x622/0x9a8 with crng_init=0 [ 0.001000] Console: colour *CGA 80x25 [ 0.001000] printk: console [ttyS1] enabled [ 0.001000] ACPI: Core revision 20220331 [ 0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.001014] APIC: Switch to symmetric I/O mode setup [ 0.003280] x2apic enabled [ 0.004008] Switched APIC routing to physical x2apic. [ 0.005013] kvm-guest: setup PV IPIs [ 0.007853] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.008000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.008028] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.009010] pid_max: default: 32768 minimum: 301 [ 0.010128] LSM: Security Framework initializing [ 0.011040] Yama: becoming mindful. [ 0.011824] SELinux: Initializing. [ 0.013058] *** VALIDATE selinux *** [ 0.019000] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.020000] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.020148] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.021095] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.022103] *** VALIDATE tmpfs *** [ 0.023399] *** VALIDATE proc *** [ 0.024206] *** VALIDATE cgroup *** [ 0.025007] *** VALIDATE cgroup2 *** [ 0.027096] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.028155] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.029009] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.030029] Spectre V2 : User space: Vulnerable [ 0.031010] Speculative Store Bypass: Vulnerable [ 0.034353] debug: unmapping init [mem 0xffffffff96059000-0xffffffff96060fff] [ 0.037157] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.038690] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.039024] ... version: 2 [ 0.040012] ... bit width: 48 [ 0.041013] ... generic registers: 4 [ 0.042010] ... value mask: 0000ffffffffffff [ 0.043010] ... max period: 00007fffffffffff [ 0.044015] ... fixed-purpose events: 3 [ 0.045013] ... event mask: 000000070000000f [ 0.046293] rcu: Hierarchical SRCU implementation. [ 0.048361] smp: Bringing up secondary CPUs ... [ 0.049473] x86: Booting SMP configuration: [ 0.050022] .... node #0, CPUs: #1 #2 #3 [ 0.059299] smp: Brought up 1 node, 4 CPUs [ 0.061012] smpboot: Max logical packages: 1 [ 0.062011] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.131024] node 0 deferred pages initialised in 65ms [ 0.135106] devtmpfs: initialized [ 0.136276] x86/mm: Memory block size: 128MB [ 0.139789] gcov: version magic: 0x41383552 [ 0.142144] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.145092] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.147278] pinctrl core: initialized pinctrl subsystem [ 0.149160] [ 0.149747] ************************************************************* [ 0.151014] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.154014] ** ** [ 0.156010] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.158013] ** ** [ 0.161013] ** This means that this kernel is built to expose internal ** [ 0.163011] ** IOMMU data structures, which may compromise security on ** [ 0.165011] ** your system. ** [ 0.167024] ** ** [ 0.170015] ** If you see this message and you are not debugging the ** [ 0.172011] ** kernel, report this immediately to your vendor! ** [ 0.175014] ** ** [ 0.176011] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.178010] ************************************************************* [ 0.180831] NET: Registered protocol family 16 [ 0.182518] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.185059] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.188069] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.192580] cpuidle: using governor menu [ 0.195221] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.197437] PCI: Using configuration type 1 for base access [ 0.200135] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.208128] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.209017] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.211045] cryptd: max_cpu_qlen set to 1000 [ 0.212966] ACPI: Added _OSI(Module Device) [ 0.213000] ACPI: Added _OSI(Processor Device) [ 0.213000] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.213000] ACPI: Added _OSI(Processor Aggregator Device) [ 0.218494] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.226773] ACPI: Interpreter enabled [ 0.228067] ACPI: PM: (supports S0 S3 S4 S5) [ 0.230016] ACPI: Using IOAPIC for interrupt routing [ 0.231124] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.234391] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.244426] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.247053] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.250019] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.253090] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.258336] acpiphp: Slot [2] registered [ 0.260139] acpiphp: Slot [5] registered [ 0.261113] acpiphp: Slot [6] registered [ 0.263100] acpiphp: Slot [7] registered [ 0.264100] acpiphp: Slot [8] registered [ 0.266131] acpiphp: Slot [9] registered [ 0.267096] acpiphp: Slot [10] registered [ 0.269136] acpiphp: Slot [3] registered [ 0.270107] acpiphp: Slot [4] registered [ 0.272100] acpiphp: Slot [11] registered [ 0.273083] acpiphp: Slot [12] registered [ 0.275097] acpiphp: Slot [13] registered [ 0.276084] acpiphp: Slot [14] registered [ 0.278097] acpiphp: Slot [15] registered [ 0.279073] acpiphp: Slot [16] registered [ 0.280092] acpiphp: Slot [17] registered [ 0.282156] acpiphp: Slot [18] registered [ 0.284103] acpiphp: Slot [19] registered [ 0.285131] acpiphp: Slot [20] registered [ 0.287097] acpiphp: Slot [21] registered [ 0.288097] acpiphp: Slot [22] registered [ 0.289105] acpiphp: Slot [23] registered [ 0.291100] acpiphp: Slot [24] registered [ 0.292098] acpiphp: Slot [25] registered [ 0.294103] acpiphp: Slot [26] registered [ 0.295118] acpiphp: Slot [27] registered [ 0.296087] acpiphp: Slot [28] registered [ 0.298103] acpiphp: Slot [29] registered [ 0.299110] acpiphp: Slot [30] registered [ 0.300070] acpiphp: Slot [31] registered [ 0.302082] PCI host bridge to bus 0000:00 [ 0.303026] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.305021] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.307024] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.309029] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.312035] pci_bus 0000:00: root bus resource [mem 0x380000000000-0x38007fffffff window] [ 0.314029] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.316188] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.319010] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.323302] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.332019] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.337059] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.339015] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.342024] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.344018] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.347584] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.349679] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.352041] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.354810] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.360016] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.373017] pci 0000:00:02.0: reg 0x20: [mem 0x380000000000-0x380000003fff 64bit pref] [ 0.377027] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.382696] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.389019] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.391000] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.404020] pci 0000:00:05.0: reg 0x20: [mem 0x380000004000-0x380000007fff 64bit pref] [ 0.412185] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.417000] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.421019] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.435024] pci 0000:00:06.0: reg 0x20: [mem 0x380000008000-0x38000000bfff 64bit pref] [ 0.446618] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.452014] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.457019] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.471018] pci 0000:00:07.0: reg 0x20: [mem 0x38000000c000-0x38000000ffff 64bit pref] [ 0.482704] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.487016] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.492014] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.504017] pci 0000:00:08.0: reg 0x20: [mem 0x380000010000-0x380000013fff 64bit pref] [ 0.512687] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.518014] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.524016] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.537018] pci 0000:00:09.0: reg 0x20: [mem 0x380000014000-0x380000017fff 64bit pref] [ 0.543000] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.548029] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.552015] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.564020] pci 0000:00:0a.0: reg 0x20: [mem 0x380000018000-0x38000001bfff 64bit pref] [ 0.575421] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.578387] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.581350] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.583375] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.586227] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.591848] iommu: Default domain type: Passthrough [ 0.593418] SCSI subsystem initialized [ 0.595164] ACPI: bus type USB registered [ 0.596290] usbcore: registered new interface driver usbfs [ 0.598097] usbcore: registered new interface driver hub [ 0.600092] usbcore: registered new device driver usb [ 0.602164] pps_core: LinuxPPS API ver. 1 registered [ 0.604024] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.607063] PTP clock support registered [ 0.610124] EDAC MC: Ver: 3.0.0 [ 0.612172] PCI: Using ACPI for IRQ routing [ 0.614932] NetLabel: Initializing [ 0.616010] NetLabel: domain hash size = 128 [ 0.618011] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.620092] NetLabel: unlabeled traffic allowed by default [ 0.622154] vgaarb: loaded [ 0.623235] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.625011] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.633298] clocksource: Switched to clocksource kvm-clock [ 0.740871] VFS: Disk quotas dquot_6.6.0 [ 0.742970] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.746164] *** VALIDATE ramfs *** [ 0.747436] *** VALIDATE hugetlbfs *** [ 0.750418] pnp: PnP ACPI init [ 0.753049] pnp: PnP ACPI: found 6 devices [ 0.769043] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.772339] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.774489] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.776656] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.779025] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.781396] pci_bus 0000:00: resource 8 [mem 0x380000000000-0x38007fffffff window] [ 0.784206] NET: Registered protocol family 2 [ 0.786602] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.790442] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.793071] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.797780] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.800939] TCP: Hash tables configured (established 65536 bind 65536) [ 0.803468] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.806613] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.809267] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.812445] NET: Registered protocol family 1 [ 0.815364] RPC: Registered named UNIX socket transport module. [ 0.817442] RPC: Registered udp transport module. [ 0.819155] RPC: Registered tcp transport module. [ 0.820936] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.823415] NET: Registered protocol family 44 [ 0.825828] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.828025] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.830265] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.832792] PCI: CLS 0 bytes, default 64 [ 0.834439] Unpacking initramfs... [ 2.280532] debug: unmapping init [mem 0xffff9002bcc54000-0xffff9002bffbffff] [ 2.284243] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.286205] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.288746] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 2.801970] Initialise system trusted keyrings [ 2.803753] Key type blacklist registered [ 2.805889] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.815731] zbud: loaded [ 2.819083] *** VALIDATE nfs *** [ 2.820584] *** VALIDATE nfs4 *** [ 2.822457] pstore: using deflate compression [ 2.831413] Platform Keyring initialized [ 2.948141] NET: Registered protocol family 38 [ 2.950036] Key type asymmetric registered [ 2.951432] Asymmetric key parser 'x509' registered [ 2.953217] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 2.956564] io scheduler mq-deadline registered [ 2.958514] io scheduler kyber registered [ 2.960327] io scheduler bfq registered [ 2.961864] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 2.964768] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 2.967610] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 2.970784] ACPI: Power Button [PWRF] [ 3.061371] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 3.147996] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 3.351511] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 3.447029] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 3.635394] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 3.663314] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.692816] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.700401] Non-volatile memory driver v1.3 [ 3.702360] Linux agpgart interface v0.103 [ 3.746511] virtio_blk virtio1: [vda] 133832 512-byte logical blocks (68.5 MB/65.3 MiB) [ 3.749560] vda: detected capacity change from 0 to 68521984 [ 3.767442] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.770630] vdb: detected capacity change from 0 to 1073741824 [ 3.789073] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.792694] vdc: detected capacity change from 0 to 2621440000 [ 3.807316] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.809826] vdd: detected capacity change from 0 to 2621440000 [ 3.824799] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.827860] vde: detected capacity change from 0 to 4294967296 [ 3.843449] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.846675] vdf: detected capacity change from 0 to 4294967296 [ 3.854182] libphy: Fixed MDIO Bus: probed [ 3.859582] usbcore: registered new interface driver usbserial_generic [ 3.862324] usbserial: USB Serial support registered for generic [ 3.864191] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.867930] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.869469] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.871610] mousedev: PS/2 mouse device common for all mice [ 3.877269] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.881343] rtc_cmos 00:05: RTC can wake from S4 [ 3.886182] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.887246] rtc_cmos 00:05: registered as rtc0 [ 3.893992] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.894247] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.897689] intel_pstate: CPU model not supported [ 3.906596] hid: raw HID events driver (C) Jiri Kosina [ 3.908694] usbcore: registered new interface driver usbhid [ 3.910823] usbhid: USB HID core driver [ 3.912660] drop_monitor: Initializing network drop monitor service [ 3.916619] Initializing XFRM netlink socket [ 3.918763] NET: Registered protocol family 10 [ 3.922130] Segment Routing with IPv6 [ 3.923756] NET: Registered protocol family 17 [ 3.926203] mpls_gso: MPLS GSO support [ 3.931672] RAS: Correctable Errors collector initialized. [ 3.933779] AVX version of gcm_enc/dec engaged. [ 3.935672] AES CTR mode by8 optimization enabled [ 4.016170] sched_clock: Marking stable (4016133475, 0)->(4919896444, -903762969) [ 4.023510] registered taskstats version 1 [ 4.025696] Loading compiled-in X.509 certificates [ 4.029105] zswap: loaded using pool lzo/zbud [ 4.053690] Key type big_key registered [ 4.066036] Key type encrypted registered [ 4.067731] ima: No TPM chip found, activating TPM-bypass! [ 4.070115] ima: Allocated hash algorithm: sha1 [ 4.071885] ima: No architecture policies found [ 4.073785] evm: Initialising EVM extended attributes: [ 4.077851] evm: security.selinux [ 4.079235] evm: security.ima [ 4.080456] evm: security.capability [ 4.081963] evm: HMAC attrs: 0x1 [ 4.084411] rtc_cmos 00:05: setting system clock to 2025-11-16 23:39:43 UTC (1763336383) [ 4.090567] debug: unmapping init [mem 0xffffffff97003000-0xffffffff971fffff] [ 4.093152] debug: unmapping init [mem 0xffffffff95d82000-0xffffffff96058fff] [ 4.102090] Write protecting the kernel read-only data: 28672k [ 4.105155] debug: unmapping init [mem 0xffffffff94403000-0xffffffff945fffff] [ 4.108052] debug: unmapping init [mem 0xffffffff94d14000-0xffffffff94dfffff] [ 4.142864] 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.151483] systemd[1]: Detected virtualization kvm. [ 4.153524] systemd[1]: Detected architecture x86-64. [ 4.155917] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 4.183670] systemd[1]: No hostname configured. [ 4.185628] systemd[1]: Set hostname to . [ 4.187654] random: systemd: uninitialized urandom read (16 bytes read) [ 4.190422] systemd[1]: Initializing machine ID from random generator. [ 4.228487] random: ln: uninitialized urandom read (6 bytes read) [ 4.321335] random: systemd: uninitialized urandom read (16 bytes read) [ 4.324252] systemd[1]: Reached target Timers. [ OK ] Reached target Timers. [ 4.329187] systemd[1]: Listening on Journal Socket. [ OK ] Listening on Journal Socket. [ 4.338406] systemd[1]: Starting Setup Virtual Console... Starting Setup Virtual Console... [ OK ] Started Memstrack Anylazing Service. [ OK ] Listening on udev Kernel Socket. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Listening on Journal Socket (/dev/log). Starting Journal Service... [ OK ] Reached target Slices. [ OK ] Listening on udev Control Socket. [ OK ] Reached target Initrd Root Device. [ OK ] Reached target Swap. Starting Apply Kernel Variables... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Paths. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Local File Systems. Starting Create Volatile Files and Directories... [ OK ] Reached target Sockets. [ OK ] Started Setup Virtual Console. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Apply Kernel Variables. [ OK ] Started Create Volatile Files and Directories. Starting Create Static Device Nodes in /dev... Starting dracut cmdline hook... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started Journal Service. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 4.985531] device-mapper: uevent: version 1.0.3 [ 4.988756] device-mapper: ioctl: 4.46.0-ioctl (2022-02-22) initialised: dm-devel@redhat.com [ OK ] Started dracut pre-udev hook. Starting udev Kernel Device Manager... [ OK ] Started udev Kernel Device Manager. Starting dracut pre-trigger hook... [ OK ] Started dracut pre-trigger hook. Starting udev Coldplug all Devices... Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. Starting dracut initqueue hook... [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ 5.750127] virtio_net virtio0 ens2: renamed from eth0 [ 5.756389] random: fast init done [ 5.829477] scsi host0: ata_piix [ 5.858241] scsi host1: ata_piix [ 5.860189] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 5.862970] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 10.285156] dracut-initqueue[589]: RTNETLINK answers: File exists [ 10.587543] random: crng init done [ 10.589120] random: 7 urandom warning(s) missed due to ratelimiting Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. Mounting /sysroot... [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. [ 11.061453] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped target Timers. Stopping Hardware RNG Entropy Gatherer Daemon... [ 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 dracut initqueue hook. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Sockets. [ OK ] Stopped target Paths. [ OK ] Stopped target Slices. [ OK ] Stopped target System Initialization. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. [ OK ] Stopped target Swap. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. Stopping udev Kernel Device Manager... [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ 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 Control Socket. [ OK ] Closed udev Kernel Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 12.266502] printk: systemd: 26 output lines suppressed due to ratelimiting [ 12.515728] SELinux: Disabled at runtime. [ 12.572714] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 12.581215] systemd[1]: Detected virtualization kvm. [ 12.583157] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 13.068455] systemd[1]: initrd-switch-root.service: Succeeded. [ 13.072595] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 13.077782] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 13.082254] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 13.087951] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 13.099392] systemd[1]: Starting Journal Service... Starting Journal Service... [ 13.106642] systemd[1]: Activating swap /dev/disk/by-label/SWAP... Activating swap /dev/disk/by-label/SWAP... [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Reached target rpc_pipefs.target. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd Root File System. [ OK ] Listening on udev Kernel Socket. Mounting Huge Pages Fil[ 13.137271] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS e System... [ OK ] Listening on Process Core Dump Socket. Starting Remount Root and Kernel File Systems... [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Reached target RPC Port Mapper. Mounting POSIX Message Queue File System... [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Created slice system-getty.slice. [ OK ] Listening on udev Control Socket. Starting udev Coldplug all Devices... Starting Apply Kernel Variables... Starting Create list of required st…ce nodes for the current kernel... [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. Mounting Kernel Debug File System... [ OK ] Created slice User and Session Slice. [ OK ] Reached target Slices. [ OK ] Reached target Paths. [ OK ] Stopped target Initrd File Systems. [ OK ] Started Journal Service. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Mounted Huge Pages File System. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Started Apply Kernel Variables. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Mounted Kernel Debug File System. Starting Configure read-only root support... Starting Create Static Device Nodes in /dev... [ OK ] Reached target Swap. Starting Flush Journal to Persistent Storage... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. Starting udev Kernel Device Manager... [ OK ] Reached target Local File Systems (Pre). Mounting /home/green/git/lustre-release... Mounting /mnt... [ OK ] Mounted /mnt. [ 13.566189] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Started udev Coldplug all Devices. [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 13.897260] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 13.908636] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 14.042239] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 14.055833] EDAC sbridge: Ver: 1.1.2 [ 16.126923] Key type dns_resolver registered [ 16.474529] NFS: Registering the id_resolver key type [ 16.476959] Key type id_resolver registered [ 16.478655] Key type id_legacy registered [ 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 Load/Save Random Seed. [ OK ] Started Create Volatile Files and Directories. Starting Update UTMP about System Boot/Shutdown... Starting RPC Bind... [ 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 daily update of the root trust anchor for DNSSEC. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. [ OK ] Started irqbalance daemon. Starting Restore /run/initramfs on shutdown... [ OK ] Started D-Bus System Message Bus. Starting Network Manager... Starting Login Service... [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Reached target sshd-keygen.target. [ OK ] Started dnf makecache --timer. [ OK ] Reached target Timers. [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Login Service. [ OK ] Started Network Manager. [ OK ] Reached target Network. Starting OpenSSH server daemon... Starting GSSAPI Proxy Daemon... Starting Dynamic System Tuning Daemon... Starting Network Manager Wait Online... Starting Hostname Service... [ OK ] Started OpenSSH server daemon. [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... [ OK ] Started Permit User Sessions. [ OK ] Started Getty on tty1. [ OK ] Started Command Scheduler. [ OK ] Started Serial Getty on ttyS1. [ OK ] Started Serial Getty on ttyS0. [ 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. Starting Authorization Manager... [ OK ] Started Authorization Manager. [ OK ] Started Dynamic System Tuning Daemon. [ OK ] Reached target Multi-User System. [ OK ] Reached target Graphical Interface. Starting Update UTMP about System Runlevel Changes... [ OK ] Started Update UTMP about System Runlevel Changes. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg148-server login: [ 40.712256] hrtimer: interrupt took 5246913 ns [ 58.688921] libcfs: loading out-of-tree module taints kernel. [ 58.709679] Key type ._llcrypt registered [ 58.711866] Key type .llcrypt registered [ 58.854589] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_hostid [ 74.133336] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing load_modules_local [ 75.044369] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 75.054714] alg: No test for adler32 (adler32-zlib) [ 76.328305] Lustre: Lustre: Build Version: 2.16.61_51_gca28732 [ 77.011899] LNet: Added LNI 192.168.201.148@tcp [8/256/0/180] [ 78.735256] Key type lgssc registered [ 80.118268] Lustre: Echo OBD driver; http://www.lustre.org/ [ 90.705824] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 92.070905] LDISKFS-fs (vdc): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 98.295784] LDISKFS-fs (vdd): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 103.813987] LDISKFS-fs (vde): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 108.736131] LDISKFS-fs (vdf): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 120.590027] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing load_modules_local [ 131.527644] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 131.584921] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 131.599061] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 132.817508] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 132.860087] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 132.936969] Lustre: lustre-MDT0000: new disk, initializing [ 133.027115] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 133.040993] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 135.880793] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 147.092863] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 147.136535] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 147.220190] Lustre: 6511:0:(mgs_llog.c:1346:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 147.268207] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 147.285570] Lustre: Skipped 1 previous similar message [ 147.410305] Lustre: lustre-MDT0001: new disk, initializing [ 147.529365] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 147.556833] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 147.566039] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 150.321618] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 153.972958] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 161.066977] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 161.137334] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 161.377494] Lustre: lustre-OST0000: new disk, initializing [ 161.381907] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 161.448535] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 162.928397] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 162.944327] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 163.039761] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 166.516692] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 177.691480] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 177.756431] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 177.894662] Lustre: lustre-OST0001: new disk, initializing [ 177.902823] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 177.964786] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 182.174597] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 186.920500] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 186.931693] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 187.020943] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 191.655564] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 195.842716] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 205.218312] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing check_logdir /tmp/testlogs/ [ 208.720401] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing yml_node [ 212.087254] Lustre: DEBUG MARKER: Client: 2.16.61.51 [ 213.923244] Lustre: DEBUG MARKER: MDS: 2.16.61.51 [ 216.098834] Lustre: DEBUG MARKER: OSS: 2.16.61.51 [ 217.320129] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity-lfsck ============----- Sun Nov 16 18:43:16 EST 2025 [ 232.284471] Lustre: DEBUG MARKER: excepting tests: 18b 23b [ 241.359571] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing load_modules_local [ 248.292293] 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 [ 248.295962] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 248.305160] Lustre: Skipped 1 previous similar message [ 253.411094] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 253.414169] Lustre: Skipped 6 previous similar messages [ 253.556489] LustreError: 12575:0:(obd_class.h:479:obd_check_dev()) Device 28 not setup [ 253.632333] Lustre: server umount lustre-MDT0000 complete [ 259.931571] LustreError: 6503:0:(ldlm_lockd.c:2563:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1763336639 with bad export cookie 6448744505438052314 [ 259.938844] LustreError: MGC192.168.201.148@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 259.943299] LustreError: 6503:0:(ldlm_lockd.c:2563:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 260.072291] LustreError: 13026:0:(obd_class.h:479:obd_check_dev()) Device 27 not setup [ 260.075215] LustreError: 13026:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 260.209968] Lustre: server umount lustre-MDT0001 complete [ 277.178631] LustreError: 13476:0:(obd_class.h:479:obd_check_dev()) Device 19 not setup [ 277.181640] LustreError: 13476:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 277.235774] Lustre: server umount lustre-OST0000 complete [ 280.160096] Lustre: 3656:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763336643/real 1763336643] req@ffff900204612300 x1848992287779968/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1763336659 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 280.192753] 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 [ 280.216562] Lustre: Skipped 2 previous similar messages [ 281.058211] Lustre: 3653:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763336644/real 1763336644] req@ffff900204c72680 x1848992287780224/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1763336660 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 282.771316] LustreError: 13927:0:(obd_class.h:479:obd_check_dev()) Device 2 not setup [ 282.774583] LustreError: 13927:0:(obd_class.h:479:obd_check_dev()) Skipped 3 previous similar messages [ 282.874255] Lustre: server umount lustre-OST0001 complete [ 295.456954] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing unload_modules_local [ 297.684313] Key type lgssc unregistered [ 297.934342] LNet: 14708:0:(lib-ptl.c:967:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 297.946986] LNetError: 14708:0:(acceptor.c:264:lnet_acceptor_remove_socket()) Interface ens2 not found [ 297.961336] LNet: Removed LNI 192.168.201.148@tcp [ 298.608320] Key type .llcrypt unregistered [ 298.610134] Key type ._llcrypt unregistered [ 321.120251] Key type ._llcrypt registered [ 321.121811] Key type .llcrypt registered [ 321.232958] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_hostid [ 331.464332] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing load_modules_local [ 331.917583] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 331.938430] alg: No test for adler32 (adler32-zlib) [ 332.892925] Lustre: Lustre: Build Version: 2.16.61_51_gca28732 [ 333.056090] LNet: Added LNI 192.168.201.148@tcp [8/256/0/180] [ 334.679200] Key type lgssc registered [ 335.338711] Lustre: Echo OBD driver; http://www.lustre.org/ [ 341.500762] LDISKFS-fs (vdc): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 346.703190] LDISKFS-fs (vdd): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 351.317537] LDISKFS-fs (vde): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 355.957609] LDISKFS-fs (vdf): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 365.804155] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing load_modules_local [ 375.066925] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 375.107146] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 375.123592] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 376.415966] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 376.460155] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 376.517681] Lustre: lustre-MDT0000: new disk, initializing [ 376.588513] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 376.625287] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 379.879361] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 390.967308] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 391.016290] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 391.067885] Lustre: 19114:0:(mgs_llog.c:1346:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 391.097887] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 391.101936] Lustre: Skipped 1 previous similar message [ 391.160875] Lustre: lustre-MDT0001: new disk, initializing [ 391.209655] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 391.236124] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 391.245303] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 394.100292] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 398.255371] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 407.360052] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 407.421137] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 407.704611] Lustre: lustre-OST0000: new disk, initializing [ 407.717124] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 407.788320] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 413.208178] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 416.314350] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 416.336240] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 416.465296] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 424.846968] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 424.895225] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 425.004448] Lustre: lustre-OST0001: new disk, initializing [ 425.007176] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 425.083301] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 425.415708] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 425.431716] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 425.484314] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 429.225924] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 437.943311] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 442.626172] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 454.208072] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 18:47:12 (1763336832) === [ 456.621799] Lustre: DEBUG MARKER: == sanity-lfsck test 0: Control LFSCK manually =========== 18:47:15 (1763336835) [ 456.768869] Lustre: 19120:0:(osd_internal.h:1472:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 251 < left 278, rollback = 2 [ 456.773503] Lustre: 19120:0:(osd_handler.c:2082:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 456.777916] Lustre: 19120:0:(osd_handler.c:2089:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 456.782716] Lustre: 19120:0:(osd_handler.c:2099:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 456.789374] Lustre: 19120:0:(osd_handler.c:2106:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 456.796113] Lustre: 19120:0:(osd_handler.c:2113:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 457.277029] Lustre: 19120:0:(osd_internal.h:1472:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 457.281623] Lustre: 19120:0:(osd_internal.h:1472:osd_trans_exec_op()) Skipped 17 previous similar messages [ 457.286354] Lustre: 19120:0:(osd_handler.c:2082:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 457.290450] Lustre: 19120:0:(osd_handler.c:2082:osd_trans_dump_creds()) Skipped 17 previous similar messages [ 457.294565] Lustre: 19120:0:(osd_handler.c:2089:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 457.297732] Lustre: 19120:0:(osd_handler.c:2089:osd_trans_dump_creds()) Skipped 17 previous similar messages [ 457.300924] Lustre: 19120:0:(osd_handler.c:2099:osd_trans_dump_creds()) write: 2/12/0, punch: 0/0/0, quota 1/3/0 [ 457.304639] Lustre: 19120:0:(osd_handler.c:2099:osd_trans_dump_creds()) Skipped 17 previous similar messages [ 457.307749] Lustre: 19120:0:(osd_handler.c:2106:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 457.319937] Lustre: 19120:0:(osd_handler.c:2106:osd_trans_dump_creds()) Skipped 17 previous similar messages [ 457.325386] Lustre: 19120:0:(osd_handler.c:2113:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 457.329814] Lustre: 19120:0:(osd_handler.c:2113:osd_trans_dump_creds()) Skipped 17 previous similar messages [ 458.302125] Lustre: 21822:0:(osd_internal.h:1472:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 458.312701] Lustre: 21822:0:(osd_internal.h:1472:osd_trans_exec_op()) Skipped 47 previous similar messages [ 458.321241] Lustre: 21822:0:(osd_handler.c:2082:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 458.328368] Lustre: 21822:0:(osd_handler.c:2082:osd_trans_dump_creds()) Skipped 47 previous similar messages [ 458.332139] Lustre: 21822:0:(osd_handler.c:2089:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 458.337462] Lustre: 21822:0:(osd_handler.c:2089:osd_trans_dump_creds()) Skipped 47 previous similar messages [ 458.342715] Lustre: 21822:0:(osd_handler.c:2099:osd_trans_dump_creds()) write: 2/12/0, punch: 0/0/0, quota 1/3/0 [ 458.349393] Lustre: 21822:0:(osd_handler.c:2099:osd_trans_dump_creds()) Skipped 47 previous similar messages [ 458.355323] Lustre: 21822:0:(osd_handler.c:2106:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 458.361346] Lustre: 21822:0:(osd_handler.c:2106:osd_trans_dump_creds()) Skipped 47 previous similar messages [ 458.370739] Lustre: 21822:0:(osd_handler.c:2113:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 458.375548] Lustre: 21822:0:(osd_handler.c:2113:osd_trans_dump_creds()) Skipped 47 previous similar messages [ 460.341191] Lustre: 19121:0:(osd_internal.h:1472:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 460.345421] Lustre: 19121:0:(osd_internal.h:1472:osd_trans_exec_op()) Skipped 113 previous similar messages [ 460.348774] Lustre: 19121:0:(osd_handler.c:2082:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 460.351787] Lustre: 19121:0:(osd_handler.c:2082:osd_trans_dump_creds()) Skipped 113 previous similar messages [ 460.360715] Lustre: 19121:0:(osd_handler.c:2089:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 460.367886] Lustre: 19121:0:(osd_handler.c:2089:osd_trans_dump_creds()) Skipped 113 previous similar messages [ 460.372243] Lustre: 19121:0:(osd_handler.c:2099:osd_trans_dump_creds()) write: 2/12/0, punch: 0/0/0, quota 1/3/0 [ 460.377791] Lustre: 19121:0:(osd_handler.c:2099:osd_trans_dump_creds()) Skipped 113 previous similar messages [ 460.382484] Lustre: 19121:0:(osd_handler.c:2106:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 460.388849] Lustre: 19121:0:(osd_handler.c:2106:osd_trans_dump_creds()) Skipped 113 previous similar messages [ 460.392800] Lustre: 19121:0:(osd_handler.c:2113:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 460.396790] Lustre: 19121:0:(osd_handler.c:2113:osd_trans_dump_creds()) Skipped 113 previous similar messages [ 462.759743] Lustre: *** cfs_fail_loc=1600, val=3*** [ 465.566415] Lustre: *** cfs_fail_loc=1600, val=3*** [ 467.233695] Lustre: 21012:0:(osd_internal.h:1472:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 259 < left 274, rollback = 2 [ 467.233719] Lustre: 23224:0:(osd_handler.c:2082:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 467.241065] Lustre: 21012:0:(osd_internal.h:1472:osd_trans_exec_op()) Skipped 109 previous similar messages [ 467.241127] Lustre: 21012:0:(osd_handler.c:2089:osd_trans_dump_creds()) attr_set: 1/1/1, xattr_set: 2/274/0 [ 467.241134] Lustre: 21012:0:(osd_handler.c:2089:osd_trans_dump_creds()) Skipped 108 previous similar messages [ 467.241142] Lustre: 21012:0:(osd_handler.c:2099:osd_trans_dump_creds()) write: 0/0/0, punch: 0/0/0, quota 7/225/0 [ 467.241147] Lustre: 21012:0:(osd_handler.c:2099:osd_trans_dump_creds()) Skipped 108 previous similar messages [ 467.241153] Lustre: 21012:0:(osd_handler.c:2106:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 467.241157] Lustre: 21012:0:(osd_handler.c:2106:osd_trans_dump_creds()) Skipped 108 previous similar messages [ 467.241162] Lustre: 21012:0:(osd_handler.c:2113:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 467.246696] Lustre: 23224:0:(osd_handler.c:2082:osd_trans_dump_creds()) Skipped 109 previous similar messages [ 467.252288] Lustre: 21012:0:(osd_handler.c:2113:osd_trans_dump_creds()) Skipped 108 previous similar messages [ 476.640266] 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 [ 476.641245] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 476.646461] Lustre: Skipped 3 previous similar messages [ 476.649868] Lustre: Skipped 2 previous similar messages [ 479.571850] LustreError: 24084:0:(obd_class.h:479:obd_check_dev()) Device 28 not setup [ 479.626929] Lustre: server umount lustre-MDT0000 complete [ 481.850775] LustreError: 19105:0:(ldlm_lockd.c:2563:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1763336861 with bad export cookie 8253419789875342882 [ 481.854570] LustreError: MGC192.168.201.148@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 481.859421] LustreError: 19105:0:(ldlm_lockd.c:2563:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 481.967284] LustreError: 24288:0:(obd_class.h:479:obd_check_dev()) Device 27 not setup [ 481.972152] LustreError: 24288:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 482.068383] Lustre: server umount lustre-MDT0001 complete [ 495.096195] LustreError: 24488:0:(obd_class.h:479:obd_check_dev()) Device 19 not setup [ 495.100664] LustreError: 24488:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 495.145499] Lustre: server umount lustre-OST0000 complete [ 508.041618] LustreError: 24690:0:(obd_class.h:479:obd_check_dev()) Device 2 not setup [ 508.048919] LustreError: 24690:0:(obd_class.h:479:obd_check_dev()) Skipped 3 previous similar messages [ 508.149342] Lustre: server umount lustre-OST0001 complete [ 514.157346] Lustre: DEBUG MARKER: == sanity-lfsck test 1a: LFSCK can find out and repair crashed FID-in-dirent ========================================================== 18:48:13 (1763336893) [ 522.687105] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing load_modules_local [ 529.513664] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 529.914059] LustreError: 26058: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. [ 529.936856] LustreError: 26058:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 5 previous similar messages [ 530.027587] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 533.700964] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 535.009735] LustreError: 26076: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. [ 535.025674] LustreError: 26076:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 1 previous similar message [ 540.128717] LustreError: 26076: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. [ 543.171307] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 543.645558] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 548.198139] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 552.467592] Lustre: 27167:0:(mgs_llog.c:1346:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 559.991932] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 560.188669] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 564.802936] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 568.357422] LustreError: 27523: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. [ 571.345206] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 574.704449] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:41 to 0x280000401:65) [ 574.705679] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:41 to 0x2c0000401:65) [ 575.924554] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 582.101302] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 585.093898] Lustre: 29015:0:(mgs_llog.c:1346:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 591.315329] Lustre: 29034:0:(osd_internal.h:1472:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 591.320347] Lustre: 29034:0:(osd_internal.h:1472:osd_trans_exec_op()) Skipped 60 previous similar messages [ 591.324468] Lustre: 29034:0:(osd_handler.c:2082:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 591.329399] Lustre: 29034:0:(osd_handler.c:2082:osd_trans_dump_creds()) Skipped 53 previous similar messages [ 591.334867] Lustre: 29034:0:(osd_handler.c:2089:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 591.339125] Lustre: 29034:0:(osd_handler.c:2089:osd_trans_dump_creds()) Skipped 61 previous similar messages [ 591.343970] Lustre: 29034:0:(osd_handler.c:2099:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 591.347176] Lustre: 29034:0:(osd_handler.c:2099:osd_trans_dump_creds()) Skipped 61 previous similar messages [ 591.356909] Lustre: 29034:0:(osd_handler.c:2106:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 591.361217] Lustre: 29034:0:(osd_handler.c:2106:osd_trans_dump_creds()) Skipped 61 previous similar messages [ 591.368109] Lustre: 29034:0:(osd_handler.c:2113:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 591.371750] Lustre: 29034:0:(osd_handler.c:2113:osd_trans_dump_creds()) Skipped 61 previous similar messages [ 597.197574] Lustre: *** cfs_fail_loc=1501, val=0*** [ 602.889779] Lustre: Failing over lustre-MDT0000 [ 602.976877] LustreError: 29404:0:(obd_class.h:479:obd_check_dev()) Device 10 not setup [ 602.982132] LustreError: 29404:0:(obd_class.h:479:obd_check_dev()) Skipped 5 previous similar messages [ 603.039946] Lustre: server umount lustre-MDT0000 complete [ 605.155351] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 605.160182] 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 [ 605.187079] LustreError: 26058: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. [ 611.382597] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 611.504754] LustreError: MGC192.168.201.148@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 611.717861] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 611.720299] Lustre: Skipped 1 previous similar message [ 611.758041] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 615.099053] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 616.930505] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 616.931019] Lustre: lustre-MDT0000: Denying connection for new client 0bf15b02-8986-4852-9894-aef1d8855013 (at 192.168.201.48@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:59 [ 616.938820] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 616.963620] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 616.986594] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:106 to 0x280000401:129) [ 616.986963] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:105 to 0x2c0000401:129) [ 623.145521] Lustre: *** cfs_fail_loc=1505, val=0*** [ 629.985507] Lustre: DEBUG MARKER: == sanity-lfsck test 1b: LFSCK can find out and repair the missing FID-in-LMA ========================================================== 18:50:08 (1763337008) [ 631.334260] Lustre: 28782:0:(osd_internal.h:1472:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 631.340385] Lustre: 28782:0:(osd_internal.h:1472:osd_trans_exec_op()) Skipped 326 previous similar messages [ 631.344951] Lustre: 28782:0:(osd_handler.c:2082:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 631.350764] Lustre: 28782:0:(osd_handler.c:2082:osd_trans_dump_creds()) Skipped 326 previous similar messages [ 631.354278] Lustre: 28782:0:(osd_handler.c:2089:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 631.365768] Lustre: 28782:0:(osd_handler.c:2089:osd_trans_dump_creds()) Skipped 326 previous similar messages [ 631.371218] Lustre: 28782:0:(osd_handler.c:2099:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 631.376850] Lustre: 28782:0:(osd_handler.c:2099:osd_trans_dump_creds()) Skipped 326 previous similar messages [ 631.380198] Lustre: 28782:0:(osd_handler.c:2106:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 631.384707] Lustre: 28782:0:(osd_handler.c:2106:osd_trans_dump_creds()) Skipped 326 previous similar messages [ 631.389556] Lustre: 28782:0:(osd_handler.c:2113:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 631.393841] Lustre: 28782:0:(osd_handler.c:2113:osd_trans_dump_creds()) Skipped 326 previous similar messages [ 636.743152] Lustre: *** cfs_fail_loc=1502, val=0*** [ 645.605047] Lustre: Failing over lustre-MDT0000 [ 645.722910] LustreError: 31066:0:(obd_class.h:479:obd_check_dev()) Device 10 not setup [ 645.727930] LustreError: 31066:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 647.648411] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 647.654940] 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 [ 647.655461] LustreError: 26054: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. [ 647.655468] LustreError: 26054:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 7 previous similar messages [ 647.684119] Lustre: Skipped 6 previous similar messages [ 647.820174] Lustre: server umount lustre-MDT0000 complete [ 658.131151] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 658.235067] LustreError: MGC192.168.201.148@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 658.525672] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 661.279274] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 662.686175] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 662.691960] Lustre: lustre-MDT0000: Denying connection for new client d846efcb-9299-4a98-983e-49e57c80fb5f (at 192.168.201.48@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:59 [ 663.526424] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 663.529195] Lustre: Skipped 3 previous similar messages [ 663.540683] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 663.570606] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:169 to 0x2c0000401:193) [ 663.571936] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:170 to 0x280000401:193) [ 668.855038] Lustre: *** cfs_fail_loc=1505, val=0*** [ 677.184579] Lustre: DEBUG MARKER: == sanity-lfsck test 1c: LFSCK can find out and repair lost FID-in-dirent ========================================================== 18:50:55 (1763337055) [ 678.785748] Lustre: 26054:0:(osd_internal.h:1472:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 678.797393] Lustre: 26054:0:(osd_internal.h:1472:osd_trans_exec_op()) Skipped 326 previous similar messages [ 678.804252] Lustre: 26054:0:(osd_handler.c:2082:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 678.810303] Lustre: 26054:0:(osd_handler.c:2082:osd_trans_dump_creds()) Skipped 326 previous similar messages [ 678.815076] Lustre: 26054:0:(osd_handler.c:2089:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 678.819046] Lustre: 26054:0:(osd_handler.c:2089:osd_trans_dump_creds()) Skipped 326 previous similar messages [ 678.823738] Lustre: 26054:0:(osd_handler.c:2099:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 678.829053] Lustre: 26054:0:(osd_handler.c:2099:osd_trans_dump_creds()) Skipped 326 previous similar messages [ 678.833877] Lustre: 26054:0:(osd_handler.c:2106:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 678.837602] Lustre: 26054:0:(osd_handler.c:2106:osd_trans_dump_creds()) Skipped 326 previous similar messages [ 678.840085] Lustre: 26054:0:(osd_handler.c:2113:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 678.845313] Lustre: 26054:0:(osd_handler.c:2113:osd_trans_dump_creds()) Skipped 326 previous similar messages [ 684.725289] Lustre: *** cfs_fail_loc=1504, val=0*** [ 684.733120] Lustre: *** cfs_fail_loc=1504, val=0*** [ 684.735192] Lustre: Skipped 1 previous similar message [ 691.610919] Lustre: Failing over lustre-MDT0000 [ 691.731968] LustreError: 32624:0:(obd_class.h:479:obd_check_dev()) Device 10 not setup [ 691.743082] LustreError: 32624:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 691.826050] Lustre: server umount lustre-MDT0000 complete [ 694.241549] 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 [ 694.247864] LustreError: 29034: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. [ 694.248076] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 694.267740] Lustre: Skipped 2 previous similar messages [ 694.300795] LustreError: 29034:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 14 previous similar messages [ 701.552688] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 701.785553] LustreError: MGC192.168.201.148@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 702.027573] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 702.030635] Lustre: Skipped 1 previous similar message [ 702.065154] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 705.041230] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 706.981263] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 706.992640] Lustre: lustre-MDT0000: Denying connection for new client ce0c8107-cbe9-4cbe-9dc3-d0f3deb91d5e (at 192.168.201.48@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:59 [ 707.048736] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 707.051806] Lustre: Skipped 3 previous similar messages [ 707.064620] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 707.090027] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:233 to 0x280000401:257) [ 707.090026] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:234 to 0x2c0000401:257) [ 713.910492] Lustre: *** cfs_fail_loc=1505, val=0*** [ 720.044433] Lustre: DEBUG MARKER: == sanity-lfsck test 2a: LFSCK can find out and repair crashed linkEA entry ========================================================== 18:51:39 (1763337099) [ 725.716666] Lustre: *** cfs_fail_loc=1603, val=0*** [ 732.405371] Lustre: Failing over lustre-MDT0000 [ 732.551554] LustreError: 34180:0:(obd_class.h:479:obd_check_dev()) Device 10 not setup [ 732.553844] LustreError: 34180:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 732.602755] Lustre: server umount lustre-MDT0000 complete [ 732.639797] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 732.676831] 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 [ 732.681020] Lustre: Skipped 1 previous similar message [ 732.687328] LustreError: 26054: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. [ 732.726747] LustreError: 26054:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 7 previous similar messages [ 742.452742] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 742.592813] LustreError: MGC192.168.201.148@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 742.980446] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 747.188328] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 748.002414] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 748.011527] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 748.019025] Lustre: Skipped 3 previous similar messages [ 748.029125] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 748.070247] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:298 to 0x2c0000401:321) [ 748.072763] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:297 to 0x280000401:321) [ 755.510245] Lustre: DEBUG MARKER: == sanity-lfsck test 2b: LFSCK can find out and remove invalid linkEA entry ========================================================== 18:52:14 (1763337134) [ 756.925447] Lustre: 26054:0:(osd_internal.h:1472:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 756.930659] Lustre: 26054:0:(osd_internal.h:1472:osd_trans_exec_op()) Skipped 652 previous similar messages [ 756.941627] Lustre: 26054:0:(osd_handler.c:2082:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 756.945945] Lustre: 26054:0:(osd_handler.c:2082:osd_trans_dump_creds()) Skipped 652 previous similar messages [ 756.952885] Lustre: 26054:0:(osd_handler.c:2089:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 756.959221] Lustre: 26054:0:(osd_handler.c:2089:osd_trans_dump_creds()) Skipped 652 previous similar messages [ 756.971988] Lustre: 26054:0:(osd_handler.c:2099:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 756.975595] Lustre: 26054:0:(osd_handler.c:2099:osd_trans_dump_creds()) Skipped 652 previous similar messages [ 756.983435] Lustre: 26054:0:(osd_handler.c:2106:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 756.991581] Lustre: 26054:0:(osd_handler.c:2106:osd_trans_dump_creds()) Skipped 652 previous similar messages [ 756.995190] Lustre: 26054:0:(osd_handler.c:2113:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 757.000831] Lustre: 26054:0:(osd_handler.c:2113:osd_trans_dump_creds()) Skipped 652 previous similar messages [ 762.059210] Lustre: *** cfs_fail_loc=1604, val=0*** [ 767.869455] Lustre: Failing over lustre-MDT0000 [ 768.069365] Lustre: server umount lustre-MDT0000 complete [ 768.481628] 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 [ 768.482200] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 768.488210] Lustre: Skipped 6 previous similar messages [ 777.208329] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 777.326831] LustreError: MGC192.168.201.148@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 777.545159] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 780.809764] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 782.817660] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 782.837417] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 782.837427] Lustre: Skipped 3 previous similar messages [ 782.889603] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 782.915684] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:362 to 0x2c0000401:385) [ 782.917416] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:361 to 0x280000401:385) [ 789.651809] Lustre: DEBUG MARKER: == sanity-lfsck test 2c: LFSCK can find out and remove repeated linkEA entry ========================================================== 18:52:48 (1763337168) [ 796.567910] Lustre: *** cfs_fail_loc=1605, val=0*** [ 802.825100] Lustre: Failing over lustre-MDT0000 [ 802.971590] LustreError: 37096:0:(obd_class.h:479:obd_check_dev()) Device 10 not setup [ 802.984535] LustreError: 37096:0:(obd_class.h:479:obd_check_dev()) Skipped 15 previous similar messages [ 803.076273] Lustre: server umount lustre-MDT0000 complete [ 803.295836] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 803.298210] 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 [ 803.301574] LustreError: 26057: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. [ 803.301585] LustreError: 26057:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 12 previous similar messages [ 803.348988] Lustre: Skipped 3 previous similar messages [ 812.087518] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 812.162931] LustreError: MGC192.168.201.148@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 812.428664] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 815.608500] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 817.485662] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 817.492403] Lustre: lustre-MDT0000: Denying connection for new client c0d72827-095a-431e-b13f-fc8b894c9537 (at 192.168.201.48@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:59 [ 817.636149] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 817.642544] Lustre: Skipped 3 previous similar messages [ 817.654360] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 817.691872] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:425 to 0x280000401:449) [ 817.696230] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:426 to 0x2c0000401:449) [ 828.834940] Lustre: DEBUG MARKER: == sanity-lfsck test 2d: LFSCK can recover the missing linkEA entry ========================================================== 18:53:27 (1763337207) [ 835.657987] Lustre: *** cfs_fail_loc=161d, val=0*** [ 841.706148] Lustre: Failing over lustre-MDT0000 [ 841.963471] Lustre: server umount lustre-MDT0000 complete [ 843.232811] 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 [ 843.254099] Lustre: Skipped 2 previous similar messages [ 850.023569] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 850.111678] LustreError: MGC192.168.201.148@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 850.330537] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 850.334949] Lustre: Skipped 3 previous similar messages [ 850.372958] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 853.459418] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 855.169801] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 855.177682] Lustre: lustre-MDT0000: Denying connection for new client c867d9eb-6d10-4808-8f94-693088909735 (at 192.168.201.48@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:59 [ 855.530064] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 855.533181] Lustre: Skipped 3 previous similar messages [ 855.537417] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 855.571181] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:490 to 0x2c0000401:513) [ 855.575100] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:489 to 0x280000401:513) [ 864.844643] Lustre: DEBUG MARKER: == sanity-lfsck test 2e: namespace LFSCK can verify remote object linkEA ========================================================== 18:54:03 (1763337243) [ 866.888132] Lustre: *** cfs_fail_loc=1603, val=0*** [ 874.469206] Lustre: DEBUG MARKER: == sanity-lfsck test 3: LFSCK can verify multiple-linked objects ========================================================== 18:54:13 (1763337253) [ 879.762233] Lustre: *** cfs_fail_loc=1603, val=0*** [ 880.410280] Lustre: *** cfs_fail_loc=1604, val=0*** [ 885.542907] Lustre: 29166:0:(osd_internal.h:1472:osd_trans_exec_op()) lustre-OST0001: opcode 2: before 259 < left 274, rollback = 2 [ 885.547175] Lustre: 29166:0:(osd_internal.h:1472:osd_trans_exec_op()) Skipped 1305 previous similar messages [ 885.552989] Lustre: 29166:0:(osd_handler.c:2082:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 885.557465] Lustre: 29166:0:(osd_handler.c:2082:osd_trans_dump_creds()) Skipped 1305 previous similar messages [ 885.564739] Lustre: 29166:0:(osd_handler.c:2089:osd_trans_dump_creds()) attr_set: 1/1/1, xattr_set: 2/274/0 [ 885.580222] Lustre: 29166:0:(osd_handler.c:2089:osd_trans_dump_creds()) Skipped 1305 previous similar messages [ 885.587849] Lustre: 29166:0:(osd_handler.c:2099:osd_trans_dump_creds()) write: 0/0/0, punch: 0/0/0, quota 7/225/0 [ 885.591308] Lustre: 29166:0:(osd_handler.c:2099:osd_trans_dump_creds()) Skipped 1305 previous similar messages [ 885.593927] Lustre: 29166:0:(osd_handler.c:2106:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 885.597096] Lustre: 27526:0:(osd_handler.c:2113:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 885.597107] Lustre: 27526:0:(osd_handler.c:2113:osd_trans_dump_creds()) Skipped 1305 previous similar messages [ 885.613085] Lustre: 29166:0:(osd_handler.c:2106:osd_trans_dump_creds()) Skipped 1306 previous similar messages [ 888.037254] Lustre: DEBUG MARKER: == sanity-lfsck test 4: FID-in-dirent can be rebuilt after MDT file-level backup/restore ========================================================== 18:54:27 (1763337267) [ 922.217628] Lustre: Failing over lustre-MDT0000 [ 922.444131] Lustre: server umount lustre-MDT0000 complete [ 926.587261] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 927.199878] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 927.200755] 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 [ 927.219554] Lustre: Skipped 4 previous similar messages [ 932.323106] LustreError: 26057: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. [ 932.347704] LustreError: 26057:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 22 previous similar messages [ 933.068759] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 933.794345] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 942.608360] Lustre: 16284:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763337306/real 1763337306] req@ffff90033afdc380 x1848992556853248/t0(0) o400->MGC192.168.201.148@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1763337322 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 942.649988] LustreError: MGC192.168.201.148@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 943.659804] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 943.675120] Lustre: lustre-MDT0000: reset Object Index mappings [ 953.192401] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 957.821313] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 958.447900] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 958.452673] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 958.482447] Lustre: Skipped 3 previous similar messages [ 958.498236] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 958.532720] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:593 to 0x2c0000401:609) [ 958.533297] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:593 to 0x280000401:609) [ 962.241756] LustreError: 42548:0:(lfsck_engine.c:1018:lfsck_master_engine()) lustre-MDT0000-osd: master engine fail to verify the .lustre/lost+found/, go ahead: rc = -115 [ 962.259158] Lustre: *** cfs_fail_loc=1601, val=1*** [ 964.325871] Lustre: *** cfs_fail_loc=1601, val=1*** [ 964.333384] Lustre: Skipped 1 previous similar message [ 971.290606] Lustre: Failing over lustre-MDT0000 [ 971.395427] LustreError: 42990:0:(obd_class.h:479:obd_check_dev()) Device 10 not setup [ 971.399213] LustreError: 42990:0:(obd_class.h:479:obd_check_dev()) Skipped 23 previous similar messages [ 971.461737] Lustre: server umount lustre-MDT0000 complete [ 981.050196] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 984.789644] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 986.650047] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:593 to 0x280000401:641) [ 986.651480] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:593 to 0x2c0000401:641) [ 987.953642] Lustre: *** cfs_fail_loc=1505, val=0*** [ 994.792719] Lustre: DEBUG MARKER: == sanity-lfsck test 5: LFSCK can handle IGIF object upgrading ========================================================== 18:56:13 (1763337373) [ 997.280917] Lustre: *** cfs_fail_loc=1504, val=0*** [ 1004.299911] Lustre: Failing over lustre-MDT0000 [ 1004.520846] Lustre: server umount lustre-MDT0000 complete [ 1007.072170] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1008.783134] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1015.719112] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 1016.391247] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1023.459342] Lustre: 16284:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763337386/real 1763337386] req@ffff9003080cce00 x1848992556941312/t0(0) o400->MGC192.168.201.148@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1763337402 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1025.868331] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1025.888989] Lustre: lustre-MDT0000: reset Object Index mappings [ 1032.685767] LustreError: 16280:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9003390a5500 x1848992556949504/t0(0) o250->MGC192.168.201.148@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 [ 1032.996645] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1033.006377] Lustre: Skipped 1 previous similar message [ 1036.207405] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1038.307324] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1038.309212] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1038.321035] Lustre: Skipped 7 previous similar messages [ 1038.343879] Lustre: Skipped 1 previous similar message [ 1038.368898] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1038.379979] Lustre: Skipped 1 previous similar message [ 1038.425536] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:682 to 0x2c0000401:705) [ 1038.426624] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:681 to 0x280000401:705) [ 1039.930699] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1039.936076] Lustre: Skipped 2 previous similar messages [ 1048.159290] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1048.161206] Lustre: Skipped 7 previous similar messages [ 1053.616295] Lustre: Failing over lustre-MDT0000 [ 1053.666377] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1053.669453] Lustre: Skipped 3 previous similar messages [ 1053.990740] Lustre: server umount lustre-MDT0000 complete [ 1064.042809] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1067.319434] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1069.377661] Lustre: lustre-MDT0000: Denying connection for new client b43d6e52-a9a7-4f25-ac31-27adbc1d55b8 (at 192.168.201.48@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:59 [ 1069.606583] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:682 to 0x2c0000401:737) [ 1069.608047] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:681 to 0x280000401:737) [ 1075.712761] Lustre: *** cfs_fail_loc=1505, val=0*** [ 1075.714759] Lustre: Skipped 85 previous similar messages [ 1082.188938] Lustre: DEBUG MARKER: == sanity-lfsck test 6a: LFSCK resumes from last checkpoint (1) ========================================================== 18:57:41 (1763337461) [ 1089.555182] Lustre: *** cfs_fail_loc=1600, val=1*** [ 1107.605992] Lustre: DEBUG MARKER: == sanity-lfsck test 6b: LFSCK resumes from last checkpoint (2) ========================================================== 18:58:06 (1763337486) [ 1121.887365] Lustre: *** cfs_fail_loc=1609, val=1*** [ 1121.894466] Lustre: Skipped 15 previous similar messages [ 1138.411842] Lustre: DEBUG MARKER: == sanity-lfsck test 7a: non-stopped LFSCK should auto restarts after MDS remount (1) ========================================================== 18:58:36 (1763337516) [ 1141.553077] Lustre: 40663:0:(osd_internal.h:1472:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 1141.565430] Lustre: 40663:0:(osd_internal.h:1472:osd_trans_exec_op()) Skipped 1364 previous similar messages [ 1141.571492] Lustre: 40663:0:(osd_handler.c:2082:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 1141.581430] Lustre: 40663:0:(osd_handler.c:2082:osd_trans_dump_creds()) Skipped 1364 previous similar messages [ 1141.586571] Lustre: 40663:0:(osd_handler.c:2089:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 1141.592220] Lustre: 40663:0:(osd_handler.c:2089:osd_trans_dump_creds()) Skipped 1364 previous similar messages [ 1141.599189] Lustre: 40663:0:(osd_handler.c:2099:osd_trans_dump_creds()) write: 2/12/0, punch: 0/0/0, quota 1/3/0 [ 1141.610554] Lustre: 40663:0:(osd_handler.c:2099:osd_trans_dump_creds()) Skipped 1364 previous similar messages [ 1141.618054] Lustre: 40663:0:(osd_handler.c:2106:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 1141.620496] Lustre: 40663:0:(osd_handler.c:2106:osd_trans_dump_creds()) Skipped 1363 previous similar messages [ 1141.626210] Lustre: 40663:0:(osd_handler.c:2113:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 1141.632652] Lustre: 40663:0:(osd_handler.c:2113:osd_trans_dump_creds()) Skipped 1364 previous similar messages [ 1153.888119] Lustre: Failing over lustre-MDT0000 [ 1154.073451] Lustre: server umount lustre-MDT0000 complete [ 1156.576858] 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 [ 1156.582604] Lustre: Skipped 15 previous similar messages [ 1161.736699] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1161.909959] LustreError: MGC192.168.201.148@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1161.915078] LustreError: Skipped 3 previous similar messages [ 1162.124892] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1162.130608] Lustre: Skipped 4 previous similar messages [ 1162.171437] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1162.179859] Lustre: Skipped 1 previous similar message [ 1165.159877] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1167.333513] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1167.346636] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1167.350943] Lustre: Skipped 1 previous similar message [ 1167.373872] Lustre: Skipped 7 previous similar messages [ 1167.390707] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1167.397099] Lustre: Skipped 1 previous similar message [ 1167.439292] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:855 to 0x280000401:897) [ 1167.445270] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:855 to 0x2c0000401:897) [ 1173.170298] Lustre: DEBUG MARKER: == sanity-lfsck test 7b: non-stopped LFSCK should auto restarts after MDS remount (2) ========================================================== 18:59:12 (1763337552) [ 1184.961583] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing load_modules_local [ 1198.950085] Lustre: 52528:0:(mgs_llog.c:1346:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 1217.612939] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1220.225586] Lustre: 53664:0:(mgs_llog.c:1346:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 1232.931913] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1232.937197] Lustre: Skipped 82 previous similar messages [ 1235.358986] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1236.383668] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1237.407336] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1238.961165] Lustre: Failing over lustre-MDT0000 [ 1239.009198] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1239.024379] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1239.026624] LustreError: Skipped 1 previous similar message [ 1239.034522] Lustre: Skipped 2 previous similar messages [ 1239.119602] LustreError: 53985:0:(obd_class.h:479:obd_check_dev()) Device 10 not setup [ 1239.131341] LustreError: 53985:0:(obd_class.h:479:obd_check_dev()) Skipped 31 previous similar messages [ 1239.274700] Lustre: server umount lustre-MDT0000 complete [ 1244.130768] LustreError: 26076: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. [ 1244.157342] LustreError: 26076:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 71 previous similar messages [ 1246.138508] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1249.195890] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1251.877528] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:947 to 0x280000401:993) [ 1251.894536] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:947 to 0x2c0000401:993) [ 1257.530116] Lustre: DEBUG MARKER: == sanity-lfsck test 8: LFSCK state machine ============== 19:00:36 (1763337636) [ 1262.050731] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1267.167990] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1267.173904] Lustre: Skipped 6 previous similar messages [ 1273.311375] Lustre: lustre-MDT0000 is waiting for obd_unlinked_exports more than 8 seconds. The obd refcount = 3. Is it stuck? [ 1273.517380] Lustre: server umount lustre-MDT0000 complete [ 1276.834778] LustreError: 26039:0:(ldlm_lockd.c:2563:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1763337656 with bad export cookie 8253419789875559021 [ 1276.848439] LustreError: 26039:0:(ldlm_lockd.c:2563:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 1277.117061] Lustre: server umount lustre-MDT0001 complete [ 1289.763679] Lustre: server umount lustre-OST0000 complete [ 1292.708832] Lustre: 16283:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763337656/real 1763337656] req@ffff90033a9c3100 x1848992557257728/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1763337672 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1293.897509] Lustre: server umount lustre-OST0001 complete [ 1299.334149] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_hostid [ 1304.738407] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing load_modules_local [ 1313.982872] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 1321.100852] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 1328.329690] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 1334.779515] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 1346.909767] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing load_modules_local [ 1355.309182] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 1355.364269] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1355.584599] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 1355.636087] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 1355.700536] Lustre: lustre-MDT0000: new disk, initializing [ 1355.789983] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 1359.528667] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1369.008370] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 1369.058774] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 1369.111821] Lustre: 58752:0:(mgs_llog.c:1346:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 1369.146310] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 1369.149319] Lustre: Skipped 1 previous similar message [ 1369.199512] Lustre: lustre-MDT0001: new disk, initializing [ 1369.281109] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 1369.288171] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 1372.187525] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1376.124384] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 1381.609880] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 1381.660562] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 1381.810619] Lustre: lustre-OST0000: new disk, initializing [ 1381.821641] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 1382.997121] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 1383.004136] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 1383.082115] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 1386.764807] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1395.483461] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 1395.555434] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 1395.624388] Lustre: lustre-OST0001: new disk, initializing [ 1395.629382] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 1397.628348] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 1397.644117] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 1397.690552] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 1400.463793] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1409.758934] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1413.695029] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 1429.224893] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1430.181377] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1430.183131] Lustre: Skipped 19 previous similar messages [ 1433.747540] Lustre: *** cfs_fail_loc=1601, val=2*** [ 1433.749569] Lustre: Skipped 11 previous similar messages [ 1449.323278] Lustre: Failing over lustre-MDT0000 [ 1449.630831] Lustre: server umount lustre-MDT0000 complete [ 1451.489333] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1451.501540] LustreError: Skipped 1 previous similar message [ 1451.503274] 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 [ 1451.542827] Lustre: Skipped 9 previous similar messages [ 1458.924342] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1459.091846] LustreError: MGC192.168.201.148@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1459.096747] LustreError: Skipped 2 previous similar messages [ 1459.169823] Lustre: lustre-MDT0000: Not available for connect from 0@lo (not set up) [ 1459.175474] Lustre: Skipped 7 previous similar messages [ 1459.359283] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1459.379602] Lustre: Skipped 1 previous similar message [ 1463.344184] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1464.800470] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1464.801844] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1464.818355] Lustre: Skipped 1 previous similar message [ 1464.834288] Lustre: Skipped 7 previous similar messages [ 1464.871172] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1464.877334] Lustre: Skipped 1 previous similar message [ 1464.911400] Lustre: *** cfs_fail_loc=160b, val=2*** [ 1464.919529] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:65) [ 1464.919970] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:44 to 0x280000401:65) [ 1471.150061] Lustre: Failing over lustre-MDT0000 [ 1471.525050] Lustre: server umount lustre-MDT0000 complete [ 1479.276473] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1482.702940] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1484.800361] Lustre: *** cfs_fail_loc=160b, val=2*** [ 1484.804672] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:44 to 0x280000401:97) [ 1484.804672] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:97) [ 1486.706025] Lustre: Failing over lustre-MDT0000 [ 1486.917126] Lustre: server umount lustre-MDT0000 complete [ 1494.264409] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1498.113774] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1499.669784] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:44 to 0x280000401:129) [ 1499.671038] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:129) [ 1503.230791] Lustre: *** cfs_fail_loc=1602, val=2*** [ 1503.234062] Lustre: Skipped 1 previous similar message [ 1514.162650] Lustre: DEBUG MARKER: == sanity-lfsck test 9a: LFSCK speed control (1) ========= 19:04:53 (1763337893) [ 1524.783307] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing load_modules_local [ 1540.110899] Lustre: 68095:0:(mgs_llog.c:1346:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 1559.105052] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1561.839421] Lustre: 69231:0:(mgs_llog.c:1346:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 1682.814831] Lustre: DEBUG MARKER: == sanity-lfsck test 9b: LFSCK speed control (2) ========= 19:07:41 (1763338061) [ 1728.133971] Lustre: 70064:0:(osd_internal.h:1472:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 1728.142864] Lustre: 70064:0:(osd_internal.h:1472:osd_trans_exec_op()) Skipped 17023 previous similar messages [ 1728.153225] Lustre: 70064:0:(osd_handler.c:2082:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 1728.163299] Lustre: 70064:0:(osd_handler.c:2082:osd_trans_dump_creds()) Skipped 17023 previous similar messages [ 1728.173055] Lustre: 70064:0:(osd_handler.c:2089:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 1728.179825] Lustre: 70064:0:(osd_handler.c:2089:osd_trans_dump_creds()) Skipped 17024 previous similar messages [ 1728.184725] Lustre: 70064:0:(osd_handler.c:2099:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 1728.191679] Lustre: 70064:0:(osd_handler.c:2099:osd_trans_dump_creds()) Skipped 17024 previous similar messages [ 1728.197870] Lustre: 70064:0:(osd_handler.c:2106:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 1728.208248] Lustre: 70064:0:(osd_handler.c:2106:osd_trans_dump_creds()) Skipped 17024 previous similar messages [ 1728.212569] Lustre: 70064:0:(osd_handler.c:2113:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 1728.223763] Lustre: 70064:0:(osd_handler.c:2113:osd_trans_dump_creds()) Skipped 17023 previous similar messages [ 1733.633027] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1733.635046] Lustre: Skipped 4 previous similar messages [ 1760.074469] Lustre: *** cfs_fail_loc=160c, val=0*** [ 1760.080377] Lustre: Skipped 7 previous similar messages [ 1794.080538] Lustre: DEBUG MARKER: == sanity-lfsck test 10: System is available during LFSCK scanning ========================================================== 19:09:32 (1763338172) [ 1840.860527] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1848.872087] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1848.873782] Lustre: Skipped 442 previous similar messages [ 1864.937461] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1864.940993] Lustre: Skipped 832 previous similar messages [ 1896.943425] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1896.944952] Lustre: Skipped 1648 previous similar messages [ 1908.637330] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1908.642838] Lustre: Skipped 2599 previous similar messages [ 2137.164637] Lustre: DEBUG MARKER: == sanity-lfsck test 11a: LFSCK can rebuild lost last_id ========================================================== 19:15:15 (1763338515) [ 2303.456271] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 2303.464726] 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 [ 2303.470189] LustreError: Skipped 2 previous similar messages [ 2303.470717] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2303.493341] Lustre: Skipped 12 previous similar messages [ 2306.976637] LustreError: 73550:0:(obd_class.h:479:obd_check_dev()) Device 22 not setup [ 2306.993280] LustreError: 73550:0:(obd_class.h:479:obd_check_dev()) Skipped 57 previous similar messages [ 2307.110321] Lustre: server umount lustre-MDT0000 complete [ 2308.583346] LustreError: 70064: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. [ 2308.591115] LustreError: 70064:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 13 previous similar messages [ 2310.579748] LustreError: 73440:0:(ldlm_lockd.c:2563:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1763338689 with bad export cookie 8253419789875578362 [ 2310.583465] LustreError: MGC192.168.201.148@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2310.595858] LustreError: 73440:0:(ldlm_lockd.c:2563:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 2310.600133] LustreError: Skipped 2 previous similar messages [ 2310.906315] Lustre: server umount lustre-MDT0001 complete [ 2323.765622] Lustre: server umount lustre-OST0000 complete [ 2337.845393] Lustre: server umount lustre-OST0001 complete [ 2344.622831] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: (null) [ 2352.350582] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 2367.903885] LustreError: Failed to get MGS log lustre-sptlrpc and no local copy. [ 2373.024378] LustreError: 74954:0:(mgc_request.c:233:do_config_log_add()) MGC192.168.201.148@tcp: failed processing log, type 4: rc = -110 [ 2398.751230] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 2398.754592] Lustre: Skipped 8 previous similar messages [ 2403.952355] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2407.680160] Lustre: 75521: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. [ 2407.705808] Lustre: *** cfs_fail_loc=160e, val=3*** [ 2410.727769] Lustre: 75521:0:(ofd_dev.c:572:ofd_lfsck_out_notify()) lustre-OST0000: Rebuilt crashed LAST_ID files successfully. [ 2419.471936] Lustre: DEBUG MARKER: == sanity-lfsck test 11b: LFSCK can rebuild crashed last_id ========================================================== 19:19:58 (1763338798) [ 2432.461864] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing load_modules_local [ 2442.046260] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2442.488605] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3273 to 0x280000401:3297) [ 2446.563511] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2454.555775] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 2458.612348] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2461.704643] Lustre: 78147:0:(mgs_llog.c:1346:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 2476.596668] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 2476.799526] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 2476.803980] Lustre: Skipped 2 previous similar messages [ 2477.921785] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3208 to 0x2c0000401:3233) [ 2481.956662] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2488.744450] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 2491.757913] Lustre: 79633:0:(mgs_llog.c:1346:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 2497.942084] Lustre: 77029:0:(osd_internal.h:1472:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 256 < left 278, rollback = 2 [ 2497.949800] Lustre: 77029:0:(osd_internal.h:1472:osd_trans_exec_op()) Skipped 22028 previous similar messages [ 2497.957106] Lustre: 77029:0:(osd_handler.c:2082:osd_trans_dump_creds()) create: 1/4/2, destroy: 0/0/0 [ 2497.965275] Lustre: 77029:0:(osd_handler.c:2082:osd_trans_dump_creds()) Skipped 22029 previous similar messages [ 2497.978222] Lustre: 77029:0:(osd_handler.c:2089:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 2497.988608] Lustre: 77029:0:(osd_handler.c:2089:osd_trans_dump_creds()) Skipped 22029 previous similar messages [ 2497.994792] Lustre: 77029:0:(osd_handler.c:2099:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 2498.001217] Lustre: 77029:0:(osd_handler.c:2099:osd_trans_dump_creds()) Skipped 22029 previous similar messages [ 2498.005819] Lustre: 77029:0:(osd_handler.c:2106:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 2498.012018] Lustre: 77029:0:(osd_handler.c:2106:osd_trans_dump_creds()) Skipped 22029 previous similar messages [ 2498.020579] Lustre: 77029:0:(osd_handler.c:2113:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 2498.026381] Lustre: 77029:0:(osd_handler.c:2113:osd_trans_dump_creds()) Skipped 22029 previous similar messages [ 2500.416210] Lustre: *** cfs_fail_loc=160d, val=0*** [ 2505.379799] Lustre: Failing over lustre-OST0000 [ 2505.472813] Lustre: server umount lustre-OST0000 complete [ 2513.753087] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 2513.939859] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 2513.943325] Lustre: Skipped 2 previous similar messages [ 2514.996608] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 2515.000455] Lustre: Skipped 2 previous similar messages [ 2515.022081] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 2515.023035] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 2515.023644] Lustre: *** cfs_fail_loc=215, val=0*** [ 2515.035567] Lustre: Skipped 2 previous similar messages [ 2515.058408] Lustre: Skipped 11 previous similar messages [ 2517.739083] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2520.031989] Lustre: *** cfs_fail_loc=215, val=0*** [ 2520.034066] Lustre: Skipped 2 previous similar messages [ 2520.810077] Lustre: 81022: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. [ 2520.822961] Lustre: 81022:0:(ofd_dev.c:572:ofd_lfsck_out_notify()) lustre-OST0000: Rebuilt crashed LAST_ID files successfully. [ 2522.976982] Lustre: Failing over lustre-OST0000 [ 2523.104318] Lustre: server umount lustre-OST0000 complete [ 2530.938929] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 2532.381450] Lustre: *** cfs_fail_loc=215, val=0*** [ 2532.385544] Lustre: Skipped 1 previous similar message [ 2536.434294] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2537.440491] Lustre: *** cfs_fail_loc=215, val=0*** [ 2537.442444] Lustre: Skipped 1 previous similar message [ 2542.048061] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2542.050940] Lustre: Skipped 3 previous similar messages [ 2546.656262] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2547.992756] Lustre: server umount lustre-MDT0000 complete [ 2551.554950] LustreError: 78149:0:(ldlm_lockd.c:2563:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1763338930 with bad export cookie 8253419789877135834 [ 2551.560952] LustreError: 78149:0:(ldlm_lockd.c:2563:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 2551.823967] Lustre: server umount lustre-MDT0001 complete [ 2564.820981] Lustre: server umount lustre-OST0000 complete [ 2568.223127] Lustre: 16281:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763338931/real 1763338931] req@ffff90033d889f80 x1848992561066624/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1763338947 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2568.734376] Lustre: server umount lustre-OST0001 complete [ 2577.231312] Lustre: DEBUG MARKER: == sanity-lfsck test 12a: single command to trigger LFSCK on all devices ========================================================== 19:22:35 (1763338955) [ 2588.639909] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing load_modules_local [ 2597.749729] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2602.482820] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2611.684884] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 2612.043940] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 2612.051164] Lustre: Skipped 3 previous similar messages [ 2615.457423] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2617.900512] Lustre: 85345:0:(mgs_llog.c:1346:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 2624.104947] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 2626.430459] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3362 to 0x280000401:3393) [ 2629.253484] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2636.143748] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 2637.356729] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3208 to 0x2c0000401:3265) [ 2641.212733] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2646.938816] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 2650.084150] Lustre: 87191:0:(mgs_llog.c:1346:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 2683.013335] Lustre: DEBUG MARKER: == sanity-lfsck test 12b: auto detect Lustre device ====== 19:24:21 (1763339061) [ 2695.483788] Lustre: DEBUG MARKER: == sanity-lfsck test 13: LFSCK can repair crashed lmm_oi ========================================================== 19:24:34 (1763339074) [ 2696.597344] Lustre: *** cfs_fail_loc=160f, val=0*** [ 2706.612969] Lustre: DEBUG MARKER: == sanity-lfsck test 14a: LFSCK can repair MDT-object with dangling LOV EA reference (1) ========================================================== 19:24:45 (1763339085) [ 2710.670467] Lustre: *** cfs_fail_loc=1610, val=0*** [ 2710.672351] Lustre: Skipped 7 previous similar messages [ 2760.170703] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2760.186350] Lustre: Skipped 6 previous similar messages [ 2765.682437] Lustre: server umount lustre-MDT0000 complete [ 2769.775760] LustreError: 84215:0:(ldlm_lockd.c:2563:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1763339149 with bad export cookie 8253419789877144262 [ 2769.807360] LustreError: 84215:0:(ldlm_lockd.c:2563:ldlm_cancel_handler()) Skipped 3 previous similar messages [ 2770.145347] Lustre: server umount lustre-MDT0001 complete [ 2783.138957] Lustre: server umount lustre-OST0000 complete [ 2795.730779] Lustre: server umount lustre-OST0001 complete [ 2808.215443] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing load_modules_local [ 2815.493918] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2819.174676] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2826.110168] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 2829.293041] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2831.784336] Lustre: 93009:0:(mgs_llog.c:1346:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 2837.121120] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 2841.579849] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3554 to 0x280000401:3585) [ 2841.897993] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2848.861584] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 2850.695485] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3317 to 0x2c0000401:3361) [ 2851.762253] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:116 to 0x280000400:161) [ 2851.769170] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:116 to 0x2c0000400:161) [ 2853.792304] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2859.600200] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 2862.731561] Lustre: 94852:0:(mgs_llog.c:1346:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 2873.713537] Lustre: DEBUG MARKER: == sanity-lfsck test 14b: LFSCK can repair MDT-object with dangling LOV EA reference (2) ========================================================== 19:27:32 (1763339252) [ 2878.861477] Lustre: *** cfs_fail_loc=1610, val=0*** [ 2878.867109] Lustre: Skipped 63 previous similar messages [ 2896.595437] Lustre: server umount lustre-MDT0000 complete [ 2899.041043] LustreError: 94854:0:(ldlm_lockd.c:2563:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1763339278 with bad export cookie 8253419789877172640 [ 2899.049046] LustreError: 94854:0:(ldlm_lockd.c:2563:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 2899.232272] Lustre: server umount lustre-MDT0001 complete [ 2912.251131] LustreError: 96352:0:(obd_class.h:479:obd_check_dev()) Device 23 not setup [ 2912.253071] LustreError: 96352:0:(obd_class.h:479:obd_check_dev()) Skipped 101 previous similar messages [ 2912.290339] Lustre: server umount lustre-OST0000 complete [ 2925.211056] Lustre: server umount lustre-OST0001 complete [ 2937.464258] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing load_modules_local [ 2944.922366] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2945.252991] LustreError: 97727: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. [ 2945.267093] LustreError: 97727:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 43 previous similar messages [ 2945.304843] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 2945.308166] Lustre: Skipped 6 previous similar messages [ 2947.698732] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2953.468423] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 2956.356923] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2958.445679] Lustre: 98839:0:(mgs_llog.c:1346:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 2963.009958] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 2964.196991] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:116 to 0x280000400:193) [ 2966.782555] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2970.599507] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3682 to 0x280000401:3713) [ 2973.185680] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 2974.681556] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:116 to 0x2c0000400:193) [ 2974.690369] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3317 to 0x2c0000401:3393) [ 2978.354668] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2985.796813] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3000.168666] Lustre: DEBUG MARKER: == sanity-lfsck test 15a: LFSCK can repair unmatched MDT-object/OST-object pairs (1) ========================================================== 19:29:38 (1763339378) [ 3003.511566] Lustre: *** cfs_fail_loc=1611, val=0*** [ 3003.513176] Lustre: Skipped 63 previous similar messages [ 3003.691656] Lustre: *** cfs_fail_loc=1611, val=0*** [ 3012.510659] Lustre: DEBUG MARKER: == sanity-lfsck test 15b: LFSCK can repair unmatched MDT-object/OST-object pairs (2) ========================================================== 19:29:51 (1763339391) [ 3014.374793] Lustre: *** cfs_fail_loc=1612, val=0*** [ 3014.377681] Lustre: Skipped 1 previous similar message [ 3014.422719] Lustre: *** cfs_fail_loc=1612, val=0*** [ 3014.433322] Lustre: Skipped 3 previous similar messages [ 3024.567172] Lustre: DEBUG MARKER: == sanity-lfsck test 15c: LFSCK can repair unmatched MDT-object/OST-object pairs (3) ========================================================== 19:30:03 (1763339403) [ 3026.313802] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_15c MDS newer than 2.7.55, LU-6475 [ 3028.129991] Lustre: DEBUG MARKER: == sanity-lfsck test 15d: LFSCK don't crash upon dir migration failure ========================================================== 19:30:06 (1763339406) [ 3034.334902] Lustre: *** cfs_fail_loc=1709, val=0*** [ 3034.354740] LustreError: 97737:0:(mdt_reint.c:2564:mdt_reint_migrate()) lustre-MDT0000: migrate [0x240002340:0x6c:0x0]/f14 failed: rc = -5 [ 3101.665512] 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 [ 3101.668457] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3101.679539] Lustre: Skipped 22 previous similar messages [ 3101.683584] Lustre: Skipped 6 previous similar messages [ 3107.466485] Lustre: server umount lustre-MDT0000 complete [ 3114.004641] LustreError: 102206:0:(ldlm_lockd.c:2563:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1763339493 with bad export cookie 8253419789877187368 [ 3114.011256] LustreError: MGC192.168.201.148@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3114.016131] LustreError: Skipped 3 previous similar messages [ 3114.292909] Lustre: server umount lustre-MDT0001 complete [ 3130.732965] Lustre: server umount lustre-OST0000 complete [ 3133.284455] Lustre: 16284:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763339496/real 1763339496] req@ffff90033b3c6680 x1848992562042240/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1763339512 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3135.265080] Lustre: 16281:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763339498/real 1763339498] req@ffff900307ba2d80 x1848992562042496/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1763339514 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3137.900271] Lustre: server umount lustre-OST0001 complete [ 3151.522814] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing unload_modules_local [ 3153.965502] Key type lgssc unregistered [ 3154.188358] LNet: 104502:0:(lib-ptl.c:967:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 3154.200569] LNetError: 104502:0:(acceptor.c:264:lnet_acceptor_remove_socket()) Interface ens2 not found [ 3154.221690] LNet: Removed LNI 192.168.201.148@tcp [ 3154.938227] Key type .llcrypt unregistered [ 3154.943807] Key type ._llcrypt unregistered [ 3174.288791] Key type ._llcrypt registered [ 3174.303837] Key type .llcrypt registered [ 3174.419682] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_hostid [ 3185.417469] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing load_modules_local [ 3186.084101] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 3186.168510] alg: No test for adler32 (adler32-zlib) [ 3187.187905] Lustre: Lustre: Build Version: 2.16.61_51_gca28732 [ 3187.397363] LNet: Added LNI 192.168.201.148@tcp [8/256/0/180] [ 3189.063344] Key type lgssc registered [ 3189.970151] Lustre: Echo OBD driver; http://www.lustre.org/ [ 3199.239746] LDISKFS-fs (vdc): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 3206.085576] LDISKFS-fs (vdd): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 3213.129103] LDISKFS-fs (vde): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 3219.897201] LDISKFS-fs (vdf): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 3232.810167] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing load_modules_local [ 3244.063745] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 3244.111059] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 3244.128803] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3245.330679] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 3245.376421] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 3245.437866] Lustre: lustre-MDT0000: new disk, initializing [ 3245.540425] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3245.553549] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 3248.953342] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3262.445090] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 3262.561570] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 3262.691658] Lustre: 108889:0:(mgs_llog.c:1346:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 3262.783988] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 3262.786412] Lustre: Skipped 1 previous similar message [ 3262.960429] Lustre: lustre-MDT0001: new disk, initializing [ 3263.067034] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 3263.122521] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 3263.131934] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 3268.004561] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3273.476792] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 3283.671707] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 3283.758681] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 3284.048799] Lustre: lustre-OST0000: new disk, initializing [ 3284.064531] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 3284.136358] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 3288.634513] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 3288.668802] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 3288.748588] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 3290.048878] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3302.557565] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 3302.617784] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 3302.755578] Lustre: lustre-OST0001: new disk, initializing [ 3302.767694] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 3302.842970] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 3308.092948] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3308.616286] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 3308.626379] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 3308.660263] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 3317.382458] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3322.927095] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 3332.619469] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 19:35:11 (1763339711) === [ 3338.908701] Lustre: DEBUG MARKER: == sanity-lfsck test 16: LFSCK can repair inconsistent MDT-object/OST-object owner ========================================================== 19:35:17 (1763339717) [ 3339.134182] Lustre: 108895:0:(osd_internal.h:1472:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 251 < left 278, rollback = 2 [ 3339.142097] Lustre: 108895:0:(osd_handler.c:2082:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 3339.151349] Lustre: 108895:0:(osd_handler.c:2089:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3339.155723] Lustre: 108895:0:(osd_handler.c:2099:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 3339.162428] Lustre: 108895:0:(osd_handler.c:2106:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 3339.166990] Lustre: 108895:0:(osd_handler.c:2113:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3339.686900] Lustre: 111042:0:(osd_internal.h:1472:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 252 < left 278, rollback = 2 [ 3339.691282] Lustre: 111042:0:(osd_internal.h:1472:osd_trans_exec_op()) Skipped 9 previous similar messages [ 3339.694760] Lustre: 111042:0:(osd_handler.c:2082:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 3339.698021] Lustre: 111042:0:(osd_handler.c:2082:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3339.701502] Lustre: 111042:0:(osd_handler.c:2089:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3339.705172] Lustre: 111042:0:(osd_handler.c:2089:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3339.708757] Lustre: 111042:0:(osd_handler.c:2099:osd_trans_dump_creds()) write: 2/12/1, punch: 0/0/0, quota 7/369/2 [ 3339.712660] Lustre: 111042:0:(osd_handler.c:2099:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3339.716348] Lustre: 111042:0:(osd_handler.c:2106:osd_trans_dump_creds()) insert: 2/33/1, delete: 0/0/0 [ 3339.722425] Lustre: 111042:0:(osd_handler.c:2106:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3339.729459] Lustre: 111042:0:(osd_handler.c:2113:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3339.733488] Lustre: 111042:0:(osd_handler.c:2113:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3340.699545] Lustre: 108895:0:(osd_internal.h:1472:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 3340.708666] Lustre: 108895:0:(osd_internal.h:1472:osd_trans_exec_op()) Skipped 176 previous similar messages [ 3340.712780] Lustre: 108895:0:(osd_handler.c:2082:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 3340.722179] Lustre: 108895:0:(osd_handler.c:2082:osd_trans_dump_creds()) Skipped 176 previous similar messages [ 3340.732840] Lustre: 108895:0:(osd_handler.c:2089:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3340.745100] Lustre: 108895:0:(osd_handler.c:2089:osd_trans_dump_creds()) Skipped 176 previous similar messages [ 3340.758156] Lustre: 108895:0:(osd_handler.c:2099:osd_trans_dump_creds()) write: 2/12/0, punch: 0/0/0, quota 7/369/0 [ 3340.761992] Lustre: 108895:0:(osd_handler.c:2099:osd_trans_dump_creds()) Skipped 176 previous similar messages [ 3340.765574] Lustre: 108895:0:(osd_handler.c:2106:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 3340.770370] Lustre: 108895:0:(osd_handler.c:2106:osd_trans_dump_creds()) Skipped 176 previous similar messages [ 3340.774278] Lustre: 108895:0:(osd_handler.c:2113:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3340.779471] Lustre: 108895:0:(osd_handler.c:2113:osd_trans_dump_creds()) Skipped 176 previous similar messages [ 3342.255342] Lustre: *** cfs_fail_loc=1613, val=0*** [ 3351.026234] Lustre: DEBUG MARKER: == sanity-lfsck test 17: LFSCK can repair multiple references ========================================================== 19:35:29 (1763339729) [ 3352.198101] Lustre: 108895:0:(osd_internal.h:1472:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 3352.206695] Lustre: 108895:0:(osd_internal.h:1472:osd_trans_exec_op()) Skipped 122 previous similar messages [ 3352.215570] Lustre: 108895:0:(osd_handler.c:2082:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 3352.221105] Lustre: 108895:0:(osd_handler.c:2082:osd_trans_dump_creds()) Skipped 122 previous similar messages [ 3352.230321] Lustre: 108895:0:(osd_handler.c:2089:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3352.240259] Lustre: 108895:0:(osd_handler.c:2089:osd_trans_dump_creds()) Skipped 122 previous similar messages [ 3352.248367] Lustre: 108895:0:(osd_handler.c:2099:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 3352.261559] Lustre: 108895:0:(osd_handler.c:2099:osd_trans_dump_creds()) Skipped 122 previous similar messages [ 3352.269642] Lustre: 108895:0:(osd_handler.c:2106:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 3352.274633] Lustre: 108895:0:(osd_handler.c:2106:osd_trans_dump_creds()) Skipped 122 previous similar messages [ 3352.278649] Lustre: 108895:0:(osd_handler.c:2113:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3352.282465] Lustre: 108895:0:(osd_handler.c:2113:osd_trans_dump_creds()) Skipped 122 previous similar messages [ 3353.582304] Lustre: *** cfs_fail_loc=1614, val=0*** [ 3354.135451] Lustre: *** cfs_fail_loc=1614, val=103*** [ 3354.140115] Lustre: Skipped 1 previous similar message [ 3358.986497] Lustre: 110791:0:(osd_internal.h:1472:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 259 < left 275, rollback = 2 [ 3358.991295] Lustre: 110791:0:(osd_internal.h:1472:osd_trans_exec_op()) Skipped 11 previous similar messages [ 3359.000459] Lustre: 110791:0:(osd_handler.c:2082:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 3359.013329] Lustre: 110791:0:(osd_handler.c:2082:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3359.020391] Lustre: 110791:0:(osd_handler.c:2089:osd_trans_dump_creds()) attr_set: 1/1/1, xattr_set: 3/275/0 [ 3359.024930] Lustre: 110791:0:(osd_handler.c:2089:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3359.028831] Lustre: 110791:0:(osd_handler.c:2099:osd_trans_dump_creds()) write: 1/12/0, punch: 1/4/0, quota 7/225/0 [ 3359.032535] Lustre: 110791:0:(osd_handler.c:2099:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3359.039697] Lustre: 110791:0:(osd_handler.c:2106:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 3359.053973] Lustre: 110791:0:(osd_handler.c:2106:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3359.057762] Lustre: 110791:0:(osd_handler.c:2113:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3359.063343] Lustre: 110791:0:(osd_handler.c:2113:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3367.557919] Lustre: DEBUG MARKER: == sanity-lfsck test 18a: Find out orphan OST-object and repair it (1) ========================================================== 19:35:45 (1763339745) [ 3367.943961] Lustre: 111042:0:(osd_internal.h:1472:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 3367.953832] Lustre: 111042:0:(osd_internal.h:1472:osd_trans_exec_op()) Skipped 1 previous similar message [ 3367.959156] Lustre: 111042:0:(osd_handler.c:2082:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 3367.963567] Lustre: 111042:0:(osd_handler.c:2082:osd_trans_dump_creds()) Skipped 1 previous similar message [ 3367.968683] Lustre: 111042:0:(osd_handler.c:2089:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3367.973557] Lustre: 111042:0:(osd_handler.c:2089:osd_trans_dump_creds()) Skipped 1 previous similar message [ 3367.978246] Lustre: 111042:0:(osd_handler.c:2099:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 3367.982884] Lustre: 111042:0:(osd_handler.c:2099:osd_trans_dump_creds()) Skipped 1 previous similar message [ 3367.990631] Lustre: 111042:0:(osd_handler.c:2106:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 3367.995289] Lustre: 111042:0:(osd_handler.c:2106:osd_trans_dump_creds()) Skipped 1 previous similar message [ 3367.999658] Lustre: 111042:0:(osd_handler.c:2113:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3368.011279] Lustre: 111042:0:(osd_handler.c:2113:osd_trans_dump_creds()) Skipped 1 previous similar message [ 3370.828348] Lustre: *** cfs_fail_loc=1615, val=0*** [ 3370.843750] Lustre: Skipped 1 previous similar message [ 3372.446244] Lustre: *** cfs_fail_loc=1615, val=0*** [ 3372.463825] Lustre: Skipped 1 previous similar message [ 3379.501282] LustreError: 114117:0:(lfsck_layout.c:2091:lfsck_layout_add_comp()) five: Five five five five five five file Hello [0x2c0000401:0x2:0x0] and [0x2c0000401:0x2:0x0]d: rc = 0 [ 3393.940026] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_18b skipping excluded test 18b [ 3395.531837] Lustre: DEBUG MARKER: == sanity-lfsck test 18c: Find out orphan OST-object and repair it (3) ========================================================== 19:36:14 (1763339774) [ 3395.949651] Lustre: 111042:0:(osd_internal.h:1472:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 3395.956924] Lustre: 111042:0:(osd_internal.h:1472:osd_trans_exec_op()) Skipped 21 previous similar messages [ 3395.961941] Lustre: 111042:0:(osd_handler.c:2082:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 3395.967120] Lustre: 111042:0:(osd_handler.c:2082:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3395.972688] Lustre: 111042:0:(osd_handler.c:2089:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3395.976706] Lustre: 111042:0:(osd_handler.c:2089:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3395.981850] Lustre: 111042:0:(osd_handler.c:2099:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 3395.986873] Lustre: 111042:0:(osd_handler.c:2099:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3395.997616] Lustre: 111042:0:(osd_handler.c:2106:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 3396.001514] Lustre: 111042:0:(osd_handler.c:2106:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3396.007881] Lustre: 111042:0:(osd_handler.c:2113:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3396.012165] Lustre: 111042:0:(osd_handler.c:2113:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3398.539342] Lustre: *** cfs_fail_loc=1617, val=0*** [ 3398.592313] Lustre: *** cfs_fail_loc=1617, val=0*** [ 3400.807741] Lustre: *** cfs_fail_loc=1616, val=0*** [ 3400.810065] Lustre: Skipped 3 previous similar messages [ 3419.715867] Lustre: DEBUG MARKER: == sanity-lfsck test 18d: Find out orphan OST-object and repair it (4) ========================================================== 19:36:38 (1763339798) [ 3421.757783] Lustre: *** cfs_fail_loc=1618, val=0*** [ 3421.759478] Lustre: Skipped 5 previous similar messages [ 3456.992203] 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 [ 3456.996953] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3457.019283] Lustre: Skipped 1 previous similar message [ 3457.027555] Lustre: Skipped 3 previous similar messages [ 3461.360947] LustreError: 115712:0:(obd_class.h:479:obd_check_dev()) Device 28 not setup [ 3461.469158] Lustre: server umount lustre-MDT0000 complete [ 3465.654289] LustreError: 108881:0:(ldlm_lockd.c:2563:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1763339845 with bad export cookie 9614157159028611907 [ 3465.656092] LustreError: MGC192.168.201.148@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3465.661324] LustreError: 108881:0:(ldlm_lockd.c:2563:ldlm_cancel_handler()) Skipped 3 previous similar messages [ 3465.880934] LustreError: 115913:0:(obd_class.h:479:obd_check_dev()) Device 27 not setup [ 3465.895736] LustreError: 115913:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 3466.086970] Lustre: server umount lustre-MDT0001 complete [ 3480.204212] LustreError: 116114:0:(obd_class.h:479:obd_check_dev()) Device 19 not setup [ 3480.215315] LustreError: 116114:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 3480.292127] Lustre: server umount lustre-OST0000 complete [ 3482.591286] Lustre: 106059:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763339846/real 1763339846] req@ffff900307450a80 x1848995548967936/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1763339862 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3482.620415] 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 [ 3482.630130] Lustre: Skipped 2 previous similar messages [ 3483.870325] LustreError: 116316:0:(obd_class.h:479:obd_check_dev()) Device 2 not setup [ 3483.876839] LustreError: 116316:0:(obd_class.h:479:obd_check_dev()) Skipped 3 previous similar messages [ 3484.016527] Lustre: server umount lustre-OST0001 complete [ 3498.773814] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing load_modules_local [ 3509.109700] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3509.414352] LustreError: 117489: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. [ 3509.431859] LustreError: 117489:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 5 previous similar messages [ 3509.490462] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3513.449279] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3514.856170] LustreError: 117489: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. [ 3518.950761] LustreError: 117489: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. [ 3522.106032] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 3522.328663] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 3526.272190] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3528.979044] Lustre: 118597:0:(mgs_llog.c:1346:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3535.800876] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 3541.575512] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3547.366989] LustreError: 118953: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. [ 3547.378811] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:4 to 0x280000400:33) [ 3549.991733] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 3550.149675] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 3550.154337] Lustre: Skipped 1 previous similar message [ 3551.306818] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:33) [ 3554.408908] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:4 to 0x2c0000401:33) [ 3554.436714] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:116 to 0x280000401:161) [ 3556.405463] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3562.628932] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3565.700149] Lustre: 120448:0:(mgs_llog.c:1346:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 3583.358367] Lustre: DEBUG MARKER: == sanity-lfsck test 18e: Find out orphan OST-object and repair it (5) ========================================================== 19:39:21 (1763339961) [ 3583.716324] Lustre: 120411:0:(osd_internal.h:1472:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 3583.720973] Lustre: 120411:0:(osd_internal.h:1472:osd_trans_exec_op()) Skipped 46 previous similar messages [ 3583.725522] Lustre: 120411:0:(osd_handler.c:2082:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 3583.728761] Lustre: 120411:0:(osd_handler.c:2082:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 3583.733847] Lustre: 120411:0:(osd_handler.c:2089:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3583.738015] Lustre: 120411:0:(osd_handler.c:2089:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 3583.742240] Lustre: 120411:0:(osd_handler.c:2099:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 3583.746922] Lustre: 120411:0:(osd_handler.c:2099:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 3583.751091] Lustre: 120411:0:(osd_handler.c:2106:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 3583.756300] Lustre: 120411:0:(osd_handler.c:2106:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 3583.760741] Lustre: 120411:0:(osd_handler.c:2113:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3583.765611] Lustre: 120411:0:(osd_handler.c:2113:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 3585.826360] Lustre: *** cfs_fail_loc=1618, val=0*** [ 3585.828340] Lustre: Skipped 3 previous similar messages [ 3619.808129] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3619.821095] 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 [ 3619.832803] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3621.344315] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3621.346512] Lustre: Skipped 2 previous similar messages [ 3625.020898] LustreError: 121221:0:(obd_class.h:479:obd_check_dev()) Device 10 not setup [ 3625.028501] LustreError: 121221:0:(obd_class.h:479:obd_check_dev()) Skipped 5 previous similar messages [ 3625.110847] Lustre: server umount lustre-MDT0000 complete [ 3626.464452] LustreError: 117485: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. [ 3626.483800] LustreError: 117485:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 3 previous similar messages [ 3628.428381] LustreError: 118977:0:(ldlm_lockd.c:2563:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1763340007 with bad export cookie 9614157159028627132 [ 3628.433933] LustreError: MGC192.168.201.148@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3628.463587] LustreError: 118977:0:(ldlm_lockd.c:2563:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 3628.738288] Lustre: server umount lustre-MDT0001 complete [ 3642.208925] LustreError: 121626:0:(obd_class.h:479:obd_check_dev()) Device 23 not setup [ 3642.213423] LustreError: 121626:0:(obd_class.h:479:obd_check_dev()) Skipped 15 previous similar messages [ 3642.255865] Lustre: server umount lustre-OST0000 complete [ 3654.749268] Lustre: server umount lustre-OST0001 complete [ 3668.136749] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing load_modules_local [ 3677.070673] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3677.782105] LustreError: 123002: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. [ 3677.868911] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3682.548184] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3690.780931] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 3693.922817] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3696.369950] Lustre: 124110:0:(mgs_llog.c:1346:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3702.684216] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 3704.046559] LustreError: 124467: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. [ 3704.059585] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:166 to 0x280000401:193) [ 3704.072081] LustreError: 124467:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 2 previous similar messages [ 3708.731500] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3716.582529] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:4 to 0x280000400:65) [ 3716.607395] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 3718.212412] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:65) [ 3718.214031] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:4 to 0x2c0000401:65) [ 3721.479038] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3727.816564] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3731.151676] Lustre: 125957:0:(mgs_llog.c:1346:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 3741.680447] Lustre: 123003:0:(osd_internal.h:1472:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 252 < left 260, rollback = 2 [ 3741.689479] Lustre: 123003:0:(osd_internal.h:1472:osd_trans_exec_op()) Skipped 21 previous similar messages [ 3741.699527] Lustre: 123003:0:(osd_handler.c:2082:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 3741.712946] Lustre: 123003:0:(osd_handler.c:2082:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3741.724863] Lustre: 123003:0:(osd_handler.c:2089:osd_trans_dump_creds()) attr_set: 0/0/0, xattr_set: 1/260/0 [ 3741.734184] Lustre: *** cfs_fail_loc=1602, val=10*** [ 3741.735135] Lustre: 123003:0:(osd_handler.c:2089:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3741.735162] Lustre: 123003:0:(osd_handler.c:2099:osd_trans_dump_creds()) write: 1/12/0, punch: 0/0/0, quota 4/150/2 [ 3741.735167] Lustre: 123003:0:(osd_handler.c:2099:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3741.735172] Lustre: 123003:0:(osd_handler.c:2106:osd_trans_dump_creds()) insert: 1/17/2, delete: 0/0/0 [ 3741.735174] Lustre: 123003:0:(osd_handler.c:2106:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3741.735178] Lustre: 123003:0:(osd_handler.c:2113:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3741.735181] Lustre: 123003:0:(osd_handler.c:2113:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3741.810026] Lustre: Skipped 1 previous similar message [ 3768.033124] Lustre: DEBUG MARKER: == sanity-lfsck test 18f: Skip the failed OST(s) when handle orphan OST-objects ========================================================== 19:42:26 (1763340146) [ 3771.507687] Lustre: *** cfs_fail_loc=1616, val=0*** [ 3771.515806] Lustre: Skipped 3 previous similar messages [ 3777.064959] Lustre: *** cfs_fail_loc=161c, val=0*** [ 3793.691058] Lustre: DEBUG MARKER: == sanity-lfsck test 18g: Find out orphan OST-object and repair it (7) ========================================================== 19:42:52 (1763340172) [ 3795.354929] Lustre: *** cfs_fail_loc=162e, val=0*** [ 3806.513984] Lustre: DEBUG MARKER: == sanity-lfsck test 18h: LFSCK can repair crashed PFL extent range ========================================================== 19:43:05 (1763340185) [ 3810.287403] Lustre: *** cfs_fail_loc=162f, val=0*** [ 3810.289424] Lustre: Skipped 9 previous similar messages [ 3812.434758] LustreError: 129000:0:(lfsck_layout.c:2091:lfsck_layout_add_comp()) five: Five five five five five five file Hello [0x280000401:0xc6:0x0] and [0x280000401:0xc6:0x0]d: rc = 0 [ 3826.688298] Lustre: DEBUG MARKER: == sanity-lfsck test 19a: OST-object inconsistency self detect ========================================================== 19:43:25 (1763340205) [ 3836.770720] Lustre: DEBUG MARKER: == sanity-lfsck test 19b: OST-object inconsistency self repair ========================================================== 19:43:35 (1763340215) [ 3839.171951] Lustre: *** cfs_fail_loc=1611, val=0*** [ 3839.211986] Lustre: *** cfs_fail_loc=1611, val=0*** [ 3839.214110] Lustre: Skipped 3 previous similar messages [ 3843.560179] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.201.48@tcp inode [0x2000013a1:0x1f:0x0] object 0x280000401:203 extent [0-4095], client returned csum 0 (type 4), server csum 703fb3ad (type 4) [ 3844.707629] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.201.48@tcp inode [0x2000013a1:0x20:0x0] object 0x280000401:204 extent [0-4095], client returned csum 0 (type 4), server csum 7cbb935c (type 4) [ 3852.334405] Lustre: DEBUG MARKER: == sanity-lfsck test 20a: Handle the orphan with dummy LOV EA slot properly ========================================================== 19:43:50 (1763340230) [ 3871.338257] Lustre: 130538:0:(osd_internal.h:1472:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 253 < left 263, rollback = 2 [ 3871.344169] Lustre: 130538:0:(osd_internal.h:1472:osd_trans_exec_op()) Skipped 125 previous similar messages [ 3871.348809] Lustre: 130538:0:(osd_handler.c:2082:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 3871.353285] Lustre: 130538:0:(osd_handler.c:2082:osd_trans_dump_creds()) Skipped 125 previous similar messages [ 3871.361534] Lustre: 130538:0:(osd_handler.c:2089:osd_trans_dump_creds()) attr_set: 0/0/0, xattr_set: 2/263/0 [ 3871.372845] Lustre: 130538:0:(osd_handler.c:2089:osd_trans_dump_creds()) Skipped 125 previous similar messages [ 3871.376880] Lustre: 130538:0:(osd_handler.c:2099:osd_trans_dump_creds()) write: 0/0/0, punch: 0/0/0, quota 1/3/2 [ 3871.383073] Lustre: 130538:0:(osd_handler.c:2099:osd_trans_dump_creds()) Skipped 125 previous similar messages [ 3871.391320] Lustre: 130538:0:(osd_handler.c:2106:osd_trans_dump_creds()) insert: 2/33/1, delete: 0/0/0 [ 3871.395552] Lustre: 130538:0:(osd_handler.c:2106:osd_trans_dump_creds()) Skipped 125 previous similar messages [ 3871.400458] Lustre: 130538:0:(osd_handler.c:2113:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3871.407240] Lustre: 130538:0:(osd_handler.c:2113:osd_trans_dump_creds()) Skipped 124 previous similar messages [ 3881.421940] Lustre: DEBUG MARKER: == sanity-lfsck test 20b: Handle the orphan with dummy LOV EA slot properly - PFL case ========================================================== 19:44:20 (1763340260) [ 3884.306240] Lustre: *** cfs_fail_loc=1616, val=0*** [ 3884.308098] Lustre: Skipped 7 previous similar messages [ 3888.978472] LustreError: 131230:0:(lfsck_layout.c:2091:lfsck_layout_add_comp()) five: Five five five five five five file Hello [0x280000401:0xd3:0x0] and [0x280000401:0xd3:0x0]d: rc = 0 [ 3903.981653] Lustre: DEBUG MARKER: == sanity-lfsck test 21: run all LFSCK components by default ========================================================== 19:44:42 (1763340282) [ 3912.230158] Lustre: DEBUG MARKER: == sanity-lfsck test 22a: LFSCK can repair unmatched pairs (1) ========================================================== 19:44:51 (1763340291) [ 3914.180634] Lustre: *** cfs_fail_loc=161e, val=0*** [ 3914.187847] Lustre: *** cfs_fail_loc=161e, val=0*** [ 3914.189877] Lustre: Skipped 1 previous similar message [ 3922.124040] Lustre: DEBUG MARKER: == sanity-lfsck test 22b: LFSCK can repair unmatched pairs (2) ========================================================== 19:45:01 (1763340301) [ 3923.697333] Lustre: *** cfs_fail_loc=161e, val=0*** [ 3923.710171] Lustre: *** cfs_fail_loc=161e, val=0*** [ 3932.706337] Lustre: DEBUG MARKER: == sanity-lfsck test 23a: LFSCK can repair dangling name entry (1) ========================================================== 19:45:11 (1763340311) [ 3934.125781] Lustre: *** cfs_fail_loc=1620, val=0*** [ 3945.115823] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_23b skipping excluded test 23b [ 3946.392623] Lustre: DEBUG MARKER: == sanity-lfsck test 23c: LFSCK can repair dangling name entry (3) ========================================================== 19:45:25 (1763340325) [ 3951.669377] Lustre: *** cfs_fail_loc=1621, val=142*** [ 3951.671459] Lustre: Skipped 1 previous similar message [ 3954.419902] Lustre: *** cfs_fail_loc=1602, val=10*** [ 3972.694630] Lustre: DEBUG MARKER: == sanity-lfsck test 23d: LFSCK can repair a dangling name entry to a remote object ========================================================== 19:45:51 (1763340351) [ 3974.465646] Lustre: Failing over lustre-MDT0000 [ 3974.677482] LustreError: 134731:0:(obd_class.h:479:obd_check_dev()) Device 10 not setup [ 3974.692537] LustreError: 134731:0:(obd_class.h:479:obd_check_dev()) Skipped 9 previous similar messages [ 3974.764515] Lustre: server umount lustre-MDT0000 complete [ 3977.526773] LustreError: 126267:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.201.48@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3977.543572] LustreError: 126267:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 4 previous similar messages [ 3977.698846] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3977.705133] 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 [ 3977.712300] Lustre: Skipped 3 previous similar messages [ 3981.238329] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3981.299413] LustreError: MGC192.168.201.148@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3981.428395] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3981.431157] Lustre: Skipped 3 previous similar messages [ 3981.451638] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 3982.627647] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 3983.965495] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3986.922859] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 3986.952151] Lustre: lustre-MDT0000: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 3986.988527] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:271 to 0x280000401:289) [ 3986.988537] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:138 to 0x2c0000401:161) [ 3987.002170] LustreError: 122998:0:(mdt_open.c:1315:mdt_cross_open()) lustre-MDT0000: [0x2000013a3:0x91:0x0] doesn't exist!: rc = -14 [ 3994.341077] Lustre: DEBUG MARKER: == sanity-lfsck test 24: LFSCK can repair multiple-referenced name entry ========================================================== 19:46:13 (1763340373) [ 3995.788848] Lustre: *** cfs_fail_loc=1622, val=0*** [ 3995.898268] Lustre: *** cfs_fail_loc=1622, val=0*** [ 3995.900451] Lustre: Skipped 1 previous similar message [ 4003.085454] Lustre: DEBUG MARKER: == sanity-lfsck test 25: LFSCK can repair bad file type in the name entry ========================================================== 19:46:22 (1763340382) [ 4004.424381] Lustre: *** cfs_fail_loc=1623, val=0*** [ 4011.292975] Lustre: DEBUG MARKER: == sanity-lfsck test 26a: LFSCK can add the missing local name entry back to the namespace ========================================================== 19:46:30 (1763340390) [ 4012.339221] Lustre: *** cfs_fail_loc=1624, val=0*** [ 4019.486696] Lustre: DEBUG MARKER: == sanity-lfsck test 26b: LFSCK can add the missing remote name entry back to the namespace ========================================================== 19:46:38 (1763340398) [ 4028.544353] Lustre: DEBUG MARKER: == sanity-lfsck test 27a: LFSCK can recreate the lost local parent directory as orphan ========================================================== 19:46:47 (1763340407) [ 4029.846917] Lustre: *** cfs_fail_loc=1624, val=0*** [ 4029.848732] Lustre: Skipped 1 previous similar message [ 4037.040411] Lustre: DEBUG MARKER: == sanity-lfsck test 27b: LFSCK can recreate the lost remote parent directory as orphan ========================================================== 19:46:56 (1763340416) [ 4045.343170] Lustre: DEBUG MARKER: == sanity-lfsck test 28: Skip the failed MDT(s) when handle orphan MDT-objects ========================================================== 19:47:04 (1763340424) [ 4050.378584] Lustre: *** cfs_fail_loc=161c, val=0*** [ 4050.381741] Lustre: Skipped 1 previous similar message [ 4061.539524] Lustre: DEBUG MARKER: == sanity-lfsck test 29b: LFSCK can repair bad nlink count (2) ========================================================== 19:47:20 (1763340440) [ 4063.166221] Lustre: *** cfs_fail_loc=1626, val=0*** [ 4063.168023] Lustre: Skipped 4 previous similar messages [ 4072.595653] Lustre: DEBUG MARKER: == sanity-lfsck test 29c: verify linkEA size limitation == 19:47:31 (1763340451) [ 4095.960180] Lustre: DEBUG MARKER: == sanity-lfsck test 29d: accessing non-existing inode shouldn't turn fs read-only (ldiskfs) ========================================================== 19:47:54 (1763340474) [ 4098.055672] LustreError: 122998:0:(osd_handler.c:268:osd_idc_find_or_init()) lustre-MDT0000: cannot lookup FID [0x2000013a3:0xad:0x0]: rc = -2 [ 4103.135130] Lustre: DEBUG MARKER: == sanity-lfsck test 30: LFSCK can recover the orphans from backend /lost+found ========================================================== 19:48:02 (1763340482) [ 4128.164636] Lustre: Failing over lustre-MDT0000 [ 4128.288714] LustreError: 141188:0:(obd_class.h:479:obd_check_dev()) Device 10 not setup [ 4128.292555] LustreError: 141188:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 4128.343555] Lustre: server umount lustre-MDT0000 complete [ 4130.272375] 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 [ 4130.273766] LustreError: 124850: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. [ 4130.274409] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4130.281607] Lustre: Skipped 6 previous similar messages [ 4130.292351] LustreError: 124850:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 7 previous similar messages [ 4134.854932] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 4134.952935] LustreError: MGC192.168.201.148@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4135.138099] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4135.185965] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4137.842464] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4139.448171] Lustre: 142159:0:(osd_internal.h:1472:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 264, rollback = 2 [ 4139.452087] Lustre: 142159:0:(osd_internal.h:1472:osd_trans_exec_op()) Skipped 815 previous similar messages [ 4139.455916] Lustre: 142159:0:(osd_handler.c:2082:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 4139.459016] Lustre: 142159:0:(osd_handler.c:2082:osd_trans_dump_creds()) Skipped 815 previous similar messages [ 4139.462511] Lustre: 142159:0:(osd_handler.c:2089:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 2/264/0 [ 4139.470929] Lustre: 142159:0:(osd_handler.c:2089:osd_trans_dump_creds()) Skipped 815 previous similar messages [ 4139.474792] Lustre: 142159:0:(osd_handler.c:2099:osd_trans_dump_creds()) write: 0/0/0, punch: 0/0/0, quota 1/3/0 [ 4139.478460] Lustre: 142159:0:(osd_handler.c:2099:osd_trans_dump_creds()) Skipped 815 previous similar messages [ 4139.483100] Lustre: 142159:0:(osd_handler.c:2106:osd_trans_dump_creds()) insert: 2/32/1, delete: 1/1/0 [ 4139.487334] Lustre: 142159:0:(osd_handler.c:2106:osd_trans_dump_creds()) Skipped 815 previous similar messages [ 4139.491111] Lustre: 142159:0:(osd_handler.c:2113:osd_trans_dump_creds()) ref_add: 1/1/0, ref_del: 0/0/0 [ 4139.495609] Lustre: 142159:0:(osd_handler.c:2113:osd_trans_dump_creds()) Skipped 815 previous similar messages [ 4140.513161] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4140.515056] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 4140.519573] Lustre: Skipped 3 previous similar messages [ 4140.533278] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4140.558951] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:167 to 0x2c0000401:193) [ 4140.559103] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:294 to 0x280000401:321) [ 4147.377499] Lustre: DEBUG MARKER: == sanity-lfsck test 31a: The LFSCK can find/repair the name entry with bad name hash (1) ========================================================== 19:48:46 (1763340526) [ 4156.347812] Lustre: DEBUG MARKER: == sanity-lfsck test 31b: The LFSCK can find/repair the name entry with bad name hash (2) ========================================================== 19:48:55 (1763340535) [ 4166.717034] Lustre: DEBUG MARKER: == sanity-lfsck test 31c: Re-generate the lost master LMV EA for striped directory ========================================================== 19:49:05 (1763340545) [ 4167.851494] Lustre: *** cfs_fail_loc=1629, val=0*** [ 4167.853501] Lustre: Skipped 9 previous similar messages [ 4176.176097] Lustre: DEBUG MARKER: == sanity-lfsck test 31d: Set broken striped directory (modified after broken) as read-only ========================================================== 19:49:15 (1763340555) [ 4180.014401] Lustre: Failing over lustre-MDT0000 [ 4180.177230] Lustre: server umount lustre-MDT0000 complete [ 4181.472119] 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 [ 4181.491690] Lustre: Skipped 3 previous similar messages [ 4186.361780] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4186.433863] LustreError: MGC192.168.201.148@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4186.620613] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4189.542874] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4191.301996] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4191.308439] Lustre: lustre-MDT0000: Denying connection for new client 72bdbe85-bb9b-4805-84a1-72d13f74bd41 (at 192.168.201.48@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:59 [ 4191.715150] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4191.729418] Lustre: Skipped 3 previous similar messages [ 4191.744467] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4191.782971] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:294 to 0x280000401:353) [ 4191.783625] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:167 to 0x2c0000401:225) [ 4201.298267] Lustre: Failing over lustre-MDT0000 [ 4201.510927] LustreError: 145013:0:(obd_class.h:479:obd_check_dev()) Device 10 not setup [ 4201.514048] LustreError: 145013:0:(obd_class.h:479:obd_check_dev()) Skipped 15 previous similar messages [ 4201.556712] Lustre: server umount lustre-MDT0000 complete [ 4201.953507] 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 [ 4201.954894] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4206.956821] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4207.041713] LustreError: MGC192.168.201.148@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4207.267709] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4209.868776] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4212.001089] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4212.708301] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4212.717561] Lustre: Skipped 3 previous similar messages [ 4212.733978] Lustre: lustre-MDT0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 4212.757819] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:227 to 0x2c0000401:257) [ 4212.758383] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:294 to 0x280000401:385) [ 4217.414299] Lustre: DEBUG MARKER: == sanity-lfsck test 31e: Re-generate the lost slave LMV EA for striped directory (1) ========================================================== 19:49:56 (1763340596) [ 4224.410556] Lustre: DEBUG MARKER: == sanity-lfsck test 31f: Re-generate the lost slave LMV EA for striped directory (2) ========================================================== 19:50:03 (1763340603) [ 4232.589547] Lustre: DEBUG MARKER: == sanity-lfsck test 31g: Repair the corrupted slave LMV EA ========================================================== 19:50:11 (1763340611) [ 4269.624719] Lustre: DEBUG MARKER: == sanity-lfsck test 31h: Repair the corrupted shard's name entry ========================================================== 19:50:48 (1763340648) [ 4280.562963] Lustre: DEBUG MARKER: == sanity-lfsck test 32a: stop LFSCK when some OST failed ========================================================== 19:50:59 (1763340659) [ 4287.572075] LustreError: 147935:0:(lfsck_layout.c:4468:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d sleeping for 3000ms [ 4289.508325] Lustre: Failing over lustre-OST0000 [ 4289.578435] Lustre: server umount lustre-OST0000 complete [ 4290.016199] LustreError: lustre-OST0000-osc-MDT0001: operation ost_statfs to node 0@lo failed: rc = -107 [ 4290.020878] Lustre: lustre-OST0000-osc-MDT0001: Connection to lustre-OST0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 4290.028350] Lustre: Skipped 3 previous similar messages [ 4290.030933] LustreError: 124529: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. [ 4290.041336] LustreError: 124529:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 14 previous similar messages [ 4290.652596] LustreError: 147935:0:(lfsck_layout.c:4468:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d awake [ 4290.663535] LustreError: 147935:0:(lfsck_layout.c:4468:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d sleeping for 3000ms [ 4291.527330] LustreError: 147935:0:(lfsck_layout.c:4468:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout interrupted [ 4300.648968] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 4300.757822] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 4302.134924] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4302.149258] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 4302.149308] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 4302.159719] Lustre: Skipped 3 previous similar messages [ 4304.516645] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4310.234545] Lustre: DEBUG MARKER: == sanity-lfsck test 32b: stop LFSCK when some MDT failed ========================================================== 19:51:29 (1763340689) [ 4320.846585] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing load_modules_local [ 4334.516075] Lustre: 150706:0:(mgs_llog.c:1346:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 4352.039913] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4354.671459] Lustre: 151839:0:(mgs_llog.c:1346:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 4371.623453] LustreError: 151972:0:(lfsck_striped_dir.c:1755:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d sleeping for 3000ms [ 4373.786527] Lustre: Failing over lustre-MDT0001 [ 4374.632299] LustreError: 151972:0:(lfsck_striped_dir.c:1755:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d awake [ 4374.697292] LustreError: 151971:0:(lfsck_striped_dir.c:1755:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d sleeping for 3000ms [ 4374.698325] LustreError: lustre-MDT0001-osp-MDT0000: operation out_update to node 0@lo failed: rc = -107 [ 4374.708311] LustreError: 151971:0:(lfsck_striped_dir.c:1755:lfsck_namespace_verify_stripe_slave()) Skipped 1 previous similar message [ 4374.727769] LustreError: Skipped 1 previous similar message [ 4374.727801] 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 [ 4374.727804] Lustre: Skipped 1 previous similar message [ 4374.729859] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 4374.794834] LustreError: 152124:0:(obd_class.h:479:obd_check_dev()) Device 18 not setup [ 4374.804536] LustreError: 152124:0:(obd_class.h:479:obd_check_dev()) Skipped 11 previous similar messages [ 4374.883695] Lustre: server umount lustre-MDT0001 complete [ 4376.863180] LustreError: 151971:0:(lfsck_striped_dir.c:1755:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout interrupted [ 4387.006918] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 4387.406764] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 4390.495251] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4392.417594] Lustre: lustre-MDT0001-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 4392.417670] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4392.426746] Lustre: Skipped 1 previous similar message [ 4392.446528] Lustre: lustre-MDT0001: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4392.479593] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:68 to 0x2c0000400:97) [ 4392.479718] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:71 to 0x280000400:97) [ 4398.109121] Lustre: DEBUG MARKER: == sanity-lfsck test 33: check LFSCK paramters =========== 19:52:56 (1763340776) [ 4409.749162] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing load_modules_local [ 4426.066573] Lustre: 154658:0:(mgs_llog.c:1346:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 4444.319395] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4470.736515] Lustre: DEBUG MARKER: == sanity-lfsck test 34: LFSCK can rebuild the lost agent object ========================================================== 19:54:09 (1763340849) [ 4472.175353] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_34 Only valid for ZFS backend [ 4473.867423] Lustre: DEBUG MARKER: == sanity-lfsck test 35: LFSCK can rebuild the lost agent entry ========================================================== 19:54:12 (1763340852) [ 4480.895970] Lustre: *** cfs_fail_loc=1631, val=0*** [ 4493.136541] Lustre: server umount lustre-MDT0000 complete [ 4496.529468] LustreError: 140198:0:(ldlm_lockd.c:2563:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1763340875 with bad export cookie 9614157159028704132 [ 4496.532832] LustreError: MGC192.168.201.148@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4496.540443] LustreError: 140198:0:(ldlm_lockd.c:2563:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 4496.823906] Lustre: server umount lustre-MDT0001 complete [ 4510.590797] Lustre: server umount lustre-OST0000 complete [ 4523.543247] Lustre: server umount lustre-OST0001 complete [ 4535.906284] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing load_modules_local [ 4545.307916] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4545.691947] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4545.695098] Lustre: Skipped 4 previous similar messages [ 4548.788871] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4551.136597] LustreError: 158563: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. [ 4551.144468] LustreError: 158563:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 16 previous similar messages [ 4555.463647] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 4559.380743] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4561.702299] Lustre: 159672:0:(mgs_llog.c:1346:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 4561.707986] Lustre: 159672:0:(mgs_llog.c:1346:mgs_modify_param()) Skipped 1 previous similar message [ 4566.505565] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 4570.863137] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4571.827630] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:542 to 0x280000401:577) [ 4578.552500] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 4580.119835] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:414 to 0x2c0000401:449) [ 4581.166710] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:68 to 0x2c0000400:129) [ 4581.169915] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:71 to 0x280000400:129) [ 4582.961232] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4588.817234] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4605.026741] Lustre: DEBUG MARKER: == sanity-lfsck test 36a: rebuild LOV EA for mirrored file (1) ========================================================== 19:56:23 (1763340983) [ 4606.597526] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36a needs >= 3 OSTs [ 4608.600354] Lustre: DEBUG MARKER: == sanity-lfsck test 36b: rebuild LOV EA for mirrored file (2) ========================================================== 19:56:27 (1763340987) [ 4611.127847] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36b needs >= 3 OSTs [ 4613.669876] Lustre: DEBUG MARKER: == sanity-lfsck test 36c: rebuild LOV EA for mirrored file (3) ========================================================== 19:56:31 (1763340991) [ 4615.393758] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36c needs >= 3 OSTs [ 4616.909511] Lustre: DEBUG MARKER: == sanity-lfsck test 37: LFSCK must skip a ORPHAN ======== 19:56:35 (1763340995) [ 4625.521684] Lustre: DEBUG MARKER: == sanity-lfsck test 38: LFSCK does not break foreign file and reverse is also true ========================================================== 19:56:44 (1763341004) [ 4636.037052] Lustre: DEBUG MARKER: == sanity-lfsck test 39: LFSCK does not break foreign dir and reverse is also true ========================================================== 19:56:55 (1763341015) [ 4647.111858] Lustre: DEBUG MARKER: == sanity-lfsck test 40a: LFSCK correctly fixes lmm_oi in composite layout ========================================================== 19:57:05 (1763341025) [ 4659.861734] Lustre: DEBUG MARKER: == sanity-lfsck test 41: SEL support in LFSCK ============ 19:57:18 (1763341038) [ 4661.512973] Lustre: 158558:0:(osd_internal.h:1472:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 253 < left 264, rollback = 2 [ 4661.528815] Lustre: 158558:0:(osd_internal.h:1472:osd_trans_exec_op()) Skipped 1693 previous similar messages [ 4661.542364] Lustre: 158558:0:(osd_handler.c:2082:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4661.554900] Lustre: 158558:0:(osd_handler.c:2082:osd_trans_dump_creds()) Skipped 1693 previous similar messages [ 4661.561045] Lustre: 158558:0:(osd_handler.c:2089:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 3/264/0 [ 4661.570846] Lustre: 158558:0:(osd_handler.c:2089:osd_trans_dump_creds()) Skipped 1692 previous similar messages [ 4661.577695] Lustre: 158558:0:(osd_handler.c:2099:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 4661.589362] Lustre: 158558:0:(osd_handler.c:2099:osd_trans_dump_creds()) Skipped 1693 previous similar messages [ 4661.604720] Lustre: 158558:0:(osd_handler.c:2106:osd_trans_dump_creds()) insert: 2/33/1, delete: 0/0/0 [ 4661.610498] Lustre: 158558:0:(osd_handler.c:2106:osd_trans_dump_creds()) Skipped 1692 previous similar messages [ 4661.614906] Lustre: 158558:0:(osd_handler.c:2113:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 4661.619544] Lustre: 158558:0:(osd_handler.c:2113:osd_trans_dump_creds()) Skipped 1693 previous similar messages [ 4675.752203] Lustre: DEBUG MARKER: == sanity-lfsck test 42: LFSCK repairs inconsistent MDT-object/OST-object encryption flags ========================================================== 19:57:34 (1763341054) [ 4709.678036] Lustre: *** cfs_fail_loc=1632, val=0*** [ 4723.780679] Lustre: DEBUG MARKER: == sanity-lfsck test 43: LFSCK does not loop endlessly on iget failure in scanning-phase1 ========================================================== 19:58:22 (1763341102) [ 4726.514378] Lustre: Failing over lustre-MDT0001 [ 4726.659949] LustreError: 164904:0:(obd_class.h:479:obd_check_dev()) Device 18 not setup [ 4726.663886] LustreError: 164904:0:(obd_class.h:479:obd_check_dev()) Skipped 33 previous similar messages [ 4726.774762] Lustre: server umount lustre-MDT0001 complete [ 4729.824831] 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 [ 4729.842572] Lustre: Skipped 8 previous similar messages [ 4733.097202] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 4733.418829] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 4733.421021] Lustre: lustre-MDT0001: Aborting client recovery [ 4733.428628] LustreError: 165304:0:(ldlm_lib.c:2982:target_stop_recovery_thread()) lustre-MDT0001: Aborting recovery [ 4733.439319] Lustre: 165332:0:(ldlm_lib.c:2385:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 4733.451089] Lustre: 165332:0:(genops.c:1618:class_disconnect_stale_exports()) lustre-MDT0001: disconnect stale client ed19c4ab-f32e-4fb5-8ec7-385c33a57b6c@ [ 4733.462239] Lustre: lustre-MDT0001: disconnecting 2 stale clients [ 4733.473782] Lustre: lustre-MDT0001-osd: cancel update llog [0x240000400:0x1:0x0] [ 4733.490168] Lustre: lustre-MDT0000-osp-MDT0001: cancel update llog [0x200000401:0x1:0x0] [ 4733.524698] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:71 to 0x280000400:161) [ 4733.532161] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:131 to 0x2c0000400:161) [ 4736.819863] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4738.530486] LustreError: lustre-MDT0001-osp-MDT0000: This client was evicted by lustre-MDT0001; in progress operations using this service will fail. [ 4738.539061] Lustre: lustre-MDT0001-osp-MDT0000: Connection restored to 0@lo (at 0@lo) [ 4738.542211] Lustre: Skipped 2 previous similar messages [ 4739.867354] Lustre: *** cfs_fail_loc=1e2, val=483*** [ 4743.177127] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing wait_import_state FULL osp.lustre-MDT0001-os[pc]-MDT0000.*_server_uuid [ 4743.438705] Lustre: DEBUG MARKER: osp.lustre-MDT0001-os[pc]-MDT0000.*_server_uuid in FULL state after 0 sec [ 4749.000329] Lustre: DEBUG MARKER: == sanity-lfsck test 44: umount while lfsck is stopping == 19:58:47 (1763341127) [ 4756.631112] Lustre: *** cfs_fail_loc=1600, val=3*** [ 4759.303490] Lustre: Failing over lustre-MDT0000 [ 4759.530426] Lustre: server umount lustre-MDT0000 complete [ 4764.128411] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4768.078253] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4768.220484] LustreError: MGC192.168.201.148@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4768.517478] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4768.532417] Lustre: Skipped 2 previous similar messages [ 4771.626204] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4773.206113] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4773.860939] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 4773.897857] Lustre: lustre-MDT0000: Recovery over after 0:02, of 2 clients 2 recovered and 0 were evicted. [ 4773.929377] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:622 to 0x280000401:641) [ 4773.938105] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:489 to 0x2c0000401:513) [ 4782.246942] Lustre: DEBUG MARKER: == sanity-lfsck test 45: LFSCK should fix UID/GID/PROJID of OST object ========================================================== 19:59:20 (1763341160) [ 4802.373080] Lustre: Failing over lustre-OST0000 [ 4802.524588] Lustre: server umount lustre-OST0000 complete [ 4804.576135] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 4807.984209] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: (null) [ 4818.002712] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 4819.320885] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 4819.815115] Lustre: lustre-OST0000: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [ 4823.176355] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4828.326804] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing wait_import_state FULL os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid 50 [ 4828.529386] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid in FULL state after 0 sec [ 4831.616073] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing wait_import_state FULL os[cp].lustre-OST0000-osc-MDT0001.ost_server_uuid 50 [ 4831.782089] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0001.ost_server_uuid in FULL state after 0 sec [ 4835.054106] Lustre: DEBUG MARKER: oleg148-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff951d51150800.ost_server_uuid 50 [ 4836.429754] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff951d51150800.ost_server_uuid in FULL state after 0 sec [ 4866.018503] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4869.601245] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4869.613749] Lustre: Skipped 3 previous similar messages [ 4871.840809] Lustre: server umount lustre-MDT0000 complete [ 4880.101596] LustreError: 158545:0:(ldlm_lockd.c:2563:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1763341259 with bad export cookie 9614157159028787488 [ 4880.106058] LustreError: MGC192.168.201.148@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4880.109720] LustreError: 158545:0:(ldlm_lockd.c:2563:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 4880.438562] Lustre: server umount lustre-MDT0001 complete [ 4900.123766] Lustre: server umount lustre-OST0000 complete [ 4901.343317] Lustre: 106059:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763341264/real 1763341264] req@ffff900202c8a680 x1848995550686720/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1763341280 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4902.367168] Lustre: 106057:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763341265/real 1763341265] req@ffff900204177100 x1848995550687104/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1763341281 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4906.531311] Lustre: 106059:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763341269/real 1763341269] req@ffff90020bb0d500 x1848995550687488/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1763341285 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4908.546530] Lustre: server umount lustre-OST0001 complete [ 4925.083827] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing unload_modules_local [ 4927.646805] Key type lgssc unregistered [ 4927.937779] LNet: 173622:0:(lib-ptl.c:967:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 4927.963264] LNetError: 173622:0:(acceptor.c:264:lnet_acceptor_remove_socket()) Interface ens2 not found [ 4927.981765] LNet: Removed LNI 192.168.201.148@tcp [ 4928.735256] Key type .llcrypt unregistered [ 4928.737367] Key type ._llcrypt unregistered [ 4950.544886] Key type ._llcrypt registered [ 4950.546664] Key type .llcrypt registered [ 4950.620894] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_hostid [ 4964.812447] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing load_modules_local [ 4965.924407] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 4965.956050] alg: No test for adler32 (adler32-zlib) [ 4966.959176] Lustre: Lustre: Build Version: 2.16.61_51_gca28732 [ 4967.250624] LNet: Added LNI 192.168.201.148@tcp [8/256/0/180] [ 4968.927271] Key type lgssc registered [ 4969.810716] Lustre: Echo OBD driver; http://www.lustre.org/ [ 4980.137544] LDISKFS-fs (vdc): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 4989.606696] LDISKFS-fs (vdd): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 4998.693638] LDISKFS-fs (vde): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 5007.394917] LDISKFS-fs (vdf): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 5021.336649] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing load_modules_local [ 5032.221996] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 5032.275820] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 5032.307976] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5033.550679] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 5033.573271] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 5033.638942] Lustre: lustre-MDT0000: new disk, initializing [ 5033.711668] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 5033.728948] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 5037.151501] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5049.084698] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 5049.150352] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 5049.217920] Lustre: 178030:0:(mgs_llog.c:1346:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 5049.247682] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 5049.252620] Lustre: Skipped 1 previous similar message [ 5049.297569] Lustre: lustre-MDT0001: new disk, initializing [ 5049.366889] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 5049.402310] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 5049.415508] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 5052.784352] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5057.976099] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 5070.101288] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 5070.222805] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 5070.529778] Lustre: lustre-OST0000: new disk, initializing [ 5070.538761] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 5070.611609] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 5077.255262] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5080.618107] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 5080.629679] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 5080.709082] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 5093.695845] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro [ 5093.752150] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: user_xattr,acl,no_mbcache,nodelalloc [ 5093.842290] Lustre: lustre-OST0001: new disk, initializing [ 5093.845212] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 5093.889078] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 5098.944752] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5101.089244] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 5101.114917] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 5101.169686] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 5109.721531] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5113.625317] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 5126.064571] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 20:05:04 (1763341504) === [ 5127.992928] Lustre: DEBUG MARKER: == sanity-lfsck test complete, duration 4909 sec ========= 20:05:06 (1763341506) [ 5130.226860] Lustre: DEBUG MARKER: === sanity-lfsck: start cleanup 20:05:08 (1763341508) === [ 5134.995694] Lustre: DEBUG MARKER: === sanity-lfsck: finish cleanup 20:05:13 (1763341513) === [ 5141.472136] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 5141.476658] 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 [ 5141.485070] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5141.985267] 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 [ 5141.987058] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5142.001136] Lustre: Skipped 1 previous similar message [ 5142.017716] Lustre: Skipped 2 previous similar messages [ 5145.008152] LustreError: 182211:0:(obd_class.h:479:obd_check_dev()) Device 28 not setup [ 5145.095394] Lustre: server umount lustre-MDT0000 complete [ 5151.416502] LustreError: 178022:0:(ldlm_lockd.c:2563:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1763341530 with bad export cookie 17732845449015828176 [ 5151.422040] LustreError: MGC192.168.201.148@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5151.569100] LustreError: 182664:0:(obd_class.h:479:obd_check_dev()) Device 27 not setup [ 5151.571570] LustreError: 182664:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 5151.731393] Lustre: server umount lustre-MDT0001 complete [ 5167.584768] Lustre: 175198:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763341531/real 1763341531] req@ffff90033a607100 x1848997415305600/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1763341547 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5167.615987] 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 [ 5167.627076] Lustre: Skipped 1 previous similar message [ 5168.695071] LustreError: 183114:0:(obd_class.h:479:obd_check_dev()) Device 19 not setup [ 5168.705038] LustreError: 183114:0:(obd_class.h:479:obd_check_dev()) Skipped 7 previous similar messages [ 5168.769219] Lustre: server umount lustre-OST0000 complete [ 5172.385636] Lustre: 175197:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1763341535/real 1763341535] req@ffff9002056a5880 x1848997415305856/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1763341551 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5176.364666] LustreError: 183566:0:(obd_class.h:479:obd_check_dev()) Device 2 not setup [ 5176.367991] LustreError: 183566:0:(obd_class.h:479:obd_check_dev()) Skipped 3 previous similar messages [ 5176.554434] Lustre: server umount lustre-OST0001 complete [ 5192.937958] Lustre: DEBUG MARKER: oleg148-server.virtnet: executing unload_modules_local [ 5195.481558] Key type lgssc unregistered [ 5195.770745] LNet: 184396:0:(lib-ptl.c:967:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 5195.780894] LNetError: 184396:0:(acceptor.c:264:lnet_acceptor_remove_socket()) Interface ens2 not found [ 5195.807349] LNet: Removed LNI 192.168.201.148@tcp [ 5196.578264] Key type .llcrypt unregistered [ 5196.585104] Key type ._llcrypt unregistered