[ 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 485166761 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2399.998 MHz processor [ 0.000000] last_pfn = 0x146e00 max_arch_pfn = 0x400000000 [ 0.000000] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT [ 0.000000] last_pfn = 0xbffce max_arch_pfn = 0x400000000 [ 0.000000] found SMP MP-table at [mem 0x000f54b0-0x000f54bf] [ 0.000000] RAMDISK: [mem 0xbcc54000-0xbffbffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F52D0 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE247C 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE2318 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 0022D8 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE238C 000090 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE241C 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE2454 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe2318-0xbffe238b] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe2317] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe238c-0xbffe241b] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe241c-0xbffe2453] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe2454-0xbffe247b] [ 0.000000] No NUMA configuration found [ 0.000000] Faking a node at [mem 0x0000000000000000-0x0000000146dfffff] [ 0.000000] NODE_DATA(0) allocated [mem 0x1465a3000-0x1465cdfff] [ 0.000000] Reserving 256MB of memory at 2752MB for crashkernel (System RAM: 4205MB) [ 0.000000] Zone ranges: [ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.000000] DMA32 [mem 0x0000000001000000-0x00000000ffffffff] [ 0.000000] Normal [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Device empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff] [ 0.000000] node 0: [mem 0x0000000000100000-0x00000000bffcdfff] [ 0.000000] node 0: [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Zeroed struct page in unavailable ranges: 4756 pages [ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x0000000146dfffff] [ 0.000000] ACPI: PM-Timer IO Port: 0x608 [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) [ 0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) [ 0.000000] Using ACPI (MADT) for SMP configuration information [ 0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000] TSC deadline timer available [ 0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs [ 0.000000] kvm-guest: KVM setup pv remote TLB flush [ 0.000000] kvm-guest: setup PV sched yield [ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff] [ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff] [ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff] [ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff] [ 0.000000] PM: Registered nosave memory: [mem 0xbffce000-0xbfffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xc0000000-0xfeffbfff] [ 0.000000] PM: Registered nosave memory: [mem 0xfeffc000-0xfeffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xff000000-0xfffbffff] [ 0.000000] PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff] [ 0.000000] [mem 0xc0000000-0xfeffbfff] available for PCI devices [ 0.000000] Booting paravirtualized kernel on KVM [ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns [ 0.000000] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1 [ 0.000000] percpu: Embedded 63 pages/cpu s221184 r8192 d28672 u524288 [ 0.000000] kvm-guest: PV spinlocks enabled [ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1059606 [ 0.000000] Policy zone: Normal [ 0.000000] Kernel command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] Specific versions of hardware are certified with Red Hat Enterprise Linux 8. Please see the list of hardware certified with Red Hat Enterprise Linux 8 at https://catalog.redhat.com. [ 0.000000] audit: disabled (until reboot) [ 0.000000] software IO TLB: area num 4. [ 0.000000] Memory: 2829652K/4306352K available (18435K kernel code, 11221K rwdata, 7248K rodata, 2908K init, 18040K bss, 524580K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] ftrace: allocating 41240 entries in 162 pages [ 0.000000] ftrace: allocated 162 pages with 3 groups [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] rcu: RCU event tracing is enabled. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ 0.000000] rcu: RCU callback double-/use-after-free debug enabled. [ 0.000000] Rude variant of Tasks RCU enabled. [ 0.000000] Tracing variant of Tasks RCU enabled. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 0.000000] NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16 [ 0.000000] random: get_random_bytes called from start_kernel+0x622/0x9a8 with crng_init=0 [ 0.001000] Console: colour *CGA 80x25 [ 0.001000] printk: console [ttyS1] enabled [ 0.001000] ACPI: Core revision 20220331 [ 0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.001018] APIC: Switch to symmetric I/O mode setup [ 0.003096] x2apic enabled [ 0.004018] Switched APIC routing to physical x2apic. [ 0.005025] kvm-guest: setup PV IPIs [ 0.008000] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.008000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.008032] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.009025] pid_max: default: 32768 minimum: 301 [ 0.010183] LSM: Security Framework initializing [ 0.011093] Yama: becoming mindful. [ 0.012068] SELinux: Initializing. [ 0.013126] *** VALIDATE selinux *** [ 0.021837] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.026255] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.027210] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.029070] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.030162] *** VALIDATE tmpfs *** [ 0.031567] *** VALIDATE proc *** [ 0.032333] *** VALIDATE cgroup *** [ 0.033018] *** VALIDATE cgroup2 *** [ 0.035162] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.036204] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.037013] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.038037] Spectre V2 : User space: Vulnerable [ 0.039013] Speculative Store Bypass: Vulnerable [ 0.042391] debug: unmapping init [mem 0xffffffff8e059000-0xffffffff8e060fff] [ 0.044243] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.045883] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.046033] ... version: 2 [ 0.047020] ... bit width: 48 [ 0.048031] ... generic registers: 4 [ 0.049017] ... value mask: 0000ffffffffffff [ 0.050021] ... max period: 00007fffffffffff [ 0.051020] ... fixed-purpose events: 3 [ 0.052020] ... event mask: 000000070000000f [ 0.053391] rcu: Hierarchical SRCU implementation. [ 0.055765] smp: Bringing up secondary CPUs ... [ 0.056685] x86: Booting SMP configuration: [ 0.057036] .... node #0, CPUs: #1 #2 #3 [ 0.062026] smp: Brought up 1 node, 4 CPUs [ 0.064028] smpboot: Max logical packages: 1 [ 0.065020] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.198094] node 0 deferred pages initialised in 129ms [ 0.203199] devtmpfs: initialized [ 0.205322] x86/mm: Memory block size: 128MB [ 0.208967] gcov: version magic: 0x41383552 [ 0.211331] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.214105] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.216478] pinctrl core: initialized pinctrl subsystem [ 0.218243] [ 0.218657] ************************************************************* [ 0.220015] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.221009] ** ** [ 0.223013] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.225013] ** ** [ 0.226013] ** This means that this kernel is built to expose internal ** [ 0.228015] ** IOMMU data structures, which may compromise security on ** [ 0.229012] ** your system. ** [ 0.231018] ** ** [ 0.233031] ** If you see this message and you are not debugging the ** [ 0.235025] ** kernel, report this immediately to your vendor! ** [ 0.237026] ** ** [ 0.238013] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.240029] ************************************************************* [ 0.243374] NET: Registered protocol family 16 [ 0.245536] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.247071] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.250083] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.253130] cpuidle: using governor menu [ 0.256091] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.260000] PCI: Using configuration type 1 for base access [ 0.265340] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.281250] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.282000] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.287049] cryptd: max_cpu_qlen set to 1000 [ 0.293288] ACPI: Added _OSI(Module Device) [ 0.296021] ACPI: Added _OSI(Processor Device) [ 0.299024] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.302020] ACPI: Added _OSI(Processor Aggregator Device) [ 0.310607] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.319424] ACPI: Interpreter enabled [ 0.322097] ACPI: PM: (supports S0 S3 S4 S5) [ 0.326019] ACPI: Using IOAPIC for interrupt routing [ 0.329211] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.334887] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.350515] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.353056] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.356025] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.360146] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.366685] acpiphp: Slot [2] registered [ 0.367000] acpiphp: Slot [5] registered [ 0.368025] acpiphp: Slot [6] registered [ 0.370284] acpiphp: Slot [7] registered [ 0.372198] acpiphp: Slot [8] registered [ 0.374225] acpiphp: Slot [9] registered [ 0.376450] acpiphp: Slot [10] registered [ 0.378393] acpiphp: Slot [3] registered [ 0.380148] acpiphp: Slot [4] registered [ 0.382196] acpiphp: Slot [11] registered [ 0.384200] acpiphp: Slot [12] registered [ 0.386251] acpiphp: Slot [13] registered [ 0.388250] acpiphp: Slot [14] registered [ 0.390229] acpiphp: Slot [15] registered [ 0.392247] acpiphp: Slot [16] registered [ 0.394217] acpiphp: Slot [17] registered [ 0.396111] acpiphp: Slot [18] registered [ 0.398237] acpiphp: Slot [19] registered [ 0.400270] acpiphp: Slot [20] registered [ 0.402214] acpiphp: Slot [21] registered [ 0.404166] acpiphp: Slot [22] registered [ 0.406131] acpiphp: Slot [23] registered [ 0.408165] acpiphp: Slot [24] registered [ 0.409119] acpiphp: Slot [25] registered [ 0.411199] acpiphp: Slot [26] registered [ 0.413126] acpiphp: Slot [27] registered [ 0.414153] acpiphp: Slot [28] registered [ 0.416124] acpiphp: Slot [29] registered [ 0.418127] acpiphp: Slot [30] registered [ 0.419083] acpiphp: Slot [31] registered [ 0.420058] PCI host bridge to bus 0000:00 [ 0.422021] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.425061] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.428029] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.431030] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.433020] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.436030] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.438264] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.442315] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.446579] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.458025] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.463136] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.466027] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.469031] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.473027] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.477493] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.480996] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.484172] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.488282] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.495019] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.507019] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.513014] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.521745] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.531019] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.540000] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.580043] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.602972] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.619018] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.634020] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.680019] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.695594] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.706000] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.720082] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.790024] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.816534] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.832025] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.853017] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.884024] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.898054] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.911024] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.923015] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.942016] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 0.956099] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.969020] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.981050] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 1.036013] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 1.060000] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 1.063420] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 1.066365] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 1.068460] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 1.071329] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 1.077177] iommu: Default domain type: Passthrough [ 1.079491] SCSI subsystem initialized [ 1.080000] ACPI: bus type USB registered [ 1.080000] usbcore: registered new interface driver usbfs [ 1.084217] usbcore: registered new interface driver hub [ 1.087167] usbcore: registered new device driver usb [ 1.090803] pps_core: LinuxPPS API ver. 1 registered [ 1.093022] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 1.096124] PTP clock support registered [ 1.099136] EDAC MC: Ver: 3.0.0 [ 1.101194] PCI: Using ACPI for IRQ routing [ 1.104560] NetLabel: Initializing [ 1.107036] NetLabel: domain hash size = 128 [ 1.109140] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 1.113286] NetLabel: unlabeled traffic allowed by default [ 1.117710] vgaarb: loaded [ 1.121234] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 1.124032] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 1.132265] clocksource: Switched to clocksource kvm-clock [ 1.321937] VFS: Disk quotas dquot_6.6.0 [ 1.323597] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 1.326519] *** VALIDATE ramfs *** [ 1.328590] *** VALIDATE hugetlbfs *** [ 1.333889] pnp: PnP ACPI init [ 1.340050] pnp: PnP ACPI: found 6 devices [ 1.366341] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 1.372203] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 1.376687] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 1.380665] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 1.383792] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 1.388838] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 1.393803] NET: Registered protocol family 2 [ 1.398149] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 1.406947] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 1.412521] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 1.419494] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 1.424111] TCP: Hash tables configured (established 65536 bind 65536) [ 1.428225] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 1.432631] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 1.436317] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 1.439636] NET: Registered protocol family 1 [ 1.443048] RPC: Registered named UNIX socket transport module. [ 1.446497] RPC: Registered udp transport module. [ 1.449497] RPC: Registered tcp transport module. [ 1.451963] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 1.454722] NET: Registered protocol family 44 [ 1.456750] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 1.458529] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 1.460655] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 1.463119] PCI: CLS 0 bytes, default 64 [ 1.465341] Unpacking initramfs... [ 3.220844] debug: unmapping init [mem 0xffff90fcbcc54000-0xffff90fcbffbffff] [ 3.228173] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 3.230813] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 3.234226] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 3.905876] Initialise system trusted keyrings [ 3.907986] Key type blacklist registered [ 3.910275] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 3.922975] zbud: loaded [ 3.935299] *** VALIDATE nfs *** [ 3.936734] *** VALIDATE nfs4 *** [ 3.938893] pstore: using deflate compression [ 3.942611] Platform Keyring initialized [ 4.069963] NET: Registered protocol family 38 [ 4.071927] Key type asymmetric registered [ 4.073313] Asymmetric key parser 'x509' registered [ 4.075475] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 4.086081] io scheduler mq-deadline registered [ 4.091961] io scheduler kyber registered [ 4.094536] io scheduler bfq registered [ 4.101193] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 4.104993] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 4.108562] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 4.111942] ACPI: Power Button [PWRF] [ 4.120289] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 4.133810] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 4.170624] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 4.188659] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 4.214042] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 4.245875] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 4.277702] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 4.284340] Non-volatile memory driver v1.3 [ 4.286910] Linux agpgart interface v0.103 [ 4.326269] virtio_blk virtio1: [vda] 149768 512-byte logical blocks (76.7 MB/73.1 MiB) [ 4.329410] vda: detected capacity change from 0 to 76681216 [ 4.355820] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 4.359279] vdb: detected capacity change from 0 to 1073741824 [ 4.391830] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 4.395301] vdc: detected capacity change from 0 to 2621440000 [ 4.415544] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 4.420525] vdd: detected capacity change from 0 to 2621440000 [ 4.447833] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 4.453954] vde: detected capacity change from 0 to 4294967296 [ 4.473472] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 4.476597] vdf: detected capacity change from 0 to 4294967296 [ 4.487913] libphy: Fixed MDIO Bus: probed [ 4.507808] usbcore: registered new interface driver usbserial_generic [ 4.510814] usbserial: USB Serial support registered for generic [ 4.513780] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 4.518764] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 4.521263] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 4.523987] mousedev: PS/2 mouse device common for all mice [ 4.527331] rtc_cmos 00:05: RTC can wake from S4 [ 4.531752] rtc_cmos 00:05: registered as rtc0 [ 4.534438] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 4.536840] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 4.539039] intel_pstate: CPU model not supported [ 4.554651] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 4.555211] hid: raw HID events driver (C) Jiri Kosina [ 4.562686] usbcore: registered new interface driver usbhid [ 4.566801] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 4.567139] usbhid: USB HID core driver [ 4.571940] drop_monitor: Initializing network drop monitor service [ 4.574210] Initializing XFRM netlink socket [ 4.576339] NET: Registered protocol family 10 [ 4.579394] Segment Routing with IPv6 [ 4.580710] NET: Registered protocol family 17 [ 4.583316] mpls_gso: MPLS GSO support [ 4.589870] RAS: Correctable Errors collector initialized. [ 4.592501] AVX version of gcm_enc/dec engaged. [ 4.594508] AES CTR mode by8 optimization enabled [ 4.701409] sched_clock: Marking stable (4701315871, 0)->(5808397561, -1107081690) [ 4.706769] registered taskstats version 1 [ 4.710743] Loading compiled-in X.509 certificates [ 4.713489] zswap: loaded using pool lzo/zbud [ 4.755291] Key type big_key registered [ 4.778250] Key type encrypted registered [ 4.779782] ima: No TPM chip found, activating TPM-bypass! [ 4.783305] ima: Allocated hash algorithm: sha1 [ 4.785135] ima: No architecture policies found [ 4.786792] evm: Initialising EVM extended attributes: [ 4.788702] evm: security.selinux [ 4.789892] evm: security.ima [ 4.791144] evm: security.capability [ 4.793183] evm: HMAC attrs: 0x1 [ 4.796071] rtc_cmos 00:05: setting system clock to 2026-09-03 19:16:01 UTC (1788462961) [ 4.804162] debug: unmapping init [mem 0xffffffff8f003000-0xffffffff8f1fffff] [ 4.807453] debug: unmapping init [mem 0xffffffff8dd82000-0xffffffff8e058fff] [ 4.815373] Write protecting the kernel read-only data: 28672k [ 4.820958] debug: unmapping init [mem 0xffffffff8c403000-0xffffffff8c5fffff] [ 4.823830] debug: unmapping init [mem 0xffffffff8cd14000-0xffffffff8cdfffff] [ 4.874803] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 4.884774] systemd[1]: Detected virtualization kvm. [ 4.887232] systemd[1]: Detected architecture x86-64. [ 4.889268] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 4.926749] systemd[1]: No hostname configured. [ 4.929290] systemd[1]: Set hostname to . [ 4.932971] random: systemd: uninitialized urandom read (16 bytes read) [ 4.937938] systemd[1]: Initializing machine ID from random generator. [ 5.143492] random: systemd: uninitialized urandom read (16 bytes read) [ 5.151827] systemd[1]: Listening on udev Control Socket. [ OK ] Listening on udev Control Socket. [ 5.161607] random: systemd: uninitialized urandom read (16 bytes read) [ 5.168553] systemd[1]: Reached target Local File Systems. [ OK ] Reached target Local File Systems. [ 5.183144] systemd[1]: Started Dispatch Password Requests to Console Directory Watch. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Paths. [ OK ] Listening on udev Kernel Socket. [ OK ] Reached target Swap. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Timers. [ OK ] Reached target Slices. [ OK ] Listening on Journal Socket (/dev/log). [ OK ] Listening on Journal Socket. [ OK ] Started Memstrack Anylazing Service. Starting Journal Service... [ OK ] Reached target Sockets. Starting Create Volatile Files and Directories... Starting Apply Kernel Variables... Starting Create list of required st…ce nodes for the current kernel... Starting Setup Virtual Console... [ OK ] Reached target Initrd Root Device. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Apply Kernel Variables. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Setup Virtual Console. Starting dracut cmdline hook... Starting Create Static Device Nodes in /dev... [ OK ] Started Journal Service. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 7.529459] device-mapper: uevent: version 1.0.3 [ 7.533803] 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. [ 10.222235] virtio_net virtio0 ens2: renamed from eth0 [ 10.310297] random: fast init done [ 10.550396] scsi host0: ata_piix [ 10.836326] scsi host1: ata_piix [ 10.837832] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 10.852117] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 16.332275] random: crng init done [ 16.334038] random: 7 urandom warning(s) missed due to ratelimiting [ 19.100351] dracut-initqueue[585]: RTNETLINK answers: File exists Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. Mounting /sysroot... [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. [ 21.696472] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Timers. [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. Stopping Hardware RNG Entropy Gatherer Daemon... [ 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 Slices. [ OK ] Stopped target Paths. [ OK ] Stopped target Sockets. [ OK ] Stopped target System Initialization. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. [ OK ] Stopped target Swap. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. Stopping udev Kernel Device Manager... [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped Apply Kernel Variables. [ 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... [ 26.264319] printk: systemd: 25 output lines suppressed due to ratelimiting [ 27.601059] SELinux: Disabled at runtime. [ 27.723395] 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) [ 27.735124] systemd[1]: Detected virtualization kvm. [ 27.737024] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 29.575526] systemd[1]: initrd-switch-root.service: Succeeded. [ 29.587420] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 29.613398] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 29.622343] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 29.628454] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 29.660430] systemd[1]: Starting Journal Service... Starting Journal Service... [ 29.704536] systemd[1]: Listening on udev Control Socket. [ OK ] Listening on udev Control Socket. Mounting Huge Pages File System... Mounting Kernel Debug File System... [ OK ] Reached target rpc_pipefs.target. [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Stopped target Switch Root. Mounting POSIX Message Queue File System... [ OK ] Listening on udev Kernel Socket. Starting Apply Kernel Variables... Starting Remount Root and Kernel File Systems... [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped target Initrd Root File System. Activating swap /dev/disk/by-label/SWAP... [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Created slice system-getty.slice. Starting udev Coldplug all Devices... [ 30.628485] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Reached target Paths. [ OK ] Stopped target Initrd File Systems. [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Reached target RPC Port Mapper. [ OK ] Listening on Process Core Dump Socket. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Created slice system-sshd\x2dkeygen.slice. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Created slice User and Session Slice. [ OK ] Reached target Slices. [ OK ] Started Journal Service. [ OK ] Mounted Huge Pages File System. [ OK ] Mounted Kernel Debug File System. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Started Apply Kernel Variables. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ 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 udev Coldplug all Devices. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Reached target Local File Systems (Pre). Mounting /home/green/git/lustre-release... Mounting /mnt... Starting udev Kernel Device Manager... [ OK ] Mounted /mnt. [ 32.308207] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 33.173383] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 33.208162] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 33.417868] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 33.478306] EDAC sbridge: Ver: 1.1.2 [* ] A start job is running for Configur…-only root support (8s / no limit) [** ] A start job is running for Configur…-only root support (9s / no limit)[ 38.825193] Key type dns_resolver registered [*** ] A start job is running for Configur…-only root support (9s / no limit) [ *** ] A start job is running for Configur…only root support (10s / no limit) [ *** ] A start job is running for Configur…only root support (10s / no limit)[ 40.382222] NFS: Registering the id_resolver key type [ 40.393852] Key type id_resolver registered [ 40.417751] Key type id_legacy registered [ ***] A start job is running for Configur…only root support (11s / no limit) [ **] A start job is running for Configur…only root support (11s / no limit) [ OK ] Started Configure read-only root support. [ OK ] Reached target Local File Systems. Starting Rebuild Dynamic Linker Cache... Starting Mark the need to relabel after reboot... Starting Load/Save Random Seed... Starting Create Volatile Files and Directories... [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Load/Save Random Seed. [ OK ] Started Create Volatile Files and Directories. Starting Update UTMP about System Boot/Shutdown... Starting RPC Bind... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Started dnf makecache --timer. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Reached target Timers. [ OK ] Reached target Basic System. Starting Restore /run/initramfs on shutdown... [ OK ] Started D-Bus System Message Bus. Starting Network Manager... Starting Login Service... [ OK ] Reached target sshd-keygen.target. [ OK ] Started irqbalance daemon. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Login Service. [ OK ] Started Network Manager. Starting Network Manager Wait Online... [ OK ] Reached target Network. Starting Dynamic System Tuning Daemon... Starting OpenSSH server daemon... Starting GSSAPI Proxy Daemon... 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 Command Scheduler. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Getty on tty1. [ OK ] Reached target Login Prompts. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting System Logging Service... Starting Notify NFS peers of a restart... Starting Crash recovery kernel arming... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg408-server login: [ 57.595016] hrtimer: interrupt took 1214686 ns [ 114.607394] libcfs: loading out-of-tree module taints kernel. [ 114.686665] Key type ._llcrypt registered [ 114.688059] Key type .llcrypt registered [ 114.808650] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_hostid [ 133.435704] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing load_modules_local [ 134.826221] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 134.850022] alg: No test for adler32 (adler32-zlib) [ 136.376490] Lustre: Lustre: Build Version: 2.17.58_2_gbb63b80 [ 137.244062] LNet: Added LNI 192.168.204.108@tcp [8/256/0/180] [ 139.064863] Key type lgssc registered [ 141.174576] Lustre: Echo OBD driver; http://www.lustre.org/ [ 160.883926] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 203.217516] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing load_modules_local [ 217.305496] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 217.372054] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 218.759976] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 218.841390] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 219.018800] Lustre: lustre-MDT0000: new disk, initializing [ 219.157533] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 219.191294] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 224.650562] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 240.089557] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 240.218634] Lustre: 6514:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 240.254969] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 240.266808] Lustre: Skipped 1 previous similar message [ 240.422548] Lustre: lustre-MDT0001: new disk, initializing [ 240.514593] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 240.569835] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 240.579343] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 245.492667] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 250.911709] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 262.333713] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 262.783795] Lustre: lustre-OST0000: new disk, initializing [ 262.789359] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 262.804427] Lustre: 8455:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 262.905977] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 264.446048] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 264.473798] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 264.615732] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 270.306786] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 287.589219] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 287.761422] Lustre: lustre-OST0001: new disk, initializing [ 287.766380] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 287.773472] Lustre: 9527:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 287.858582] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 295.028096] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 295.978846] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 295.988561] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 296.027122] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 307.226802] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 313.847202] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 321.866489] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing check_logdir /tmp/testlogs/ [ 327.296790] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing yml_node [ 333.065303] Lustre: DEBUG MARKER: Client: 2.17.58.2 [ 335.788257] Lustre: DEBUG MARKER: MDS: 2.17.58.2 [ 339.025066] Lustre: DEBUG MARKER: OSS: 2.17.58.2 [ 341.400879] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity-lfsck ============----- Thu Sep 3 15:21:36 EDT 2026 [ 361.684463] Lustre: DEBUG MARKER: excepting tests: 18b 23b [ 373.546873] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing load_modules_local [ 382.964829] 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 [ 382.968906] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 382.989544] Lustre: Skipped 2 previous similar messages [ 383.017629] Lustre: Skipped 3 previous similar messages [ 388.074194] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 388.093926] Lustre: Skipped 3 previous similar messages [ 389.101457] Lustre: server umount lustre-MDT0000 complete [ 398.307063] LustreError: 7810:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 398.332609] LustreError: 7810:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 8 previous similar messages [ 399.164660] LustreError: 6506:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788463355 with bad export cookie 11726072991916181547 [ 399.173372] LustreError: MGC192.168.204.108@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 399.175706] LustreError: 6506:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 3 previous similar messages [ 399.404656] Lustre: server umount lustre-MDT0001 complete [ 419.449986] Lustre: server umount lustre-OST0000 complete [ 419.619443] Lustre: 3645:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788463360/real 1788463360] req@ffff90fd1019ad80 x1875339476314880/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788463376 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 419.632502] 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 [ 419.643234] Lustre: Skipped 1 previous similar message [ 420.833761] Lustre: 3647:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788463361/real 1788463361] req@ffff90fd10198e00 x1875339476315136/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788463377 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 424.802592] Lustre: 3645:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788463365/real 1788463365] req@ffff90fc03611500 x1875339476315392/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788463381 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 430.047134] Lustre: 3646:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788463370/real 1788463370] req@ffff90fc01d7e300 x1875339476315776/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788463386 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 430.938951] Lustre: server umount lustre-OST0001 complete [ 451.685661] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing unload_modules_local [ 455.773790] Key type lgssc unregistered [ 456.249641] LNet: 14801:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 456.257546] LNetError: 14801:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 457.331667] LNet: Removed LNI 192.168.204.108@tcp [ 458.553175] Key type .llcrypt unregistered [ 458.559264] Key type ._llcrypt unregistered [ 488.842201] Key type ._llcrypt registered [ 488.846477] Key type .llcrypt registered [ 488.981702] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_hostid [ 508.175649] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing load_modules_local [ 509.809405] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 509.859431] alg: No test for adler32 (adler32-zlib) [ 511.195091] Lustre: Lustre: Build Version: 2.17.58_2_gbb63b80 [ 511.491045] LNet: Added LNI 192.168.204.108@tcp [8/256/0/180] [ 513.415245] Key type lgssc registered [ 514.918887] Lustre: Echo OBD driver; http://www.lustre.org/ [ 576.138776] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing load_modules_local [ 592.471721] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 592.496503] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 593.874289] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 593.905695] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 593.976405] Lustre: lustre-MDT0000: new disk, initializing [ 594.023120] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 594.038699] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 598.812804] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 613.963505] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 614.133752] Lustre: 19258:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 614.177704] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 614.183754] Lustre: Skipped 1 previous similar message [ 614.277614] Lustre: lustre-MDT0001: new disk, initializing [ 614.361221] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 614.393858] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 614.405364] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 619.535684] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 625.244519] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 637.780910] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 638.083444] Lustre: lustre-OST0000: new disk, initializing [ 638.086839] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 638.095981] Lustre: 21197:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 638.188844] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 644.640514] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 644.658428] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 644.812490] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 647.060962] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 664.706633] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 664.994139] Lustre: lustre-OST0001: new disk, initializing [ 665.007497] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 665.018616] Lustre: 22223:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 665.109790] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 671.889507] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 673.365874] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 673.376552] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 673.439504] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 685.933344] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 691.933358] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 702.564642] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 15:27:37 (1788463657) === [ 705.606578] Lustre: DEBUG MARKER: == sanity-lfsck test 0: Control LFSCK manually =========== 15:27:40 (1788463660) [ 705.876475] Lustre: 19265:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 251 < left 278, rollback = 2 [ 705.884584] Lustre: 19265:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 705.888993] Lustre: 19265:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 705.895313] Lustre: 19265:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 705.902684] Lustre: 19265:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 705.907718] Lustre: 19265:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 706.479262] Lustre: 21410:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 706.484556] Lustre: 21410:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 14 previous similar messages [ 706.487452] Lustre: 21410:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 706.490736] Lustre: 21410:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 14 previous similar messages [ 706.494029] Lustre: 21410:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 706.497037] Lustre: 21410:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 14 previous similar messages [ 706.500768] Lustre: 21410:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 706.504092] Lustre: 21410:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 14 previous similar messages [ 706.507402] Lustre: 21410:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 706.510354] Lustre: 21410:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 14 previous similar messages [ 706.514556] Lustre: 21410:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 706.517424] Lustre: 21410:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 14 previous similar messages [ 707.518889] Lustre: 19264:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 707.528893] Lustre: 19264:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 50 previous similar messages [ 707.538743] Lustre: 19264:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 707.548368] Lustre: 19264:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 50 previous similar messages [ 707.559433] Lustre: 19264:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 707.566729] Lustre: 19264:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 50 previous similar messages [ 707.573825] Lustre: 19264:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 707.585695] Lustre: 19264:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 50 previous similar messages [ 707.604845] Lustre: 19264:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 707.617288] Lustre: 19264:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 50 previous similar messages [ 707.622955] Lustre: 19264:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 707.631293] Lustre: 19264:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 50 previous similar messages [ 709.537419] Lustre: 19264:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 709.543199] Lustre: 19264:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 77 previous similar messages [ 709.547849] Lustre: 19264:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 709.552697] Lustre: 19264:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 77 previous similar messages [ 709.613996] Lustre: 21410:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 709.619821] Lustre: 21410:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 80 previous similar messages [ 709.626836] Lustre: 21410:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 709.633713] Lustre: 21410:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 80 previous similar messages [ 709.642896] Lustre: 21410:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 709.656950] Lustre: 21410:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 80 previous similar messages [ 709.671647] Lustre: 21410:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 709.686755] Lustre: 21410:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 80 previous similar messages [ 714.198614] Lustre: *** cfs_fail_loc=1600, val=3*** [ 716.294269] Lustre: 21186:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-OST0001: opcode 2: before 259 < left 274, rollback = 2 [ 716.309134] Lustre: 21186:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 131 previous similar messages [ 716.314563] Lustre: 21186:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 716.322236] Lustre: 21186:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 131 previous similar messages [ 716.328790] Lustre: 21186:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/1, xattr_set: 2/274/0 [ 716.338104] Lustre: 21186:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 128 previous similar messages [ 716.347244] Lustre: 21186:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 0/0/0, punch: 0/0/0, quota 7/225/0 [ 716.358693] Lustre: 21186:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 128 previous similar messages [ 716.366484] Lustre: 21186:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 716.377561] Lustre: 21186:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 128 previous similar messages [ 716.392481] Lustre: 21186:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 716.408169] Lustre: 21186:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 128 previous similar messages [ 719.186975] Lustre: *** cfs_fail_loc=1600, val=3*** [ 730.730573] Lustre: 23630:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 259 < left 274, rollback = 2 [ 730.731394] Lustre: 23632:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 730.741727] Lustre: 23630:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 64 previous similar messages [ 730.741789] Lustre: 23630:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/1, xattr_set: 2/274/0 [ 730.741794] Lustre: 23630:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 63 previous similar messages [ 730.741800] Lustre: 23630:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 0/0/0, punch: 0/0/0, quota 7/225/0 [ 730.741803] Lustre: 23630:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 63 previous similar messages [ 730.741808] Lustre: 23630:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 730.741812] Lustre: 23630:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 63 previous similar messages [ 730.741817] Lustre: 23630:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 730.741820] Lustre: 23630:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 63 previous similar messages [ 730.791154] Lustre: 23632:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 66 previous similar messages [ 735.204744] 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.207857] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 735.233954] Lustre: Skipped 1 previous similar message [ 735.252600] Lustre: Skipped 3 previous similar messages [ 740.281212] Lustre: server umount lustre-MDT0000 complete [ 744.679105] LustreError: 19250:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788463701 with bad export cookie 1022639678449429847 [ 744.683147] LustreError: MGC192.168.204.108@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 744.698710] LustreError: 19250:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 745.283847] Lustre: server umount lustre-MDT0001 complete [ 760.777284] Lustre: server umount lustre-OST0000 complete [ 761.824380] Lustre: 16414:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788463702/real 1788463702] req@ffff90fc09eddc00 x1875339869537408/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788463718 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 761.886848] 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 [ 761.929841] Lustre: Skipped 2 previous similar messages [ 765.567840] Lustre: server umount lustre-OST0001 complete [ 775.938885] Lustre: DEBUG MARKER: == sanity-lfsck test 1a: LFSCK can find out and repair crashed FID-in-dirent ========================================================== 15:28:51 (1788463731) [ 793.668639] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing load_modules_local [ 805.602570] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 806.070802] LustreError: 26282:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 806.099410] LustreError: 26282:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 5 previous similar messages [ 806.206262] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 811.070429] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 811.491778] LustreError: 26283:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 815.591214] LustreError: 26282:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 819.786716] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 820.305498] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 826.381821] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 830.030755] Lustre: 27422:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 837.736131] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 838.342112] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 844.516647] LustreError: 27775:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 847.865753] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 849.913334] LustreError: 27776:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 850.937212] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:40 to 0x280000401:65) [ 858.975963] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 864.259370] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:41 to 0x2c0000401:65) [ 866.992398] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 876.011989] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 880.240530] Lustre: 29290:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 881.791626] Lustre: 26277:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 881.797737] Lustre: 26277:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 5 previous similar messages [ 881.802765] Lustre: 26277:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 881.810507] Lustre: 26277:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 3 previous similar messages [ 881.818789] Lustre: 26277:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 881.824544] Lustre: 26277:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 6 previous similar messages [ 881.829840] Lustre: 26277:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 881.836140] Lustre: 26277:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 6 previous similar messages [ 881.840855] Lustre: 26277:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 881.845296] Lustre: 26277:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 6 previous similar messages [ 881.848963] Lustre: 26277:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 881.853073] Lustre: 26277:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 6 previous similar messages [ 887.220295] Lustre: *** cfs_fail_loc=1501, val=0*** [ 896.160157] Lustre: Failing over lustre-MDT0000 [ 896.564226] Lustre: server umount lustre-MDT0000 complete [ 896.991658] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 897.005134] 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 [ 897.037560] LustreError: 26282:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 897.062593] LustreError: 26282:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 4 previous similar messages [ 900.073792] 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 [ 909.247101] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 909.509225] LustreError: MGC192.168.204.108@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 909.806114] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 909.813834] Lustre: Skipped 1 previous similar message [ 909.866483] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 914.913693] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 914.924228] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 914.937246] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 914.970166] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:105 to 0x280000401:129) [ 914.970981] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:105 to 0x2c0000401:129) [ 915.362279] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 919.422186] Lustre: *** cfs_fail_loc=1505, val=0*** [ 927.947183] Lustre: DEBUG MARKER: == sanity-lfsck test 1b: LFSCK can find out and repair the missing FID-in-LMA ========================================================== 15:31:23 (1788463883) [ 929.457953] Lustre: 26276:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 929.466705] Lustre: 26276:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 321 previous similar messages [ 929.471370] Lustre: 26276:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 929.480251] Lustre: 26276:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 929.490097] Lustre: 26276:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 929.505097] Lustre: 26276:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 929.519315] Lustre: 26276:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 929.537878] Lustre: 26276:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 929.553492] Lustre: 26276:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 929.571830] Lustre: 26276:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 929.590255] Lustre: 26276:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 929.602747] Lustre: 26276:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 322 previous similar messages [ 935.156881] Lustre: *** cfs_fail_loc=1502, val=0*** [ 945.762540] Lustre: Failing over lustre-MDT0000 [ 946.022788] Lustre: server umount lustre-MDT0000 complete [ 950.752298] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 950.757552] 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 [ 950.766787] LustreError: 26283:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 950.766798] LustreError: 26283:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 8 previous similar messages [ 950.835748] Lustre: Skipped 4 previous similar messages [ 958.187220] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 958.415807] LustreError: MGC192.168.204.108@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 958.746801] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 963.966947] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 964.080405] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 964.091894] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 964.108418] Lustre: Skipped 3 previous similar messages [ 964.138614] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 964.191530] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:169 to 0x280000401:193) [ 964.207188] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:169 to 0x2c0000401:193) [ 967.495541] Lustre: *** cfs_fail_loc=1505, val=0*** [ 975.802569] Lustre: DEBUG MARKER: == sanity-lfsck test 1c: LFSCK can find out and repair lost FID-in-dirent ========================================================== 15:32:10 (1788463930) [ 982.759626] Lustre: *** cfs_fail_loc=1504, val=0*** [ 982.775352] Lustre: *** cfs_fail_loc=1504, val=0*** [ 982.779743] Lustre: Skipped 1 previous similar message [ 991.260737] Lustre: Failing over lustre-MDT0000 [ 991.596290] Lustre: server umount lustre-MDT0000 complete [ 994.787567] 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 [ 994.799905] LustreError: 26278:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 994.819577] Lustre: Skipped 4 previous similar messages [ 994.876898] LustreError: 26278:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 10 previous similar messages [ 1003.821209] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1003.991496] LustreError: MGC192.168.204.108@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1004.198509] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1004.206804] Lustre: Skipped 1 previous similar message [ 1004.240592] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1009.370478] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1009.639750] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1009.649543] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1009.678738] Lustre: Skipped 3 previous similar messages [ 1009.700205] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1009.761247] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:233 to 0x2c0000401:257) [ 1009.766391] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:233 to 0x280000401:257) [ 1012.707993] Lustre: *** cfs_fail_loc=1505, val=0*** [ 1020.969745] Lustre: DEBUG MARKER: == sanity-lfsck test 2a: LFSCK can find out and repair crashed linkEA entry ========================================================== 15:32:55 (1788463975) [ 1022.367612] Lustre: 27213:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 1022.375397] Lustre: 27213:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 644 previous similar messages [ 1022.380519] Lustre: 27213:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 1022.384925] Lustre: 27213:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 1022.390287] Lustre: 27213:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 1022.397952] Lustre: 27213:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 1022.405228] Lustre: 27213:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 1022.411509] Lustre: 27213:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 1022.420110] Lustre: 27213:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 1022.429521] Lustre: 27213:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 1022.434790] Lustre: 27213:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 1022.439780] Lustre: 27213:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 644 previous similar messages [ 1027.660385] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1036.640454] Lustre: Failing over lustre-MDT0000 [ 1037.038458] Lustre: server umount lustre-MDT0000 complete [ 1040.352781] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1040.372831] 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 [ 1040.402033] Lustre: Skipped 3 previous similar messages [ 1049.234684] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1049.359525] LustreError: MGC192.168.204.108@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1049.725396] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1054.698957] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1054.708227] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1054.721599] Lustre: Skipped 3 previous similar messages [ 1054.748351] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1054.790435] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:297 to 0x2c0000401:321) [ 1054.793191] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:297 to 0x280000401:321) [ 1055.015803] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1064.979810] Lustre: DEBUG MARKER: == sanity-lfsck test 2b: LFSCK can find out and remove invalid linkEA entry ========================================================== 15:33:39 (1788464019) [ 1070.955439] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1079.021586] Lustre: Failing over lustre-MDT0000 [ 1079.288579] Lustre: server umount lustre-MDT0000 complete [ 1080.294174] 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 [ 1080.299533] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1080.313050] LustreError: 26276:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1080.313063] LustreError: 26276:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 12 previous similar messages [ 1080.315736] Lustre: Skipped 2 previous similar messages [ 1090.753257] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1090.908627] LustreError: MGC192.168.204.108@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1091.214166] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1096.161768] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1096.176676] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1096.182989] Lustre: Skipped 3 previous similar messages [ 1096.229384] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1096.301359] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:361 to 0x2c0000401:385) [ 1096.306051] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:361 to 0x280000401:385) [ 1096.980298] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1106.753151] Lustre: DEBUG MARKER: == sanity-lfsck test 2c: LFSCK can find out and remove repeated linkEA entry ========================================================== 15:34:21 (1788464061) [ 1113.255515] Lustre: *** cfs_fail_loc=1605, val=0*** [ 1121.871932] Lustre: Failing over lustre-MDT0000 [ 1122.208490] Lustre: server umount lustre-MDT0000 complete [ 1132.227920] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1132.304609] LustreError: MGC192.168.204.108@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1132.474795] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1132.477185] Lustre: Skipped 2 previous similar messages [ 1132.507201] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1137.341735] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1137.637824] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1137.662585] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1137.666485] Lustre: Skipped 3 previous similar messages [ 1137.678625] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1137.725740] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:425 to 0x2c0000401:449) [ 1137.726043] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:425 to 0x280000401:449) [ 1147.930757] Lustre: DEBUG MARKER: == sanity-lfsck test 2d: LFSCK can recover the missing linkEA entry ========================================================== 15:35:03 (1788464103) [ 1150.459333] Lustre: 26278:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 1150.472970] Lustre: 26278:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 1019 previous similar messages [ 1150.479691] Lustre: 26278:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 1150.485364] Lustre: 26278:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1019 previous similar messages [ 1150.492863] Lustre: 26278:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 1150.501268] Lustre: 26278:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1019 previous similar messages [ 1150.507902] Lustre: 26278:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 1/3/0 [ 1150.514317] Lustre: 26278:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1019 previous similar messages [ 1150.520316] Lustre: 26278:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 1150.539637] Lustre: 26278:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1019 previous similar messages [ 1150.548242] Lustre: 26278:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 1150.552191] Lustre: 26278:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1019 previous similar messages [ 1154.844134] Lustre: *** cfs_fail_loc=161d, val=0*** [ 1163.118724] Lustre: Failing over lustre-MDT0000 [ 1163.235821] 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 [ 1163.236441] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1163.257413] Lustre: Skipped 5 previous similar messages [ 1163.259090] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1163.453841] Lustre: server umount lustre-MDT0000 complete [ 1173.718254] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1173.828273] LustreError: MGC192.168.204.108@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1174.134220] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1178.583128] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1179.107896] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1179.114889] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1179.142243] Lustre: Skipped 3 previous similar messages [ 1179.173687] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1179.230692] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:489 to 0x2c0000401:513) [ 1179.233087] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:489 to 0x280000401:513) [ 1187.933703] Lustre: DEBUG MARKER: == sanity-lfsck test 2e: namespace LFSCK can verify remote object linkEA ========================================================== 15:35:43 (1788464143) [ 1190.508931] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1201.245560] Lustre: DEBUG MARKER: == sanity-lfsck test 3: LFSCK can verify multiple-linked objects ========================================================== 15:35:56 (1788464156) [ 1207.194690] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1208.098335] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1220.400596] Lustre: DEBUG MARKER: == sanity-lfsck test 4: FID-in-dirent can be rebuilt after MDT file-level backup/restore ========================================================== 15:36:15 (1788464175) [ 1254.683043] Lustre: Failing over lustre-MDT0000 [ 1255.018809] Lustre: server umount lustre-MDT0000 complete [ 1255.907727] LustreError: 27213:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1255.920265] LustreError: 27213:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 29 previous similar messages [ 1260.942970] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1272.293910] Lustre: 16414:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788464212/real 1788464212] req@ffff90fd39f60380 x1875339870174848/t0(0) o400->MGC192.168.204.108@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1788464228 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1272.342775] LustreError: MGC192.168.204.108@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1273.629773] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1286.487133] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1286.519514] Lustre: lustre-MDT0000: reset Object Index mappings [ 1298.212911] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1303.522347] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1303.529147] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1303.543303] Lustre: Skipped 3 previous similar messages [ 1303.559252] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1303.604944] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:592 to 0x2c0000401:609) [ 1303.607648] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:592 to 0x280000401:609) [ 1304.268357] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1308.610201] LustreError: 42942:0:(lfsck_engine.c:1018:lfsck_master_engine()) lustre-MDT0000-osd: master engine fail to verify the .lustre/lost+found/, go ahead: rc = -115 [ 1308.624053] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1310.687388] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1310.691554] Lustre: Skipped 1 previous similar message [ 1318.337301] Lustre: Failing over lustre-MDT0000 [ 1318.578497] Lustre: server umount lustre-MDT0000 complete [ 1318.882802] 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 [ 1318.897435] Lustre: Skipped 10 previous similar messages [ 1328.882914] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1334.167952] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1334.872302] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:592 to 0x2c0000401:641) [ 1334.874162] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:592 to 0x280000401:641) [ 1338.066414] Lustre: *** cfs_fail_loc=1505, val=0*** [ 1345.478832] Lustre: DEBUG MARKER: == sanity-lfsck test 5: LFSCK can handle IGIF object upgrading ========================================================== 15:38:20 (1788464300) [ 1348.072572] Lustre: *** cfs_fail_loc=1504, val=0*** [ 1358.517123] Lustre: Failing over lustre-MDT0000 [ 1358.865193] Lustre: server umount lustre-MDT0000 complete [ 1360.352933] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1365.173837] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1376.743902] Lustre: 16415:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788464317/real 1788464317] req@ffff90fd1085a680 x1875339870277248/t0(0) o400->MGC192.168.204.108@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1788464333 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1377.053238] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null) [ 1389.330569] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1389.363757] Lustre: lustre-MDT0000: reset Object Index mappings [ 1401.314907] LustreError: 16411:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff90fd39f60700 x1875339870289280/t0(0) o250->MGC192.168.204.108@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 0 ref 1 fl Rpc:NQU/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1401.598457] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1401.603060] Lustre: Skipped 3 previous similar messages [ 1401.635895] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1401.643165] Lustre: Skipped 1 previous similar message [ 1405.767078] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1406.946593] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1406.964974] Lustre: Skipped 1 previous similar message [ 1406.968388] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1406.977892] Lustre: Skipped 7 previous similar messages [ 1407.006699] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1407.019479] Lustre: Skipped 1 previous similar message [ 1407.050392] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:681 to 0x280000401:705) [ 1407.055346] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:681 to 0x2c0000401:705) [ 1409.215532] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1409.218579] Lustre: Skipped 2 previous similar messages [ 1421.180978] Lustre: Failing over lustre-MDT0000 [ 1421.512403] Lustre: server umount lustre-MDT0000 complete [ 1422.309258] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1431.372054] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1431.510852] LustreError: MGC192.168.204.108@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1431.524883] LustreError: Skipped 2 previous similar messages [ 1437.017966] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1437.228739] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:681 to 0x280000401:737) [ 1437.230879] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:681 to 0x2c0000401:737) [ 1440.489688] Lustre: *** cfs_fail_loc=1505, val=0*** [ 1440.495428] Lustre: Skipped 84 previous similar messages [ 1448.572557] Lustre: DEBUG MARKER: == sanity-lfsck test 6a: LFSCK resumes from last checkpoint (1) ========================================================== 15:40:03 (1788464403) [ 1450.056370] Lustre: 26278:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 1450.062312] Lustre: 26278:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 1226 previous similar messages [ 1450.067506] Lustre: 26278:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 1450.075682] Lustre: 26278:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1226 previous similar messages [ 1450.080095] Lustre: 26278:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 1450.085293] Lustre: 26278:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1226 previous similar messages [ 1450.089935] Lustre: 26278:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 1450.094603] Lustre: 26278:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1226 previous similar messages [ 1450.099479] Lustre: 26278:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 1450.103349] Lustre: 26278:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1226 previous similar messages [ 1450.107378] Lustre: 26278:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 1450.115500] Lustre: 26278:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1226 previous similar messages [ 1456.420342] Lustre: *** cfs_fail_loc=1600, val=1*** [ 1456.425026] Lustre: Skipped 7 previous similar messages [ 1475.119581] Lustre: DEBUG MARKER: == sanity-lfsck test 6b: LFSCK resumes from last checkpoint (2) ========================================================== 15:40:30 (1788464430) [ 1483.721486] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1483.726359] Lustre: Skipped 8 previous similar messages [ 1508.711661] Lustre: DEBUG MARKER: == sanity-lfsck test 7a: non-stopped LFSCK should auto restarts after MDS remount (1) ========================================================== 15:41:04 (1788464464) [ 1518.951471] Lustre: *** cfs_fail_loc=1601, val=1*** [ 1518.955705] Lustre: Skipped 12 previous similar messages [ 1525.158734] Lustre: Failing over lustre-MDT0000 [ 1525.354623] Lustre: server umount lustre-MDT0000 complete [ 1529.312105] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1529.318677] LustreError: 26278:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1529.346196] LustreError: 26278:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 99 previous similar messages [ 1534.549767] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1534.917345] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1534.929179] Lustre: Skipped 1 previous similar message [ 1539.424272] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1540.076292] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1540.087966] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1540.095246] Lustre: Skipped 1 previous similar message [ 1540.102406] Lustre: Skipped 7 previous similar messages [ 1540.129680] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1540.139983] Lustre: Skipped 1 previous similar message [ 1540.208841] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:853 to 0x2c0000401:897) [ 1540.209318] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:854 to 0x280000401:897) [ 1549.093661] Lustre: DEBUG MARKER: == sanity-lfsck test 7b: non-stopped LFSCK should auto restarts after MDS remount (2) ========================================================== 15:41:44 (1788464504) [ 1564.781695] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing load_modules_local [ 1582.192629] Lustre: 52963:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 1603.200338] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1605.725100] Lustre: 54099:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 1612.394971] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1612.398990] Lustre: Skipped 81 previous similar messages [ 1615.527503] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1616.549286] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1617.567173] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1619.615628] Lustre: *** cfs_fail_loc=1602, val=1*** [ 1619.623631] Lustre: Skipped 1 previous similar message [ 1623.472436] Lustre: Failing over lustre-MDT0000 [ 1623.932443] Lustre: server umount lustre-MDT0000 complete [ 1627.107949] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1627.109118] 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 [ 1627.165679] Lustre: Skipped 15 previous similar messages [ 1635.347902] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1640.732971] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1641.063783] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:946 to 0x2c0000401:961) [ 1641.064029] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:947 to 0x280000401:993) [ 1650.398366] Lustre: DEBUG MARKER: == sanity-lfsck test 8: LFSCK state machine ============== 15:43:25 (1788464605) [ 1656.290724] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1656.298184] Lustre: Skipped 6 previous similar messages [ 1658.796736] Lustre: server umount lustre-MDT0000 complete [ 1662.231352] LustreError: 26262:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788464618 with bad export cookie 1022639678449643767 [ 1662.237790] LustreError: 26262:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 1662.496635] Lustre: server umount lustre-MDT0001 complete [ 1675.937189] Lustre: server umount lustre-OST0000 complete [ 1689.805357] Lustre: server umount lustre-OST0001 complete [ 1694.574790] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_hostid [ 1701.086746] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing load_modules_local [ 1759.430307] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing load_modules_local [ 1769.965398] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1770.203443] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 1770.231844] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 1770.311980] Lustre: lustre-MDT0000: new disk, initializing [ 1770.443951] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 1775.578412] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1785.384951] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 1785.479744] Lustre: 59160:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 1785.513408] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 1785.525080] Lustre: Skipped 1 previous similar message [ 1785.625264] Lustre: lustre-MDT0001: new disk, initializing [ 1785.750673] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 1785.769532] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 1789.755330] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1793.998813] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 1799.826590] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 1800.165863] Lustre: lustre-OST0000: new disk, initializing [ 1800.170700] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 1800.176989] Lustre: 60790:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 1801.442184] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 1801.448830] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 1801.510148] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 1804.677301] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1813.638787] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 1813.763238] Lustre: lustre-OST0001: new disk, initializing [ 1813.768389] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 1813.772941] Lustre: 61661:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 1815.279096] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 1815.287332] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 1815.357263] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 1820.263204] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1829.507206] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1833.061630] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 1842.386439] Lustre: *** cfs_fail_loc=1603, val=0*** [ 1843.439856] Lustre: *** cfs_fail_loc=1604, val=0*** [ 1843.446687] Lustre: Skipped 19 previous similar messages [ 1847.447101] Lustre: *** cfs_fail_loc=1601, val=2*** [ 1847.451924] Lustre: Skipped 6 previous similar messages [ 1865.148085] Lustre: Failing over lustre-MDT0000 [ 1865.524464] Lustre: server umount lustre-MDT0000 complete [ 1874.356598] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1874.482705] LustreError: MGC192.168.204.108@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1874.492521] LustreError: Skipped 3 previous similar messages [ 1874.700301] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1874.710194] Lustre: Skipped 1 previous similar message [ 1878.835458] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1880.035762] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1880.038769] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 1880.050289] Lustre: Skipped 1 previous similar message [ 1880.061974] Lustre: Skipped 7 previous similar messages [ 1880.096821] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1880.112935] Lustre: Skipped 1 previous similar message [ 1880.143152] Lustre: *** cfs_fail_loc=160b, val=2*** [ 1880.148652] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:65) [ 1880.150078] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:65) [ 1886.743432] Lustre: Failing over lustre-MDT0000 [ 1887.025386] Lustre: server umount lustre-MDT0000 complete [ 1894.577442] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1898.224982] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1900.056608] Lustre: *** cfs_fail_loc=160b, val=2*** [ 1900.061838] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:97) [ 1900.065744] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:97) [ 1903.801036] Lustre: Failing over lustre-MDT0000 [ 1904.134407] Lustre: server umount lustre-MDT0000 complete [ 1905.119855] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 1913.257774] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 1913.797642] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1913.804373] Lustre: Skipped 9 previous similar messages [ 1918.904466] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1919.082651] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:43 to 0x280000401:129) [ 1919.084797] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:43 to 0x2c0000401:129) [ 1924.801865] Lustre: *** cfs_fail_loc=1602, val=2*** [ 1924.803735] Lustre: Skipped 3 previous similar messages [ 1935.751453] Lustre: DEBUG MARKER: == sanity-lfsck test 9a: LFSCK speed control (1) ========= 15:48:11 (1788464891) [ 1948.556955] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing load_modules_local [ 1966.509741] Lustre: 68617:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 1986.587933] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 1990.172901] Lustre: 69753:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 1998.839387] Lustre: 59168:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 1998.845406] Lustre: 59168:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 2772 previous similar messages [ 1998.850583] Lustre: 59168:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 1998.855281] Lustre: 59168:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 2772 previous similar messages [ 1998.859561] Lustre: 59168:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 1998.864365] Lustre: 59168:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 2772 previous similar messages [ 1998.869120] Lustre: 59168:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 1998.874077] Lustre: 59168:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 2772 previous similar messages [ 1998.880513] Lustre: 59168:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 1998.885639] Lustre: 59168:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 2772 previous similar messages [ 1998.890855] Lustre: 59168:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 1998.896032] Lustre: 59168:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 2772 previous similar messages [ 2102.645461] Lustre: DEBUG MARKER: == sanity-lfsck test 9b: LFSCK speed control (2) ========= 15:50:57 (1788465057) [ 2154.685385] Lustre: *** cfs_fail_loc=1604, val=0*** [ 2154.687956] Lustre: Skipped 4 previous similar messages [ 2177.604196] Lustre: *** cfs_fail_loc=160c, val=0*** [ 2177.607851] Lustre: Skipped 8 previous similar messages [ 2214.163466] Lustre: DEBUG MARKER: == sanity-lfsck test 10: System is available during LFSCK scanning ========================================================== 15:52:49 (1788465169) [ 2262.307569] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2263.331597] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2263.335569] Lustre: Skipped 50 previous similar messages [ 2265.337827] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2265.340950] Lustre: Skipped 103 previous similar messages [ 2269.352608] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2269.364296] Lustre: Skipped 180 previous similar messages [ 2277.438683] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2277.440566] Lustre: Skipped 358 previous similar messages [ 2293.447175] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2293.453478] Lustre: Skipped 765 previous similar messages [ 2325.458717] Lustre: *** cfs_fail_loc=1603, val=0*** [ 2325.463342] Lustre: Skipped 1823 previous similar messages [ 2329.957619] Lustre: *** cfs_fail_loc=1604, val=0*** [ 2329.960154] Lustre: Skipped 2599 previous similar messages [ 2563.010766] Lustre: DEBUG MARKER: == sanity-lfsck test 11a: LFSCK can rebuild lost last_id ========================================================== 15:58:38 (1788465518) [ 2607.101976] Lustre: 59165:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 320, rollback = 2 [ 2607.114492] Lustre: 59165:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 36831 previous similar messages [ 2607.120316] Lustre: 59165:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 1/4/0 [ 2607.125692] Lustre: 59165:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 36831 previous similar messages [ 2607.132043] Lustre: 59165:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 5/5/0, xattr_set: 7/320/0 [ 2607.137846] Lustre: 59165:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 36831 previous similar messages [ 2607.145424] Lustre: 59165:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 6/46/0, punch: 0/0/0, quota 1/3/0 [ 2607.154345] Lustre: 59165:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 36831 previous similar messages [ 2607.168487] Lustre: 59165:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 2/5/0 [ 2607.175863] Lustre: 59165:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 36831 previous similar messages [ 2607.185127] Lustre: 59165:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 1/1/0, ref_del: 2/2/1 [ 2607.200957] Lustre: 59165:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 36831 previous similar messages [ 2712.544973] 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 [ 2712.545447] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2712.546925] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 2712.554608] Lustre: Skipped 18 previous similar messages [ 2712.570818] Lustre: Skipped 3 previous similar messages [ 2717.672198] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2717.678845] Lustre: Skipped 3 previous similar messages [ 2718.190996] Lustre: server umount lustre-MDT0000 complete [ 2721.321694] LustreError: 60801:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788465678 with bad export cookie 1022639678449662856 [ 2721.325159] LustreError: MGC192.168.204.108@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2721.332183] LustreError: 60801:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 2721.336201] LustreError: Skipped 2 previous similar messages [ 2721.561545] Lustre: server umount lustre-MDT0001 complete [ 2735.396984] Lustre: server umount lustre-OST0000 complete [ 2738.335302] Lustre: 16414:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788465679/real 1788465679] req@ffff90fd367e6a00 x1875339874374400/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788465695 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2739.569810] Lustre: server umount lustre-OST0001 complete [ 2746.335513] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: (null) [ 2755.019526] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 2770.530679] LustreError: Failed to get MGS log lustre-sptlrpc and no local copy. [ 2775.647495] LustreError: 75258:0:(mgc_request.c:233:do_config_log_add()) MGC192.168.204.108@tcp: failed processing log, type 4: rc = -110 [ 2801.311264] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 2806.955285] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2811.431816] Lustre: 75842: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. [ 2811.467749] Lustre: *** cfs_fail_loc=160e, val=3*** [ 2814.511239] Lustre: 75842:0:(ofd_dev.c:573:ofd_lfsck_out_notify()) lustre-OST0000: Rebuilt crashed LAST_ID files successfully. [ 2824.203809] Lustre: DEBUG MARKER: == sanity-lfsck test 11b: LFSCK can rebuild crashed last_id ========================================================== 16:02:59 (1788465779) [ 2837.494337] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing load_modules_local [ 2849.428565] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2849.895063] LustreError: 75283:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 2849.918093] LustreError: 75283:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 37 previous similar messages [ 2850.033525] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3272 to 0x280000401:3297) [ 2855.413419] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2866.141412] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 2872.332660] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2876.268535] Lustre: 78509:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 2891.231251] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2896.870912] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3207 to 0x2c0000401:3233) [ 2897.054393] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2904.322054] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 2907.027201] Lustre: 80008:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 2911.373038] Lustre: *** cfs_fail_loc=160d, val=0*** [ 2917.068871] Lustre: Failing over lustre-OST0000 [ 2917.302978] Lustre: server umount lustre-OST0000 complete [ 2917.350731] LustreError: 75275:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 2917.370504] LustreError: 75275:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 19 previous similar messages [ 2927.197572] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2927.415464] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 2927.419526] Lustre: Skipped 2 previous similar messages [ 2928.683412] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 2928.688779] Lustre: Skipped 2 previous similar messages [ 2928.727618] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 2928.727671] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 2928.728611] Lustre: *** cfs_fail_loc=215, val=0*** [ 2928.737218] Lustre: Skipped 2 previous similar messages [ 2928.768922] Lustre: Skipped 11 previous similar messages [ 2934.241435] Lustre: *** cfs_fail_loc=215, val=0*** [ 2934.247581] Lustre: Skipped 1 previous similar message [ 2934.775733] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2939.157767] Lustre: 81406: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. [ 2939.166340] Lustre: 81406:0:(ofd_dev.c:573:ofd_lfsck_out_notify()) lustre-OST0000: Rebuilt crashed LAST_ID files successfully. [ 2939.360061] Lustre: *** cfs_fail_loc=215, val=0*** [ 2942.886774] Lustre: Failing over lustre-OST0000 [ 2942.945727] Lustre: lustre-OST0000: Not available for connect from 0@lo (stopping) [ 2942.956755] Lustre: Skipped 1 previous similar message [ 2943.146228] Lustre: server umount lustre-OST0000 complete [ 2951.925591] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 2953.365912] Lustre: *** cfs_fail_loc=215, val=0*** [ 2953.370425] Lustre: Skipped 1 previous similar message [ 2957.732278] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2958.818036] Lustre: *** cfs_fail_loc=215, val=0*** [ 2963.940130] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2972.642201] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2972.655470] Lustre: Skipped 7 previous similar messages [ 2977.247612] Lustre: lustre-MDT0000 is waiting for obd_unlinked_exports more than 8 seconds. The obd refcount = 3. Is it stuck? [ 2977.596479] Lustre: server umount lustre-MDT0000 complete [ 2981.045290] LustreError: 75264:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788465937 with bad export cookie 1022639678451223821 [ 2981.058979] LustreError: 75264:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 2981.282394] Lustre: server umount lustre-MDT0001 complete [ 2994.461746] Lustre: server umount lustre-OST0000 complete [ 3008.466966] Lustre: server umount lustre-OST0001 complete [ 3019.378514] Lustre: DEBUG MARKER: == sanity-lfsck test 12a: single command to trigger LFSCK on all devices ========================================================== 16:06:14 (1788465974) [ 3033.453230] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing load_modules_local [ 3044.400207] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3049.480616] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3050.464891] LustreError: 84649:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3050.481373] LustreError: 84649:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 9 previous similar messages [ 3060.529351] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3066.647889] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3070.165383] Lustre: 85793:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3077.595891] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3084.583761] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3090.283121] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3362 to 0x280000401:3393) [ 3092.832512] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3098.095841] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3207 to 0x2c0000401:3265) [ 3098.819297] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3106.135256] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3109.273608] Lustre: 87662:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 3142.069215] Lustre: DEBUG MARKER: == sanity-lfsck test 12b: auto detect Lustre device ====== 16:08:17 (1788466097) [ 3157.705931] Lustre: DEBUG MARKER: == sanity-lfsck test 13: LFSCK can repair crashed lmm_oi ========================================================== 16:08:32 (1788466112) [ 3158.817125] Lustre: *** cfs_fail_loc=160f, val=0*** [ 3170.969841] Lustre: DEBUG MARKER: == sanity-lfsck test 14a: LFSCK can repair MDT-object with dangling LOV EA reference (1) ========================================================== 16:08:45 (1788466125) [ 3175.460805] Lustre: *** cfs_fail_loc=1610, val=0*** [ 3175.466340] Lustre: Skipped 7 previous similar messages [ 3230.180870] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 3230.187610] LustreError: Skipped 1 previous similar message [ 3230.198296] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3232.721821] Lustre: server umount lustre-MDT0000 complete [ 3236.912840] LustreError: 84632:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788466193 with bad export cookie 1022639678451232277 [ 3236.942765] LustreError: 84632:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 3237.284745] Lustre: server umount lustre-MDT0001 complete [ 3251.852754] Lustre: server umount lustre-OST0000 complete [ 3267.393979] Lustre: server umount lustre-OST0001 complete [ 3285.246514] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing load_modules_local [ 3299.741203] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3306.467736] LustreError: 92389:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3306.479566] LustreError: 92389:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 11 previous similar messages [ 3308.314870] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3320.369051] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3326.778335] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3329.855611] Lustre: 93530:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3338.183873] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3345.336581] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3345.714121] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:116 to 0x280000400:161) [ 3345.727594] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3554 to 0x280000401:3585) [ 3354.440085] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3359.745438] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:116 to 0x2c0000400:161) [ 3359.756256] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3317 to 0x2c0000401:3361) [ 3361.660673] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3370.811965] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3374.735084] Lustre: 95403:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 3383.174986] Lustre: DEBUG MARKER: == sanity-lfsck test 14b: LFSCK can repair MDT-object with dangling LOV EA reference (2) ========================================================== 16:12:18 (1788466338) [ 3385.790256] Lustre: 94183:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 256 < left 278, rollback = 2 [ 3385.808155] Lustre: 94183:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 1360 previous similar messages [ 3385.813901] Lustre: 94183:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 3385.828330] Lustre: 94183:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1360 previous similar messages [ 3385.836620] Lustre: 94183:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3385.846052] Lustre: 94183:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1360 previous similar messages [ 3385.858108] Lustre: 94183:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 3385.865738] Lustre: 94183:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1360 previous similar messages [ 3385.873553] Lustre: 94183:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 3385.877786] Lustre: 94183:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1360 previous similar messages [ 3385.882823] Lustre: 94183:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3385.888538] Lustre: 94183:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1360 previous similar messages [ 3389.575861] Lustre: *** cfs_fail_loc=1610, val=0*** [ 3389.579621] Lustre: Skipped 63 previous similar messages [ 3416.032430] 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 [ 3416.035382] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3416.044587] Lustre: Skipped 16 previous similar messages [ 3416.067063] Lustre: Skipped 7 previous similar messages [ 3419.461769] Lustre: server umount lustre-MDT0000 complete [ 3423.555869] LustreError: 92370:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788466380 with bad export cookie 1022639678451260690 [ 3423.557354] LustreError: MGC192.168.204.108@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3423.564138] LustreError: 92370:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 3423.571494] LustreError: Skipped 2 previous similar messages [ 3423.849569] Lustre: server umount lustre-MDT0001 complete [ 3437.608199] Lustre: server umount lustre-OST0000 complete [ 3452.155625] Lustre: server umount lustre-OST0001 complete [ 3468.636777] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing load_modules_local [ 3480.928995] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3481.802307] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3481.807682] Lustre: Skipped 13 previous similar messages [ 3487.173884] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3496.184876] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3496.422625] Lustre: lustre-MDT0001: Not available for connect from 0@lo (not set up) [ 3503.460672] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3507.432170] Lustre: 99437:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 3515.104299] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3521.537110] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:116 to 0x280000400:193) [ 3521.946929] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3526.639523] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:3682 to 0x280000401:3713) [ 3530.865599] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3536.367043] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:3317 to 0x2c0000401:3393) [ 3536.369372] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:116 to 0x2c0000400:193) [ 3537.360845] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3544.411039] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3556.265126] Lustre: DEBUG MARKER: == sanity-lfsck test 15a: LFSCK can repair unmatched MDT-object/OST-object pairs (1) ========================================================== 16:15:11 (1788466511) [ 3560.115320] Lustre: *** cfs_fail_loc=1611, val=0*** [ 3560.118743] Lustre: Skipped 63 previous similar messages [ 3560.363339] Lustre: *** cfs_fail_loc=1611, val=0*** [ 3570.664059] Lustre: DEBUG MARKER: == sanity-lfsck test 15b: LFSCK can repair unmatched MDT-object/OST-object pairs (2) ========================================================== 16:15:26 (1788466526) [ 3572.939231] Lustre: *** cfs_fail_loc=1612, val=0*** [ 3573.024897] Lustre: *** cfs_fail_loc=1612, val=0*** [ 3573.033741] Lustre: Skipped 3 previous similar messages [ 3583.725971] Lustre: DEBUG MARKER: == sanity-lfsck test 15c: LFSCK can repair unmatched MDT-object/OST-object pairs (3) ========================================================== 16:15:38 (1788466538) [ 3585.304947] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_15c MDS newer than 2.7.55, LU-6475 [ 3587.054966] Lustre: DEBUG MARKER: == sanity-lfsck test 15d: LFSCK don't crash upon dir migration failure ========================================================== 16:15:42 (1788466542) [ 3592.568344] Lustre: *** cfs_fail_loc=1709, val=0*** [ 3592.571682] LustreError: 98305:0:(mdt_reint.c:2644:mdt_reint_migrate()) lustre-MDT0000: migrate [0x240002340:0x6c:0x0]/f98 failed: rc = -5 [ 3659.240544] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3659.248765] Lustre: Skipped 2 previous similar messages [ 3664.108326] Lustre: server umount lustre-MDT0000 complete [ 3672.853401] LustreError: 98279:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788466629 with bad export cookie 1022639678451275432 [ 3672.879182] LustreError: 98279:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 3673.121243] Lustre: server umount lustre-MDT0001 complete [ 3690.847140] Lustre: 16414:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788466631/real 1788466631] req@ffff90fd31b72680 x1875339875471616/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788466647 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3692.080885] Lustre: server umount lustre-OST0000 complete [ 3694.047096] Lustre: 16413:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788466634/real 1788466634] req@ffff90fc0dff2300 x1875339875471872/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788466650 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3696.041766] Lustre: 16414:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788466636/real 1788466636] req@ffff90fc0dff0a80 x1875339875472128/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788466652 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3699.183962] Lustre: 16413:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788466639/real 1788466639] req@ffff90fc0e5d0000 x1875339875472512/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788466655 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3702.105319] Lustre: server umount lustre-OST0001 complete [ 3718.842953] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing unload_modules_local [ 3721.855453] Key type lgssc unregistered [ 3722.189774] LNet: 105140:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 3722.196232] LNetError: 105140:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 3722.219923] LNet: Removed LNI 192.168.204.108@tcp [ 3723.222470] Key type .llcrypt unregistered [ 3723.229875] Key type ._llcrypt unregistered [ 3746.124051] Key type ._llcrypt registered [ 3746.133300] Key type .llcrypt registered [ 3746.270922] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_hostid [ 3761.666790] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing load_modules_local [ 3763.231375] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 3763.301054] alg: No test for adler32 (adler32-zlib) [ 3764.396043] Lustre: Lustre: Build Version: 2.17.58_2_gbb63b80 [ 3764.743319] LNet: Added LNI 192.168.204.108@tcp [8/256/0/180] [ 3766.432759] Key type lgssc registered [ 3767.585713] Lustre: Echo OBD driver; http://www.lustre.org/ [ 3818.788948] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing load_modules_local [ 3832.593310] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 3832.614112] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3833.902641] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 3833.941478] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 3834.063847] Lustre: lustre-MDT0000: new disk, initializing [ 3834.216387] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3834.245834] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 3839.616120] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3853.871150] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 3854.005329] Lustre: 109595:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 3854.032478] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 3854.036978] Lustre: Skipped 1 previous similar message [ 3854.124684] Lustre: lustre-MDT0001: new disk, initializing [ 3854.227345] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 3854.251978] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 3854.267887] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 3859.231847] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3864.331604] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 3874.377737] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3874.618616] Lustre: lustre-OST0000: new disk, initializing [ 3874.635400] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 3874.657808] Lustre: 111534:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 3874.722597] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 3882.178814] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3883.068532] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 3883.081852] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 3883.185603] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 3896.424817] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 3896.608911] Lustre: lustre-OST0001: new disk, initializing [ 3896.615738] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 3896.623844] Lustre: 112559:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 3896.692876] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 3902.554766] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3906.640451] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 3906.647683] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 3906.719659] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 3915.063976] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 3925.250559] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 3930.850506] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 16:21:25 (1788466885) === [ 3937.486089] Lustre: DEBUG MARKER: == sanity-lfsck test 16: LFSCK can repair inconsistent MDT-object/OST-object owner ========================================================== 16:21:33 (1788466893) [ 3937.829501] Lustre: 109605:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 251 < left 278, rollback = 2 [ 3937.847872] Lustre: 109605:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 3937.856815] Lustre: 109605:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3937.866036] Lustre: 109605:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/2 [ 3937.871326] Lustre: 109605:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 3937.877193] Lustre: 109605:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3938.420569] Lustre: 109603:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 252 < left 278, rollback = 2 [ 3938.439059] Lustre: 109603:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 9 previous similar messages [ 3938.447052] Lustre: 109603:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 3938.458652] Lustre: 109603:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3938.470680] Lustre: 109603:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3938.485582] Lustre: 109603:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3938.497858] Lustre: 109603:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/1, punch: 0/0/0, quota 7/369/2 [ 3938.513225] Lustre: 109603:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3938.532778] Lustre: 109603:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/1, delete: 0/0/0 [ 3938.545395] Lustre: 109603:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3938.555314] Lustre: 109603:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3938.564658] Lustre: 109603:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3939.427813] Lustre: 113454:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 260 < left 278, rollback = 2 [ 3939.435412] Lustre: 113454:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 152 previous similar messages [ 3939.451466] Lustre: 109605:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 3939.457412] Lustre: 109605:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 155 previous similar messages [ 3939.477211] Lustre: 109603:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3939.485208] Lustre: 109603:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 158 previous similar messages [ 3939.506320] Lustre: 113454:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 2/20/0, punch: 0/0/0, quota 7/369/0 [ 3939.516099] Lustre: 113454:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 161 previous similar messages [ 3939.541098] Lustre: 109605:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 3939.546814] Lustre: 109605:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 164 previous similar messages [ 3939.568765] Lustre: 109603:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3939.574341] Lustre: 109603:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 167 previous similar messages [ 3941.141503] Lustre: *** cfs_fail_loc=1613, val=0*** [ 3952.025575] Lustre: DEBUG MARKER: == sanity-lfsck test 17: LFSCK can repair multiple references ========================================================== 16:21:47 (1788466907) [ 3953.200890] Lustre: 113454:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 256 < left 278, rollback = 2 [ 3953.207344] Lustre: 113454:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 146 previous similar messages [ 3953.213146] Lustre: 113454:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/2, destroy: 0/0/0 [ 3953.218325] Lustre: 113454:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 143 previous similar messages [ 3953.222905] Lustre: 113454:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3953.231291] Lustre: 113454:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 140 previous similar messages [ 3953.237187] Lustre: 113454:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 3953.242357] Lustre: 113454:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 137 previous similar messages [ 3953.248332] Lustre: 113454:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 3953.253745] Lustre: 113454:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 134 previous similar messages [ 3953.259709] Lustre: 113454:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3953.265395] Lustre: 113454:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 131 previous similar messages [ 3954.202911] Lustre: *** cfs_fail_loc=1614, val=0*** [ 3958.417672] Lustre: 111525:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 259 < left 275, rollback = 2 [ 3958.424326] Lustre: 111525:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 11 previous similar messages [ 3958.428970] Lustre: 111525:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 0/0/0, destroy: 0/0/0 [ 3958.436696] Lustre: 111525:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3958.445588] Lustre: 111525:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/1, xattr_set: 3/275/0 [ 3958.460471] Lustre: 111525:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3958.471292] Lustre: 111525:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/9/0, punch: 1/4/0, quota 7/225/0 [ 3958.485085] Lustre: 111525:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3958.493167] Lustre: 111525:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 0/0/0, delete: 0/0/0 [ 3958.498474] Lustre: 111525:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3958.502201] Lustre: 111525:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3958.506211] Lustre: 111525:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 11 previous similar messages [ 3965.432312] Lustre: DEBUG MARKER: == sanity-lfsck test 18a: Find out orphan OST-object and repair it (1) ========================================================== 16:22:00 (1788466920) [ 3966.523667] Lustre: 109603:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0001: opcode 2: before 258 < left 278, rollback = 2 [ 3966.530264] Lustre: 109603:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 13 previous similar messages [ 3966.541946] Lustre: 109603:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 3966.555216] Lustre: 109603:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 13 previous similar messages [ 3966.561312] Lustre: 109603:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3966.566159] Lustre: 109603:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 13 previous similar messages [ 3966.570657] Lustre: 109603:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 3/29/1, punch: 0/0/0, quota 1/3/0 [ 3966.575135] Lustre: 109603:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 13 previous similar messages [ 3966.581935] Lustre: 109603:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 2/33/0, delete: 0/0/0 [ 3966.592575] Lustre: 109603:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 13 previous similar messages [ 3966.599067] Lustre: 109603:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 3966.604706] Lustre: 109603:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 13 previous similar messages [ 3968.248710] Lustre: *** cfs_fail_loc=1615, val=0*** [ 3968.256678] Lustre: Skipped 1 previous similar message [ 3969.345625] Lustre: *** cfs_fail_loc=1615, val=0*** [ 3969.349916] Lustre: Skipped 1 previous similar message [ 3987.032447] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_18b skipping excluded test 18b [ 3988.850850] Lustre: DEBUG MARKER: == sanity-lfsck test 18c: Find out orphan OST-object and repair it (3) ========================================================== 16:22:24 (1788466944) [ 3989.228776] Lustre: 109604:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 259 < left 278, rollback = 2 [ 3989.240577] Lustre: 109604:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 9 previous similar messages [ 3989.250243] Lustre: 109604:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 3989.261026] Lustre: 109604:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3989.267173] Lustre: 109604:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 3989.273964] Lustre: 109604:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3989.284848] Lustre: 109604:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 3989.300654] Lustre: 109604:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3989.307223] Lustre: 109604:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/1, delete: 0/0/0 [ 3989.314539] Lustre: 109604:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3989.321144] Lustre: 109604:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 3989.331582] Lustre: 109604:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 9 previous similar messages [ 3991.431637] Lustre: *** cfs_fail_loc=1617, val=0*** [ 3991.486755] Lustre: *** cfs_fail_loc=1617, val=0*** [ 3993.378655] Lustre: *** cfs_fail_loc=1616, val=0*** [ 3993.382711] Lustre: Skipped 3 previous similar messages [ 4010.767949] Lustre: DEBUG MARKER: == sanity-lfsck test 18d: Find out orphan OST-object and repair it (4) ========================================================== 16:22:46 (1788466966) [ 4012.690476] Lustre: *** cfs_fail_loc=1618, val=0*** [ 4012.698620] Lustre: Skipped 5 previous similar messages [ 4048.870959] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4048.876472] 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 [ 4048.904874] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4050.404834] 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 [ 4050.411798] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4050.434289] Lustre: Skipped 1 previous similar message [ 4050.436709] Lustre: Skipped 1 previous similar message [ 4052.725805] Lustre: server umount lustre-MDT0000 complete [ 4056.072344] LustreError: 112558:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788467012 with bad export cookie 15654669585854970995 [ 4056.073618] LustreError: MGC192.168.204.108@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4056.085751] LustreError: 112558:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 4056.510914] Lustre: server umount lustre-MDT0001 complete [ 4070.995704] Lustre: server umount lustre-OST0000 complete [ 4085.291460] Lustre: server umount lustre-OST0001 complete [ 4100.358422] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing load_modules_local [ 4108.834573] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4109.176545] LustreError: 118268:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4109.195704] LustreError: 118268:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 5 previous similar messages [ 4109.269589] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4113.693986] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4114.403125] LustreError: 118269:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4118.504674] LustreError: 118268:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4122.107872] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4122.423332] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 4127.221206] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4130.028178] Lustre: 119409:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 4136.864144] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4143.613509] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4147.433598] LustreError: 120309:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4147.437033] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:4 to 0x280000400:33) [ 4151.834273] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4152.034670] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 4152.041523] Lustre: Skipped 1 previous similar message [ 4154.120028] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:116 to 0x280000401:161) [ 4154.132100] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:4 to 0x2c0000401:33) [ 4154.133188] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:33) [ 4157.935827] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4165.769321] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4169.727841] Lustre: 121281:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 4184.069979] Lustre: DEBUG MARKER: == sanity-lfsck test 18e: Find out orphan OST-object and repair it (5) ========================================================== 16:25:39 (1788467139) [ 4184.457537] Lustre: 118264:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 252 < left 278, rollback = 2 [ 4184.473285] Lustre: 118264:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 46 previous similar messages [ 4184.479052] Lustre: 118264:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4184.485199] Lustre: 118264:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4184.492119] Lustre: 118264:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4184.498723] Lustre: 118264:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4184.508746] Lustre: 118264:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/1 [ 4184.518448] Lustre: 118264:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4184.527223] Lustre: 118264:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/3, delete: 0/0/0 [ 4184.531332] Lustre: 118264:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4184.537995] Lustre: 118264:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4184.543341] Lustre: 118264:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 46 previous similar messages [ 4186.427877] Lustre: *** cfs_fail_loc=1618, val=0*** [ 4186.437330] Lustre: Skipped 3 previous similar messages [ 4219.872626] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4219.884666] 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 [ 4219.915328] Lustre: Skipped 1 previous similar message [ 4219.925264] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4219.930342] Lustre: Skipped 2 previous similar messages [ 4225.924840] Lustre: server umount lustre-MDT0000 complete [ 4226.017038] LustreError: 119016:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4226.043082] LustreError: 119016:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 3 previous similar messages [ 4229.654425] LustreError: 118250:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788467186 with bad export cookie 15654669585854986248 [ 4229.658900] LustreError: MGC192.168.204.108@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4229.663926] LustreError: 118250:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 4 previous similar messages [ 4230.046964] Lustre: server umount lustre-MDT0001 complete [ 4244.396144] Lustre: server umount lustre-OST0000 complete [ 4246.496446] Lustre: 106753:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788467187/real 1788467187] req@ffff90fc0b0e0000 x1875343280720640/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788467203 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4246.534868] 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 [ 4246.552839] Lustre: Skipped 3 previous similar messages [ 4247.379521] Lustre: server umount lustre-OST0001 complete [ 4260.820693] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing load_modules_local [ 4269.860837] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4270.218556] LustreError: 123844:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4270.288527] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4274.369610] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4281.984503] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4286.282964] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4288.853121] Lustre: 124983:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 4294.429851] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4294.630784] LustreError: 125336:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4294.651966] LustreError: 125336:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 2 previous similar messages [ 4299.757869] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:166 to 0x280000401:193) [ 4299.816916] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4306.927351] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:4 to 0x280000400:65) [ 4307.015291] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 4312.579094] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:4 to 0x2c0000401:65) [ 4312.582123] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:3 to 0x2c0000400:65) [ 4313.082488] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4320.686033] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4324.347738] Lustre: 126851:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 4328.702537] Lustre: 124575:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-OST0000: opcode 2: before 252 < left 260, rollback = 2 [ 4328.718747] Lustre: 124575:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 21 previous similar messages [ 4328.726119] Lustre: 124575:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/4, destroy: 0/0/0 [ 4328.745808] Lustre: 124575:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4328.752450] Lustre: *** cfs_fail_loc=1602, val=10*** [ 4328.755938] Lustre: 124575:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 0/0/0, xattr_set: 1/260/0 [ 4328.780175] Lustre: 124575:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4328.793147] Lustre: 124575:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/9/0, punch: 0/0/0, quota 4/150/2 [ 4328.802920] Lustre: 124575:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4328.818313] Lustre: 124575:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 1/17/2, delete: 0/0/0 [ 4328.833604] Lustre: 124575:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4328.844980] Lustre: 124575:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 0/0/0, ref_del: 0/0/0 [ 4328.857024] Lustre: 124575:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 21 previous similar messages [ 4351.688479] Lustre: DEBUG MARKER: == sanity-lfsck test 18f: Skip the failed OST(s) when handle orphan OST-objects ========================================================== 16:28:27 (1788467307) [ 4353.907041] Lustre: *** cfs_fail_loc=1616, val=0*** [ 4353.914909] Lustre: Skipped 3 previous similar messages [ 4359.789583] Lustre: *** cfs_fail_loc=161c, val=0*** [ 4375.037587] Lustre: DEBUG MARKER: == sanity-lfsck test 18g: Find out orphan OST-object and repair it (7) ========================================================== 16:28:50 (1788467330) [ 4376.853727] Lustre: *** cfs_fail_loc=162e, val=0*** [ 4387.256833] Lustre: DEBUG MARKER: == sanity-lfsck test 18h: LFSCK can repair crashed PFL extent range ========================================================== 16:29:03 (1788467343) [ 4390.556899] Lustre: *** cfs_fail_loc=162f, val=0*** [ 4390.560754] Lustre: Skipped 9 previous similar messages [ 4403.021582] Lustre: DEBUG MARKER: == sanity-lfsck test 19a: OST-object inconsistency self detect ========================================================== 16:29:18 (1788467358) [ 4412.673797] Lustre: DEBUG MARKER: == sanity-lfsck test 19b: OST-object inconsistency self repair ========================================================== 16:29:28 (1788467368) [ 4414.975986] Lustre: *** cfs_fail_loc=1611, val=0*** [ 4415.011824] Lustre: *** cfs_fail_loc=1611, val=0*** [ 4415.014707] Lustre: Skipped 3 previous similar messages [ 4419.067811] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.204.8@tcp inode [0x2000013a1:0x1f:0x0] object 0x280000401:203 extent [0-4095], client returned csum 0 (type 4), server csum 703fb3ad (type 4) [ 4420.157336] LustreError: lustre-OST0000: BAD READ CHECKSUM: should have changed on the client or in transit: from 192.168.204.8@tcp inode [0x2000013a1:0x20:0x0] object 0x280000401:204 extent [0-4095], client returned csum 0 (type 4), server csum 7cbb935c (type 4) [ 4425.899977] Lustre: DEBUG MARKER: == sanity-lfsck test 20a: Handle the orphan with dummy LOV EA slot properly ========================================================== 16:29:41 (1788467381) [ 4444.176363] Lustre: DEBUG MARKER: == sanity-lfsck test 20b: Handle the orphan with dummy LOV EA slot properly - PFL case ========================================================== 16:29:59 (1788467399) [ 4449.429103] Lustre: DEBUG MARKER: == sanity-lfsck test 21: run all LFSCK components by default ========================================================== 16:30:05 (1788467405) [ 4458.719340] Lustre: DEBUG MARKER: == sanity-lfsck test 22a: LFSCK can repair unmatched pairs (1) ========================================================== 16:30:14 (1788467414) [ 4459.714958] Lustre: 123839:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 257 < left 278, rollback = 2 [ 4459.722984] Lustre: 123839:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 438 previous similar messages [ 4459.728681] Lustre: 123839:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/1, destroy: 0/0/0 [ 4459.733855] Lustre: 123839:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 438 previous similar messages [ 4459.739637] Lustre: 123839:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4459.745420] Lustre: 123839:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 438 previous similar messages [ 4459.750554] Lustre: 123839:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 4459.756562] Lustre: 123839:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 438 previous similar messages [ 4459.762093] Lustre: 123839:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 4459.767373] Lustre: 123839:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 438 previous similar messages [ 4459.771833] Lustre: 123839:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4459.776776] Lustre: 123839:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 438 previous similar messages [ 4460.781681] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4460.786499] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4460.788669] Lustre: Skipped 1 previous similar message [ 4468.353709] Lustre: DEBUG MARKER: == sanity-lfsck test 22b: LFSCK can repair unmatched pairs (2) ========================================================== 16:30:24 (1788467424) [ 4469.614246] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4469.619650] Lustre: *** cfs_fail_loc=161e, val=0*** [ 4477.602627] Lustre: DEBUG MARKER: == sanity-lfsck test 23a: LFSCK can repair dangling name entry (1) ========================================================== 16:30:33 (1788467433) [ 4479.135019] Lustre: *** cfs_fail_loc=1620, val=0*** [ 4491.839684] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_23b skipping excluded test 23b [ 4493.311351] Lustre: DEBUG MARKER: == sanity-lfsck test 23c: LFSCK can repair dangling name entry (3) ========================================================== 16:30:48 (1788467448) [ 4498.349760] Lustre: *** cfs_fail_loc=1621, val=127*** [ 4498.357554] Lustre: Skipped 1 previous similar message [ 4501.012717] Lustre: *** cfs_fail_loc=1602, val=10*** [ 4520.154183] Lustre: DEBUG MARKER: == sanity-lfsck test 23d: LFSCK can repair a dangling name entry to a remote object ========================================================== 16:31:15 (1788467475) [ 4522.214580] Lustre: Failing over lustre-MDT0000 [ 4522.468296] 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 [ 4522.478866] LustreError: 126617:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4522.480753] Lustre: Skipped 2 previous similar messages [ 4522.510043] LustreError: 126617:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 7 previous similar messages [ 4522.562774] Lustre: server umount lustre-MDT0000 complete [ 4531.191223] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4531.317968] LustreError: MGC192.168.204.108@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4531.584437] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4531.592141] Lustre: Skipped 3 previous similar messages [ 4531.635307] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4534.784299] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4535.882971] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4536.821987] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4536.869732] Lustre: lustre-MDT0000: Recovery over after 0:02, of 2 clients 2 recovered and 0 were evicted. [ 4536.900989] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:130 to 0x2c0000401:161) [ 4536.902872] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:265 to 0x280000401:289) [ 4537.832650] LustreError: 128163:0:(mdt_open.c:1324:mdt_cross_open()) lustre-MDT0000: [0x2000013a3:0x82:0x0] doesn't exist!: rc = -14 [ 4547.130276] Lustre: DEBUG MARKER: == sanity-lfsck test 24: LFSCK can repair multiple-referenced name entry ========================================================== 16:31:42 (1788467502) [ 4549.119244] Lustre: *** cfs_fail_loc=1622, val=0*** [ 4549.286867] Lustre: *** cfs_fail_loc=1622, val=0*** [ 4549.291231] Lustre: Skipped 1 previous similar message [ 4558.662471] Lustre: DEBUG MARKER: == sanity-lfsck test 25: LFSCK can repair bad file type in the name entry ========================================================== 16:31:54 (1788467514) [ 4560.042628] Lustre: *** cfs_fail_loc=1623, val=0*** [ 4568.825530] Lustre: DEBUG MARKER: == sanity-lfsck test 26a: LFSCK can add the missing local name entry back to the namespace ========================================================== 16:32:04 (1788467524) [ 4570.045553] Lustre: *** cfs_fail_loc=1624, val=0*** [ 4579.301877] Lustre: DEBUG MARKER: == sanity-lfsck test 26b: LFSCK can add the missing remote name entry back to the namespace ========================================================== 16:32:14 (1788467534) [ 4591.669573] Lustre: DEBUG MARKER: == sanity-lfsck test 27a: LFSCK can recreate the lost local parent directory as orphan ========================================================== 16:32:27 (1788467547) [ 4593.069821] Lustre: *** cfs_fail_loc=1624, val=0*** [ 4593.076331] Lustre: Skipped 1 previous similar message [ 4603.632457] Lustre: DEBUG MARKER: == sanity-lfsck test 27b: LFSCK can recreate the lost remote parent directory as orphan ========================================================== 16:32:39 (1788467559) [ 4615.665502] Lustre: DEBUG MARKER: == sanity-lfsck test 28: Skip the failed MDT(s) when handle orphan MDT-objects ========================================================== 16:32:51 (1788467571) [ 4622.448076] Lustre: *** cfs_fail_loc=161c, val=0*** [ 4622.453594] Lustre: Skipped 1 previous similar message [ 4635.402573] Lustre: DEBUG MARKER: == sanity-lfsck test 29b: LFSCK can repair bad nlink count (2) ========================================================== 16:33:10 (1788467590) [ 4637.027900] Lustre: *** cfs_fail_loc=1626, val=0*** [ 4637.033113] Lustre: Skipped 4 previous similar messages [ 4645.227422] Lustre: DEBUG MARKER: == sanity-lfsck test 29c: verify linkEA size limitation == 16:33:21 (1788467601) [ 4669.159710] Lustre: DEBUG MARKER: == sanity-lfsck test 29d: accessing non-existing inode shouldn't turn fs read-only (ldiskfs) ========================================================== 16:33:44 (1788467624) [ 4671.185798] LustreError: 123841:0:(osd_handler.c:284:osd_idc_find_or_init()) lustre-MDT0000: cannot lookup FID [0x2000013a3:0x9e:0x0]: rc = -2 [ 4675.928544] Lustre: DEBUG MARKER: == sanity-lfsck test 30: LFSCK can recover the orphans from backend /lost+found ========================================================== 16:33:51 (1788467631) [ 4701.370948] Lustre: Failing over lustre-MDT0000 [ 4701.546289] Lustre: server umount lustre-MDT0000 complete [ 4705.770375] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4705.783068] 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 [ 4705.793763] LustreError: 141513:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4705.794485] Lustre: Skipped 3 previous similar messages [ 4705.809428] LustreError: 141513:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 9 previous similar messages [ 4708.929177] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 4709.041437] LustreError: MGC192.168.204.108@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4709.225246] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4709.269608] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4712.404739] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4714.465107] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4714.473984] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4714.485718] Lustre: Skipped 3 previous similar messages [ 4714.500572] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4714.534476] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:166 to 0x2c0000401:193) [ 4714.539463] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:295 to 0x280000401:321) [ 4720.649729] Lustre: DEBUG MARKER: == sanity-lfsck test 31a: The LFSCK can find/repair the name entry with bad name hash (1) ========================================================== 16:34:36 (1788467676) [ 4720.880638] Lustre: 126617:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 4720.892676] Lustre: 126617:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 474 previous similar messages [ 4720.898397] Lustre: 126617:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 4720.903344] Lustre: 126617:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 474 previous similar messages [ 4720.909149] Lustre: 126617:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 4720.915026] Lustre: 126617:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 474 previous similar messages [ 4720.920497] Lustre: 126617:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 4720.928428] Lustre: 126617:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 474 previous similar messages [ 4720.933641] Lustre: 126617:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 4720.937364] Lustre: 126617:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 474 previous similar messages [ 4720.942742] Lustre: 126617:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 4720.948477] Lustre: 126617:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 474 previous similar messages [ 4730.297678] Lustre: DEBUG MARKER: == sanity-lfsck test 31b: The LFSCK can find/repair the name entry with bad name hash (2) ========================================================== 16:34:46 (1788467686) [ 4741.524553] Lustre: DEBUG MARKER: == sanity-lfsck test 31c: Re-generate the lost master LMV EA for striped directory ========================================================== 16:34:57 (1788467697) [ 4742.576682] Lustre: *** cfs_fail_loc=1629, val=0*** [ 4742.579095] Lustre: Skipped 7 previous similar messages [ 4774.217060] Lustre: DEBUG MARKER: == sanity-lfsck test 31d: Set broken striped directory (modified after broken) as read-only ========================================================== 16:35:29 (1788467729) [ 4779.442826] Lustre: Failing over lustre-MDT0000 [ 4779.683260] Lustre: server umount lustre-MDT0000 complete [ 4781.026698] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4781.033927] 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 [ 4781.048986] Lustre: Skipped 4 previous similar messages [ 4786.482043] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4786.615909] LustreError: MGC192.168.204.108@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4786.860988] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4790.515091] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4792.291916] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4792.298954] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4792.305432] Lustre: Skipped 3 previous similar messages [ 4792.331404] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4792.362752] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:295 to 0x280000401:353) [ 4792.363136] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:166 to 0x2c0000401:225) [ 4798.099737] Lustre: Failing over lustre-MDT0000 [ 4798.307343] Lustre: server umount lustre-MDT0000 complete [ 4802.533253] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 4804.617155] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 4804.694310] LustreError: MGC192.168.204.108@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4804.897783] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4807.679928] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4808.232983] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4810.216474] Lustre: lustre-MDT0000-lwp-MDT0001: Connection restored to 0@lo (at 0@lo) [ 4810.228939] Lustre: Skipped 3 previous similar messages [ 4810.246966] Lustre: lustre-MDT0000: Recovery over after 0:03, of 2 clients 2 recovered and 0 were evicted. [ 4810.293353] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:295 to 0x280000401:385) [ 4810.295450] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:227 to 0x2c0000401:257) [ 4815.451605] Lustre: DEBUG MARKER: == sanity-lfsck test 31e: Re-generate the lost slave LMV EA for striped directory (1) ========================================================== 16:36:11 (1788467771) [ 4824.894426] Lustre: DEBUG MARKER: == sanity-lfsck test 31f: Re-generate the lost slave LMV EA for striped directory (2) ========================================================== 16:36:20 (1788467780) [ 4838.883402] Lustre: DEBUG MARKER: == sanity-lfsck test 31g: Repair the corrupted slave LMV EA ========================================================== 16:36:33 (1788467793) [ 4879.046682] Lustre: DEBUG MARKER: == sanity-lfsck test 31h: Repair the corrupted shard's name entry ========================================================== 16:37:14 (1788467834) [ 4880.216379] Lustre: *** cfs_fail_loc=162c, val=0*** [ 4880.228401] Lustre: Skipped 13 previous similar messages [ 4893.289249] Lustre: DEBUG MARKER: == sanity-lfsck test 32a: stop LFSCK when some OST failed ========================================================== 16:37:28 (1788467848) [ 4903.105240] LustreError: 148352:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d sleeping for 3000ms [ 4905.686397] Lustre: Failing over lustre-OST0000 [ 4905.955627] LustreError: lustre-OST0000-osc-MDT0001: operation ost_statfs to node 0@lo failed: rc = -107 [ 4905.967435] 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 [ 4905.982400] Lustre: Skipped 4 previous similar messages [ 4906.010543] LustreError: 125337:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4906.037867] LustreError: 125337:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 13 previous similar messages [ 4906.091417] Lustre: server umount lustre-OST0000 complete [ 4906.192441] LustreError: 148352:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d awake [ 4906.199181] LustreError: 148352:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout id 162d sleeping for 3000ms [ 4909.063348] LustreError: 148352:0:(lfsck_layout.c:4529:lfsck_layout_assistant_handler_p1()) cfs_fail_timeout interrupted [ 4920.571156] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 4920.731813] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 4922.157750] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4922.193374] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 4922.193459] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 4922.218827] Lustre: Skipped 3 previous similar messages [ 4925.695203] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4935.096334] Lustre: DEBUG MARKER: == sanity-lfsck test 32b: stop LFSCK when some MDT failed ========================================================== 16:38:10 (1788467890) [ 4949.037781] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing load_modules_local [ 4967.744380] Lustre: 151164:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 4990.481877] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 4994.452235] Lustre: 152298:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 5004.378283] LustreError: 152410:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d sleeping for 3000ms [ 5006.799359] Lustre: Failing over lustre-MDT0001 [ 5007.431141] LustreError: 152410:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d awake [ 5007.431531] LustreError: 152409:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout id 162d sleeping for 3000ms [ 5007.433077] LustreError: lustre-MDT0001-osp-MDT0000: operation out_update to node 0@lo failed: rc = -107 [ 5007.433100] 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 [ 5007.433103] Lustre: Skipped 1 previous similar message [ 5007.436814] Lustre: lustre-MDT0001: Not available for connect from 0@lo (stopping) [ 5007.436823] Lustre: Skipped 4 previous similar messages [ 5007.439772] LustreError: 152410:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) Skipped 1 previous similar message [ 5007.500298] LustreError: 152409:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) Skipped 1 previous similar message [ 5007.685445] Lustre: server umount lustre-MDT0001 complete [ 5010.433261] LustreError: 152409:0:(lfsck_striped_dir.c:1762:lfsck_namespace_verify_stripe_slave()) cfs_fail_timeout interrupted [ 5020.674689] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,user_xattr,no_mbcache,nodelalloc [ 5021.131594] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 5021.139790] Lustre: Skipped 3 previous similar messages [ 5021.170754] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 5025.794351] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5026.275159] Lustre: lustre-MDT0001: Will be in recovery for at least 1:00, or until 1 client reconnects [ 5026.284561] Lustre: lustre-MDT0001-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 5026.299778] Lustre: Skipped 1 previous similar message [ 5026.318653] Lustre: lustre-MDT0001: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 5026.406672] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:69 to 0x2c0000400:97) [ 5026.411274] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:70 to 0x280000400:97) [ 5034.469487] Lustre: DEBUG MARKER: == sanity-lfsck test 33: check LFSCK paramters =========== 16:39:49 (1788467989) [ 5049.158563] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing load_modules_local [ 5067.127930] Lustre: 155132:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 5086.486766] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5089.355236] Lustre: 156266:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 5107.641420] Lustre: DEBUG MARKER: == sanity-lfsck test 34: LFSCK can rebuild the lost agent object ========================================================== 16:41:02 (1788468062) [ 5109.204738] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_34 Only valid for ZFS backend [ 5110.606208] Lustre: DEBUG MARKER: == sanity-lfsck test 35: LFSCK can rebuild the lost agent entry ========================================================== 16:41:06 (1788468066) [ 5116.799897] Lustre: *** cfs_fail_loc=1631, val=0*** [ 5127.837563] Lustre: server umount lustre-MDT0000 complete [ 5128.676671] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 5130.461264] LustreError: 123825:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788468087 with bad export cookie 15654669585855059055 [ 5130.463414] LustreError: MGC192.168.204.108@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5130.469224] LustreError: 123825:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 5130.704960] Lustre: server umount lustre-MDT0001 complete [ 5144.138978] Lustre: server umount lustre-OST0000 complete [ 5156.723182] Lustre: server umount lustre-OST0001 complete [ 5170.659480] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing load_modules_local [ 5182.776223] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5183.412757] LustreError: 159023:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0001: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 5183.447041] LustreError: 159023:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 18 previous similar messages [ 5187.073126] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5197.268676] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5203.032956] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5206.549758] Lustre: 160163:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/debug_raw_pointers=Y (mode = 0) failed: rc = -17 [ 5213.634413] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5221.248452] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5223.161542] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:70 to 0x280000400:129) [ 5229.546508] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:540 to 0x280000401:577) [ 5230.551989] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5236.219586] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:412 to 0x2c0000401:449) [ 5236.221663] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:69 to 0x2c0000400:129) [ 5238.179874] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5247.488954] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5251.797231] Lustre: 162034:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 5262.623272] Lustre: DEBUG MARKER: == sanity-lfsck test 36a: rebuild LOV EA for mirrored file (1) ========================================================== 16:43:37 (1788468217) [ 5264.360868] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36a needs >= 3 OSTs [ 5266.334136] Lustre: DEBUG MARKER: == sanity-lfsck test 36b: rebuild LOV EA for mirrored file (2) ========================================================== 16:43:41 (1788468221) [ 5268.134748] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36b needs >= 3 OSTs [ 5269.836719] Lustre: DEBUG MARKER: == sanity-lfsck test 36c: rebuild LOV EA for mirrored file (3) ========================================================== 16:43:45 (1788468225) [ 5271.576526] Lustre: DEBUG MARKER: SKIP: sanity-lfsck test_36c needs >= 3 OSTs [ 5273.424176] Lustre: DEBUG MARKER: == sanity-lfsck test 37: LFSCK must skip a ORPHAN ======== 16:43:48 (1788468228) [ 5275.140290] Lustre: 160226:0:(osd_internal.h:1460:osd_trans_exec_op()) lustre-MDT0000: opcode 2: before 258 < left 278, rollback = 2 [ 5275.149755] Lustre: 160226:0:(osd_internal.h:1460:osd_trans_exec_op()) Skipped 1642 previous similar messages [ 5275.156662] Lustre: 160226:0:(osd_handler.c:2090:osd_trans_dump_creds()) create: 1/4/0, destroy: 0/0/0 [ 5275.170919] Lustre: 160226:0:(osd_handler.c:2090:osd_trans_dump_creds()) Skipped 1642 previous similar messages [ 5275.181566] Lustre: 160226:0:(osd_handler.c:2097:osd_trans_dump_creds()) attr_set: 1/1/0, xattr_set: 4/278/0 [ 5275.192940] Lustre: 160226:0:(osd_handler.c:2097:osd_trans_dump_creds()) Skipped 1642 previous similar messages [ 5275.198667] Lustre: 160226:0:(osd_handler.c:2107:osd_trans_dump_creds()) write: 1/11/0, punch: 0/0/0, quota 1/3/0 [ 5275.204520] Lustre: 160226:0:(osd_handler.c:2107:osd_trans_dump_creds()) Skipped 1642 previous similar messages [ 5275.210316] Lustre: 160226:0:(osd_handler.c:2114:osd_trans_dump_creds()) insert: 4/65/2, delete: 0/0/0 [ 5275.216780] Lustre: 160226:0:(osd_handler.c:2114:osd_trans_dump_creds()) Skipped 1642 previous similar messages [ 5275.223233] Lustre: 160226:0:(osd_handler.c:2121:osd_trans_dump_creds()) ref_add: 2/2/0, ref_del: 0/0/0 [ 5275.228775] Lustre: 160226:0:(osd_handler.c:2121:osd_trans_dump_creds()) Skipped 1642 previous similar messages [ 5286.151578] Lustre: DEBUG MARKER: == sanity-lfsck test 38: LFSCK does not break foreign file and reverse is also true ========================================================== 16:44:01 (1788468241) [ 5300.817866] Lustre: DEBUG MARKER: == sanity-lfsck test 39: LFSCK does not break foreign dir and reverse is also true ========================================================== 16:44:16 (1788468256) [ 5316.602474] Lustre: DEBUG MARKER: == sanity-lfsck test 40a: LFSCK correctly fixes lmm_oi in composite layout ========================================================== 16:44:31 (1788468271) [ 5333.256081] Lustre: DEBUG MARKER: == sanity-lfsck test 41: SEL support in LFSCK ============ 16:44:48 (1788468288) [ 5355.842737] Lustre: DEBUG MARKER: == sanity-lfsck test 42: LFSCK repairs inconsistent MDT-object/OST-object encryption flags ========================================================== 16:45:10 (1788468310) [ 5390.938481] Lustre: *** cfs_fail_loc=1632, val=0*** [ 5411.320413] Lustre: DEBUG MARKER: == sanity-lfsck test 43: LFSCK does not loop endlessly on iget failure in scanning-phase1 ========================================================== 16:46:05 (1788468365) [ 5414.864669] Lustre: Failing over lustre-MDT0001 [ 5414.910060] LustreError: 106754:0:(client.c:1394:ptlrpc_import_delay_req()) @@@ IMP_CLOSED req@ffff90fc0a06ea00 x1875343282246912/t0(0) o103->lustre-MDT0000-osp-MDT0001@0@lo:17/18 lens 328/224 e 0 to 0 dl 0 ref 1 fl Rpc:QU/200/ffffffff rc 0/-1 job:'jbd2/dm-1-8.0' uid:0 gid:0 projid:4294967295 [ 5415.390165] Lustre: server umount lustre-MDT0001 complete [ 5415.450762] 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 [ 5415.480683] Lustre: Skipped 8 previous similar messages [ 5426.055422] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5426.718723] Lustre: lustre-MDT0001: in recovery but waiting for the first client to connect [ 5426.722593] Lustre: lustre-MDT0001: Aborting client recovery [ 5426.743768] LustreError: 165822:0:(ldlm_lib.c:3029:target_stop_recovery_thread()) lustre-MDT0001: Aborting recovery [ 5426.749996] LustreError: 165844:0:(lod_dev.c:511:lod_sub_recovery_thread()) lustre-MDT0001-osd: get update log duration 0, retries 0, failed: rc = -108 [ 5426.758660] Lustre: 165846:0:(ldlm_lib.c:2429:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 5426.805517] Lustre: 165846:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0001: disconnect stale client 906c1597-3b51-47d3-b38d-a0606985b2b2@ [ 5426.828958] Lustre: lustre-MDT0001: disconnecting 2 stale clients [ 5426.838183] Lustre: lustre-MDT0001-osd: cancel update llog [0x240000400:0x1:0x0] [ 5426.869066] Lustre: lustre-MDT0000-osp-MDT0001: cancel update llog [0x200000401:0x1:0x0] [ 5426.929090] Lustre: lustre-OST0000: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x280000400:131 to 0x280000400:161) [ 5426.937388] Lustre: lustre-OST0001: new connection from lustre-MDT0001-mdtlov (cleaning up unused objects from 0x2c0000400:69 to 0x2c0000400:161) [ 5431.779080] Lustre: lustre-MDT0001-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 5431.786419] Lustre: Skipped 2 previous similar messages [ 5431.812209] LustreError: lustre-MDT0001-osp-MDT0000: This client was evicted by lustre-MDT0001; in progress operations using this service will fail. [ 5432.395184] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5437.533501] Lustre: *** cfs_fail_loc=1e2, val=483*** [ 5441.567388] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing wait_import_state FULL osp.lustre-MDT0001-os[pc]-MDT0000.*_server_uuid [ 5441.909977] Lustre: DEBUG MARKER: osp.lustre-MDT0001-os[pc]-MDT0000.*_server_uuid in FULL state after 0 sec [ 5450.147720] Lustre: DEBUG MARKER: == sanity-lfsck test 44: umount while lfsck is stopping == 16:46:45 (1788468405) [ 5459.526503] Lustre: *** cfs_fail_loc=1600, val=3*** [ 5462.765058] Lustre: Failing over lustre-MDT0000 [ 5462.796357] LustreError: lustre-MDT0000-osp-MDT0001: operation out_update to node 0@lo failed: rc = -107 [ 5462.820553] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5463.023764] Lustre: server umount lustre-MDT0000 complete [ 5473.631374] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5473.777548] LustreError: MGC192.168.204.108@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5474.052446] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 5474.061644] Lustre: Skipped 2 previous similar messages [ 5477.884147] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 5479.250895] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5479.405857] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 5479.420796] Lustre: Skipped 2 previous similar messages [ 5479.488411] Lustre: lustre-MDT0000: Recovery over after 0:02, of 2 clients 2 recovered and 0 were evicted. [ 5479.563150] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000401:621 to 0x280000401:641) [ 5479.565739] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x2c0000401:489 to 0x2c0000401:513) [ 5491.621997] Lustre: DEBUG MARKER: == sanity-lfsck test 45: LFSCK should fix UID/GID/PROJID of OST object ========================================================== 16:47:26 (1788468446) [ 5534.680972] Lustre: Failing over lustre-OST0001 [ 5534.827809] Lustre: server umount lustre-OST0001 complete [ 5543.198382] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: (null) [ 5558.920815] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5559.152755] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 5559.164997] Lustre: Skipped 6 previous similar messages [ 5559.177764] Lustre: lustre-OST0001: in recovery but waiting for the first client to connect [ 5559.813920] Lustre: lustre-OST0001: Will be in recovery for at least 1:00, or until 3 clients reconnect [ 5560.504060] Lustre: lustre-OST0001: Recovery over after 0:01, of 3 clients 3 recovered and 0 were evicted. [ 5560.507275] Lustre: lustre-OST0001-osc-MDT0001: Connection restored to 0@lo (at 0@lo) [ 5560.534486] Lustre: Skipped 3 previous similar messages [ 5568.210544] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5576.528661] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing wait_import_state (FULL|IDLE) os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid 50 [ 5576.718743] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0000.ost_server_uuid in FULL state after 0 sec [ 5581.995209] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing wait_import_state (FULL|IDLE) os[cp].lustre-OST0000-osc-MDT0001.ost_server_uuid 50 [ 5582.229418] Lustre: DEBUG MARKER: os[cp].lustre-OST0000-osc-MDT0001.ost_server_uuid in FULL state after 0 sec [ 5588.999175] Lustre: DEBUG MARKER: oleg408-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0000-osc-ffff970cce29e000.ost_server_uuid 50 [ 5590.989690] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff970cce29e000.ost_server_uuid in FULL state after 0 sec [ 5677.032467] 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 [ 5677.047634] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5677.057663] Lustre: Skipped 9 previous similar messages [ 5677.070217] Lustre: Skipped 2 previous similar messages [ 5682.145091] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5682.152954] Lustre: Skipped 4 previous similar messages [ 5683.245761] Lustre: server umount lustre-MDT0000 complete [ 5692.045099] LustreError: 159004:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788468648 with bad export cookie 15654669585855141823 [ 5692.054451] LustreError: MGC192.168.204.108@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5692.068207] LustreError: 159004:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 5692.546340] Lustre: server umount lustre-MDT0001 complete [ 5701.450122] Lustre: server umount lustre-OST0000 complete [ 5710.621135] Lustre: server umount lustre-OST0001 complete [ 5732.184290] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing unload_modules_local [ 5736.078524] Key type lgssc unregistered [ 5736.443595] LNet: 175468:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 5736.450807] LNetError: 175468:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 5736.468167] LNet: Removed LNI 192.168.204.108@tcp [ 5737.533321] Key type .llcrypt unregistered [ 5737.536678] Key type ._llcrypt unregistered [ 5764.212478] Key type ._llcrypt registered [ 5764.216340] Key type .llcrypt registered [ 5764.371581] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_hostid [ 5782.633708] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing load_modules_local [ 5784.259432] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 5784.353876] alg: No test for adler32 (adler32-zlib) [ 5785.518816] Lustre: Lustre: Build Version: 2.17.58_2_gbb63b80 [ 5785.881255] LNet: Added LNI 192.168.204.108@tcp [8/256/0/180] [ 5787.583315] Key type lgssc registered [ 5788.907607] Lustre: Echo OBD driver; http://www.lustre.org/ [ 5842.201114] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing load_modules_local [ 5857.779879] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 5857.823318] LDISKFS-fs (dm-0): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5859.100207] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 5859.131333] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 5859.177343] Lustre: lustre-MDT0000: new disk, initializing [ 5859.238239] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 5859.258373] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 5864.842041] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5880.602677] LDISKFS-fs (dm-1): mounted filesystem with ordered data mode. Opts: user_xattr,errors=remount-ro,no_mbcache,nodelalloc [ 5880.717492] Lustre: 179939:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify lustre-MDT0001/mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity (mode = 0) failed: rc = -17 [ 5880.752520] Lustre: srv-lustre-MDT0001: No data found on store. Initialize space. [ 5880.757864] Lustre: Skipped 1 previous similar message [ 5880.843506] Lustre: lustre-MDT0001: new disk, initializing [ 5880.911093] Lustre: lustre-MDT0001: Imperative Recovery not enabled, recovery window 60-180 [ 5880.947196] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:1:mdt [ 5880.967985] Lustre: cli-ctl-lustre-MDT0001: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:1:mdt] [ 5885.173685] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5889.918750] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 5899.428790] LDISKFS-fs (dm-2): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5899.845873] Lustre: lustre-OST0000: new disk, initializing [ 5899.855494] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 5899.861862] Lustre: 181879:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 5899.960745] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 5906.503421] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:0:ost [ 5906.525244] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:0:ost] [ 5906.580456] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5906.623165] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x280000401 [ 5919.913327] LDISKFS-fs (dm-3): mounted filesystem with ordered data mode. Opts: errors=remount-ro,no_mbcache,nodelalloc [ 5920.074515] Lustre: lustre-OST0001: new disk, initializing [ 5920.079081] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 5920.085746] Lustre: 182904:0:(osd_compat.c:1353:osd_object_spec_find()) UNKNOWN COMPAT FID [0x200000001:0x101e:0x0] [ 5920.155651] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 5926.096587] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5926.943939] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x00000002c0000400-0x0000000300000400]:1:ost [ 5926.955477] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x00000002c0000400-0x0000000300000400]:1:ost] [ 5927.002991] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x2c0000401 [ 5937.502583] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 5943.588884] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 5949.629219] Lustre: DEBUG MARKER: === sanity-lfsck: finish setup 16:55:04 (1788468904) === [ 5951.310187] Lustre: DEBUG MARKER: == sanity-lfsck test complete, duration 5608 sec ========= 16:55:06 (1788468906) [ 5953.072920] Lustre: DEBUG MARKER: === sanity-lfsck: start cleanup 16:55:08 (1788468908) === [ 5956.747100] Lustre: DEBUG MARKER: === sanity-lfsck: finish cleanup 16:55:11 (1788468911) === [ 5962.722794] 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 [ 5962.723047] LustreError: lustre-MDT0000-osp-MDT0001: operation mds_statfs to node 0@lo failed: rc = -107 [ 5962.723213] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5962.734621] Lustre: Skipped 2 previous similar messages [ 5966.719257] Lustre: server umount lustre-MDT0000 complete [ 5972.961436] LustreError: 181358:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 5972.984676] LustreError: 181358:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 8 previous similar messages [ 5975.026307] LustreError: 179931:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788468931 with bad export cookie 15499979676007550765 [ 5975.027896] LustreError: MGC192.168.204.108@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5975.044137] LustreError: 179931:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 1 previous similar message [ 5975.469435] Lustre: server umount lustre-MDT0001 complete [ 5993.439350] Lustre: 177098:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788468934/real 1788468934] req@ffff90fc0a95fb80 x1875345399693440/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788468950 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5993.484699] 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 [ 5994.614595] Lustre: server umount lustre-OST0000 complete [ 5996.255160] Lustre: 177096:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788468936/real 1788468936] req@ffff90fc0e483b80 x1875345399693696/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788468952 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5999.079154] Lustre: 177099:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788468939/real 1788468939] req@ffff90fc097aed80 x1875345399693952/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788468955 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6001.186871] Lustre: 177099:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788468941/real 1788468941] req@ffff90fc0e483800 x1875345399694336/t0(0) o400->lustre-MDT0001-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788468957 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6002.923327] Lustre: server umount lustre-OST0001 complete [ 6025.176470] Lustre: DEBUG MARKER: oleg408-server.virtnet: executing unload_modules_local [ 6027.972915] Key type lgssc unregistered [ 6028.398149] LNet: 186376:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 6028.421032] LNetError: 186376:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 6028.441919] LNet: Removed LNI 192.168.204.108@tcp [ 6029.394226] Key type .llcrypt unregistered [ 6029.398084] Key type ._llcrypt unregistered