[ 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 521263767 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2399.998 MHz processor [ 0.000000] last_pfn = 0x146e00 max_arch_pfn = 0x400000000 [ 0.000000] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT [ 0.000000] last_pfn = 0xbffce max_arch_pfn = 0x400000000 [ 0.000000] found SMP MP-table at [mem 0x000f54b0-0x000f54bf] [ 0.000000] RAMDISK: [mem 0xbcc54000-0xbffbffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F52D0 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE247C 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE2318 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 0022D8 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE238C 000090 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE241C 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE2454 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe2318-0xbffe238b] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe2317] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe238c-0xbffe241b] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe241c-0xbffe2453] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe2454-0xbffe247b] [ 0.000000] No NUMA configuration found [ 0.000000] Faking a node at [mem 0x0000000000000000-0x0000000146dfffff] [ 0.000000] NODE_DATA(0) allocated [mem 0x1465a3000-0x1465cdfff] [ 0.000000] Reserving 256MB of memory at 2752MB for crashkernel (System RAM: 4205MB) [ 0.000000] Zone ranges: [ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.000000] DMA32 [mem 0x0000000001000000-0x00000000ffffffff] [ 0.000000] Normal [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Device empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff] [ 0.000000] node 0: [mem 0x0000000000100000-0x00000000bffcdfff] [ 0.000000] node 0: [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Zeroed struct page in unavailable ranges: 4756 pages [ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x0000000146dfffff] [ 0.000000] ACPI: PM-Timer IO Port: 0x608 [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) [ 0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) [ 0.000000] Using ACPI (MADT) for SMP configuration information [ 0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000] TSC deadline timer available [ 0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs [ 0.000000] kvm-guest: KVM setup pv remote TLB flush [ 0.000000] kvm-guest: setup PV sched yield [ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff] [ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff] [ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff] [ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff] [ 0.000000] PM: Registered nosave memory: [mem 0xbffce000-0xbfffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xc0000000-0xfeffbfff] [ 0.000000] PM: Registered nosave memory: [mem 0xfeffc000-0xfeffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xff000000-0xfffbffff] [ 0.000000] PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff] [ 0.000000] [mem 0xc0000000-0xfeffbfff] available for PCI devices [ 0.000000] Booting paravirtualized kernel on KVM [ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns [ 0.000000] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1 [ 0.000000] percpu: Embedded 63 pages/cpu s221184 r8192 d28672 u524288 [ 0.000000] kvm-guest: PV spinlocks enabled [ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1059606 [ 0.000000] Policy zone: Normal [ 0.000000] Kernel command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] Specific versions of hardware are certified with Red Hat Enterprise Linux 8. Please see the list of hardware certified with Red Hat Enterprise Linux 8 at https://catalog.redhat.com. [ 0.000000] audit: disabled (until reboot) [ 0.000000] software IO TLB: area num 4. [ 0.000000] Memory: 2829652K/4306352K available (18435K kernel code, 11221K rwdata, 7248K rodata, 2908K init, 18040K bss, 524584K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] ftrace: allocating 41240 entries in 162 pages [ 0.000000] ftrace: allocated 162 pages with 3 groups [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] rcu: RCU event tracing is enabled. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ 0.000000] rcu: RCU callback double-/use-after-free debug enabled. [ 0.000000] Rude variant of Tasks RCU enabled. [ 0.000000] Tracing variant of Tasks RCU enabled. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 0.000000] NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16 [ 0.000000] random: get_random_bytes called from start_kernel+0x622/0x9a8 with crng_init=0 [ 0.001000] Console: colour *CGA 80x25 [ 0.001000] printk: console [ttyS1] enabled [ 0.001000] ACPI: Core revision 20220331 [ 0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.001014] APIC: Switch to symmetric I/O mode setup [ 0.003089] x2apic enabled [ 0.004009] Switched APIC routing to physical x2apic. [ 0.005023] 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.009025] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.010017] pid_max: default: 32768 minimum: 301 [ 0.011193] LSM: Security Framework initializing [ 0.012067] Yama: becoming mindful. [ 0.013046] SELinux: Initializing. [ 0.014095] *** VALIDATE selinux *** [ 0.023523] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.028134] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.029177] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.030131] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.031131] *** VALIDATE tmpfs *** [ 0.033105] *** VALIDATE proc *** [ 0.034264] *** VALIDATE cgroup *** [ 0.035010] *** VALIDATE cgroup2 *** [ 0.037229] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.038158] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.039014] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.040030] Spectre V2 : User space: Vulnerable [ 0.041014] Speculative Store Bypass: Vulnerable [ 0.043838] debug: unmapping init [mem 0xffffffffa9259000-0xffffffffa9260fff] [ 0.045198] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.046771] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.047034] ... version: 2 [ 0.048020] ... bit width: 48 [ 0.049017] ... generic registers: 4 [ 0.050017] ... value mask: 0000ffffffffffff [ 0.051020] ... max period: 00007fffffffffff [ 0.052029] ... fixed-purpose events: 3 [ 0.053014] ... event mask: 000000070000000f [ 0.054404] rcu: Hierarchical SRCU implementation. [ 0.056752] smp: Bringing up secondary CPUs ... [ 0.057678] x86: Booting SMP configuration: [ 0.058032] .... node #0, CPUs: #1 #2 #3 [ 0.062128] smp: Brought up 1 node, 4 CPUs [ 0.064023] smpboot: Max logical packages: 1 [ 0.065019] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.221023] node 0 deferred pages initialised in 154ms [ 0.226225] devtmpfs: initialized [ 0.227326] x86/mm: Memory block size: 128MB [ 0.233872] gcov: version magic: 0x41383552 [ 0.238446] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.239100] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.242466] pinctrl core: initialized pinctrl subsystem [ 0.245883] [ 0.246012] ************************************************************* [ 0.249022] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.252020] ** ** [ 0.255023] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.258019] ** ** [ 0.260017] ** This means that this kernel is built to expose internal ** [ 0.263021] ** IOMMU data structures, which may compromise security on ** [ 0.265017] ** your system. ** [ 0.267021] ** ** [ 0.269025] ** If you see this message and you are not debugging the ** [ 0.271020] ** kernel, report this immediately to your vendor! ** [ 0.273016] ** ** [ 0.275013] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.277081] ************************************************************* [ 0.279741] NET: Registered protocol family 16 [ 0.281367] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.284053] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.286062] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.289122] cpuidle: using governor menu [ 0.292299] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.295575] PCI: Using configuration type 1 for base access [ 0.298159] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.307237] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.310119] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.314030] cryptd: max_cpu_qlen set to 1000 [ 0.317870] ACPI: Added _OSI(Module Device) [ 0.319010] ACPI: Added _OSI(Processor Device) [ 0.320018] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.321013] ACPI: Added _OSI(Processor Aggregator Device) [ 0.326050] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.332521] ACPI: Interpreter enabled [ 0.334071] ACPI: PM: (supports S0 S3 S4 S5) [ 0.336016] ACPI: Using IOAPIC for interrupt routing [ 0.338178] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.341484] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.352091] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.354051] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.357021] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.361091] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.367182] acpiphp: Slot [2] registered [ 0.369201] acpiphp: Slot [5] registered [ 0.370196] acpiphp: Slot [6] registered [ 0.372219] acpiphp: Slot [7] registered [ 0.374136] acpiphp: Slot [8] registered [ 0.375141] acpiphp: Slot [9] registered [ 0.377136] acpiphp: Slot [10] registered [ 0.379189] acpiphp: Slot [3] registered [ 0.380133] acpiphp: Slot [4] registered [ 0.382158] acpiphp: Slot [11] registered [ 0.384151] acpiphp: Slot [12] registered [ 0.386210] acpiphp: Slot [13] registered [ 0.387127] acpiphp: Slot [14] registered [ 0.389134] acpiphp: Slot [15] registered [ 0.391160] acpiphp: Slot [16] registered [ 0.392117] acpiphp: Slot [17] registered [ 0.394126] acpiphp: Slot [18] registered [ 0.396172] acpiphp: Slot [19] registered [ 0.397089] acpiphp: Slot [20] registered [ 0.399149] acpiphp: Slot [21] registered [ 0.401152] acpiphp: Slot [22] registered [ 0.403141] acpiphp: Slot [23] registered [ 0.405116] acpiphp: Slot [24] registered [ 0.406130] acpiphp: Slot [25] registered [ 0.408105] acpiphp: Slot [26] registered [ 0.409092] acpiphp: Slot [27] registered [ 0.410138] acpiphp: Slot [28] registered [ 0.412101] acpiphp: Slot [29] registered [ 0.413087] acpiphp: Slot [30] registered [ 0.415119] acpiphp: Slot [31] registered [ 0.416067] PCI host bridge to bus 0000:00 [ 0.417022] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.420026] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.422021] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.424025] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.427025] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.429021] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.431187] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.433977] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.436773] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.446014] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.451731] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.454025] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.455019] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.458022] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.461133] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.464980] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.468059] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.471698] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.477017] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.491018] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.498909] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.503780] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.508015] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.513019] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.528019] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.539073] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.549026] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.556028] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.576029] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.586996] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.594016] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.602021] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.628018] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.644786] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.650028] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.657031] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.672034] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.681469] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.686024] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.692039] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.704027] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 0.719166] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.724022] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.728017] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.747023] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 0.754890] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.757294] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.759342] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.761338] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.763193] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.768023] iommu: Default domain type: Passthrough [ 0.769357] SCSI subsystem initialized [ 0.770089] ACPI: bus type USB registered [ 0.771091] usbcore: registered new interface driver usbfs [ 0.772065] usbcore: registered new interface driver hub [ 0.773075] usbcore: registered new device driver usb [ 0.774134] pps_core: LinuxPPS API ver. 1 registered [ 0.775013] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.777047] PTP clock support registered [ 0.778193] EDAC MC: Ver: 3.0.0 [ 0.779351] PCI: Using ACPI for IRQ routing [ 0.780899] NetLabel: Initializing [ 0.782013] NetLabel: domain hash size = 128 [ 0.783010] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.785111] NetLabel: unlabeled traffic allowed by default [ 0.787311] vgaarb: loaded [ 0.789302] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.790017] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.797167] clocksource: Switched to clocksource kvm-clock [ 0.910260] VFS: Disk quotas dquot_6.6.0 [ 0.913745] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.916361] *** VALIDATE ramfs *** [ 0.917661] *** VALIDATE hugetlbfs *** [ 0.919468] pnp: PnP ACPI init [ 0.921931] pnp: PnP ACPI: found 6 devices [ 0.943049] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.945629] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.947284] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.948988] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.950979] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.953023] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.955254] NET: Registered protocol family 2 [ 0.957359] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.961770] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.965654] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.971912] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.976426] TCP: Hash tables configured (established 65536 bind 65536) [ 0.979718] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.983216] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.986369] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.989312] NET: Registered protocol family 1 [ 0.991249] RPC: Registered named UNIX socket transport module. [ 0.992685] RPC: Registered udp transport module. [ 0.994660] RPC: Registered tcp transport module. [ 0.995962] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.998015] NET: Registered protocol family 44 [ 0.999705] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 1.002136] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 1.004407] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 1.006903] PCI: CLS 0 bytes, default 64 [ 1.009156] Unpacking initramfs... [ 2.458340] debug: unmapping init [mem 0xffff95f2fcc54000-0xffff95f2fffbffff] [ 2.462300] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.464538] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.467652] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 2.960905] Initialise system trusted keyrings [ 2.963645] Key type blacklist registered [ 2.965862] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.974528] zbud: loaded [ 2.978073] *** VALIDATE nfs *** [ 2.979892] *** VALIDATE nfs4 *** [ 2.981925] pstore: using deflate compression [ 2.985980] Platform Keyring initialized [ 3.090536] NET: Registered protocol family 38 [ 3.092981] Key type asymmetric registered [ 3.094554] Asymmetric key parser 'x509' registered [ 3.096610] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 3.100932] io scheduler mq-deadline registered [ 3.103417] io scheduler kyber registered [ 3.105746] io scheduler bfq registered [ 3.108347] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 3.112423] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 3.116458] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 3.120399] ACPI: Power Button [PWRF] [ 3.125803] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 3.133300] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 3.162230] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 3.169102] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 3.185772] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 3.212668] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.238085] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.242761] Non-volatile memory driver v1.3 [ 3.245419] Linux agpgart interface v0.103 [ 3.278565] virtio_blk virtio1: [vda] 146728 512-byte logical blocks (75.1 MB/71.6 MiB) [ 3.283161] vda: detected capacity change from 0 to 75124736 [ 3.304123] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.306623] vdb: detected capacity change from 0 to 1073741824 [ 3.330991] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.334455] vdc: detected capacity change from 0 to 2621440000 [ 3.352588] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.355501] vdd: detected capacity change from 0 to 2621440000 [ 3.371356] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.374785] vde: detected capacity change from 0 to 4294967296 [ 3.391455] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.395072] vdf: detected capacity change from 0 to 4294967296 [ 3.402477] libphy: Fixed MDIO Bus: probed [ 3.412742] usbcore: registered new interface driver usbserial_generic [ 3.414639] usbserial: USB Serial support registered for generic [ 3.416474] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.421101] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.422847] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.425533] mousedev: PS/2 mouse device common for all mice [ 3.429562] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.430296] rtc_cmos 00:05: RTC can wake from S4 [ 3.439298] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.443373] rtc_cmos 00:05: registered as rtc0 [ 3.447917] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.448956] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.457034] intel_pstate: CPU model not supported [ 3.460951] hid: raw HID events driver (C) Jiri Kosina [ 3.463902] usbcore: registered new interface driver usbhid [ 3.466873] usbhid: USB HID core driver [ 3.469195] drop_monitor: Initializing network drop monitor service [ 3.472629] Initializing XFRM netlink socket [ 3.475258] NET: Registered protocol family 10 [ 3.478901] Segment Routing with IPv6 [ 3.480669] NET: Registered protocol family 17 [ 3.483256] mpls_gso: MPLS GSO support [ 3.489560] RAS: Correctable Errors collector initialized. [ 3.492256] AVX version of gcm_enc/dec engaged. [ 3.494228] AES CTR mode by8 optimization enabled [ 3.581652] sched_clock: Marking stable (3581634598, 0)->(4489959042, -908324444) [ 3.584293] registered taskstats version 1 [ 3.585619] Loading compiled-in X.509 certificates [ 3.586822] zswap: loaded using pool lzo/zbud [ 3.608261] Key type big_key registered [ 3.619589] Key type encrypted registered [ 3.620858] ima: No TPM chip found, activating TPM-bypass! [ 3.622016] ima: Allocated hash algorithm: sha1 [ 3.622866] ima: No architecture policies found [ 3.623874] evm: Initialising EVM extended attributes: [ 3.624976] evm: security.selinux [ 3.625658] evm: security.ima [ 3.626461] evm: security.capability [ 3.627317] evm: HMAC attrs: 0x1 [ 3.629141] rtc_cmos 00:05: setting system clock to 2026-09-08 02:59:50 UTC (1788836390) [ 3.634965] debug: unmapping init [mem 0xffffffffaa203000-0xffffffffaa3fffff] [ 3.638132] debug: unmapping init [mem 0xffffffffa8f82000-0xffffffffa9258fff] [ 3.648073] Write protecting the kernel read-only data: 28672k [ 3.650527] debug: unmapping init [mem 0xffffffffa7603000-0xffffffffa77fffff] [ 3.652115] debug: unmapping init [mem 0xffffffffa7f14000-0xffffffffa7ffffff] [ 3.683320] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 3.688378] systemd[1]: Detected virtualization kvm. [ 3.689349] systemd[1]: Detected architecture x86-64. [ 3.690383] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.712949] systemd[1]: No hostname configured. [ 3.713951] systemd[1]: Set hostname to . [ 3.715439] random: systemd: uninitialized urandom read (16 bytes read) [ 3.717251] systemd[1]: Initializing machine ID from random generator. [ 3.833858] random: systemd: uninitialized urandom read (16 bytes read) [ 3.836521] systemd[1]: Listening on udev Control Socket. [ OK ] Listening on udev Control Socket. [ 3.842597] random: systemd: uninitialized urandom read (16 bytes read) [ 3.845762] systemd[1]: Listening on Journal Socket. [ OK ] Listening on Journal Socket. [ 3.852689] systemd[1]: Started Memstrack Anylazing Service. [ OK ] Started Memstrack Anylazing Service. [ OK ] Reached target Slices. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Reached target Swap. [ OK ] Listening on udev Kernel Socket. [ OK ] Reached target Initrd Root Device. Starting Setup Virtual Console... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Paths. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Listening on Journal Socket (/dev/log). [ OK ] Reached target Sockets. Starting Journal Service... [ OK ] Reached target Local File Systems. Starting Create Volatile Files and Directories... [ OK ] Reached target Timers. Starting Apply Kernel Variables... [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Setup Virtual Console. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Apply Kernel Variables. Starting dracut cmdline hook... Starting Create Static Device Nodes in /dev... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started Journal Service. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 4.471275] device-mapper: uevent: version 1.0.3 [ 4.473709] 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. [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ 5.138984] random: fast init done Starting dracut initqueue hook... [ 5.173897] virtio_net virtio0 ens2: renamed from eth0 [ 5.295607] scsi host0: ata_piix [ 5.321692] scsi host1: ata_piix [ 5.323392] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 5.325925] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 9.715556] dracut-initqueue[589]: RTNETLINK answers: File exists [ 10.132341] random: crng init done [ 10.134047] random: 7 urandom warning(s) missed due to ratelimiting Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Mounting /sysroot... [ 10.603327] 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 Initrd Default Target. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped target Timers. [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Sockets. [ OK ] Stopped target Slices. [ OK ] Stopped target System Initialization. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. Stopping udev Kernel Device Manager... [ OK ] Stopped target Swap. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped target Paths. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Closed udev Control Socket. [ OK ] Closed udev Kernel Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 11.866285] printk: systemd: 26 output lines suppressed due to ratelimiting [ 12.208140] SELinux: Disabled at runtime. [ 12.275575] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 12.284640] systemd[1]: Detected virtualization kvm. [ 12.286658] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 12.815799] systemd[1]: initrd-switch-root.service: Succeeded. [ 12.819155] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 12.826046] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 12.830689] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 12.834915] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 12.843614] systemd[1]: Starting Journal Service... Starting Journal Service... [ 12.853900] systemd[1]: Activating swap /dev/disk/by-label/SWAP... Activating swap /dev/disk/by-label/SWAP... [ OK ] Created slice User and Session Slice. [ OK ] Created slice system-getty.slice. Mounting POSIX Message Queue File System... [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. [ 12.881975] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. Mounting Huge Pages File System... [ OK ] Created slice system-sshd\x2dkeygen.slice. Mounting Kernel Debug File System... [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Listening on initctl Compatibility Named Pipe. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Listening on udev Control Socket. [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. [ OK ] Reached target rpc_pipefs.target. [ OK ] Listening on udev Kernel Socket. Starting udev Coldplug all Devices... Starting Apply Kernel Variables... [ OK ] Reached target RPC Port Mapper. [ OK ] Listening on Process Core Dump Socket. [ OK ] Reached target Slices. Starting Remount Root and Kernel File Systems... [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd File Systems. [ OK ] Stopped target Initrd Root File System. [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Started Journal Service. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Mounted Huge Pages File System. [ OK ] Mounted Kernel Debug File System. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Apply Kernel Variables. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. Starting Configure read-only root support... Starting Create Static Device Nodes in /dev... [ OK ] Reached target Swap. Starting Flush Journal to Persistent Storage... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Reached target Local File Systems (Pre). Mounting /mnt... Mounting /home/green/git/lustre-release... Starting udev Kernel Device Manager... [ OK ] Mounted /mnt. [ OK ] Started udev Coldplug all Devices. [ 13.376704] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 13.725291] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 13.752709] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 13.936933] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 13.948476] EDAC sbridge: Ver: 1.1.2 [ 15.735453] Key type dns_resolver registered [ 16.048954] NFS: Registering the id_resolver key type [ 16.051075] Key type id_resolver registered [ 16.052758] Key type id_legacy registered [ OK ] Started Configure read-only root support. Starting Load/Save Random Seed... [ OK ] Reached target Local File Systems. Starting Mark the need to relabel after reboot... Starting Create Volatile Files and Directories... Starting Rebuild Dynamic Linker Cache... [ OK ] Started Load/Save Random Seed. [ OK ] Started Mark the need to relabel after reboot. [ 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 Cleanup of Temporary Directories. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Reached target Basic System. [ OK ] Started D-Bus System Message Bus. [ OK ] Started irqbalance daemon. Starting Network Manager... Starting Login Service... [ OK ] Reached target sshd-keygen.target. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Started dnf makecache --timer. [ OK ] Reached target Timers. Starting Restore /run/initramfs on shutdown... [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Login Service. [ OK ] Started Network Manager. Starting Network Manager Wait Online... [ OK ] Reached target Network. Starting OpenSSH server daemon... Starting GSSAPI Proxy Daemon... Starting Dynamic System Tuning 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 ttyS0. [ OK ] Started Getty on tty1. [ OK ] Started Serial Getty on ttyS1. [ OK ] Reached target Login Prompts. [ OK ] Started Command Scheduler. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting Crash recovery kernel arming... Starting Notify NFS peers of a restart... Starting System Logging Service... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Starting Authorization Manager... [ OK ] Started Authorization Manager. [ OK ] Started Dynamic System Tuning Daemon. [ OK ] Reached target Multi-User System. [ OK ] Reached target Graphical Interface. Starting Update UTMP about System Runlevel Changes... [ OK ] Started Update UTMP about System Runlevel Changes. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg201-server login: [ 47.731522] hrtimer: interrupt took 24508902 ns [ 56.382291] spl: loading out-of-tree module taints kernel. [ 64.836672] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 80.633276] Key type ._llcrypt registered [ 80.635730] Key type .llcrypt registered [ 80.799712] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_hostid [ 102.327506] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing load_modules_local [ 104.714082] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 104.743930] alg: No test for adler32 (adler32-zlib) [ 106.381644] Lustre: Lustre: Build Version: 2.17.57_113_gf5ca795 [ 107.679366] LNet: Added LNI 192.168.202.101@tcp [8/256/0/180] [ 109.503251] Key type lgssc registered [ 112.169795] Lustre: Echo OBD driver; http://www.lustre.org/ [ 126.850488] vdc: vdc1 vdc9 [ 139.341488] vde: vde1 vde9 [ 153.136076] vdf: vdf1 vdf9 [ 176.037864] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing load_modules_local [ 188.661825] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 190.166929] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 190.520595] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 190.664610] Lustre: lustre-MDT0000: new disk, initializing [ 191.252987] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 191.342737] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 197.043462] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 203.138126] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 211.221539] Lustre: lustre-OST0000: new disk, initializing [ 211.225888] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 211.236027] Lustre: Skipped 1 previous similar message [ 211.390322] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 214.833198] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:0:ost [ 214.841162] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:0:ost] [ 215.090110] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x240000400 [ 219.503939] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 233.842767] Lustre: lustre-OST0001: new disk, initializing [ 233.850578] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 234.051115] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 239.420168] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:1:ost [ 239.433028] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:1:ost] [ 239.604774] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x280000400 [ 242.425393] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 255.938800] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 265.326205] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 273.049548] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing check_logdir /tmp/testlogs/ [ 278.923758] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing yml_node [ 283.265662] Lustre: DEBUG MARKER: Client: 2.17.57.113 [ 286.282724] Lustre: DEBUG MARKER: MDS: 2.17.57.113 [ 289.155644] Lustre: DEBUG MARKER: OSS: 2.17.57.113 [ 291.288260] Lustre: DEBUG MARKER: -----============= acceptance-small: replay-single ============----- Mon Sep 7 23:04:36 EDT 2026 [ 311.986532] Lustre: DEBUG MARKER: excepting tests: 59 36 [ 314.402469] Lustre: DEBUG MARKER: === replay-single: start setup 23:04:59 (1788836699) === [ 320.512987] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing check_config_client /mnt/lustre [ 339.968692] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 343.920825] Lustre: 11312:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 347.956765] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 352.421217] Lustre: DEBUG MARKER: === replay-single: finish setup 23:05:37 (1788836737) === [ 354.672137] Lustre: DEBUG MARKER: == replay-single test 0a: empty replay =================== 23:05:39 (1788836739) [ 357.917658] LustreError: 11809:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 358.932731] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 361.027365] Lustre: Failing over lustre-MDT0000 [ 361.405925] Lustre: server umount lustre-MDT0000 complete [ 377.249899] Lustre: 3326:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788836748/real 1788836748] req@ffff95f36e7cd180 x1875731015591552/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788836764 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 377.277964] 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 [ 380.403691] LustreError: MGC192.168.202.101@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 381.301424] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 383.137766] Lustre: 3326:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788836753/real 1788836753] req@ffff95f362b56d80 x1875731015591936/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788836769 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 383.183154] Lustre: 3326:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 387.248653] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 388.265925] Lustre: 3324:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788836759/real 1788836759] req@ffff95f36e7b9500 x1875731015592320/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788836775 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 388.265925] Lustre: 3325:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788836759/real 1788836759] req@ffff95f36e7b8e00 x1875731015592448/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788836775 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 388.265942] Lustre: 3324:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 388.427167] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 388.667906] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 388.849811] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 400.468961] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 402.247874] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 411.170478] Lustre: DEBUG MARKER: == replay-single test 0b: ensure object created after recover exists. (3284) ========================================================== 23:06:36 (1788836796) [ 413.921183] Lustre: Failing over lustre-OST0000 [ 414.059642] Lustre: server umount lustre-OST0000 complete [ 414.688472] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 414.698309] Lustre: lustre-OST0000-osc-MDT0000: Connection to lustre-OST0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 414.716260] Lustre: Skipped 1 previous similar message [ 419.393034] LustreError: 8524:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.202.1@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 419.420406] LustreError: 8524:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 4 previous similar messages [ 423.391687] LustreError: 6697: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. [ 424.490374] LustreError: 6696:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.202.1@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 428.528731] LustreError: 6696: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. [ 433.642427] LustreError: 6698: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. [ 433.667646] LustreError: 6698:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 1 previous similar message [ 434.895965] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 436.386931] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 436.531485] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 436.553320] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 436.563290] Lustre: Skipped 1 previous similar message [ 441.979209] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 452.830930] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 454.377846] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 466.111682] Lustre: DEBUG MARKER: == replay-single test 0c: check replay-barrier =========== 23:07:30 (1788836850) [ 471.016973] LustreError: 14863:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 472.352823] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 475.576091] Lustre: Failing over lustre-MDT0000 [ 476.133046] 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 [ 476.143862] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 476.278896] Lustre: server umount lustre-MDT0000 complete [ 496.834696] LustreError: MGC192.168.202.101@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 497.616276] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 503.857091] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 507.025989] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 507.031988] Lustre: lustre-MDT0000: Denying connection for new client 542117df-058b-4d30-b6dc-929a97173550 (at 192.168.202.1@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 1:00 [ 512.033141] Lustre: lustre-MDT0000: Denying connection for new client 542117df-058b-4d30-b6dc-929a97173550 (at 192.168.202.1@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:55 [ 516.900928] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 517.153154] Lustre: lustre-MDT0000: Denying connection for new client 542117df-058b-4d30-b6dc-929a97173550 (at 192.168.202.1@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:50 [ 522.278776] Lustre: lustre-MDT0000: Denying connection for new client 542117df-058b-4d30-b6dc-929a97173550 (at 192.168.202.1@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:45 [ 527.398107] Lustre: lustre-MDT0000: Denying connection for new client 542117df-058b-4d30-b6dc-929a97173550 (at 192.168.202.1@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:40 [ 537.640429] Lustre: lustre-MDT0000: Denying connection for new client 542117df-058b-4d30-b6dc-929a97173550 (at 192.168.202.1@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:29 [ 537.677886] Lustre: Skipped 1 previous similar message [ 558.113473] Lustre: lustre-MDT0000: Denying connection for new client 542117df-058b-4d30-b6dc-929a97173550 (at 192.168.202.1@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:09 [ 558.159795] Lustre: Skipped 3 previous similar messages [ 567.502717] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 567.514717] Lustre: 15498:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client a79992c0-acfb-464a-b421-0541704ce396@ [ 567.538174] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 567.642747] Lustre: lustre-MDT0000: Recovery over after 1:00, of 1 clients 0 recovered and 1 was evicted. [ 567.714386] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:44 to 0x280000400:65) [ 567.715700] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:44 to 0x240000400:65) [ 578.155396] Lustre: DEBUG MARKER: == replay-single test 0d: expired recovery with no clients ========================================================== 23:09:23 (1788836963) [ 581.490639] LustreError: 16237:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 582.537621] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 584.712073] Lustre: Failing over lustre-MDT0000 [ 584.974335] Lustre: server umount lustre-MDT0000 complete [ 604.517800] LustreError: MGC192.168.202.101@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 605.114158] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 605.265700] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 605.924925] Lustre: 3324:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788836975/real 1788836975] req@ffff95f358a5c000 x1875731015648384/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788836991 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 605.959242] 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 [ 605.974545] Lustre: Skipped 1 previous similar message [ 605.988210] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 605.994659] Lustre: Skipped 1 previous similar message [ 610.087616] Lustre: 3324:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788836980/real 1788836980] req@ffff95f37c349500 x1875731015648896/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788836996 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 610.113894] Lustre: 3324:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 610.363842] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 613.035604] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 613.043164] Lustre: lustre-MDT0000: Denying connection for new client 655a43b7-ea09-4702-a8c2-c6bfe1a107ef (at 192.168.202.1@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 1:00 [ 613.071426] Lustre: Skipped 1 previous similar message [ 619.487934] Lustre: 3324:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788836990/real 1788836990] req@ffff95f37c34b800 x1875731015649536/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788837006 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 619.540088] Lustre: 3324:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 673.501218] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 673.516917] Lustre: 16879:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 542117df-058b-4d30-b6dc-929a97173550@ [ 673.534616] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 673.600065] Lustre: lustre-MDT0000: Recovery over after 1:00, of 1 clients 0 recovered and 1 was evicted. [ 673.660720] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:44 to 0x240000400:97) [ 673.668930] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:44 to 0x280000400:97) [ 685.936352] Lustre: DEBUG MARKER: == replay-single test 1: simple create =================== 23:11:10 (1788837070) [ 688.801373] LustreError: 17618:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 689.849115] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 691.718568] Lustre: Failing over lustre-MDT0000 [ 692.067871] Lustre: server umount lustre-MDT0000 complete [ 709.603230] Lustre: 3323:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788837080/real 1788837080] req@ffff95f373bf7800 x1875731015672320/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788837096 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 709.604164] 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 [ 709.646646] Lustre: 3323:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 709.663257] Lustre: Skipped 2 previous similar messages [ 709.666757] LustreError: MGC192.168.202.101@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 719.848989] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x8c53a26e3b08ceb [ 719.860264] Lustre: MGC192.168.202.101@tcp: Connection restored to 0@lo (at 0@lo) [ 719.871516] Lustre: Skipped 1 previous similar message [ 720.534359] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 720.664653] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 720.937625] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 721.121911] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 721.161490] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:44 to 0x280000400:129) [ 721.162156] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:44 to 0x240000400:129) [ 725.778388] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 734.758438] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 736.255491] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 737.951876] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 746.769268] Lustre: DEBUG MARKER: == replay-single test 2a: touch ========================== 23:12:11 (1788837131) [ 750.518262] LustreError: 19203:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 751.724315] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 754.236512] Lustre: Failing over lustre-MDT0000 [ 754.681581] Lustre: server umount lustre-MDT0000 complete [ 771.552653] Lustre: 3325:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788837142/real 1788837142] req@ffff95f376c24a80 x1875731015688704/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788837158 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 771.554129] 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 [ 771.593819] Lustre: 3325:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 8 previous similar messages [ 771.620109] Lustre: Skipped 1 previous similar message [ 771.625853] LustreError: MGC192.168.202.101@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 781.791803] LustreError: 3322:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff95f376c24000 x1875731015690496/t0(0) o250->MGC192.168.202.101@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 [ 782.443868] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 783.400777] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 783.623528] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 783.682982] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:131 to 0x280000400:161) [ 783.685400] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:44 to 0x240000400:161) [ 787.599830] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 796.518751] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 796.521673] Lustre: Skipped 1 previous similar message [ 798.452942] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 799.868128] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 808.418527] Lustre: DEBUG MARKER: == replay-single test 2b: touch ========================== 23:13:13 (1788837193) [ 811.783697] LustreError: 20795:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 812.606454] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 814.660622] Lustre: Failing over lustre-MDT0000 [ 815.129188] Lustre: server umount lustre-MDT0000 complete [ 832.483691] 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 [ 832.485836] LustreError: MGC192.168.202.101@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 838.559216] Lustre: 3324:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788837209/real 1788837209] req@ffff95f241a43480 x1875731015705600/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788837225 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 838.578480] Lustre: 3324:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 10 previous similar messages [ 843.194241] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 843.198040] Lustre: Skipped 1 previous similar message [ 843.317722] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 845.856648] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 846.084546] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 846.137136] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:131 to 0x280000400:193) [ 846.138885] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:163 to 0x240000400:193) [ 848.212493] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 857.384680] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 857.398120] Lustre: Skipped 1 previous similar message [ 858.804022] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 860.941167] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 871.103042] Lustre: DEBUG MARKER: == replay-single test 2c: setstripe replay =============== 23:14:16 (1788837256) [ 874.501066] LustreError: 22386:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 875.392527] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 877.551358] Lustre: Failing over lustre-MDT0000 [ 877.823602] Lustre: server umount lustre-MDT0000 complete [ 893.407418] 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 [ 893.410823] LustreError: MGC192.168.202.101@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 893.414256] Lustre: Skipped 1 previous similar message [ 903.657959] LustreError: 3322:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff95f373bf7480 x1875731015723136/t0(0) o250->MGC192.168.202.101@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 [ 904.365377] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 908.319856] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 908.515590] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 908.548234] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:225) [ 908.551663] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:225) [ 909.227545] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 919.658873] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 921.170887] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 929.278646] Lustre: DEBUG MARKER: == replay-single test 2d: setdirstripe replay ============ 23:15:14 (1788837314) [ 932.808978] LustreError: 23981:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 933.674419] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 935.696896] Lustre: Failing over lustre-MDT0000 [ 935.951425] Lustre: server umount lustre-MDT0000 complete [ 953.851960] LustreError: MGC192.168.202.101@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 954.545612] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 956.480764] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:257) [ 956.484074] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:257) [ 959.255975] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 959.466399] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 959.474343] Lustre: Skipped 3 previous similar messages [ 969.022254] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 970.692843] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 979.517569] Lustre: DEBUG MARKER: == replay-single test 2e: O_CREAT|O_EXCL create replay === 23:16:04 (1788837364) [ 980.686435] Lustre: *** cfs_fail_loc=13b, val=315*** [ 980.705348] Lustre: *** cfs_fail_loc=13b, val=2147483648*** [ 980.715442] LustreError: 24579:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff95f373bf5c00 x1875730992587392/t38654705666(0) o35->655a43b7-ea09-4702-a8c2-c6bfe1a107ef@192.168.202.1@tcp:29/0 lens 392/456 e 0 to 0 dl 1788837384 ref 1 fl Interpret:/600/0 rc 0/0 job:'openfile.0' uid:0 gid:0 projid:0 [ 985.469971] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 987.547675] Lustre: Failing over lustre-MDT0000 [ 987.957909] Lustre: server umount lustre-MDT0000 complete [ 1006.495199] Lustre: 3324:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788837377/real 1788837377] req@ffff95f37c34b800 x1875731015752832/t0(0) o400->MGC192.168.202.101@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1788837393 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1006.532559] Lustre: 3324:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 17 previous similar messages [ 1006.538908] 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 [ 1006.553070] Lustre: Skipped 4 previous similar messages [ 1016.817557] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x8c53a26e3b0a3c0 [ 1017.292430] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1017.296432] Lustre: Skipped 2 previous similar messages [ 1017.380884] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1021.744899] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1027.684263] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1027.693982] Lustre: Skipped 1 previous similar message [ 1027.826929] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1027.846699] Lustre: Skipped 1 previous similar message [ 1027.903300] Lustre: 26210:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff95f241a40700 x1875730992587392/t38654705666(0) o35->655a43b7-ea09-4702-a8c2-c6bfe1a107ef@192.168.202.1@tcp:76/0 lens 392/456 e 0 to 0 dl 1788837431 ref 1 fl Interpret:/602/0 rc 0/0 job:'openfile.0' uid:0 gid:0 projid:0 [ 1027.952244] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:289) [ 1027.954133] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:289) [ 1034.212910] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1035.799577] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1045.378464] Lustre: DEBUG MARKER: == replay-single test 3a: replay failed open(O_DIRECTORY) ========================================================== 23:17:10 (1788837430) [ 1048.791233] LustreError: 27190:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 1048.795354] LustreError: 27190:0:(osd_handler.c:720:osd_ro()) Skipped 1 previous similar message [ 1049.813297] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1051.926223] Lustre: Failing over lustre-MDT0000 [ 1052.140385] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1052.148045] Lustre: Skipped 2 previous similar messages [ 1052.232578] Lustre: server umount lustre-MDT0000 complete [ 1071.329121] LustreError: MGC192.168.202.101@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1071.340639] LustreError: Skipped 1 previous similar message [ 1071.868110] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1076.475834] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1079.005644] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:321) [ 1079.007661] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:321) [ 1086.217929] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1087.682955] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1096.158567] Lustre: DEBUG MARKER: == replay-single test 3b: replay failed open -ENOMEM ===== 23:18:01 (1788837481) [ 1100.554341] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1101.671399] Lustre: *** cfs_fail_loc=114, val=0*** [ 1104.633736] Lustre: Failing over lustre-MDT0000 [ 1104.887660] Lustre: server umount lustre-MDT0000 complete [ 1125.071108] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:353) [ 1125.080403] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:353) [ 1127.878292] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1128.947893] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 1128.965943] Lustre: Skipped 6 previous similar messages [ 1139.688869] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1141.278967] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1152.022199] Lustre: DEBUG MARKER: == replay-single test 3c: replay failed open -ENOMEM ===== 23:18:56 (1788837536) [ 1157.457623] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1158.917560] Lustre: *** cfs_fail_loc=128, val=0*** [ 1162.778102] Lustre: Failing over lustre-MDT0000 [ 1163.134643] Lustre: server umount lustre-MDT0000 complete [ 1181.155522] 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 [ 1181.182895] Lustre: Skipped 5 previous similar messages [ 1191.391919] LustreError: 3322:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff95f373991500 x1875731015803392/t0(0) o250->MGC192.168.202.101@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 [ 1192.091813] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1192.103058] Lustre: Skipped 1 previous similar message [ 1192.487812] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1192.503134] Lustre: Skipped 2 previous similar messages [ 1192.629285] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1192.641608] Lustre: Skipped 2 previous similar messages [ 1192.690776] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:385) [ 1192.695194] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:385) [ 1198.149440] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1209.054742] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1211.015555] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1220.128555] Lustre: DEBUG MARKER: == replay-single test 4a: |x| 10 open(O_CREAT)s ========== 23:20:05 (1788837605) [ 1223.416964] LustreError: 32158:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 1223.424393] LustreError: 32158:0:(osd_handler.c:720:osd_ro()) Skipped 2 previous similar messages [ 1224.286070] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1226.683707] Lustre: Failing over lustre-MDT0000 [ 1226.725690] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1226.924487] Lustre: server umount lustre-MDT0000 complete [ 1246.993996] LustreError: MGC192.168.202.101@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1247.007971] LustreError: Skipped 2 previous similar messages [ 1251.041572] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1254.291142] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:391 to 0x280000400:417) [ 1254.296580] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:391 to 0x240000400:417) [ 1259.607392] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1261.272542] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1269.755316] Lustre: DEBUG MARKER: == replay-single test 4b: |x| rm 10 files ================ 23:20:54 (1788837654) [ 1273.558897] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1275.558552] Lustre: Failing over lustre-MDT0000 [ 1275.824718] Lustre: server umount lustre-MDT0000 complete [ 1293.087113] Lustre: 3325:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788837663/real 1788837663] req@ffff95f358a5e300 x1875731015833088/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788837679 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1293.128390] Lustre: 3325:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 24 previous similar messages [ 1303.335946] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x8c53a26e3b0c1f7 [ 1303.917311] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1303.922135] Lustre: Skipped 4 previous similar messages [ 1305.412060] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:423 to 0x240000400:449) [ 1305.421294] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:423 to 0x280000400:449) [ 1309.403437] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1318.724338] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1320.248944] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1328.714267] Lustre: DEBUG MARKER: == replay-single test 5: |x| 220 open(O_CREAT) =========== 23:21:53 (1788837713) [ 1333.073128] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1342.957045] Lustre: Failing over lustre-MDT0000 [ 1343.671516] Lustre: server umount lustre-MDT0000 complete [ 1370.337473] LustreError: 3322:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff95f36fcf3b80 x1875731015855744/t0(0) o250->MGC192.168.202.101@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 [ 1370.672975] Lustre: lustre-MDT0000: Not available for connect from 192.168.202.1@tcp (not set up) [ 1370.687872] Lustre: Skipped 1 previous similar message [ 1371.070760] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1371.077133] Lustre: Skipped 2 previous similar messages [ 1375.891047] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1376.683568] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:577) [ 1376.684358] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:577) [ 1385.115691] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1386.536373] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1408.614892] Lustre: DEBUG MARKER: == replay-single test 6a: mkdir + contained create ======= 23:23:13 (1788837793) [ 1412.307743] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1414.495307] Lustre: Failing over lustre-MDT0000 [ 1414.881355] Lustre: server umount lustre-MDT0000 complete [ 1434.512131] Lustre: lustre-MDT0000: Not available for connect from 0@lo (not set up) [ 1439.110974] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1439.723259] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 1439.738232] Lustre: Skipped 10 previous similar messages [ 1443.573670] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:609) [ 1443.575811] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:609) [ 1450.453790] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1452.872536] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1466.572399] Lustre: DEBUG MARKER: == replay-single test 6b: |X| rmdir ====================== 23:24:10 (1788837850) [ 1471.933540] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1474.340743] Lustre: Failing over lustre-MDT0000 [ 1474.652215] Lustre: server umount lustre-MDT0000 complete [ 1491.935382] 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 [ 1491.958595] Lustre: Skipped 9 previous similar messages [ 1505.832267] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1505.842548] Lustre: Skipped 4 previous similar messages [ 1506.010844] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1506.018488] Lustre: Skipped 4 previous similar messages [ 1506.069763] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:641) [ 1506.073827] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:641) [ 1506.523944] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1515.616551] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1517.702308] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1526.703385] Lustre: DEBUG MARKER: == replay-single test 7: mkdir |X| contained create ====== 23:25:11 (1788837911) [ 1530.099135] LustreError: 40139:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 1530.103365] LustreError: 40139:0:(osd_handler.c:720:osd_ro()) Skipped 4 previous similar messages [ 1531.106864] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1533.510537] Lustre: Failing over lustre-MDT0000 [ 1534.006626] Lustre: server umount lustre-MDT0000 complete [ 1553.285924] LustreError: MGC192.168.202.101@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1553.297624] LustreError: Skipped 4 previous similar messages [ 1559.294442] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1562.389819] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:673) [ 1562.389902] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:673) [ 1569.290671] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1570.671511] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1578.802992] Lustre: DEBUG MARKER: == replay-single test 8: creat open |X| close ============ 23:26:03 (1788837963) [ 1582.900647] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1585.251583] Lustre: Failing over lustre-MDT0000 [ 1585.935595] Lustre: server umount lustre-MDT0000 complete [ 1606.122443] Lustre: lustre-MDT0000: Not available for connect from 0@lo (not set up) [ 1606.132552] Lustre: Skipped 2 previous similar messages [ 1612.229844] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1614.552371] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:705) [ 1614.554071] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:705) [ 1622.426450] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1624.415306] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1633.662125] Lustre: DEBUG MARKER: == replay-single test 9: |X| create (same inum/gen) ====== 23:26:58 (1788838018) [ 1638.142865] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1639.996842] Lustre: Failing over lustre-MDT0000 [ 1640.580537] Lustre: server umount lustre-MDT0000 complete [ 1669.401758] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1669.411449] Lustre: Skipped 4 previous similar messages [ 1671.002931] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:737) [ 1671.003590] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:737) [ 1674.893941] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1684.921910] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1686.492349] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1696.040392] Lustre: DEBUG MARKER: == replay-single test 10: create |X| rename unlink ======= 23:28:01 (1788838081) [ 1700.246032] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1702.636069] Lustre: Failing over lustre-MDT0000 [ 1702.988625] Lustre: server umount lustre-MDT0000 complete [ 1722.074988] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:769) [ 1722.075362] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:769) [ 1727.114447] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1736.696140] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1738.163761] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1747.491431] Lustre: DEBUG MARKER: == replay-single test 11: create open write rename |X| create-old-name read ========================================================== 23:28:52 (1788838132) [ 1752.377880] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1755.364034] Lustre: Failing over lustre-MDT0000 [ 1755.770133] Lustre: server umount lustre-MDT0000 complete [ 1783.263783] LustreError: 3322:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff95f373bdc380 x1875731016029440/t0(0) o250->MGC192.168.202.101@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 [ 1784.652654] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:771 to 0x240000400:801) [ 1784.659189] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:771 to 0x280000400:801) [ 1788.315567] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1798.715136] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1800.500847] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1809.228829] Lustre: DEBUG MARKER: == replay-single test 12: open, unlink |X| close ========= 23:29:53 (1788838193) [ 1814.040894] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1816.363724] Lustre: Failing over lustre-MDT0000 [ 1816.690730] Lustre: server umount lustre-MDT0000 complete [ 1835.936284] Lustre: 3325:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788838206/real 1788838206] req@ffff95f376c25c00 x1875731016043008/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788838222 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1835.968941] Lustre: 3325:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 76 previous similar messages [ 1845.216785] LustreError: 3322:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff95f37c9a1f80 x1875731016044928/t0(0) o250->MGC192.168.202.101@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 [ 1845.606226] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1845.609995] Lustre: Skipped 8 previous similar messages [ 1847.112367] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:771 to 0x240000400:833) [ 1847.126720] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:771 to 0x280000400:833) [ 1851.089789] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1860.735857] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1862.192461] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1871.150445] Lustre: DEBUG MARKER: == replay-single test 13: open chmod 0 |x| write close === 23:30:55 (1788838255) [ 1874.820389] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1876.624761] Lustre: Failing over lustre-MDT0000 [ 1876.881472] Lustre: server umount lustre-MDT0000 complete [ 1902.388979] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1903.329515] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:771 to 0x280000400:865) [ 1903.331167] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:835 to 0x240000400:865) [ 1914.194746] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1916.076562] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1924.623543] Lustre: DEBUG MARKER: == replay-single test 14: open(O_CREAT), unlink |X| close ========================================================== 23:31:49 (1788838309) [ 1929.034946] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1931.312818] Lustre: Failing over lustre-MDT0000 [ 1931.665426] Lustre: server umount lustre-MDT0000 complete [ 1960.723129] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:771 to 0x280000400:897) [ 1960.725253] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:867 to 0x240000400:897) [ 1964.595786] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1974.242865] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 1974.250675] Lustre: Skipped 17 previous similar messages [ 1976.117992] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1978.840253] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1991.300431] Lustre: DEBUG MARKER: == replay-single test 15: open(O_CREAT), unlink |X| touch new, close ========================================================== 23:32:55 (1788838375) [ 1996.222511] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1998.536209] Lustre: Failing over lustre-MDT0000 [ 1998.937104] Lustre: server umount lustre-MDT0000 complete [ 2016.231284] 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 [ 2016.247402] Lustre: Skipped 16 previous similar messages [ 2025.439717] LustreError: 3322:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff95f3739c1500 x1875731016095104/t0(0) o250->MGC192.168.202.101@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 [ 2026.938595] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 2026.942459] Lustre: Skipped 8 previous similar messages [ 2027.276067] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 2027.286726] Lustre: Skipped 8 previous similar messages [ 2027.363723] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:899 to 0x280000400:929) [ 2027.366437] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:899 to 0x240000400:929) [ 2031.984604] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2042.884552] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2045.082886] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2055.985380] Lustre: DEBUG MARKER: == replay-single test 16: |X| open(O_CREAT), unlink, touch new, unlink new ========================================================== 23:34:00 (1788838440) [ 2059.836637] LustreError: 54435:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 2059.848188] LustreError: 54435:0:(osd_handler.c:720:osd_ro()) Skipped 8 previous similar messages [ 2060.911248] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2063.497048] Lustre: Failing over lustre-MDT0000 [ 2064.080646] Lustre: server umount lustre-MDT0000 complete [ 2084.064353] LustreError: MGC192.168.202.101@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2084.085726] LustreError: Skipped 8 previous similar messages [ 2093.535989] LustreError: 3322:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff95f344b1b100 x1875731016113280/t0(0) o250->MGC192.168.202.101@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 [ 2101.203490] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2105.658701] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:899 to 0x280000400:961) [ 2105.660851] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:931 to 0x240000400:961) [ 2112.111808] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2114.123910] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2124.734984] Lustre: DEBUG MARKER: == replay-single test 17: |X| open(O_CREAT), |replay| close ========================================================== 23:35:09 (1788838509) [ 2129.314961] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2131.730022] Lustre: Failing over lustre-MDT0000 [ 2132.329080] Lustre: server umount lustre-MDT0000 complete [ 2161.120930] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x8c53a26e3b19707 [ 2163.879061] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:899 to 0x280000400:993) [ 2163.879276] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:963 to 0x240000400:993) [ 2167.020959] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2177.752474] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2180.126113] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2190.674211] Lustre: DEBUG MARKER: == replay-single test 18: open(O_CREAT), unlink, touch new, close, touch, unlink ========================================================== 23:36:15 (1788838575) [ 2195.244164] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2197.906795] Lustre: Failing over lustre-MDT0000 [ 2198.246698] Lustre: server umount lustre-MDT0000 complete [ 2226.662055] LustreError: 3322:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff95f3448f7b80 x1875731016147840/t0(0) o250->MGC192.168.202.101@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 [ 2227.595642] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 2227.600227] Lustre: Skipped 8 previous similar messages [ 2229.675513] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:995 to 0x280000400:1025) [ 2229.677698] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:995 to 0x240000400:1025) [ 2233.073385] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2244.704584] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2246.652194] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2256.502794] Lustre: DEBUG MARKER: == replay-single test 19: mcreate, open, write, rename === 23:37:21 (1788838641) [ 2261.493769] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2263.857045] Lustre: Failing over lustre-MDT0000 [ 2264.212410] Lustre: server umount lustre-MDT0000 complete [ 2300.058577] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2306.562724] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1027 to 0x240000400:1057) [ 2306.563463] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1027 to 0x280000400:1057) [ 2313.648834] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2315.431628] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2326.231426] Lustre: DEBUG MARKER: == replay-single test 20a: |X| open(O_CREAT), unlink, replay, close (test mds_cleanup_orphans) ========================================================== 23:38:30 (1788838710) [ 2332.328639] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2335.918178] Lustre: Failing over lustre-MDT0000 [ 2336.379693] Lustre: server umount lustre-MDT0000 complete [ 2373.603533] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2378.234901] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1059 to 0x240000400:1089) [ 2378.235612] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1027 to 0x280000400:1089) [ 2386.858300] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2388.478503] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2397.036586] Lustre: DEBUG MARKER: == replay-single test 20b: write, unlink, eviction, replay (test mds_cleanup_orphans) ========================================================== 23:39:41 (1788838781) [ 2403.343296] Lustre: 62442:0:(genops.c:1774:obd_export_evict_by_uuid()) lustre-MDT0000: evicting 655a43b7-ea09-4702-a8c2-c6bfe1a107ef at adminstrative request [ 2408.297484] Lustre: Failing over lustre-MDT0000 [ 2408.508684] Lustre: lustre-MDT0000: Not available for connect from 192.168.202.1@tcp (stopping) [ 2408.794663] Lustre: server umount lustre-MDT0000 complete [ 2436.511163] Lustre: 3324:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788838807/real 1788838807] req@ffff95f372d5bb80 x1875731016202368/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788838823 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2436.528841] Lustre: 3324:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 80 previous similar messages [ 2437.605081] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x8c53a26e3b1ac23 [ 2444.128388] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2449.475766] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1091 to 0x240000400:1121) [ 2449.475770] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1027 to 0x280000400:1121) [ 2455.707767] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2457.633382] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2464.076477] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 2479.098748] Lustre: DEBUG MARKER: before 4096, after 4096 [ 2485.784644] Lustre: DEBUG MARKER: == replay-single test 20c: check that client eviction does not affect file content ========================================================== 23:41:10 (1788838870) [ 2486.896294] Lustre: 64530:0:(genops.c:1774:obd_export_evict_by_uuid()) lustre-MDT0000: evicting 655a43b7-ea09-4702-a8c2-c6bfe1a107ef at adminstrative request [ 2497.339656] Lustre: DEBUG MARKER: == replay-single test 21: |X| open(O_CREAT), unlink touch new, replay, close (test mds_cleanup_orphans) ========================================================== 23:41:22 (1788838882) [ 2501.047745] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2503.486799] Lustre: Failing over lustre-MDT0000 [ 2503.825764] Lustre: server umount lustre-MDT0000 complete [ 2530.785491] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x8c53a26e3b1b12b [ 2531.165945] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 2531.167860] Lustre: Skipped 9 previous similar messages [ 2532.561880] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1124 to 0x240000400:1153) [ 2532.564669] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1123 to 0x280000400:1153) [ 2535.235561] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2543.020823] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2544.360759] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2553.157300] Lustre: DEBUG MARKER: == replay-single test 22: open(O_CREAT), |X| unlink, replay, close (test mds_cleanup_orphans) ========================================================== 23:42:17 (1788838937) [ 2557.149584] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2559.662462] Lustre: Failing over lustre-MDT0000 [ 2560.087855] Lustre: server umount lustre-MDT0000 complete [ 2588.924203] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1155 to 0x240000400:1185) [ 2588.930412] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1155 to 0x280000400:1185) [ 2591.941646] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2601.330517] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 2601.334591] Lustre: Skipped 20 previous similar messages [ 2601.908543] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2603.266559] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2611.290394] Lustre: DEBUG MARKER: == replay-single test 23: open(O_CREAT), |X| unlink touch new, replay, close (test mds_cleanup_orphans) ========================================================== 23:43:16 (1788838996) [ 2615.843256] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2617.820137] Lustre: Failing over lustre-MDT0000 [ 2618.063671] Lustre: server umount lustre-MDT0000 complete [ 2636.109298] 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 [ 2636.123967] Lustre: Skipped 17 previous similar messages [ 2640.777592] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2645.027658] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 2645.035840] Lustre: Skipped 8 previous similar messages [ 2645.217707] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 2645.221981] Lustre: Skipped 8 previous similar messages [ 2645.260534] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1187 to 0x280000400:1217) [ 2645.275129] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1187 to 0x240000400:1217) [ 2650.639975] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2652.110931] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2660.940595] Lustre: DEBUG MARKER: == replay-single test 24: open(O_CREAT), replay, unlink, close (test mds_cleanup_orphans) ========================================================== 23:44:06 (1788839046) [ 2664.226829] LustreError: 69635:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 2664.235423] LustreError: 69635:0:(osd_handler.c:720:osd_ro()) Skipped 7 previous similar messages [ 2665.096934] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2666.934193] Lustre: Failing over lustre-MDT0000 [ 2666.984274] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2667.250482] Lustre: server umount lustre-MDT0000 complete [ 2686.750872] LustreError: MGC192.168.202.101@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2686.759745] LustreError: Skipped 8 previous similar messages [ 2687.052799] Lustre: lustre-MDT0000: Not available for connect from 192.168.202.1@tcp (not set up) [ 2687.066899] Lustre: Skipped 1 previous similar message [ 2688.446439] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1219 to 0x280000400:1249) [ 2688.448952] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1219 to 0x240000400:1249) [ 2692.906551] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2701.666797] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2703.087247] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2710.051792] Lustre: DEBUG MARKER: == replay-single test 25: open(O_CREAT), unlink, replay, close (test mds_cleanup_orphans) ========================================================== 23:44:55 (1788839095) [ 2713.466843] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2714.910136] Lustre: Failing over lustre-MDT0000 [ 2715.145274] Lustre: server umount lustre-MDT0000 complete [ 2733.098566] Lustre: lustre-MDT0000: Not available for connect from 192.168.202.1@tcp (not set up) [ 2734.758403] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1251 to 0x240000400:1281) [ 2734.758792] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1219 to 0x280000400:1281) [ 2738.056791] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2747.086980] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2748.239211] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2756.256729] Lustre: DEBUG MARKER: == replay-single test 26: |X| open(O_CREAT), unlink two, close one, replay, close one (test mds_cleanup_orphans) ========================================================== 23:45:41 (1788839141) [ 2759.896074] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2761.954866] Lustre: Failing over lustre-MDT0000 [ 2762.261424] Lustre: server umount lustre-MDT0000 complete [ 2790.889906] LustreError: 3322:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff95f345f76d80 x1875731016304512/t0(0) o250->MGC192.168.202.101@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 [ 2796.635658] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2805.066631] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1283 to 0x240000400:1313) [ 2805.071979] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1283 to 0x280000400:1313) [ 2811.740930] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2814.202817] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2826.086898] Lustre: DEBUG MARKER: == replay-single test 27: |X| open(O_CREAT), unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 23:46:50 (1788839210) [ 2832.362508] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2834.993489] Lustre: Failing over lustre-MDT0000 [ 2835.557079] Lustre: server umount lustre-MDT0000 complete [ 2863.212686] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 2863.224105] Lustre: Skipped 9 previous similar messages [ 2869.226623] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2876.763527] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1315 to 0x280000400:1345) [ 2876.765781] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1315 to 0x240000400:1345) [ 2883.887967] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2885.699829] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2897.642822] Lustre: DEBUG MARKER: == replay-single test 28: open(O_CREAT), |X| unlink two, close one, replay, close one (test mds_cleanup_orphans) ========================================================== 23:48:01 (1788839281) [ 2903.850881] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2906.781681] Lustre: Failing over lustre-MDT0000 [ 2907.180987] Lustre: lustre-MDT0000: Not available for connect from 192.168.202.1@tcp (stopping) [ 2907.513847] Lustre: server umount lustre-MDT0000 complete [ 2941.891966] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2947.377639] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1347 to 0x240000400:1377) [ 2947.387196] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1347 to 0x280000400:1377) [ 2953.939534] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2955.630618] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2964.783591] Lustre: DEBUG MARKER: == replay-single test 29: open(O_CREAT), |X| unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 23:49:10 (1788839350) [ 2969.210456] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2972.319209] Lustre: Failing over lustre-MDT0000 [ 2972.740504] Lustre: server umount lustre-MDT0000 complete [ 3008.175672] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3014.059203] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1379 to 0x280000400:1409) [ 3014.059399] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1379 to 0x240000400:1409) [ 3020.417889] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3022.667547] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3031.760417] Lustre: DEBUG MARKER: == replay-single test 30: open(O_CREAT) two, unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 23:50:16 (1788839416) [ 3036.105712] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3037.930851] Lustre: Failing over lustre-MDT0000 [ 3038.330603] Lustre: server umount lustre-MDT0000 complete [ 3058.655102] Lustre: 3323:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788839429/real 1788839429] req@ffff95f34796aa00 x1875731016373376/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788839445 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3058.683089] Lustre: 3323:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 75 previous similar messages [ 3068.943744] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x8c53a26e3b1df7d [ 3075.722838] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3080.406735] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1411 to 0x240000400:1441) [ 3080.410225] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1411 to 0x280000400:1441) [ 3087.042332] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3089.213714] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3098.442931] Lustre: DEBUG MARKER: == replay-single test 31: open(O_CREAT) two, unlink one, |X| unlink one, close two (test mds_cleanup_orphans) ========================================================== 23:51:23 (1788839483) [ 3102.350929] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3104.568547] Lustre: Failing over lustre-MDT0000 [ 3104.906465] Lustre: server umount lustre-MDT0000 complete [ 3124.711848] LustreError: 81372: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. [ 3130.788888] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3132.680137] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1443 to 0x280000400:1473) [ 3132.688164] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1443 to 0x240000400:1473) [ 3140.347915] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3142.297832] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3152.081484] Lustre: DEBUG MARKER: == replay-single test 32: close() notices client eviction; close() after client eviction ========================================================== 23:52:16 (1788839536) [ 3153.280889] Lustre: 82266:0:(genops.c:1774:obd_export_evict_by_uuid()) lustre-MDT0000: evicting 655a43b7-ea09-4702-a8c2-c6bfe1a107ef at adminstrative request [ 3165.124349] Lustre: DEBUG MARKER: == replay-single test 33a: fid seq shouldn't be reused after abort recovery ========================================================== 23:52:29 (1788839549) [ 3168.546976] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3170.233166] Lustre: Failing over lustre-MDT0000 [ 3170.453776] Lustre: server umount lustre-MDT0000 complete [ 3180.055245] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3180.059532] Lustre: Skipped 10 previous similar messages [ 3180.123726] Lustre: lustre-MDT0000: Aborting client recovery [ 3180.130806] LustreError: 83187:0:(ldlm_lib.c:3029:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 3180.137822] Lustre: 83233:0:(ldlm_lib.c:2429:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 3180.151788] Lustre: 83233:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 655a43b7-ea09-4702-a8c2-c6bfe1a107ef@ [ 3180.167290] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 3180.243661] Lustre: lustre-MDT0000-osd: cancel update llog [0x200000400:0x1:0x0] [ 3180.418375] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1480 to 0x280000400:1505) [ 3180.423288] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1479 to 0x240000400:1505) [ 3185.904410] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3203.099517] Lustre: DEBUG MARKER: == replay-single test 33b: test fid seq allocation ======= 23:53:07 (1788839587) [ 3208.070920] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3210.176620] Lustre: Failing over lustre-MDT0000 [ 3210.548193] Lustre: server umount lustre-MDT0000 complete [ 3220.657451] Lustre: *** cfs_fail_loc=1311, val=0*** [ 3220.674869] Lustre: lustre-MDT0000: Aborting client recovery [ 3220.680266] LustreError: 84551:0:(ldlm_lib.c:3029:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 3220.684806] Lustre: 84599:0:(ldlm_lib.c:2429:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 3220.688689] Lustre: 84599:0:(ldlm_lib.c:2429:target_recovery_overseer()) Skipped 2 previous similar messages [ 3220.691110] Lustre: 84599:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 655a43b7-ea09-4702-a8c2-c6bfe1a107ef@ [ 3220.694434] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 3220.725873] Lustre: lustre-MDT0000-osd: cancel update llog [0x200015bc0:0x1:0x0] [ 3220.797162] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1516 to 0x240000400:1537) [ 3220.805217] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1516 to 0x280000400:1537) [ 3225.575224] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 3225.577020] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3225.582269] Lustre: Skipped 22 previous similar messages [ 3231.374618] Lustre: *** cfs_fail_loc=1311, val=0*** [ 3238.223352] Lustre: DEBUG MARKER: == replay-single test 34: abort recovery before client does replay (test mds_cleanup_orphans) ========================================================== 23:53:43 (1788839623) [ 3242.609209] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3244.876741] Lustre: Failing over lustre-MDT0000 [ 3245.127799] Lustre: server umount lustre-MDT0000 complete [ 3255.198138] 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 [ 3255.211832] Lustre: Skipped 21 previous similar messages [ 3255.424615] Lustre: lustre-MDT0000: Aborting client recovery [ 3255.427315] LustreError: 85914:0:(ldlm_lib.c:3029:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 3255.431975] Lustre: 85961:0:(ldlm_lib.c:2429:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 3255.437293] Lustre: 85961:0:(ldlm_lib.c:2429:target_recovery_overseer()) Skipped 2 previous similar messages [ 3255.441696] Lustre: 85961:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 655a43b7-ea09-4702-a8c2-c6bfe1a107ef@ [ 3255.453414] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 3255.522292] Lustre: lustre-MDT0000-osd: cancel update llog [0x200016778:0x1:0x0] [ 3255.616323] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1544 to 0x240000400:1569) [ 3255.619344] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1543 to 0x280000400:1569) [ 3260.078422] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3274.285571] Lustre: DEBUG MARKER: == replay-single test 35: test recovery from llog for unlink op ========================================================== 23:54:18 (1788839658) [ 3275.549420] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 3275.559415] LustreError: 85925:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff95f37bfbe300 x1875730993590272/t201863462916(0) o36->655a43b7-ea09-4702-a8c2-c6bfe1a107ef@192.168.202.1@tcp:53/0 lens 512/456 e 0 to 0 dl 1788839673 ref 1 fl Interpret:/200/0 rc 0/0 job:'rm.0' uid:0 gid:0 projid:4294967295 [ 3279.540625] Lustre: Failing over lustre-MDT0000 [ 3279.954192] Lustre: server umount lustre-MDT0000 complete [ 3289.892717] LustreError: MGC192.168.202.101@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3289.899818] LustreError: Skipped 10 previous similar messages [ 3290.656708] Lustre: lustre-MDT0000: Aborting client recovery [ 3290.658625] LustreError: 87124:0:(ldlm_lib.c:3029:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 3290.662965] Lustre: 87169:0:(ldlm_lib.c:2429:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 3290.669890] Lustre: 87169:0:(ldlm_lib.c:2429:target_recovery_overseer()) Skipped 2 previous similar messages [ 3290.679963] Lustre: 87169:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 655a43b7-ea09-4702-a8c2-c6bfe1a107ef@ [ 3290.695327] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 3290.712742] Lustre: lustre-MDT0000: Denying connection for new client 655a43b7-ea09-4702-a8c2-c6bfe1a107ef (at 192.168.202.1@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 1 evicted) already passed deadline 54:50 [ 3290.745576] Lustre: Skipped 11 previous similar messages [ 3290.802222] Lustre: lustre-MDT0000-osd: cancel update llog [0x200017330:0x1:0x0] [ 3290.956333] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1571 to 0x280000400:1601) [ 3290.960340] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1544 to 0x240000400:1601) [ 3296.596364] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3308.728459] Lustre: DEBUG MARKER: SKIP: replay-single test_36 skipping ALWAYS excluded test 36 [ 3310.193539] Lustre: DEBUG MARKER: == replay-single test 37: abort recovery before client does replay (test mds_cleanup_orphans for directories) ========================================================== 23:54:55 (1788839695) [ 3313.332823] LustreError: 87921:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 3313.338357] LustreError: 87921:0:(osd_handler.c:720:osd_ro()) Skipped 10 previous similar messages [ 3314.308460] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3316.974995] Lustre: Failing over lustre-MDT0000 [ 3317.370184] Lustre: server umount lustre-MDT0000 complete [ 3326.493775] Lustre: lustre-MDT0000: Aborting client recovery [ 3326.500156] LustreError: 88583:0:(ldlm_lib.c:3029:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 3326.513742] Lustre: 88629:0:(ldlm_lib.c:2429:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 3326.522834] Lustre: 88629:0:(ldlm_lib.c:2429:target_recovery_overseer()) Skipped 2 previous similar messages [ 3326.526805] Lustre: 88629:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 655a43b7-ea09-4702-a8c2-c6bfe1a107ef@192.168.202.1@tcp [ 3326.537741] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 3326.550362] Lustre: lustre-MDT0000: Denying connection for new client 655a43b7-ea09-4702-a8c2-c6bfe1a107ef (at 192.168.202.1@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 1 evicted) already passed deadline 55:26 [ 3326.595148] Lustre: lustre-MDT0000-osd: cancel update llog [0x200017b00:0x1:0x0] [ 3326.712275] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1571 to 0x280000400:1633) [ 3326.736135] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1544 to 0x240000400:1633) [ 3331.696903] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3345.031370] Lustre: DEBUG MARKER: == replay-single test 38: test recovery from unlink llog (test llog_gen_rec) ========================================================== 23:55:30 (1788839730) [ 3373.893645] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3375.668745] Lustre: Failing over lustre-MDT0000 [ 3375.952807] Lustre: server umount lustre-MDT0000 complete [ 3404.321611] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 3404.334816] Lustre: Skipped 8 previous similar messages [ 3404.481840] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 3404.486199] Lustre: Skipped 8 previous similar messages [ 3404.538804] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2034 to 0x240000400:2049) [ 3404.538913] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2034 to 0x280000400:2049) [ 3408.197860] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3417.494358] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3419.120700] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3440.599747] Lustre: DEBUG MARKER: == replay-single test 39: test recovery from unlink llog (test llog_gen_rec) ========================================================== 23:57:05 (1788839825) [ 3465.111652] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3476.333336] Lustre: Failing over lustre-MDT0000 [ 3476.877102] Lustre: server umount lustre-MDT0000 complete [ 3495.313674] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 3495.324514] Lustre: Skipped 20 previous similar messages [ 3499.616635] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3501.257138] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2450 to 0x240000400:2465) [ 3501.257644] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2450 to 0x280000400:2465) [ 3510.026397] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3511.544281] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3534.304647] Lustre: DEBUG MARKER: == replay-single test 41: read from a valid osc while other oscs are invalid ========================================================== 23:58:39 (1788839919) [ 3536.302374] Lustre: setting import lustre-OST0001_UUID INACTIVE by administrator request [ 3537.168563] Lustre: lustre-OST0001: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnecting [ 3537.176356] LustreError: lustre-OST0001-osc-MDT0000: This client was evicted by lustre-OST0001; in progress operations using this service will fail. [ 3543.381614] Lustre: DEBUG MARKER: == replay-single test 42: recovery after ost failure ===== 23:58:48 (1788839928) [ 3572.180344] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 3586.955801] Lustre: Failing over lustre-OST0000 [ 3588.590390] Lustre: lustre-OST0000: Not available for connect from 0@lo (stopping) [ 3589.091209] Lustre: server umount lustre-OST0000 complete [ 3593.710862] LustreError: 14707: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. [ 3593.750399] LustreError: 14707:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 1 previous similar message [ 3598.835410] LustreError: 6696: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. [ 3598.861286] LustreError: 6696:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 1 previous similar message [ 3603.939964] LustreError: 36618: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. [ 3603.966378] LustreError: 36618:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 1 previous similar message [ 3613.787387] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3674.157223] Lustre: DEBUG MARKER: == replay-single test 43: mds osc import failure during recovery; don't LBUG ========================================================== 00:00:58 (1788840058) [ 3679.059390] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3681.987306] Lustre: Failing over lustre-MDT0000 [ 3682.210055] Lustre: server umount lustre-MDT0000 complete [ 3700.264819] Lustre: lustre-MDT0000: Not available for connect from 192.168.202.1@tcp (not set up) [ 3700.278527] Lustre: Skipped 1 previous similar message [ 3701.535698] Lustre: 3324:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788840071/real 1788840071] req@ffff95f37d219c00 x1875731016947840/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788840087 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3701.551578] Lustre: 3324:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 50 previous similar messages [ 3701.641351] Lustre: *** cfs_fail_loc=204, val=2147483648*** [ 3701.642118] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2866 to 0x280000400:2881) [ 3704.683103] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3714.534533] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3716.012755] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3718.111296] LustreError: 96563:0:(osp_precreate.c:974:osp_precreate_cleanup_orphans()) lustre-OST0000-osc-MDT0000: cannot cleanup orphans: rc = -11 [ 3718.113969] Lustre: lustre-OST0000: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnecting [ 3719.136634] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2867 to 0x240000400:2913) [ 3734.034850] Lustre: DEBUG MARKER: == replay-single test 44a: race in target handle connect ========================================================== 00:01:59 (1788840119) [ 3739.408296] LustreError: 96540:0:(ldlm_lib.c:1176:target_handle_connect()) cfs_race id 701 sleeping [ 3744.735344] LustreError: 96540:0:(ldlm_lib.c:1176:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 3744.746350] Lustre: lustre-MDT0000: Client 655a43b7-ea09-4702-a8c2-c6bfe1a107ef (at 192.168.202.1@tcp) reconnecting [ 3744.832473] LustreError: 36611:0:(ldlm_lib.c:1176:target_handle_connect()) cfs_fail_race id 701 waking [ 3746.841625] LustreError: 97651:0:(ldlm_lib.c:1176:target_handle_connect()) cfs_race id 701 sleeping [ 3751.903383] LustreError: 97651:0:(ldlm_lib.c:1176:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 3751.917448] Lustre: lustre-MDT0000: Client 655a43b7-ea09-4702-a8c2-c6bfe1a107ef (at 192.168.202.1@tcp) reconnecting [ 3753.755762] LustreError: 96538:0:(ldlm_lib.c:1176:target_handle_connect()) cfs_race id 701 sleeping [ 3759.072104] LustreError: 96538:0:(ldlm_lib.c:1176:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 3759.100355] Lustre: lustre-MDT0000: Client 655a43b7-ea09-4702-a8c2-c6bfe1a107ef (at 192.168.202.1@tcp) reconnecting [ 3760.893474] LustreError: 97651:0:(ldlm_lib.c:1176:target_handle_connect()) cfs_race id 701 sleeping [ 3766.239133] LustreError: 97651:0:(ldlm_lib.c:1176:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 3768.420566] LustreError: 96541:0:(ldlm_lib.c:1176:target_handle_connect()) cfs_race id 701 sleeping [ 3773.919564] LustreError: 96541:0:(ldlm_lib.c:1176:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 3773.926457] Lustre: lustre-MDT0000: Client 655a43b7-ea09-4702-a8c2-c6bfe1a107ef (at 192.168.202.1@tcp) reconnecting [ 3773.939637] Lustre: Skipped 1 previous similar message [ 3783.591579] LustreError: 96540:0:(ldlm_lib.c:1176:target_handle_connect()) cfs_race id 701 sleeping [ 3783.603697] LustreError: 96540:0:(ldlm_lib.c:1176:target_handle_connect()) Skipped 1 previous similar message [ 3788.767154] LustreError: 96540:0:(ldlm_lib.c:1176:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 3788.779582] LustreError: 96540:0:(ldlm_lib.c:1176:target_handle_connect()) Skipped 1 previous similar message [ 3796.447349] Lustre: lustre-MDT0000: Client 655a43b7-ea09-4702-a8c2-c6bfe1a107ef (at 192.168.202.1@tcp) reconnecting [ 3796.453311] Lustre: Skipped 2 previous similar messages [ 3806.009768] LustreError: 96541:0:(ldlm_lib.c:1176:target_handle_connect()) cfs_race id 701 sleeping [ 3806.021485] LustreError: 96541:0:(ldlm_lib.c:1176:target_handle_connect()) Skipped 2 previous similar messages [ 3811.296067] LustreError: 96541:0:(ldlm_lib.c:1176:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 3811.301872] LustreError: 96541:0:(ldlm_lib.c:1176:target_handle_connect()) Skipped 2 previous similar messages [ 3819.712362] Lustre: DEBUG MARKER: == replay-single test 44b: race in target handle connect ========================================================== 00:03:24 (1788840204) [ 3821.669357] LustreError: 96540:0:(ldlm_lib.c:1434:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 3831.849565] Lustre: lustre-MDT0000: Export ffff95f360304000 already connecting from 192.168.202.1@tcp [ 3834.853544] Lustre: lustre-MDT0000: Export ffff95f360304000 already connecting from 192.168.202.1@tcp [ 3836.905347] Lustre: lustre-MDT0000: Export ffff95f360304000 already connecting from 192.168.202.1@tcp [ 3842.088702] Lustre: lustre-MDT0000: Export ffff95f360304000 already connecting from 192.168.202.1@tcp [ 3847.204118] Lustre: lustre-MDT0000: Export ffff95f360304000 already connecting from 192.168.202.1@tcp [ 3847.216474] Lustre: Skipped 1 previous similar message [ 3857.440987] Lustre: lustre-MDT0000: Export ffff95f360304000 already connecting from 192.168.202.1@tcp [ 3857.447570] Lustre: Skipped 1 previous similar message [ 3861.671428] LustreError: 96540:0:(ldlm_lib.c:1434:target_handle_connect()) cfs_fail_timeout id 704 awake [ 3861.687441] Lustre: 96540:0:(service.c:2582:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/20s); client may timeout req@ffff95f34743a680 x1875730996230784/t0(0) o38->655a43b7-ea09-4702-a8c2-c6bfe1a107ef@192.168.202.1@tcp:0/0 lens 520/416 e 0 to 0 dl 1788840228 ref 1 fl Complete:H/200/0 rc 0/0 job:'lctl.0' uid:0 gid:0 projid:4294967295 [ 3862.573375] Lustre: lustre-MDT0000: Client 655a43b7-ea09-4702-a8c2-c6bfe1a107ef (at 192.168.202.1@tcp) reconnecting [ 3862.580886] Lustre: Skipped 3 previous similar messages [ 3862.584224] LustreError: 96538:0:(ldlm_lib.c:1434:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 3888.179253] Lustre: lustre-MDT0000: Export ffff95f360304000 already connecting from 192.168.202.1@tcp [ 3902.607983] LustreError: 96538:0:(ldlm_lib.c:1434:target_handle_connect()) cfs_fail_timeout id 704 awake [ 3902.614600] Lustre: 96538:0:(service.c:2582:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/20s); client may timeout req@ffff95f377f26a00 x1875730996234112/t0(0) o38->655a43b7-ea09-4702-a8c2-c6bfe1a107ef@192.168.202.1@tcp:0/0 lens 520/416 e 0 to 0 dl 1788840269 ref 1 fl Complete:H/200/0 rc 0/0 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3903.523855] LustreError: 98053:0:(ldlm_lib.c:1434:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 3928.100234] Lustre: lustre-MDT0000: Export ffff95f360304000 already connecting from 192.168.202.1@tcp [ 3928.114535] Lustre: Skipped 3 previous similar messages [ 3943.615211] LustreError: 98053:0:(ldlm_lib.c:1434:target_handle_connect()) cfs_fail_timeout id 704 awake [ 3943.627513] Lustre: 98053:0:(service.c:2582:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/20s); client may timeout req@ffff95f36f248a80 x1875730996236032/t0(0) o38->655a43b7-ea09-4702-a8c2-c6bfe1a107ef@192.168.202.1@tcp:0/0 lens 520/416 e 0 to 0 dl 1788840310 ref 1 fl Complete:H/200/0 rc 0/0 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3948.581356] Lustre: lustre-MDT0000: Client 655a43b7-ea09-4702-a8c2-c6bfe1a107ef (at 192.168.202.1@tcp) reconnecting [ 3948.594794] Lustre: Skipped 1 previous similar message [ 3948.606402] LustreError: 96541:0:(ldlm_lib.c:1434:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 3988.695145] LustreError: 96541:0:(ldlm_lib.c:1434:target_handle_connect()) cfs_fail_timeout id 704 awake [ 3988.707433] Lustre: 96541:0:(service.c:2582:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/20s); client may timeout req@ffff95f373bddf80 x1875730996238208/t0(0) o38->655a43b7-ea09-4702-a8c2-c6bfe1a107ef@192.168.202.1@tcp:0/0 lens 520/416 e 0 to 0 dl 1788840355 ref 1 fl Complete:H/200/0 rc 0/0 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3989.538103] LustreError: 98053:0:(ldlm_lib.c:1434:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 4014.119095] Lustre: lustre-MDT0000: Export ffff95f360304000 already connecting from 192.168.202.1@tcp [ 4014.138141] Lustre: Skipped 8 previous similar messages [ 4029.551937] LustreError: 98053:0:(ldlm_lib.c:1434:target_handle_connect()) cfs_fail_timeout id 704 awake [ 4029.565836] Lustre: 98053:0:(service.c:2582:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/20s); client may timeout req@ffff95f348ad6d80 x1875730996240128/t0(0) o38->655a43b7-ea09-4702-a8c2-c6bfe1a107ef@192.168.202.1@tcp:0/0 lens 520/416 e 0 to 0 dl 1788840396 ref 1 fl Complete:H/200/0 rc 0/0 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4034.594661] LustreError: 96538:0:(ldlm_lib.c:1434:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 4051.097169] LustreError: 96538:0:(ldlm_lib.c:1434:target_handle_connect()) cfs_fail_timeout interrupted [ 4055.843057] Lustre: DEBUG MARKER: == replay-single test 44c: race in target handle connect ========================================================== 00:07:20 (1788840440) [ 4059.331076] LustreError: 100398:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 4059.337993] LustreError: 100398:0:(osd_handler.c:720:osd_ro()) Skipped 4 previous similar messages [ 4060.386848] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4065.022692] Lustre: Failing over lustre-MDT0000 [ 4065.387956] Lustre: server umount lustre-MDT0000 complete [ 4074.059932] LustreError: MGC192.168.202.101@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4074.066147] LustreError: Skipped 4 previous similar messages [ 4074.357730] Lustre: *** cfs_fail_loc=712, val=0*** [ 4074.359557] LustreError: 8524:0:(service.c:1394:ptlrpc_check_req()) @@@ Invalid replay without recovery req@ffff95f3584ddc00 x1875731017046144/t0(0) o400->lustre-MDT0000-mdtlov_UUID@0@lo:0/0 lens 224/0 e 0 to 0 dl 0 ref 1 fl New:/2c0/ffffffff rc 0/-1 job:'ptlrpcd_rcv.0' uid:0 gid:0 projid:4294967295 [ 4074.370752] 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 [ 4074.396826] Lustre: Skipped 15 previous similar messages [ 4074.574894] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4074.578926] Lustre: Skipped 8 previous similar messages [ 4074.678641] Lustre: lustre-MDT0000: Aborting client recovery [ 4074.682192] LustreError: 101063:0:(ldlm_lib.c:3029:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 4074.687791] Lustre: 101109:0:(ldlm_lib.c:2429:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 4074.692992] Lustre: 101109:0:(ldlm_lib.c:2429:target_recovery_overseer()) Skipped 2 previous similar messages [ 4074.699986] Lustre: 101109:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 655a43b7-ea09-4702-a8c2-c6bfe1a107ef@ [ 4074.709177] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 4074.781687] Lustre: lustre-MDT0000-osd: cancel update llog [0x2000182d0:0x1:0x0] [ 4074.914840] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2866 to 0x280000400:2913) [ 4074.924292] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2867 to 0x240000400:2945) [ 4079.598100] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 4079.600861] Lustre: Skipped 16 previous similar messages [ 4079.722650] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4088.434538] Lustre: Failing over lustre-MDT0000 [ 4088.711653] Lustre: server umount lustre-MDT0000 complete [ 4115.423923] LustreError: 3322:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff95f36f24bb80 x1875731017057664/t0(0) o250->MGC192.168.202.101@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 [ 4115.436720] LustreError: 3322:0:(client.c:1404:ptlrpc_import_delay_req()) Skipped 2 previous similar messages [ 4115.834691] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4115.849110] Lustre: Skipped 5 previous similar messages [ 4117.548892] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4117.556659] Lustre: Skipped 3 previous similar messages [ 4117.706924] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4117.715700] Lustre: Skipped 3 previous similar messages [ 4117.763534] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2867 to 0x240000400:2977) [ 4117.763534] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2866 to 0x280000400:2945) [ 4119.732469] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4129.857684] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4131.514587] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4140.433775] Lustre: DEBUG MARKER: == replay-single test 45: Handle failed close ============ 00:08:45 (1788840525) [ 4140.671593] Lustre: lustre-MDT0000: Client 655a43b7-ea09-4702-a8c2-c6bfe1a107ef (at 192.168.202.1@tcp) reconnecting [ 4140.678311] Lustre: Skipped 2 previous similar messages [ 4149.924750] Lustre: DEBUG MARKER: == replay-single test 46: Don't leak file handle after open resend (3325) ========================================================== 00:08:54 (1788840534) [ 4151.281092] Lustre: *** cfs_fail_loc=122, val=2147483648*** [ 4151.297588] LustreError: 102037:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff95f3458e4700 x1875730996298112/t0(0) o700->655a43b7-ea09-4702-a8c2-c6bfe1a107ef@192.168.202.1@tcp:174/0 lens 264/248 e 0 to 0 dl 1788840549 ref 1 fl Interpret:/200/0 rc 0/0 job:'touch.0' uid:0 gid:0 projid:4294967295 [ 4172.245155] Lustre: Failing over lustre-MDT0000 [ 4172.530095] Lustre: server umount lustre-MDT0000 complete [ 4205.190568] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2979 to 0x240000400:3009) [ 4205.192311] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2947 to 0x280000400:2977) [ 4209.949379] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4220.254946] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4221.953691] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4233.720221] Lustre: DEBUG MARKER: == replay-single test 47: MDS->OSC failure during precreate cleanup (2824) ========================================================== 00:10:18 (1788840618) [ 4236.295295] Lustre: Failing over lustre-OST0000 [ 4236.416299] Lustre: server umount lustre-OST0000 complete [ 4238.305188] LustreError: 36607: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. [ 4238.330477] LustreError: 36607:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 1 previous similar message [ 4239.397972] LustreError: 36609:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.202.1@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4243.434027] LustreError: 6697: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. [ 4248.556358] LustreError: 6698: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. [ 4248.573431] LustreError: 6698:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 1 previous similar message [ 4261.785492] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4272.150614] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 4273.569818] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4347.690989] Lustre: DEBUG MARKER: == replay-single test 48: MDS->OSC failure during precreate cleanup (2824) ========================================================== 00:12:12 (1788840732) [ 4352.630440] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4355.448524] Lustre: Failing over lustre-MDT0000 [ 4357.169439] LustreError: 103732:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.202.1@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4357.186265] LustreError: 103732:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 3 previous similar messages [ 4357.886292] Lustre: server umount lustre-MDT0000 complete [ 4373.730460] Lustre: 3324:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788840744/real 1788840744] req@ffff95f350919c00 x1875731017122176/t0(0) o400->MGC192.168.202.101@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1788840760 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4373.745403] Lustre: 3324:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 29 previous similar messages [ 4384.031971] LustreError: 3322:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff95f3584dca80 x1875731017123840/t0(0) o250->MGC192.168.202.101@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 [ 4390.330777] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4398.584569] Lustre: *** cfs_fail_loc=216, val=0*** [ 4398.589907] LustreError: 106869:0:(osp_precreate.c:974:osp_precreate_cleanup_orphans()) lustre-OST0001-osc-MDT0000: cannot cleanup orphans: rc = -30 [ 4398.598588] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3030 to 0x240000400:3073) [ 4399.649504] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2998 to 0x280000400:3041) [ 4467.354617] Lustre: DEBUG MARKER: == replay-single test 50: Double OSC recovery, don't LASSERT (3812) ========================================================== 00:14:12 (1788840852) [ 4469.087828] Lustre: lustre-OST0000: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnecting [ 4469.092343] Lustre: Skipped 2 previous similar messages [ 4482.513877] Lustre: DEBUG MARKER: == replay-single test 52: time out lock replay (3764) ==== 00:14:27 (1788840867) [ 4485.971454] Lustre: Failing over lustre-MDT0000 [ 4486.212608] Lustre: server umount lustre-MDT0000 complete [ 4505.647987] Lustre: *** cfs_fail_loc=157, val=2147483648*** [ 4505.653031] LustreError: 108506:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff95f34890df80 x1875730996416128/t0(0) o101->655a43b7-ea09-4702-a8c2-c6bfe1a107ef@192.168.202.1@tcp:528/0 lens 328/344 e 0 to 0 dl 1788840903 ref 1 fl Complete:/240/0 rc 0/0 job:'ldlm_lock_repla.0' uid:0 gid:0 projid:4294967295 [ 4509.609816] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4522.017654] Lustre: lustre-MDT0000: Client 655a43b7-ea09-4702-a8c2-c6bfe1a107ef (at 192.168.202.1@tcp) reconnected, waiting for 1 clients in recovery for 1:24 [ 4522.251673] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3084 to 0x240000400:3105) [ 4522.283213] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3053 to 0x280000400:3073) [ 4529.968181] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4532.293776] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4543.997660] Lustre: DEBUG MARKER: == replay-single test 53a: |X| close request while two MDC requests in flight ========================================================== 00:15:28 (1788840928) [ 4546.502854] Lustre: *** cfs_fail_loc=115, val=2147483648*** [ 4551.535969] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4553.905324] Lustre: Failing over lustre-MDT0000 [ 4554.195776] Lustre: server umount lustre-MDT0000 complete [ 4582.879730] LustreError: 3322:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff95f36f122a00 x1875731017179520/t0(0) o250->MGC192.168.202.101@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 [ 4587.618063] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3053 to 0x280000400:3105) [ 4587.622707] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3107 to 0x240000400:3137) [ 4588.558533] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4598.811614] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4600.251472] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4609.660704] Lustre: DEBUG MARKER: == replay-single test 53b: |X| open request while two MDC requests in flight ========================================================== 00:16:34 (1788840994) [ 4610.872169] Lustre: *** cfs_fail_loc=107, val=2147483648*** [ 4616.353859] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4618.391831] Lustre: Failing over lustre-MDT0000 [ 4618.681401] Lustre: server umount lustre-MDT0000 complete [ 4642.309592] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4651.963066] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3139 to 0x240000400:3169) [ 4651.965272] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3053 to 0x280000400:3137) [ 4657.860891] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4659.343587] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4668.494539] Lustre: DEBUG MARKER: == replay-single test 53c: |X| open request and close request while two MDC requests in flight ========================================================== 00:17:33 (1788841053) [ 4669.779499] Lustre: *** cfs_fail_loc=107, val=2147483648*** [ 4674.229857] LustreError: 112997:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 4674.235481] LustreError: 112997:0:(osd_handler.c:720:osd_ro()) Skipped 3 previous similar messages [ 4675.016503] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4677.061433] Lustre: Failing over lustre-MDT0000 [ 4677.366497] Lustre: server umount lustre-MDT0000 complete [ 4694.815211] 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 [ 4694.825651] Lustre: Skipped 15 previous similar messages [ 4694.829252] LustreError: MGC192.168.202.101@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4694.840679] LustreError: Skipped 6 previous similar messages [ 4704.224890] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x8c53a26e3b67b58 [ 4704.238497] Lustre: MGC192.168.202.101@tcp: Connection restored to 0@lo (at 0@lo) [ 4704.255613] Lustre: Skipped 16 previous similar messages [ 4704.814575] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4704.825287] Lustre: Skipped 7 previous similar messages [ 4709.813965] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4711.548939] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3171 to 0x240000400:3201) [ 4711.551845] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3053 to 0x280000400:3169) [ 4722.736511] Lustre: DEBUG MARKER: == replay-single test 53d: close reply while two MDC requests in flight ========================================================== 00:18:27 (1788841107) [ 4724.722666] Lustre: *** cfs_fail_loc=13b, val=315*** [ 4724.728055] Lustre: *** cfs_fail_loc=13b, val=2147483648*** [ 4724.736758] LustreError: 113621:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff95f34796ad80 x1875730996464000/t257698037777(0) o35->655a43b7-ea09-4702-a8c2-c6bfe1a107ef@192.168.202.1@tcp:747/0 lens 392/456 e 0 to 0 dl 1788841122 ref 1 fl Interpret:/600/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 4728.106703] Lustre: Failing over lustre-MDT0000 [ 4728.641425] Lustre: server umount lustre-MDT0000 complete [ 4746.711447] LustreError: 114913: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. [ 4746.727151] LustreError: 114913:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 2 previous similar messages [ 4747.098611] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4747.101096] Lustre: Skipped 7 previous similar messages [ 4751.372545] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4751.393178] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4751.396503] Lustre: Skipped 7 previous similar messages [ 4751.543267] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4751.550655] Lustre: Skipped 7 previous similar messages [ 4751.578666] Lustre: 114914:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff95f241a41f80 x1875730996464000/t257698037777(0) o35->655a43b7-ea09-4702-a8c2-c6bfe1a107ef@192.168.202.1@tcp:19/0 lens 392/456 e 0 to 0 dl 1788841149 ref 1 fl Interpret:/602/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 4751.589675] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3203 to 0x240000400:3233) [ 4751.605563] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3053 to 0x280000400:3201) [ 4761.171981] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4762.879737] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4771.699790] Lustre: DEBUG MARKER: == replay-single test 53e: |X| open reply while two MDC requests in flight ========================================================== 00:19:16 (1788841156) [ 4773.072273] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 4773.080962] LustreError: 115371:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff95f376c27800 x1875730996478080/t261993005072(0) o36->655a43b7-ea09-4702-a8c2-c6bfe1a107ef@192.168.202.1@tcp:40/0 lens 504/448 e 0 to 0 dl 1788841170 ref 1 fl Interpret:/200/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 4778.540898] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4780.433706] Lustre: Failing over lustre-MDT0000 [ 4780.740767] Lustre: server umount lustre-MDT0000 complete [ 4808.677472] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x8c53a26e3b68759 [ 4814.082767] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3203 to 0x240000400:3265) [ 4814.083083] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3203 to 0x280000400:3233) [ 4814.112876] Lustre: 116614:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff95f242005880 x1875730996478080/t261993005072(0) o36->655a43b7-ea09-4702-a8c2-c6bfe1a107ef@192.168.202.1@tcp:81/0 lens 504/2880 e 0 to 0 dl 1788841211 ref 1 fl Interpret:/202/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 4814.126722] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4824.002506] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4825.606221] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4834.172793] Lustre: DEBUG MARKER: == replay-single test 53f: |X| open reply and close reply while two MDC requests in flight ========================================================== 00:20:18 (1788841218) [ 4835.389410] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 4835.394059] LustreError: 116614:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff95f35fc0aa00 x1875730996492672/t266287972368(0) o36->655a43b7-ea09-4702-a8c2-c6bfe1a107ef@192.168.202.1@tcp:103/0 lens 504/448 e 0 to 0 dl 1788841233 ref 1 fl Interpret:/200/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 4837.401920] Lustre: *** cfs_fail_loc=13b, val=315*** [ 4840.971363] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4842.813357] Lustre: Failing over lustre-MDT0000 [ 4843.012174] Lustre: server umount lustre-MDT0000 complete [ 4874.999785] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4876.471313] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3203 to 0x240000400:3297) [ 4876.476468] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3235 to 0x280000400:3265) [ 4876.484096] Lustre: 118312:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff95f34890ce00 x1875730996492928/t266287972369(0) o35->655a43b7-ea09-4702-a8c2-c6bfe1a107ef@192.168.202.1@tcp:144/0 lens 392/456 e 0 to 0 dl 1788841274 ref 1 fl Interpret:/602/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 4888.207062] Lustre: DEBUG MARKER: == replay-single test 53g: |X| drop open reply and close request while close and open are both in flight ========================================================== 00:21:13 (1788841273) [ 4889.753753] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 4889.766114] Lustre: Skipped 1 previous similar message [ 4889.771105] LustreError: 118310:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff95f37bf29c00 x1875730996505216/t270582939664(0) o36->655a43b7-ea09-4702-a8c2-c6bfe1a107ef@192.168.202.1@tcp:157/0 lens 504/448 e 0 to 0 dl 1788841287 ref 1 fl Interpret:/200/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 4889.801359] LustreError: 118310:0:(ldlm_lib.c:3373:target_send_reply_msg()) Skipped 1 previous similar message [ 4891.762733] Lustre: *** cfs_fail_loc=115, val=2147483648*** [ 4891.764588] Lustre: Skipped 1 previous similar message [ 4897.013440] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4899.157540] Lustre: Failing over lustre-MDT0000 [ 4899.573533] Lustre: server umount lustre-MDT0000 complete [ 4926.432827] LustreError: 3322:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff95f36f24d500 x1875731017277568/t0(0) o250->MGC192.168.202.101@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 [ 4926.470566] LustreError: 3322:0:(client.c:1404:ptlrpc_import_delay_req()) Skipped 1 previous similar message [ 4931.709375] Lustre: 119853:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff95f373bf4a80 x1875730996505216/t270582939664(0) o36->655a43b7-ea09-4702-a8c2-c6bfe1a107ef@192.168.202.1@tcp:199/0 lens 504/2880 e 0 to 0 dl 1788841329 ref 1 fl Interpret:/202/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 4931.716118] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3203 to 0x240000400:3329) [ 4931.730824] Lustre: 119853:0:(mdt_recovery.c:102:mdt_req_from_lrd()) Skipped 1 previous similar message [ 4931.752385] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3267 to 0x280000400:3297) [ 4932.156249] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4943.200683] Lustre: DEBUG MARKER: == replay-single test 53h: open request and close reply while two MDC requests in flight ========================================================== 00:22:08 (1788841328) [ 4944.522304] Lustre: *** cfs_fail_loc=107, val=2147483648*** [ 4946.322431] Lustre: *** cfs_fail_loc=13b, val=315*** [ 4946.330346] Lustre: *** cfs_fail_loc=13b, val=2147483648*** [ 4946.337328] LustreError: 119859:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff95f3671e1880 x1875730996517248/t274877906960(0) o35->655a43b7-ea09-4702-a8c2-c6bfe1a107ef@192.168.202.1@tcp:214/0 lens 392/456 e 0 to 0 dl 1788841344 ref 1 fl Interpret:/600/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 4951.014694] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4952.748531] Lustre: Failing over lustre-MDT0000 [ 4952.955906] Lustre: server umount lustre-MDT0000 complete [ 4976.768486] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4977.904272] Lustre: 3326:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788841348/real 1788841348] req@ffff95f372d5aa00 x1875731017291648/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788841364 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4977.956319] Lustre: 3326:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 63 previous similar messages [ 4985.067516] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3267 to 0x280000400:3329) [ 4985.069182] Lustre: 121299:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff95f37bf6ca80 x1875730996517248/t274877906960(0) o35->655a43b7-ea09-4702-a8c2-c6bfe1a107ef@192.168.202.1@tcp:252/0 lens 392/456 e 0 to 0 dl 1788841382 ref 1 fl Interpret:/602/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 4985.075452] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3331 to 0x240000400:3361) [ 4994.884544] Lustre: DEBUG MARKER: == replay-single test 55: let MDS_CHECK_RESENT return the original return code instead of 0 ========================================================== 00:22:59 (1788841379) [ 4995.810249] Lustre: *** cfs_fail_loc=12b, val=2147483991*** [ 4995.819471] LustreError: 121296:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff95f345f77b80 x1875730996527616/t279172874255(0) o101->655a43b7-ea09-4702-a8c2-c6bfe1a107ef@192.168.202.1@tcp:263/0 lens 664/608 e 0 to 0 dl 1788841393 ref 1 fl Interpret:/600/0 rc 301/0 job:'touch.0' uid:0 gid:0 projid:0 [ 5012.012076] Lustre: lustre-MDT0000: Client 655a43b7-ea09-4702-a8c2-c6bfe1a107ef (at 192.168.202.1@tcp) reconnecting [ 5012.034406] Lustre: Skipped 1 previous similar message [ 5012.076587] Lustre: 121296:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff95f36f24c700 x1875730996527616/t279172874255(0) o101->655a43b7-ea09-4702-a8c2-c6bfe1a107ef@192.168.202.1@tcp:279/0 lens 664/3488 e 0 to 0 dl 1788841409 ref 1 fl Interpret:/602/0 rc 0/0 job:'touch.0' uid:0 gid:0 projid:0 [ 5020.740524] Lustre: DEBUG MARKER: == replay-single test 56: don't replay a symlink open request (3440) ========================================================== 00:23:25 (1788841405) [ 5026.099648] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5028.458952] Lustre: Failing over lustre-MDT0000 [ 5028.707938] Lustre: server umount lustre-MDT0000 complete [ 5052.504864] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5056.164671] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3267 to 0x280000400:3361) [ 5056.170025] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3363 to 0x240000400:3393) [ 5064.019895] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5066.180788] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5086.611360] Lustre: DEBUG MARKER: == replay-single test 57: test recovery from llog for setattr op ========================================================== 00:24:31 (1788841471) [ 5092.059346] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5094.125683] Lustre: Failing over lustre-MDT0000 [ 5094.567175] Lustre: server umount lustre-MDT0000 complete [ 5118.054117] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5122.748810] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3363 to 0x240000400:3425) [ 5122.752396] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3363 to 0x280000400:3393) [ 5131.037299] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5133.184770] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5141.127633] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 5155.420237] Lustre: DEBUG MARKER: == replay-single test 58a: test recovery from llog for setattr op (test llog_gen_rec) ========================================================== 00:25:39 (1788841539) [ 5204.167067] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5206.611065] Lustre: Failing over lustre-MDT0000 [ 5207.447494] Lustre: server umount lustre-MDT0000 complete [ 5226.022380] Lustre: lustre-MDT0000: Not available for connect from 192.168.202.1@tcp (not set up) [ 5227.732129] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:4676 to 0x240000400:4705) [ 5227.733310] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:4644 to 0x280000400:4673) [ 5230.880738] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5243.121206] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5244.696438] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5311.837168] Lustre: DEBUG MARKER: == replay-single test 58b: test replay of setxattr op ==== 00:28:16 (1788841696) [ 5319.327939] LustreError: 128104:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 5319.331461] LustreError: 128104:0:(osd_handler.c:720:osd_ro()) Skipped 7 previous similar messages [ 5321.238667] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5324.138772] Lustre: Failing over lustre-MDT0000 [ 5324.459903] Lustre: server umount lustre-MDT0000 complete [ 5344.223138] LustreError: MGC192.168.202.101@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5344.224277] 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 [ 5344.237570] LustreError: Skipped 8 previous similar messages [ 5344.278026] Lustre: Skipped 17 previous similar messages [ 5354.999920] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 5355.002187] Lustre: Skipped 8 previous similar messages [ 5355.061372] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 5355.074382] Lustre: Skipped 7 previous similar messages [ 5359.980195] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5368.930481] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 5368.933773] Lustre: Skipped 7 previous similar messages [ 5369.314393] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 5369.317445] Lustre: Skipped 19 previous similar messages [ 5373.249759] Lustre: lustre-MDT0000: Recovery over after 0:05, of 2 clients 2 recovered and 0 were evicted. [ 5373.265072] Lustre: Skipped 7 previous similar messages [ 5373.309231] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:4644 to 0x280000400:4705) [ 5373.310251] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:4707 to 0x240000400:4737) [ 5379.152448] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5380.929921] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5392.648281] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount FULL mgc.*.mgs_server_uuid 1475 0 [ 5394.837454] Lustre: DEBUG MARKER: mgc.*.mgs_server_uuid in FULL state after 0 sec [ 5402.391297] Lustre: DEBUG MARKER: == replay-single test 58c: resend/reconstruct setxattr op ========================================================== 00:29:47 (1788841787) [ 5409.357330] Lustre: *** cfs_fail_loc=123, val=2147483648*** [ 5427.501903] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 5427.509150] Lustre: Skipped 1 previous similar message [ 5427.511974] LustreError: 129934:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff95f24b4ff050 x1875730999312256/t296352743435(0) o36->655a43b7-ea09-4702-a8c2-c6bfe1a107ef@192.168.202.1@tcp:695/0 lens 66040/440 e 0 to 0 dl 1788841825 ref 1 fl Interpret:/600/0 rc 0/0 job:'setfattr.0' uid:0 gid:0 projid:0 [ 5442.665346] Lustre: 129399:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff95f372c85180 x1875730999312256/t296352743435(0) o36->655a43b7-ea09-4702-a8c2-c6bfe1a107ef@192.168.202.1@tcp:710/0 lens 66040/440 e 0 to 0 dl 1788841840 ref 1 fl Interpret:/602/0 rc 0/0 job:'setfattr.0' uid:0 gid:0 projid:0 [ 5454.472968] Lustre: DEBUG MARKER: SKIP: replay-single test_59 skipping ALWAYS excluded test 59 [ 5456.236700] Lustre: DEBUG MARKER: == replay-single test 60: test llog post recovery init vs llog unlink ========================================================== 00:30:41 (1788841841) [ 5467.182991] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5470.306159] Lustre: Failing over lustre-MDT0000 [ 5470.712274] Lustre: server umount lustre-MDT0000 complete [ 5500.664534] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:4806 to 0x280000400:4833) [ 5500.665317] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:4839 to 0x240000400:4865) [ 5503.807966] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5514.989836] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5517.064343] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5528.854795] Lustre: DEBUG MARKER: == replay-single test 61a: test race llog recovery vs llog cleanup ========================================================== 00:31:53 (1788841913) [ 5551.204316] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 5564.698842] Lustre: Failing over lustre-OST0000 [ 5564.817121] Lustre: server umount lustre-OST0000 complete [ 5565.480854] LustreError: 6698:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.202.1@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 5565.496895] LustreError: 6698:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 1 previous similar message [ 5570.620823] LustreError: 36606:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.202.1@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 5570.630511] LustreError: 36606:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 1 previous similar message [ 5580.848436] LustreError: 36604:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.202.1@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 5580.876425] LustreError: 36604:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 3 previous similar messages [ 5590.379614] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5605.384714] Lustre: Failing over lustre-OST0000 [ 5605.476750] Lustre: server umount lustre-OST0000 complete [ 5607.904596] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 5607.914394] LustreError: 36604: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. [ 5607.930878] LustreError: 36604:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 1 previous similar message [ 5633.524262] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5644.352715] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 5646.001135] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 5687.707040] Lustre: DEBUG MARKER: == replay-single test 61b: test race mds llog sync vs llog cleanup ========================================================== 00:34:32 (1788842072) [ 5691.423463] Lustre: Failing over lustre-MDT0000 [ 5691.859874] Lustre: server umount lustre-MDT0000 complete [ 5710.817719] Lustre: 3324:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788842081/real 1788842081] req@ffff95f34787fb80 x1875731018256512/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788842097 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5710.849282] Lustre: 3324:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 39 previous similar messages [ 5721.057038] LustreError: 3322:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff95f37d0baa00 x1875731018258560/t0(0) o250->MGC192.168.202.101@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 [ 5726.516841] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5734.517187] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5234 to 0x280000400:5249) [ 5734.522595] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5266 to 0x240000400:5281) [ 5741.702937] Lustre: Failing over lustre-MDT0000 [ 5742.019147] Lustre: server umount lustre-MDT0000 complete [ 5761.507740] LustreError: 136799: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. [ 5761.526401] LustreError: 136799:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 5 previous similar messages [ 5768.156465] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5771.445439] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5266 to 0x240000400:5313) [ 5771.447586] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5234 to 0x280000400:5281) [ 5779.813279] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5781.565313] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5792.607917] Lustre: DEBUG MARKER: == replay-single test 61c: test race mds llog sync vs llog cleanup ========================================================== 00:36:17 (1788842177) [ 5807.730783] Lustre: Failing over lustre-OST0000 [ 5807.827949] Lustre: server umount lustre-OST0000 complete [ 5833.546724] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5844.043100] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 5845.987099] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 5855.432672] Lustre: DEBUG MARKER: == replay-single test 61d: error in llog_setup should cleanup the llog context correctly ========================================================== 00:37:20 (1788842240) [ 5857.999978] Lustre: Failing over lustre-MDT0000 [ 5858.357620] LustreError: 136817:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.202.1@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 5858.387469] LustreError: 136817:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 7 previous similar messages [ 5858.505417] Lustre: server umount lustre-MDT0000 complete [ 5871.996820] Lustre: *** cfs_fail_loc=605, val=0*** [ 5871.999856] LustreError: 139814:0:(llog_obd.c:192:llog_setup()) MGS: ctxt 0 lop_setup=ffffffffc1281fe0 failed: rc = -95 [ 5872.008673] LustreError: 139814:0:(obd_config.c:845:class_setup()) setup MGS failed (-95) [ 5872.014613] LustreError: 139814:0:(obd_mount.c:259:lustre_start_simple()) MGS setup error -95 [ 5872.017799] LustreError: 139814:0:(tgt_mount.c:116:server_deregister_mount()) MGS not registered [ 5872.040490] LustreError: Failed to start MGS 'MGS' (-95). Is the 'mgs' module loaded? [ 5872.048592] LustreError: 139814:0:(tgt_mount.c:2132:server_put_super()) no obd lustre-MDT0000 [ 5872.219836] Lustre: server umount lustre-MDT0000 complete [ 5872.222493] LustreError: 139814:0:(super25.c:179:lustre_fill_super()) llite: Unable to mount : rc = -95 [ 5895.361666] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5898.399966] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5315 to 0x240000400:5345) [ 5898.401318] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5283 to 0x280000400:5313) [ 5905.759565] Lustre: DEBUG MARKER: == replay-single test 62: don't mis-drop resent replay === 00:38:10 (1788842290) [ 5910.091765] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5913.812615] Lustre: Failing over lustre-MDT0000 [ 5914.096060] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 5914.106539] Lustre: Skipped 1 previous similar message [ 5914.212939] Lustre: server umount lustre-MDT0000 complete [ 5934.195478] Lustre: *** cfs_fail_loc=707, val=0*** [ 5939.705862] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5950.549509] Lustre: lustre-MDT0000: Client 655a43b7-ea09-4702-a8c2-c6bfe1a107ef (at 192.168.202.1@tcp) reconnected, waiting for 1 clients in recovery for 0:53 [ 5951.335978] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5358 to 0x240000400:5377) [ 5951.337252] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5327 to 0x280000400:5345) [ 5957.476163] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5959.548797] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5972.488691] Lustre: DEBUG MARKER: == replay-single test 65a: AT: verify early replies ====== 00:39:16 (1788842356) [ 6006.507279] LustreError: 141518:0:(service.c:2558:ptlrpc_server_handle_request()) @@@ HIT req@ffff95f3458e6a00 x1875731000190848/t0(0) o101->655a43b7-ea09-4702-a8c2-c6bfe1a107ef@192.168.202.1@tcp:519/0 lens 664/0 e 0 to 0 dl 1788842404 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 6006.526032] LustreError: 141518:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a sleeping for 11000ms [ 6017.551128] LustreError: 141518:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a awake [ 6017.579110] LustreError: 141521:0:(service.c:2558:ptlrpc_server_handle_request()) @@@ HIT req@ffff95f372d5b800 x1875731000191872/t0(0) o35->655a43b7-ea09-4702-a8c2-c6bfe1a107ef@192.168.202.1@tcp:536/0 lens 392/0 e 0 to 0 dl 1788842421 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 6019.942373] LustreError: 141519:0:(service.c:2558:ptlrpc_server_handle_request()) @@@ HIT req@ffff95f3777ae680 x1875731000197760/t0(0) o101->655a43b7-ea09-4702-a8c2-c6bfe1a107ef@192.168.202.1@tcp:571/0 lens 576/0 e 0 to 0 dl 1788842456 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'unlinkmany.0' uid:0 gid:0 projid:0 [ 6019.965799] LustreError: 141519:0:(service.c:2558:ptlrpc_server_handle_request()) Skipped 27 previous similar messages [ 6023.251720] LustreError: 8524:0:(service.c:2558:ptlrpc_server_handle_request()) @@@ HIT req@ffff95f373990000 x1875731018344448/t0(0) o6->lustre-MDT0000-mdtlov_UUID@0@lo:536/0 lens 544/0 e 0 to 0 dl 1788842421 ref 1 fl Interpret:/200/ffffffff rc 0/-1 job:'osp-syn-1-0.0' uid:0 gid:0 projid:4294967295 [ 6023.278739] LustreError: 8524:0:(service.c:2558:ptlrpc_server_handle_request()) Skipped 20 previous similar messages [ 6028.281634] LustreError: 127680:0:(service.c:2558:ptlrpc_server_handle_request()) @@@ HIT req@ffff95f347438000 x1875731018345728/t0(0) o6->lustre-MDT0000-mdtlov_UUID@0@lo:541/0 lens 544/0 e 0 to 0 dl 1788842426 ref 1 fl Interpret:/200/ffffffff rc 0/-1 job:'osp-syn-1-0.0' uid:0 gid:0 projid:4294967295 [ 6028.317868] LustreError: 127680:0:(service.c:2558:ptlrpc_server_handle_request()) Skipped 7 previous similar messages [ 6037.674659] Lustre: DEBUG MARKER: == replay-single test 65b: AT: verify early replies on packed reply / bulk ========================================================== 00:40:22 (1788842422) [ 6068.388814] LustreError: 6703:0:(tgt_handler.c:2830:tgt_brw_write()) cfs_fail_timeout id 224 sleeping for 11000ms [ 6079.440735] LustreError: 6703:0:(tgt_handler.c:2830:tgt_brw_write()) cfs_fail_timeout id 224 awake [ 6088.242785] Lustre: DEBUG MARKER: == replay-single test 66a: AT: verify MDT service time adjusts with no early replies ========================================================== 00:41:13 (1788842473) [ 6116.919835] LustreError: 142955:0:(service.c:2558:ptlrpc_server_handle_request()) @@@ HIT req@ffff95f377f26d80 x1875731000214528/t0(0) o101->655a43b7-ea09-4702-a8c2-c6bfe1a107ef@192.168.202.1@tcp:629/0 lens 576/0 e 0 to 0 dl 1788842514 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 6116.937948] LustreError: 142955:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a sleeping for 5000ms [ 6121.943129] LustreError: 142955:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a awake [ 6134.455671] LustreError: 141828:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a awake [ 6134.465360] LustreError: 141517:0:(service.c:2558:ptlrpc_server_handle_request()) @@@ HIT req@ffff95f36de78a80 x1875731000236800/t0(0) o101->655a43b7-ea09-4702-a8c2-c6bfe1a107ef@192.168.202.1@tcp:686/0 lens 664/0 e 0 to 0 dl 1788842571 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 6134.483919] LustreError: 141517:0:(service.c:2558:ptlrpc_server_handle_request()) Skipped 120 previous similar messages [ 6154.396919] Lustre: DEBUG MARKER: == replay-single test 66b: AT: verify net latency adjusts ========================================================== 00:42:19 (1788842539) [ 6258.923908] Lustre: DEBUG MARKER: == replay-single test 67a: AT: verify slow request processing doesn't induce reconnects ========================================================== 00:44:04 (1788842644) [ 6288.365571] LustreError: 141518:0:(service.c:2558:ptlrpc_server_handle_request()) @@@ HIT req@ffff95f242007800 x1875731000291712/t0(0) o101->655a43b7-ea09-4702-a8c2-c6bfe1a107ef@192.168.202.1@tcp:46/0 lens 576/0 e 0 to 0 dl 1788842686 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 6288.403643] LustreError: 141518:0:(service.c:2558:ptlrpc_server_handle_request()) Skipped 98 previous similar messages [ 6288.411625] LustreError: 141518:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a sleeping for 400ms [ 6288.428049] LustreError: 141518:0:(service.c:2559:ptlrpc_server_handle_request()) Skipped 1 previous similar message [ 6288.863255] LustreError: 141518:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a awake [ 6304.415348] LustreError: 142955:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a sleeping for 400ms [ 6304.425992] LustreError: 142955:0:(service.c:2559:ptlrpc_server_handle_request()) Skipped 36 previous similar messages [ 6305.311474] LustreError: 141522:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a awake [ 6305.316717] LustreError: 141522:0:(service.c:2559:ptlrpc_server_handle_request()) Skipped 37 previous similar messages [ 6333.199159] LustreError: 14707:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout interrupted [ 6333.213537] LustreError: 14707:0:(service.c:2559:ptlrpc_server_handle_request()) Skipped 3 previous similar messages [ 6339.686788] Lustre: DEBUG MARKER: == replay-single test 67b: AT: verify instant slowdown doesn't induce reconnects ========================================================== 00:45:24 (1788842724) [ 6375.615164] Lustre: DEBUG MARKER: phase 2 [ 6386.390890] Lustre: DEBUG MARKER: == replay-single test 68: AT: verify slowing locks ======= 00:46:11 (1788842771) [ 6472.506042] Lustre: DEBUG MARKER: == replay-single test 70a: check multi client t-f ======== 00:47:37 (1788842857) [ 6474.273605] Lustre: DEBUG MARKER: SKIP: replay-single test_70a Need two or more clients, have 1 [ 6476.467822] Lustre: DEBUG MARKER: == replay-single test 70b: dbench 1mdts recovery; 1 clients ========================================================== 00:47:41 (1788842861) [ 6483.052762] Lustre: DEBUG MARKER: Started rundbench load pid=128810 ... [ 6489.157434] LustreError: 148347:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 6489.172876] LustreError: 148347:0:(osd_handler.c:720:osd_ro()) Skipped 3 previous similar messages [ 6490.704039] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 6493.683961] Lustre: DEBUG MARKER: test_70b fail mds1 1 times [ 6495.778130] Lustre: Failing over lustre-MDT0000 [ 6495.824898] Lustre: lustre-MDT0000: Not available for connect from 192.168.202.1@tcp (stopping) [ 6496.074796] Lustre: server umount lustre-MDT0000 complete [ 6514.145512] LustreError: MGC192.168.202.101@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 6514.157500] LustreError: Skipped 5 previous similar messages [ 6514.455251] 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 [ 6514.464181] Lustre: Skipped 14 previous similar messages [ 6514.579812] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 6514.582238] Lustre: Skipped 8 previous similar messages [ 6514.632861] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 6514.636855] Lustre: Skipped 8 previous similar messages [ 6514.726641] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 6514.739952] Lustre: Skipped 8 previous similar messages [ 6515.488108] Lustre: 3325:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788842885/real 1788842885] req@ffff95f37bf6e300 x1875731018483712/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788842901 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6515.514503] Lustre: 3325:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 26 previous similar messages [ 6515.579383] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 6515.589150] Lustre: Skipped 8 previous similar messages [ 6515.649905] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5480 to 0x240000400:5505) [ 6515.650172] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5427 to 0x280000400:5473) [ 6519.421644] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6519.806954] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 6519.816655] Lustre: Skipped 14 previous similar messages [ 6530.863600] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6532.938666] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6541.307867] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 6543.975620] Lustre: DEBUG MARKER: test_70b fail mds1 2 times [ 6546.164357] Lustre: Failing over lustre-MDT0000 [ 6546.545211] Lustre: server umount lustre-MDT0000 complete [ 6567.301844] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5549 to 0x240000400:5569) [ 6567.307142] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5517 to 0x280000400:5537) [ 6570.123974] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6579.527751] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6581.377473] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6589.312949] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 6592.349901] Lustre: DEBUG MARKER: test_70b fail mds1 3 times [ 6594.601657] Lustre: Failing over lustre-MDT0000 [ 6594.861160] Lustre: server umount lustre-MDT0000 complete [ 6622.368721] LustreError: 3322:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff95f344b1aa00 x1875731018688128/t0(0) o250->MGC192.168.202.101@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 [ 6629.231651] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6633.236248] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5571 to 0x280000400:5601) [ 6633.236693] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5602 to 0x240000400:5633) [ 6640.917742] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6642.787468] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6653.291764] Lustre: DEBUG MARKER: == replay-single test 70c: tar 1mdts recovery ============ 00:50:37 (1788843037) [ 6780.260415] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 6795.503756] Lustre: DEBUG MARKER: test_70c fail mds1 1 times [ 6798.399240] Lustre: Failing over lustre-MDT0000 [ 6799.057334] Lustre: server umount lustre-MDT0000 complete [ 6834.151771] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6843.217847] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6188 to 0x280000400:6209) [ 6843.219173] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6221 to 0x240000400:6241) [ 6851.245051] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6853.782300] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6898.521857] Lustre: DEBUG MARKER: == replay-single test 70d: mkdir/rmdir striped dir 1mdts recovery ========================================================== 00:54:43 (1788843283) [ 6900.549907] Lustre: DEBUG MARKER: SKIP: replay-single test_70d needs >= 2 MDTs [ 6902.466087] Lustre: DEBUG MARKER: == replay-single test 70e: rename cross-MDT with random fails ========================================================== 00:54:47 (1788843287) [ 6904.094891] Lustre: DEBUG MARKER: SKIP: replay-single test_70e needs >= 2 MDTs [ 6906.652980] Lustre: DEBUG MARKER: == replay-single test 70f: OSS O_DIRECT recovery with 1 clients ========================================================== 00:54:51 (1788843291) [ 6915.570081] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 6918.336846] Lustre: DEBUG MARKER: test_70f failing OST 1 times [ 6920.975306] Lustre: Failing over lustre-OST0000 [ 6921.038783] Lustre: server umount lustre-OST0000 complete [ 6923.831753] LustreError: 14579:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.202.1@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 6925.280027] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 6940.658078] LustreError: 36607: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. [ 6940.680905] LustreError: 36607:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 6 previous similar messages [ 6949.643828] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6962.384022] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 6964.083858] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 6979.628727] Lustre: DEBUG MARKER: == replay-single test 71a: mkdir/rmdir striped dir with 2 mdts recovery ========================================================== 00:56:04 (1788843364) [ 6981.442865] Lustre: DEBUG MARKER: SKIP: replay-single test_71a needs >= 2 MDTs [ 6983.845835] Lustre: DEBUG MARKER: == replay-single test 73a: open(O_CREAT), unlink, replay, reconnect before open replay, close ========================================================== 00:56:08 (1788843368) [ 6989.254368] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 6992.778210] Lustre: Failing over lustre-MDT0000 [ 6992.870320] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 6992.888517] Lustre: Skipped 1 previous similar message [ 6993.024195] Lustre: server umount lustre-MDT0000 complete [ 7023.521854] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x8c53a26e3c25ee5 [ 7031.166945] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7036.458513] Lustre: *** cfs_fail_loc=302, val=2147483648*** [ 7051.842747] Lustre: lustre-MDT0000: Client 655a43b7-ea09-4702-a8c2-c6bfe1a107ef (at 192.168.202.1@tcp) reconnected, waiting for 1 clients in recovery for 0:54 [ 7052.081950] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6240 to 0x280000400:6273) [ 7052.082829] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6273 to 0x240000400:6305) [ 7060.449952] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 7062.365390] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7075.271603] Lustre: DEBUG MARKER: == replay-single test 73b: open(O_CREAT), unlink, replay, reconnect at open_replay reply, close ========================================================== 00:57:39 (1788843459) [ 7079.392174] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 7082.679380] Lustre: Failing over lustre-MDT0000 [ 7082.940266] Lustre: server umount lustre-MDT0000 complete [ 7114.345588] Lustre: *** cfs_fail_loc=157, val=2147483648*** [ 7114.357218] LustreError: 159041:0:(ldlm_lib.c:3373:target_send_reply_msg()) @@@ dropping reply req@ffff95f37bfc4000 x1875731006376704/t339302416387(339302416387) o101->655a43b7-ea09-4702-a8c2-c6bfe1a107ef@192.168.202.1@tcp:117/0 lens 592/608 e 0 to 0 dl 1788843512 ref 1 fl Interpret:/604/0 rc 301/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 7115.756496] Lustre: 3326:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788843486/real 1788843486] req@ffff95f37bfc5f80 x1875731019288832/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788843502 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 7115.811802] Lustre: 3326:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 40 previous similar messages [ 7116.624740] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7125.030890] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 7125.040379] Lustre: Skipped 11 previous similar messages [ 7129.664976] Lustre: lustre-MDT0000: Client 655a43b7-ea09-4702-a8c2-c6bfe1a107ef (at 192.168.202.1@tcp) reconnected, waiting for 1 clients in recovery for 0:54 [ 7129.691104] Lustre: 159042:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff95f37c163100 x1875731006376704/t339302416387(339302416387) o101->655a43b7-ea09-4702-a8c2-c6bfe1a107ef@192.168.202.1@tcp:132/0 lens 592/3488 e 0 to 0 dl 1788843527 ref 1 fl Interpret:/606/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 7129.874517] Lustre: lustre-MDT0000: Recovery over after 0:15, of 1 clients 1 recovered and 0 were evicted. [ 7129.883919] Lustre: Skipped 5 previous similar messages [ 7129.982600] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6273 to 0x240000400:6337) [ 7129.986742] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6275 to 0x280000400:6305) [ 7138.779172] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 7140.763452] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7150.943265] Lustre: DEBUG MARKER: == replay-single test 74: Ensure applications don't fail waiting for OST recovery ========================================================== 00:58:55 (1788843535) [ 7155.406571] Lustre: Failing over lustre-OST0000 [ 7155.577423] Lustre: server umount lustre-OST0000 complete [ 7155.693527] Lustre: lustre-OST0000-osc-MDT0000: Connection to lustre-OST0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 7155.730075] Lustre: Skipped 12 previous similar messages [ 7155.740738] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 7155.741467] LustreError: 127680: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. [ 7160.462120] Lustre: Failing over lustre-MDT0000 [ 7160.814200] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 7160.956426] Lustre: server umount lustre-MDT0000 complete [ 7181.264752] LustreError: MGC192.168.202.101@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 7181.269628] LustreError: Skipped 5 previous similar messages [ 7181.846921] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 7181.852970] Lustre: Skipped 6 previous similar messages [ 7182.034470] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6275 to 0x280000400:6337) [ 7187.216761] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7196.274900] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 7196.279844] Lustre: Skipped 6 previous similar messages [ 7197.836711] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 7197.847185] Lustre: Skipped 6 previous similar messages [ 7197.851109] Lustre: lustre-OST0000: Denying connection for new client f86934ba-84cf-452c-afd4-37e92760316b (at 192.168.202.1@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:59 [ 7200.484259] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6273 to 0x240000400:6369) [ 7204.471739] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7216.241507] Lustre: DEBUG MARKER: == replay-single test 80a: DNE: create remote dir, drop update rep from MDT0, fail MDT0 ========================================================== 01:00:01 (1788843601) [ 7218.210070] Lustre: DEBUG MARKER: SKIP: replay-single test_80a needs >= 2 MDTs [ 7220.188602] Lustre: DEBUG MARKER: == replay-single test 80b: DNE: create remote dir, drop update rep from MDT0, fail MDT1 ========================================================== 01:00:04 (1788843604) [ 7222.282120] Lustre: DEBUG MARKER: SKIP: replay-single test_80b needs >= 2 MDTs [ 7224.444686] Lustre: DEBUG MARKER: == replay-single test 80c: DNE: create remote dir, drop update rep from MDT1, fail MDT[0,1] ========================================================== 01:00:09 (1788843609) [ 7226.420332] Lustre: DEBUG MARKER: SKIP: replay-single test_80c needs >= 2 MDTs [ 7229.051322] Lustre: DEBUG MARKER: == replay-single test 80d: DNE: create remote dir, drop update rep from MDT1, fail 2 MDTs ========================================================== 01:00:13 (1788843613) [ 7231.306615] Lustre: DEBUG MARKER: SKIP: replay-single test_80d needs >= 2 MDTs [ 7233.609406] Lustre: DEBUG MARKER: == replay-single test 80e: DNE: create remote dir, drop MDT1 rep, fail MDT0 ========================================================== 01:00:18 (1788843618) [ 7235.569650] Lustre: DEBUG MARKER: SKIP: replay-single test_80e needs >= 2 MDTs [ 7238.074924] Lustre: DEBUG MARKER: == replay-single test 80f: DNE: create remote dir, drop MDT1 rep, fail MDT1 ========================================================== 01:00:22 (1788843622) [ 7239.682684] Lustre: DEBUG MARKER: SKIP: replay-single test_80f needs >= 2 MDTs [ 7241.956435] Lustre: DEBUG MARKER: == replay-single test 80g: DNE: create remote dir, drop MDT1 rep, fail MDT0, then MDT1 ========================================================== 01:00:26 (1788843626) [ 7244.060987] Lustre: DEBUG MARKER: SKIP: replay-single test_80g needs >= 2 MDTs [ 7245.843606] Lustre: DEBUG MARKER: == replay-single test 80h: DNE: create remote dir, drop MDT1 rep, fail 2 MDTs ========================================================== 01:00:30 (1788843630) [ 7247.713707] Lustre: DEBUG MARKER: SKIP: replay-single test_80h needs >= 2 MDTs [ 7249.979648] Lustre: DEBUG MARKER: == replay-single test 81a: DNE: unlink remote dir, drop MDT0 update rep, fail MDT1 ========================================================== 01:00:34 (1788843634) [ 7251.720406] Lustre: DEBUG MARKER: SKIP: replay-single test_81a needs >= 2 MDTs [ 7253.921197] Lustre: DEBUG MARKER: == replay-single test 81b: DNE: unlink remote dir, drop MDT0 update reply, fail MDT0 ========================================================== 01:00:38 (1788843638) [ 7256.031176] Lustre: DEBUG MARKER: SKIP: replay-single test_81b needs >= 2 MDTs [ 7258.229504] Lustre: DEBUG MARKER: == replay-single test 81c: DNE: unlink remote dir, drop MDT0 update reply, fail MDT0,MDT1 ========================================================== 01:00:42 (1788843642) [ 7260.061475] Lustre: DEBUG MARKER: SKIP: replay-single test_81c needs >= 2 MDTs [ 7262.358849] Lustre: DEBUG MARKER: == replay-single test 81d: DNE: unlink remote dir, drop MDT0 update reply, fail 2 MDTs ========================================================== 01:00:46 (1788843646) [ 7263.997386] Lustre: DEBUG MARKER: SKIP: replay-single test_81d needs >= 2 MDTs [ 7265.774308] Lustre: DEBUG MARKER: == replay-single test 81e: DNE: unlink remote dir, drop MDT1 req reply, fail MDT0 ========================================================== 01:00:50 (1788843650) [ 7267.341950] Lustre: DEBUG MARKER: SKIP: replay-single test_81e needs >= 2 MDTs [ 7269.507903] Lustre: DEBUG MARKER: == replay-single test 81f: DNE: unlink remote dir, drop MDT1 req reply, fail MDT1 ========================================================== 01:00:54 (1788843654) [ 7271.162367] Lustre: DEBUG MARKER: SKIP: replay-single test_81f needs >= 2 MDTs [ 7273.108563] Lustre: DEBUG MARKER: == replay-single test 81g: DNE: unlink remote dir, drop req reply, fail M0, then M1 ========================================================== 01:00:57 (1788843657) [ 7275.218819] Lustre: DEBUG MARKER: SKIP: replay-single test_81g needs >= 2 MDTs [ 7277.632646] Lustre: DEBUG MARKER: == replay-single test 81h: DNE: unlink remote dir, drop request reply, fail 2 MDTs ========================================================== 01:01:01 (1788843661) [ 7279.632700] Lustre: DEBUG MARKER: SKIP: replay-single test_81h needs >= 2 MDTs [ 7282.113747] Lustre: DEBUG MARKER: == replay-single test 84a: stale open during export disconnect ========================================================== 01:01:06 (1788843666) [ 7284.607946] Lustre: 163700:0:(genops.c:1774:obd_export_evict_by_uuid()) lustre-MDT0000: evicting f86934ba-84cf-452c-afd4-37e92760316b at adminstrative request [ 7297.949534] Lustre: DEBUG MARKER: == replay-single test 85a: check the cancellation of unused locks during recovery(IBITS) ========================================================== 01:01:22 (1788843682) [ 7306.920191] Lustre: Failing over lustre-MDT0000 [ 7307.312548] Lustre: server umount lustre-MDT0000 complete [ 7333.366729] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0x8c53a26e3c28dca [ 7336.879290] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6421 to 0x240000400:6465) [ 7336.879743] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6389 to 0x280000400:6433) [ 7340.068746] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7350.614214] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 7352.371822] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7362.033559] Lustre: DEBUG MARKER: == replay-single test 85b: check the cancellation of unused locks during recovery(EXTENT) ========================================================== 01:02:26 (1788843746) [ 7380.935683] Lustre: Failing over lustre-OST0000 [ 7381.034035] LustreError: 127680:0:(ldlm_lib.c:1190:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.202.1@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 7381.046237] Lustre: server umount lustre-OST0000 complete [ 7381.049479] LustreError: 127680:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 5 previous similar messages [ 7408.946576] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7419.784540] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 7421.708776] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 7432.587309] Lustre: DEBUG MARKER: == replay-single test 86: umount server after clear nid_stats should not hit LBUG ========================================================== 01:03:37 (1788843817) [ 7439.011573] Lustre: Failing over lustre-MDT0000 [ 7439.502068] Lustre: server umount lustre-MDT0000 complete [ 7448.159091] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6389 to 0x280000400:6465) [ 7448.162318] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6566 to 0x240000400:6593) [ 7452.816256] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7463.912410] Lustre: DEBUG MARKER: == replay-single test 87a: write replay ================== 01:04:08 (1788843848) [ 7468.755915] LustreError: 168158:0:(osd_handler.c:720:osd_ro()) lustre-OST0000: *** setting device osd-zfs read-only *** [ 7468.763719] LustreError: 168158:0:(osd_handler.c:720:osd_ro()) Skipped 6 previous similar messages [ 7469.701284] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 7472.742666] Lustre: Failing over lustre-OST0000 [ 7472.815504] Lustre: server umount lustre-OST0000 complete [ 7500.042345] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7511.978811] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 7513.816833] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 7524.018466] Lustre: DEBUG MARKER: == replay-single test 87b: write replay with changed data (checksum resend) ========================================================== 01:05:08 (1788843908) [ 7529.513700] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 7533.774490] Lustre: Failing over lustre-OST0000 [ 7533.830079] Lustre: server umount lustre-OST0000 complete [ 7535.072138] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 7535.086402] LustreError: 14703: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. [ 7535.132874] LustreError: 14703:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 17 previous similar messages [ 7553.858336] LustreError: lustre-OST0000: BAD WRITE CHECKSUM: from 12345-192.168.202.1@tcp inode [0x200028c71:0x5:0x0] object 0x240000400:6595 extent [0-1048575]: client csum 430ab025, server csum edd660df [ 7560.834865] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7572.976524] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 7575.304565] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 7584.952374] Lustre: DEBUG MARKER: == replay-single test 88: MDS should not assign same objid to different files ========================================================== 01:06:09 (1788843969) [ 7589.490191] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 7593.816916] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 7600.575772] Lustre: Failing over lustre-MDT0000 [ 7600.802892] Lustre: server umount lustre-MDT0000 complete [ 7605.268467] LustreError: 11314:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788843992 with bad export cookie 631975261419783374 [ 7615.458116] Lustre: Failing over lustre-OST0000 [ 7615.636836] Lustre: server umount lustre-OST0000 complete [ 7650.209466] LustreError: 3322:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff95f242b66300 x1875731019435648/t0(0) o250->MGC192.168.202.101@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 [ 7650.240073] LustreError: 3322:0:(client.c:1404:ptlrpc_import_delay_req()) Skipped 1 previous similar message [ 7655.999950] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7665.558604] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6504 to 0x280000400:6529) [ 7681.158492] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6596 to 0x240000400:6625) [ 7683.168836] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7700.270816] Lustre: DEBUG MARKER: == replay-single test 89: no disk space leak on late ost connection ========================================================== 01:08:05 (1788844085) [ 7720.107471] Lustre: Failing over lustre-OST0000 [ 7720.218068] Lustre: server umount lustre-OST0000 complete [ 7725.006094] Lustre: Failing over lustre-MDT0000 [ 7725.618983] Lustre: server umount lustre-MDT0000 complete [ 7742.367196] Lustre: 3325:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788844113/real 1788844113] req@ffff95f37b000000 x1875731019460992/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1788844129 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 7742.411228] Lustre: 3325:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 17 previous similar messages [ 7754.186123] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 7754.196304] Lustre: Skipped 7 previous similar messages [ 7754.288356] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6504 to 0x280000400:6561) [ 7759.353823] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7767.526826] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 7767.531425] Lustre: Skipped 13 previous similar messages [ 7775.053963] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7777.567042] Lustre: lustre-OST0000: Denying connection for new client f9c563f0-eba4-4e5d-817c-0b1336db00fb (at 192.168.202.1@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 1:05 [ 7782.952305] Lustre: lustre-OST0000: Denying connection for new client f9c563f0-eba4-4e5d-817c-0b1336db00fb (at 192.168.202.1@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 1:00 [ 7793.183702] Lustre: lustre-OST0000: Denying connection for new client f9c563f0-eba4-4e5d-817c-0b1336db00fb (at 192.168.202.1@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 0:50 [ 7793.202821] Lustre: Skipped 1 previous similar message [ 7813.668199] Lustre: lustre-OST0000: Denying connection for new client f9c563f0-eba4-4e5d-817c-0b1336db00fb (at 192.168.202.1@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 0:29 [ 7813.691943] Lustre: Skipped 3 previous similar messages [ 7843.503076] Lustre: lustre-OST0000: recovery is timed out, evict stale exports [ 7843.519586] Lustre: 176037:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-OST0000: disconnect stale client 598eef32-656a-45d2-8d7c-3d77e712d9a5@ [ 7843.538657] Lustre: lustre-OST0000: disconnecting 1 stale clients [ 7843.625731] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6636 to 0x240000400:6657) [ 7846.490600] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 59 sec [ 7861.511477] Lustre: DEBUG MARKER: free_before: 7520256 free_after: 7520256 [ 7868.748937] Lustre: DEBUG MARKER: == replay-single test 90: lfs find identifies the missing striped file segments ========================================================== 01:10:53 (1788844253) [ 7873.577992] Lustre: Failing over lustre-OST0000 [ 7873.689366] Lustre: server umount lustre-OST0000 complete [ 7874.527805] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 7874.548645] Lustre: lustre-OST0000-osc-MDT0000: Connection to lustre-OST0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 7874.557486] Lustre: Skipped 11 previous similar messages [ 7874.570820] LustreError: 36609: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. [ 7874.586909] LustreError: 36609:0:(ldlm_lib.c:1190:target_handle_connect()) Skipped 39 previous similar messages [ 7893.975288] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 7893.981325] Lustre: Skipped 10 previous similar messages [ 7893.992770] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 7894.001327] Lustre: Skipped 8 previous similar messages [ 7895.526538] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 7895.544843] Lustre: Skipped 8 previous similar messages [ 7901.108070] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7912.010947] Lustre: DEBUG MARKER: == replay-single test 93a: replay + reconnect ============ 01:11:37 (1788844297) [ 7916.001451] Lustre: Failing over lustre-OST0000 [ 7916.087255] Lustre: server umount lustre-OST0000 complete [ 7916.513937] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 7936.613613] LustreError: 179116:0:(ldlm_lib.c:2930:target_recovery_thread()) cfs_fail_timeout id 715 sleeping for 40000ms [ 7936.629926] LustreError: 179116:0:(ldlm_lib.c:2930:target_recovery_thread()) Skipped 81 previous similar messages [ 7942.624038] Lustre: *** cfs_fail_loc=715, val=40*** [ 7944.032685] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7952.864269] Lustre: lustre-OST0000: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnected, waiting for 2 clients in recovery for 1:24 [ 7959.007427] Lustre: *** cfs_fail_loc=715, val=40*** [ 7959.010874] Lustre: Skipped 1 previous similar message [ 7968.224081] Lustre: lustre-OST0000: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnected, waiting for 2 clients in recovery for 1:09 [ 7968.237026] Lustre: Skipped 1 previous similar message [ 7969.315529] Lustre: lustre-OST0000: Client f9c563f0-eba4-4e5d-817c-0b1336db00fb (at 192.168.202.1@tcp) reconnected, waiting for 2 clients in recovery for 1:08 [ 7974.369856] Lustre: *** cfs_fail_loc=715, val=40*** [ 7974.372700] Lustre: Skipped 1 previous similar message [ 7976.671777] LustreError: 179116:0:(ldlm_lib.c:2930:target_recovery_thread()) cfs_fail_timeout id 715 awake [ 7976.685331] LustreError: 179116:0:(ldlm_lib.c:2930:target_recovery_thread()) Skipped 76 previous similar messages [ 7983.847184] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 7985.455115] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 7994.435980] Lustre: DEBUG MARKER: == replay-single test 93b: replay + reconnect on mds ===== 01:12:59 (1788844379) [ 7999.605673] Lustre: Failing over lustre-MDT0000 [ 7999.992782] Lustre: server umount lustre-MDT0000 complete [ 8018.331828] LustreError: MGC192.168.202.101@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 8018.337403] LustreError: Skipped 4 previous similar messages [ 8023.526493] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 8027.575524] LustreError: 180714:0:(ldlm_lib.c:2930:target_recovery_thread()) cfs_fail_timeout id 715 sleeping for 80000ms [ 8033.759154] Lustre: *** cfs_fail_loc=715, val=80*** [ 8033.761104] Lustre: Skipped 1 previous similar message [ 8044.062779] Lustre: lustre-MDT0000: Client f9c563f0-eba4-4e5d-817c-0b1336db00fb (at 192.168.202.1@tcp) reconnected, waiting for 1 clients in recovery for 0:53 [ 8050.143158] Lustre: *** cfs_fail_loc=715, val=80*** [ 8060.454188] Lustre: lustre-MDT0000: Client f9c563f0-eba4-4e5d-817c-0b1336db00fb (at 192.168.202.1@tcp) reconnected, waiting for 1 clients in recovery for 0:37 [ 8066.527137] Lustre: *** cfs_fail_loc=715, val=80*** [ 8075.813292] Lustre: lustre-MDT0000: Client f9c563f0-eba4-4e5d-817c-0b1336db00fb (at 192.168.202.1@tcp) reconnected, waiting for 1 clients in recovery for 0:21 [ 8092.196612] Lustre: lustre-MDT0000: Client f9c563f0-eba4-4e5d-817c-0b1336db00fb (at 192.168.202.1@tcp) reconnected, waiting for 1 clients in recovery for 0:05 [ 8098.271323] Lustre: *** cfs_fail_loc=715, val=80*** [ 8098.278765] Lustre: Skipped 1 previous similar message [ 8107.620104] LustreError: 180714:0:(ldlm_lib.c:2930:target_recovery_thread()) cfs_fail_timeout id 715 awake [ 8107.741915] Lustre: 180714:0:(ldlm_lib.c:2976:target_recovery_thread()) too long recovery - read logs [ 8107.751882] LustreError: dumping log to /tmp/lustre-log.1788844494.180714 [ 8107.958421] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6574 to 0x280000400:6593) [ 8107.959304] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6671 to 0x240000400:6689) [ 8116.020534] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 8118.247574] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8128.548977] Lustre: DEBUG MARKER: == replay-single test complete, duration 7835 sec ======== 01:15:13 (1788844513) [ 8130.267549] Lustre: DEBUG MARKER: === replay-single: start cleanup 01:15:15 (1788844515) === [ 8140.980569] Lustre: DEBUG MARKER: === replay-single: finish cleanup 01:15:25 (1788844525) === [ 8143.524931] Lustre: Failing over lustre-MDT0000 [ 8144.139599] Lustre: server umount lustre-MDT0000 complete [ 8174.215958] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6574 to 0x280000400:6625) [ 8174.217967] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6671 to 0x240000400:6721) [ 8179.510536] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 8189.999666] Lustre: DEBUG MARKER: oleg201-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 8191.747829] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 8202.723842] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 8204.111772] Lustre: server umount lustre-MDT0000 complete [ 8208.564212] LustreError: 5837:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1788844595 with bad export cookie 631975261419815308 [ 8208.576438] LustreError: 5837:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 8208.638897] Lustre: server umount lustre-OST0000 complete [ 8212.838975] Lustre: server umount lustre-OST0001 complete [ 8225.703996] Lustre: DEBUG MARKER: oleg201-server.virtnet: executing unload_modules_local [ 8228.747873] Key type lgssc unregistered [ 8229.101232] LNet: 184007:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 8229.112517] LNetError: 184007:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 8229.134852] LNet: Removed LNI 192.168.202.101@tcp [ 8230.286313] Key type .llcrypt unregistered [ 8230.290577] Key type ._llcrypt unregistered