[ 0.000000] Linux version 4.18.0rh8.10-debug (green@maintenance) (gcc version 8.5.0 20210514 (Red Hat 8.5.0-26) (GCC)) #2 SMP Mon Jul 14 01:24:22 EDT 2025 [ 0.000000] Command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers' [ 0.000000] x86/fpu: xstate_offset[2]: 576, xstate_sizes[2]: 256 [ 0.000000] x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'standard' format. [ 0.000000] signal: max sigframe size: 1776 [ 0.000000] BIOS-provided physical RAM map: [ 0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable [ 0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000000100000-0x00000000bffcdfff] usable [ 0.000000] BIOS-e820: [mem 0x00000000bffce000-0x00000000bfffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000100000000-0x0000000146dfffff] usable [ 0.000000] NX (Execute Disable) protection: active [ 0.000000] SMBIOS 2.8 present. [ 0.000000] DMI: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.17.0-10.fc44 06/10/2025 [ 0.000000] Hypervisor detected: KVM [ 0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00 [ 0.000000] kvm-clock: using sched offset of 557017937 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2399.998 MHz processor [ 0.000000] last_pfn = 0x146e00 max_arch_pfn = 0x400000000 [ 0.000000] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT [ 0.000000] last_pfn = 0xbffce max_arch_pfn = 0x400000000 [ 0.000000] found SMP MP-table at [mem 0x000f54b0-0x000f54bf] [ 0.000000] RAMDISK: [mem 0xbcc54000-0xbffbffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F52D0 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE247C 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE2318 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 0022D8 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE238C 000090 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE241C 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE2454 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe2318-0xbffe238b] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe2317] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe238c-0xbffe241b] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe241c-0xbffe2453] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe2454-0xbffe247b] [ 0.000000] No NUMA configuration found [ 0.000000] Faking a node at [mem 0x0000000000000000-0x0000000146dfffff] [ 0.000000] NODE_DATA(0) allocated [mem 0x1465a3000-0x1465cdfff] [ 0.000000] Reserving 256MB of memory at 2752MB for crashkernel (System RAM: 4205MB) [ 0.000000] Zone ranges: [ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.000000] DMA32 [mem 0x0000000001000000-0x00000000ffffffff] [ 0.000000] Normal [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Device empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff] [ 0.000000] node 0: [mem 0x0000000000100000-0x00000000bffcdfff] [ 0.000000] node 0: [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Zeroed struct page in unavailable ranges: 4756 pages [ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x0000000146dfffff] [ 0.000000] ACPI: PM-Timer IO Port: 0x608 [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) [ 0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) [ 0.000000] Using ACPI (MADT) for SMP configuration information [ 0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000] TSC deadline timer available [ 0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs [ 0.000000] kvm-guest: KVM setup pv remote TLB flush [ 0.000000] kvm-guest: setup PV sched yield [ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff] [ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff] [ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff] [ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff] [ 0.000000] PM: Registered nosave memory: [mem 0xbffce000-0xbfffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xc0000000-0xfeffbfff] [ 0.000000] PM: Registered nosave memory: [mem 0xfeffc000-0xfeffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xff000000-0xfffbffff] [ 0.000000] PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff] [ 0.000000] [mem 0xc0000000-0xfeffbfff] available for PCI devices [ 0.000000] Booting paravirtualized kernel on KVM [ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns [ 0.000000] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1 [ 0.000000] percpu: Embedded 63 pages/cpu s221184 r8192 d28672 u524288 [ 0.000000] kvm-guest: PV spinlocks enabled [ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1059606 [ 0.000000] Policy zone: Normal [ 0.000000] Kernel command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] Specific versions of hardware are certified with Red Hat Enterprise Linux 8. Please see the list of hardware certified with Red Hat Enterprise Linux 8 at https://catalog.redhat.com. [ 0.000000] audit: disabled (until reboot) [ 0.000000] software IO TLB: area num 4. [ 0.000000] Memory: 2829652K/4306352K available (18435K kernel code, 11221K rwdata, 7248K rodata, 2908K init, 18040K bss, 524584K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] ftrace: allocating 41240 entries in 162 pages [ 0.000000] ftrace: allocated 162 pages with 3 groups [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] rcu: RCU event tracing is enabled. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ 0.000000] rcu: RCU callback double-/use-after-free debug enabled. [ 0.000000] Rude variant of Tasks RCU enabled. [ 0.000000] Tracing variant of Tasks RCU enabled. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 0.000000] NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16 [ 0.000000] random: get_random_bytes called from start_kernel+0x622/0x9a8 with crng_init=0 [ 0.001000] Console: colour *CGA 80x25 [ 0.001000] printk: console [ttyS1] enabled [ 0.001000] ACPI: Core revision 20220331 [ 0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.001011] APIC: Switch to symmetric I/O mode setup [ 0.002378] x2apic enabled [ 0.003009] Switched APIC routing to physical x2apic. [ 0.004016] kvm-guest: setup PV IPIs [ 0.007000] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.007000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.007022] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.008012] pid_max: default: 32768 minimum: 301 [ 0.010061] LSM: Security Framework initializing [ 0.011058] Yama: becoming mindful. [ 0.012045] SELinux: Initializing. [ 0.013084] *** VALIDATE selinux *** [ 0.021311] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.026097] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.028156] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.030111] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.031129] *** VALIDATE tmpfs *** [ 0.033158] *** VALIDATE proc *** [ 0.034247] *** VALIDATE cgroup *** [ 0.035013] *** VALIDATE cgroup2 *** [ 0.036271] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.037166] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.038011] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.039035] Spectre V2 : User space: Vulnerable [ 0.040012] Speculative Store Bypass: Vulnerable [ 0.042638] debug: unmapping init [mem 0xffffffff9e259000-0xffffffff9e260fff] [ 0.044172] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.045656] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.046026] ... version: 2 [ 0.047014] ... bit width: 48 [ 0.048013] ... generic registers: 4 [ 0.049011] ... value mask: 0000ffffffffffff [ 0.050012] ... max period: 00007fffffffffff [ 0.051016] ... fixed-purpose events: 3 [ 0.052011] ... event mask: 000000070000000f [ 0.053317] rcu: Hierarchical SRCU implementation. [ 0.055438] smp: Bringing up secondary CPUs ... [ 0.056600] x86: Booting SMP configuration: [ 0.057032] .... node #0, CPUs: #1 #2 #3 [ 0.061010] smp: Brought up 1 node, 4 CPUs [ 0.063021] smpboot: Max logical packages: 1 [ 0.064012] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.144432] node 0 deferred pages initialised in 78ms [ 0.147108] devtmpfs: initialized [ 0.148204] x86/mm: Memory block size: 128MB [ 0.150000] gcov: version magic: 0x41383552 [ 0.153196] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.156126] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.158291] pinctrl core: initialized pinctrl subsystem [ 0.161165] [ 0.161529] ************************************************************* [ 0.163009] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.165011] ** ** [ 0.166011] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.168011] ** ** [ 0.170013] ** This means that this kernel is built to expose internal ** [ 0.172013] ** IOMMU data structures, which may compromise security on ** [ 0.173010] ** your system. ** [ 0.175009] ** ** [ 0.177010] ** If you see this message and you are not debugging the ** [ 0.178007] ** kernel, report this immediately to your vendor! ** [ 0.179011] ** ** [ 0.180017] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.182008] ************************************************************* [ 0.184610] NET: Registered protocol family 16 [ 0.186388] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.188062] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.190055] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.192415] cpuidle: using governor menu [ 0.193575] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.194514] PCI: Using configuration type 1 for base access [ 0.196119] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.203223] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.204030] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.206086] cryptd: max_cpu_qlen set to 1000 [ 0.208219] ACPI: Added _OSI(Module Device) [ 0.209000] ACPI: Added _OSI(Processor Device) [ 0.210011] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.212028] ACPI: Added _OSI(Processor Aggregator Device) [ 0.216919] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.223399] ACPI: Interpreter enabled [ 0.224051] ACPI: PM: (supports S0 S3 S4 S5) [ 0.225009] ACPI: Using IOAPIC for interrupt routing [ 0.227135] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.231556] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.241183] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.243035] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.245019] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.248069] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.251061] acpiphp: Slot [2] registered [ 0.252072] acpiphp: Slot [5] registered [ 0.253067] acpiphp: Slot [6] registered [ 0.254065] acpiphp: Slot [7] registered [ 0.255066] acpiphp: Slot [8] registered [ 0.256079] acpiphp: Slot [9] registered [ 0.257022] acpiphp: Slot [10] registered [ 0.257998] acpiphp: Slot [3] registered [ 0.258895] acpiphp: Slot [4] registered [ 0.260065] acpiphp: Slot [11] registered [ 0.261022] acpiphp: Slot [12] registered [ 0.261973] acpiphp: Slot [13] registered [ 0.263082] acpiphp: Slot [14] registered [ 0.264058] acpiphp: Slot [15] registered [ 0.265072] acpiphp: Slot [16] registered [ 0.266055] acpiphp: Slot [17] registered [ 0.266983] acpiphp: Slot [18] registered [ 0.268066] acpiphp: Slot [19] registered [ 0.269091] acpiphp: Slot [20] registered [ 0.270065] acpiphp: Slot [21] registered [ 0.271088] acpiphp: Slot [22] registered [ 0.272009] acpiphp: Slot [23] registered [ 0.273045] acpiphp: Slot [24] registered [ 0.274115] acpiphp: Slot [25] registered [ 0.275110] acpiphp: Slot [26] registered [ 0.276089] acpiphp: Slot [27] registered [ 0.277328] acpiphp: Slot [28] registered [ 0.279091] acpiphp: Slot [29] registered [ 0.280080] acpiphp: Slot [30] registered [ 0.281064] acpiphp: Slot [31] registered [ 0.282047] PCI host bridge to bus 0000:00 [ 0.283014] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.284016] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.286018] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.287018] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.289022] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.291026] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.293199] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.298009] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.300104] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.310015] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.314534] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.315013] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.317016] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.319014] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.321421] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.322497] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.325034] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.327610] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.331017] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.339018] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.343014] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.347591] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.354017] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.359020] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.374015] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.383571] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.390015] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.396015] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.414018] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.422411] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.428014] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.433019] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.445012] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.452694] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.459014] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.463017] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.479019] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.492000] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.502020] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.510016] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.535016] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 0.547067] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.552015] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.558015] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.580021] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 0.601645] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.604879] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.607847] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.609434] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.612253] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.617062] iommu: Default domain type: Passthrough [ 0.618467] SCSI subsystem initialized [ 0.619103] ACPI: bus type USB registered [ 0.619917] usbcore: registered new interface driver usbfs [ 0.621048] usbcore: registered new interface driver hub [ 0.622058] usbcore: registered new device driver usb [ 0.623143] pps_core: LinuxPPS API ver. 1 registered [ 0.624012] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.626070] PTP clock support registered [ 0.628057] EDAC MC: Ver: 3.0.0 [ 0.629158] PCI: Using ACPI for IRQ routing [ 0.630866] NetLabel: Initializing [ 0.632012] NetLabel: domain hash size = 128 [ 0.634012] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.636091] NetLabel: unlabeled traffic allowed by default [ 0.638081] vgaarb: loaded [ 0.639227] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.641016] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.646997] clocksource: Switched to clocksource kvm-clock [ 0.733795] VFS: Disk quotas dquot_6.6.0 [ 0.734842] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.737135] *** VALIDATE ramfs *** [ 0.738232] *** VALIDATE hugetlbfs *** [ 0.739223] pnp: PnP ACPI init [ 0.741479] pnp: PnP ACPI: found 6 devices [ 0.755321] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.758142] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.760311] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.761824] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.764234] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.766174] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.767785] NET: Registered protocol family 2 [ 0.769479] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.772566] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.774795] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.778740] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.782099] TCP: Hash tables configured (established 65536 bind 65536) [ 0.784461] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.786172] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.787918] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.790583] NET: Registered protocol family 1 [ 0.792890] RPC: Registered named UNIX socket transport module. [ 0.794217] RPC: Registered udp transport module. [ 0.795072] RPC: Registered tcp transport module. [ 0.795983] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.797287] NET: Registered protocol family 44 [ 0.798204] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.799616] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.801428] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.803166] PCI: CLS 0 bytes, default 64 [ 0.804730] Unpacking initramfs... [ 2.154984] debug: unmapping init [mem 0xffff9a653cc54000-0xffff9a653ffbffff] [ 2.158765] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.161357] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.164522] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 2.631145] Initialise system trusted keyrings [ 2.632499] Key type blacklist registered [ 2.649091] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.660783] zbud: loaded [ 2.666180] *** VALIDATE nfs *** [ 2.667726] *** VALIDATE nfs4 *** [ 2.669643] pstore: using deflate compression [ 2.673105] Platform Keyring initialized [ 2.765949] NET: Registered protocol family 38 [ 2.767419] Key type asymmetric registered [ 2.768301] Asymmetric key parser 'x509' registered [ 2.769379] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 2.771174] io scheduler mq-deadline registered [ 2.772117] io scheduler kyber registered [ 2.773347] io scheduler bfq registered [ 2.774472] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 2.776662] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 2.778464] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 2.780380] ACPI: Power Button [PWRF] [ 2.783917] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 2.788568] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 2.798430] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 2.803198] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 2.814623] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 2.838949] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 2.867306] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 2.873033] Non-volatile memory driver v1.3 [ 2.874714] Linux agpgart interface v0.103 [ 2.909294] virtio_blk virtio1: [vda] 149816 512-byte logical blocks (76.7 MB/73.2 MiB) [ 2.911977] vda: detected capacity change from 0 to 76705792 [ 2.929889] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 2.933377] vdb: detected capacity change from 0 to 1073741824 [ 2.953743] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 2.956749] vdc: detected capacity change from 0 to 2621440000 [ 2.972695] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 2.975755] vdd: detected capacity change from 0 to 2621440000 [ 2.994848] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 2.997958] vde: detected capacity change from 0 to 4294967296 [ 3.016520] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.019827] vdf: detected capacity change from 0 to 4294967296 [ 3.027560] libphy: Fixed MDIO Bus: probed [ 3.032479] usbcore: registered new interface driver usbserial_generic [ 3.034902] usbserial: USB Serial support registered for generic [ 3.037311] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.041706] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.043556] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.046423] mousedev: PS/2 mouse device common for all mice [ 3.050168] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.051148] rtc_cmos 00:05: RTC can wake from S4 [ 3.057056] rtc_cmos 00:05: registered as rtc0 [ 3.057747] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.059280] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.064085] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.065389] intel_pstate: CPU model not supported [ 3.071365] hid: raw HID events driver (C) Jiri Kosina [ 3.073529] usbcore: registered new interface driver usbhid [ 3.075513] usbhid: USB HID core driver [ 3.077138] drop_monitor: Initializing network drop monitor service [ 3.079504] Initializing XFRM netlink socket [ 3.081541] NET: Registered protocol family 10 [ 3.084516] Segment Routing with IPv6 [ 3.085902] NET: Registered protocol family 17 [ 3.088357] mpls_gso: MPLS GSO support [ 3.094244] RAS: Correctable Errors collector initialized. [ 3.096445] AVX version of gcm_enc/dec engaged. [ 3.098184] AES CTR mode by8 optimization enabled [ 3.164380] sched_clock: Marking stable (3164358197, 0)->(4066540179, -902181982) [ 3.167092] registered taskstats version 1 [ 3.169640] Loading compiled-in X.509 certificates [ 3.171521] zswap: loaded using pool lzo/zbud [ 3.194484] Key type big_key registered [ 3.207475] Key type encrypted registered [ 3.209228] ima: No TPM chip found, activating TPM-bypass! [ 3.211300] ima: Allocated hash algorithm: sha1 [ 3.212900] ima: No architecture policies found [ 3.214669] evm: Initialising EVM extended attributes: [ 3.216609] evm: security.selinux [ 3.217910] evm: security.ima [ 3.218993] evm: security.capability [ 3.220322] evm: HMAC attrs: 0x1 [ 3.222604] rtc_cmos 00:05: setting system clock to 2026-09-05 07:16:33 UTC (1788592593) [ 3.228810] debug: unmapping init [mem 0xffffffff9f203000-0xffffffff9f3fffff] [ 3.231963] debug: unmapping init [mem 0xffffffff9df82000-0xffffffff9e258fff] [ 3.240241] Write protecting the kernel read-only data: 28672k [ 3.242560] debug: unmapping init [mem 0xffffffff9c603000-0xffffffff9c7fffff] [ 3.244610] debug: unmapping init [mem 0xffffffff9cf14000-0xffffffff9cffffff] [ 3.277756] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 3.286509] systemd[1]: Detected virtualization kvm. [ 3.288320] systemd[1]: Detected architecture x86-64. [ 3.290238] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.316279] systemd[1]: No hostname configured. [ 3.318043] systemd[1]: Set hostname to . [ 3.320124] random: systemd: uninitialized urandom read (16 bytes read) [ 3.322581] systemd[1]: Initializing machine ID from random generator. [ 3.373498] random: ln: uninitialized urandom read (6 bytes read) [ 3.459826] random: systemd: uninitialized urandom read (16 bytes read) [ 3.462325] systemd[1]: Reached target Local File Systems. [ OK ] Reached target Local File Systems. [ 3.467072] systemd[1]: Listening on Journal Socket. [ OK ] Listening on Journal Socket. [ 3.475289] systemd[1]: Starting Setup Virtual Console... Starting Setup Virtual Console... Starting Apply Kernel Variables... [ OK ] Started Dispatch Password Requests to Console Directory Watch. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Reached target Slices. [ OK ] Listening on udev Kernel Socket. [ OK ] Reached target Swap. [ OK ] Reached target Initrd Root Device. [ OK ] Reached target Timers. [ OK ] Listening on Journal Socket (/dev/log). Starting Journal Service... [ OK ] Started Memstrack Anylazing Service. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Listening on udev Control Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Paths. Starting Create Volatile Files and Directories... [ OK ] Started Setup Virtual Console. [ OK ] Started Apply Kernel Variables. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Create Volatile Files and Directories. Starting Create Static Device Nodes in /dev... Starting dracut cmdline hook... [ OK ] Started Journal Service. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 4.107202] device-mapper: uevent: version 1.0.3 [ 4.109413] 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. [ 4.838424] virtio_net virtio0 ens2: renamed from eth0 [ 4.849698] random: fast init done [ 4.910405] scsi host0: ata_piix [ 4.924912] scsi host1: ata_piix [ 4.927423] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 4.929962] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 8.693374] dracut-initqueue[576]: RTNETLINK answers: File exists [ 9.725540] random: crng init done [ 9.727016] random: 7 urandom warning(s) missed due to ratelimiting Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. Mounting /sysroot... [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. [ 10.184328] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped target Timers. [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Slices. [ OK ] Stopped target Paths. [ OK ] Stopped target System Initialization. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. [ OK ] Stopped target Swap. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. Stopping udev Kernel Device Manager... [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped target Sockets. [ 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... [ 11.368964] printk: systemd: 25 output lines suppressed due to ratelimiting [ 11.598133] SELinux: Disabled at runtime. [ 11.657926] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 11.665443] systemd[1]: Detected virtualization kvm. [ 11.667552] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 12.071299] systemd[1]: initrd-switch-root.service: Succeeded. [ 12.074628] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 12.078547] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 12.081900] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 12.084827] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 12.094221] systemd[1]: Starting Journal Service... Starting Journal Service... [ 12.108782] systemd[1]: Listening on Process Core Dump Socket. [ OK ] Listening on Process Core Dump Socket. [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Reached target rpc_pipefs.target. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Created slice system-sshd\x2dkeygen.slice. Starting Remount Root and Kernel File Systems... [ OK ] Created slice system-getty.slice. [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Reached target Paths. Mounting POSIX Message Queue File System... Mounting Kernel Debug File System... [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Created slice User and Session Slice. Starting Create list of required st…ce nodes for the current kernel... Activating swap /dev/disk/by-label/SWAP... [ OK ] Reached target Slices. [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Listening on udev Control Socket. [ OK ] Listening on udev Kernel Socket. Starting udev Coldplug all Devices... [ OK ] Listening on RPCbind Server Activation Socket. [[ 12.210370] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS  OK ] Reached target RPC Port Mapper. [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd File Systems. [ OK ] Stopped target Initrd Root File System. Starting Apply Kernel Variables... Mounting Huge Pages File System... [ OK ] Started Journal Service. [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 ] Mounted Kernel Debug File System. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Started Apply Kernel Variables. [ OK ] Mounted Huge Pages File System. [ OK ] Reached target Swap. Starting Configure read-only root support... Starting Create Static Device Nodes in /dev... Starting Flush Journal to Persistent Storage... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Reached target Local File Systems (Pre). Mounting /home/green/git/lustre-release... Mounting /mnt... Starting udev Kernel Device Manager... [ OK ] Mounted /mnt. [ 12.531661] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Coldplug all Devices. [ OK ] Started udev Kernel Device Manager. [ 12.865322] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 12.876683] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 13.055468] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 13.067643] EDAC sbridge: Ver: 1.1.2 [ 14.556284] Key type dns_resolver registered [ 14.826096] NFS: Registering the id_resolver key type [ 14.827155] Key type id_resolver registered [ 14.828110] Key type id_legacy registered [ OK ] Started Configure read-only root support. Starting Load/Save Random Seed... [ OK ] Reached target Local File Systems. Starting Rebuild Dynamic Linker Cache... Starting Mark the need to relabel after reboot... Starting Create Volatile Files and Directories... [ OK ] Started Load/Save Random Seed. [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Create Volatile Files and Directories. Starting RPC Bind... Starting Update UTMP about System Boot/Shutdown... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting Login Service... Starting Restore /run/initramfs on shutdown... [ OK ] Started dnf makecache --timer. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Reached target Timers. [ OK ] Started irqbalance daemon. [ OK ] Started D-Bus System Message Bus. Starting Network Manager... [ OK ] Reached target sshd-keygen.target. [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Login Service. [ OK ] Started Network Manager. [ OK ] Reached target Network. Starting GSSAPI Proxy Daemon... Starting Dynamic System Tuning Daemon... Starting OpenSSH server daemon... Starting Network Manager Wait Online... Starting Hostname Service... [ 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 OpenSSH server daemon. [ 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 Notify NFS peers of a restart... Starting Crash recovery kernel arming... [ 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 oleg155-server login: [ 44.072422] libcfs: loading out-of-tree module taints kernel. [ 44.134988] Key type ._llcrypt registered [ 44.138163] Key type .llcrypt registered [ 44.246687] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_hostid [ 65.959888] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing load_modules_local [ 67.441323] hrtimer: interrupt took 7386632 ns [ 68.067765] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 68.096941] alg: No test for adler32 (adler32-zlib) [ 69.918556] Lustre: Lustre: Build Version: 2.17.58_2_gae7f7f4 [ 71.014151] LNet: Added LNI 192.168.201.155@tcp [8/256/0/180] [ 72.808669] Key type lgssc registered [ 74.694638] Lustre: Echo OBD driver; http://www.lustre.org/ [ 91.882758] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 139.833270] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing load_modules_local [ 154.802355] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 154.823936] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 156.117907] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 156.170245] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 156.255311] Lustre: lustre-MDT0000: new disk, initializing [ 156.319533] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 156.334464] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 161.171464] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 176.571859] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 176.758390] Lustre: 6508:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 176.789706] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 176.792526] Lustre: Skipped 1 previous similar message [ 176.903318] Lustre: lustre-MDT0001: new disk, initializing [ 176.999363] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 177.064400] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 177.076378] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 182.056359] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 187.304273] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 200.772593] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 201.286419] Lustre: lustre-OST0000: new disk, initializing [ 201.295898] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 201.306316] Lustre: 8446:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 201.408292] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 202.444570] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 202.475785] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 202.598631] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 211.001825] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 227.026444] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 227.215922] Lustre: lustre-OST0001: new disk, initializing [ 227.221981] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 227.229910] Lustre: 9519:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 227.303982] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 234.411824] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 237.103884] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 237.123422] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 237.325215] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 249.216889] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 256.376186] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 263.304353] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing check_logdir /tmp/testlogs/ [ 271.002380] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing yml_node [ 276.129687] Lustre: DEBUG MARKER: Client: 2.17.58.2 [ 279.404097] Lustre: DEBUG MARKER: MDS: 2.17.58.2 [ 282.068291] Lustre: DEBUG MARKER: OSS: 2.17.58.2 [ 283.823434] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity-lfsck ============----- Sat Sep 5 03:21:12 EDT 2026 [ 301.168123] Lustre: DEBUG MARKER: excepting tests: 18b 23b [ 310.441524] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing load_modules_local [ 319.457105] 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 [ 319.460769] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 319.484375] Lustre: Skipped 1 previous similar message [ 319.502306] Lustre: Skipped 3 previous similar messages [ 324.730894] Lustre: server umount lustre-MDT0000 complete [ 329.708193] LustreError: 6513:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 329.745915] LustreError: 6513:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 8 previous similar messages [ 334.128878] LustreError: 7921:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788592924 with bad export cookie 3529988108495067889 [ 334.129960] LustreError: MGC192.168.201.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 334.136780] LustreError: 7921:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 334.528345] Lustre: server umount lustre-MDT0001 complete [ 351.136282] Lustre: 3639:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788592925/real 1788592925] req@ffff9a65985c2680 x1875475338204800/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788592941 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 351.156812] 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 [ 351.175837] Lustre: Skipped 2 previous similar messages [ 354.405178] Lustre: server umount lustre-OST0000 complete [ 356.321325] Lustre: 3637:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788592930/real 1788592930] req@ffff9a65985c0700 x1875475338205056/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788592946 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 360.353724] Lustre: 3639:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788592934/real 1788592934] req@ffff9a658754bb80 x1875475338205440/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788592950 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 363.173813] Lustre: server umount lustre-OST0001 complete [ 382.561950] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing unload_modules_local [ 387.015527] Key type lgssc unregistered [ 387.525135] LNet: 14791:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 387.532605] LNetError: 14791:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 388.607384] LNet: Removed LNI 192.168.201.155@tcp [ 389.909291] Key type .llcrypt unregistered [ 389.914392] Key type ._llcrypt unregistered [ 415.017422] Key type ._llcrypt registered [ 415.019418] Key type .llcrypt registered [ 415.113758] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_hostid [ 433.093501] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing load_modules_local [ 435.095039] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 435.177572] alg: No test for adler32 (adler32-zlib) [ 436.381311] Lustre: Lustre: Build Version: 2.17.58_2_gae7f7f4 [ 436.803425] LNet: Added LNI 192.168.201.155@tcp [8/256/0/180] [ 438.480938] Key type lgssc registered [ 440.505326] Lustre: Echo OBD driver; http://www.lustre.org/ [ 491.911624] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing load_modules_local [ 506.733205] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 506.752307] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 508.135912] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 508.161058] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 508.261542] Lustre: lustre-MDT0000: new disk, initializing [ 508.382360] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 508.399519] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 513.095884] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 528.207745] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 528.371752] Lustre: 19243:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 528.440259] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 528.452716] Lustre: Skipped 1 previous similar message [ 528.555331] Lustre: lustre-MDT0001: new disk, initializing [ 528.622429] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 528.673290] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 528.692466] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 533.951981] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 539.110324] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 548.660966] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 548.934325] Lustre: lustre-OST0000: new disk, initializing [ 548.936315] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 548.941200] Lustre: 21186:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 548.994740] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 552.874069] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 552.891898] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 553.015804] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 555.388492] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 568.634498] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 568.745367] Lustre: lustre-OST0001: new disk, initializing [ 568.749883] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 568.757655] Lustre: 22208:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 568.820823] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 575.347825] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 577.058741] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 577.070160] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 577.220238] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 586.768549] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 594.192207] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 602.137909] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 03:26:30 (1788593190) === [ 605.398372] Lustre: DEBUG MARKER: == sanity-lfsck test 0: Control LFSCK manually =========== 03:26:33 (1788593193) [ 605.617817] Lustre: 22651:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 251 < left 278, rollback = 2 [ 605.625777] Lustre: 22651:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 605.635332] Lustre: 22651:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 605.645239] Lustre: 22651:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 605.655199] Lustre: 22651:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 605.669217] Lustre: 22651:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 606.186773] Lustre: 22651:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 606.196348] Lustre: 22651:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 11 previous similar messages [ 606.220675] Lustre: 22651:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 606.237735] Lustre: 22651:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 606.248367] Lustre: 22651:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 606.253973] Lustre: 22651:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 606.266278] Lustre: 22651:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 606.274689] Lustre: 22651:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 606.288259] Lustre: 22651:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 606.296266] Lustre: 22651:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 606.309260] Lustre: 22651:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 606.327674] Lustre: 22651:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 607.231877] Lustre: 19252:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 607.241580] Lustre: 19252:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 32 previous similar messages [ 607.246604] Lustre: 19252:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 607.250503] Lustre: 19252:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 32 previous similar messages [ 607.260310] Lustre: 19252:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 607.269436] Lustre: 19252:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 32 previous similar messages [ 607.280887] Lustre: 19252:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 607.290342] Lustre: 19252:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 32 previous similar messages [ 607.306164] Lustre: 19252:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 607.313258] Lustre: 19252:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 32 previous similar messages [ 607.321858] Lustre: 19252:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 607.341731] Lustre: 19252:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 32 previous similar messages [ 609.260876] Lustre: 19251:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 609.268851] Lustre: 19251:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 107 previous similar messages [ 609.278795] Lustre: 19251:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 609.287553] Lustre: 19251:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 107 previous similar messages [ 609.294542] Lustre: 19251:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 609.304947] Lustre: 19251:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 107 previous similar messages [ 609.314945] Lustre: 19251:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 609.324048] Lustre: 19251:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 107 previous similar messages [ 609.331954] Lustre: 19251:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 609.340803] Lustre: 19251:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 107 previous similar messages [ 609.347328] Lustre: 19251:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 609.353601] Lustre: 19251:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 107 previous similar messages [ 613.627912] Lustre: *** cfs_fail_loc=1600, val=3*** [ 615.995932] Lustre: 21174:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-OST0001: opcode 2: before 259 < left 274, rollback = 2 [ 615.998335] Lustre: 23395:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 616.014872] Lustre: 21174:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 124 previous similar messages [ 616.014901] Lustre: 21174:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/1, xattr_set: 2/274/0 [ 616.014905] Lustre: 21174:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 123 previous similar messages [ 616.014911] Lustre: 21174:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 0/0/0, punch: 0/0/0, quota 7/225/0 [ 616.014914] Lustre: 21174:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 123 previous similar messages [ 616.014920] Lustre: 21174:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 616.014923] Lustre: 21174:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 123 previous similar messages [ 616.014928] Lustre: 21174:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 616.014931] Lustre: 21174:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 123 previous similar messages [ 616.130292] Lustre: 23395:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 135 previous similar messages [ 618.330551] Lustre: *** cfs_fail_loc=1600, val=3*** [ 629.691638] Lustre: 21174:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 259 < left 274, rollback = 2 [ 629.693118] Lustre: 23599:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 629.708778] Lustre: 21174:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 62 previous similar messages [ 629.708811] Lustre: 21174:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/1, xattr_set: 2/274/0 [ 629.708815] Lustre: 21174:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 62 previous similar messages [ 629.708821] Lustre: 21174:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 0/0/0, punch: 0/0/0, quota 7/225/0 [ 629.708824] Lustre: 21174:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 62 previous similar messages [ 629.708828] Lustre: 21174:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 629.708832] Lustre: 21174:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 62 previous similar messages [ 629.708837] Lustre: 21174:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 629.708840] Lustre: 21174:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 62 previous similar messages [ 629.825289] Lustre: 23599:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 53 previous similar messages [ 633.833311] 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 [ 633.844315] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 633.855845] Lustre: Skipped 1 previous similar message [ 638.947948] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 638.954557] Lustre: Skipped 6 previous similar messages [ 644.067436] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 644.074567] Lustre: Skipped 3 previous similar messages [ 646.112246] Lustre: lustre-MDT0000 is waiting for obd_unlinked_exports more than 8 seconds. The obd refcount = 3. Is it stuck? [ 648.355960] Lustre: server umount lustre-MDT0000 complete [ 653.054180] LustreError: 19237:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788593243 with bad export cookie 691450287131267355 [ 653.060056] LustreError: MGC192.168.201.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 653.068757] LustreError: 19237:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 3 previous similar messages [ 653.522404] Lustre: server umount lustre-MDT0001 complete [ 667.903715] Lustre: server umount lustre-OST0000 complete [ 669.858897] Lustre: 16402:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788593244/real 1788593244] req@ffff9a648a0af800 x1875475721991552/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788593260 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 669.884448] 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 [ 669.907674] Lustre: Skipped 2 previous similar messages [ 672.062751] Lustre: server umount lustre-OST0001 complete [ 681.986509] Lustre: DEBUG MARKER: == sanity-lfsck test 1a: LFSCK can find out and repair crashed FID-in-dirent ========================================================== 03:27:50 (1788593270) [ 699.478274] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing load_modules_local [ 711.541516] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 711.826951] LustreError: 26272:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 711.845490] LustreError: 26272:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 5 previous similar messages [ 711.912628] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 717.162768] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 717.284015] LustreError: 26273:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 722.411374] LustreError: 26272:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 726.156789] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 726.519101] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 731.324912] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 734.141751] Lustre: 27412:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 742.521767] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 742.972417] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 751.569960] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 752.163598] LustreError: 27766:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 757.224467] LustreError: 28160:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 758.248838] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:41 to 0x280000401:65) [ 761.364378] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 766.970028] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:40 to 0x2c0000401:65) [ 768.958398] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 778.504684] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 783.503754] Lustre: 29282:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 785.571841] Lustre: 26267:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 785.578274] Lustre: 26267:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 5 previous similar messages [ 785.582654] Lustre: 26267:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 785.586502] Lustre: 26267:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 2 previous similar messages [ 785.592164] Lustre: 26267:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 785.598310] Lustre: 26267:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 6 previous similar messages [ 785.603521] Lustre: 26267:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 785.617684] Lustre: 26267:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 6 previous similar messages [ 785.633193] Lustre: 26267:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 785.640287] Lustre: 26267:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 6 previous similar messages [ 785.645242] Lustre: 26267:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 785.651077] Lustre: 26267:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 6 previous similar messages [ 791.233534] Lustre: *** cfs_fail_loc=1501, val=0*** [ 801.577438] Lustre: Failing over lustre-MDT0000 [ 801.884976] Lustre: server umount lustre-MDT0000 complete [ 802.791279] 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 [ 802.802886] LustreError: 27004:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 802.814315] Lustre: Skipped 3 previous similar messages [ 802.850178] LustreError: 27004:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 5 previous similar messages [ 813.949048] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 814.231930] LustreError: MGC192.168.201.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 814.534299] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 814.537229] Lustre: Skipped 1 previous similar message [ 814.592118] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 818.929459] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 819.684503] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 819.704598] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 819.739772] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 819.856531] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:105 to 0x2c0000401:129) [ 819.857098] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:105 to 0x280000401:129) [ 823.481916] Lustre: *** cfs_fail_loc=1505, val=0*** [ 831.567565] Lustre: DEBUG MARKER: == sanity-lfsck test 1b: LFSCK can find out and repair the missing FID-in-LMA ========================================================== 03:30:19 (1788593419) [ 833.360432] Lustre: 26268:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 833.372839] Lustre: 26268:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 322 previous similar messages [ 833.380852] Lustre: 26268:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 833.389142] Lustre: 26268:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 833.403019] Lustre: 26268:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 833.411203] Lustre: 26268:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 833.423786] Lustre: 26268:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 833.431876] Lustre: 26268:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 833.437609] Lustre: 26268:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 833.443939] Lustre: 26268:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 833.449406] Lustre: 26268:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 833.453294] Lustre: 26268:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 838.745127] Lustre: *** cfs_fail_loc=1502, val=0*** [ 849.821739] Lustre: Failing over lustre-MDT0000 [ 850.201440] Lustre: server umount lustre-MDT0000 complete [ 850.404313] 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 [ 850.411790] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 850.419412] Lustre: Skipped 1 previous similar message [ 850.422461] LustreError: 26267:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 850.441705] LustreError: 26267:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 11 previous similar messages [ 861.795858] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 861.956169] LustreError: MGC192.168.201.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 862.150503] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 867.301613] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 867.305991] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 867.321706] Lustre: Skipped 3 previous similar messages [ 867.344609] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 867.429873] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:169 to 0x2c0000401:193) [ 867.431184] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:169 to 0x280000401:193) [ 868.420248] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 873.667452] Lustre: *** cfs_fail_loc=1505, val=0*** [ 883.742550] Lustre: DEBUG MARKER: == sanity-lfsck test 1c: LFSCK can find out and repair lost FID-in-dirent ========================================================== 03:31:12 (1788593472) [ 891.616975] Lustre: *** cfs_fail_loc=1504, val=0*** [ 891.621231] Lustre: *** cfs_fail_loc=1504, val=0*** [ 891.624757] Lustre: Skipped 1 previous similar message [ 901.879850] Lustre: Failing over lustre-MDT0000 [ 902.485135] Lustre: server umount lustre-MDT0000 complete [ 903.146961] 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 [ 903.148320] LustreError: 26268:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 903.164958] Lustre: Skipped 4 previous similar messages [ 903.174389] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 903.194427] LustreError: 26268:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 10 previous similar messages [ 916.003542] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 916.208151] LustreError: MGC192.168.201.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 916.589849] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 916.602896] Lustre: Skipped 1 previous similar message [ 916.657647] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 921.736620] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 922.089488] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 922.094753] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 922.118079] Lustre: Skipped 3 previous similar messages [ 922.155034] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 922.225598] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:233 to 0x280000401:257) [ 922.227209] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:233 to 0x2c0000401:257) [ 926.408758] Lustre: *** cfs_fail_loc=1505, val=0*** [ 933.636871] Lustre: DEBUG MARKER: == sanity-lfsck test 2a: LFSCK can find out and repair crashed linkEA entry ========================================================== 03:32:02 (1788593522) [ 934.966485] Lustre: 29295:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 934.973734] Lustre: 29295:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 643 previous similar messages [ 934.979627] Lustre: 29295:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 934.984576] Lustre: 29295:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 934.988507] Lustre: 29295:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 934.991718] Lustre: 29295:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 934.996500] Lustre: 29295:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 935.007097] Lustre: 29295:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 935.027469] Lustre: 29295:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 935.045391] Lustre: 29295:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 935.059257] Lustre: 29295:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 935.071656] Lustre: 29295:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 939.686814] Lustre: *** cfs_fail_loc=1603, val=0*** [ 948.989062] Lustre: Failing over lustre-MDT0000 [ 949.312799] Lustre: server umount lustre-MDT0000 complete [ 952.800814] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 952.808933] 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 [ 952.837379] Lustre: Skipped 4 previous similar messages [ 960.857548] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 960.969867] LustreError: MGC192.168.201.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 961.257837] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 965.697956] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 966.630585] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 966.636386] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 966.659194] Lustre: Skipped 3 previous similar messages [ 966.690430] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 966.769641] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:297 to 0x280000401:321) [ 966.777581] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:297 to 0x2c0000401:321) [ 975.549594] Lustre: DEBUG MARKER: == sanity-lfsck test 2b: LFSCK can find out and remove invalid linkEA entry ========================================================== 03:32:44 (1788593564) [ 982.459210] Lustre: *** cfs_fail_loc=1604, val=0*** [ 991.197081] Lustre: Failing over lustre-MDT0000 [ 991.540692] Lustre: server umount lustre-MDT0000 complete [ 992.224628] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 992.227721] 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 [ 992.262692] LustreError: 27004:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 992.286542] LustreError: 27004:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 20 previous similar messages [ 1003.388365] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1003.486557] LustreError: MGC192.168.201.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1003.854514] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1009.132273] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1009.138116] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1009.148300] Lustre: Skipped 3 previous similar messages [ 1009.164572] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1009.238704] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:361 to 0x2c0000401:385) [ 1009.239102] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:361 to 0x280000401:385) [ 1009.839156] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1019.165218] Lustre: DEBUG MARKER: == sanity-lfsck test 2c: LFSCK can find out and remove repeated linkEA entry ========================================================== 03:33:27 (1788593607) [ 1027.053088] Lustre: *** cfs_fail_loc=1605, val=0*** [ 1035.338493] Lustre: Failing over lustre-MDT0000 [ 1035.650464] Lustre: server umount lustre-MDT0000 complete [ 1039.841355] 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 [ 1039.872575] Lustre: Skipped 6 previous similar messages [ 1046.524029] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1046.667504] LustreError: MGC192.168.201.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1046.983162] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1046.987779] Lustre: Skipped 2 previous similar messages [ 1047.029511] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1051.794795] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1052.136969] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1052.138427] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1052.143789] Lustre: Skipped 3 previous similar messages [ 1052.169837] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1052.217178] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:425 to 0x280000401:449) [ 1052.224714] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:425 to 0x2c0000401:449) [ 1062.695091] Lustre: DEBUG MARKER: == sanity-lfsck test 2d: LFSCK can recover the missing linkEA entry ========================================================== 03:34:11 (1788593651) [ 1064.447289] Lustre: 26266:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 1064.453198] Lustre: 26266:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 968 previous similar messages [ 1064.457294] Lustre: 26266:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 1064.461812] Lustre: 26266:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 968 previous similar messages [ 1064.470675] Lustre: 26266:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 1064.474978] Lustre: 26266:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 968 previous similar messages [ 1064.478968] Lustre: 26266:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 1064.486624] Lustre: 26266:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 968 previous similar messages [ 1064.497550] Lustre: 26266:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 1064.510776] Lustre: 26266:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 968 previous similar messages [ 1064.516142] Lustre: 26266:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 1064.523221] Lustre: 26266:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 968 previous similar messages [ 1070.548900] Lustre: *** cfs_fail_loc=161d, val=0*** [ 1079.261842] Lustre: Failing over lustre-MDT0000 [ 1079.553293] Lustre: server umount lustre-MDT0000 complete [ 1082.848613] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1091.455043] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1091.627977] LustreError: MGC192.168.201.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1091.969671] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1097.188456] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1097.206811] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1097.219205] Lustre: Skipped 3 previous similar messages [ 1097.257780] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1097.303740] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1097.307950] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:489 to 0x2c0000401:513) [ 1097.308180] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:489 to 0x280000401:513) [ 1108.011878] Lustre: DEBUG MARKER: == sanity-lfsck test 2e: namespace LFSCK can verify remote object linkEA ========================================================== 03:34:56 (1788593696) [ 1111.323813] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1124.112495] Lustre: DEBUG MARKER: == sanity-lfsck test 3: LFSCK can verify multiple-linked objects ========================================================== 03:35:12 (1788593712) [ 1131.511774] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1132.917831] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1145.729066] Lustre: DEBUG MARKER: == sanity-lfsck test 4: FID-in-dirent can be rebuilt after MDT file-level backup/restore ========================================================== 03:35:33 (1788593733) [ 1181.455589] Lustre: Failing over lustre-MDT0000 [ 1181.846112] Lustre: server umount lustre-MDT0000 complete [ 1184.242962] 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 [ 1184.251235] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1184.251443] LustreError: 26266:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1184.251451] LustreError: 26266:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 24 previous similar messages [ 1184.266386] Lustre: Skipped 6 previous similar messages [ 1187.473470] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1198.241370] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1200.608236] Lustre: 16404:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788593774/real 1788593774] req@ffff9a65ba9a4e00 x1875475722611328/t0(0) o400->MGC192.168.201.155@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1788593790 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1200.660667] LustreError: MGC192.168.201.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1211.446494] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1211.476661] Lustre: lustre-MDT0000: reset Object Index mappings [ 1225.188822] LustreError: 16401:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9a65bace7800 x1875475722624000/t0(0) o250->MGC192.168.201.155@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 [ 1225.688285] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1230.855705] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1230.869325] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 1230.886351] Lustre: Skipped 3 previous similar messages [ 1230.918145] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1230.992341] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:592 to 0x280000401:609) [ 1230.992384] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:592 to 0x2c0000401:609) [ 1231.433656] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1235.746430] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1236.768734] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1237.794806] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1239.841869] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1239.849556] Lustre: Skipped 1 previous similar message [ 1246.067910] Lustre: Failing over lustre-MDT0000 [ 1246.186889] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1246.188293] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1246.627119] Lustre: server umount lustre-MDT0000 complete [ 1257.412135] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1262.641174] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1263.149787] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:592 to 0x2c0000401:641) [ 1263.150508] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:592 to 0x280000401:641) [ 1265.944399] Lustre: *** cfs_fail_loc=1505, val=0*** [ 1275.661840] Lustre: DEBUG MARKER: == sanity-lfsck test 5: LFSCK can handle IGIF object upgrading ========================================================== 03:37:43 (1788593863) [ 1278.162829] Lustre: *** cfs_fail_loc=1504, val=0*** [ 1288.216509] Lustre: Failing over lustre-MDT0000 [ 1288.683619] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1288.745733] Lustre: server umount lustre-MDT0000 complete [ 1295.563642] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1306.421535] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1310.180100] Lustre: 16404:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788593884/real 1788593884] req@ffff9a65baf13100 x1875475722714624/t0(0) o400->MGC192.168.201.155@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1788593900 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1319.292233] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1319.312766] Lustre: lustre-MDT0000: reset Object Index mappings [ 1320.848431] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1320.853542] Lustre: Skipped 3 previous similar messages [ 1320.899570] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1320.913448] Lustre: Skipped 1 previous similar message [ 1325.834779] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1326.051265] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1326.056026] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1326.059948] Lustre: Skipped 1 previous similar message [ 1326.067544] Lustre: Skipped 7 previous similar messages [ 1326.078530] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1326.083397] Lustre: Skipped 1 previous similar message [ 1326.132334] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:681 to 0x2c0000401:705) [ 1326.137302] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:681 to 0x280000401:705) [ 1329.097817] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1337.312281] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1337.314277] Lustre: Skipped 7 previous similar messages [ 1343.267318] Lustre: Failing over lustre-MDT0000 [ 1343.673226] Lustre: server umount lustre-MDT0000 complete [ 1346.530100] 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 [ 1346.571155] Lustre: Skipped 11 previous similar messages [ 1357.905069] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1358.076778] LustreError: MGC192.168.201.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1358.086658] LustreError: Skipped 2 previous similar messages [ 1363.492571] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:681 to 0x280000401:737) [ 1363.502376] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:681 to 0x2c0000401:737) [ 1363.889747] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1368.309585] Lustre: *** cfs_fail_loc=1505, val=0*** [ 1368.316972] Lustre: Skipped 84 previous similar messages [ 1377.277082] Lustre: DEBUG MARKER: == sanity-lfsck test 6a: LFSCK resumes from last checkpoint (1) ========================================================== 03:39:25 (1788593965) [ 1378.418391] Lustre: 34135:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 1378.425185] Lustre: 34135:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 1296 previous similar messages [ 1378.431181] Lustre: 34135:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 1378.438345] Lustre: 34135:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1296 previous similar messages [ 1378.444342] Lustre: 34135:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 1378.449961] Lustre: 34135:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1296 previous similar messages [ 1378.455279] Lustre: 34135:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 1378.462936] Lustre: 34135:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1296 previous similar messages [ 1378.472377] Lustre: 34135:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 1378.487069] Lustre: 34135:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1296 previous similar messages [ 1378.504146] Lustre: 34135:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 1378.519392] Lustre: 34135:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1296 previous similar messages [ 1387.424273] Lustre: *** cfs_fail_loc=1600, val=1*** [ 1414.542211] Lustre: DEBUG MARKER: == sanity-lfsck test 6b: LFSCK resumes from last checkpoint (2) ========================================================== 03:40:02 (1788594002) [ 1426.636257] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1426.638248] Lustre: Skipped 11 previous similar messages [ 1457.625560] Lustre: DEBUG MARKER: == sanity-lfsck test 7a: non-stopped LFSCK should auto restarts after MDS remount (1) ========================================================== 03:40:44 (1788594044) [ 1482.813027] Lustre: Failing over lustre-MDT0000 [ 1483.284673] Lustre: server umount lustre-MDT0000 complete [ 1486.304725] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1486.325357] LustreError: Skipped 1 previous similar message [ 1486.337276] LustreError: 26268:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1486.395284] LustreError: 26268:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 94 previous similar messages [ 1495.159175] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1495.872698] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1495.879901] Lustre: Skipped 1 previous similar message [ 1501.156736] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1501.165120] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1501.166678] Lustre: Skipped 1 previous similar message [ 1501.176392] Lustre: Skipped 7 previous similar messages [ 1501.221718] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1501.238571] Lustre: Skipped 1 previous similar message [ 1501.277859] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1501.317396] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:854 to 0x2c0000401:897) [ 1501.321582] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:853 to 0x280000401:897) [ 1512.160805] Lustre: DEBUG MARKER: == sanity-lfsck test 7b: non-stopped LFSCK should auto restarts after MDS remount (2) ========================================================== 03:41:40 (1788594100) [ 1527.944496] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing load_modules_local [ 1548.032470] Lustre: 52977:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 1572.647476] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1576.746974] Lustre: 54114:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 1586.220048] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1586.224853] Lustre: Skipped 81 previous similar messages [ 1590.369630] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1591.392107] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1592.416274] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1594.465746] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1594.467681] Lustre: Skipped 1 previous similar message [ 1597.904171] Lustre: Failing over lustre-MDT0000 [ 1598.308490] Lustre: server umount lustre-MDT0000 complete [ 1609.162030] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1614.971704] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:947 to 0x2c0000401:993) [ 1614.973848] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:946 to 0x280000401:961) [ 1615.627671] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1625.082966] Lustre: DEBUG MARKER: == sanity-lfsck test 8: LFSCK state machine ============== 03:43:33 (1788594213) [ 1630.181477] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1630.183280] 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 [ 1630.183893] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1630.183898] Lustre: Skipped 3 previous similar messages [ 1630.217107] Lustre: Skipped 12 previous similar messages [ 1633.488233] Lustre: server umount lustre-MDT0000 complete [ 1637.736914] LustreError: 26252:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788594228 with bad export cookie 691450287131480288 [ 1637.743802] LustreError: MGC192.168.201.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1637.760421] LustreError: 26252:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 1637.795342] LustreError: Skipped 2 previous similar messages [ 1638.055545] Lustre: server umount lustre-MDT0001 complete [ 1653.160298] Lustre: server umount lustre-OST0000 complete [ 1656.545222] Lustre: 16402:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788594230/real 1788594230] req@ffff9a65bb62f480 x1875475723065984/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788594246 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1657.388649] Lustre: server umount lustre-OST0001 complete [ 1665.105440] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_hostid [ 1672.577521] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing load_modules_local [ 1718.260120] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing load_modules_local [ 1728.978116] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1729.268436] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 1729.321111] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 1729.484287] Lustre: lustre-MDT0000: new disk, initializing [ 1729.598226] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 1734.596644] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1745.637854] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1745.693407] Lustre: 59173:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 1745.717829] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 1745.719985] Lustre: Skipped 1 previous similar message [ 1745.776586] Lustre: lustre-MDT0001: new disk, initializing [ 1745.874389] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 1745.887256] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 1750.300482] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1754.742411] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 1761.267923] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 1761.502300] Lustre: lustre-OST0000: new disk, initializing [ 1761.506843] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 1761.521251] Lustre: 60807:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 1762.734304] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 1762.746706] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 1762.837667] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 1768.646700] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1779.438832] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 1779.572684] Lustre: lustre-OST0001: new disk, initializing [ 1779.578120] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 1779.582878] Lustre: 61678:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 1781.407938] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 1781.423976] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 1781.514730] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 1786.332868] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1796.265592] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1800.868883] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 1812.095254] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1813.345878] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1813.347802] Lustre: Skipped 19 previous similar messages [ 1818.443763] Lustre: *** cfs_fail_loc=1601, val=2*** [ 1818.454613] Lustre: Skipped 22 previous similar messages [ 1840.306197] Lustre: Failing over lustre-MDT0000 [ 1840.566211] Lustre: server umount lustre-MDT0000 complete [ 1851.184632] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1851.582571] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1851.591032] Lustre: Skipped 7 previous similar messages [ 1851.630618] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1851.637039] Lustre: Skipped 1 previous similar message [ 1857.009129] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1857.015820] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1857.024930] Lustre: Skipped 1 previous similar message [ 1857.054367] Lustre: Skipped 7 previous similar messages [ 1857.096739] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1857.113795] Lustre: Skipped 1 previous similar message [ 1857.179322] Lustre: *** cfs_fail_loc=160b, val=2*** [ 1857.195724] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:65) [ 1857.198510] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:65) [ 1857.217749] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1867.628132] Lustre: Failing over lustre-MDT0000 [ 1868.021608] Lustre: server umount lustre-MDT0000 complete [ 1878.565737] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1884.178863] Lustre: *** cfs_fail_loc=160b, val=2*** [ 1884.182398] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:97) [ 1884.186273] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:97) [ 1884.888722] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1890.937231] Lustre: Failing over lustre-MDT0000 [ 1891.215401] Lustre: server umount lustre-MDT0000 complete [ 1899.037359] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1904.483468] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1904.667475] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:129) [ 1904.667960] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:129) [ 1910.219514] Lustre: *** cfs_fail_loc=1602, val=2*** [ 1910.221333] Lustre: Skipped 3 previous similar messages [ 1923.990747] Lustre: DEBUG MARKER: == sanity-lfsck test 9a: LFSCK speed control (1) ========= 03:48:32 (1788594512) [ 1939.644887] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing load_modules_local [ 1961.618598] Lustre: 68684:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 1987.936736] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1991.906043] Lustre: 69820:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 2001.800892] Lustre: 59179:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 2001.809469] Lustre: 59179:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 2836 previous similar messages [ 2001.815162] Lustre: 59179:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 2001.821498] Lustre: 59179:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 2836 previous similar messages [ 2001.828047] Lustre: 59179:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 2001.831462] Lustre: 59179:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 2836 previous similar messages [ 2001.835127] Lustre: 59179:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 2001.840523] Lustre: 59179:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 2836 previous similar messages [ 2001.844430] Lustre: 59179:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 2001.848883] Lustre: 59179:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 2836 previous similar messages [ 2001.855491] Lustre: 59179:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 2001.861664] Lustre: 59179:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 2836 previous similar messages [ 2104.578118] Lustre: DEBUG MARKER: == sanity-lfsck test 9b: LFSCK speed control (2) ========= 03:51:33 (1788594693) [ 2159.452741] Lustre: *** cfs_fail_loc=1604, val=0*** [ 2159.462559] Lustre: Skipped 4 previous similar messages [ 2186.198076] Lustre: *** cfs_fail_loc=160c, val=0*** [ 2186.199906] Lustre: Skipped 10 previous similar messages [ 2224.443020] Lustre: DEBUG MARKER: == sanity-lfsck test 10: System is available during LFSCK scanning ========================================================== 03:53:33 (1788594813) [ 2271.794778] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2272.799934] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2272.802707] Lustre: Skipped 46 previous similar messages [ 2274.817456] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2274.821232] Lustre: Skipped 94 previous similar messages [ 2278.851897] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2278.853497] Lustre: Skipped 173 previous similar messages [ 2286.855061] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2286.861380] Lustre: Skipped 396 previous similar messages [ 2302.874980] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2302.876966] Lustre: Skipped 779 previous similar messages [ 2334.888255] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2334.897416] Lustre: Skipped 1462 previous similar messages [ 2347.988313] Lustre: *** cfs_fail_loc=1604, val=0*** [ 2347.999203] Lustre: Skipped 2599 previous similar messages [ 2608.150426] Lustre: DEBUG MARKER: == sanity-lfsck test 11a: LFSCK can rebuild lost last_id ========================================================== 03:59:56 (1788595196) [ 2615.400182] Lustre: 59180:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 320, rollback = 2 [ 2615.406320] Lustre: 59180:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 36831 previous similar messages [ 2615.411561] Lustre: 59180:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 1/4/0 [ 2615.416890] Lustre: 59180:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 36831 previous similar messages [ 2615.422319] Lustre: 59180:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 5/5/0, xattr_set: 7/320/0 [ 2615.427693] Lustre: 59180:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 36831 previous similar messages [ 2615.437387] Lustre: 59180:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 6/46/0, punch: 0/0/0, quota 1/3/0 [ 2615.443818] Lustre: 59180:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 36831 previous similar messages [ 2615.448840] Lustre: 59180:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 2/5/0 [ 2615.454863] Lustre: 59180:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 36831 previous similar messages [ 2615.459826] Lustre: 59180:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 1/1/0, ref_del: 2/2/1 [ 2615.465284] Lustre: 59180:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 36831 previous similar messages [ 2763.957477] Lustre: server umount lustre-MDT0000 complete [ 2764.785339] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 2764.791724] LustreError: Skipped 2 previous similar messages [ 2764.792425] 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 [ 2764.795829] LustreError: 60800:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 2764.807800] Lustre: Skipped 14 previous similar messages [ 2764.833271] LustreError: 60800:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 43 previous similar messages [ 2768.217921] LustreError: 59166:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788595358 with bad export cookie 691450287131499377 [ 2768.220459] LustreError: MGC192.168.201.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2768.237057] LustreError: 59166:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 2768.253445] LustreError: Skipped 3 previous similar messages [ 2768.624909] Lustre: server umount lustre-MDT0001 complete [ 2783.409786] Lustre: server umount lustre-OST0000 complete [ 2785.761127] Lustre: 16405:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788595360/real 1788595360] req@ffff9a65bdabd500 x1875475726891776/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788595376 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2787.278778] Lustre: server umount lustre-OST0001 complete [ 2794.133721] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: (null) [ 2802.560627] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 2818.080420] LustreError: Failed to get MGS log lustre-sptlrpc and no local copy. [ 2823.202154] LustreError: 74939:0:(mgc_request.c:233:do_config_log_add()) MGC192.168.201.155@tcp: failed processing log, type 4: rc = -110 [ 2848.928698] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 2848.938359] Lustre: Skipped 2 previous similar messages [ 2854.823076] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2858.682650] Lustre: 75524:0:(ofd_dev.c:561:ofd_lfsck_out_notify()) lustre-OST0000: Found crashed LAST_ID, deny creating new OST-object on the device until the LAST_ID rebuilt successfully. [ 2858.707052] Lustre: *** cfs_fail_loc=160e, val=3*** [ 2861.736942] Lustre: 75524:0:(ofd_dev.c:573:ofd_lfsck_out_notify()) lustre-OST0000: Rebuilt crashed LAST_ID files successfully. [ 2871.733871] Lustre: DEBUG MARKER: == sanity-lfsck test 11b: LFSCK can rebuild crashed last_id ========================================================== 04:04:19 (1788595459) [ 2888.040651] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing load_modules_local [ 2901.651228] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2902.134725] LustreError: 74964:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 2902.278391] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3272 to 0x280000401:3297) [ 2907.457883] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2918.054406] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2923.959341] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2927.627446] Lustre: 78190:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 2946.582811] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2952.189902] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3207 to 0x2c0000401:3233) [ 2953.585708] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2962.287821] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 2966.817391] Lustre: 79689:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 2972.905823] Lustre: *** cfs_fail_loc=160d, val=0*** [ 2982.341355] Lustre: Failing over lustre-OST0000 [ 2982.457812] Lustre: server umount lustre-OST0000 complete [ 2982.910177] 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 [ 2982.936748] Lustre: Skipped 3 previous similar messages [ 2994.354379] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2994.767798] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 2994.788491] Lustre: Skipped 2 previous similar messages [ 2996.582033] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 2996.597246] Lustre: Skipped 2 previous similar messages [ 2996.638966] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 2996.642539] Lustre: lustre-OST0000-osc-MDT0001: Connection restored to 0@lo (at 0@lo) [ 2996.644939] Lustre: *** cfs_fail_loc=215, val=0*** [ 2996.653134] Lustre: Skipped 2 previous similar messages [ 2996.673037] Lustre: Skipped 11 previous similar messages [ 3001.824734] Lustre: *** cfs_fail_loc=215, val=0*** [ 3001.832791] Lustre: Skipped 1 previous similar message [ 3003.416585] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3006.946570] Lustre: *** cfs_fail_loc=215, val=0*** [ 3006.949422] Lustre: Skipped 2 previous similar messages [ 3007.642533] Lustre: 81090:0:(ofd_dev.c:561:ofd_lfsck_out_notify()) lustre-OST0000: Found crashed LAST_ID, deny creating new OST-object on the device until the LAST_ID rebuilt successfully. [ 3007.678558] Lustre: 81090:0:(ofd_dev.c:573:ofd_lfsck_out_notify()) lustre-OST0000: Rebuilt crashed LAST_ID files successfully. [ 3010.419957] Lustre: Failing over lustre-OST0000 [ 3010.488515] Lustre: server umount lustre-OST0000 complete [ 3012.065714] LustreError: lustre-OST0000-osc-MDT0001: operation ost_statfs to node 0@lo failed: rc = -107 [ 3018.917532] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3020.473739] Lustre: *** cfs_fail_loc=215, val=0*** [ 3020.477755] Lustre: Skipped 3 previous similar messages [ 3025.115203] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3025.888531] Lustre: *** cfs_fail_loc=215, val=0*** [ 3025.894954] Lustre: Skipped 1 previous similar message [ 3031.019198] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3031.024337] Lustre: Skipped 3 previous similar messages [ 3034.599146] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3034.607543] Lustre: Skipped 3 previous similar messages [ 3039.713172] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3039.727818] Lustre: Skipped 3 previous similar messages [ 3044.835867] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3044.840043] Lustre: Skipped 3 previous similar messages [ 3045.344318] Lustre: lustre-MDT0000 is waiting for obd_unlinked_exports more than 8 seconds. The obd refcount = 3. Is it stuck? [ 3045.425281] Lustre: server umount lustre-MDT0000 complete [ 3049.428774] LustreError: 74946:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788595639 with bad export cookie 691450287133081615 [ 3049.446532] LustreError: MGC192.168.201.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3049.460058] LustreError: 74946:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 3049.827540] Lustre: server umount lustre-MDT0001 complete [ 3065.094635] Lustre: server umount lustre-OST0000 complete [ 3065.760994] Lustre: 16403:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788595640/real 1788595640] req@ffff9a65bc54b800 x1875475726997248/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788595656 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3070.322704] Lustre: server umount lustre-OST0001 complete [ 3081.262711] Lustre: DEBUG MARKER: == sanity-lfsck test 12a: single command to trigger LFSCK on all devices ========================================================== 04:07:49 (1788595669) [ 3097.695149] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing load_modules_local [ 3110.347298] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3110.853293] LustreError: 84333:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3110.871390] LustreError: 84333:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 31 previous similar messages [ 3115.807944] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3125.203064] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3130.939818] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3133.815565] Lustre: 85474:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3139.730686] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3146.052606] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3154.164221] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3156.400316] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3362 to 0x280000401:3393) [ 3156.405972] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3207 to 0x2c0000401:3265) [ 3161.138073] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3168.740245] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3172.795914] Lustre: 87344:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 3205.130738] Lustre: DEBUG MARKER: == sanity-lfsck test 12b: auto detect Lustre device ====== 04:09:53 (1788595793) [ 3219.590377] Lustre: DEBUG MARKER: == sanity-lfsck test 13: LFSCK can repair crashed lmm_oi ========================================================== 04:10:08 (1788595808) [ 3219.980237] Lustre: 84329:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 252 < left 278, rollback = 2 [ 3219.991304] Lustre: 84329:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 1002 previous similar messages [ 3220.000730] Lustre: 84329:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 3220.014573] Lustre: 84329:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1002 previous similar messages [ 3220.035108] Lustre: 84329:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3220.041016] Lustre: 84329:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1002 previous similar messages [ 3220.048142] Lustre: 84329:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 3220.052456] Lustre: 84329:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1002 previous similar messages [ 3220.057227] Lustre: 84329:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 3220.062927] Lustre: 84329:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1002 previous similar messages [ 3220.068441] Lustre: 84329:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3220.073660] Lustre: 84329:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1002 previous similar messages [ 3221.158448] Lustre: *** cfs_fail_loc=160f, val=0*** [ 3233.068904] Lustre: DEBUG MARKER: == sanity-lfsck test 14a: LFSCK can repair MDT-object with dangling LOV EA reference (1) ========================================================== 04:10:21 (1788595821) [ 3237.116873] Lustre: *** cfs_fail_loc=1610, val=0*** [ 3237.121498] Lustre: Skipped 7 previous similar messages [ 3289.579053] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3289.585417] 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 [ 3289.588281] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3289.600217] LustreError: Skipped 2 previous similar messages [ 3289.646900] Lustre: Skipped 11 previous similar messages [ 3291.739879] Lustre: server umount lustre-MDT0000 complete [ 3295.295865] LustreError: 84314:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788595885 with bad export cookie 691450287133090064 [ 3295.304712] LustreError: MGC192.168.201.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3295.310074] LustreError: 84314:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 3295.531618] Lustre: server umount lustre-MDT0001 complete [ 3309.128747] Lustre: server umount lustre-OST0000 complete [ 3323.682067] Lustre: server umount lustre-OST0001 complete [ 3340.535281] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing load_modules_local [ 3352.811459] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3358.541526] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3367.262862] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3372.491916] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3375.964806] Lustre: 93214:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3383.512541] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3389.773524] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3391.984135] LustreError: 93570:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3392.004115] LustreError: 93570:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 10 previous similar messages [ 3392.008512] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:116 to 0x280000400:161) [ 3398.151268] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3554 to 0x280000401:3585) [ 3400.663836] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3406.311444] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:116 to 0x2c0000400:161) [ 3406.326644] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3317 to 0x2c0000401:3361) [ 3408.867732] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3417.658313] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3422.011307] Lustre: 95088:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 3429.193637] Lustre: DEBUG MARKER: == sanity-lfsck test 14b: LFSCK can repair MDT-object with dangling LOV EA reference (2) ========================================================== 04:13:37 (1788596017) [ 3435.063478] Lustre: *** cfs_fail_loc=1610, val=0*** [ 3435.074904] Lustre: Skipped 63 previous similar messages [ 3460.066810] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3460.075606] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3460.079991] Lustre: Skipped 3 previous similar messages [ 3472.353327] Lustre: lustre-MDT0000 is waiting for obd_unlinked_exports more than 8 seconds. The obd refcount = 3. Is it stuck? [ 3472.730803] Lustre: server umount lustre-MDT0000 complete [ 3477.137698] LustreError: 92056:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788596067 with bad export cookie 691450287133118477 [ 3477.153606] LustreError: 92056:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 3477.705608] Lustre: server umount lustre-MDT0001 complete [ 3492.373296] Lustre: server umount lustre-OST0000 complete [ 3494.374313] Lustre: 16404:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788596068/real 1788596068] req@ffff9a648aa24380 x1875475727353344/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788596084 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3496.142700] Lustre: server umount lustre-OST0001 complete [ 3514.874292] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing load_modules_local [ 3525.384025] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3525.798389] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3525.808073] Lustre: Skipped 13 previous similar messages [ 3530.786987] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3538.984605] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3544.119972] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3547.059713] Lustre: 99122:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3554.030971] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3561.129133] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3564.729705] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:116 to 0x280000400:193) [ 3570.254056] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3572.529748] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3317 to 0x2c0000401:3393) [ 3572.671625] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:116 to 0x2c0000400:193) [ 3572.681229] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3682 to 0x280000401:3713) [ 3577.419752] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3584.965419] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3595.395429] Lustre: DEBUG MARKER: == sanity-lfsck test 15a: LFSCK can repair unmatched MDT-object/OST-object pairs (1) ========================================================== 04:16:24 (1788596184) [ 3598.772582] Lustre: *** cfs_fail_loc=1611, val=0*** [ 3598.780939] Lustre: Skipped 63 previous similar messages [ 3598.974239] Lustre: *** cfs_fail_loc=1611, val=0*** [ 3609.530847] Lustre: DEBUG MARKER: == sanity-lfsck test 15b: LFSCK can repair unmatched MDT-object/OST-object pairs (2) ========================================================== 04:16:38 (1788596198) [ 3612.059319] Lustre: *** cfs_fail_loc=1612, val=0*** [ 3612.153119] Lustre: *** cfs_fail_loc=1612, val=0*** [ 3612.159263] Lustre: Skipped 2 previous similar messages [ 3623.503632] Lustre: DEBUG MARKER: == sanity-lfsck test 15c: LFSCK can repair unmatched MDT-object/OST-object pairs (3) ========================================================== 04:16:52 (1788596212) [ 3625.220633] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_15c MDS newer than 2.7.55, LU-6475 [ 3627.124972] Lustre: DEBUG MARKER: == sanity-lfsck test 15d: LFSCK don't crash upon dir migration failure ========================================================== 04:16:55 (1788596215) [ 3633.396391] Lustre: *** cfs_fail_loc=1709, val=0*** [ 3633.403472] LustreError: 97992:0:(mdt_reint.c:2644:mdt_reint_migrate()) lustre-MDT0000: migrate [0x240002340:0x6c:0x0]/f58 failed: rc = -5 [ 3703.266028] 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 [ 3703.282519] Lustre: Skipped 5 previous similar messages [ 3703.285276] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3703.290083] Lustre: Skipped 8 previous similar messages [ 3709.269268] Lustre: server umount lustre-MDT0000 complete [ 3718.811880] LustreError: 97963:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788596309 with bad export cookie 691450287133133212 [ 3718.816684] LustreError: MGC192.168.201.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3718.829392] LustreError: 97963:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 3718.871468] LustreError: Skipped 1 previous similar message [ 3719.440471] Lustre: server umount lustre-MDT0001 complete [ 3737.504920] Lustre: 16402:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788596311/real 1788596311] req@ffff9a648dcc5500 x1875475727992832/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788596327 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3740.831040] Lustre: server umount lustre-OST0000 complete [ 3742.691312] Lustre: 16402:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788596316/real 1788596316] req@ffff9a65bca49f80 x1875475727993344/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788596332 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3742.751356] Lustre: 16402:0:(client.c:2504:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 3750.840350] Lustre: server umount lustre-OST0001 complete [ 3770.173959] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing unload_modules_local [ 3774.348523] Key type lgssc unregistered [ 3774.769796] LNet: 104831:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 3774.777368] LNetError: 104831:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 3774.802320] LNet: Removed LNI 192.168.201.155@tcp [ 3775.908168] Key type .llcrypt unregistered [ 3775.912128] Key type ._llcrypt unregistered [ 3803.128720] Key type ._llcrypt registered [ 3803.130340] Key type .llcrypt registered [ 3803.306429] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_hostid [ 3819.865641] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing load_modules_local [ 3821.627962] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 3821.709300] alg: No test for adler32 (adler32-zlib) [ 3822.853372] Lustre: Lustre: Build Version: 2.17.58_2_gae7f7f4 [ 3823.150030] LNet: Added LNI 192.168.201.155@tcp [8/256/0/180] [ 3824.826961] Key type lgssc registered [ 3826.352924] Lustre: Echo OBD driver; http://www.lustre.org/ [ 3880.360363] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing load_modules_local [ 3893.314346] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 3893.333778] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3894.586724] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 3894.612958] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 3894.729240] Lustre: lustre-MDT0000: new disk, initializing [ 3894.877604] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3894.912585] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 3899.812979] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3913.357441] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3913.465774] Lustre: 109285:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 3913.491802] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 3913.495550] Lustre: Skipped 1 previous similar message [ 3913.560934] Lustre: lustre-MDT0001: new disk, initializing [ 3913.603660] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 3913.619628] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 3913.622770] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 3917.711783] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3922.504854] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 3931.762075] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3931.980371] Lustre: lustre-OST0000: new disk, initializing [ 3931.982755] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 3931.985889] Lustre: 111221:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 3932.015232] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 3932.145531] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 3932.158583] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 3932.208182] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 3937.713928] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3950.727860] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3950.861495] Lustre: lustre-OST0001: new disk, initializing [ 3950.865726] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 3950.870991] Lustre: 112243:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 3950.926417] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 3957.878595] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3960.876074] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 3960.882979] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 3960.947860] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 3969.649970] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3979.499158] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 3985.705993] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 04:22:54 (1788596574) === [ 3992.452740] Lustre: DEBUG MARKER: == sanity-lfsck test 16: LFSCK can repair inconsistent MDT-object/OST-object owner ========================================================== 04:23:01 (1788596581) [ 3992.711863] Lustre: 109293:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 251 < left 278, rollback = 2 [ 3992.734494] Lustre: 109293:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 3992.749493] Lustre: 109293:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3992.767066] Lustre: 109293:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 3992.781983] Lustre: 109293:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 3992.796423] Lustre: 109293:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3993.347349] Lustre: 109293:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 252 < left 278, rollback = 2 [ 3993.357943] Lustre: 109293:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 9 previous similar messages [ 3993.360746] Lustre: 109293:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 3993.374619] Lustre: 109293:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3993.387589] Lustre: 109293:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3993.399121] Lustre: 109293:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3993.415532] Lustre: 109293:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/1, punch: 0/0/0, quota 7/369/2 [ 3993.425734] Lustre: 109293:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3993.436104] Lustre: 109293:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/1, delete: 0/0/0 [ 3993.446555] Lustre: 109293:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3993.456506] Lustre: 109293:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3993.466497] Lustre: 109293:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3994.353878] Lustre: 112774:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 3994.359749] Lustre: 112774:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 176 previous similar messages [ 3994.364025] Lustre: 112774:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 3994.367954] Lustre: 112774:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 176 previous similar messages [ 3994.391155] Lustre: 109292:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3994.395959] Lustre: 109292:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 182 previous similar messages [ 3994.420599] Lustre: 112774:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 7/369/0 [ 3994.425143] Lustre: 112774:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 188 previous similar messages [ 3994.444935] Lustre: 109291:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 3994.449666] Lustre: 109291:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 191 previous similar messages [ 3994.462821] Lustre: 109292:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3994.467760] Lustre: 109292:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 194 previous similar messages [ 3995.952608] Lustre: *** cfs_fail_loc=1613, val=0*** [ 4007.481481] Lustre: DEBUG MARKER: == sanity-lfsck test 17: LFSCK can repair multiple references ========================================================== 04:23:15 (1788596595) [ 4008.720325] Lustre: 112774:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 257 < left 278, rollback = 2 [ 4008.726994] Lustre: 112774:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 122 previous similar messages [ 4008.733689] Lustre: 112774:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 4008.739755] Lustre: 112774:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 122 previous similar messages [ 4008.743648] Lustre: 112774:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4008.751069] Lustre: 112774:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 116 previous similar messages [ 4008.754897] Lustre: 112774:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 4008.759361] Lustre: 112774:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 110 previous similar messages [ 4008.763837] Lustre: 112774:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 4008.768538] Lustre: 112774:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 107 previous similar messages [ 4008.773804] Lustre: 112774:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4008.778771] Lustre: 112774:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 4009.879837] Lustre: *** cfs_fail_loc=1614, val=0*** [ 4014.456781] Lustre: 111211:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 259 < left 275, rollback = 2 [ 4014.471073] Lustre: 111211:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 11 previous similar messages [ 4014.479502] Lustre: 111211:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 4014.491939] Lustre: 111211:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 4014.501976] Lustre: 111211:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/1, xattr_set: 3/275/0 [ 4014.512194] Lustre: 111211:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 4014.526552] Lustre: 111211:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/9/0, punch: 1/4/0, quota 7/225/0 [ 4014.535161] Lustre: 111211:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 4014.539722] Lustre: 111211:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 4014.545947] Lustre: 111211:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 4014.553599] Lustre: 111211:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 4014.563846] Lustre: 111211:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 4022.149716] Lustre: DEBUG MARKER: == sanity-lfsck test 18a: Find out orphan OST-object and repair it (1) ========================================================== 04:23:30 (1788596610) [ 4022.537433] Lustre: 112774:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 252 < left 278, rollback = 2 [ 4022.552530] Lustre: 112774:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 1 previous similar message [ 4022.570601] Lustre: 112774:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4022.573135] Lustre: 112774:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1 previous similar message [ 4022.595688] Lustre: 112774:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4022.607965] Lustre: 112774:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1 previous similar message [ 4022.623047] Lustre: 112774:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 4022.637511] Lustre: 112774:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1 previous similar message [ 4022.650853] Lustre: 112774:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 4022.658652] Lustre: 112774:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1 previous similar message [ 4022.665989] Lustre: 112774:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4022.672565] Lustre: 112774:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1 previous similar message [ 4025.414300] Lustre: *** cfs_fail_loc=1615, val=0*** [ 4025.415798] Lustre: Skipped 1 previous similar message [ 4026.507837] Lustre: *** cfs_fail_loc=1615, val=0*** [ 4026.510919] Lustre: Skipped 3 previous similar messages [ 4046.812734] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_18b skipping excluded test 18b [ 4048.438071] Lustre: DEBUG MARKER: == sanity-lfsck test 18c: Find out orphan OST-object and repair it (3) ========================================================== 04:23:57 (1788596637) [ 4049.045046] Lustre: 112774:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 4049.057844] Lustre: 112774:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 21 previous similar messages [ 4049.074857] Lustre: 112774:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 4049.084299] Lustre: 112774:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4049.090993] Lustre: 112774:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4049.104928] Lustre: 112774:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4049.115129] Lustre: 112774:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 4049.127871] Lustre: 112774:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4049.140099] Lustre: 112774:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 4049.147231] Lustre: 112774:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4049.159543] Lustre: 112774:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4049.167608] Lustre: 112774:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4051.991590] Lustre: *** cfs_fail_loc=1617, val=0*** [ 4052.051918] Lustre: *** cfs_fail_loc=1617, val=0*** [ 4055.049752] Lustre: *** cfs_fail_loc=1616, val=0*** [ 4055.055779] Lustre: Skipped 1 previous similar message [ 4077.109638] Lustre: DEBUG MARKER: == sanity-lfsck test 18d: Find out orphan OST-object and repair it (4) ========================================================== 04:24:25 (1788596665) [ 4079.082818] Lustre: *** cfs_fail_loc=1618, val=0*** [ 4079.086605] Lustre: Skipped 5 previous similar messages [ 4113.377321] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4113.384714] 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 [ 4113.394924] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4114.415304] 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 [ 4114.422664] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4114.451517] Lustre: Skipped 3 previous similar messages [ 4118.619616] Lustre: server umount lustre-MDT0000 complete [ 4122.858349] LustreError: 109275:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788596713 with bad export cookie 8446178810005740161 [ 4122.866063] LustreError: MGC192.168.201.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4122.872179] LustreError: 109275:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 4123.177938] Lustre: server umount lustre-MDT0001 complete [ 4136.978701] Lustre: server umount lustre-OST0000 complete [ 4139.940424] Lustre: 106441:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788596714/real 1788596714] req@ffff9a65b92a8e00 x1875479272569856/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788596730 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4139.967043] 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 [ 4139.986274] Lustre: Skipped 2 previous similar messages [ 4141.362503] Lustre: server umount lustre-OST0001 complete [ 4158.849334] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing load_modules_local [ 4169.829854] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4170.243743] LustreError: 117965:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4170.272521] LustreError: 117965:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 5 previous similar messages [ 4170.407568] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4175.598353] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4175.841860] LustreError: 117966:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4179.936944] LustreError: 117965:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4182.215225] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4182.425241] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 4186.023901] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4188.270164] Lustre: 119105:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 4193.282517] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4195.618995] LustreError: 119460:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4195.626656] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:116 to 0x280000401:161) [ 4198.455961] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4200.931499] LustreError: 119459:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4208.105029] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:4 to 0x280000400:33) [ 4208.500710] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4208.686238] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 4208.692389] Lustre: Skipped 1 previous similar message [ 4213.752310] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:4 to 0x2c0000401:33) [ 4213.833114] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:33) [ 4215.536466] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4223.478965] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4227.183225] Lustre: 120976:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 4240.697894] Lustre: DEBUG MARKER: == sanity-lfsck test 18e: Find out orphan OST-object and repair it (5) ========================================================== 04:27:09 (1788596829) [ 4241.025855] Lustre: 117960:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 251 < left 278, rollback = 2 [ 4241.030909] Lustre: 117960:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 46 previous similar messages [ 4241.033640] Lustre: 117960:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4241.036283] Lustre: 117960:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4241.038990] Lustre: 117960:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4241.041520] Lustre: 117960:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4241.044455] Lustre: 117960:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 4241.047099] Lustre: 117960:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4241.049566] Lustre: 117960:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 4241.052078] Lustre: 117960:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4241.054969] Lustre: 117960:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4241.057795] Lustre: 117960:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4242.408159] Lustre: *** cfs_fail_loc=1618, val=0*** [ 4242.410390] Lustre: Skipped 3 previous similar messages [ 4279.787056] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4279.799293] 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 [ 4279.824357] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4281.630762] Lustre: server umount lustre-MDT0000 complete [ 4285.173800] LustreError: 119107:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788596875 with bad export cookie 8446178810005755414 [ 4285.178993] LustreError: MGC192.168.201.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4285.183767] LustreError: 119107:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 4285.393964] Lustre: server umount lustre-MDT0001 complete [ 4298.887598] Lustre: server umount lustre-OST0000 complete [ 4300.777060] Lustre: 106442:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788596875/real 1788596875] req@ffff9a65b3ef9c00 x1875479272642688/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788596891 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4300.820126] 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 [ 4300.830034] Lustre: Skipped 3 previous similar messages [ 4302.946904] Lustre: server umount lustre-OST0001 complete [ 4319.011534] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing load_modules_local [ 4330.055399] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4330.420943] LustreError: 123542:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4330.438989] LustreError: 123542:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 3 previous similar messages [ 4330.516235] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4335.085251] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4345.248332] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4350.343693] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4353.659844] Lustre: 124684:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 4360.733752] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4368.077800] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4370.422095] LustreError: 125037:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4370.435724] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:4 to 0x280000400:65) [ 4370.463204] LustreError: 125037:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 2 previous similar messages [ 4375.530492] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:166 to 0x280000401:193) [ 4377.196492] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4382.729258] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:65) [ 4382.739419] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:4 to 0x2c0000401:65) [ 4385.074402] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4395.007966] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4399.568593] Lustre: 126555:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 4407.277993] Lustre: 123543:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 252 < left 260, rollback = 2 [ 4407.282371] Lustre: 123543:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 21 previous similar messages [ 4407.285413] Lustre: 123543:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4407.288811] Lustre: 123543:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4407.292315] Lustre: 123543:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 0/0/0, xattr_set: 1/260/0 [ 4407.295810] Lustre: 123543:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4407.300149] Lustre: 123543:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/9/0, punch: 0/0/0, quota 4/150/2 [ 4407.305517] Lustre: 123543:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4407.310730] Lustre: 123543:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 1/17/2, delete: 0/0/0 [ 4407.315479] Lustre: 123543:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4407.322660] Lustre: 123543:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 4407.333673] Lustre: 123543:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4407.360690] Lustre: *** cfs_fail_loc=1602, val=10*** [ 4437.253975] Lustre: DEBUG MARKER: == sanity-lfsck test 18f: Skip the failed OST(s) when handle orphan OST-objects ========================================================== 04:30:25 (1788597025) [ 4441.418961] Lustre: *** cfs_fail_loc=1616, val=0*** [ 4441.421464] Lustre: Skipped 3 previous similar messages [ 4447.515138] Lustre: *** cfs_fail_loc=161c, val=0*** [ 4447.517316] Lustre: Skipped 1 previous similar message [ 4469.018332] Lustre: DEBUG MARKER: == sanity-lfsck test 18g: Find out orphan OST-object and repair it (7) ========================================================== 04:30:56 (1788597056) [ 4471.407287] Lustre: *** cfs_fail_loc=162e, val=0*** [ 4491.665235] Lustre: DEBUG MARKER: == sanity-lfsck test 18h: LFSCK can repair crashed PFL extent range ========================================================== 04:31:20 (1788597080) [ 4497.212973] Lustre: *** cfs_fail_loc=162f, val=0*** [ 4497.219846] Lustre: Skipped 9 previous similar messages [ 4515.822770] Lustre: DEBUG MARKER: == sanity-lfsck test 19a: OST-object inconsistency self detect ========================================================== 04:31:44 (1788597104) [ 4528.959091] Lustre: DEBUG MARKER: == sanity-lfsck test 19b: OST-object inconsistency self repair ========================================================== 04:31:57 (1788597117) [ 4532.245766] Lustre: *** cfs_fail_loc=1611, val=0*** [ 4532.293616] Lustre: *** cfs_fail_loc=1611, val=0*** [ 4532.295546] Lustre: Skipped 3 previous similar messages [ 4536.892799] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.201.55@tcp inode [0x2000013a1:0x1f:0x0] object 0x280000401:202 extent [0-4095], client returned csum 0 (type 20), server csum a10080 (type 20) [ 4537.979488] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.201.55@tcp inode [0x2000013a1:0x20:0x0] object 0x280000401:203 extent [0-4095], client returned csum 0 (type 20), server csum a0007f (type 20) [ 4547.853320] Lustre: DEBUG MARKER: == sanity-lfsck test 20a: Handle the orphan with dummy LOV EA slot properly ========================================================== 04:32:15 (1788597135) [ 4548.199815] Lustre: 125515:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 252 < left 278, rollback = 2 [ 4548.206783] Lustre: 125515:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 104 previous similar messages [ 4548.213414] Lustre: 125515:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4548.219489] Lustre: 125515:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 4548.224224] Lustre: 125515:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4548.229786] Lustre: 125515:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 4548.236364] Lustre: 125515:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 4548.242121] Lustre: 125515:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 4548.246729] Lustre: 125515:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 4548.251880] Lustre: 125515:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 4548.256313] Lustre: 125515:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4548.260613] Lustre: 125515:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 4579.507938] Lustre: DEBUG MARKER: == sanity-lfsck test 20b: Handle the orphan with dummy LOV EA slot properly - PFL case ========================================================== 04:32:48 (1788597168) [ 4586.395818] Lustre: DEBUG MARKER: == sanity-lfsck test 21: run all LFSCK components by default ========================================================== 04:32:55 (1788597175) [ 4601.705645] Lustre: DEBUG MARKER: == sanity-lfsck test 22a: LFSCK can repair unmatched pairs (1) ========================================================== 04:33:09 (1788597189) [ 4604.583535] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4604.600513] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4604.611374] Lustre: Skipped 1 previous similar message [ 4617.150897] Lustre: DEBUG MARKER: == sanity-lfsck test 22b: LFSCK can repair unmatched pairs (2) ========================================================== 04:33:25 (1788597205) [ 4618.916160] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4618.920730] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4632.238965] Lustre: DEBUG MARKER: == sanity-lfsck test 23a: LFSCK can repair dangling name entry (1) ========================================================== 04:33:40 (1788597220) [ 4634.278435] Lustre: *** cfs_fail_loc=1620, val=0*** [ 4650.558839] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_23b skipping excluded test 23b [ 4652.339414] Lustre: DEBUG MARKER: == sanity-lfsck test 23c: LFSCK can repair dangling name entry (3) ========================================================== 04:34:01 (1788597241) [ 4658.818601] Lustre: *** cfs_fail_loc=1621, val=127*** [ 4658.820273] Lustre: Skipped 1 previous similar message [ 4661.630621] Lustre: *** cfs_fail_loc=1602, val=10*** [ 4684.633080] Lustre: DEBUG MARKER: == sanity-lfsck test 23d: LFSCK can repair a dangling name entry to a remote object ========================================================== 04:34:32 (1788597272) [ 4687.382225] Lustre: Failing over lustre-MDT0000 [ 4688.869707] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4688.872928] 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 [ 4688.893201] LustreError: 123543:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4688.909023] LustreError: 123543:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 2 previous similar messages [ 4689.691823] Lustre: server umount lustre-MDT0000 complete [ 4699.698478] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4699.795745] LustreError: MGC192.168.201.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4700.038430] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4700.046610] Lustre: Skipped 3 previous similar messages [ 4700.111154] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4701.754317] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4705.262089] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4705.318774] Lustre: lustre-MDT0000: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 4705.345970] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:130 to 0x2c0000401:161) [ 4705.347651] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:265 to 0x280000401:289) [ 4705.502903] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4707.378648] LustreError: 123538:0:(mdt_open.c:1324:mdt_cross_open()) lustre-MDT0000: [0x2000013a3:0x82:0x0] doesn't exist!: rc = -14 [ 4718.574321] Lustre: DEBUG MARKER: == sanity-lfsck test 24: LFSCK can repair multiple-referenced name entry ========================================================== 04:35:07 (1788597307) [ 4720.796162] Lustre: *** cfs_fail_loc=1622, val=0*** [ 4720.936363] Lustre: *** cfs_fail_loc=1622, val=0*** [ 4720.939402] Lustre: Skipped 1 previous similar message [ 4732.520319] Lustre: DEBUG MARKER: == sanity-lfsck test 25: LFSCK can repair bad file type in the name entry ========================================================== 04:35:21 (1788597321) [ 4734.068990] Lustre: *** cfs_fail_loc=1623, val=0*** [ 4743.904427] Lustre: DEBUG MARKER: == sanity-lfsck test 26a: LFSCK can add the missing local name entry back to the namespace ========================================================== 04:35:32 (1788597332) [ 4745.373603] Lustre: *** cfs_fail_loc=1624, val=0*** [ 4757.395301] Lustre: DEBUG MARKER: == sanity-lfsck test 26b: LFSCK can add the missing remote name entry back to the namespace ========================================================== 04:35:45 (1788597345) [ 4771.488389] Lustre: DEBUG MARKER: == sanity-lfsck test 27a: LFSCK can recreate the lost local parent directory as orphan ========================================================== 04:35:59 (1788597359) [ 4773.347356] Lustre: *** cfs_fail_loc=1624, val=0*** [ 4773.353533] Lustre: Skipped 1 previous similar message [ 4786.290769] Lustre: DEBUG MARKER: == sanity-lfsck test 27b: LFSCK can recreate the lost remote parent directory as orphan ========================================================== 04:36:14 (1788597374) [ 4800.143694] Lustre: DEBUG MARKER: == sanity-lfsck test 28: Skip the failed MDT(s) when handle orphan MDT-objects ========================================================== 04:36:28 (1788597388) [ 4805.973654] Lustre: *** cfs_fail_loc=161c, val=0*** [ 4823.803613] Lustre: DEBUG MARKER: == sanity-lfsck test 29b: LFSCK can repair bad nlink count (2) ========================================================== 04:36:52 (1788597412) [ 4824.599164] Lustre: 125515:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 4824.606981] Lustre: 125515:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 518 previous similar messages [ 4824.610411] Lustre: 125515:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 4824.614557] Lustre: 125515:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 518 previous similar messages [ 4824.617155] Lustre: 125515:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4824.621831] Lustre: 125515:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 518 previous similar messages [ 4824.626481] Lustre: 125515:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 4824.637639] Lustre: 125515:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 518 previous similar messages [ 4824.642623] Lustre: 125515:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 4824.646764] Lustre: 125515:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 518 previous similar messages [ 4824.650229] Lustre: 125515:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4824.653833] Lustre: 125515:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 518 previous similar messages [ 4826.038033] Lustre: *** cfs_fail_loc=1626, val=0*** [ 4826.039956] Lustre: Skipped 4 previous similar messages [ 4839.869824] Lustre: DEBUG MARKER: == sanity-lfsck test 29c: verify linkEA size limitation == 04:37:08 (1788597428) [ 4869.333884] Lustre: DEBUG MARKER: == sanity-lfsck test 29d: accessing non-existing inode shouldn't turn fs read-only (ldiskfs) ========================================================== 04:37:37 (1788597457) [ 4872.664851] LustreError: 123539:0:(osd_handler.c:284:osd_idc_find_or_init()) lustre-MDT0000: cannot lookup FID [0x2000013a3:0x9e:0x0]: rc = -2 [ 4879.402201] Lustre: DEBUG MARKER: == sanity-lfsck test 30: LFSCK can recover the orphans from backend /lost+found ========================================================== 04:37:47 (1788597467) [ 4889.783719] Lustre: Failing over lustre-MDT0000 [ 4890.017645] Lustre: server umount lustre-MDT0000 complete [ 4894.699216] 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 [ 4894.701320] LustreError: 123539:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4894.705943] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4894.724400] Lustre: Skipped 4 previous similar messages [ 4894.758771] LustreError: 123539:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 13 previous similar messages [ 4902.025767] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 4902.189861] LustreError: MGC192.168.201.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4902.509258] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4902.570099] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4907.491320] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4907.528243] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4907.547311] Lustre: Skipped 3 previous similar messages [ 4907.601942] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4907.644120] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:166 to 0x2c0000401:193) [ 4907.645098] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:295 to 0x280000401:321) [ 4907.891430] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4923.415133] Lustre: DEBUG MARKER: == sanity-lfsck test 31a: The LFSCK can find/repair the name entry with bad name hash (1) ========================================================== 04:38:31 (1788597511) [ 4938.766853] Lustre: DEBUG MARKER: == sanity-lfsck test 31b: The LFSCK can find/repair the name entry with bad name hash (2) ========================================================== 04:38:46 (1788597526) [ 4954.945489] Lustre: DEBUG MARKER: == sanity-lfsck test 31c: Re-generate the lost master LMV EA for striped directory ========================================================== 04:39:03 (1788597543) [ 4956.490037] Lustre: *** cfs_fail_loc=1629, val=0*** [ 4956.500094] Lustre: Skipped 7 previous similar messages [ 4972.718791] Lustre: DEBUG MARKER: == sanity-lfsck test 31d: Set broken striped directory (modified after broken) as read-only ========================================================== 04:39:20 (1788597560) [ 4981.451650] Lustre: Failing over lustre-MDT0000 [ 4981.945734] Lustre: server umount lustre-MDT0000 complete [ 4984.290620] 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 [ 4984.338319] Lustre: Skipped 4 previous similar messages [ 4991.727925] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4991.858558] LustreError: MGC192.168.201.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4992.190421] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4997.607939] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4997.622609] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4997.638728] Lustre: Skipped 3 previous similar messages [ 4997.656203] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4997.707408] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:295 to 0x280000401:353) [ 4997.707536] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:166 to 0x2c0000401:225) [ 4997.756209] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5008.849108] Lustre: Failing over lustre-MDT0000 [ 5009.143796] Lustre: server umount lustre-MDT0000 complete [ 5012.961973] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 5018.518542] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5018.724422] LustreError: MGC192.168.201.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5019.276893] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 5021.238908] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 5023.001700] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5024.232949] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 5024.245253] Lustre: Skipped 3 previous similar messages [ 5024.286018] Lustre: lustre-MDT0000: Recovery over after 0:03, of 2 clients 2 recovered and 0 were evicted. [ 5024.336607] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:166 to 0x2c0000401:257) [ 5024.339839] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:355 to 0x280000401:385) [ 5035.117466] Lustre: DEBUG MARKER: == sanity-lfsck test 31e: Re-generate the lost slave LMV EA for striped directory (1) ========================================================== 04:40:22 (1788597622) [ 5054.527652] Lustre: DEBUG MARKER: == sanity-lfsck test 31f: Re-generate the lost slave LMV EA for striped directory (2) ========================================================== 04:40:42 (1788597642) [ 5070.401092] Lustre: DEBUG MARKER: == sanity-lfsck test 31g: Repair the corrupted slave LMV EA ========================================================== 04:40:58 (1788597658) [ 5113.023718] Lustre: DEBUG MARKER: == sanity-lfsck test 31h: Repair the corrupted shard's name entry ========================================================== 04:41:40 (1788597700) [ 5114.757934] Lustre: *** cfs_fail_loc=162c, val=0*** [ 5114.765408] Lustre: Skipped 13 previous similar messages [ 5130.586293] Lustre: DEBUG MARKER: == sanity-lfsck test 32a: stop LFSCK when some OST failed ========================================================== 04:41:58 (1788597718) [ 5146.261482] LustreError: 147909:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d sleeping for 3000ms [ 5149.362567] LustreError: 147909:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d awake [ 5149.368828] LustreError: 147909:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d sleeping for 3000ms [ 5149.440248] Lustre: Failing over lustre-OST0000 [ 5149.782550] Lustre: server umount lustre-OST0000 complete [ 5152.225525] 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 [ 5152.226979] LustreError: 125036:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 5152.256203] Lustre: Skipped 6 previous similar messages [ 5152.315775] LustreError: 125036:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 23 previous similar messages [ 5152.464066] LustreError: 147909:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d awake [ 5152.485881] LustreError: 147909:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d sleeping for 3000ms [ 5154.433056] LustreError: 147909:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout interrupted [ 5168.696455] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 5168.870189] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 5168.875111] Lustre: Skipped 2 previous similar messages [ 5168.885286] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 5170.155146] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 5170.193019] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 5170.193127] Lustre: lustre-OST0000-osc-MDT0001: Connection restored to 0@lo (at 0@lo) [ 5170.218993] Lustre: Skipped 3 previous similar messages [ 5177.040114] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5189.092341] Lustre: DEBUG MARKER: == sanity-lfsck test 32b: stop LFSCK when some MDT failed ========================================================== 04:42:56 (1788597776) [ 5208.434226] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing load_modules_local [ 5229.970867] Lustre: 150716:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 5256.760056] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5263.557157] Lustre: 151853:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 5279.326795] LustreError: 151990:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d sleeping for 3000ms [ 5279.376033] LustreError: 151990:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) Skipped 1 previous similar message [ 5282.380890] LustreError: 151990:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d awake [ 5283.629685] Lustre: Failing over lustre-MDT0001 [ 5284.847564] LustreError: lustre-MDT0001-osp-MDT0000: operation out_update to node 0@lo failed: rc = -107 [ 5284.859400] 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 [ 5284.869310] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 5284.872790] Lustre: Skipped 4 previous similar messages [ 5285.440307] LustreError: 151990:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d awake [ 5285.459683] LustreError: 151990:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) Skipped 1 previous similar message [ 5285.796754] Lustre: server umount lustre-MDT0001 complete [ 5302.844249] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 5303.448428] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 5308.907187] Lustre: lustre-MDT0001-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 5308.912836] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 1 client reconnects [ 5308.918358] Lustre: Skipped 1 previous similar message [ 5308.966720] Lustre: lustre-MDT0001: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 5309.056018] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:70 to 0x280000400:97) [ 5309.056792] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:69 to 0x2c0000400:97) [ 5309.482032] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5318.997527] Lustre: DEBUG MARKER: == sanity-lfsck test 33: check LFSCK paramters =========== 04:45:07 (1788597907) [ 5335.531069] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing load_modules_local [ 5356.229432] Lustre: 154710:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 5381.001995] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5384.675845] Lustre: 155845:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 5387.689498] Lustre: 123537:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 257 < left 278, rollback = 2 [ 5387.702122] Lustre: 123537:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 1220 previous similar messages [ 5387.710656] Lustre: 123537:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 5387.719534] Lustre: 123537:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1220 previous similar messages [ 5387.726352] Lustre: 123537:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 5387.739684] Lustre: 123537:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1220 previous similar messages [ 5387.753805] Lustre: 123537:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 5387.765734] Lustre: 123537:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1220 previous similar messages [ 5387.772634] Lustre: 123537:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 5387.787333] Lustre: 123537:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1220 previous similar messages [ 5387.797751] Lustre: 123537:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 5387.808147] Lustre: 123537:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1220 previous similar messages [ 5408.798410] Lustre: DEBUG MARKER: == sanity-lfsck test 34: LFSCK can rebuild the lost agent object ========================================================== 04:46:37 (1788597997) [ 5410.383994] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_34 Only valid for ZFS backend [ 5413.156615] Lustre: DEBUG MARKER: == sanity-lfsck test 35: LFSCK can rebuild the lost agent entry ========================================================== 04:46:41 (1788598001) [ 5421.195432] Lustre: *** cfs_fail_loc=1631, val=0*** [ 5441.505808] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 5441.533839] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5443.816822] Lustre: server umount lustre-MDT0000 complete [ 5447.139572] LustreError: 147911:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 5447.177729] LustreError: 147911:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 21 previous similar messages [ 5449.201232] LustreError: 130923:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788598039 with bad export cookie 8446178810005828214 [ 5449.201952] LustreError: MGC192.168.201.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5449.210347] LustreError: 130923:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 5449.409974] Lustre: server umount lustre-MDT0001 complete [ 5462.872910] Lustre: server umount lustre-OST0000 complete [ 5477.072192] Lustre: server umount lustre-OST0001 complete [ 5498.271586] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing load_modules_local [ 5507.962567] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5513.138596] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5521.865047] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5527.201377] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5530.245966] Lustre: 159746:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 5538.277995] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5545.001780] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5547.757530] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:70 to 0x280000400:129) [ 5552.880423] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:540 to 0x280000401:577) [ 5553.509623] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5559.288951] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:412 to 0x2c0000401:449) [ 5559.301316] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:69 to 0x2c0000400:129) [ 5560.601260] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5568.640917] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5572.426388] Lustre: 161617:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 5583.220675] Lustre: DEBUG MARKER: == sanity-lfsck test 36a: rebuild LOV EA for mirrored file (1) ========================================================== 04:49:32 (1788598172) [ 5584.838317] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36a needs >= 3 OSTs [ 5586.877747] Lustre: DEBUG MARKER: == sanity-lfsck test 36b: rebuild LOV EA for mirrored file (2) ========================================================== 04:49:35 (1788598175) [ 5588.695506] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36b needs >= 3 OSTs [ 5590.457956] Lustre: DEBUG MARKER: == sanity-lfsck test 36c: rebuild LOV EA for mirrored file (3) ========================================================== 04:49:39 (1788598179) [ 5591.998317] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36c needs >= 3 OSTs [ 5594.162380] Lustre: DEBUG MARKER: == sanity-lfsck test 37: LFSCK must skip a ORPHAN ======== 04:49:42 (1788598182) [ 5603.866467] Lustre: DEBUG MARKER: == sanity-lfsck test 38: LFSCK does not break foreign file and reverse is also true ========================================================== 04:49:52 (1788598192) [ 5617.148183] Lustre: DEBUG MARKER: == sanity-lfsck test 39: LFSCK does not break foreign dir and reverse is also true ========================================================== 04:50:06 (1788598206) [ 5629.107758] Lustre: DEBUG MARKER: == sanity-lfsck test 40a: LFSCK correctly fixes lmm_oi in composite layout ========================================================== 04:50:18 (1788598218) [ 5641.310449] Lustre: DEBUG MARKER: == sanity-lfsck test 41: SEL support in LFSCK ============ 04:50:30 (1788598230) [ 5660.295346] Lustre: DEBUG MARKER: == sanity-lfsck test 42: LFSCK repairs inconsistent MDT-object/OST-object encryption flags ========================================================== 04:50:49 (1788598249) [ 5694.386099] Lustre: *** cfs_fail_loc=1632, val=0*** [ 5712.537247] Lustre: DEBUG MARKER: == sanity-lfsck test 43: LFSCK does not loop endlessly on iget failure in scanning-phase1 ========================================================== 04:51:40 (1788598300) [ 5715.241714] Lustre: Failing over lustre-MDT0001 [ 5715.553807] Lustre: server umount lustre-MDT0001 complete [ 5716.966654] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 5716.975418] 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 [ 5716.985179] Lustre: Skipped 6 previous similar messages [ 5723.769141] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5724.181559] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 5724.195156] Lustre: Skipped 5 previous similar messages [ 5724.231714] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 5724.233256] Lustre: lustre-MDT0001: Aborting client recovery [ 5724.246127] LustreError: 165407:0:(ldlm_lib.c:3029:target_stop_recovery_thread()) lustre-MDT0001: Aborting recovery [ 5724.248144] LustreError: 165429:0:(lod_dev.c:511:lod_sub_recovery_thread()) lustre-MDT0001-osd: get update log duration 0, retries 0, failed: rc = -108 [ 5724.253703] Lustre: 165431:0:(ldlm_lib.c:2429:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 5724.274310] Lustre: 165431:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0001: disconnect stale client a156426e-a540-465b-bd25-7938cd67cfc1@ [ 5724.282597] Lustre: lustre-MDT0001: disconnecting 2 stale clients [ 5724.291438] Lustre: lustre-MDT0001-osd: cancel update llog [0x240000400:0x1:0x0] [ 5724.309149] Lustre: lustre-MDT0000-osp-MDT0001: cancel update llog [0x200000401:0x1:0x0] [ 5724.360854] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:131 to 0x2c0000400:161) [ 5724.366968] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:70 to 0x280000400:161) [ 5729.264802] LustreError: lustre-MDT0001-osp-MDT0000: This client was evicted by lustre-MDT0001; in progress operations using this service will fail. [ 5729.283489] Lustre: lustre-MDT0001-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 5729.296882] Lustre: Skipped 3 previous similar messages [ 5729.852818] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5739.295808] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing wait_import_state FULL osp.lustre-MDT0001-os[pc]-MDT0000.*_server_uuid [ 5739.600962] Lustre: DEBUG MARKER: osp.lustre-MDT0001-os[pc]-MDT0000.*_server_uuid in FULL state after 0 sec [ 5748.486588] Lustre: DEBUG MARKER: == sanity-lfsck test 44: umount while lfsck is stopping == 04:52:16 (1788598336) [ 5760.388425] Lustre: *** cfs_fail_loc=1600, val=3*** [ 5764.351791] Lustre: Failing over lustre-MDT0000 [ 5766.634676] Lustre: server umount lustre-MDT0000 complete [ 5779.961263] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5780.143679] LustreError: MGC192.168.201.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5780.496749] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 5780.510587] Lustre: Skipped 2 previous similar messages [ 5780.548672] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 5784.589508] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5785.583464] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 5785.595445] Lustre: Skipped 1 previous similar message [ 5785.617347] Lustre: lustre-MDT0000: Recovery over after 0:05, of 2 clients 2 recovered and 0 were evicted. [ 5785.727266] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:489 to 0x2c0000401:513) [ 5785.734015] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:621 to 0x280000401:641) [ 5796.071578] Lustre: DEBUG MARKER: == sanity-lfsck test 45: LFSCK should fix UID/GID/PROJID of OST object ========================================================== 04:53:03 (1788598383) [ 5848.088281] Lustre: Failing over lustre-OST0001 [ 5848.191974] Lustre: server umount lustre-OST0001 complete [ 5852.134946] LustreError: lustre-OST0001-osc-MDT0001: operation ost_statfs to node 0@lo failed: rc = -107 [ 5852.140044] LustreError: Skipped 1 previous similar message [ 5855.106449] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: (null) [ 5867.963555] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5868.263572] Lustre: lustre-OST0001: in recovery but waiting for the first client to connect [ 5869.957636] Lustre: lustre-OST0001: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 5870.213374] Lustre: lustre-OST0001: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [ 5870.234288] Lustre: lustre-OST0001-osc-MDT0001: Connection restored to 0@lo (at 0@lo) [ 5870.251286] Lustre: Skipped 3 previous similar messages [ 5875.009483] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5882.986512] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing wait_import_state (FULL|IDLE) os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid 50 [ 5883.238893] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid in FULL state after 0 sec [ 5887.907874] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing wait_import_state (FULL|IDLE) os[cp].lustre-OST0000-osc-MDT0001.ost_server_uuid 50 [ 5888.155686] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0001.ost_server_uuid in FULL state after 0 sec [ 5894.155643] Lustre: DEBUG MARKER: oleg155-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0000-osc-ffff9fa547661800.ost_server_uuid 50 [ 5895.953162] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9fa547661800.ost_server_uuid in FULL state after 0 sec [ 5980.130857] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5980.138689] Lustre: Skipped 4 previous similar messages [ 5984.227077] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5984.231317] Lustre: Skipped 3 previous similar messages [ 5986.170530] Lustre: server umount lustre-MDT0000 complete [ 5989.347783] LustreError: 161203:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 5989.390329] LustreError: 161203:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 44 previous similar messages [ 5996.310329] LustreError: MGC192.168.201.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5996.308631] LustreError: 158587:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788598586 with bad export cookie 8446178810005910870 [ 5996.372331] LustreError: 158587:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 3 previous similar messages [ 5996.744235] Lustre: server umount lustre-MDT0001 complete [ 6014.944268] Lustre: 106442:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788598589/real 1788598589] req@ffff9a65b87ad500 x1875479274496128/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788598605 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6016.071614] Lustre: server umount lustre-OST0000 complete [ 6016.997370] Lustre: 106443:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788598591/real 1788598591] req@ffff9a6481f8e300 x1875479274496384/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788598607 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6020.065265] Lustre: 106442:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788598594/real 1788598594] req@ffff9a658890e300 x1875479274496640/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788598610 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6022.116760] Lustre: 106444:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788598596/real 1788598596] req@ffff9a65b87adc00 x1875479274497024/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788598612 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6025.516949] Lustre: server umount lustre-OST0001 complete [ 6043.696489] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing unload_modules_local [ 6046.652619] Key type lgssc unregistered [ 6046.949474] LNet: 175106:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 6046.952842] LNetError: 175106:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 6047.979569] LNet: Removed LNI 192.168.201.155@tcp [ 6048.808206] Key type .llcrypt unregistered [ 6048.810717] Key type ._llcrypt unregistered [ 6073.185028] Key type ._llcrypt registered [ 6073.186874] Key type .llcrypt registered [ 6073.315680] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_hostid [ 6091.022239] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing load_modules_local [ 6093.020222] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 6093.056888] alg: No test for adler32 (adler32-zlib) [ 6094.508737] Lustre: Lustre: Build Version: 2.17.58_2_gae7f7f4 [ 6095.084662] LNet: Added LNI 192.168.201.155@tcp [8/256/0/180] [ 6097.027218] Key type lgssc registered [ 6098.855888] Lustre: Echo OBD driver; http://www.lustre.org/ [ 6157.814621] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing load_modules_local [ 6170.984400] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 6171.028578] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 6172.271922] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 6172.309700] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 6172.395982] Lustre: lustre-MDT0000: new disk, initializing [ 6172.492724] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 6172.515335] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 6176.887772] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6189.357706] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 6189.421940] Lustre: 179558:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 6189.446454] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 6189.449383] Lustre: Skipped 1 previous similar message [ 6189.494173] Lustre: lustre-MDT0001: new disk, initializing [ 6189.559190] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 6189.618618] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 6189.638516] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 6195.765334] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6201.784923] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 6212.621183] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 6212.861774] Lustre: lustre-OST0000: new disk, initializing [ 6212.864415] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 6212.867880] Lustre: 181498:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 6212.918307] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 6217.280831] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 6217.297453] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 6217.398647] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 6219.455792] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6232.841318] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 6233.041615] Lustre: lustre-OST0001: new disk, initializing [ 6233.043343] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 6233.047960] Lustre: 182524:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 6233.126706] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 6239.870944] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 6239.890680] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 6239.998224] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 6241.360683] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6254.724362] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 6260.021843] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 6266.536582] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 05:00:54 (1788598854) === [ 6268.840311] Lustre: DEBUG MARKER: == sanity-lfsck test complete, duration 5982 sec ========= 05:00:57 (1788598857) [ 6270.878667] Lustre: DEBUG MARKER: === sanity-lfsck: start cleanup 05:00:59 (1788598859) === [ 6275.439553] Lustre: DEBUG MARKER: === sanity-lfsck: finish cleanup 05:01:03 (1788598863) === [ 6281.187544] 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 [ 6281.187958] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 6281.209105] Lustre: Skipped 1 previous similar message [ 6286.309997] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 6286.315698] Lustre: Skipped 6 previous similar messages [ 6286.838633] Lustre: server umount lustre-MDT0000 complete [ 6295.988588] LustreError: 179551:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788598886 with bad export cookie 13580706969796801366 [ 6295.991475] LustreError: MGC192.168.201.155@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 6295.998039] LustreError: 179551:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 6296.576909] Lustre: server umount lustre-MDT0001 complete [ 6312.672156] Lustre: 176718:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788598886/real 1788598886] req@ffff9a648434c000 x1875481654807936/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788598902 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6312.701865] 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 [ 6312.712053] Lustre: Skipped 2 previous similar messages [ 6315.937769] Lustre: 176716:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788598890/real 1788598890] req@ffff9a65afe26680 x1875481654808192/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788598906 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6316.969071] Lustre: server umount lustre-OST0000 complete [ 6317.037441] Lustre: 176719:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788598891/real 1788598891] req@ffff9a65baf27800 x1875481654808448/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788598907 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6322.208108] Lustre: 176716:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788598896/real 1788598896] req@ffff9a65baf27b80 x1875481654808832/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788598912 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6326.463029] Lustre: server umount lustre-OST0001 complete [ 6345.172604] Lustre: DEBUG MARKER: oleg155-server.virtnet: executing unload_modules_local [ 6348.845183] Key type lgssc unregistered [ 6349.438712] LNet: 186010:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 6349.443215] LNetError: 186010:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 6349.458811] LNet: Removed LNI 192.168.201.155@tcp [ 6350.659270] Key type .llcrypt unregistered [ 6350.668359] Key type ._llcrypt unregistered