[ 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 511045795 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2400.000 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, 524584K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] ftrace: allocating 41240 entries in 162 pages [ 0.000000] ftrace: allocated 162 pages with 3 groups [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] rcu: RCU event tracing is enabled. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ 0.000000] rcu: RCU callback double-/use-after-free debug enabled. [ 0.000000] Rude variant of Tasks RCU enabled. [ 0.000000] Tracing variant of Tasks RCU enabled. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 0.000000] NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16 [ 0.000000] random: get_random_bytes called from start_kernel+0x622/0x9a8 with crng_init=0 [ 0.001000] Console: colour *CGA 80x25 [ 0.001000] printk: console [ttyS1] enabled [ 0.001000] ACPI: Core revision 20220331 [ 0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.001011] APIC: Switch to symmetric I/O mode setup [ 0.002360] x2apic enabled [ 0.003015] Switched APIC routing to physical x2apic. [ 0.004018] kvm-guest: setup PV IPIs [ 0.007366] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.008000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x22983777dd9, max_idle_ns: 440795300422 ns [ 0.008026] Calibrating delay loop (skipped) preset value.. 4800.00 BogoMIPS (lpj=2400000) [ 0.009017] pid_max: default: 32768 minimum: 301 [ 0.010159] LSM: Security Framework initializing [ 0.011077] Yama: becoming mindful. [ 0.012064] SELinux: Initializing. [ 0.013127] *** VALIDATE selinux *** [ 0.024297] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.030398] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.031173] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.032119] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.033122] *** VALIDATE tmpfs *** [ 0.034567] *** VALIDATE proc *** [ 0.035292] *** VALIDATE cgroup *** [ 0.036012] *** VALIDATE cgroup2 *** [ 0.037335] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.038182] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.039017] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.040040] Spectre V2 : User space: Vulnerable [ 0.042017] Speculative Store Bypass: Vulnerable [ 0.044901] debug: unmapping init [mem 0xffffffff9d459000-0xffffffff9d460fff] [ 0.046296] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.047848] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.048031] ... version: 2 [ 0.049015] ... bit width: 48 [ 0.050020] ... generic registers: 4 [ 0.051018] ... value mask: 0000ffffffffffff [ 0.052020] ... max period: 00007fffffffffff [ 0.053020] ... fixed-purpose events: 3 [ 0.054017] ... event mask: 000000070000000f [ 0.055417] rcu: Hierarchical SRCU implementation. [ 0.057887] smp: Bringing up secondary CPUs ... [ 0.058772] x86: Booting SMP configuration: [ 0.059032] .... node #0, CPUs: #1 #2 #3 [ 0.062724] smp: Brought up 1 node, 4 CPUs [ 0.064015] smpboot: Max logical packages: 1 [ 0.065024] smpboot: Total of 4 processors activated (19200.00 BogoMIPS) [ 0.145730] node 0 deferred pages initialised in 78ms [ 0.150009] devtmpfs: initialized [ 0.151332] x86/mm: Memory block size: 128MB [ 0.154000] gcov: version magic: 0x41383552 [ 0.157307] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.162123] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.164351] pinctrl core: initialized pinctrl subsystem [ 0.167216] [ 0.167719] ************************************************************* [ 0.170016] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.173015] ** ** [ 0.175011] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.178013] ** ** [ 0.180012] ** This means that this kernel is built to expose internal ** [ 0.182015] ** IOMMU data structures, which may compromise security on ** [ 0.185015] ** your system. ** [ 0.187015] ** ** [ 0.189013] ** If you see this message and you are not debugging the ** [ 0.191015] ** kernel, report this immediately to your vendor! ** [ 0.194024] ** ** [ 0.196012] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.198023] ************************************************************* [ 0.201782] NET: Registered protocol family 16 [ 0.203494] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.206065] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.209083] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.212494] cpuidle: using governor menu [ 0.213797] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.214462] PCI: Using configuration type 1 for base access [ 0.216156] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.223127] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.226022] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.231087] cryptd: max_cpu_qlen set to 1000 [ 0.234242] ACPI: Added _OSI(Module Device) [ 0.236015] ACPI: Added _OSI(Processor Device) [ 0.237014] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.239029] ACPI: Added _OSI(Processor Aggregator Device) [ 0.244080] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.250142] ACPI: Interpreter enabled [ 0.251055] ACPI: PM: (supports S0 S3 S4 S5) [ 0.252028] ACPI: Using IOAPIC for interrupt routing [ 0.253153] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.254434] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.263322] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.266060] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.269018] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.271092] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.276844] acpiphp: Slot [2] registered [ 0.277000] acpiphp: Slot [5] registered [ 0.279149] acpiphp: Slot [6] registered [ 0.281131] acpiphp: Slot [7] registered [ 0.283136] acpiphp: Slot [8] registered [ 0.284135] acpiphp: Slot [9] registered [ 0.286157] acpiphp: Slot [10] registered [ 0.288171] acpiphp: Slot [3] registered [ 0.290118] acpiphp: Slot [4] registered [ 0.292136] acpiphp: Slot [11] registered [ 0.294121] acpiphp: Slot [12] registered [ 0.296145] acpiphp: Slot [13] registered [ 0.298153] acpiphp: Slot [14] registered [ 0.299098] acpiphp: Slot [15] registered [ 0.300114] acpiphp: Slot [16] registered [ 0.302117] acpiphp: Slot [17] registered [ 0.303126] acpiphp: Slot [18] registered [ 0.305093] acpiphp: Slot [19] registered [ 0.306140] acpiphp: Slot [20] registered [ 0.308179] acpiphp: Slot [21] registered [ 0.310119] acpiphp: Slot [22] registered [ 0.313126] acpiphp: Slot [23] registered [ 0.315126] acpiphp: Slot [24] registered [ 0.317128] acpiphp: Slot [25] registered [ 0.318120] acpiphp: Slot [26] registered [ 0.320159] acpiphp: Slot [27] registered [ 0.323151] acpiphp: Slot [28] registered [ 0.324135] acpiphp: Slot [29] registered [ 0.325104] acpiphp: Slot [30] registered [ 0.326104] acpiphp: Slot [31] registered [ 0.326874] PCI host bridge to bus 0000:00 [ 0.328019] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.329016] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.330022] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.332019] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.334026] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.336026] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.340187] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.342690] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.347533] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.358018] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.364058] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.367022] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.369017] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.372033] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.374651] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.377869] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.381072] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.384176] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.389018] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.402017] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.408015] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.413123] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.423022] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.431018] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.451022] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.463203] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.471016] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.480019] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.496016] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.511955] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.518022] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.525014] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.545023] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.557376] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.565014] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.572015] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.596017] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.606289] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.613015] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.620015] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.644017] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 0.656131] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.662016] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.670136] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.701016] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 0.721492] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.724525] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.727106] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.730367] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.732365] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.738173] iommu: Default domain type: Passthrough [ 0.739481] SCSI subsystem initialized [ 0.740175] ACPI: bus type USB registered [ 0.742150] usbcore: registered new interface driver usbfs [ 0.744117] usbcore: registered new interface driver hub [ 0.746121] usbcore: registered new device driver usb [ 0.747120] pps_core: LinuxPPS API ver. 1 registered [ 0.749021] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.752092] PTP clock support registered [ 0.754167] EDAC MC: Ver: 3.0.0 [ 0.757175] PCI: Using ACPI for IRQ routing [ 0.758603] NetLabel: Initializing [ 0.760014] NetLabel: domain hash size = 128 [ 0.761012] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.763083] NetLabel: unlabeled traffic allowed by default [ 0.765142] vgaarb: loaded [ 0.766258] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.769021] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.776415] clocksource: Switched to clocksource kvm-clock [ 0.890312] VFS: Disk quotas dquot_6.6.0 [ 0.892983] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.895679] *** VALIDATE ramfs *** [ 0.896889] *** VALIDATE hugetlbfs *** [ 0.898307] pnp: PnP ACPI init [ 0.900265] pnp: PnP ACPI: found 6 devices [ 0.918161] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.923278] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.926271] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.929119] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.932032] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.934038] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.936732] NET: Registered protocol family 2 [ 0.939061] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.943612] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.947784] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.953814] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.957518] TCP: Hash tables configured (established 65536 bind 65536) [ 0.960424] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.963429] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.965982] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.968625] NET: Registered protocol family 1 [ 0.971275] RPC: Registered named UNIX socket transport module. [ 0.973526] RPC: Registered udp transport module. [ 0.975026] RPC: Registered tcp transport module. [ 0.976520] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.978571] NET: Registered protocol family 44 [ 0.980100] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.982066] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.984361] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.986542] PCI: CLS 0 bytes, default 64 [ 0.988628] Unpacking initramfs... [ 2.407583] debug: unmapping init [mem 0xffff95f8fcc54000-0xffff95f8fffbffff] [ 2.411407] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.413614] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.416379] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x22983777dd9, max_idle_ns: 440795300422 ns [ 2.906380] Initialise system trusted keyrings [ 2.908223] Key type blacklist registered [ 2.910745] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.919926] zbud: loaded [ 2.922864] *** VALIDATE nfs *** [ 2.924025] *** VALIDATE nfs4 *** [ 2.925405] pstore: using deflate compression [ 2.929965] Platform Keyring initialized [ 3.033351] NET: Registered protocol family 38 [ 3.034888] Key type asymmetric registered [ 3.036429] Asymmetric key parser 'x509' registered [ 3.037846] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 3.040975] io scheduler mq-deadline registered [ 3.042876] io scheduler kyber registered [ 3.044338] io scheduler bfq registered [ 3.047179] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 3.050398] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 3.053752] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 3.057139] ACPI: Power Button [PWRF] [ 3.062670] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 3.070342] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 3.085487] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 3.093466] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 3.113936] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 3.145133] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.176244] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.180581] Non-volatile memory driver v1.3 [ 3.181881] Linux agpgart interface v0.103 [ 3.215451] virtio_blk virtio1: [vda] 145416 512-byte logical blocks (74.5 MB/71.0 MiB) [ 3.219292] vda: detected capacity change from 0 to 74452992 [ 3.232123] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.237506] vdb: detected capacity change from 0 to 1073741824 [ 3.252455] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.255386] vdc: detected capacity change from 0 to 2621440000 [ 3.270609] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.273176] vdd: detected capacity change from 0 to 2621440000 [ 3.287891] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.290402] vde: detected capacity change from 0 to 4294967296 [ 3.304400] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.307103] vdf: detected capacity change from 0 to 4294967296 [ 3.312652] libphy: Fixed MDIO Bus: probed [ 3.317386] usbcore: registered new interface driver usbserial_generic [ 3.320726] usbserial: USB Serial support registered for generic [ 3.324078] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.329169] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.330625] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.333405] mousedev: PS/2 mouse device common for all mice [ 3.335832] rtc_cmos 00:05: RTC can wake from S4 [ 3.338643] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.341849] rtc_cmos 00:05: registered as rtc0 [ 3.344638] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.345240] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.345422] intel_pstate: CPU model not supported [ 3.359932] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.363680] hid: raw HID events driver (C) Jiri Kosina [ 3.365361] usbcore: registered new interface driver usbhid [ 3.367121] usbhid: USB HID core driver [ 3.368453] drop_monitor: Initializing network drop monitor service [ 3.370622] Initializing XFRM netlink socket [ 3.372432] NET: Registered protocol family 10 [ 3.374758] Segment Routing with IPv6 [ 3.376927] NET: Registered protocol family 17 [ 3.379942] mpls_gso: MPLS GSO support [ 3.386227] RAS: Correctable Errors collector initialized. [ 3.389764] AVX version of gcm_enc/dec engaged. [ 3.391964] AES CTR mode by8 optimization enabled [ 3.469864] sched_clock: Marking stable (3469840588, 0)->(4531246153, -1061405565) [ 3.473308] registered taskstats version 1 [ 3.475174] Loading compiled-in X.509 certificates [ 3.477271] zswap: loaded using pool lzo/zbud [ 3.500392] Key type big_key registered [ 3.511382] Key type encrypted registered [ 3.513044] ima: No TPM chip found, activating TPM-bypass! [ 3.515059] ima: Allocated hash algorithm: sha1 [ 3.516717] ima: No architecture policies found [ 3.518298] evm: Initialising EVM extended attributes: [ 3.520054] evm: security.selinux [ 3.521200] evm: security.ima [ 3.522330] evm: security.capability [ 3.523540] evm: HMAC attrs: 0x1 [ 3.525840] rtc_cmos 00:05: setting system clock to 2026-08-15 18:30:53 UTC (1786818653) [ 3.532452] debug: unmapping init [mem 0xffffffff9e403000-0xffffffff9e5fffff] [ 3.535294] debug: unmapping init [mem 0xffffffff9d182000-0xffffffff9d458fff] [ 3.545072] Write protecting the kernel read-only data: 28672k [ 3.548457] debug: unmapping init [mem 0xffffffff9b803000-0xffffffff9b9fffff] [ 3.551089] debug: unmapping init [mem 0xffffffff9c114000-0xffffffff9c1fffff] [ 3.583467] 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.591555] systemd[1]: Detected virtualization kvm. [ 3.594520] systemd[1]: Detected architecture x86-64. [ 3.598059] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.626966] systemd[1]: No hostname configured. [ 3.629479] systemd[1]: Set hostname to . [ 3.632158] random: systemd: uninitialized urandom read (16 bytes read) [ 3.634934] systemd[1]: Initializing machine ID from random generator. [ 3.670736] random: ln: uninitialized urandom read (6 bytes read) [ 3.751759] random: systemd: uninitialized urandom read (16 bytes read) [ 3.754936] systemd[1]: Reached target Local File Systems. [ OK ] Reached target Local File Systems. [ 3.762423] systemd[1]: Listening on Journal Socket. [ OK ] Listening on Journal Socket. [ 3.769352] systemd[1]: Listening on Journal Socket (/dev/log). [ OK ] Listening on Journal Socket (/dev/log). Starting Create list of required st…ce nodes for the current kernel... [ OK ] Reached target Swap. [ OK ] Reached target Initrd Root Device. Starting Journal Service... [ OK ] Listening on udev Kernel Socket. [ OK ] Listening on udev Control Socket. [ OK ] Reached target Sockets. Starting Apply Kernel Variables... Starting Setup Virtual Console... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Paths. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Slices. [ OK ] Started Memstrack Anylazing Service. [ OK ] Reached target Timers. Starting 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. [ OK ] Started Create Volatile Files and Directories. 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.349984] device-mapper: uevent: version 1.0.3 [ 4.353290] device-mapper: ioctl: 4.46.0-ioctl (2022-02-22) initialised: dm-devel@redhat.com [ OK ] Started dracut pre-udev hook. Starting udev Kernel Device Manager... [ OK ] Started udev Kernel Device Manager. Starting dracut pre-trigger hook... [ OK ] Started dracut pre-trigger hook. Starting udev Coldplug all Devices... Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. Starting dracut initqueue hook... [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ 5.034769] random: fast init done [ 5.064396] virtio_net virtio0 ens2: renamed from eth0 [ 5.118465] scsi host0: ata_piix [ 5.130798] scsi host1: ata_piix [ 5.134091] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 5.136132] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 5.362236] dracut-initqueue[510]: RTNETLINK answers: File exists [ 10.029455] random: crng init done [ 10.030493] 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.554075] 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 Initrd Default Target. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Paths. [ OK ] Stopped target System Initialization. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Swap. [ OK ] Stopped target Local File Systems. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. Stopping udev Kernel Device Manager... [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped target Slices. [ OK ] Stopped target Sockets. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Closed udev Kernel Socket. [ OK ] Closed udev Control Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 11.671425] printk: systemd: 26 output lines suppressed due to ratelimiting [ 11.953535] SELinux: Disabled at runtime. [ 12.014790] 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.023360] systemd[1]: Detected virtualization kvm. [ 12.025078] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 12.562796] systemd[1]: initrd-switch-root.service: Succeeded. [ 12.567555] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 12.571205] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 12.574987] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 12.577851] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 12.587277] systemd[1]: Starting Journal Service... Starting Journal Service... [ 12.591674] systemd[1]: proc-sys-fs-binfmt_misc.automount: Refusing to start, unit to trigger not loaded. [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. Starting Create list of required st…ce nodes for the current kernel... Mounting Kernel Debug File System... [ OK ] Stopped target Switch Root. Starting Remount Root and Kernel File Systems... [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Created slice system-getty.slice. [ OK ] Listening on Process Core Dump Socket. Mounting POSIX Message Queue File System... [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Reached target RPC Port Mapper. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Stopped target Initrd File Systems. [ OK ] Reached target rpc_pipefs.target. [ OK ] Stopped target Initrd Root File System. Mounting Huge Pages File System... [ OK ] Created slice User and Session Slice. [ OK ] Reached target Slices. [ OK ] Listening on udev Control Socket. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. [ OK ] Listening on udev Kernel Socket. Starting udev Coldplug all Devices... Starting Apply Kernel Variables... Activating swap /dev/disk/by-label/SWAP... [ OK ] Started Journal Service. [ 12.750162] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Mounted Kernel Debug File System. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Mounted Huge Pages File System. [ OK ] Started Apply Kernel Variables. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ 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 /mnt... Mounting /home/green/git/lustre-release... [ OK ] Started udev Coldplug all Devices. [ OK ] Mounted /mnt. [ 12.998171] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 13.249882] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 13.262471] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 13.396079] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 13.410329] EDAC sbridge: Ver: 1.1.2 [ 15.323723] Key type dns_resolver registered [ 15.617113] NFS: Registering the id_resolver key type [ 15.619243] Key type id_resolver registered [ 15.621254] Key type id_legacy registered [ OK ] Started Configure read-only root support. Starting Load/Save Random Seed... [ OK ] Reached target Local File Systems. Starting Mark the need to relabel after reboot... Starting Rebuild Dynamic Linker Cache... Starting Create Volatile Files and Directories... [ 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 ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. Starting Restore /run/initramfs on shutdown... Starting Login Service... [ OK ] Started D-Bus System Message Bus. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Started dnf makecache --timer. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Reached target Timers. [ OK ] Started irqbalance daemon. [ OK ] Reached target sshd-keygen.target. Starting Network Manager... [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Login Service. [ OK ] Started Network Manager. [ OK ] Reached target Network. Starting Dynamic System Tuning Daemon... Starting OpenSSH server daemon... Starting GSSAPI Proxy Daemon... Starting Network Manager Wait Online... Starting Hostname Service... [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... [ OK ] Started OpenSSH server daemon. [ OK ] Started Permit User Sessions. [ OK ] Started Serial Getty on ttyS1. [ OK ] Started Getty on tty1. [ OK ] Started Command Scheduler. [ OK ] Started Serial Getty on ttyS0. [ OK ] Reached target Login Prompts. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting System Logging Service... Starting Crash recovery kernel arming... Starting Notify NFS peers of a restart... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Starting Authorization Manager... [ OK ] Started Authorization Manager. [ OK ] Started Dynamic System Tuning Daemon. [ OK ] Reached target Multi-User System. [ OK ] Reached target Graphical Interface. Starting Update UTMP about System Runlevel Changes... [ OK ] Started Update UTMP about System Runlevel Changes. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg415-server login: [ 42.393445] libcfs: loading out-of-tree module taints kernel. [ 42.412849] Key type ._llcrypt registered [ 42.414237] Key type .llcrypt registered [ 42.464934] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_hostid [ 54.985356] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing load_modules_local [ 56.734368] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 56.766765] alg: No test for adler32 (adler32-zlib) [ 58.231121] Lustre: Lustre: Build Version: 2.17.54_84_gc7429ec [ 59.228542] LNet: Added LNI 192.168.204.115@tcp [8/256/0/180] [ 61.081401] Key type lgssc registered [ 63.099457] Lustre: Echo OBD driver; http://www.lustre.org/ [ 86.780651] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 136.095576] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing load_modules_local [ 149.028324] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 149.079214] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 150.301153] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 150.345380] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 150.442512] Lustre: lustre-MDT0000: new disk, initializing [ 150.539938] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 150.555405] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 154.834374] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 166.625497] hrtimer: interrupt took 5940666 ns [ 167.522098] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 167.600643] Lustre: 6501:0:(mgs_llog.c:1447:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 167.623729] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 167.629403] Lustre: Skipped 1 previous similar message [ 167.710773] Lustre: lustre-MDT0001: new disk, initializing [ 167.774762] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 167.803947] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 167.817754] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 172.921648] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 178.073442] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 188.825777] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 189.221965] Lustre: lustre-OST0000: new disk, initializing [ 189.231139] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 189.237437] Lustre: 8439:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 189.347824] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 190.385535] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 190.405552] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 190.512695] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 196.369139] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 210.748443] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 210.849823] Lustre: lustre-OST0001: new disk, initializing [ 210.852535] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 210.856536] Lustre: 9509:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 210.910151] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 217.398231] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 219.694111] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 219.718434] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 219.814466] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 228.906748] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 232.792408] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 238.458150] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing check_logdir /tmp/testlogs/ [ 243.275236] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing yml_node [ 246.849614] Lustre: DEBUG MARKER: Client: 2.17.54.84 [ 249.263468] Lustre: DEBUG MARKER: MDS: 2.17.54.84 [ 251.707410] Lustre: DEBUG MARKER: OSS: 2.17.54.84 [ 253.310644] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity-lfsck ============----- Sat Aug 15 14:35:01 EDT 2026 [ 270.997908] Lustre: DEBUG MARKER: excepting tests: 18b 23b [ 281.072122] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing load_modules_local [ 290.787107] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 290.800345] 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 [ 290.834051] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 291.810956] 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 [ 291.816038] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 291.830614] Lustre: Skipped 1 previous similar message [ 291.839603] Lustre: Skipped 3 previous similar messages [ 293.714189] Lustre: server umount lustre-MDT0000 complete [ 301.314614] LustreError: 6494:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1786818951 with bad export cookie 5299897792177666634 [ 301.317606] LustreError: MGC192.168.204.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 301.326544] LustreError: 6494:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 3 previous similar messages [ 301.642848] Lustre: server umount lustre-MDT0001 complete [ 318.304301] Lustre: 3632:0:(client.c:2489:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786818952/real 1786818952] req@ffff95f845cb2a00 x1873615214706688/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786818968 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 318.323280] 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 [ 318.329210] Lustre: Skipped 1 previous similar message [ 320.506321] Lustre: server umount lustre-OST0000 complete [ 322.528149] Lustre: 3633:0:(client.c:2489:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786818956/real 1786818956] req@ffff95f967d0b480 x1873615214706944/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786818972 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 327.649085] Lustre: 3631:0:(client.c:2489:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786818961/real 1786818961] req@ffff95f967d09500 x1873615214707584/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786818977 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 327.676552] Lustre: 3631:0:(client.c:2489:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 327.894694] Lustre: server umount lustre-OST0001 complete [ 341.418552] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing unload_modules_local [ 343.751435] Key type lgssc unregistered [ 344.017856] LNet: 14780:0:(lib-ptl.c:967:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 344.026066] LNetError: 14780:0:(acceptor.c:246:lnet_acceptor_remove_socket()) Interface ens2 not found [ 344.052483] LNet: Removed LNI 192.168.204.115@tcp [ 344.886156] Key type .llcrypt unregistered [ 344.887801] Key type ._llcrypt unregistered [ 364.273270] Key type ._llcrypt registered [ 364.276712] Key type .llcrypt registered [ 364.375229] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_hostid [ 376.916823] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing load_modules_local [ 377.775470] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 377.852752] alg: No test for adler32 (adler32-zlib) [ 378.863893] Lustre: Lustre: Build Version: 2.17.54_84_gc7429ec [ 379.072164] LNet: Added LNI 192.168.204.115@tcp [8/256/0/180] [ 380.728746] Key type lgssc registered [ 381.767675] Lustre: Echo OBD driver; http://www.lustre.org/ [ 427.718189] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing load_modules_local [ 440.145724] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 440.181513] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 441.586333] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 441.623451] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 441.743556] Lustre: lustre-MDT0000: new disk, initializing [ 441.844110] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 441.874474] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 447.280148] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 459.713571] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 459.796708] Lustre: 19213:0:(mgs_llog.c:1447:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 459.820184] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 459.822518] Lustre: Skipped 1 previous similar message [ 459.890497] Lustre: lustre-MDT0001: new disk, initializing [ 459.937433] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 459.976286] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 459.998290] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 464.073955] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 468.081229] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 475.442112] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 475.613243] Lustre: lustre-OST0000: new disk, initializing [ 475.618752] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 475.629254] Lustre: 21153:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 475.633203] Lustre: lustre-OST0000: Not available for connect from 0@lo (not set up) [ 475.679324] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 480.773360] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 480.778460] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 480.805743] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000400 [ 481.117642] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 493.946122] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 494.103150] Lustre: lustre-OST0001: new disk, initializing [ 494.113915] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 494.119986] Lustre: 22175:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 494.196576] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 500.312737] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 500.319879] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 500.407676] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 500.938342] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 510.261739] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 518.547262] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 525.094859] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 14:39:33 (1786819173) === [ 527.617325] Lustre: DEBUG MARKER: == sanity-lfsck test 0: Control LFSCK manually =========== 14:39:35 (1786819175) [ 527.769281] Lustre: 22183:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 251 < left 278, rollback = 2 [ 527.777726] Lustre: 22183:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 527.784375] Lustre: 22183:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 527.789266] Lustre: 22183:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 527.799790] Lustre: 22183:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 527.809094] Lustre: 22183:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 528.302267] Lustre: 19221:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 528.312904] Lustre: 19221:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 20 previous similar messages [ 528.319982] Lustre: 19221:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 528.327879] Lustre: 19221:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 20 previous similar messages [ 528.335318] Lustre: 19221:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 528.345115] Lustre: 19221:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 20 previous similar messages [ 528.351981] Lustre: 19221:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 528.358244] Lustre: 19221:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 20 previous similar messages [ 528.364548] Lustre: 19221:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 528.370705] Lustre: 19221:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 20 previous similar messages [ 528.377814] Lustre: 19221:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 528.383830] Lustre: 19221:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 20 previous similar messages [ 529.304563] Lustre: 19221:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 529.313849] Lustre: 19221:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 59 previous similar messages [ 529.319650] Lustre: 19221:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 529.326070] Lustre: 19221:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 59 previous similar messages [ 529.338322] Lustre: 19221:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 529.346163] Lustre: 19221:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 59 previous similar messages [ 529.352520] Lustre: 19221:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 529.365486] Lustre: 19221:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 59 previous similar messages [ 529.374236] Lustre: 19221:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 529.382852] Lustre: 19221:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 59 previous similar messages [ 529.389843] Lustre: 19221:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 529.400212] Lustre: 19221:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 59 previous similar messages [ 531.318900] Lustre: 22183:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 531.329395] Lustre: 22183:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 116 previous similar messages [ 531.341519] Lustre: 22183:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 531.353761] Lustre: 22183:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 116 previous similar messages [ 531.361040] Lustre: 22183:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 531.379060] Lustre: 22183:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 116 previous similar messages [ 531.385439] Lustre: 22183:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 531.395039] Lustre: 22183:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 116 previous similar messages [ 531.405079] Lustre: 22183:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 531.415757] Lustre: 22183:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 116 previous similar messages [ 531.425099] Lustre: 22183:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 531.435428] Lustre: 22183:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 116 previous similar messages [ 534.139206] Lustre: *** cfs_fail_loc=1600, val=3*** [ 537.880579] Lustre: *** cfs_fail_loc=1600, val=3*** [ 538.108377] Lustre: 21140:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-OST0001: opcode 2: before 259 < left 274, rollback = 2 [ 538.111932] Lustre: 23380:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 538.116409] Lustre: 21140:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 79 previous similar messages [ 538.119564] Lustre: 23380:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 78 previous similar messages [ 538.119586] Lustre: 23380:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/1, xattr_set: 2/274/0 [ 538.119590] Lustre: 23380:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 78 previous similar messages [ 538.119597] Lustre: 23380:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 0/0/0, punch: 0/0/0, quota 7/225/0 [ 538.119600] Lustre: 23380:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 78 previous similar messages [ 538.119605] Lustre: 23380:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 538.119608] Lustre: 23380:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 78 previous similar messages [ 538.119614] Lustre: 23380:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 538.119617] Lustre: 23380:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 78 previous similar messages [ 551.905197] 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 [ 551.908038] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 551.911184] Lustre: Skipped 1 previous similar message [ 557.024747] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 557.034627] Lustre: Skipped 6 previous similar messages [ 557.517632] Lustre: server umount lustre-MDT0000 complete [ 561.493726] LustreError: 19207:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1786819211 with bad export cookie 4693458067445803804 [ 561.494413] LustreError: MGC192.168.204.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 561.504681] LustreError: 19207:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 561.825420] Lustre: server umount lustre-MDT0001 complete [ 576.269807] Lustre: server umount lustre-OST0000 complete [ 579.041486] Lustre: 16378:0:(client.c:2489:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786819212/real 1786819212] req@ffff95f84da76300 x1873615550260480/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786819228 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 579.084752] 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 [ 579.098714] Lustre: Skipped 2 previous similar messages [ 580.814908] Lustre: server umount lustre-OST0001 complete [ 589.704877] Lustre: DEBUG MARKER: == sanity-lfsck test 1a: LFSCK can find out and repair crashed FID-in-dirent ========================================================== 14:40:37 (1786819237) [ 602.768523] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing load_modules_local [ 611.730711] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 612.084541] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 616.596300] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 617.450470] LustreError: 26230:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 617.480584] LustreError: 26230:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 2 previous similar messages [ 622.563341] LustreError: 26231:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 624.535529] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 624.828274] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 628.988216] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 631.972664] Lustre: 27370:0:(mgs_llog.c:1447:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 638.619981] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 645.364830] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 649.194708] LustreError: 27723:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 653.395875] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 653.618177] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 653.622023] Lustre: Skipped 1 previous similar message [ 657.737067] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:40 to 0x2c0000401:65) [ 657.740416] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:41 to 0x280000400:65) [ 660.072249] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 667.622926] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 671.235376] Lustre: 29243:0:(mgs_llog.c:1447:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 672.760950] Lustre: 26227:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 255 < left 278, rollback = 2 [ 672.769252] Lustre: 26227:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 62 previous similar messages [ 672.773865] Lustre: 26227:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/2, destroy: 0/0/0 [ 672.777624] Lustre: 26227:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 69 previous similar messages [ 672.785037] Lustre: 26227:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 672.797114] Lustre: 26227:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 69 previous similar messages [ 672.813041] Lustre: 26227:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 672.828862] Lustre: 26227:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 69 previous similar messages [ 672.835899] Lustre: 26227:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 672.853771] Lustre: 26227:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 69 previous similar messages [ 672.871475] Lustre: 26227:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 672.886830] Lustre: 26227:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 69 previous similar messages [ 678.003785] Lustre: *** cfs_fail_loc=1501, val=0*** [ 686.973337] Lustre: Failing over lustre-MDT0000 [ 687.552770] Lustre: server umount lustre-MDT0000 complete [ 688.613401] 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 [ 688.618951] LustreError: 26227:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 688.625400] Lustre: Skipped 2 previous similar messages [ 688.646049] LustreError: 26227:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 3 previous similar messages [ 693.739162] LustreError: 26227:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 693.750371] LustreError: 26227:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 3 previous similar messages [ 698.860732] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 699.021723] LustreError: MGC192.168.204.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 699.274722] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 699.310431] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 703.345847] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 704.487779] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 704.493484] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 704.515687] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 704.548146] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:105 to 0x280000400:129) [ 704.550984] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:105 to 0x2c0000401:129) [ 706.418940] Lustre: *** cfs_fail_loc=1505, val=0*** [ 713.604836] Lustre: DEBUG MARKER: == sanity-lfsck test 1b: LFSCK can find out and repair the missing FID-in-LMA ========================================================== 14:42:41 (1786819361) [ 714.907558] Lustre: 26227:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 714.913197] Lustre: 26227:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 322 previous similar messages [ 714.918581] Lustre: 26227:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 714.922989] Lustre: 26227:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 714.927294] Lustre: 26227:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 714.933977] Lustre: 26227:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 714.938667] Lustre: 26227:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 714.943474] Lustre: 26227:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 714.948272] Lustre: 26227:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 714.953244] Lustre: 26227:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 714.957356] Lustre: 26227:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 714.961162] Lustre: 26227:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 719.976656] Lustre: *** cfs_fail_loc=1502, val=0*** [ 730.363784] Lustre: Failing over lustre-MDT0000 [ 730.681765] Lustre: server umount lustre-MDT0000 complete [ 735.210894] 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 [ 735.220901] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 735.235721] Lustre: Skipped 1 previous similar message [ 735.238910] LustreError: 26226:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 735.299723] LustreError: 26226:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 7 previous similar messages [ 743.269370] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 743.398955] LustreError: MGC192.168.204.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 743.591393] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 748.363303] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 749.025545] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 749.047196] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 749.060995] Lustre: Skipped 3 previous similar messages [ 749.108675] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 749.140406] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:169 to 0x2c0000401:193) [ 749.142680] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:169 to 0x280000400:193) [ 752.095353] Lustre: *** cfs_fail_loc=1505, val=0*** [ 758.706712] Lustre: DEBUG MARKER: == sanity-lfsck test 1c: LFSCK can find out and repair lost FID-in-dirent ========================================================== 14:43:26 (1786819406) [ 760.119669] Lustre: 26226:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 760.125805] Lustre: 26226:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 321 previous similar messages [ 760.130789] Lustre: 26226:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 760.134543] Lustre: 26226:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 760.139072] Lustre: 26226:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 760.142613] Lustre: 26226:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 760.147802] Lustre: 26226:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 760.151255] Lustre: 26226:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 760.155083] Lustre: 26226:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 760.158338] Lustre: 26226:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 760.164323] Lustre: 26226:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 760.169962] Lustre: 26226:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 764.768944] Lustre: *** cfs_fail_loc=1504, val=0*** [ 764.774794] Lustre: *** cfs_fail_loc=1504, val=0*** [ 764.777210] Lustre: Skipped 1 previous similar message [ 770.615385] Lustre: Failing over lustre-MDT0000 [ 770.762608] Lustre: server umount lustre-MDT0000 complete [ 774.625455] 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 [ 774.630365] LustreError: 26226:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 774.640268] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 774.644434] Lustre: Skipped 6 previous similar messages [ 774.688630] LustreError: 26226:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 7 previous similar messages [ 779.695559] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 779.859232] LustreError: MGC192.168.204.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 780.089946] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 780.095857] Lustre: Skipped 1 previous similar message [ 780.127909] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 783.376363] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 785.124164] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 785.132660] Lustre: lustre-MDT0000: Denying connection for new client 27d66e26-c49e-436f-91f1-5761c5a10419 (at 192.168.204.15@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 1:00 [ 785.385433] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 785.390566] Lustre: Skipped 3 previous similar messages [ 785.399071] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 785.432317] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:233 to 0x280000400:257) [ 785.432548] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:233 to 0x2c0000401:257) [ 791.646575] Lustre: *** cfs_fail_loc=1505, val=0*** [ 797.774978] Lustre: DEBUG MARKER: == sanity-lfsck test 2a: LFSCK can find out and repair crashed linkEA entry ========================================================== 14:44:05 (1786819445) [ 803.326572] Lustre: *** cfs_fail_loc=1603, val=0*** [ 809.667458] Lustre: Failing over lustre-MDT0000 [ 809.943720] Lustre: server umount lustre-MDT0000 complete [ 810.979333] 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 [ 810.980430] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 811.002607] LustreError: 26962:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 811.043861] LustreError: 26962:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 7 previous similar messages [ 818.745420] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 818.820292] LustreError: MGC192.168.204.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 819.036888] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 823.167968] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 824.292560] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 824.304148] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 824.315263] Lustre: Skipped 3 previous similar messages [ 824.340206] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 824.387914] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:297 to 0x2c0000401:321) [ 824.392188] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:297 to 0x280000400:321) [ 830.796943] Lustre: DEBUG MARKER: == sanity-lfsck test 2b: LFSCK can find out and remove invalid linkEA entry ========================================================== 14:44:38 (1786819478) [ 831.919754] Lustre: 26226:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 256 < left 278, rollback = 2 [ 831.926933] Lustre: 26226:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 644 previous similar messages [ 831.932512] Lustre: 26226:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 831.938533] Lustre: 26226:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 831.944615] Lustre: 26226:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 831.949670] Lustre: 26226:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 831.955528] Lustre: 26226:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 831.963135] Lustre: 26226:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 831.969184] Lustre: 26226:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 831.976236] Lustre: 26226:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 831.982041] Lustre: 26226:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 831.987758] Lustre: 26226:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 836.111102] Lustre: *** cfs_fail_loc=1604, val=0*** [ 843.686289] Lustre: Failing over lustre-MDT0000 [ 843.884241] Lustre: server umount lustre-MDT0000 complete [ 844.769026] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 844.771096] 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 [ 844.791262] Lustre: Skipped 6 previous similar messages [ 852.990811] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 853.119864] LustreError: MGC192.168.204.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 853.412831] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 857.256381] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 858.594922] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 858.599373] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 858.605341] Lustre: Skipped 3 previous similar messages [ 858.617495] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 858.655286] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:361 to 0x280000400:385) [ 858.658204] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:361 to 0x2c0000401:385) [ 865.473144] Lustre: DEBUG MARKER: == sanity-lfsck test 2c: LFSCK can find out and remove repeated linkEA entry ========================================================== 14:45:13 (1786819513) [ 870.810845] Lustre: *** cfs_fail_loc=1605, val=0*** [ 876.360709] Lustre: Failing over lustre-MDT0000 [ 876.513956] Lustre: server umount lustre-MDT0000 complete [ 879.078983] 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 [ 879.088565] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 879.090243] LustreError: 26225:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 879.090252] LustreError: 26225:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 12 previous similar messages [ 879.097022] Lustre: Skipped 1 previous similar message [ 885.393578] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 885.551889] LustreError: MGC192.168.204.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 885.815092] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 889.239878] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 890.858212] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 890.861764] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 890.872930] Lustre: Skipped 3 previous similar messages [ 890.904555] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 890.938870] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:425 to 0x2c0000401:449) [ 890.939672] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:425 to 0x280000400:449) [ 896.481072] Lustre: DEBUG MARKER: == sanity-lfsck test 2d: LFSCK can recover the missing linkEA entry ========================================================== 14:45:44 (1786819544) [ 901.862856] Lustre: *** cfs_fail_loc=161d, val=0*** [ 907.781620] Lustre: Failing over lustre-MDT0000 [ 907.990233] Lustre: server umount lustre-MDT0000 complete [ 911.330877] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 916.974685] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 917.355754] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 917.366212] Lustre: Skipped 3 previous similar messages [ 917.406523] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 921.520521] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 922.593976] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 922.596042] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 922.603652] Lustre: Skipped 3 previous similar messages [ 922.612538] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 922.641284] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:489 to 0x2c0000401:513) [ 922.641829] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:489 to 0x280000400:513) [ 928.846595] Lustre: DEBUG MARKER: == sanity-lfsck test 2e: namespace LFSCK can verify remote object linkEA ========================================================== 14:46:16 (1786819576) [ 931.022431] Lustre: *** cfs_fail_loc=1603, val=0*** [ 940.129775] Lustre: DEBUG MARKER: == sanity-lfsck test 3: LFSCK can verify multiple-linked objects ========================================================== 14:46:27 (1786819587) [ 946.096968] Lustre: *** cfs_fail_loc=1603, val=0*** [ 946.923235] Lustre: *** cfs_fail_loc=1604, val=0*** [ 957.911637] Lustre: DEBUG MARKER: == sanity-lfsck test 4: FID-in-dirent can be rebuilt after MDT file-level backup/restore ========================================================== 14:46:45 (1786819605) [ 959.951876] Lustre: 29261:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 959.959039] Lustre: 29261:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 1385 previous similar messages [ 959.965493] Lustre: 29261:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 959.972740] Lustre: 29261:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1385 previous similar messages [ 959.979467] Lustre: 29261:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 959.985085] Lustre: 29261:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1385 previous similar messages [ 959.994487] Lustre: 29261:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 960.009493] Lustre: 29261:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1385 previous similar messages [ 960.020255] Lustre: 29261:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 960.028151] Lustre: 29261:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1385 previous similar messages [ 960.035243] Lustre: 29261:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 960.041104] Lustre: 29261:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1385 previous similar messages [ 992.003630] Lustre: Failing over lustre-MDT0000 [ 992.276778] Lustre: server umount lustre-MDT0000 complete [ 994.272822] 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 [ 994.274715] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 994.288223] Lustre: Skipped 8 previous similar messages [ 996.693551] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1005.965843] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1009.633583] LustreError: 29261:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1009.663383] LustreError: 29261:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 30 previous similar messages [ 1010.656715] Lustre: 16377:0:(client.c:2489:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786819644/real 1786819644] req@ffff95f975432680 x1873615550847616/t0(0) o400->MGC192.168.204.115@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1786819660 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1010.711787] LustreError: MGC192.168.204.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1010.733062] LustreError: Skipped 1 previous similar message [ 1018.604479] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1018.632652] Lustre: lustre-MDT0000: reset Object Index mappings [ 1020.833480] LustreError: 42393:0:(import.c:339:ptlrpc_invalidate_import()) MGS: timeout waiting for callback (1 != 0) [ 1020.843874] LustreError: 42393:0:(import.c:363:ptlrpc_invalidate_import()) @@@ still on sending list req@ffff95f963889880 x1873615550853632/t0(0) o250->MGC192.168.204.115@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 1786819670 ref 1 fl Rpc:NQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1020.866656] LustreError: 42393:0:(import.c:373:ptlrpc_invalidate_import()) MGS: Unregistering RPCs found (0). Network is sluggish? Waiting for them to error out. [ 1021.334393] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1025.830913] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1026.534759] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1026.537581] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1026.575112] Lustre: Skipped 3 previous similar messages [ 1026.609625] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1026.691185] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:592 to 0x2c0000401:609) [ 1026.691484] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:592 to 0x280000400:609) [ 1030.396514] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1032.480133] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1032.483329] Lustre: Skipped 1 previous similar message [ 1040.407967] Lustre: Failing over lustre-MDT0000 [ 1040.806552] Lustre: server umount lustre-MDT0000 complete [ 1041.892477] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1050.420986] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1055.060273] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1055.824550] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:592 to 0x2c0000401:641) [ 1055.826634] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:592 to 0x280000400:641) [ 1058.861574] Lustre: *** cfs_fail_loc=1505, val=0*** [ 1066.953930] Lustre: DEBUG MARKER: == sanity-lfsck test 5: LFSCK can handle IGIF object upgrading ========================================================== 14:48:34 (1786819714) [ 1069.698170] Lustre: *** cfs_fail_loc=1504, val=0*** [ 1078.272092] Lustre: Failing over lustre-MDT0000 [ 1078.694497] Lustre: server umount lustre-MDT0000 complete [ 1084.269948] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1093.890277] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1097.701584] Lustre: 16375:0:(client.c:2489:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786819731/real 1786819731] req@ffff95f967d09c00 x1873615550945408/t0(0) o400->MGC192.168.204.115@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1786819747 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1097.742805] LustreError: MGC192.168.204.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1097.769593] LustreError: Skipped 1 previous similar message [ 1105.087813] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1105.111630] Lustre: lustre-MDT0000: reset Object Index mappings [ 1107.232806] LustreError: 46093:0:(import.c:339:ptlrpc_invalidate_import()) MGS: timeout waiting for callback (1 != 0) [ 1107.241201] LustreError: 46093:0:(import.c:363:ptlrpc_invalidate_import()) @@@ still on sending list req@ffff95f97ef84700 x1873615550951040/t0(0) o250->MGC192.168.204.115@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 1786819757 ref 1 fl Rpc:NQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1107.256743] LustreError: 46093:0:(import.c:373:ptlrpc_invalidate_import()) MGS: Unregistering RPCs found (0). Network is sluggish? Waiting for them to error out. [ 1108.320939] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1108.335261] Lustre: Skipped 1 previous similar message [ 1113.101337] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1113.573701] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1113.583951] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1113.586257] Lustre: Skipped 1 previous similar message [ 1113.598307] Lustre: Skipped 7 previous similar messages [ 1113.621918] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1113.629127] Lustre: Skipped 1 previous similar message [ 1113.667746] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:681 to 0x2c0000401:705) [ 1113.668078] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:681 to 0x280000400:705) [ 1116.439205] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1116.442783] Lustre: Skipped 2 previous similar messages [ 1124.640155] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1124.642257] Lustre: Skipped 7 previous similar messages [ 1130.827030] Lustre: Failing over lustre-MDT0000 [ 1131.352195] Lustre: server umount lustre-MDT0000 complete [ 1134.048980] 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 [ 1134.050705] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1134.065400] Lustre: Skipped 10 previous similar messages [ 1134.102237] LustreError: Skipped 1 previous similar message [ 1142.124366] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1146.945040] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1147.952459] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:681 to 0x280000400:737) [ 1147.955279] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:681 to 0x2c0000401:737) [ 1150.510310] Lustre: *** cfs_fail_loc=1505, val=0*** [ 1150.517992] Lustre: Skipped 84 previous similar messages [ 1158.794719] Lustre: DEBUG MARKER: == sanity-lfsck test 6a: LFSCK resumes from last checkpoint (1) ========================================================== 14:50:06 (1786819806) [ 1166.352237] Lustre: *** cfs_fail_loc=1600, val=1*** [ 1185.578297] Lustre: DEBUG MARKER: == sanity-lfsck test 6b: LFSCK resumes from last checkpoint (2) ========================================================== 14:50:33 (1786819833) [ 1199.200210] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1199.209393] Lustre: Skipped 14 previous similar messages [ 1219.459664] Lustre: DEBUG MARKER: == sanity-lfsck test 7a: non-stopped LFSCK should auto restarts after MDS remount (1) ========================================================== 14:51:07 (1786819867) [ 1221.501203] Lustre: 29008:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 1221.506270] Lustre: 29008:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 1347 previous similar messages [ 1221.512402] Lustre: 29008:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 1221.527287] Lustre: 29008:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1348 previous similar messages [ 1221.537414] Lustre: 29008:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 1221.560950] Lustre: 29008:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1348 previous similar messages [ 1221.573377] Lustre: 29008:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 1221.582331] Lustre: 29008:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1348 previous similar messages [ 1221.590387] Lustre: 29008:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 1221.596469] Lustre: 29008:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1348 previous similar messages [ 1221.601763] Lustre: 29008:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 1221.609427] Lustre: 29008:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1348 previous similar messages [ 1235.813770] Lustre: Failing over lustre-MDT0000 [ 1238.062198] Lustre: server umount lustre-MDT0000 complete [ 1247.091586] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1247.196522] LustreError: MGC192.168.204.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1247.210951] LustreError: Skipped 1 previous similar message [ 1247.415256] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1247.420313] Lustre: Skipped 4 previous similar messages [ 1247.457608] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1247.462049] Lustre: Skipped 1 previous similar message [ 1251.569540] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1252.836604] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1252.837449] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1252.859100] Lustre: Skipped 1 previous similar message [ 1252.873458] Lustre: Skipped 7 previous similar messages [ 1252.906577] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1252.915293] Lustre: Skipped 1 previous similar message [ 1253.010971] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:854 to 0x280000400:897) [ 1253.012154] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:853 to 0x2c0000401:897) [ 1259.576541] Lustre: DEBUG MARKER: == sanity-lfsck test 7b: non-stopped LFSCK should auto restarts after MDS remount (2) ========================================================== 14:51:47 (1786819907) [ 1272.690555] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing load_modules_local [ 1290.278747] Lustre: 52999:0:(mgs_llog.c:1447:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 1309.284392] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1312.810520] Lustre: 54134:0:(mgs_llog.c:1447:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 1319.753080] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1319.754982] Lustre: Skipped 81 previous similar messages [ 1322.493479] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1323.553241] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1324.583503] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1326.624462] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1326.630081] Lustre: Skipped 1 previous similar message [ 1327.167709] Lustre: Failing over lustre-MDT0000 [ 1327.472895] Lustre: server umount lustre-MDT0000 complete [ 1329.635796] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1329.641018] LustreError: 26231:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1329.641496] LustreError: Skipped 1 previous similar message [ 1329.654426] LustreError: 26231:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 67 previous similar messages [ 1336.129889] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1340.464148] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1342.027804] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:946 to 0x2c0000401:961) [ 1342.030107] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:947 to 0x280000400:993) [ 1348.651646] Lustre: DEBUG MARKER: == sanity-lfsck test 8: LFSCK state machine ============== 14:53:16 (1786819996) [ 1352.161338] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1352.169878] Lustre: Skipped 3 previous similar messages [ 1356.613682] Lustre: server umount lustre-MDT0000 complete [ 1359.197665] LustreError: 26213:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1786820009 with bad export cookie 4693458067446016583 [ 1359.204744] LustreError: 26213:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 1359.461936] Lustre: server umount lustre-MDT0001 complete [ 1372.995683] Lustre: server umount lustre-OST0000 complete [ 1387.036373] Lustre: server umount lustre-OST0001 complete [ 1393.017598] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_hostid [ 1400.560318] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing load_modules_local [ 1443.899866] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing load_modules_local [ 1455.656677] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1456.048910] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 1456.104242] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 1456.226747] Lustre: lustre-MDT0000: new disk, initializing [ 1456.368623] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 1460.836723] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1471.806846] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1471.935619] Lustre: 59192:0:(mgs_llog.c:1447:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 1471.992450] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 1471.999775] Lustre: Skipped 1 previous similar message [ 1472.168792] Lustre: lustre-MDT0001: new disk, initializing [ 1472.270724] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 1472.284942] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 1477.338715] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1482.279706] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 1488.979689] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 1489.235430] Lustre: lustre-OST0000: new disk, initializing [ 1489.238766] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 1489.245548] Lustre: 60825:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 1491.168636] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 1491.182511] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 1491.262482] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 1495.293257] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1505.673108] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 1505.799584] Lustre: lustre-OST0001: new disk, initializing [ 1505.803507] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 1505.810031] Lustre: 61696:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 1507.530662] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 1507.537278] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 1507.622375] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 1511.773392] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1521.658522] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1525.020488] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 1535.452768] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1536.388028] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1536.392663] Lustre: Skipped 19 previous similar messages [ 1540.287877] Lustre: *** cfs_fail_loc=1601, val=2*** [ 1540.290365] Lustre: Skipped 13 previous similar messages [ 1556.463186] Lustre: Failing over lustre-MDT0000 [ 1558.818656] Lustre: server umount lustre-MDT0000 complete [ 1559.012068] 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 [ 1559.037281] Lustre: Skipped 16 previous similar messages [ 1568.344949] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1568.508438] LustreError: MGC192.168.204.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1568.526815] LustreError: Skipped 2 previous similar messages [ 1568.848303] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1568.864393] Lustre: Skipped 1 previous similar message [ 1573.049385] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1573.864810] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1573.866136] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1573.872376] Lustre: Skipped 7 previous similar messages [ 1573.888447] Lustre: Skipped 1 previous similar message [ 1573.897442] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1573.901585] Lustre: Skipped 1 previous similar message [ 1573.933645] Lustre: *** cfs_fail_loc=160b, val=2*** [ 1573.942648] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:65) [ 1573.943420] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:65) [ 1580.382983] Lustre: Failing over lustre-MDT0000 [ 1580.644072] Lustre: server umount lustre-MDT0000 complete [ 1588.969375] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1589.217431] Lustre: lustre-MDT0000: Not available for connect from 0@lo (not set up) [ 1589.225095] Lustre: Skipped 1 previous similar message [ 1594.209696] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1594.942909] Lustre: *** cfs_fail_loc=160b, val=2*** [ 1594.948560] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:97) [ 1594.949653] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:97) [ 1600.753796] Lustre: Failing over lustre-MDT0000 [ 1601.022332] Lustre: server umount lustre-MDT0000 complete [ 1605.099601] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1605.113236] LustreError: Skipped 2 previous similar messages [ 1609.400419] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1613.820932] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1614.868563] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:129) [ 1614.870235] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:129) [ 1618.456274] Lustre: *** cfs_fail_loc=1602, val=2*** [ 1630.484558] Lustre: DEBUG MARKER: == sanity-lfsck test 9a: LFSCK speed control (1) ========= 14:57:58 (1786820278) [ 1641.961580] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing load_modules_local [ 1665.623394] Lustre: 68653:0:(mgs_llog.c:1447:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 1686.689158] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1689.849109] Lustre: 69788:0:(mgs_llog.c:1447:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 1733.506348] Lustre: 65633:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 1733.514260] Lustre: 65633:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 10739 previous similar messages [ 1733.520896] Lustre: 65633:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 1733.525102] Lustre: 65633:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 10739 previous similar messages [ 1733.541922] Lustre: 59199:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 1733.547139] Lustre: 59199:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 10745 previous similar messages [ 1733.581687] Lustre: 65633:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 1733.586732] Lustre: 65633:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 10757 previous similar messages [ 1733.591068] Lustre: 65633:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 1733.594517] Lustre: 65633:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 10759 previous similar messages [ 1733.603552] Lustre: 65633:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 1733.610479] Lustre: 65633:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 10759 previous similar messages [ 1793.870184] Lustre: DEBUG MARKER: == sanity-lfsck test 9b: LFSCK speed control (2) ========= 15:00:41 (1786820441) [ 1838.653286] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1838.662427] Lustre: Skipped 4 previous similar messages [ 1859.946896] Lustre: *** cfs_fail_loc=160c, val=0*** [ 1859.948728] Lustre: Skipped 7 previous similar messages [ 1893.041404] Lustre: DEBUG MARKER: == sanity-lfsck test 10: System is available during LFSCK scanning ========================================================== 15:02:21 (1786820541) [ 1934.450443] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1942.489914] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1942.491696] Lustre: Skipped 491 previous similar messages [ 1958.498576] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1958.500404] Lustre: Skipped 971 previous similar messages [ 1990.641646] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1990.649632] Lustre: Skipped 2599 previous similar messages [ 2209.517716] Lustre: DEBUG MARKER: == sanity-lfsck test 11a: LFSCK can rebuild lost last_id ========================================================== 15:07:37 (1786820857) [ 2349.214966] Lustre: 60538:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 2349.225362] Lustre: 60538:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 28145 previous similar messages [ 2349.246747] Lustre: 60538:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 2349.260702] Lustre: 60538:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 28147 previous similar messages [ 2349.268813] Lustre: 60538:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 2349.276105] Lustre: 60538:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 28141 previous similar messages [ 2349.296064] Lustre: 60538:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 2349.316592] Lustre: 60538:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 28129 previous similar messages [ 2349.322428] Lustre: 60538:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 2349.330573] Lustre: 60538:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 28127 previous similar messages [ 2349.337832] Lustre: 60538:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 2349.345318] Lustre: 60538:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 28127 previous similar messages [ 2356.418983] Lustre: server umount lustre-MDT0000 complete [ 2357.216551] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 2357.232172] 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 [ 2357.249123] Lustre: Skipped 8 previous similar messages [ 2357.257798] LustreError: 60819:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 2357.283157] LustreError: 60819:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 27 previous similar messages [ 2360.211865] LustreError: 59184:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1786821010 with bad export cookie 4693458067446035686 [ 2360.214809] LustreError: MGC192.168.204.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2360.225652] LustreError: 59184:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 2360.255254] LustreError: Skipped 2 previous similar messages [ 2360.933853] Lustre: server umount lustre-MDT0001 complete [ 2375.492922] Lustre: server umount lustre-OST0000 complete [ 2378.721167] Lustre: 16376:0:(client.c:2489:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786821012/real 1786821012] req@ffff95f945705500 x1873615555010432/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786821028 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2379.275463] Lustre: server umount lustre-OST0001 complete [ 2386.255972] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: (null) [ 2395.587627] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 2411.232394] LustreError: Failed to get MGS log lustre-sptlrpc and no local copy. [ 2416.355273] LustreError: 74917:0:(mgc_request.c:233:do_config_log_add()) MGC192.168.204.115@tcp: failed processing log, type 4: rc = -110 [ 2442.145829] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 2442.154242] Lustre: Skipped 8 previous similar messages [ 2447.994988] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2451.306415] Lustre: 75500: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. [ 2451.317206] Lustre: *** cfs_fail_loc=160e, val=3*** [ 2454.376139] Lustre: 75500:0:(ofd_dev.c:573:ofd_lfsck_out_notify()) lustre-OST0000: Rebuilt crashed LAST_ID files successfully. [ 2462.261131] Lustre: DEBUG MARKER: == sanity-lfsck test 11b: LFSCK can rebuild crashed last_id ========================================================== 15:11:50 (1786821110) [ 2476.375534] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing load_modules_local [ 2486.232787] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2486.802535] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3271 to 0x280000401:3297) [ 2491.241855] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2498.933591] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2503.708058] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2506.434103] Lustre: 78165:0:(mgs_llog.c:1447:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 2519.760162] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2519.945285] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 2519.949197] Lustre: Skipped 2 previous similar messages [ 2524.914353] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2525.171986] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3208 to 0x2c0000401:3233) [ 2530.828485] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 2533.598226] Lustre: 79666:0:(mgs_llog.c:1447:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 2537.368830] Lustre: *** cfs_fail_loc=160d, val=0*** [ 2543.375356] Lustre: Failing over lustre-OST0000 [ 2543.561257] Lustre: server umount lustre-OST0000 complete [ 2552.816348] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2552.976344] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 2552.982235] Lustre: Skipped 2 previous similar messages [ 2554.403771] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 2554.416732] Lustre: Skipped 2 previous similar messages [ 2554.443155] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 2554.446049] Lustre: lustre-OST0000-osc-MDT0001: Connection restored to 0@lo (at 0@lo) [ 2554.446705] Lustre: *** cfs_fail_loc=215, val=0*** [ 2554.454559] Lustre: Skipped 2 previous similar messages [ 2554.482527] Lustre: Skipped 11 previous similar messages [ 2559.068408] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2559.970087] Lustre: *** cfs_fail_loc=215, val=0*** [ 2559.974269] Lustre: Skipped 2 previous similar messages [ 2562.373624] Lustre: 81066: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. [ 2562.393877] Lustre: 81066:0:(ofd_dev.c:573:ofd_lfsck_out_notify()) lustre-OST0000: Rebuilt crashed LAST_ID files successfully. [ 2564.749891] Lustre: Failing over lustre-OST0000 [ 2564.898426] Lustre: server umount lustre-OST0000 complete [ 2572.513927] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2574.263386] Lustre: *** cfs_fail_loc=215, val=0*** [ 2574.270935] Lustre: Skipped 2 previous similar messages [ 2578.190543] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2579.427617] Lustre: *** cfs_fail_loc=215, val=0*** [ 2579.432180] Lustre: Skipped 1 previous similar message [ 2586.593688] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2588.129066] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2588.134285] Lustre: Skipped 2 previous similar messages [ 2589.384239] Lustre: server umount lustre-MDT0000 complete [ 2592.598690] LustreError: 74923:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1786821242 with bad export cookie 4693458067447608453 [ 2592.613292] LustreError: 74923:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 2592.920933] Lustre: server umount lustre-MDT0001 complete [ 2606.801680] Lustre: server umount lustre-OST0000 complete [ 2609.376170] Lustre: 16378:0:(client.c:2489:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786821243/real 1786821243] req@ffff95f974ce2a00 x1873615555099904/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786821259 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2610.067502] Lustre: server umount lustre-OST0001 complete [ 2617.070924] Lustre: DEBUG MARKER: == sanity-lfsck test 12a: single command to trigger LFSCK on all devices ========================================================== 15:14:25 (1786821265) [ 2631.137410] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing load_modules_local [ 2639.933221] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2644.577243] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2653.390696] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2653.651504] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 2653.655597] Lustre: Skipped 3 previous similar messages [ 2658.116447] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2660.738483] Lustre: 85446:0:(mgs_llog.c:1447:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 2666.996780] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2672.668798] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2680.254671] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2685.621727] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3208 to 0x2c0000401:3265) [ 2685.624069] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3362 to 0x280000401:3393) [ 2686.402742] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2693.809617] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 2697.451767] Lustre: 87317:0:(mgs_llog.c:1447:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 2756.751244] Lustre: DEBUG MARKER: == sanity-lfsck test 12b: auto detect Lustre device ====== 15:16:44 (1786821404) [ 2769.225656] Lustre: DEBUG MARKER: == sanity-lfsck test 13: LFSCK can repair crashed lmm_oi ========================================================== 15:16:56 (1786821416) [ 2770.630863] Lustre: *** cfs_fail_loc=160f, val=0*** [ 2780.378534] Lustre: DEBUG MARKER: == sanity-lfsck test 14a: LFSCK can repair MDT-object with dangling LOV EA reference (1) ========================================================== 15:17:08 (1786821428) [ 2783.740056] Lustre: *** cfs_fail_loc=1610, val=0*** [ 2783.742399] Lustre: Skipped 7 previous similar messages [ 2832.357110] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2837.040562] Lustre: server umount lustre-MDT0000 complete [ 2840.309274] LustreError: 84287:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1786821490 with bad export cookie 4693458067447616923 [ 2840.318713] LustreError: 84287:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 2840.698526] Lustre: server umount lustre-MDT0001 complete [ 2854.463045] Lustre: server umount lustre-OST0000 complete [ 2868.859797] Lustre: server umount lustre-OST0001 complete [ 2883.070950] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing load_modules_local [ 2893.094023] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2897.862839] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2906.155119] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2910.473307] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2912.776538] Lustre: 93988:0:(mgs_llog.c:1447:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 2918.333121] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2918.586908] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 2918.598366] Lustre: Skipped 4 previous similar messages [ 2919.595468] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3554 to 0x280000401:3585) [ 2923.923853] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2931.177656] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:116 to 0x280000400:161) [ 2932.622802] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2938.349519] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:116 to 0x2c0000400:161) [ 2938.351801] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3317 to 0x2c0000401:3361) [ 2939.010304] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2945.419894] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 2948.392477] Lustre: 95858:0:(mgs_llog.c:1447:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 2953.957144] Lustre: DEBUG MARKER: == sanity-lfsck test 14b: LFSCK can repair MDT-object with dangling LOV EA reference (2) ========================================================== 15:20:02 (1786821602) [ 2955.801887] Lustre: 92846:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 256 < left 278, rollback = 2 [ 2955.810373] Lustre: 92846:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 1384 previous similar messages [ 2955.817059] Lustre: 92846:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 2955.823977] Lustre: 92846:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1384 previous similar messages [ 2955.830626] Lustre: 92846:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 2955.837561] Lustre: 92846:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1384 previous similar messages [ 2955.844947] Lustre: 92846:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 2955.854284] Lustre: 92846:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1384 previous similar messages [ 2955.858885] Lustre: 92846:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 2955.864313] Lustre: 92846:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1384 previous similar messages [ 2955.875633] Lustre: 92846:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 2955.881841] Lustre: 92846:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1384 previous similar messages [ 2958.551349] Lustre: *** cfs_fail_loc=1610, val=0*** [ 2958.553987] Lustre: Skipped 63 previous similar messages [ 2975.848869] Lustre: server umount lustre-MDT0000 complete [ 2978.273716] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 2978.279647] LustreError: Skipped 4 previous similar messages [ 2978.283131] 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 [ 2978.293595] Lustre: Skipped 17 previous similar messages [ 2978.297364] LustreError: 92849:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 2978.322532] LustreError: 92849:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 40 previous similar messages [ 2978.649763] LustreError: 92831:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1786821628 with bad export cookie 4693458067447645343 [ 2978.652571] LustreError: MGC192.168.204.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2978.656176] LustreError: 92831:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 3 previous similar messages [ 2978.666579] LustreError: Skipped 2 previous similar messages [ 2979.298482] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 2979.301863] Lustre: Skipped 3 previous similar messages [ 2983.339068] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 2983.353558] Lustre: Skipped 1 previous similar message [ 2985.159351] Lustre: server umount lustre-MDT0001 complete [ 2989.787681] Lustre: server umount lustre-OST0000 complete [ 2996.059301] Lustre: server umount lustre-OST0001 complete [ 3011.947577] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing load_modules_local [ 3020.112411] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3024.242886] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3031.975985] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3036.455934] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3038.899799] Lustre: 99890:0:(mgs_llog.c:1447:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3044.397826] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3045.737963] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3682 to 0x280000401:3713) [ 3050.157734] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3057.147553] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:116 to 0x280000400:193) [ 3057.884995] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3063.274521] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:116 to 0x2c0000400:193) [ 3063.279647] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3317 to 0x2c0000401:3393) [ 3063.432266] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3070.777461] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3080.415916] Lustre: DEBUG MARKER: == sanity-lfsck test 15a: LFSCK can repair unmatched MDT-object/OST-object pairs (1) ========================================================== 15:22:08 (1786821728) [ 3083.503923] Lustre: *** cfs_fail_loc=1611, val=0*** [ 3083.507758] Lustre: Skipped 63 previous similar messages [ 3083.677525] Lustre: *** cfs_fail_loc=1611, val=0*** [ 3092.407808] Lustre: DEBUG MARKER: == sanity-lfsck test 15b: LFSCK can repair unmatched MDT-object/OST-object pairs (2) ========================================================== 15:22:20 (1786821740) [ 3094.371822] Lustre: *** cfs_fail_loc=1612, val=0*** [ 3094.424659] Lustre: *** cfs_fail_loc=1612, val=0*** [ 3094.426352] Lustre: Skipped 2 previous similar messages [ 3104.411701] Lustre: DEBUG MARKER: == sanity-lfsck test 15c: LFSCK can repair unmatched MDT-object/OST-object pairs (3) ========================================================== 15:22:32 (1786821752) [ 3105.699765] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_15c MDS newer than 2.7.55, LU-6475 [ 3107.562033] Lustre: DEBUG MARKER: == sanity-lfsck test 15d: LFSCK don't crash upon dir migration failure ========================================================== 15:22:35 (1786821755) [ 3113.494440] Lustre: *** cfs_fail_loc=1709, val=0*** [ 3113.505439] LustreError: 98759:0:(mdt_reint.c:2644:mdt_reint_migrate()) lustre-MDT0000: migrate [0x240002340:0x6c:0x0]/f4 failed: rc = -5 [ 3181.025098] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3181.035847] Lustre: Skipped 3 previous similar messages [ 3186.298977] Lustre: server umount lustre-MDT0000 complete [ 3194.488682] LustreError: 98730:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1786821844 with bad export cookie 4693458067447660078 [ 3194.511846] LustreError: 98730:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 3194.925507] Lustre: server umount lustre-MDT0001 complete [ 3212.576155] Lustre: 16377:0:(client.c:2489:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786821846/real 1786821846] req@ffff95f842453800 x1873615556088320/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786821862 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3213.789220] Lustre: server umount lustre-OST0000 complete [ 3215.776145] Lustre: 16375:0:(client.c:2489:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786821849/real 1786821849] req@ffff95f851e29500 x1873615556088576/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786821865 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3220.961164] Lustre: 16375:0:(client.c:2489:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786821854/real 1786821854] req@ffff95f84aca8a80 x1873615556089216/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786821870 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3221.004300] Lustre: 16375:0:(client.c:2489:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 3222.039966] Lustre: server umount lustre-OST0001 complete [ 3238.349845] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing unload_modules_local [ 3240.867073] Key type lgssc unregistered [ 3241.155479] LNet: 105593:0:(lib-ptl.c:967:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 3241.165100] LNetError: 105593:0:(acceptor.c:246:lnet_acceptor_remove_socket()) Interface ens2 not found [ 3241.179542] LNet: Removed LNI 192.168.204.115@tcp [ 3242.092173] Key type .llcrypt unregistered [ 3242.094826] Key type ._llcrypt unregistered [ 3264.222205] Key type ._llcrypt registered [ 3264.225361] Key type .llcrypt registered [ 3264.313371] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_hostid [ 3276.669628] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing load_modules_local [ 3277.487206] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 3277.555519] alg: No test for adler32 (adler32-zlib) [ 3278.720714] Lustre: Lustre: Build Version: 2.17.54_84_gc7429ec [ 3278.946306] LNet: Added LNI 192.168.204.115@tcp [8/256/0/180] [ 3280.624197] Key type lgssc registered [ 3281.677811] Lustre: Echo OBD driver; http://www.lustre.org/ [ 3326.858895] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing load_modules_local [ 3340.095913] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 3340.134730] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3341.336697] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 3341.378199] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 3341.452160] Lustre: lustre-MDT0000: new disk, initializing [ 3341.524224] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3341.537283] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 3345.376266] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3355.638514] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3355.749469] Lustre: 110029:0:(mgs_llog.c:1447:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 3355.782326] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 3355.785809] Lustre: Skipped 1 previous similar message [ 3355.838805] Lustre: lustre-MDT0001: new disk, initializing [ 3355.889177] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 3355.906179] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 3355.920344] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 3359.777310] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3363.883935] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 3371.182613] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3371.351583] Lustre: lustre-OST0000: new disk, initializing [ 3371.354852] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 3371.359940] Lustre: 111964:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 3371.417574] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 3373.602695] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 3373.622540] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 3373.735946] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 3378.481139] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3391.097543] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3391.225700] Lustre: lustre-OST0001: new disk, initializing [ 3391.228063] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 3391.243180] Lustre: 112989:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 3391.304986] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 3397.879235] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3398.705662] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 3398.713151] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 3398.823528] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 3408.344684] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3413.958755] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 3419.797554] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 15:27:47 (1786822067) === [ 3426.405890] Lustre: DEBUG MARKER: == sanity-lfsck test 16: LFSCK can repair inconsistent MDT-object/OST-object owner ========================================================== 15:27:54 (1786822074) [ 3426.619220] Lustre: 113519:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 251 < left 278, rollback = 2 [ 3426.636692] Lustre: 113519:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 3426.644729] Lustre: 113519:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3426.653799] Lustre: 113519:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 3426.669147] Lustre: 113519:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 3426.677411] Lustre: 113519:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3427.141074] Lustre: 110035:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 3427.147955] Lustre: 110035:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 6 previous similar messages [ 3427.153132] Lustre: 110035:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 3427.157624] Lustre: 110035:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 6 previous similar messages [ 3427.162074] Lustre: 110035:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3427.165796] Lustre: 110035:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 6 previous similar messages [ 3427.170162] Lustre: 110035:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 3427.175017] Lustre: 110035:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 6 previous similar messages [ 3427.179759] Lustre: 110035:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 3427.187236] Lustre: 110035:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 6 previous similar messages [ 3427.203426] Lustre: 110035:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3427.210666] Lustre: 110035:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 6 previous similar messages [ 3428.152928] Lustre: 112858:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 3428.162328] Lustre: 112858:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 170 previous similar messages [ 3428.170675] Lustre: 112858:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 3428.179873] Lustre: 112858:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 170 previous similar messages [ 3428.188094] Lustre: 112858:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3428.195660] Lustre: 112858:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 170 previous similar messages [ 3428.201062] Lustre: 112858:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 7/369/0 [ 3428.211382] Lustre: 112858:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 170 previous similar messages [ 3428.218571] Lustre: 112858:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 3428.224774] Lustre: 112858:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 170 previous similar messages [ 3428.231248] Lustre: 112858:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3428.237183] Lustre: 112858:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 170 previous similar messages [ 3430.014066] Lustre: *** cfs_fail_loc=1613, val=0*** [ 3438.747722] Lustre: DEBUG MARKER: == sanity-lfsck test 17: LFSCK can repair multiple references ========================================================== 15:28:06 (1786822086) [ 3439.837299] Lustre: 112858:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 257 < left 278, rollback = 2 [ 3439.848264] Lustre: 112858:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 131 previous similar messages [ 3439.858287] Lustre: 112858:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 3439.869807] Lustre: 112858:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 131 previous similar messages [ 3439.885934] Lustre: 112858:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3439.898425] Lustre: 112858:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 131 previous similar messages [ 3439.902857] Lustre: 112858:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 3439.909408] Lustre: 112858:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 131 previous similar messages [ 3439.916260] Lustre: 112858:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 3439.921541] Lustre: 112858:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 131 previous similar messages [ 3439.926541] Lustre: 112858:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3439.932358] Lustre: 112858:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 131 previous similar messages [ 3441.014094] Lustre: *** cfs_fail_loc=1614, val=0*** [ 3444.877611] Lustre: 111955:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 259 < left 275, rollback = 2 [ 3444.884326] Lustre: 111955:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 11 previous similar messages [ 3444.889844] Lustre: 111955:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 3444.898835] Lustre: 111955:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3444.909977] Lustre: 111955:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/1, xattr_set: 3/275/0 [ 3444.920956] Lustre: 111955:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3444.927895] Lustre: 111955:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/9/0, punch: 1/4/0, quota 7/225/0 [ 3444.931859] Lustre: 111955:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3444.936643] Lustre: 111955:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 3444.940436] Lustre: 111955:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3444.945781] Lustre: 111955:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3444.950101] Lustre: 111955:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3451.443027] Lustre: DEBUG MARKER: == sanity-lfsck test 18a: Find out orphan OST-object and repair it (1) ========================================================== 15:28:19 (1786822099) [ 3453.115197] Lustre: 111953:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 259 < left 274, rollback = 2 [ 3453.127296] Lustre: 111953:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 19 previous similar messages [ 3453.129157] Lustre: 115078:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 3453.133532] Lustre: 111953:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/1, xattr_set: 2/274/0 [ 3453.133542] Lustre: 111953:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 19 previous similar messages [ 3453.133548] Lustre: 111953:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 0/0/0, punch: 0/0/0, quota 7/225/0 [ 3453.133551] Lustre: 111953:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 19 previous similar messages [ 3453.133556] Lustre: 111953:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 3453.133560] Lustre: 111953:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 19 previous similar messages [ 3453.133565] Lustre: 111953:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3453.133567] Lustre: 111953:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 19 previous similar messages [ 3453.216309] Lustre: 115078:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 20 previous similar messages [ 3454.257929] Lustre: *** cfs_fail_loc=1615, val=0*** [ 3454.261974] Lustre: Skipped 1 previous similar message [ 3455.319982] Lustre: *** cfs_fail_loc=1615, val=0*** [ 3455.328643] Lustre: Skipped 3 previous similar messages [ 3460.572501] LustreError: 115319:0:(lfsck_layout.c:2103:lfsck_layout_add_comp()) five: Five five five five five five file Hello [0x2c0000401:0x2:0x0] and [0x2c0000401:0x2:0x0]d: rc = 0 [ 3472.438321] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_18b skipping excluded test 18b [ 3474.332643] Lustre: DEBUG MARKER: == sanity-lfsck test 18c: Find out orphan OST-object and repair it (3) ========================================================== 15:28:41 (1786822121) [ 3474.756466] Lustre: 110036:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 3474.767324] Lustre: 110036:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 2 previous similar messages [ 3474.773177] Lustre: 110036:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 3474.790454] Lustre: 110036:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 2 previous similar messages [ 3474.802377] Lustre: 110036:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3474.810114] Lustre: 110036:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 3 previous similar messages [ 3474.820439] Lustre: 110036:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 3474.837809] Lustre: 110036:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 3 previous similar messages [ 3474.845390] Lustre: 110036:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 3474.862147] Lustre: 110036:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 3 previous similar messages [ 3474.871379] Lustre: 110036:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3474.883552] Lustre: 110036:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 3 previous similar messages [ 3476.870383] Lustre: *** cfs_fail_loc=1617, val=0*** [ 3476.968806] Lustre: *** cfs_fail_loc=1617, val=0*** [ 3479.484865] Lustre: *** cfs_fail_loc=1616, val=0*** [ 3479.486746] Lustre: Skipped 1 previous similar message [ 3498.493957] Lustre: DEBUG MARKER: == sanity-lfsck test 18d: Find out orphan OST-object and repair it (4) ========================================================== 15:29:06 (1786822146) [ 3500.834865] Lustre: *** cfs_fail_loc=1618, val=0*** [ 3500.837583] Lustre: Skipped 5 previous similar messages [ 3535.329231] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3535.339609] 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 [ 3535.366209] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3537.377626] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3537.378512] 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 [ 3540.516973] Lustre: server umount lustre-MDT0000 complete [ 3542.506193] LustreError: 110035:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3542.529936] LustreError: 110035:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 5 previous similar messages [ 3544.483744] LustreError: 110022:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1786822194 with bad export cookie 11530033675874255895 [ 3544.488084] LustreError: MGC192.168.204.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3544.503957] LustreError: 110022:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 3544.937463] Lustre: server umount lustre-MDT0001 complete [ 3559.818453] Lustre: server umount lustre-OST0000 complete [ 3573.336251] Lustre: server umount lustre-OST0001 complete [ 3591.296105] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing load_modules_local [ 3602.398765] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3602.760374] LustreError: 118726:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3602.826577] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3607.417225] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3608.034700] LustreError: 118727:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3612.132151] LustreError: 118726:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3615.349579] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3615.646700] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 3620.039293] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3622.937939] Lustre: 119865:0:(mgs_llog.c:1447:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3630.223447] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3637.481889] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3640.872940] LustreError: 120219:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3640.880257] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:4 to 0x280000400:33) [ 3646.569899] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3646.892903] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 3646.905743] Lustre: Skipped 1 previous similar message [ 3647.940424] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:116 to 0x280000401:161) [ 3647.958337] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:33) [ 3647.965364] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:4 to 0x2c0000401:33) [ 3652.986315] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3660.460055] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3663.997888] Lustre: 121739:0:(mgs_llog.c:1447:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 3677.270838] Lustre: DEBUG MARKER: == sanity-lfsck test 18e: Find out orphan OST-object and repair it (5) ========================================================== 15:32:05 (1786822325) [ 3677.594704] Lustre: 118721:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 252 < left 278, rollback = 2 [ 3677.603858] Lustre: 118721:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 46 previous similar messages [ 3677.609224] Lustre: 118721:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 3677.616601] Lustre: 118721:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 3677.628770] Lustre: 118721:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3677.638155] Lustre: 118721:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 3677.648094] Lustre: 118721:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/1 [ 3677.657714] Lustre: 118721:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 3677.666594] Lustre: 118721:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 3677.677175] Lustre: 118721:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 3677.685521] Lustre: 118721:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3677.691445] Lustre: 118721:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 3679.224492] Lustre: *** cfs_fail_loc=1618, val=0*** [ 3679.227670] Lustre: Skipped 3 previous similar messages [ 3712.994607] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3713.005589] 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 [ 3713.016765] Lustre: Skipped 2 previous similar messages [ 3713.024303] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3713.026935] Lustre: Skipped 3 previous similar messages [ 3718.415061] Lustre: server umount lustre-MDT0000 complete [ 3719.649965] LustreError: 118722:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3719.673147] LustreError: 118722:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 4 previous similar messages [ 3721.938083] LustreError: 118708:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1786822371 with bad export cookie 11530033675874271141 [ 3721.948211] LustreError: MGC192.168.204.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3721.961804] LustreError: 118708:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 3722.376585] Lustre: server umount lustre-MDT0001 complete [ 3736.502550] Lustre: server umount lustre-OST0000 complete [ 3750.600883] Lustre: server umount lustre-OST0001 complete [ 3765.802794] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing load_modules_local [ 3774.840041] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3775.324612] LustreError: 124305:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3775.467372] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3779.283413] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3786.086873] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3790.469163] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3793.061932] Lustre: 125446:0:(mgs_llog.c:1447:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3799.041968] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3800.427845] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:166 to 0x280000401:193) [ 3805.045402] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3810.786831] LustreError: 125799:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3810.801658] LustreError: 125799:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 4 previous similar messages [ 3811.841586] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:4 to 0x280000400:65) [ 3813.018839] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3818.344602] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3818.490835] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:65) [ 3818.505131] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:4 to 0x2c0000401:65) [ 3827.631543] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3832.416898] Lustre: 127316:0:(mgs_llog.c:1447:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 3838.898306] Lustre: 126911:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 252 < left 260, rollback = 2 [ 3838.909290] Lustre: 126911:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 21 previous similar messages [ 3838.920631] Lustre: 126911:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 3838.926307] Lustre: 126911:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3838.934371] Lustre: 126911:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 0/0/0, xattr_set: 1/260/0 [ 3838.942541] Lustre: 126911:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3838.949324] Lustre: 126911:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/9/0, punch: 0/0/0, quota 4/150/2 [ 3838.952880] Lustre: 126911:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3838.958986] Lustre: 126911:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 1/17/2, delete: 0/0/0 [ 3838.967446] Lustre: 126911:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3838.977638] Lustre: 126911:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3838.989789] Lustre: 126911:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 3839.055815] Lustre: *** cfs_fail_loc=1602, val=10*** [ 3863.539742] Lustre: DEBUG MARKER: == sanity-lfsck test 18f: Skip the failed OST(s) when handle orphan OST-objects ========================================================== 15:35:11 (1786822511) [ 3866.157803] Lustre: *** cfs_fail_loc=1616, val=0*** [ 3866.162833] Lustre: Skipped 3 previous similar messages [ 3872.152399] Lustre: *** cfs_fail_loc=161c, val=0*** [ 3890.794391] Lustre: DEBUG MARKER: == sanity-lfsck test 18g: Find out orphan OST-object and repair it (7) ========================================================== 15:35:38 (1786822538) [ 3893.230655] Lustre: *** cfs_fail_loc=162e, val=0*** [ 3905.150900] Lustre: DEBUG MARKER: == sanity-lfsck test 18h: LFSCK can repair crashed PFL extent range ========================================================== 15:35:53 (1786822553) [ 3908.843451] Lustre: *** cfs_fail_loc=162f, val=0*** [ 3908.849639] Lustre: Skipped 9 previous similar messages [ 3910.731781] LustreError: 130303:0:(lfsck_layout.c:2103:lfsck_layout_add_comp()) five: Five five five five five five file Hello [0x280000401:0xc6:0x0] and [0x280000401:0xc6:0x0]d: rc = 0 [ 3923.731307] Lustre: DEBUG MARKER: == sanity-lfsck test 19a: OST-object inconsistency self detect ========================================================== 15:36:11 (1786822571) [ 3935.151816] Lustre: DEBUG MARKER: == sanity-lfsck test 19b: OST-object inconsistency self repair ========================================================== 15:36:23 (1786822583) [ 3937.989913] Lustre: *** cfs_fail_loc=1611, val=0*** [ 3938.041117] Lustre: *** cfs_fail_loc=1611, val=0*** [ 3938.048468] Lustre: Skipped 3 previous similar messages [ 3943.168524] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.204.15@tcp inode [0x2000013a1:0x1f:0x0] object 0x280000401:203 extent [0-4095], client returned csum 0 (type 4), server csum 703fb3ad (type 4) [ 3944.254376] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.204.15@tcp inode [0x2000013a1:0x20:0x0] object 0x280000401:204 extent [0-4095], client returned csum 0 (type 4), server csum 7cbb935c (type 4) [ 3951.135776] Lustre: DEBUG MARKER: == sanity-lfsck test 20a: Handle the orphan with dummy LOV EA slot properly ========================================================== 15:36:39 (1786822599) [ 3970.472611] Lustre: 131841:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 253 < left 263, rollback = 2 [ 3970.494483] Lustre: 131841:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 125 previous similar messages [ 3970.502910] Lustre: 131841:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 3970.509014] Lustre: 131841:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 125 previous similar messages [ 3970.519852] Lustre: 131841:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 0/0/0, xattr_set: 2/263/0 [ 3970.528592] Lustre: 131841:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 125 previous similar messages [ 3970.538767] Lustre: 131841:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 0/0/0, punch: 0/0/0, quota 1/3/2 [ 3970.551379] Lustre: 131841:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 125 previous similar messages [ 3970.560693] Lustre: 131841:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/1, delete: 0/0/0 [ 3970.573512] Lustre: 131841:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 125 previous similar messages [ 3970.583735] Lustre: 131841:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3970.596305] Lustre: 131841:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 125 previous similar messages [ 3982.863809] Lustre: DEBUG MARKER: == sanity-lfsck test 20b: Handle the orphan with dummy LOV EA slot properly - PFL case ========================================================== 15:37:10 (1786822630) [ 3988.348742] Lustre: DEBUG MARKER: == sanity-lfsck test 21: run all LFSCK components by default ========================================================== 15:37:16 (1786822636) [ 3998.845280] Lustre: DEBUG MARKER: == sanity-lfsck test 22a: LFSCK can repair unmatched pairs (1) ========================================================== 15:37:26 (1786822646) [ 4001.031521] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4001.047921] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4001.053253] Lustre: Skipped 1 previous similar message [ 4011.855955] Lustre: DEBUG MARKER: == sanity-lfsck test 22b: LFSCK can repair unmatched pairs (2) ========================================================== 15:37:39 (1786822659) [ 4013.687955] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4013.695372] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4024.003637] Lustre: DEBUG MARKER: == sanity-lfsck test 23a: LFSCK can repair dangling name entry (1) ========================================================== 15:37:52 (1786822672) [ 4025.761681] Lustre: *** cfs_fail_loc=1620, val=0*** [ 4041.181902] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_23b skipping excluded test 23b [ 4043.043230] Lustre: DEBUG MARKER: == sanity-lfsck test 23c: LFSCK can repair dangling name entry (3) ========================================================== 15:38:10 (1786822690) [ 4048.739750] Lustre: *** cfs_fail_loc=1621, val=127*** [ 4048.743740] Lustre: Skipped 1 previous similar message [ 4051.820458] Lustre: *** cfs_fail_loc=1602, val=10*** [ 4072.456050] Lustre: DEBUG MARKER: == sanity-lfsck test 23d: LFSCK can repair a dangling name entry to a remote object ========================================================== 15:38:40 (1786822720) [ 4074.821747] Lustre: Failing over lustre-MDT0000 [ 4075.229803] Lustre: server umount lustre-MDT0000 complete [ 4076.074249] LustreError: 124301:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.204.15@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4076.086306] LustreError: 124301:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 2 previous similar messages [ 4078.565327] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4078.573358] 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 [ 4078.596198] Lustre: Skipped 3 previous similar messages [ 4084.979950] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4085.084731] LustreError: MGC192.168.204.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4085.266822] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4085.277962] Lustre: Skipped 3 previous similar messages [ 4085.319306] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4087.802331] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4088.851133] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4090.339331] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4090.350532] Lustre: lustre-MDT0000: Recovery over after 0:03, of 2 clients 2 recovered and 0 were evicted. [ 4090.378374] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:265 to 0x280000401:289) [ 4090.378523] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:130 to 0x2c0000401:161) [ 4090.493727] LustreError: 126189:0:(mdt_open.c:1324:mdt_cross_open()) lustre-MDT0000: [0x2000013a3:0x82:0x0] doesn't exist!: rc = -14 [ 4098.849705] Lustre: DEBUG MARKER: == sanity-lfsck test 24: LFSCK can repair multiple-referenced name entry ========================================================== 15:39:06 (1786822746) [ 4101.084105] Lustre: *** cfs_fail_loc=1622, val=0*** [ 4101.180459] Lustre: *** cfs_fail_loc=1622, val=0*** [ 4101.188658] Lustre: Skipped 1 previous similar message [ 4111.369667] Lustre: DEBUG MARKER: == sanity-lfsck test 25: LFSCK can repair bad file type in the name entry ========================================================== 15:39:19 (1786822759) [ 4113.159588] Lustre: *** cfs_fail_loc=1623, val=0*** [ 4123.648360] Lustre: DEBUG MARKER: == sanity-lfsck test 26a: LFSCK can add the missing local name entry back to the namespace ========================================================== 15:39:31 (1786822771) [ 4124.873079] Lustre: *** cfs_fail_loc=1624, val=0*** [ 4135.170894] Lustre: DEBUG MARKER: == sanity-lfsck test 26b: LFSCK can add the missing remote name entry back to the namespace ========================================================== 15:39:43 (1786822783) [ 4146.100801] Lustre: DEBUG MARKER: == sanity-lfsck test 27a: LFSCK can recreate the lost local parent directory as orphan ========================================================== 15:39:54 (1786822794) [ 4147.403565] Lustre: *** cfs_fail_loc=1624, val=0*** [ 4147.411683] Lustre: Skipped 1 previous similar message [ 4156.616574] Lustre: DEBUG MARKER: == sanity-lfsck test 27b: LFSCK can recreate the lost remote parent directory as orphan ========================================================== 15:40:04 (1786822804) [ 4168.468905] Lustre: DEBUG MARKER: == sanity-lfsck test 28: Skip the failed MDT(s) when handle orphan MDT-objects ========================================================== 15:40:16 (1786822816) [ 4174.145631] Lustre: *** cfs_fail_loc=161c, val=0*** [ 4174.148958] Lustre: Skipped 1 previous similar message [ 4188.649561] Lustre: DEBUG MARKER: == sanity-lfsck test 29b: LFSCK can repair bad nlink count (2) ========================================================== 15:40:36 (1786822836) [ 4190.878244] Lustre: *** cfs_fail_loc=1626, val=0*** [ 4190.883399] Lustre: Skipped 4 previous similar messages [ 4202.211325] Lustre: DEBUG MARKER: == sanity-lfsck test 29c: verify linkEA size limitation == 15:40:49 (1786822849) [ 4231.170975] Lustre: DEBUG MARKER: == sanity-lfsck test 29d: accessing non-existing inode shouldn't turn fs read-only (ldiskfs) ========================================================== 15:41:18 (1786822878) [ 4231.509803] Lustre: 139005:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 4231.518612] Lustre: 139005:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 754 previous similar messages [ 4231.530717] Lustre: 139005:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 4231.542891] Lustre: 139005:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 754 previous similar messages [ 4231.558478] Lustre: 139005:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4231.577356] Lustre: 139005:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 754 previous similar messages [ 4231.590492] Lustre: 139005:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 4231.601607] Lustre: 139005:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 754 previous similar messages [ 4231.615404] Lustre: 139005:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 4231.627461] Lustre: 139005:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 754 previous similar messages [ 4231.643291] Lustre: 139005:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4231.654819] Lustre: 139005:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 754 previous similar messages [ 4233.973595] LustreError: 139005:0:(osd_handler.c:284:osd_idc_find_or_init()) lustre-MDT0000: cannot lookup FID [0x2000013a3:0x9e:0x0]: rc = -2 [ 4239.904287] Lustre: DEBUG MARKER: == sanity-lfsck test 30: LFSCK can recover the orphans from backend /lost+found ========================================================== 15:41:27 (1786822887) [ 4264.597377] Lustre: Failing over lustre-MDT0000 [ 4264.858398] Lustre: server umount lustre-MDT0000 complete [ 4269.536850] 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 [ 4269.539066] LustreError: 126189:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4269.547443] Lustre: Skipped 5 previous similar messages [ 4269.547698] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4269.576990] LustreError: 126189:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 14 previous similar messages [ 4273.624620] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 4273.726576] LustreError: MGC192.168.204.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4273.932393] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4273.984410] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4277.549827] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4279.267396] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4279.293032] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 4279.300491] Lustre: Skipped 3 previous similar messages [ 4279.311121] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4279.361689] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:294 to 0x280000401:321) [ 4279.365418] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:167 to 0x2c0000401:193) [ 4288.529908] Lustre: DEBUG MARKER: == sanity-lfsck test 31a: The LFSCK can find/repair the name entry with bad name hash (1) ========================================================== 15:42:16 (1786822936) [ 4300.544205] Lustre: DEBUG MARKER: == sanity-lfsck test 31b: The LFSCK can find/repair the name entry with bad name hash (2) ========================================================== 15:42:28 (1786822948) [ 4315.778159] Lustre: DEBUG MARKER: == sanity-lfsck test 31c: Re-generate the lost master LMV EA for striped directory ========================================================== 15:42:43 (1786822963) [ 4317.551739] Lustre: *** cfs_fail_loc=1629, val=0*** [ 4317.554381] Lustre: Skipped 7 previous similar messages [ 4330.329731] Lustre: DEBUG MARKER: == sanity-lfsck test 31d: Set broken striped directory (modified after broken) as read-only ========================================================== 15:42:58 (1786822978) [ 4336.342984] Lustre: Failing over lustre-MDT0000 [ 4336.620085] Lustre: server umount lustre-MDT0000 complete [ 4340.706327] 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 [ 4340.725466] Lustre: Skipped 1 previous similar message [ 4344.864644] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4345.014626] LustreError: MGC192.168.204.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4345.356356] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4349.404362] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4350.438973] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4350.440520] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4350.445794] Lustre: Skipped 3 previous similar messages [ 4350.473608] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4350.524051] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:167 to 0x2c0000401:225) [ 4350.524922] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:294 to 0x280000401:353) [ 4357.611470] Lustre: Failing over lustre-MDT0000 [ 4357.925175] Lustre: server umount lustre-MDT0000 complete [ 4360.674242] 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 [ 4360.675793] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4360.688302] Lustre: Skipped 4 previous similar messages [ 4365.391607] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4365.463700] LustreError: MGC192.168.204.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4365.668708] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4366.845039] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4369.670067] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4370.923898] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4370.932676] Lustre: Skipped 3 previous similar messages [ 4370.978241] Lustre: lustre-MDT0000: Recovery over after 0:04, of 2 clients 2 recovered and 0 were evicted. [ 4371.004147] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:227 to 0x2c0000401:257) [ 4371.004341] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:294 to 0x280000401:385) [ 4377.945142] Lustre: DEBUG MARKER: == sanity-lfsck test 31e: Re-generate the lost slave LMV EA for striped directory (1) ========================================================== 15:43:45 (1786823025) [ 4388.718763] Lustre: DEBUG MARKER: == sanity-lfsck test 31f: Re-generate the lost slave LMV EA for striped directory (2) ========================================================== 15:43:56 (1786823036) [ 4399.310488] Lustre: DEBUG MARKER: == sanity-lfsck test 31g: Repair the corrupted slave LMV EA ========================================================== 15:44:07 (1786823047) [ 4437.793746] Lustre: DEBUG MARKER: == sanity-lfsck test 31h: Repair the corrupted shard's name entry ========================================================== 15:44:45 (1786823085) [ 4452.652471] Lustre: DEBUG MARKER: == sanity-lfsck test 32a: stop LFSCK when some OST failed ========================================================== 15:44:59 (1786823099) [ 4463.180335] LustreError: 148718:0:(lfsck_layout.c:4532:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d sleeping for 3000ms [ 4465.948582] Lustre: Failing over lustre-OST0000 [ 4466.182941] Lustre: server umount lustre-OST0000 complete [ 4466.245590] LustreError: 148718:0:(lfsck_layout.c:4532:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d awake [ 4466.262696] LustreError: 148718:0:(lfsck_layout.c:4532:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d sleeping for 3000ms [ 4467.171066] LustreError: lustre-OST0000-osc-MDT0001: operation ost_statfs to node 0@lo failed: rc = -107 [ 4467.188916] 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 [ 4468.792325] LustreError: 148718:0:(lfsck_layout.c:4532:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout interrupted [ 4480.946609] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 4481.180782] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 4482.419358] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4482.462078] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 4482.462505] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 4482.509442] Lustre: Skipped 3 previous similar messages [ 4488.693497] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4498.037639] Lustre: DEBUG MARKER: == sanity-lfsck test 32b: stop LFSCK when some MDT failed ========================================================== 15:45:45 (1786823145) [ 4510.704844] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing load_modules_local [ 4528.386630] Lustre: 151521:0:(mgs_llog.c:1447:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 4551.634952] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4555.266348] Lustre: 152655:0:(mgs_llog.c:1447:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 4566.090582] LustreError: 152777:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d sleeping for 3000ms [ 4569.172295] LustreError: 152777:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d awake [ 4569.192515] LustreError: 152776:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d sleeping for 3000ms [ 4569.195911] LustreError: 152777:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) Skipped 1 previous similar message [ 4569.243452] LustreError: 152776:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) Skipped 2 previous similar messages [ 4569.518613] Lustre: Failing over lustre-MDT0001 [ 4570.594757] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 4570.614960] 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 [ 4570.659151] Lustre: Skipped 1 previous similar message [ 4570.679840] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 4570.692038] Lustre: Skipped 4 previous similar messages [ 4572.257138] LustreError: 152777:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d awake [ 4572.568669] Lustre: server umount lustre-MDT0001 complete [ 4573.665782] LustreError: 125810:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4573.689424] LustreError: 125810:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 18 previous similar messages [ 4587.438869] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 4587.894028] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 4587.896190] Lustre: Skipped 3 previous similar messages [ 4587.936513] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 4592.704722] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4593.125165] Lustre: lustre-MDT0001-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 4593.126489] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4593.138566] Lustre: Skipped 1 previous similar message [ 4593.171103] Lustre: lustre-MDT0001: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4593.247392] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:69 to 0x2c0000400:97) [ 4593.252237] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:70 to 0x280000400:97) [ 4600.730955] Lustre: DEBUG MARKER: == sanity-lfsck test 33: check LFSCK paramters =========== 15:47:28 (1786823248) [ 4615.332945] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing load_modules_local [ 4632.089345] Lustre: 155498:0:(mgs_llog.c:1447:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 4653.082894] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4656.848663] Lustre: 156632:0:(mgs_llog.c:1447:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 4677.011243] Lustre: DEBUG MARKER: == sanity-lfsck test 34: LFSCK can rebuild the lost agent object ========================================================== 15:48:44 (1786823324) [ 4679.139243] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_34 Only valid for ZFS backend [ 4681.446247] Lustre: DEBUG MARKER: == sanity-lfsck test 35: LFSCK can rebuild the lost agent entry ========================================================== 15:48:48 (1786823328) [ 4689.308978] Lustre: *** cfs_fail_loc=1631, val=0*** [ 4705.762278] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4705.764518] 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 [ 4705.775177] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4705.817397] Lustre: Skipped 5 previous similar messages [ 4707.095571] Lustre: server umount lustre-MDT0000 complete [ 4710.751562] LustreError: 140976:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1786823360 with bad export cookie 11530033675874343948 [ 4710.755440] LustreError: MGC192.168.204.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4710.769179] LustreError: 140976:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 4710.881480] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 4710.889211] Lustre: Skipped 4 previous similar messages [ 4711.299794] Lustre: server umount lustre-MDT0001 complete [ 4717.468412] Lustre: server umount lustre-OST0000 complete [ 4721.419595] Lustre: server umount lustre-OST0001 complete [ 4739.547118] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing load_modules_local [ 4749.606487] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4754.705213] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4762.567653] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4767.208118] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4770.404081] Lustre: 160528:0:(mgs_llog.c:1447:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 4777.170898] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4783.449687] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4787.706188] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:70 to 0x280000400:129) [ 4791.469121] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4794.730359] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:540 to 0x280000401:577) [ 4794.751618] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:412 to 0x2c0000401:449) [ 4794.785469] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:69 to 0x2c0000400:129) [ 4797.785478] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4805.418723] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4810.315097] Lustre: 162399:0:(mgs_llog.c:1447:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 4820.377027] Lustre: DEBUG MARKER: == sanity-lfsck test 36a: rebuild LOV EA for mirrored file (1) ========================================================== 15:51:08 (1786823468) [ 4821.766522] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36a needs >= 3 OSTs [ 4823.585244] Lustre: DEBUG MARKER: == sanity-lfsck test 36b: rebuild LOV EA for mirrored file (2) ========================================================== 15:51:11 (1786823471) [ 4825.341663] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36b needs >= 3 OSTs [ 4827.248398] Lustre: DEBUG MARKER: == sanity-lfsck test 36c: rebuild LOV EA for mirrored file (3) ========================================================== 15:51:14 (1786823474) [ 4829.160662] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36c needs >= 3 OSTs [ 4830.997484] Lustre: DEBUG MARKER: == sanity-lfsck test 37: LFSCK must skip a ORPHAN ======== 15:51:18 (1786823478) [ 4832.460959] Lustre: 159382:0:(osd_internal.h:1461:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 4832.482103] Lustre: 159382:0:(osd_internal.h:1461:osd_trans_exec_op()) Skipped 1674 previous similar messages [ 4832.493253] Lustre: 159382:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 4832.499516] Lustre: 159382:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1674 previous similar messages [ 4832.514033] Lustre: 159382:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4832.522153] Lustre: 159382:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1674 previous similar messages [ 4832.527891] Lustre: 159382:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 4832.538915] Lustre: 159382:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1674 previous similar messages [ 4832.545574] Lustre: 159382:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 4832.552170] Lustre: 159382:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1674 previous similar messages [ 4832.559070] Lustre: 159382:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4832.567775] Lustre: 159382:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1674 previous similar messages [ 4843.303716] Lustre: DEBUG MARKER: == sanity-lfsck test 38: LFSCK does not break foreign file and reverse is also true ========================================================== 15:51:31 (1786823491) [ 4858.076405] Lustre: DEBUG MARKER: == sanity-lfsck test 39: LFSCK does not break foreign dir and reverse is also true ========================================================== 15:51:45 (1786823505) [ 4874.120264] Lustre: DEBUG MARKER: == sanity-lfsck test 40a: LFSCK correctly fixes lmm_oi in composite layout ========================================================== 15:52:01 (1786823521) [ 4891.447893] Lustre: DEBUG MARKER: == sanity-lfsck test 41: SEL support in LFSCK ============ 15:52:19 (1786823539) [ 4912.892781] Lustre: DEBUG MARKER: == sanity-lfsck test 42: LFSCK repairs inconsistent MDT-object/OST-object encryption flags ========================================================== 15:52:40 (1786823560) [ 4946.841565] Lustre: *** cfs_fail_loc=1632, val=0*** [ 4962.761135] Lustre: DEBUG MARKER: == sanity-lfsck test 43: LFSCK does not loop endlessly on iget failure in scanning-phase1 ========================================================== 15:53:30 (1786823610) [ 4966.243248] Lustre: Failing over lustre-MDT0001 [ 4966.680149] Lustre: server umount lustre-MDT0001 complete [ 4967.918324] LustreError: lustre-MDT0001-osp-MDT0000: operation mds_statfs to node 0@lo failed: rc = -107 [ 4967.928948] 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 [ 4967.941920] Lustre: Skipped 2 previous similar messages [ 4974.968727] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4975.514122] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 4975.517076] Lustre: lustre-MDT0001: Aborting client recovery [ 4975.522600] LustreError: 166192:0:(ldlm_lib.c:2990:target_stop_recovery_thread()) lustre-MDT0001: Aborting recovery [ 4975.526322] Lustre: 166215:0:(ldlm_lib.c:2390:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 4975.532734] Lustre: 166215:0:(genops.c:1622:class_disconnect_stale_exports()) lustre-MDT0001: disconnect stale client 1c281fbc-0d6e-4e81-a2b4-65cf59dcf8bd@ [ 4975.539544] Lustre: lustre-MDT0001: disconnecting 2 stale clients [ 4975.549547] Lustre: lustre-MDT0001-osd: cancel update llog [0x240000400:0x1:0x0] [ 4975.562948] Lustre: lustre-MDT0000-osp-MDT0001: cancel update llog [0x200000401:0x1:0x0] [ 4975.604487] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:131 to 0x2c0000400:161) [ 4975.610444] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:70 to 0x280000400:161) [ 4980.705045] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4980.716351] Lustre: lustre-MDT0001-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 4980.721351] Lustre: Skipped 2 previous similar messages [ 4980.729142] LustreError: lustre-MDT0001-osp-MDT0000: This client was evicted by lustre-MDT0001; in progress operations using this service will fail. [ 4989.309581] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing wait_import_state FULL osp.lustre-MDT0001-os[pc]-MDT0000.*_server_uuid [ 4989.611686] Lustre: DEBUG MARKER: osp.lustre-MDT0001-os[pc]-MDT0000.*_server_uuid in FULL state after 0 sec [ 4996.300065] Lustre: DEBUG MARKER: == sanity-lfsck test 44: umount while lfsck is stopping == 15:54:04 (1786823644) [ 5004.950870] Lustre: *** cfs_fail_loc=1600, val=3*** [ 5007.870677] Lustre: Failing over lustre-MDT0000 [ 5008.265271] Lustre: server umount lustre-MDT0000 complete [ 5017.344280] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5017.468950] LustreError: MGC192.168.204.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5017.748457] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 5017.757628] Lustre: Skipped 2 previous similar messages [ 5020.678179] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 5022.301308] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5023.215284] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 5023.222825] Lustre: Skipped 2 previous similar messages [ 5023.268566] Lustre: lustre-MDT0000: Recovery over after 0:03, of 2 clients 2 recovered and 0 were evicted. [ 5023.299837] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:489 to 0x2c0000401:513) [ 5023.301261] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:621 to 0x280000401:641) [ 5031.588116] Lustre: DEBUG MARKER: == sanity-lfsck test 45: LFSCK should fix UID/GID/PROJID of OST object ========================================================== 15:54:39 (1786823679) [ 5058.616162] Lustre: Failing over lustre-OST0000 [ 5058.738249] Lustre: server umount lustre-OST0000 complete [ 5065.742064] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: (null) [ 5076.849598] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5078.375927] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 5078.461527] Lustre: lustre-OST0000: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [ 5083.703619] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5090.609576] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing wait_import_state FULL os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid 50 [ 5090.765333] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid in FULL state after 0 sec [ 5096.511553] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing wait_import_state FULL os[cp].lustre-OST0000-osc-MDT0001.ost_server_uuid 50 [ 5096.851486] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0001.ost_server_uuid in FULL state after 0 sec [ 5103.986181] Lustre: DEBUG MARKER: oleg415-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff8b512e697800.ost_server_uuid 50 [ 5105.692732] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff8b512e697800.ost_server_uuid in FULL state after 0 sec [ 5158.895297] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5163.349420] Lustre: server umount lustre-MDT0000 complete [ 5164.000895] LustreError: 168769:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 5164.019396] LustreError: 168769:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 42 previous similar messages [ 5171.179054] LustreError: 160132:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1786823821 with bad export cookie 11530033675874426821 [ 5171.186431] LustreError: MGC192.168.204.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5171.187596] LustreError: 160132:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 5171.536480] Lustre: server umount lustre-MDT0001 complete [ 5188.576270] Lustre: 107190:0:(client.c:2489:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786823822/real 1786823822] req@ffff95f9671edc00 x1873618591994240/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786823838 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5190.898531] Lustre: server umount lustre-OST0000 complete [ 5192.673926] Lustre: 107187:0:(client.c:2489:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786823826/real 1786823826] req@ffff95f84fdb3480 x1873618591994624/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786823842 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5197.800752] Lustre: 107188:0:(client.c:2489:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786823831/real 1786823831] req@ffff95f84f4d9180 x1873618591995392/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786823847 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5197.837101] Lustre: 107188:0:(client.c:2489:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 5199.997664] Lustre: server umount lustre-OST0001 complete [ 5217.225309] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing unload_modules_local [ 5220.513554] Key type lgssc unregistered [ 5220.851966] LNet: 175321:0:(lib-ptl.c:967:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 5220.861673] LNetError: 175321:0:(acceptor.c:246:lnet_acceptor_remove_socket()) Interface ens2 not found [ 5220.884095] LNet: Removed LNI 192.168.204.115@tcp [ 5221.609162] Key type .llcrypt unregistered [ 5221.611665] Key type ._llcrypt unregistered [ 5246.706223] Key type ._llcrypt registered [ 5246.710915] Key type .llcrypt registered [ 5246.870055] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_hostid [ 5262.897571] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing load_modules_local [ 5264.241624] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 5264.315504] alg: No test for adler32 (adler32-zlib) [ 5265.356756] Lustre: Lustre: Build Version: 2.17.54_84_gc7429ec [ 5265.675945] LNet: Added LNI 192.168.204.115@tcp [8/256/0/180] [ 5267.434990] Key type lgssc registered [ 5268.722922] Lustre: Echo OBD driver; http://www.lustre.org/ [ 5318.402698] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing load_modules_local [ 5332.691358] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 5332.730358] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5334.192540] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 5334.230685] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 5334.352566] Lustre: lustre-MDT0000: new disk, initializing [ 5334.456546] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 5334.485243] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 5338.250844] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5351.669454] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5351.865449] Lustre: 179777:0:(mgs_llog.c:1447:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 5351.920798] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 5351.936991] Lustre: Skipped 1 previous similar message [ 5352.172340] Lustre: lustre-MDT0001: new disk, initializing [ 5352.360104] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 5352.418924] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 5352.444714] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 5357.803717] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5362.887150] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 5372.737075] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5372.924414] Lustre: lustre-OST0000: new disk, initializing [ 5372.928991] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 5372.935833] Lustre: 181715:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 5373.000312] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 5380.299158] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5382.726507] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 5382.738302] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 5382.776053] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 5395.148191] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5395.353810] Lustre: lustre-OST0001: new disk, initializing [ 5395.360497] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 5395.386199] Lustre: 182739:0:(osd_compat.c:1352:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 5395.529830] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 5402.143948] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 5402.158253] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 5402.249800] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 5403.618160] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5415.299905] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5424.501510] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 5430.761654] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 16:01:18 (1786824078) === [ 5432.395569] Lustre: DEBUG MARKER: == sanity-lfsck test complete, duration 5178 sec ========= 16:01:20 (1786824080) [ 5434.445630] Lustre: DEBUG MARKER: === sanity-lfsck: start cleanup 16:01:22 (1786824082) === [ 5438.640209] Lustre: DEBUG MARKER: === sanity-lfsck: finish cleanup 16:01:26 (1786824086) === [ 5444.581668] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 5444.590970] 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 [ 5444.616062] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5448.161561] 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 [ 5448.162822] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5448.178815] Lustre: Skipped 1 previous similar message [ 5448.181689] Lustre: Skipped 1 previous similar message [ 5449.896410] Lustre: server umount lustre-MDT0000 complete [ 5457.646309] LustreError: 179768:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1786824107 with bad export cookie 12253116863969214023 [ 5457.647397] LustreError: MGC192.168.204.115@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5457.653356] LustreError: 179768:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 3 previous similar messages [ 5457.921079] Lustre: server umount lustre-MDT0001 complete [ 5474.592361] Lustre: 176939:0:(client.c:2489:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786824108/real 1786824108] req@ffff95f947279880 x1873620673581568/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786824124 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5474.645139] 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 [ 5474.666825] Lustre: Skipped 1 previous similar message [ 5478.753926] Lustre: 176940:0:(client.c:2489:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786824112/real 1786824112] req@ffff95f94727b100 x1873620673581824/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786824128 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5479.090893] Lustre: server umount lustre-OST0000 complete [ 5479.915229] Lustre: 176938:0:(client.c:2489:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786824113/real 1786824113] req@ffff95f94694ed80 x1873620673582080/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786824129 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5483.936104] Lustre: 176940:0:(client.c:2489:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786824117/real 1786824117] req@ffff95f947278700 x1873620673582464/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786824133 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5488.106502] Lustre: 176941:0:(client.c:2489:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1786824122/real 1786824122] req@ffff95f94727ad80 x1873620673582976/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1786824138 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5488.169819] Lustre: 176941:0:(client.c:2489:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 5488.594533] Lustre: server umount lustre-OST0001 complete [ 5503.329284] Lustre: DEBUG MARKER: oleg415-server.virtnet: executing unload_modules_local [ 5505.837486] Key type lgssc unregistered [ 5506.110774] LNet: 186225:0:(lib-ptl.c:967:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 5506.126741] LNetError: 186225:0:(acceptor.c:246:lnet_acceptor_remove_socket()) Interface ens2 not found [ 5506.147201] LNet: Removed LNI 192.168.204.115@tcp [ 5506.971259] Key type .llcrypt unregistered [ 5506.974119] Key type ._llcrypt unregistered