[ 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 516950241 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2399.998 MHz processor [ 0.000000] last_pfn = 0x146e00 max_arch_pfn = 0x400000000 [ 0.000000] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT [ 0.000000] last_pfn = 0xbffce max_arch_pfn = 0x400000000 [ 0.000000] found SMP MP-table at [mem 0x000f54b0-0x000f54bf] [ 0.000000] RAMDISK: [mem 0xbcc54000-0xbffbffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F52D0 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE247C 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE2318 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 0022D8 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE238C 000090 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE241C 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE2454 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe2318-0xbffe238b] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe2317] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe238c-0xbffe241b] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe241c-0xbffe2453] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe2454-0xbffe247b] [ 0.000000] No NUMA configuration found [ 0.000000] Faking a node at [mem 0x0000000000000000-0x0000000146dfffff] [ 0.000000] NODE_DATA(0) allocated [mem 0x1465a3000-0x1465cdfff] [ 0.000000] Reserving 256MB of memory at 2752MB for crashkernel (System RAM: 4205MB) [ 0.000000] Zone ranges: [ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.000000] DMA32 [mem 0x0000000001000000-0x00000000ffffffff] [ 0.000000] Normal [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Device empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff] [ 0.000000] node 0: [mem 0x0000000000100000-0x00000000bffcdfff] [ 0.000000] node 0: [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Zeroed struct page in unavailable ranges: 4756 pages [ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x0000000146dfffff] [ 0.000000] ACPI: PM-Timer IO Port: 0x608 [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) [ 0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) [ 0.000000] Using ACPI (MADT) for SMP configuration information [ 0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000] TSC deadline timer available [ 0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs [ 0.000000] kvm-guest: KVM setup pv remote TLB flush [ 0.000000] kvm-guest: setup PV sched yield [ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff] [ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff] [ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff] [ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff] [ 0.000000] PM: Registered nosave memory: [mem 0xbffce000-0xbfffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xc0000000-0xfeffbfff] [ 0.000000] PM: Registered nosave memory: [mem 0xfeffc000-0xfeffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xff000000-0xfffbffff] [ 0.000000] PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff] [ 0.000000] [mem 0xc0000000-0xfeffbfff] available for PCI devices [ 0.000000] Booting paravirtualized kernel on KVM [ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns [ 0.000000] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1 [ 0.000000] percpu: Embedded 63 pages/cpu s221184 r8192 d28672 u524288 [ 0.000000] kvm-guest: PV spinlocks enabled [ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1059606 [ 0.000000] Policy zone: Normal [ 0.000000] Kernel command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] Specific versions of hardware are certified with Red Hat Enterprise Linux 8. Please see the list of hardware certified with Red Hat Enterprise Linux 8 at https://catalog.redhat.com. [ 0.000000] audit: disabled (until reboot) [ 0.000000] software IO TLB: area num 4. [ 0.000000] Memory: 2895240K/4306352K available (18435K kernel code, 11221K rwdata, 7248K rodata, 2908K init, 18040K bss, 524580K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] ftrace: allocating 41240 entries in 162 pages [ 0.000000] ftrace: allocated 162 pages with 3 groups [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] rcu: RCU event tracing is enabled. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ 0.000000] rcu: RCU callback double-/use-after-free debug enabled. [ 0.000000] Rude variant of Tasks RCU enabled. [ 0.000000] Tracing variant of Tasks RCU enabled. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 0.000000] NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16 [ 0.000000] random: get_random_bytes called from start_kernel+0x622/0x9a8 with crng_init=0 [ 0.001000] Console: colour *CGA 80x25 [ 0.001000] printk: console [ttyS1] enabled [ 0.001000] ACPI: Core revision 20220331 [ 0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.001012] APIC: Switch to symmetric I/O mode setup [ 0.002207] x2apic enabled [ 0.003007] Switched APIC routing to physical x2apic. [ 0.004011] kvm-guest: setup PV IPIs [ 0.006000] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.006000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.007020] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.008011] pid_max: default: 32768 minimum: 301 [ 0.009122] LSM: Security Framework initializing [ 0.010043] Yama: becoming mindful. [ 0.011680] SELinux: Initializing. [ 0.012054] *** VALIDATE selinux *** [ 0.020056] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.025426] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.027120] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.028104] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.029127] *** VALIDATE tmpfs *** [ 0.030439] *** VALIDATE proc *** [ 0.031195] *** VALIDATE cgroup *** [ 0.032008] *** VALIDATE cgroup2 *** [ 0.033258] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.034147] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.035007] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.036031] Spectre V2 : User space: Vulnerable [ 0.036833] Speculative Store Bypass: Vulnerable [ 0.039411] debug: unmapping init [mem 0xffffffffa4a59000-0xffffffffa4a60fff] [ 0.041969] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.042842] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.043020] ... version: 2 [ 0.043905] ... bit width: 48 [ 0.044011] ... generic registers: 4 [ 0.044870] ... value mask: 0000ffffffffffff [ 0.045013] ... max period: 00007fffffffffff [ 0.046010] ... fixed-purpose events: 3 [ 0.046950] ... event mask: 000000070000000f [ 0.047340] rcu: Hierarchical SRCU implementation. [ 0.049280] smp: Bringing up secondary CPUs ... [ 0.050563] x86: Booting SMP configuration: [ 0.051020] .... node #0, CPUs: #1 #2 #3 [ 0.054455] smp: Brought up 1 node, 4 CPUs [ 0.055980] smpboot: Max logical packages: 1 [ 0.056012] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.133382] node 0 deferred pages initialised in 74ms [ 0.138095] devtmpfs: initialized [ 0.139240] x86/mm: Memory block size: 128MB [ 0.141876] gcov: version magic: 0x41383552 [ 0.145316] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.149088] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.151364] pinctrl core: initialized pinctrl subsystem [ 0.154201] [ 0.154700] ************************************************************* [ 0.157013] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.159013] ** ** [ 0.162016] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.165016] ** ** [ 0.166012] ** This means that this kernel is built to expose internal ** [ 0.168016] ** IOMMU data structures, which may compromise security on ** [ 0.170013] ** your system. ** [ 0.173015] ** ** [ 0.175011] ** If you see this message and you are not debugging the ** [ 0.177012] ** kernel, report this immediately to your vendor! ** [ 0.179016] ** ** [ 0.182016] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.184016] ************************************************************* [ 0.187291] NET: Registered protocol family 16 [ 0.189513] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.192060] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.194059] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.197110] cpuidle: using governor menu [ 0.200800] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.203517] PCI: Using configuration type 1 for base access [ 0.205221] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.216025] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.217018] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.220254] cryptd: max_cpu_qlen set to 1000 [ 0.223278] ACPI: Added _OSI(Module Device) [ 0.225015] ACPI: Added _OSI(Processor Device) [ 0.227012] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.228014] ACPI: Added _OSI(Processor Aggregator Device) [ 0.234657] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.240890] ACPI: Interpreter enabled [ 0.242059] ACPI: PM: (supports S0 S3 S4 S5) [ 0.244016] ACPI: Using IOAPIC for interrupt routing [ 0.245111] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.248401] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.259523] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.262047] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.264019] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.268109] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.275359] acpiphp: Slot [2] registered [ 0.277503] acpiphp: Slot [5] registered [ 0.279172] acpiphp: Slot [6] registered [ 0.281170] acpiphp: Slot [7] registered [ 0.284185] acpiphp: Slot [8] registered [ 0.286147] acpiphp: Slot [9] registered [ 0.287119] acpiphp: Slot [10] registered [ 0.288296] acpiphp: Slot [3] registered [ 0.290109] acpiphp: Slot [4] registered [ 0.291129] acpiphp: Slot [11] registered [ 0.293206] acpiphp: Slot [12] registered [ 0.295131] acpiphp: Slot [13] registered [ 0.297127] acpiphp: Slot [14] registered [ 0.299145] acpiphp: Slot [15] registered [ 0.301114] acpiphp: Slot [16] registered [ 0.303135] acpiphp: Slot [17] registered [ 0.305125] acpiphp: Slot [18] registered [ 0.307172] acpiphp: Slot [19] registered [ 0.309181] acpiphp: Slot [20] registered [ 0.310107] acpiphp: Slot [21] registered [ 0.312123] acpiphp: Slot [22] registered [ 0.314126] acpiphp: Slot [23] registered [ 0.315096] acpiphp: Slot [24] registered [ 0.317097] acpiphp: Slot [25] registered [ 0.318093] acpiphp: Slot [26] registered [ 0.319154] acpiphp: Slot [27] registered [ 0.321114] acpiphp: Slot [28] registered [ 0.322126] acpiphp: Slot [29] registered [ 0.323076] acpiphp: Slot [30] registered [ 0.324075] acpiphp: Slot [31] registered [ 0.325072] PCI host bridge to bus 0000:00 [ 0.326029] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.329027] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.332025] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.335024] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.337036] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.340028] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.342207] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.345925] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.349210] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.360017] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.364868] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.367020] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.369021] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.372018] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.375532] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.376000] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.379048] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.383194] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.388020] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.404018] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.411019] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.420185] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.428016] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.435019] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.451017] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.460384] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.469018] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.476021] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.497000] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.505000] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.517016] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.525022] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.555019] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.569283] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.583019] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.592023] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.621028] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.632000] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.639546] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.651025] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.674023] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 0.693070] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.699024] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.707020] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.724021] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 0.734206] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.737520] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.740408] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.743435] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.746330] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.753255] iommu: Default domain type: Passthrough [ 0.755469] SCSI subsystem initialized [ 0.758191] ACPI: bus type USB registered [ 0.759125] usbcore: registered new interface driver usbfs [ 0.761119] usbcore: registered new interface driver hub [ 0.763093] usbcore: registered new device driver usb [ 0.765182] pps_core: LinuxPPS API ver. 1 registered [ 0.767013] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.769069] PTP clock support registered [ 0.772046] EDAC MC: Ver: 3.0.0 [ 0.774222] PCI: Using ACPI for IRQ routing [ 0.775595] NetLabel: Initializing [ 0.776014] NetLabel: domain hash size = 128 [ 0.778013] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.780088] NetLabel: unlabeled traffic allowed by default [ 0.782133] vgaarb: loaded [ 0.783243] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.785015] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.790000] clocksource: Switched to clocksource kvm-clock [ 0.908311] VFS: Disk quotas dquot_6.6.0 [ 0.909783] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.912457] *** VALIDATE ramfs *** [ 0.913583] *** VALIDATE hugetlbfs *** [ 0.914976] pnp: PnP ACPI init [ 0.917254] pnp: PnP ACPI: found 6 devices [ 0.931883] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.935446] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.937565] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.939591] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.941857] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.944238] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.947247] NET: Registered protocol family 2 [ 0.949904] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.954666] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.958454] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.963327] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.966646] TCP: Hash tables configured (established 65536 bind 65536) [ 0.969829] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.972691] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.975605] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.978774] NET: Registered protocol family 1 [ 0.981706] RPC: Registered named UNIX socket transport module. [ 0.983770] RPC: Registered udp transport module. [ 0.985312] RPC: Registered tcp transport module. [ 0.987363] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.990117] NET: Registered protocol family 44 [ 0.992079] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.994823] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.996776] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.999035] PCI: CLS 0 bytes, default 64 [ 1.001223] Unpacking initramfs... [ 2.551557] debug: unmapping init [mem 0xffff90913cc54000-0xffff90913ffbffff] [ 2.555782] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.558273] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.561378] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 3.072837] Initialise system trusted keyrings [ 3.074346] Key type blacklist registered [ 3.078548] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 3.087429] zbud: loaded [ 3.090314] *** VALIDATE nfs *** [ 3.091553] *** VALIDATE nfs4 *** [ 3.092936] pstore: using deflate compression [ 3.096150] Platform Keyring initialized [ 3.221685] NET: Registered protocol family 38 [ 3.223828] Key type asymmetric registered [ 3.225703] Asymmetric key parser 'x509' registered [ 3.227888] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 3.231511] io scheduler mq-deadline registered [ 3.233325] io scheduler kyber registered [ 3.235130] io scheduler bfq registered [ 3.237255] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 3.240605] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 3.243760] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 3.246517] ACPI: Power Button [PWRF] [ 3.252168] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 3.262434] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 3.290183] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 3.302210] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 3.332568] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 3.368231] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.399816] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.405485] Non-volatile memory driver v1.3 [ 3.407583] Linux agpgart interface v0.103 [ 3.450364] virtio_blk virtio1: [vda] 146552 512-byte logical blocks (75.0 MB/71.6 MiB) [ 3.453495] vda: detected capacity change from 0 to 75034624 [ 3.472873] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.476160] vdb: detected capacity change from 0 to 1073741824 [ 3.503107] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.507939] vdc: detected capacity change from 0 to 2621440000 [ 3.531561] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.535273] vdd: detected capacity change from 0 to 2621440000 [ 3.555713] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.559056] vde: detected capacity change from 0 to 4294967296 [ 3.580334] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.583029] vdf: detected capacity change from 0 to 4294967296 [ 3.593809] libphy: Fixed MDIO Bus: probed [ 3.619893] usbcore: registered new interface driver usbserial_generic [ 3.625041] usbserial: USB Serial support registered for generic [ 3.629794] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.636811] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.638216] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.640483] mousedev: PS/2 mouse device common for all mice [ 3.645638] rtc_cmos 00:05: RTC can wake from S4 [ 3.649936] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.651034] rtc_cmos 00:05: registered as rtc0 [ 3.658926] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.662170] intel_pstate: CPU model not supported [ 3.664904] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.672565] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.678319] hid: raw HID events driver (C) Jiri Kosina [ 3.681308] usbcore: registered new interface driver usbhid [ 3.683516] usbhid: USB HID core driver [ 3.686589] drop_monitor: Initializing network drop monitor service [ 3.690486] Initializing XFRM netlink socket [ 3.693929] NET: Registered protocol family 10 [ 3.703646] Segment Routing with IPv6 [ 3.705112] NET: Registered protocol family 17 [ 3.708154] mpls_gso: MPLS GSO support [ 3.716342] RAS: Correctable Errors collector initialized. [ 3.718550] AVX version of gcm_enc/dec engaged. [ 3.720172] AES CTR mode by8 optimization enabled [ 3.822487] sched_clock: Marking stable (3822399628, 0)->(4690163661, -867764033) [ 3.826135] registered taskstats version 1 [ 3.827854] Loading compiled-in X.509 certificates [ 3.830237] zswap: loaded using pool lzo/zbud [ 3.862106] Key type big_key registered [ 3.876869] Key type encrypted registered [ 3.880219] ima: No TPM chip found, activating TPM-bypass! [ 3.882778] ima: Allocated hash algorithm: sha1 [ 3.884462] ima: No architecture policies found [ 3.886567] evm: Initialising EVM extended attributes: [ 3.888838] evm: security.selinux [ 3.890187] evm: security.ima [ 3.891321] evm: security.capability [ 3.892851] evm: HMAC attrs: 0x1 [ 3.895223] rtc_cmos 00:05: setting system clock to 2026-08-27 01:06:16 UTC (1787792776) [ 3.901812] debug: unmapping init [mem 0xffffffffa5a03000-0xffffffffa5bfffff] [ 3.905360] debug: unmapping init [mem 0xffffffffa4782000-0xffffffffa4a58fff] [ 3.915194] Write protecting the kernel read-only data: 28672k [ 3.918608] debug: unmapping init [mem 0xffffffffa2e03000-0xffffffffa2ffffff] [ 3.921409] debug: unmapping init [mem 0xffffffffa3714000-0xffffffffa37fffff] [ 3.960438] 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.967751] systemd[1]: Detected virtualization kvm. [ 3.971137] systemd[1]: Detected architecture x86-64. [ 3.972934] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.999541] systemd[1]: No hostname configured. [ 4.001374] systemd[1]: Set hostname to . [ 4.003511] random: systemd: uninitialized urandom read (16 bytes read) [ 4.005802] systemd[1]: Initializing machine ID from random generator. [ 4.160277] random: systemd: uninitialized urandom read (16 bytes read) [ 4.163468] systemd[1]: Reached target Local File Systems. [ OK ] Reached target Local File Systems. [ 4.168632] random: systemd: uninitialized urandom read (16 bytes read) [ 4.171815] systemd[1]: Listening on Journal Socket. [ OK ] Listening on Journal Socket. [ 4.182810] systemd[1]: Started Memstrack Anylazing Service. [ OK ] Started Memstrack Anylazing Service. Starting Create Volatile Files and Directories... Starting Create list of required st…ce nodes for the current kernel... [ OK ] Listening on udev Kernel Socket. [ OK ] Reached target Initrd Root Device. [ OK ] Reached target Slices. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. [ OK ] Listening on udev Control Socket. [ OK ] Reached target Timers. Starting Apply Kernel Variables... [ OK ] Listening on Journal Socket (/dev/log). [ OK ] Reached target Sockets. Starting Journal Service... [ OK ] Reached target Swap. Starting Setup Virtual Console... [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Apply Kernel Variables. [ OK ] Started Setup Virtual Console. Starting dracut cmdline hook... Starting Create Static Device Nodes in /dev... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started Journal Service. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 4.875659] device-mapper: uevent: version 1.0.3 [ 4.877555] device-mapper: ioctl: 4.46.0-ioctl (2022-02-22) initialised: dm-devel@redhat.com [[ 5.136865] random: fast init done  OK ] Started dracut pre-udev hook. Starting udev Kernel Device Manager... [ OK ] Started udev Kernel Device Manager. Starting dracut pre-trigger hook... [ OK ] Started dracut pre-trigger hook. Starting udev Coldplug all Devices... Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. Starting dracut initqueue hook... [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ 5.649730] virtio_net virtio0 ens2: renamed from eth0 [ 5.689867] scsi host0: ata_piix [ 5.729957] scsi host1: ata_piix [ 5.735404] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 5.738339] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 9.913173] dracut-initqueue[591]: RTNETLINK answers: File exists [ 10.397799] random: crng init done [ 10.399057] random: 7 urandom warning(s) missed due to ratelimiting Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Mounting /sysroot... [ 10.847854] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped target Timers. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped 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 Sockets. [ OK ] Stopped target System Initialization. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. [ OK ] Stopped target Local File Systems. [ OK ] Stopped target Local Encrypted Volumes. Stopping udev Kernel Device Manager... [ OK ] Stopped target Swap. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped target Paths. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Closed udev Kernel Socket. [ OK ] Closed udev Control Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 12.031771] printk: systemd: 26 output lines suppressed due to ratelimiting [ 12.302945] SELinux: Disabled at runtime. [ 12.367525] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 12.377286] systemd[1]: Detected virtualization kvm. [ 12.379302] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 12.893867] systemd[1]: initrd-switch-root.service: Succeeded. [ 12.897689] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 12.901889] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 12.905445] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 12.909758] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 12.916507] systemd[1]: Starting Journal Service... Starting Journal Service... [ 12.921591] systemd[1]: Created slice system-sshd\x2dkeygen.slice. [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Listening on Process Core Dump Socket. Mounting POSIX Message Queue File System... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target rpc_pipefs.target. [ OK ] Listening on initctl Compatibility Named Pipe. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Listening on udev Kernel Socket. [ OK ] Listening on RPCbind Server Activation Socket. Starting Remount Root and Kernel File Systems... Activating swap /dev/disk/by-label/SWAP... [ OK ] Reached target RPC Port Mapper. [ OK ] Created slice system-getty.slice. Starting Apply Kernel Variables... [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Stopped target Switch Root. [ OK ] Stopped targe[ 13.045775] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS t Initrd File Systems. Mounting Huge Pages File System... [ OK ] Stopped target Initrd Root File System. Mounting Kernel Debug File System... [ OK ] Created slice User and Session Slice. [ OK ] Reached target Slices. [ OK ] Listening on udev Control Socket. Starting udev Coldplug all Devices... [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. [ OK ] Started Journal Service. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Started Apply Kernel Variables. [ OK ] Mounted Huge Pages File System. [ OK ] Mounted Kernel Debug 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. Starting udev Kernel Device Manager... [ OK ] Reached target Local File Systems (Pre). Mounting /home/green/git/lustre-release... Mounting /mnt... [ OK ] Started udev Coldplug all Devices. [ OK ] Mounted /mnt. [ 13.384094] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 13.673339] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 13.686433] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 13.796323] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 13.811942] EDAC sbridge: Ver: 1.1.2 [ 15.607567] Key type dns_resolver registered [ 15.917918] NFS: Registering the id_resolver key type [ 15.920042] Key type id_resolver registered [ 15.921642] 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 Create Volatile Files and Directories... Starting Mark the need to relabel after reboot... [ 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 Cleanup of Temporary Directories. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Started dnf makecache --timer. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Reached target Timers. [ OK ] Reached target Basic System. [ OK ] Started irqbalance daemon. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Reached target sshd-keygen.target. Starting Login Service... [ OK ] Started D-Bus System Message Bus. Starting Network Manager... Starting Restore /run/initramfs on shutdown... [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Login Service. [ OK ] Started Network Manager. Starting Network Manager Wait Online... [ OK ] Reached target Network. Starting OpenSSH server daemon... Starting Dynamic System Tuning Daemon... Starting GSSAPI Proxy Daemon... Starting Hostname Service... [ OK ] Started OpenSSH server daemon. [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... [ OK ] Started Permit User Sessions. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Serial Getty on ttyS1. [ OK ] Started Command Scheduler. [ OK ] Started Getty on tty1. [ 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 Crash recovery kernel arming... Starting System Logging Service... Starting Notify NFS peers of a restart... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Starting Authorization Manager... Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg450-server login: [ 59.696213] hrtimer: interrupt took 4190839 ns [ 69.046232] libcfs: loading out-of-tree module taints kernel. [ 69.113489] Key type ._llcrypt registered [ 69.116440] Key type .llcrypt registered [ 69.261576] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_hostid [ 86.888238] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing load_modules_local [ 88.241711] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 88.262799] alg: No test for adler32 (adler32-zlib) [ 89.615615] Lustre: Lustre: Build Version: 2.17.57_48_g018c4cb [ 90.744937] LNet: Added LNI 192.168.204.150@tcp [8/256/0/180] [ 92.511442] Key type lgssc registered [ 94.535056] Lustre: Echo OBD driver; http://www.lustre.org/ [ 120.129309] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 165.333924] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing load_modules_local [ 183.292858] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 183.342882] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 184.673976] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 184.762792] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 184.920359] Lustre: lustre-MDT0000: new disk, initializing [ 185.064381] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 185.094707] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 191.299099] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 206.781553] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 206.871139] Lustre: 6524: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 [ 206.899696] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 206.905593] Lustre: Skipped 1 previous similar message [ 206.989882] Lustre: lustre-MDT0001: new disk, initializing [ 207.052027] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 207.090671] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 207.100034] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 211.111930] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 216.087586] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 226.259401] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 226.531264] Lustre: lustre-OST0000: new disk, initializing [ 226.536845] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 226.545659] Lustre: 8461:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 226.628707] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 226.935288] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 226.948896] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 227.043653] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 233.834514] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 249.819594] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 249.994463] Lustre: lustre-OST0001: new disk, initializing [ 249.997584] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 250.003539] Lustre: 9537:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 250.070886] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 257.260288] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 258.644620] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 258.661763] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 258.725488] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 269.817475] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 276.111054] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 282.926292] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing check_logdir /tmp/testlogs/ [ 287.977680] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing yml_node [ 292.647931] Lustre: DEBUG MARKER: Client: 2.17.57.48 [ 295.380238] Lustre: DEBUG MARKER: MDS: 2.17.57.48 [ 298.309472] Lustre: DEBUG MARKER: OSS: 2.17.57.48 [ 300.068875] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity-lfsck ============----- Wed Aug 26 21:11:11 EDT 2026 [ 319.231491] Lustre: DEBUG MARKER: excepting tests: 18b 23b [ 330.680580] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing load_modules_local [ 340.449307] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 340.458091] 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 [ 340.487149] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 340.968137] 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 [ 345.666083] Lustre: server umount lustre-MDT0000 complete [ 351.205272] LustreError: 10112: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. [ 351.233834] LustreError: 10112:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 8 previous similar messages [ 354.746833] LustreError: 6514:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787793127 with bad export cookie 16609973720632432352 [ 354.747725] LustreError: MGC192.168.204.150@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 354.760830] LustreError: 6514:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 355.050230] Lustre: server umount lustre-MDT0001 complete [ 371.488088] Lustre: 3655:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787793128/real 1787793128] req@ffff9090874f6d80 x1874636689216128/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787793144 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 371.547159] 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 [ 371.585731] Lustre: Skipped 2 previous similar messages [ 374.753089] Lustre: 3653:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787793131/real 1787793131] req@ffff9091c1d4ce00 x1874636689216384/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787793147 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 374.849470] Lustre: server umount lustre-OST0000 complete [ 376.735252] Lustre: 3655:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787793133/real 1787793133] req@ffff9090879a5880 x1874636689216640/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787793149 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 380.895181] Lustre: 3655:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787793137/real 1787793137] req@ffff9090874f5c00 x1874636689217280/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787793153 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 380.923289] Lustre: 3655:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 384.993232] Lustre: 3656:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787793141/real 1787793141] req@ffff9090874f4e00 x1874636689217536/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787793157 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 385.557992] Lustre: server umount lustre-OST0001 complete [ 405.277164] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing unload_modules_local [ 409.102759] Key type lgssc unregistered [ 409.494992] LNet: 14814:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 409.503221] LNetError: 14814:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 409.526433] LNet: Removed LNI 192.168.204.150@tcp [ 410.570903] Key type .llcrypt unregistered [ 410.572809] Key type ._llcrypt unregistered [ 436.975768] Key type ._llcrypt registered [ 436.977435] Key type .llcrypt registered [ 437.083728] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_hostid [ 452.726631] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing load_modules_local [ 454.138602] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 454.165758] alg: No test for adler32 (adler32-zlib) [ 455.442234] Lustre: Lustre: Build Version: 2.17.57_48_g018c4cb [ 455.906133] LNet: Added LNI 192.168.204.150@tcp [8/256/0/180] [ 457.703156] Key type lgssc registered [ 459.131497] Lustre: Echo OBD driver; http://www.lustre.org/ [ 514.644444] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing load_modules_local [ 529.115238] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 529.160173] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 530.468799] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 530.511823] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 530.637473] Lustre: lustre-MDT0000: new disk, initializing [ 530.744930] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 530.781502] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 536.271338] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 551.714720] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 551.854871] Lustre: 19272: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 [ 551.931107] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 551.935239] Lustre: Skipped 1 previous similar message [ 552.051708] Lustre: lustre-MDT0001: new disk, initializing [ 552.165752] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 552.206964] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 552.223252] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 557.323547] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 563.040604] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 572.818431] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 573.103068] Lustre: lustre-OST0000: new disk, initializing [ 573.107509] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 573.115038] Lustre: 21214:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 573.194517] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 575.841669] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 575.854879] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 575.968167] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 580.734513] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 595.712129] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 595.854678] Lustre: lustre-OST0001: new disk, initializing [ 595.858688] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 595.865295] Lustre: 22237:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 595.959834] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 602.994406] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 604.208616] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 604.221560] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 604.286776] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 615.404661] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 623.785717] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 632.350734] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 21:16:43 (1787793403) === [ 635.426476] Lustre: DEBUG MARKER: == sanity-lfsck test 0: Control LFSCK manually =========== 21:16:46 (1787793406) [ 635.712717] Lustre: 19279:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 251 < left 278, rollback = 2 [ 635.719238] Lustre: 19279:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 635.725438] Lustre: 19279:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 635.738714] Lustre: 19279:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 635.757605] Lustre: 19279:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 635.762970] Lustre: 19279:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 636.280859] Lustre: 20495:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 636.298719] Lustre: 20495:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 11 previous similar messages [ 636.309336] Lustre: 20495:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 636.318613] Lustre: 20495:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 636.326435] Lustre: 20495:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 636.337196] Lustre: 20495:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 636.345812] Lustre: 20495:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 636.353460] Lustre: 20495:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 636.360255] Lustre: 20495:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 636.371801] Lustre: 20495:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 636.384392] Lustre: 20495:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 636.391871] Lustre: 20495:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 637.325084] Lustre: 19279:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 637.337676] Lustre: 19279:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 35 previous similar messages [ 637.346865] Lustre: 19279:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 637.358556] Lustre: 19279:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 35 previous similar messages [ 637.373449] Lustre: 19279:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 637.388533] Lustre: 19279:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 35 previous similar messages [ 637.399085] Lustre: 19279:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 637.410690] Lustre: 19279:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 35 previous similar messages [ 637.424264] Lustre: 19279:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 637.433321] Lustre: 19279:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 35 previous similar messages [ 637.439880] Lustre: 19279:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 637.453301] Lustre: 19279:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 35 previous similar messages [ 639.332644] Lustre: 20495:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 639.340834] Lustre: 20495:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 80 previous similar messages [ 639.347346] Lustre: 20495:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 639.353354] Lustre: 20495:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 80 previous similar messages [ 639.423410] Lustre: 19280:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 639.427995] Lustre: 19280:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 83 previous similar messages [ 639.437211] Lustre: 19280:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 639.443051] Lustre: 19280:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 83 previous similar messages [ 639.451839] Lustre: 19280:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 639.459651] Lustre: 19280:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 83 previous similar messages [ 639.465912] Lustre: 19280:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 639.473238] Lustre: 19280:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 83 previous similar messages [ 644.550045] Lustre: *** cfs_fail_loc=1600, val=3*** [ 645.895592] Lustre: 21201:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-OST0001: opcode 2: before 260 < left 274, rollback = 2 [ 645.896758] Lustre: 21203:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 645.920329] Lustre: 21201:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 150 previous similar messages [ 645.920360] Lustre: 21201:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 2/274/0 [ 645.920364] Lustre: 21201:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 146 previous similar messages [ 645.920371] Lustre: 21201:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 0/0/0, punch: 0/0/0, quota 7/225/0 [ 645.920375] Lustre: 21201:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 146 previous similar messages [ 645.920379] Lustre: 21201:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 645.920383] Lustre: 21201:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 146 previous similar messages [ 645.920389] Lustre: 21201:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 645.920393] Lustre: 21201:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 146 previous similar messages [ 646.035874] Lustre: 21203:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 163 previous similar messages [ 649.429677] Lustre: *** cfs_fail_loc=1600, val=3*** [ 660.908062] Lustre: 23580:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 259 < left 274, rollback = 2 [ 660.910678] Lustre: 23590:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 660.918295] Lustre: 23580:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 52 previous similar messages [ 660.918322] Lustre: 23580:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/1, xattr_set: 2/274/0 [ 660.918326] Lustre: 23580:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 52 previous similar messages [ 660.918332] Lustre: 23580:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 0/0/0, punch: 0/0/0, quota 7/225/0 [ 660.918335] Lustre: 23580:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 52 previous similar messages [ 660.918340] Lustre: 23580:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 660.918343] Lustre: 23580:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 52 previous similar messages [ 660.918348] Lustre: 23580:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 660.918351] Lustre: 23580:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 52 previous similar messages [ 661.034359] Lustre: 23590:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 44 previous similar messages [ 665.060124] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 665.062703] 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 [ 665.084878] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 665.568652] 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 [ 665.601479] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 665.609722] Lustre: Skipped 2 previous similar messages [ 670.062140] Lustre: server umount lustre-MDT0000 complete [ 673.886033] LustreError: 19263:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787793446 with bad export cookie 4794969777149468268 [ 673.888975] LustreError: MGC192.168.204.150@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 673.891777] LustreError: 19263:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 674.184741] Lustre: server umount lustre-MDT0001 complete [ 688.860387] Lustre: server umount lustre-OST0000 complete [ 691.999113] Lustre: 16431:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787793448/real 1787793448] req@ffff90908e169880 x1874637071958016/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787793464 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 692.030223] 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 [ 692.042715] Lustre: Skipped 2 previous similar messages [ 693.682395] Lustre: server umount lustre-OST0001 complete [ 703.349309] Lustre: DEBUG MARKER: == sanity-lfsck test 1a: LFSCK can find out and repair crashed FID-in-dirent ========================================================== 21:17:54 (1787793474) [ 718.182332] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing load_modules_local [ 727.743899] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 728.168258] LustreError: 26297: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. [ 728.205778] LustreError: 26297:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 5 previous similar messages [ 728.278695] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 732.567910] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 733.667677] LustreError: 26298: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. [ 737.829565] LustreError: 26297: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. [ 741.990282] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 742.333891] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 746.992835] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 749.811261] Lustre: 27437:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 757.077808] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 764.158331] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 766.638752] LustreError: 27790: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. [ 772.077455] LustreError: 27792: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. [ 773.102720] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:41 to 0x280000401:65) [ 773.653770] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 773.836604] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 773.846372] Lustre: Skipped 1 previous similar message [ 779.265924] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:40 to 0x2c0000401:65) [ 780.631443] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 789.010967] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 793.334267] Lustre: 29307:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 795.406648] Lustre: 26293:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 795.411814] Lustre: 26293:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 13 previous similar messages [ 795.416559] Lustre: 26293:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 795.422018] Lustre: 26293:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 6 previous similar messages [ 795.428398] Lustre: 26293:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 795.436444] Lustre: 26293:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 14 previous similar messages [ 795.444729] Lustre: 26293:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 795.451694] Lustre: 26293:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 14 previous similar messages [ 795.457106] Lustre: 26293:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 795.462585] Lustre: 26293:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 14 previous similar messages [ 795.468283] Lustre: 26293:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 795.473557] Lustre: 26293:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 14 previous similar messages [ 802.406157] Lustre: *** cfs_fail_loc=1501, val=0*** [ 811.727078] Lustre: Failing over lustre-MDT0000 [ 812.235959] Lustre: server umount lustre-MDT0000 complete [ 814.051212] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 814.056228] 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 [ 814.075514] LustreError: 26298: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. [ 814.100373] LustreError: 26298:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 2 previous similar messages [ 824.937784] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 825.136198] LustreError: MGC192.168.204.150@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 825.321323] Lustre: lustre-MDT0000: Not available for connect from 0@lo (not set up) [ 825.331607] Lustre: Skipped 3 previous similar messages [ 825.490571] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 825.538888] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 830.950986] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 830.962118] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 831.025569] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 831.121301] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:105 to 0x2c0000401:129) [ 831.122915] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:105 to 0x280000401:129) [ 831.478410] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 836.392113] Lustre: *** cfs_fail_loc=1505, val=0*** [ 843.674214] Lustre: DEBUG MARKER: == sanity-lfsck test 1b: LFSCK can find out and repair the missing FID-in-LMA ========================================================== 21:20:14 (1787793614) [ 845.132708] Lustre: 28522:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 255 < left 278, rollback = 2 [ 845.137183] Lustre: 28522:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 322 previous similar messages [ 845.140757] Lustre: 28522:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/2, destroy: 0/0/0 [ 845.144814] Lustre: 28522:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 845.148435] Lustre: 28522:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 845.151752] Lustre: 28522:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 845.156561] Lustre: 28522:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 845.163440] Lustre: 28522:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 845.169062] Lustre: 28522:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 845.177677] Lustre: 28522:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 845.184641] Lustre: 28522:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 845.189517] Lustre: 28522:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 850.807164] Lustre: *** cfs_fail_loc=1502, val=0*** [ 859.418059] Lustre: Failing over lustre-MDT0000 [ 859.629817] Lustre: server umount lustre-MDT0000 complete [ 861.664423] 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 [ 861.688417] Lustre: Skipped 5 previous similar messages [ 861.697981] LustreError: 26294: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. [ 861.726961] LustreError: 26294:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 11 previous similar messages [ 871.148272] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 871.265337] LustreError: MGC192.168.204.150@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 871.519698] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 876.145589] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 876.515100] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 876.522876] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 876.531362] Lustre: Skipped 3 previous similar messages [ 876.554439] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 876.586756] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:169 to 0x280000401:193) [ 876.589168] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:169 to 0x2c0000401:193) [ 880.054971] Lustre: *** cfs_fail_loc=1505, val=0*** [ 888.147628] Lustre: DEBUG MARKER: == sanity-lfsck test 1c: LFSCK can find out and repair lost FID-in-dirent ========================================================== 21:20:59 (1787793659) [ 895.940482] Lustre: *** cfs_fail_loc=1504, val=0*** [ 895.944376] Lustre: *** cfs_fail_loc=1504, val=0*** [ 895.949139] Lustre: Skipped 1 previous similar message [ 904.406339] Lustre: Failing over lustre-MDT0000 [ 904.649372] Lustre: server umount lustre-MDT0000 complete [ 907.232311] 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 [ 907.236130] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 907.240428] LustreError: 26297: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. [ 907.240441] LustreError: 26297:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 4 previous similar messages [ 907.246893] Lustre: Skipped 4 previous similar messages [ 915.979454] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 916.169121] LustreError: MGC192.168.204.150@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 916.446294] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 916.452472] Lustre: Skipped 1 previous similar message [ 916.479747] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 921.573620] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 921.586419] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 921.592140] Lustre: Skipped 3 previous similar messages [ 921.634326] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 921.638671] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 921.682979] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:233 to 0x280000401:257) [ 921.687556] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:233 to 0x2c0000401:257) [ 925.152578] Lustre: *** cfs_fail_loc=1505, val=0*** [ 933.357996] Lustre: DEBUG MARKER: == sanity-lfsck test 2a: LFSCK can find out and repair crashed linkEA entry ========================================================== 21:21:44 (1787793704) [ 935.005416] Lustre: 28522:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 256 < left 278, rollback = 2 [ 935.018661] Lustre: 28522:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 644 previous similar messages [ 935.023539] Lustre: 28522:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 935.027368] Lustre: 28522:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 935.033107] Lustre: 28522:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 935.038926] Lustre: 28522:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 935.048882] Lustre: 28522:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 935.054312] Lustre: 28522:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 935.058685] Lustre: 28522:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 935.063138] Lustre: 28522:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 935.068308] Lustre: 28522:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 935.072988] Lustre: 28522:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 941.193125] Lustre: *** cfs_fail_loc=1603, val=0*** [ 950.380045] Lustre: Failing over lustre-MDT0000 [ 950.742920] Lustre: server umount lustre-MDT0000 complete [ 952.289390] 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 [ 952.297262] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 952.303156] Lustre: Skipped 2 previous similar messages [ 962.133550] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 962.237283] LustreError: MGC192.168.204.150@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 962.428896] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 966.488734] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 967.649634] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 967.662448] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 967.671977] Lustre: Skipped 3 previous similar messages [ 967.689168] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 967.741050] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:297 to 0x280000401:321) [ 967.742502] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:297 to 0x2c0000401:321) [ 977.084690] Lustre: DEBUG MARKER: == sanity-lfsck test 2b: LFSCK can find out and remove invalid linkEA entry ========================================================== 21:22:28 (1787793748) [ 984.145817] Lustre: *** cfs_fail_loc=1604, val=0*** [ 992.272651] Lustre: Failing over lustre-MDT0000 [ 992.548198] Lustre: server umount lustre-MDT0000 complete [ 993.249799] 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 [ 993.255412] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 993.265127] Lustre: Skipped 4 previous similar messages [ 993.267311] LustreError: 26294: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. [ 993.315568] LustreError: 26294:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 18 previous similar messages [ 1003.080559] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1003.223477] LustreError: MGC192.168.204.150@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1003.538509] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1008.446875] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1008.621586] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1008.627182] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1008.645722] Lustre: Skipped 3 previous similar messages [ 1008.672689] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1008.742596] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:361 to 0x280000401:385) [ 1008.742843] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:361 to 0x2c0000401:385) [ 1017.375680] Lustre: DEBUG MARKER: == sanity-lfsck test 2c: LFSCK can find out and remove repeated linkEA entry ========================================================== 21:23:08 (1787793788) [ 1024.916545] Lustre: *** cfs_fail_loc=1605, val=0*** [ 1034.592130] Lustre: Failing over lustre-MDT0000 [ 1035.174989] Lustre: server umount lustre-MDT0000 complete [ 1049.059147] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1049.276718] LustreError: MGC192.168.204.150@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1049.575886] Lustre: lustre-MDT0000: Not available for connect from 0@lo (not set up) [ 1049.586317] Lustre: Skipped 3 previous similar messages [ 1049.722057] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1049.727198] Lustre: Skipped 2 previous similar messages [ 1049.768687] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1055.200514] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1055.215118] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1055.225545] Lustre: Skipped 3 previous similar messages [ 1055.243293] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1055.296115] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:425 to 0x2c0000401:449) [ 1055.307470] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:425 to 0x280000401:449) [ 1055.440667] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1065.994740] Lustre: DEBUG MARKER: == sanity-lfsck test 2d: LFSCK can recover the missing linkEA entry ========================================================== 21:23:56 (1787793836) [ 1067.883655] Lustre: 28522:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 1067.901435] Lustre: 28522:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 967 previous similar messages [ 1067.916131] Lustre: 28522:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 1067.932256] Lustre: 28522:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 967 previous similar messages [ 1067.938920] Lustre: 28522:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 1067.951380] Lustre: 28522:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 968 previous similar messages [ 1067.960399] Lustre: 28522:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 1067.977228] Lustre: 28522:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 967 previous similar messages [ 1067.991031] Lustre: 28522:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 1068.004707] Lustre: 28522:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 967 previous similar messages [ 1068.019756] Lustre: 28522:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 1068.042378] Lustre: 28522:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 968 previous similar messages [ 1073.878700] Lustre: *** cfs_fail_loc=161d, val=0*** [ 1081.877365] Lustre: Failing over lustre-MDT0000 [ 1082.129323] Lustre: server umount lustre-MDT0000 complete [ 1085.920588] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1085.930698] 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 [ 1085.943592] Lustre: Skipped 4 previous similar messages [ 1092.338964] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1092.491854] LustreError: MGC192.168.204.150@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1092.773802] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1097.147563] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1098.214405] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1098.226298] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1098.254554] Lustre: Skipped 3 previous similar messages [ 1098.285680] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1098.378133] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:489 to 0x2c0000401:513) [ 1098.380117] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:489 to 0x280000401:513) [ 1106.366648] Lustre: DEBUG MARKER: == sanity-lfsck test 2e: namespace LFSCK can verify remote object linkEA ========================================================== 21:24:37 (1787793877) [ 1109.282578] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1120.927571] Lustre: DEBUG MARKER: == sanity-lfsck test 3: LFSCK can verify multiple-linked objects ========================================================== 21:24:51 (1787793891) [ 1128.419852] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1129.564184] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1145.195710] Lustre: DEBUG MARKER: == sanity-lfsck test 4: FID-in-dirent can be rebuilt after MDT file-level backup/restore ========================================================== 21:25:15 (1787793915) [ 1180.900594] Lustre: Failing over lustre-MDT0000 [ 1183.172808] Lustre: server umount lustre-MDT0000 complete [ 1185.247500] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1185.250975] LustreError: 28522: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. [ 1185.275606] LustreError: 28522:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 23 previous similar messages [ 1188.093737] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1198.704857] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1200.608200] Lustre: 16432:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787793957/real 1787793957] req@ffff909085beed80 x1874637072573312/t0(0) o400->MGC192.168.204.150@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1787793973 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1200.633421] LustreError: MGC192.168.204.150@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1211.331315] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1211.364811] Lustre: lustre-MDT0000: reset Object Index mappings [ 1226.529311] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1231.538913] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1231.850203] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1231.852208] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1231.868093] Lustre: Skipped 3 previous similar messages [ 1231.901271] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1231.947957] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:592 to 0x2c0000401:609) [ 1231.948586] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:592 to 0x280000401:609) [ 1235.928635] LustreError: 42953:0:(lfsck_engine.c:1018:lfsck_master_engine()) lustre-MDT0000-osd: master engine fail to verify the .lustre/lost+found/, go ahead: rc = -115 [ 1235.988611] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1238.049293] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1238.059713] Lustre: Skipped 1 previous similar message [ 1244.554087] Lustre: Failing over lustre-MDT0000 [ 1244.936480] Lustre: server umount lustre-MDT0000 complete [ 1247.204752] 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 [ 1247.210872] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1247.219369] Lustre: Skipped 10 previous similar messages [ 1256.732664] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1262.644972] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:592 to 0x2c0000401:641) [ 1262.653631] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:592 to 0x280000401:641) [ 1262.738451] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1266.498287] Lustre: *** cfs_fail_loc=1505, val=0*** [ 1275.440475] Lustre: DEBUG MARKER: == sanity-lfsck test 5: LFSCK can handle IGIF object upgrading ========================================================== 21:27:26 (1787794046) [ 1278.166022] Lustre: *** cfs_fail_loc=1504, val=0*** [ 1287.995239] Lustre: Failing over lustre-MDT0000 [ 1288.212991] Lustre: server umount lustre-MDT0000 complete [ 1294.269677] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1303.523381] Lustre: 16431:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787794060/real 1787794060] req@ffff9091aea0f100 x1874637072669824/t0(0) o400->MGC192.168.204.150@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1787794076 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1304.145716] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1316.265725] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1316.283090] Lustre: lustre-MDT0000: reset Object Index mappings [ 1329.122589] LustreError: 16429:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff90908da10000 x1874637072682368/t0(0) o250->MGC192.168.204.150@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 [ 1329.650773] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1329.659644] Lustre: Skipped 3 previous similar messages [ 1329.737571] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1329.754243] Lustre: Skipped 1 previous similar message [ 1334.757991] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1334.760350] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1334.768052] Lustre: Skipped 7 previous similar messages [ 1334.793308] Lustre: Skipped 1 previous similar message [ 1334.834354] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1334.850456] Lustre: Skipped 1 previous similar message [ 1334.905664] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:681 to 0x2c0000401:705) [ 1334.906462] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:681 to 0x280000401:705) [ 1335.491409] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1339.799916] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1339.804576] Lustre: Skipped 1 previous similar message [ 1352.738228] Lustre: Failing over lustre-MDT0000 [ 1355.040444] Lustre: server umount lustre-MDT0000 complete [ 1355.232838] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1366.529113] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1366.708104] LustreError: MGC192.168.204.150@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1366.726564] LustreError: Skipped 2 previous similar messages [ 1372.220814] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:681 to 0x280000401:737) [ 1372.223524] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:681 to 0x2c0000401:737) [ 1372.414838] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1376.595959] Lustre: *** cfs_fail_loc=1505, val=0*** [ 1376.601843] Lustre: Skipped 84 previous similar messages [ 1384.853822] Lustre: DEBUG MARKER: == sanity-lfsck test 6a: LFSCK resumes from last checkpoint (1) ========================================================== 21:29:15 (1787794155) [ 1386.522941] Lustre: 28522:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 255 < left 278, rollback = 2 [ 1386.534598] Lustre: 28522:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 1234 previous similar messages [ 1386.543996] Lustre: 28522:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/2, destroy: 0/0/0 [ 1386.556498] Lustre: 28522:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1234 previous similar messages [ 1386.563794] Lustre: 28522:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 1386.569099] Lustre: 28522:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1234 previous similar messages [ 1386.576625] Lustre: 28522:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 1386.584031] Lustre: 28522:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1234 previous similar messages [ 1386.591046] Lustre: 28522:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 1386.595981] Lustre: 28522:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1234 previous similar messages [ 1386.601202] Lustre: 28522:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 1386.606337] Lustre: 28522:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1234 previous similar messages [ 1393.865743] Lustre: *** cfs_fail_loc=1600, val=1*** [ 1393.868985] Lustre: Skipped 7 previous similar messages [ 1415.390149] Lustre: DEBUG MARKER: == sanity-lfsck test 6b: LFSCK resumes from last checkpoint (2) ========================================================== 21:29:46 (1787794186) [ 1424.445343] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1424.448205] Lustre: Skipped 10 previous similar messages [ 1448.877501] Lustre: DEBUG MARKER: == sanity-lfsck test 7a: non-stopped LFSCK should auto restarts after MDS remount (1) ========================================================== 21:30:20 (1787794220) [ 1459.414065] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1459.419972] Lustre: Skipped 12 previous similar messages [ 1464.765539] Lustre: Failing over lustre-MDT0000 [ 1465.002070] Lustre: server umount lustre-MDT0000 complete [ 1469.409141] LustreError: 28522: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. [ 1469.420621] LustreError: 28522:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 91 previous similar messages [ 1473.784960] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1474.279746] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1474.296503] Lustre: Skipped 1 previous similar message [ 1478.195335] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1479.652243] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1479.659968] Lustre: Skipped 1 previous similar message [ 1479.661029] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1479.672327] Lustre: Skipped 7 previous similar messages [ 1479.697926] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1479.704338] Lustre: Skipped 1 previous similar message [ 1479.742932] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:853 to 0x2c0000401:897) [ 1479.744225] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:854 to 0x280000401:897) [ 1485.699863] Lustre: DEBUG MARKER: == sanity-lfsck test 7b: non-stopped LFSCK should auto restarts after MDS remount (2) ========================================================== 21:30:57 (1787794257) [ 1498.869292] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing load_modules_local [ 1515.202880] Lustre: 52871:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 1536.441078] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1540.028456] Lustre: 54006:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 1548.879694] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1548.886315] Lustre: Skipped 81 previous similar messages [ 1551.949233] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1552.991320] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1554.015203] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1556.066480] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1556.073991] Lustre: Skipped 1 previous similar message [ 1557.079744] Lustre: Failing over lustre-MDT0000 [ 1557.450855] Lustre: server umount lustre-MDT0000 complete [ 1561.569286] 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 [ 1561.574921] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1561.594902] Lustre: Skipped 15 previous similar messages [ 1561.623913] LustreError: Skipped 1 previous similar message [ 1567.650596] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1573.273339] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1573.431156] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:947 to 0x2c0000401:993) [ 1573.431156] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:946 to 0x280000401:961) [ 1583.551713] Lustre: DEBUG MARKER: == sanity-lfsck test 8: LFSCK state machine ============== 21:32:34 (1787794354) [ 1588.719451] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1593.046669] Lustre: server umount lustre-MDT0000 complete [ 1597.026453] LustreError: 29332:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787794369 with bad export cookie 4794969777149681299 [ 1597.051506] LustreError: 29332:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 1597.375085] Lustre: server umount lustre-MDT0001 complete [ 1612.566898] Lustre: server umount lustre-OST0000 complete [ 1615.335195] Lustre: 16433:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787794371/real 1787794371] req@ffff9091c1060380 x1874637073003776/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787794387 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1617.578710] Lustre: server umount lustre-OST0001 complete [ 1625.263311] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_hostid [ 1632.795435] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing load_modules_local [ 1677.558650] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing load_modules_local [ 1687.927957] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1688.148934] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 1688.207645] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 1688.335218] Lustre: lustre-MDT0000: new disk, initializing [ 1688.466447] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 1693.204208] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1704.983334] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1705.066743] Lustre: 59067: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 [ 1705.103734] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 1705.111240] Lustre: Skipped 1 previous similar message [ 1705.215494] Lustre: lustre-MDT0001: new disk, initializing [ 1705.387542] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 1705.398657] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 1709.568635] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1714.789041] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 1722.510282] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 1722.838246] Lustre: lustre-OST0000: new disk, initializing [ 1722.848134] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 1722.867272] Lustre: 60699:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 1724.689654] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 1724.701068] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 1724.866545] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 1731.565984] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1744.706900] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 1744.826538] Lustre: lustre-OST0001: new disk, initializing [ 1744.830728] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 1744.835793] Lustre: 61570:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 1746.378751] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 1746.393219] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 1746.509024] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 1751.764581] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1761.916892] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1765.965714] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 1778.812563] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1780.077767] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1780.084444] Lustre: Skipped 19 previous similar messages [ 1786.235901] Lustre: *** cfs_fail_loc=1601, val=2*** [ 1786.243343] Lustre: Skipped 5 previous similar messages [ 1807.719662] Lustre: Failing over lustre-MDT0000 [ 1807.840621] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1807.849031] Lustre: Skipped 3 previous similar messages [ 1808.147719] Lustre: server umount lustre-MDT0000 complete [ 1819.594311] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1819.689530] LustreError: MGC192.168.204.150@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1819.696991] LustreError: Skipped 3 previous similar messages [ 1819.933800] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1819.939625] Lustre: Skipped 1 previous similar message [ 1824.770476] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1825.261651] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1825.271174] Lustre: Skipped 1 previous similar message [ 1825.274586] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1825.285465] Lustre: Skipped 7 previous similar messages [ 1825.334407] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1825.341980] Lustre: Skipped 1 previous similar message [ 1825.396211] Lustre: *** cfs_fail_loc=160b, val=2*** [ 1825.409891] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:65) [ 1825.412725] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:65) [ 1834.261646] Lustre: Failing over lustre-MDT0000 [ 1834.524436] Lustre: server umount lustre-MDT0000 complete [ 1835.491799] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1835.498983] LustreError: Skipped 2 previous similar messages [ 1845.045750] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1845.478551] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1845.488388] Lustre: Skipped 8 previous similar messages [ 1850.410600] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1850.914850] Lustre: *** cfs_fail_loc=160b, val=2*** [ 1850.923182] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:97) [ 1850.934207] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:97) [ 1856.316697] Lustre: Failing over lustre-MDT0000 [ 1856.611724] Lustre: server umount lustre-MDT0000 complete [ 1866.026660] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1871.945125] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:129) [ 1871.945255] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:129) [ 1872.297583] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1879.057315] Lustre: *** cfs_fail_loc=1602, val=2*** [ 1879.066307] Lustre: Skipped 1 previous similar message [ 1892.659029] Lustre: DEBUG MARKER: == sanity-lfsck test 9a: LFSCK speed control (1) ========= 21:37:43 (1787794663) [ 1908.861606] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing load_modules_local [ 1929.795608] Lustre: 68535:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 1956.667601] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1960.095825] Lustre: 69673:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 1969.582944] Lustre: 59072:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 1969.591438] Lustre: 59072:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 2765 previous similar messages [ 1969.596989] Lustre: 59072:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 1969.606021] Lustre: 59072:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 2765 previous similar messages [ 1969.614554] Lustre: 59072:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 1969.627109] Lustre: 59072:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 2765 previous similar messages [ 1969.635641] Lustre: 59072:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 1969.641275] Lustre: 59072:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 2765 previous similar messages [ 1969.646958] Lustre: 59072:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 1969.659150] Lustre: 59072:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 2765 previous similar messages [ 1969.673078] Lustre: 59072:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 1969.683703] Lustre: 59072:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 2765 previous similar messages [ 2081.544506] Lustre: DEBUG MARKER: == sanity-lfsck test 9b: LFSCK speed control (2) ========= 21:40:52 (1787794852) [ 2135.190904] Lustre: *** cfs_fail_loc=1604, val=0*** [ 2135.197939] Lustre: Skipped 4 previous similar messages [ 2161.276778] Lustre: *** cfs_fail_loc=160c, val=0*** [ 2161.280419] Lustre: Skipped 9 previous similar messages [ 2198.540490] Lustre: DEBUG MARKER: == sanity-lfsck test 10: System is available during LFSCK scanning ========================================================== 21:42:49 (1787794969) [ 2247.091765] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2248.093304] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2248.101148] Lustre: Skipped 45 previous similar messages [ 2250.142420] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2250.147582] Lustre: Skipped 81 previous similar messages [ 2254.147566] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2254.149995] Lustre: Skipped 191 previous similar messages [ 2262.152966] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2262.154883] Lustre: Skipped 339 previous similar messages [ 2278.208865] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2278.214168] Lustre: Skipped 762 previous similar messages [ 2310.280793] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2310.287388] Lustre: Skipped 1497 previous similar messages [ 2323.629670] Lustre: *** cfs_fail_loc=1604, val=0*** [ 2323.634512] Lustre: Skipped 2599 previous similar messages [ 2572.728946] Lustre: DEBUG MARKER: == sanity-lfsck test 11a: LFSCK can rebuild lost last_id ========================================================== 21:49:03 (1787795343) [ 2685.229996] Lustre: 71452:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 320, rollback = 2 [ 2685.244164] Lustre: 71452:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 36831 previous similar messages [ 2685.257717] Lustre: 71452:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 1/4/0 [ 2685.268953] Lustre: 71452:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 36831 previous similar messages [ 2685.282059] Lustre: 71452:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 5/5/0, xattr_set: 7/320/0 [ 2685.293144] Lustre: 71452:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 36831 previous similar messages [ 2685.301687] Lustre: 71452:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 6/46/0, punch: 0/0/0, quota 1/3/0 [ 2685.311943] Lustre: 71452:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 36831 previous similar messages [ 2685.327849] Lustre: 71452:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 2/5/0 [ 2685.340106] Lustre: 71452:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 36831 previous similar messages [ 2685.350690] Lustre: 71452:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 1/1/0, ref_del: 2/2/1 [ 2685.361698] Lustre: 71452:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 36831 previous similar messages [ 2747.359923] 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 [ 2747.364288] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2747.365181] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 2747.365200] LustreError: Skipped 1 previous similar message [ 2747.380241] Lustre: Skipped 18 previous similar messages [ 2752.149968] Lustre: server umount lustre-MDT0000 complete [ 2752.489977] LustreError: 70120: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. [ 2752.519862] LustreError: 70120:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 39 previous similar messages [ 2755.855788] LustreError: 59863:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787795528 with bad export cookie 4794969777149700395 [ 2755.856771] LustreError: MGC192.168.204.150@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2755.890307] LustreError: 59863:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 2755.914430] LustreError: Skipped 2 previous similar messages [ 2756.214367] Lustre: server umount lustre-MDT0001 complete [ 2770.900671] Lustre: server umount lustre-OST0000 complete [ 2773.792401] Lustre: 16430:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787795530/real 1787795530] req@ffff9091aea0a680 x1874637076843520/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787795546 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2776.252541] Lustre: server umount lustre-OST0001 complete [ 2782.572141] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: (null) [ 2790.272448] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 2805.856597] LustreError: Failed to get MGS log lustre-sptlrpc and no local copy. [ 2810.975335] LustreError: 75138:0:(mgc_request.c:233:do_config_log_add()) MGC192.168.204.150@tcp: failed processing log, type 4: rc = -110 [ 2836.703342] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 2836.711841] Lustre: Skipped 1 previous similar message [ 2843.020325] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2846.665197] Lustre: 75723: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. [ 2846.686608] Lustre: *** cfs_fail_loc=160e, val=3*** [ 2849.709657] Lustre: 75723:0:(ofd_dev.c:573:ofd_lfsck_out_notify()) lustre-OST0000: Rebuilt crashed LAST_ID files successfully. [ 2859.115524] Lustre: DEBUG MARKER: == sanity-lfsck test 11b: LFSCK can rebuild crashed last_id ========================================================== 21:53:49 (1787795629) [ 2875.552370] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing load_modules_local [ 2886.036649] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2886.306524] LustreError: 75163: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. [ 2886.391757] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3272 to 0x280000401:3297) [ 2892.037914] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2901.451039] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2907.688874] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2911.064648] Lustre: 78407:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 2926.120252] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2931.707588] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3207 to 0x2c0000401:3233) [ 2933.230434] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2941.751760] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 2946.026860] Lustre: 79906:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 2951.396278] Lustre: *** cfs_fail_loc=160d, val=0*** [ 2951.943905] Lustre: *** cfs_fail_loc=160d, val=0*** [ 2951.950184] Lustre: Skipped 3 previous similar messages [ 2958.732781] Lustre: Failing over lustre-OST0000 [ 2958.835915] Lustre: server umount lustre-OST0000 complete [ 2962.402160] Lustre: lustre-OST0000-osc-MDT0000: Connection to lustre-OST0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 2962.429712] Lustre: Skipped 3 previous similar messages [ 2967.590410] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2967.768918] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 2967.778765] Lustre: Skipped 2 previous similar messages [ 2969.253300] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 2969.262613] Lustre: Skipped 2 previous similar messages [ 2969.288581] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 2969.290233] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 2969.292362] Lustre: *** cfs_fail_loc=215, val=0*** [ 2969.295383] Lustre: Skipped 2 previous similar messages [ 2969.311790] Lustre: Skipped 11 previous similar messages [ 2974.409276] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2974.690271] Lustre: *** cfs_fail_loc=215, val=0*** [ 2974.694504] Lustre: Skipped 2 previous similar messages [ 2978.507559] Lustre: 81303: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. [ 2978.517590] Lustre: 81303:0:(ofd_dev.c:573:ofd_lfsck_out_notify()) lustre-OST0000: Rebuilt crashed LAST_ID files successfully. [ 2979.807685] Lustre: *** cfs_fail_loc=215, val=0*** [ 2979.809907] Lustre: Skipped 1 previous similar message [ 2981.349233] Lustre: Failing over lustre-OST0000 [ 2981.446406] Lustre: server umount lustre-OST0000 complete [ 2990.488577] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2992.077417] Lustre: *** cfs_fail_loc=215, val=0*** [ 2992.081547] Lustre: Skipped 1 previous similar message [ 2997.216794] Lustre: *** cfs_fail_loc=215, val=0*** [ 2997.812897] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3004.390689] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3004.400281] Lustre: Skipped 3 previous similar messages [ 3010.346798] Lustre: server umount lustre-MDT0000 complete [ 3015.091874] LustreError: 75146:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787795787 with bad export cookie 4794969777151270425 [ 3015.107759] LustreError: 75146:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 3015.502407] Lustre: server umount lustre-MDT0001 complete [ 3028.801125] Lustre: server umount lustre-OST0000 complete [ 3032.351114] Lustre: 16430:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787795788/real 1787795788] req@ffff909089926300 x1874637076941312/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787795804 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3033.498322] Lustre: server umount lustre-OST0001 complete [ 3043.612550] Lustre: DEBUG MARKER: == sanity-lfsck test 12a: single command to trigger LFSCK on all devices ========================================================== 21:56:54 (1787795814) [ 3060.425830] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing load_modules_local [ 3071.432181] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3071.903773] LustreError: 84547: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. [ 3071.926527] LustreError: 84547:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 28 previous similar messages [ 3077.096254] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3089.868375] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3096.391619] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3100.827736] Lustre: 85688:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3108.793120] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3116.323845] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3117.296204] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3362 to 0x280000401:3393) [ 3126.750160] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3132.407841] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3207 to 0x2c0000401:3265) [ 3133.812075] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3142.421469] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3147.507297] Lustre: 87555:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 3185.122628] Lustre: DEBUG MARKER: == sanity-lfsck test 12b: auto detect Lustre device ====== 21:59:16 (1787795956) [ 3201.789706] Lustre: DEBUG MARKER: == sanity-lfsck test 13: LFSCK can repair crashed lmm_oi ========================================================== 21:59:32 (1787795972) [ 3203.129421] Lustre: *** cfs_fail_loc=160f, val=0*** [ 3214.773723] Lustre: DEBUG MARKER: == sanity-lfsck test 14a: LFSCK can repair MDT-object with dangling LOV EA reference (1) ========================================================== 21:59:45 (1787795985) [ 3219.187875] Lustre: *** cfs_fail_loc=1610, val=0*** [ 3219.194092] Lustre: Skipped 3 previous similar messages [ 3269.599610] 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 [ 3269.608495] Lustre: Skipped 8 previous similar messages [ 3269.612060] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3269.614769] Lustre: Skipped 4 previous similar messages [ 3275.687443] Lustre: server umount lustre-MDT0000 complete [ 3279.278942] LustreError: 88688:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787796051 with bad export cookie 4794969777151278881 [ 3279.311174] LustreError: 88688:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 3279.562797] Lustre: server umount lustre-MDT0001 complete [ 3294.358479] Lustre: server umount lustre-OST0000 complete [ 3297.249073] Lustre: 16433:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787796053/real 1787796053] req@ffff9091ae74b480 x1874637077178496/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787796069 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3298.781424] Lustre: server umount lustre-OST0001 complete [ 3317.812108] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing load_modules_local [ 3329.570273] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3330.231281] LustreError: 92296: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. [ 3330.259015] LustreError: 92296:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 12 previous similar messages [ 3335.434222] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3345.424472] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3351.404736] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3355.058323] Lustre: 93436:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3362.498782] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3370.026798] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3371.130120] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:116 to 0x280000400:161) [ 3375.209638] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3554 to 0x280000401:3585) [ 3379.278536] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3384.828533] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:116 to 0x2c0000400:161) [ 3384.834543] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3317 to 0x2c0000401:3361) [ 3386.969897] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3395.034852] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3398.519626] Lustre: 95309:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 3405.739193] Lustre: DEBUG MARKER: == sanity-lfsck test 14b: LFSCK can repair MDT-object with dangling LOV EA reference (2) ========================================================== 22:02:56 (1787796176) [ 3407.918319] Lustre: 92292:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 256 < left 278, rollback = 2 [ 3407.927393] Lustre: 92292:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 1361 previous similar messages [ 3407.931389] Lustre: 92292:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 3407.938279] Lustre: 92292:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1361 previous similar messages [ 3407.947794] Lustre: 92292:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3407.954174] Lustre: 92292:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1361 previous similar messages [ 3407.962312] Lustre: 92292:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 3407.967147] Lustre: 92292:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1361 previous similar messages [ 3407.973376] Lustre: 92292:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 3407.978957] Lustre: 92292:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1361 previous similar messages [ 3407.984768] Lustre: 92292:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3407.989494] Lustre: 92292:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1361 previous similar messages [ 3411.378553] Lustre: *** cfs_fail_loc=1610, val=0*** [ 3411.392401] Lustre: Skipped 63 previous similar messages [ 3436.019267] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3436.028507] Lustre: Skipped 6 previous similar messages [ 3441.842120] Lustre: server umount lustre-MDT0000 complete [ 3445.410942] LustreError: 92278:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787796218 with bad export cookie 4794969777151307294 [ 3445.415061] LustreError: MGC192.168.204.150@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3445.435613] LustreError: 92278:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 3445.458476] LustreError: Skipped 2 previous similar messages [ 3445.806504] Lustre: server umount lustre-MDT0001 complete [ 3460.288372] Lustre: server umount lustre-OST0000 complete [ 3461.586885] Lustre: 16433:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787796218/real 1787796218] req@ffff909081396680 x1874637077307520/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787796234 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3465.703081] Lustre: 16433:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787796222/real 1787796222] req@ffff90908473c700 x1874637077307776/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787796238 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3466.241272] Lustre: server umount lustre-OST0001 complete [ 3487.037878] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing load_modules_local [ 3499.882295] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3500.391651] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3500.396915] Lustre: Skipped 13 previous similar messages [ 3504.846365] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3513.672506] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3518.079860] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3521.514874] Lustre: 99347:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3528.895229] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3537.501239] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3538.622298] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:116 to 0x280000400:193) [ 3545.075315] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3682 to 0x280000401:3713) [ 3547.997445] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3553.773850] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3317 to 0x2c0000401:3393) [ 3553.782559] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:116 to 0x2c0000400:193) [ 3556.829575] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3567.121778] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3583.099119] Lustre: DEBUG MARKER: == sanity-lfsck test 15a: LFSCK can repair unmatched MDT-object/OST-object pairs (1) ========================================================== 22:05:53 (1787796353) [ 3587.654914] Lustre: *** cfs_fail_loc=1611, val=0*** [ 3587.660034] Lustre: Skipped 63 previous similar messages [ 3587.991376] Lustre: *** cfs_fail_loc=1611, val=0*** [ 3600.588513] Lustre: DEBUG MARKER: == sanity-lfsck test 15b: LFSCK can repair unmatched MDT-object/OST-object pairs (2) ========================================================== 22:06:11 (1787796371) [ 3603.454341] Lustre: *** cfs_fail_loc=1612, val=0*** [ 3603.512518] Lustre: *** cfs_fail_loc=1612, val=0*** [ 3603.514488] Lustre: Skipped 2 previous similar messages [ 3616.120299] Lustre: DEBUG MARKER: == sanity-lfsck test 15c: LFSCK can repair unmatched MDT-object/OST-object pairs (3) ========================================================== 22:06:26 (1787796386) [ 3617.736991] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_15c MDS newer than 2.7.55, LU-6475 [ 3619.589659] Lustre: DEBUG MARKER: == sanity-lfsck test 15d: LFSCK don't crash upon dir migration failure ========================================================== 22:06:30 (1787796390) [ 3625.735566] Lustre: *** cfs_fail_loc=1709, val=0*** [ 3626.048918] LustreError: 98216:0:(osp_object.c:618:osp_attr_get()) lustre-MDT0000-osp-MDT0001: osp_attr_get update error [0x200003ab2:0x1:0x0]: rc = -5 [ 3626.058596] LustreError: 98216:0:(mdt_reint.c:2644:mdt_reint_migrate()) lustre-MDT0001: migrate [0x240002340:0x6c:0x0]/s77 failed: rc = -5 [ 3650.432621] LustreError: 99265:0:(lod_object.c:945:lod_load_lmv_shards()) lustre-MDT0001-mdtlov: the shard [0x200003ab1:0x58:0x0]:1 for the striped directory [0x240002340:0x7f:0x0] is out of the known LMV EA range [0 - 0], failout [ 3658.269246] LustreError: 98202:0:(lod_object.c:945:lod_load_lmv_shards()) lustre-MDT0001-mdtlov: the shard [0x200003ab1:0x58:0x0]:1 for the striped directory [0x240002340:0x7f:0x0] is out of the known LMV EA range [0 - 0], failout [ 3658.282515] LustreError: 98202:0:(mdt_handler.c:1498:mdt_getattr_internal()) lustre-MDT0001: getattr error for [0x240002340:0x7f:0x0]: rc = -5 [ 3697.725785] Lustre: server umount lustre-MDT0000 complete [ 3698.656649] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3698.675381] LustreError: Skipped 2 previous similar messages [ 3698.689453] 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 [ 3698.713694] Lustre: Skipped 9 previous similar messages [ 3708.368780] LustreError: 98186:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787796480 with bad export cookie 4794969777151322022 [ 3708.386749] LustreError: 98186:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 3708.776593] Lustre: server umount lustre-MDT0001 complete [ 3726.623245] Lustre: 16431:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787796483/real 1787796483] req@ffff90908e44b100 x1874637077933568/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787796499 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3728.955620] Lustre: server umount lustre-OST0000 complete [ 3737.655818] Lustre: server umount lustre-OST0001 complete [ 3755.271248] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing unload_modules_local [ 3758.427304] Key type lgssc unregistered [ 3758.810405] LNet: 105058:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 3758.815080] LNetError: 105058:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 3758.826767] LNet: Removed LNI 192.168.204.150@tcp [ 3759.953156] Key type .llcrypt unregistered [ 3759.956632] Key type ._llcrypt unregistered [ 3786.838966] Key type ._llcrypt registered [ 3786.841152] Key type .llcrypt registered [ 3786.951224] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_hostid [ 3800.716234] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing load_modules_local [ 3802.233359] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 3802.250603] alg: No test for adler32 (adler32-zlib) [ 3803.384104] Lustre: Lustre: Build Version: 2.17.57_48_g018c4cb [ 3803.715188] LNet: Added LNI 192.168.204.150@tcp [8/256/0/180] [ 3805.401155] Key type lgssc registered [ 3806.661933] Lustre: Echo OBD driver; http://www.lustre.org/ [ 3860.155316] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing load_modules_local [ 3875.786449] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 3875.819784] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3877.129517] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 3877.163712] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 3877.238484] Lustre: lustre-MDT0000: new disk, initializing [ 3877.299502] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3877.312968] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 3882.547427] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3897.157729] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3897.250686] Lustre: 109495: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 [ 3897.295503] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 3897.299884] Lustre: Skipped 1 previous similar message [ 3897.376603] Lustre: lustre-MDT0001: new disk, initializing [ 3897.429896] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 3897.461257] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 3897.471506] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 3901.518957] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3906.578810] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 3917.812272] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3918.060046] Lustre: lustre-OST0000: new disk, initializing [ 3918.062858] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 3918.067427] Lustre: 111430:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 3918.159232] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 3919.253937] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 3919.266836] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 3919.379450] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 3925.736856] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3942.061399] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3942.301636] Lustre: lustre-OST0001: new disk, initializing [ 3942.306843] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 3942.322843] Lustre: 112460:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 3942.402273] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 3948.160359] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 3948.176057] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 3948.326650] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 3951.095861] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3963.487093] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3972.305675] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 3978.343221] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 22:12:29 (1787796749) === [ 3987.715252] Lustre: DEBUG MARKER: == sanity-lfsck test 16: LFSCK can repair inconsistent MDT-object/OST-object owner ========================================================== 22:12:38 (1787796758) [ 3988.024254] Lustre: 109500:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 251 < left 278, rollback = 2 [ 3988.034937] Lustre: 109500:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 3988.040897] Lustre: 109500:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3988.047118] Lustre: 109500:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 3988.058898] Lustre: 109500:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 3988.065916] Lustre: 109500:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3988.628896] Lustre: 109502:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 252 < left 278, rollback = 2 [ 3988.644153] Lustre: 109502:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 9 previous similar messages [ 3988.652672] Lustre: 109502:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 3988.659208] Lustre: 109502:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3988.665504] Lustre: 109502:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3988.672143] Lustre: 109502:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3988.682910] Lustre: 109502:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/1, punch: 0/0/0, quota 7/369/2 [ 3988.693599] Lustre: 109502:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3988.699179] Lustre: 109502:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/1, delete: 0/0/0 [ 3988.704510] Lustre: 109502:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3988.709386] Lustre: 109502:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3988.713479] Lustre: 109502:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3989.635640] Lustre: 109501:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 3989.650800] Lustre: 109501:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 167 previous similar messages [ 3989.662809] Lustre: 109501:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 3989.671386] Lustre: 109501:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 167 previous similar messages [ 3989.679440] Lustre: 109501:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3989.687054] Lustre: 109501:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 167 previous similar messages [ 3989.695616] Lustre: 109501:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 7/369/0 [ 3989.699817] Lustre: 109501:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 167 previous similar messages [ 3989.706269] Lustre: 109501:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 3989.711270] Lustre: 109501:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 167 previous similar messages [ 3989.715786] Lustre: 109501:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3989.721847] Lustre: 109501:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 167 previous similar messages [ 3991.799000] Lustre: *** cfs_fail_loc=1613, val=0*** [ 4004.595333] Lustre: DEBUG MARKER: == sanity-lfsck test 17: LFSCK can repair multiple references ========================================================== 22:12:55 (1787796775) [ 4006.137897] Lustre: 111498:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 257 < left 278, rollback = 2 [ 4006.146500] Lustre: 111498:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 131 previous similar messages [ 4006.154563] Lustre: 111498:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 4006.164350] Lustre: 111498:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 131 previous similar messages [ 4006.172409] Lustre: 111498:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4006.187209] Lustre: 111498:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 131 previous similar messages [ 4006.207190] Lustre: 111498:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 4006.214742] Lustre: 111498:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 131 previous similar messages [ 4006.224609] Lustre: 111498:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 4006.232556] Lustre: 111498:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 131 previous similar messages [ 4006.246570] Lustre: 111498:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4006.259632] Lustre: 111498:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 131 previous similar messages [ 4007.813365] Lustre: *** cfs_fail_loc=1614, val=0*** [ 4008.342390] Lustre: *** cfs_fail_loc=1614, val=103*** [ 4008.344076] Lustre: Skipped 1 previous similar message [ 4013.405276] Lustre: 111421:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 259 < left 275, rollback = 2 [ 4013.412986] Lustre: 111421:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 11 previous similar messages [ 4013.419078] Lustre: 111421:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 4013.424250] Lustre: 111421:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 4013.431888] Lustre: 111421:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/1, xattr_set: 3/275/0 [ 4013.439837] Lustre: 111421:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 4013.449531] Lustre: 111421:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/9/0, punch: 1/4/0, quota 7/225/0 [ 4013.457160] Lustre: 111421:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 4013.461072] Lustre: 111421:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 4013.465618] Lustre: 111421:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 4013.474814] Lustre: 111421:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 4013.494105] Lustre: 111421:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 4021.487489] Lustre: DEBUG MARKER: == sanity-lfsck test 18a: Find out orphan OST-object and repair it (1) ========================================================== 22:13:12 (1787796792) [ 4021.888556] Lustre: 109500:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 252 < left 278, rollback = 2 [ 4021.902271] Lustre: 109500:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 1 previous similar message [ 4021.909013] Lustre: 109500:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4021.916388] Lustre: 109500:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1 previous similar message [ 4021.928511] Lustre: 109500:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4021.934760] Lustre: 109500:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1 previous similar message [ 4021.947165] Lustre: 109500:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 4021.955506] Lustre: 109500:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1 previous similar message [ 4021.961709] Lustre: 109500:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 4021.969168] Lustre: 109500:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1 previous similar message [ 4021.983182] Lustre: 109500:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4021.991276] Lustre: 109500:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1 previous similar message [ 4024.625758] Lustre: *** cfs_fail_loc=1615, val=0*** [ 4024.630099] Lustre: Skipped 1 previous similar message [ 4025.735523] Lustre: *** cfs_fail_loc=1615, val=0*** [ 4025.740990] Lustre: Skipped 1 previous similar message [ 4046.142583] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_18b skipping excluded test 18b [ 4047.787807] Lustre: DEBUG MARKER: == sanity-lfsck test 18c: Find out orphan OST-object and repair it (3) ========================================================== 22:13:39 (1787796819) [ 4048.377772] Lustre: 109500:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 4048.387393] Lustre: 109500:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 21 previous similar messages [ 4048.392805] Lustre: 109500:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 4048.398430] Lustre: 109500:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4048.404602] Lustre: 109500:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4048.410179] Lustre: 109500:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4048.416372] Lustre: 109500:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 4048.421860] Lustre: 109500:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4048.426607] Lustre: 109500:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 4048.432504] Lustre: 109500:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4048.437635] Lustre: 109500:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4048.442541] Lustre: 109500:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4051.281723] Lustre: *** cfs_fail_loc=1617, val=0*** [ 4051.427286] Lustre: *** cfs_fail_loc=1617, val=0*** [ 4054.204480] Lustre: *** cfs_fail_loc=1616, val=0*** [ 4054.211589] Lustre: Skipped 3 previous similar messages [ 4076.795658] Lustre: DEBUG MARKER: == sanity-lfsck test 18d: Find out orphan OST-object and repair it (4) ========================================================== 22:14:07 (1787796847) [ 4079.178111] Lustre: *** cfs_fail_loc=1618, val=0*** [ 4079.182292] Lustre: Skipped 5 previous similar messages [ 4116.448899] 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 [ 4116.460936] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4116.463449] Lustre: Skipped 2 previous similar messages [ 4116.478529] Lustre: Skipped 3 previous similar messages [ 4119.463685] Lustre: server umount lustre-MDT0000 complete [ 4124.126236] LustreError: 109485:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787796896 with bad export cookie 17771864819980359831 [ 4124.138218] LustreError: MGC192.168.204.150@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4124.148253] LustreError: 109485:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 4124.495360] Lustre: server umount lustre-MDT0001 complete [ 4139.649973] Lustre: server umount lustre-OST0000 complete [ 4143.391707] Lustre: 106653:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787796899/real 1787796899] req@ffff90908e448700 x1874640582695168/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787796915 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4143.413673] 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 [ 4143.432654] Lustre: Skipped 1 previous similar message [ 4144.116387] Lustre: server umount lustre-OST0001 complete [ 4164.433181] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing load_modules_local [ 4175.634712] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4176.101078] LustreError: 118173: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. [ 4176.114336] LustreError: 118173:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 5 previous similar messages [ 4176.177354] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4180.959333] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4181.472040] LustreError: 118174: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. [ 4185.569769] LustreError: 118173: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. [ 4190.693731] LustreError: 118174: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. [ 4191.597341] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4192.090122] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 4197.422939] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4201.184118] Lustre: 119314:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 4209.248694] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4209.553931] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 4216.762866] LustreError: 119667: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. [ 4216.808281] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:4 to 0x280000400:33) [ 4217.384771] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4220.907169] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:116 to 0x280000401:161) [ 4226.021959] LustreError: 119992: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. [ 4226.042688] LustreError: 119992:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 3 previous similar messages [ 4227.748657] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4233.203011] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:33) [ 4233.209869] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:4 to 0x2c0000401:33) [ 4235.721701] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4244.032283] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4247.856564] Lustre: 121183:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 4266.129761] Lustre: DEBUG MARKER: == sanity-lfsck test 18e: Find out orphan OST-object and repair it (5) ========================================================== 22:17:17 (1787797037) [ 4266.553943] Lustre: 118169:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 252 < left 278, rollback = 2 [ 4266.560101] Lustre: 118169:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 46 previous similar messages [ 4266.564883] Lustre: 118169:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4266.570602] Lustre: 118169:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4266.578626] Lustre: 118169:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4266.584053] Lustre: 118169:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4266.588922] Lustre: 118169:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/1 [ 4266.595810] Lustre: 118169:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4266.600331] Lustre: 118169:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 4266.605813] Lustre: 118169:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4266.611060] Lustre: 118169:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4266.615349] Lustre: 118169:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4268.582741] Lustre: *** cfs_fail_loc=1618, val=0*** [ 4268.587073] Lustre: Skipped 3 previous similar messages [ 4304.864298] 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 [ 4304.869909] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4304.871661] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4304.879409] Lustre: Skipped 2 previous similar messages [ 4309.988523] LustreError: 118173: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. [ 4310.009462] LustreError: 118173:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 3 previous similar messages [ 4310.498224] Lustre: server umount lustre-MDT0000 complete [ 4315.117493] LustreError: 118153:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787797087 with bad export cookie 17771864819980375077 [ 4315.122566] LustreError: 106651:0:(client.c:1394:ptlrpc_import_delay_req()) @@@ IMP_CLOSED req@ffff90918766c700 x1874640582776448/t0(0) o38->lustre-MDT0000-lwp-MDT0001@0@lo:12/10 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 [ 4315.136631] LustreError: MGC192.168.204.150@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4315.473968] Lustre: server umount lustre-MDT0001 complete [ 4329.707078] Lustre: server umount lustre-OST0000 complete [ 4344.506782] Lustre: server umount lustre-OST0001 complete [ 4361.343659] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing load_modules_local [ 4372.366844] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4372.846279] LustreError: 123757: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. [ 4372.864224] LustreError: 123757:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 3 previous similar messages [ 4372.957406] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4372.967649] Lustre: Skipped 1 previous similar message [ 4378.188780] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4389.296569] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4395.208765] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4398.443740] Lustre: 124897:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 4407.249800] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4414.388366] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4414.644864] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:4 to 0x280000400:65) [ 4417.715819] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:166 to 0x280000401:193) [ 4423.724735] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4429.288690] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:4 to 0x2c0000401:65) [ 4429.427736] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:65) [ 4430.898598] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4439.568829] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4443.460628] Lustre: 126768:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 4449.547570] Lustre: 123758:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 252 < left 260, rollback = 2 [ 4449.563757] Lustre: 123758:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 21 previous similar messages [ 4449.574546] Lustre: 123758:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4449.586781] Lustre: 123758:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4449.605259] Lustre: 123758:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 0/0/0, xattr_set: 1/260/0 [ 4449.611831] Lustre: 123758:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4449.622275] Lustre: 123758:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/9/0, punch: 0/0/0, quota 4/150/2 [ 4449.635086] Lustre: 123758:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4449.641847] Lustre: 123758:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 1/17/2, delete: 0/0/0 [ 4449.645579] Lustre: 123758:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4449.654885] Lustre: 123758:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 4449.661893] Lustre: 123758:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4449.707459] Lustre: *** cfs_fail_loc=1602, val=10*** [ 4479.500877] Lustre: DEBUG MARKER: == sanity-lfsck test 18f: Skip the failed OST(s) when handle orphan OST-objects ========================================================== 22:20:50 (1787797250) [ 4483.923797] Lustre: *** cfs_fail_loc=1616, val=0*** [ 4483.926717] Lustre: Skipped 3 previous similar messages [ 4491.352970] Lustre: *** cfs_fail_loc=161c, val=0*** [ 4514.086540] Lustre: DEBUG MARKER: == sanity-lfsck test 18g: Find out orphan OST-object and repair it (7) ========================================================== 22:21:24 (1787797284) [ 4516.748056] Lustre: *** cfs_fail_loc=162e, val=0*** [ 4516.754309] Lustre: *** cfs_fail_loc=162e, val=0*** [ 4516.757644] Lustre: Skipped 7 previous similar messages [ 4533.382459] Lustre: DEBUG MARKER: == sanity-lfsck test 18h: LFSCK can repair crashed PFL extent range ========================================================== 22:21:43 (1787797303) [ 4558.312501] Lustre: DEBUG MARKER: == sanity-lfsck test 19a: OST-object inconsistency self detect ========================================================== 22:22:09 (1787797329) [ 4573.052521] Lustre: DEBUG MARKER: == sanity-lfsck test 19b: OST-object inconsistency self repair ========================================================== 22:22:24 (1787797344) [ 4576.518419] Lustre: *** cfs_fail_loc=1611, val=0*** [ 4576.549663] Lustre: *** cfs_fail_loc=1611, val=0*** [ 4576.557398] Lustre: Skipped 3 previous similar messages [ 4582.340605] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.204.50@tcp inode [0x2000013a1:0x1f:0x0] object 0x280000401:202 extent [0-4095], client returned csum 0 (type 10), server csum 70380e72 (type 10) [ 4583.480444] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.204.50@tcp inode [0x2000013a1:0x20:0x0] object 0x280000401:203 extent [0-4095], client returned csum 0 (type 10), server csum 70290e71 (type 10) [ 4592.067106] Lustre: DEBUG MARKER: == sanity-lfsck test 20a: Handle the orphan with dummy LOV EA slot properly ========================================================== 22:22:43 (1787797363) [ 4592.396640] Lustre: 123754:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 252 < left 278, rollback = 2 [ 4592.404378] Lustre: 123754:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 104 previous similar messages [ 4592.410060] Lustre: 123754:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4592.416446] Lustre: 123754:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 4592.421273] Lustre: 123754:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4592.426295] Lustre: 123754:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 4592.431618] Lustre: 123754:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 4592.436839] Lustre: 123754:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 4592.441717] Lustre: 123754:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 4592.446877] Lustre: 123754:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 4592.451496] Lustre: 123754:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4592.460022] Lustre: 123754:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 104 previous similar messages [ 4594.571788] Lustre: *** cfs_fail_loc=1616, val=0*** [ 4594.576587] Lustre: Skipped 3 previous similar messages [ 4617.395060] Lustre: DEBUG MARKER: == sanity-lfsck test 20b: Handle the orphan with dummy LOV EA slot properly - PFL case ========================================================== 22:23:08 (1787797388) [ 4624.674140] Lustre: DEBUG MARKER: == sanity-lfsck test 21: run all LFSCK components by default ========================================================== 22:23:15 (1787797395) [ 4639.804741] Lustre: DEBUG MARKER: == sanity-lfsck test 22a: LFSCK can repair unmatched pairs (1) ========================================================== 22:23:30 (1787797410) [ 4642.464482] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4642.472904] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4642.479165] Lustre: Skipped 1 previous similar message [ 4654.043978] Lustre: DEBUG MARKER: == sanity-lfsck test 22b: LFSCK can repair unmatched pairs (2) ========================================================== 22:23:45 (1787797425) [ 4655.725183] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4655.729478] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4668.577666] Lustre: DEBUG MARKER: == sanity-lfsck test 23a: LFSCK can repair dangling name entry (1) ========================================================== 22:23:59 (1787797439) [ 4670.512862] Lustre: *** cfs_fail_loc=1620, val=0*** [ 4687.008325] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_23b skipping excluded test 23b [ 4689.383600] Lustre: DEBUG MARKER: == sanity-lfsck test 23c: LFSCK can repair dangling name entry (3) ========================================================== 22:24:20 (1787797460) [ 4696.541970] Lustre: *** cfs_fail_loc=1621, val=127*** [ 4696.547705] Lustre: Skipped 1 previous similar message [ 4699.694885] Lustre: *** cfs_fail_loc=1602, val=10*** [ 4723.199198] Lustre: DEBUG MARKER: == sanity-lfsck test 23d: LFSCK can repair a dangling name entry to a remote object ========================================================== 22:24:54 (1787797494) [ 4726.229953] Lustre: Failing over lustre-MDT0000 [ 4726.250642] 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 [ 4726.303412] Lustre: Skipped 3 previous similar messages [ 4726.336666] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4726.364658] Lustre: Skipped 3 previous similar messages [ 4726.868136] Lustre: server umount lustre-MDT0000 complete [ 4730.674337] LustreError: 127252:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.204.50@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4730.695628] LustreError: 127252:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 8 previous similar messages [ 4740.055130] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4740.247116] LustreError: MGC192.168.204.150@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4740.706585] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4740.713635] Lustre: Skipped 3 previous similar messages [ 4740.772507] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4740.869594] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4745.700582] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4745.754924] Lustre: lustre-MDT0000: Recovery over after 0:05, of 2 clients 2 recovered and 0 were evicted. [ 4745.800877] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:130 to 0x2c0000401:161) [ 4745.802472] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:265 to 0x280000401:289) [ 4747.512754] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4750.212536] LustreError: 123753:0:(mdt_open.c:1324:mdt_cross_open()) lustre-MDT0000: [0x2000013a3:0x82:0x0] doesn't exist!: rc = -14 [ 4763.631636] Lustre: DEBUG MARKER: == sanity-lfsck test 24: LFSCK can repair multiple-referenced name entry ========================================================== 22:25:33 (1787797533) [ 4766.337116] Lustre: *** cfs_fail_loc=1622, val=0*** [ 4766.508687] Lustre: *** cfs_fail_loc=1622, val=0*** [ 4766.516611] Lustre: Skipped 1 previous similar message [ 4781.577796] Lustre: DEBUG MARKER: == sanity-lfsck test 25: LFSCK can repair bad file type in the name entry ========================================================== 22:25:52 (1787797552) [ 4783.535529] Lustre: *** cfs_fail_loc=1623, val=0*** [ 4796.156619] Lustre: DEBUG MARKER: == sanity-lfsck test 26a: LFSCK can add the missing local name entry back to the namespace ========================================================== 22:26:06 (1787797566) [ 4798.331957] Lustre: *** cfs_fail_loc=1624, val=0*** [ 4811.678912] Lustre: DEBUG MARKER: == sanity-lfsck test 26b: LFSCK can add the missing remote name entry back to the namespace ========================================================== 22:26:22 (1787797582) [ 4827.202886] Lustre: DEBUG MARKER: == sanity-lfsck test 27a: LFSCK can recreate the lost local parent directory as orphan ========================================================== 22:26:38 (1787797598) [ 4829.038755] Lustre: *** cfs_fail_loc=1624, val=0*** [ 4829.044590] Lustre: Skipped 1 previous similar message [ 4841.497420] Lustre: DEBUG MARKER: == sanity-lfsck test 27b: LFSCK can recreate the lost remote parent directory as orphan ========================================================== 22:26:52 (1787797612) [ 4856.457755] Lustre: DEBUG MARKER: == sanity-lfsck test 28: Skip the failed MDT(s) when handle orphan MDT-objects ========================================================== 22:27:07 (1787797627) [ 4856.814069] Lustre: 127927:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 252 < left 278, rollback = 2 [ 4856.819329] Lustre: 127927:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 497 previous similar messages [ 4856.824084] Lustre: 127927:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4856.828470] Lustre: 127927:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 497 previous similar messages [ 4856.833047] Lustre: 127927:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4856.837534] Lustre: 127927:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 497 previous similar messages [ 4856.842483] Lustre: 127927:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 4856.845975] Lustre: 127927:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 497 previous similar messages [ 4856.850907] Lustre: 127927:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 4856.856273] Lustre: 127927:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 497 previous similar messages [ 4856.861227] Lustre: 127927:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4856.866061] Lustre: 127927:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 497 previous similar messages [ 4865.077213] Lustre: *** cfs_fail_loc=161c, val=0*** [ 4865.080934] Lustre: Skipped 1 previous similar message [ 4882.998914] Lustre: DEBUG MARKER: == sanity-lfsck test 29b: LFSCK can repair bad nlink count (2) ========================================================== 22:27:34 (1787797654) [ 4885.600066] Lustre: *** cfs_fail_loc=1626, val=0*** [ 4885.605879] Lustre: Skipped 4 previous similar messages [ 4899.045572] Lustre: DEBUG MARKER: == sanity-lfsck test 29c: verify linkEA size limitation == 22:27:50 (1787797670) [ 4933.945824] Lustre: DEBUG MARKER: == sanity-lfsck test 29d: accessing non-existing inode shouldn't turn fs read-only (ldiskfs) ========================================================== 22:28:24 (1787797704) [ 4937.467696] LustreError: 123754:0:(osd_handler.c:284:osd_idc_find_or_init()) lustre-MDT0000: cannot lookup FID [0x2000013a3:0x9e:0x0]: rc = -2 [ 4945.561307] Lustre: DEBUG MARKER: == sanity-lfsck test 30: LFSCK can recover the orphans from backend /lost+found ========================================================== 22:28:36 (1787797716) [ 4949.647327] Lustre: *** cfs_fail_loc=1624, val=0*** [ 4949.655174] Lustre: Skipped 2 previous similar messages [ 4967.953762] Lustre: Failing over lustre-MDT0000 [ 4968.444505] Lustre: server umount lustre-MDT0000 complete [ 4970.979897] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4970.991679] 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 [ 4970.999293] LustreError: 123754: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. [ 4971.017925] Lustre: Skipped 2 previous similar messages [ 4971.037789] LustreError: 123754:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 12 previous similar messages [ 4980.416058] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 4980.591191] LustreError: MGC192.168.204.150@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4980.873388] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4980.912522] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4985.407500] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4986.355305] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4986.363380] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4986.381834] Lustre: Skipped 3 previous similar messages [ 4986.394594] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4986.455772] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:167 to 0x2c0000401:193) [ 4986.457380] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:294 to 0x280000401:321) [ 4998.617379] Lustre: DEBUG MARKER: == sanity-lfsck test 31a: The LFSCK can find/repair the name entry with bad name hash (1) ========================================================== 22:29:29 (1787797769) [ 5014.820930] Lustre: DEBUG MARKER: == sanity-lfsck test 31b: The LFSCK can find/repair the name entry with bad name hash (2) ========================================================== 22:29:45 (1787797785) [ 5031.205964] Lustre: DEBUG MARKER: == sanity-lfsck test 31c: Re-generate the lost master LMV EA for striped directory ========================================================== 22:30:01 (1787797801) [ 5032.884798] Lustre: *** cfs_fail_loc=1629, val=0*** [ 5032.890803] Lustre: Skipped 5 previous similar messages [ 5063.021373] Lustre: DEBUG MARKER: == sanity-lfsck test 31d: Set broken striped directory (modified after broken) as read-only ========================================================== 22:30:34 (1787797834) [ 5070.443210] Lustre: Failing over lustre-MDT0000 [ 5070.871889] Lustre: server umount lustre-MDT0000 complete [ 5073.375821] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 5073.391848] 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 [ 5073.430633] Lustre: Skipped 3 previous similar messages [ 5081.319506] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5081.404855] LustreError: MGC192.168.204.150@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5081.691463] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 5086.283409] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5086.696615] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 5086.701417] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 5086.714766] Lustre: Skipped 3 previous similar messages [ 5086.738855] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 5086.791259] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:167 to 0x2c0000401:225) [ 5086.803761] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:294 to 0x280000401:353) [ 5097.748621] Lustre: Failing over lustre-MDT0000 [ 5098.170596] Lustre: server umount lustre-MDT0000 complete [ 5102.049294] 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 [ 5102.058426] Lustre: Skipped 2 previous similar messages [ 5102.060574] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 5107.451137] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5107.567599] LustreError: MGC192.168.204.150@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5107.934512] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 5109.500553] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 5113.127184] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5113.320963] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 5113.334494] Lustre: Skipped 3 previous similar messages [ 5113.372479] Lustre: lustre-MDT0000: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 5113.467130] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:355 to 0x280000401:385) [ 5113.469373] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:167 to 0x2c0000401:257) [ 5123.396387] Lustre: DEBUG MARKER: == sanity-lfsck test 31e: Re-generate the lost slave LMV EA for striped directory (1) ========================================================== 22:31:34 (1787797894) [ 5138.477335] Lustre: DEBUG MARKER: == sanity-lfsck test 31f: Re-generate the lost slave LMV EA for striped directory (2) ========================================================== 22:31:49 (1787797909) [ 5153.519906] Lustre: DEBUG MARKER: == sanity-lfsck test 31g: Repair the corrupted slave LMV EA ========================================================== 22:32:04 (1787797924) [ 5193.359500] Lustre: DEBUG MARKER: == sanity-lfsck test 31h: Repair the corrupted shard's name entry ========================================================== 22:32:44 (1787797964) [ 5212.051841] Lustre: DEBUG MARKER: == sanity-lfsck test 32a: stop LFSCK when some OST failed ========================================================== 22:33:03 (1787797983) [ 5222.469840] LustreError: 148162:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d sleeping for 3000ms [ 5225.355693] Lustre: Failing over lustre-OST0000 [ 5225.492341] Lustre: server umount lustre-OST0000 complete [ 5225.559117] LustreError: 148162:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d awake [ 5225.575556] LustreError: 148162:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d sleeping for 3000ms [ 5225.957443] 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 [ 5225.969533] Lustre: Skipped 1 previous similar message [ 5228.327165] LustreError: 148162:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout interrupted [ 5231.075455] LustreError: 125252: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. [ 5231.093095] LustreError: 125252:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 25 previous similar messages [ 5240.750401] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 5240.996798] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 5241.006417] Lustre: Skipped 2 previous similar messages [ 5241.024237] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 5242.697716] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 5242.742995] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 5242.745521] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 5242.768066] Lustre: Skipped 3 previous similar messages [ 5248.605767] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5257.979971] Lustre: DEBUG MARKER: == sanity-lfsck test 32b: stop LFSCK when some MDT failed ========================================================== 22:33:48 (1787798028) [ 5274.599019] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing load_modules_local [ 5296.350799] Lustre: 150967:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 5322.791309] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5326.500910] Lustre: 152103:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 5340.706956] LustreError: 152236:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d sleeping for 3000ms [ 5343.554219] Lustre: Failing over lustre-MDT0001 [ 5343.722339] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 5343.727691] 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 [ 5343.728815] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 5343.728822] Lustre: Skipped 1 previous similar message [ 5343.756173] Lustre: Skipped 2 previous similar messages [ 5343.775136] LustreError: 152236:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d awake [ 5343.800091] LustreError: 152235:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d sleeping for 3000ms [ 5343.814146] LustreError: 152235:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) Skipped 1 previous similar message [ 5343.982789] Lustre: server umount lustre-MDT0001 complete [ 5346.864110] LustreError: 152235:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout interrupted [ 5359.909773] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 5360.620584] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 5365.755358] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 1 client reconnects [ 5365.766262] Lustre: lustre-MDT0001-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 5365.776628] Lustre: Skipped 1 previous similar message [ 5365.807741] Lustre: lustre-MDT0001: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 5365.895661] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:71 to 0x280000400:97) [ 5365.915308] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:68 to 0x2c0000400:97) [ 5366.037255] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5376.839461] Lustre: DEBUG MARKER: == sanity-lfsck test 33: check LFSCK paramters =========== 22:35:47 (1787798147) [ 5391.092637] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing load_modules_local [ 5409.927692] Lustre: 154956:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 5435.307357] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5439.472581] Lustre: 156092:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 5441.886629] Lustre: 123753:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 257 < left 278, rollback = 2 [ 5441.897059] Lustre: 123753:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 1242 previous similar messages [ 5441.908876] Lustre: 123753:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 5441.919631] Lustre: 123753:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1243 previous similar messages [ 5441.930801] Lustre: 123753:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 5441.937924] Lustre: 123753:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1243 previous similar messages [ 5441.943876] Lustre: 123753:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 5441.951708] Lustre: 123753:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1243 previous similar messages [ 5441.957743] Lustre: 123753:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 5441.963337] Lustre: 123753:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1243 previous similar messages [ 5441.973334] Lustre: 123753:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 5441.980705] Lustre: 123753:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1243 previous similar messages [ 5462.696385] Lustre: DEBUG MARKER: == sanity-lfsck test 34: LFSCK can rebuild the lost agent object ========================================================== 22:37:13 (1787798233) [ 5464.548857] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_34 Only valid for ZFS backend [ 5466.380267] Lustre: DEBUG MARKER: == sanity-lfsck test 35: LFSCK can rebuild the lost agent entry ========================================================== 22:37:17 (1787798237) [ 5474.469491] Lustre: *** cfs_fail_loc=1631, val=0*** [ 5488.621822] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 5488.624092] 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 [ 5488.643221] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5488.653677] Lustre: Skipped 4 previous similar messages [ 5488.672137] Lustre: Skipped 5 previous similar messages [ 5493.737189] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5493.748249] Lustre: Skipped 3 previous similar messages [ 5494.093452] Lustre: server umount lustre-MDT0000 complete [ 5498.733448] LustreError: 123738:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787798271 with bad export cookie 17771864819980447961 [ 5498.736860] LustreError: MGC192.168.204.150@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5498.748799] LustreError: 123738:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 8 previous similar messages [ 5498.857811] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 5498.863784] Lustre: Skipped 1 previous similar message [ 5499.244621] Lustre: server umount lustre-MDT0001 complete [ 5506.453571] Lustre: server umount lustre-OST0000 complete [ 5510.872115] Lustre: server umount lustre-OST0001 complete [ 5529.924296] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing load_modules_local [ 5541.682953] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5547.731406] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5556.185870] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5560.902783] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5564.211516] Lustre: 159994:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 5571.528269] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5580.208309] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5582.197779] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:71 to 0x280000400:129) [ 5587.304395] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:540 to 0x280000401:577) [ 5590.129728] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5595.626484] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:412 to 0x2c0000401:449) [ 5595.632165] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:68 to 0x2c0000400:129) [ 5597.811782] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5605.505715] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5609.446235] Lustre: 161864:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 5619.908458] Lustre: DEBUG MARKER: == sanity-lfsck test 36a: rebuild LOV EA for mirrored file (1) ========================================================== 22:39:50 (1787798390) [ 5621.533352] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36a needs >= 3 OSTs [ 5623.387442] Lustre: DEBUG MARKER: == sanity-lfsck test 36b: rebuild LOV EA for mirrored file (2) ========================================================== 22:39:54 (1787798394) [ 5624.943318] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36b needs >= 3 OSTs [ 5626.802546] Lustre: DEBUG MARKER: == sanity-lfsck test 36c: rebuild LOV EA for mirrored file (3) ========================================================== 22:39:57 (1787798397) [ 5628.434721] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36c needs >= 3 OSTs [ 5630.269706] Lustre: DEBUG MARKER: == sanity-lfsck test 37: LFSCK must skip a ORPHAN ======== 22:40:01 (1787798401) [ 5641.048728] Lustre: DEBUG MARKER: == sanity-lfsck test 38: LFSCK does not break foreign file and reverse is also true ========================================================== 22:40:12 (1787798412) [ 5684.207910] Lustre: DEBUG MARKER: == sanity-lfsck test 39: LFSCK does not break foreign dir and reverse is also true ========================================================== 22:40:55 (1787798455) [ 5700.245174] Lustre: DEBUG MARKER: == sanity-lfsck test 40a: LFSCK correctly fixes lmm_oi in composite layout ========================================================== 22:41:11 (1787798471) [ 5715.193805] Lustre: DEBUG MARKER: == sanity-lfsck test 41: SEL support in LFSCK ============ 22:41:26 (1787798486) [ 5738.214112] Lustre: DEBUG MARKER: == sanity-lfsck test 42: LFSCK repairs inconsistent MDT-object/OST-object encryption flags ========================================================== 22:41:49 (1787798509) [ 5772.470927] Lustre: *** cfs_fail_loc=1632, val=0*** [ 5789.890937] Lustre: DEBUG MARKER: == sanity-lfsck test 43: LFSCK does not loop endlessly on iget failure in scanning-phase1 ========================================================== 22:42:40 (1787798560) [ 5793.566280] Lustre: Failing over lustre-MDT0001 [ 5793.935827] Lustre: server umount lustre-MDT0001 complete [ 5795.296723] Lustre: lustre-MDT0001-lwp-OST0000: Connection to lustre-MDT0001 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 5795.302987] LustreError: 159586: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. [ 5795.308682] Lustre: Skipped 4 previous similar messages [ 5795.326558] LustreError: 159586:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 21 previous similar messages [ 5801.699844] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5802.063030] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 5802.074862] Lustre: Skipped 5 previous similar messages [ 5802.117836] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 5802.118129] Lustre: lustre-MDT0001: Aborting client recovery [ 5802.130124] LustreError: 166414:0:(ldlm_lib.c:3029:target_stop_recovery_thread()) lustre-MDT0001: Aborting recovery [ 5802.130793] Lustre: 166438:0:(ldlm_lib.c:2429:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 5802.145678] LustreError: 166436:0:(lod_dev.c:511:lod_sub_recovery_thread()) lustre-MDT0001-osd: get update log duration 0, retries 0, failed: rc = -108 [ 5802.163357] Lustre: 166438:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0001: disconnect stale client dd4b1f56-01b1-42c2-b340-946ee034aae5@ [ 5802.174684] Lustre: lustre-MDT0001: disconnecting 2 stale clients [ 5802.189482] Lustre: lustre-MDT0001-osd: cancel update llog [0x240000400:0x1:0x0] [ 5802.210604] Lustre: lustre-MDT0000-osp-MDT0001: cancel update llog [0x200000401:0x1:0x0] [ 5802.291663] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:131 to 0x2c0000400:161) [ 5802.292796] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:71 to 0x280000400:161) [ 5806.699271] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5807.080407] Lustre: lustre-MDT0001-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 5807.086944] Lustre: Skipped 2 previous similar messages [ 5807.093607] LustreError: lustre-MDT0001-osp-MDT0000: This client was evicted by lustre-MDT0001; in progress operations using this service will fail. [ 5815.200723] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing wait_import_state FULL osp.lustre-MDT0001-os[pc]-MDT0000.*_server_uuid [ 5815.521320] Lustre: DEBUG MARKER: osp.lustre-MDT0001-os[pc]-MDT0000.*_server_uuid in FULL state after 0 sec [ 5821.725872] Lustre: DEBUG MARKER: == sanity-lfsck test 44: umount while lfsck is stopping == 22:43:13 (1787798593) [ 5830.987363] Lustre: *** cfs_fail_loc=1600, val=3*** [ 5833.589825] Lustre: Failing over lustre-MDT0000 [ 5833.610578] LustreError: lustre-MDT0000-osp-MDT0001: operation out_update to node 0@lo failed: rc = -107 [ 5833.624550] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5833.937476] Lustre: server umount lustre-MDT0000 complete [ 5843.645247] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5843.937968] LustreError: MGC192.168.204.150@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5844.278351] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 5844.284924] Lustre: Skipped 2 previous similar messages [ 5847.818119] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 5849.258331] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5849.573354] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 5849.581117] Lustre: Skipped 2 previous similar messages [ 5849.611028] Lustre: lustre-MDT0000: Recovery over after 0:02, of 2 clients 2 recovered and 0 were evicted. [ 5849.676824] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:489 to 0x2c0000401:513) [ 5849.679675] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:621 to 0x280000401:641) [ 5860.621670] Lustre: DEBUG MARKER: == sanity-lfsck test 45: LFSCK should fix UID/GID/PROJID of OST object ========================================================== 22:43:51 (1787798631) [ 5887.014281] Lustre: Failing over lustre-OST0000 [ 5887.120503] Lustre: server umount lustre-OST0000 complete [ 5888.992793] LustreError: lustre-OST0000-osc-MDT0001: operation ost_statfs to node 0@lo failed: rc = -107 [ 5893.015867] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: (null) [ 5903.159033] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5904.129218] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 5904.836762] Lustre: lustre-OST0000: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [ 5909.539850] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5915.742881] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing wait_import_state (FULL|IDLE) os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid 50 [ 5916.021298] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid in FULL state after 0 sec [ 5921.874342] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing wait_import_state (FULL|IDLE) os[cp].lustre-OST0000-osc-MDT0001.ost_server_uuid 50 [ 5922.184755] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0001.ost_server_uuid in FULL state after 0 sec [ 5927.669415] Lustre: DEBUG MARKER: oleg450-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0000-osc-ffff94e04785a000.ost_server_uuid 50 [ 5929.285511] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff94e04785a000.ost_server_uuid in FULL state after 0 sec [ 5985.137000] Lustre: server umount lustre-MDT0000 complete [ 5995.095662] LustreError: 158835:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787798767 with bad export cookie 17771864819980530925 [ 5995.097507] LustreError: MGC192.168.204.150@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5995.106617] LustreError: 158835:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 5995.452317] Lustre: server umount lustre-MDT0001 complete [ 6011.682312] Lustre: 106652:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787798768/real 1787798768] req@ffff90908ac4a300 x1874640584625024/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787798784 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6016.736346] Lustre: 106655:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787798773/real 1787798773] req@ffff9091ac038380 x1874640584625408/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787798789 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6017.063942] Lustre: server umount lustre-OST0000 complete [ 6021.087103] Lustre: 106653:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787798777/real 1787798777] req@ffff90918443b100 x1874640584625792/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787798793 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6026.283464] Lustre: 106654:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787798782/real 1787798782] req@ffff90908ac49500 x1874640584626176/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787798798 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6027.341940] Lustre: server umount lustre-OST0001 complete [ 6047.195542] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing unload_modules_local [ 6050.382445] Key type lgssc unregistered [ 6050.556505] LNet: 175549:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 6050.569363] LNetError: 175549:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 6050.586975] LNet: Removed LNI 192.168.204.150@tcp [ 6051.285139] Key type .llcrypt unregistered [ 6051.289271] Key type ._llcrypt unregistered [ 6074.693620] Key type ._llcrypt registered [ 6074.696909] Key type .llcrypt registered [ 6074.773062] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_hostid [ 6092.856280] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing load_modules_local [ 6093.764542] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 6093.791498] alg: No test for adler32 (adler32-zlib) [ 6094.867862] Lustre: Lustre: Build Version: 2.17.57_48_g018c4cb [ 6095.090754] LNet: Added LNI 192.168.204.150@tcp [8/256/0/180] [ 6096.727169] Key type lgssc registered [ 6097.901505] Lustre: Echo OBD driver; http://www.lustre.org/ [ 6158.733956] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing load_modules_local [ 6173.828939] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 6173.847964] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 6175.042281] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 6175.068855] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 6175.170534] Lustre: lustre-MDT0000: new disk, initializing [ 6175.283212] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 6175.296735] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 6180.174156] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6195.021966] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 6195.170749] Lustre: 180012: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 [ 6195.232596] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 6195.237808] Lustre: Skipped 1 previous similar message [ 6195.366620] Lustre: lustre-MDT0001: new disk, initializing [ 6195.464222] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 6195.504621] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 6195.519283] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 6200.565357] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6206.134500] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 6217.466568] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 6217.829367] Lustre: lustre-OST0000: new disk, initializing [ 6217.832479] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 6217.839157] Lustre: 181952:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 6217.920933] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 6225.473185] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6227.016182] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 6227.025745] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 6227.130845] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 6239.254980] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 6239.419517] Lustre: lustre-OST0001: new disk, initializing [ 6239.425463] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 6239.437942] Lustre: 182980:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 6239.517750] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 6245.432669] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 6245.443086] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 6245.566930] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 6246.491044] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6259.492918] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 6267.959829] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 6274.030270] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 22:50:45 (1787799045) === [ 6275.837871] Lustre: DEBUG MARKER: == sanity-lfsck test complete, duration 5974 sec ========= 22:50:46 (1787799046) [ 6277.743208] Lustre: DEBUG MARKER: === sanity-lfsck: start cleanup 22:50:48 (1787799048) === [ 6281.395078] Lustre: DEBUG MARKER: === sanity-lfsck: finish cleanup 22:50:52 (1787799052) === [ 6286.821436] 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 [ 6286.828679] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 6286.838435] Lustre: Skipped 1 previous similar message [ 6286.848770] Lustre: Skipped 3 previous similar messages [ 6291.961478] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 6293.091366] Lustre: server umount lustre-MDT0000 complete [ 6301.421452] LustreError: 180004:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787799074 with bad export cookie 14937051638107111839 [ 6301.425878] LustreError: MGC192.168.204.150@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 6301.432248] LustreError: 180004:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 6301.786537] Lustre: server umount lustre-MDT0001 complete [ 6317.407444] Lustre: 177171:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787799074/real 1787799074] req@ffff90908cdb8700 x1874642984848000/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787799090 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6317.445601] 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 [ 6317.463474] Lustre: Skipped 2 previous similar messages [ 6320.674517] Lustre: server umount lustre-OST0000 complete [ 6322.335106] Lustre: 177169:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787799078/real 1787799078] req@ffff90908cdb9c00 x1874642984848256/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787799094 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6328.287165] Lustre: 177168:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787799084/real 1787799084] req@ffff90908cdb9500 x1874642984848896/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787799100 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6328.329549] Lustre: 177168:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 6331.105905] Lustre: server umount lustre-OST0001 complete [ 6353.152810] Lustre: DEBUG MARKER: oleg450-server.virtnet: executing unload_modules_local [ 6355.927548] Key type lgssc unregistered [ 6356.175410] LNet: 186455:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 6356.184147] LNetError: 186455:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 6356.199718] LNet: Removed LNI 192.168.204.150@tcp [ 6357.054181] Key type .llcrypt unregistered [ 6357.056102] Key type ._llcrypt unregistered