[ 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-8.fc42 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 697949381 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 0x00000000BFFE2439 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE22D5 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 002295 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE2349 000090 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE23D9 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE2411 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe22d5-0xbffe2348] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe22d4] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe2349-0xbffe23d8] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe23d9-0xbffe2410] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe2411-0xbffe2438] [ 0.000000] No NUMA configuration found [ 0.000000] Faking a node at [mem 0x0000000000000000-0x0000000146dfffff] [ 0.000000] NODE_DATA(0) allocated [mem 0x1465a3000-0x1465cdfff] [ 0.000000] Reserving 256MB of memory at 2752MB for crashkernel (System RAM: 4205MB) [ 0.000000] Zone ranges: [ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.000000] DMA32 [mem 0x0000000001000000-0x00000000ffffffff] [ 0.000000] Normal [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Device empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff] [ 0.000000] node 0: [mem 0x0000000000100000-0x00000000bffcdfff] [ 0.000000] node 0: [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Zeroed struct page in unavailable ranges: 4756 pages [ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x0000000146dfffff] [ 0.000000] ACPI: PM-Timer IO Port: 0x608 [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) [ 0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) [ 0.000000] Using ACPI (MADT) for SMP configuration information [ 0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000] TSC deadline timer available [ 0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs [ 0.000000] kvm-guest: KVM setup pv remote TLB flush [ 0.000000] kvm-guest: setup PV sched yield [ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff] [ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff] [ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff] [ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff] [ 0.000000] PM: Registered nosave memory: [mem 0xbffce000-0xbfffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xc0000000-0xfeffbfff] [ 0.000000] PM: Registered nosave memory: [mem 0xfeffc000-0xfeffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xff000000-0xfffbffff] [ 0.000000] PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff] [ 0.000000] [mem 0xc0000000-0xfeffbfff] available for PCI devices [ 0.000000] Booting paravirtualized kernel on KVM [ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns [ 0.000000] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1 [ 0.000000] percpu: Embedded 63 pages/cpu s221184 r8192 d28672 u524288 [ 0.000000] kvm-guest: PV spinlocks enabled [ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1059606 [ 0.000000] Policy zone: Normal [ 0.000000] Kernel command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] Specific versions of hardware are certified with Red Hat Enterprise Linux 8. Please see the list of hardware certified with Red Hat Enterprise Linux 8 at https://catalog.redhat.com. [ 0.000000] audit: disabled (until reboot) [ 0.000000] software IO TLB: area num 4. [ 0.000000] Memory: 2829652K/4306352K available (18435K kernel code, 11221K rwdata, 7248K rodata, 2908K init, 18040K bss, 524580K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] ftrace: allocating 41240 entries in 162 pages [ 0.000000] ftrace: allocated 162 pages with 3 groups [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] rcu: RCU event tracing is enabled. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ 0.000000] rcu: RCU callback double-/use-after-free debug enabled. [ 0.000000] Rude variant of Tasks RCU enabled. [ 0.000000] Tracing variant of Tasks RCU enabled. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 0.000000] NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16 [ 0.000000] random: get_random_bytes called from start_kernel+0x622/0x9a8 with crng_init=0 [ 0.001000] Console: colour *CGA 80x25 [ 0.001000] printk: console [ttyS1] enabled [ 0.001000] ACPI: Core revision 20220331 [ 0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.001012] APIC: Switch to symmetric I/O mode setup [ 0.002281] x2apic enabled [ 0.003007] Switched APIC routing to physical x2apic. [ 0.004009] kvm-guest: setup PV IPIs [ 0.007285] ..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.008024] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.009012] pid_max: default: 32768 minimum: 301 [ 0.010131] LSM: Security Framework initializing [ 0.011000] Yama: becoming mindful. [ 0.012018] SELinux: Initializing. [ 0.012860] *** VALIDATE selinux *** [ 0.021228] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.025751] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.026201] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.027088] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.028110] *** VALIDATE tmpfs *** [ 0.029463] *** VALIDATE proc *** [ 0.031097] *** VALIDATE cgroup *** [ 0.032014] *** VALIDATE cgroup2 *** [ 0.034105] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.035144] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.036000] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.037028] Spectre V2 : User space: Vulnerable [ 0.038014] Speculative Store Bypass: Vulnerable [ 0.041107] debug: unmapping init [mem 0xffffffff9b659000-0xffffffff9b660fff] [ 0.045000] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.045882] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.046019] ... version: 2 [ 0.047010] ... bit width: 48 [ 0.047906] ... generic registers: 4 [ 0.048011] ... value mask: 0000ffffffffffff [ 0.049009] ... max period: 00007fffffffffff [ 0.050011] ... fixed-purpose events: 3 [ 0.050896] ... event mask: 000000070000000f [ 0.051289] rcu: Hierarchical SRCU implementation. [ 0.053892] smp: Bringing up secondary CPUs ... [ 0.054687] x86: Booting SMP configuration: [ 0.055023] .... node #0, CPUs: #1 #2 #3 [ 0.063574] smp: Brought up 1 node, 4 CPUs [ 0.065014] smpboot: Max logical packages: 1 [ 0.066008] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.108000] node 0 deferred pages initialised in 39ms [ 0.111314] devtmpfs: initialized [ 0.113218] x86/mm: Memory block size: 128MB [ 0.119346] gcov: version magic: 0x41383552 [ 0.122615] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.139103] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.141000] pinctrl core: initialized pinctrl subsystem [ 0.146000] [ 0.146000] ************************************************************* [ 0.168020] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.180027] ** ** [ 0.186017] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.195011] ** ** [ 0.203017] ** This means that this kernel is built to expose internal ** [ 0.205022] ** IOMMU data structures, which may compromise security on ** [ 0.211019] ** your system. ** [ 0.216142] ** ** [ 0.224018] ** If you see this message and you are not debugging the ** [ 0.230019] ** kernel, report this immediately to your vendor! ** [ 0.235167] ** ** [ 0.241017] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.247024] ************************************************************* [ 0.260519] NET: Registered protocol family 16 [ 0.262752] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.267123] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.273083] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.282091] cpuidle: using governor menu [ 0.284762] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.294000] PCI: Using configuration type 1 for base access [ 0.304522] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.352237] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.353036] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.359043] cryptd: max_cpu_qlen set to 1000 [ 0.364652] ACPI: Added _OSI(Module Device) [ 0.366042] ACPI: Added _OSI(Processor Device) [ 0.368014] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.370015] ACPI: Added _OSI(Processor Aggregator Device) [ 0.377447] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.388298] ACPI: Interpreter enabled [ 0.389068] ACPI: PM: (supports S0 S3 S4 S5) [ 0.391013] ACPI: Using IOAPIC for interrupt routing [ 0.393122] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.397554] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.412386] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.415051] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.418021] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.423095] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.430053] acpiphp: Slot [2] registered [ 0.432166] acpiphp: Slot [5] registered [ 0.440153] acpiphp: Slot [6] registered [ 0.444068] acpiphp: Slot [7] registered [ 0.448201] acpiphp: Slot [8] registered [ 0.454223] acpiphp: Slot [9] registered [ 0.460128] acpiphp: Slot [10] registered [ 0.465401] acpiphp: Slot [3] registered [ 0.467276] acpiphp: Slot [4] registered [ 0.477258] acpiphp: Slot [11] registered [ 0.486054] acpiphp: Slot [12] registered [ 0.491082] acpiphp: Slot [13] registered [ 0.493882] acpiphp: Slot [14] registered [ 0.497714] acpiphp: Slot [15] registered [ 0.500471] acpiphp: Slot [16] registered [ 0.503297] acpiphp: Slot [17] registered [ 0.506961] acpiphp: Slot [18] registered [ 0.518000] acpiphp: Slot [19] registered [ 0.524805] acpiphp: Slot [20] registered [ 0.531031] acpiphp: Slot [21] registered [ 0.539288] acpiphp: Slot [22] registered [ 0.545890] acpiphp: Slot [23] registered [ 0.550199] acpiphp: Slot [24] registered [ 0.552309] acpiphp: Slot [25] registered [ 0.554174] acpiphp: Slot [26] registered [ 0.559591] acpiphp: Slot [27] registered [ 0.561209] acpiphp: Slot [28] registered [ 0.565035] acpiphp: Slot [29] registered [ 0.570194] acpiphp: Slot [30] registered [ 0.572154] acpiphp: Slot [31] registered [ 0.575119] PCI host bridge to bus 0000:00 [ 0.577034] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.581030] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.584026] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.588030] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.591028] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.597126] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.602241] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.612161] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.616707] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.632736] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.646055] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.651021] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.653020] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.655020] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.657818] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.660529] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.666048] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.671084] pci 0000:00:01.3: quirk_piix4_acpi+0x0/0x1e0 took 10742 usecs [ 0.679878] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.714022] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.727019] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.735022] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.744627] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.750019] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.757018] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.773018] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.783000] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.788016] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.793015] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.812016] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.822562] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.828015] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.836018] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.849019] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.863000] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.872019] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.879017] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.898028] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.901000] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.901000] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.901000] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.909020] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 0.921391] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.932019] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.938017] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.955021] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 0.970557] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.973543] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.976408] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.978408] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.981225] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.987072] iommu: Default domain type: Passthrough [ 0.988424] SCSI subsystem initialized [ 0.989126] ACPI: bus type USB registered [ 0.991123] usbcore: registered new interface driver usbfs [ 0.994100] usbcore: registered new interface driver hub [ 0.996117] usbcore: registered new device driver usb [ 0.997175] pps_core: LinuxPPS API ver. 1 registered [ 0.999011] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 1.002072] PTP clock support registered [ 1.004094] EDAC MC: Ver: 3.0.0 [ 1.007185] PCI: Using ACPI for IRQ routing [ 1.008000] NetLabel: Initializing [ 1.010014] NetLabel: domain hash size = 128 [ 1.012016] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 1.015096] NetLabel: unlabeled traffic allowed by default [ 1.018490] vgaarb: loaded [ 1.020171] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 1.022012] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 1.029268] clocksource: Switched to clocksource kvm-clock [ 1.183991] VFS: Disk quotas dquot_6.6.0 [ 1.188943] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 1.193923] *** VALIDATE ramfs *** [ 1.195420] *** VALIDATE hugetlbfs *** [ 1.198403] pnp: PnP ACPI init [ 1.203178] pnp: PnP ACPI: found 6 devices [ 1.236141] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 1.240651] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 1.243694] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 1.246716] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 1.250182] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 1.253273] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 1.257209] NET: Registered protocol family 2 [ 1.260464] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 1.266690] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 1.270940] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 1.277375] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 1.281415] TCP: Hash tables configured (established 65536 bind 65536) [ 1.292376] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 1.298878] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 1.305322] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 1.313703] NET: Registered protocol family 1 [ 1.318224] RPC: Registered named UNIX socket transport module. [ 1.320967] RPC: Registered udp transport module. [ 1.323899] RPC: Registered tcp transport module. [ 1.327258] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 1.330855] NET: Registered protocol family 44 [ 1.333944] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 1.336924] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 1.339914] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 1.344646] PCI: CLS 0 bytes, default 64 [ 1.347618] Unpacking initramfs... [ 3.548518] debug: unmapping init [mem 0xffff9e88bcc54000-0xffff9e88bffbffff] [ 3.552980] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 3.554826] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 3.559594] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 4.951269] Initialise system trusted keyrings [ 4.952843] Key type blacklist registered [ 4.956067] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 4.965271] zbud: loaded [ 4.970805] *** VALIDATE nfs *** [ 4.972625] *** VALIDATE nfs4 *** [ 4.974376] pstore: using deflate compression [ 4.978977] Platform Keyring initialized [ 5.291449] NET: Registered protocol family 38 [ 5.294412] Key type asymmetric registered [ 5.297264] Asymmetric key parser 'x509' registered [ 5.299677] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 5.304297] io scheduler mq-deadline registered [ 5.305931] io scheduler kyber registered [ 5.308782] io scheduler bfq registered [ 5.312406] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 5.315863] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 5.318983] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 5.321513] ACPI: Power Button [PWRF] [ 5.329266] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 5.339536] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 5.355477] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 5.365468] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 5.385890] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 5.417892] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 5.463777] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 5.469523] Non-volatile memory driver v1.3 [ 5.471464] Linux agpgart interface v0.103 [ 5.508974] virtio_blk virtio1: [vda] 133944 512-byte logical blocks (68.6 MB/65.4 MiB) [ 5.512497] vda: detected capacity change from 0 to 68579328 [ 5.533869] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 5.543698] vdb: detected capacity change from 0 to 1073741824 [ 5.572620] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 5.577403] vdc: detected capacity change from 0 to 2621440000 [ 5.602331] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 5.606130] vdd: detected capacity change from 0 to 2621440000 [ 5.633315] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 5.637129] vde: detected capacity change from 0 to 4294967296 [ 5.663260] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 5.666794] vdf: detected capacity change from 0 to 4294967296 [ 5.683437] libphy: Fixed MDIO Bus: probed [ 5.689955] usbcore: registered new interface driver usbserial_generic [ 5.692978] usbserial: USB Serial support registered for generic [ 5.696719] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 5.702521] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 5.705076] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 5.709798] mousedev: PS/2 mouse device common for all mice [ 5.714736] rtc_cmos 00:05: RTC can wake from S4 [ 5.719111] rtc_cmos 00:05: registered as rtc0 [ 5.721587] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 5.724668] intel_pstate: CPU model not supported [ 5.728406] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 5.732990] hid: raw HID events driver (C) Jiri Kosina [ 5.739333] usbcore: registered new interface driver usbhid [ 5.741506] usbhid: USB HID core driver [ 5.743112] drop_monitor: Initializing network drop monitor service [ 5.747562] Initializing XFRM netlink socket [ 5.750693] NET: Registered protocol family 10 [ 5.752433] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 5.759316] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 5.760490] Segment Routing with IPv6 [ 5.764397] NET: Registered protocol family 17 [ 5.766415] mpls_gso: MPLS GSO support [ 5.771957] RAS: Correctable Errors collector initialized. [ 5.774150] AVX version of gcm_enc/dec engaged. [ 5.776104] AES CTR mode by8 optimization enabled [ 5.891709] sched_clock: Marking stable (5891601676, 0)->(7392231907, -1500630231) [ 5.897841] registered taskstats version 1 [ 5.900601] Loading compiled-in X.509 certificates [ 5.904089] zswap: loaded using pool lzo/zbud [ 5.940692] Key type big_key registered [ 5.959155] Key type encrypted registered [ 5.961993] ima: No TPM chip found, activating TPM-bypass! [ 5.965272] ima: Allocated hash algorithm: sha1 [ 5.967464] ima: No architecture policies found [ 5.969882] evm: Initialising EVM extended attributes: [ 5.972477] evm: security.selinux [ 5.973971] evm: security.ima [ 5.975430] evm: security.capability [ 5.977431] evm: HMAC attrs: 0x1 [ 5.981124] rtc_cmos 00:05: setting system clock to 2026-04-23 04:39:18 UTC (1776919158) [ 5.989646] debug: unmapping init [mem 0xffffffff9c603000-0xffffffff9c7fffff] [ 5.993595] debug: unmapping init [mem 0xffffffff9b382000-0xffffffff9b658fff] [ 6.003111] Write protecting the kernel read-only data: 28672k [ 6.010836] debug: unmapping init [mem 0xffffffff99a03000-0xffffffff99bfffff] [ 6.018101] debug: unmapping init [mem 0xffffffff9a314000-0xffffffff9a3fffff] [ 6.083156] 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) [ 6.095608] systemd[1]: Detected virtualization kvm. [ 6.097871] systemd[1]: Detected architecture x86-64. [ 6.100459] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 6.135336] systemd[1]: No hostname configured. [ 6.137904] systemd[1]: Set hostname to . [ 6.140056] random: systemd: uninitialized urandom read (16 bytes read) [ 6.142944] systemd[1]: Initializing machine ID from random generator. [ 6.375102] random: ln: uninitialized urandom read (6 bytes read) [ 6.775272] random: systemd: uninitialized urandom read (16 bytes read) [ 6.780705] systemd[1]: Reached target Initrd Root Device. [ OK ] Reached target Initrd Root Device. [ 6.793561] systemd[1]: Reached target Swap. [ OK ] Reached target Swap. [ 6.808666] systemd[1]: Listening on Journal Socket. [ OK ] Listening on Journal Socket. Starting Create list of required st…ce nodes for the current kernel... Starting Setup Virtual Console... [ OK ] Listening on Journal Socket (/dev/log). Starting Journal Service... [ OK ] Started Memstrack Anylazing Service. [ OK ] Reached target Slices. [ OK ] Reached target Timers. [ OK ] Reached target Local File Systems. Starting Create Volatile Files and Directories... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Listening on udev Control Socket. [ OK ] Listening on udev Kernel Socket. [ OK ] Reached target Sockets. Starting Apply Kernel Variables... [ OK ] Reached target Paths. [ 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 Journal Service. [ 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 dracut cmdline hook. Starting dracut pre-udev hook... [ 8.503876] device-mapper: uevent: version 1.0.3 [ 8.509838] device-mapper: ioctl: 4.46.0-ioctl (2022-02-22) initialised: dm-devel@redhat.com [ OK ] Started dracut pre-udev hook. Starting udev Kernel Device Manager... [ OK ] Started udev Kernel Device Manager. Starting dracut pre-trigger hook... [ OK ] Started dracut pre-trigger hook. Starting udev Coldplug all Devices... Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. Starting dracut initqueue hook... [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ 11.022286] virtio_net virtio0 ens2: renamed from eth0 [ 11.157453] random: fast init done [ 11.645057] scsi host0: ata_piix [ 11.717692] scsi host1: ata_piix [ 11.720396] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 11.723647] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 16.513385] random: crng init done [ 16.514804] random: 7 urandom warning(s) missed due to ratelimiting [ 19.442822] dracut-initqueue[585]: RTNETLINK answers: File exists 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... [ 21.483740] 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 Remote File Systems. [ OK ] Stopped target Initrd Default Target. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped target Timers. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Sockets. [ OK ] Stopped target System Initialization. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. Stopping udev Kernel Device Manager... [ OK ] Stopped target Swap. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. [ OK ] Stopped target Slices. [ OK ] Stopped target Paths. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Closed udev Kernel Socket. [ OK ] Closed udev Control Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 23.599782] printk: systemd: 22 output lines suppressed due to ratelimiting [ 24.572522] SELinux: Disabled at runtime. [ 24.699398] 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) [ 24.713198] systemd[1]: Detected virtualization kvm. [ 24.716128] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 26.660217] systemd[1]: initrd-switch-root.service: Succeeded. [ 26.676043] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 26.692770] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 26.704369] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 26.717323] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 26.738473] systemd[1]: Starting Journal Service... Starting Journal Service... [ 26.756323] systemd[1]: Starting Remount Root and Kernel File Systems... Starting Remount Root and Kernel File Systems... Activating swap /dev/disk/by-label/SWAP... [ OK ] Started Dispatch Password Requests to Console Directory Watch. Mounting Huge Pages File System... [ OK ] Reached target rpc_pipefs.target. [ OK ] Created slice User and Session Slice. [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Listening on udev Control Socket. [ OK ] Listening on RPCbind Server Activation Socket. [ 26.953785] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS [ OK ] Listening on Process Core Dump Socket. Mounting Kernel Debug File System... [ OK ] Listening on udev Kernel Socket. Starting udev Coldplug all Devices... [ OK ] Listening on initctl Compatibility Named Pipe. Mounting POSIX Message Queue File System... [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd File Systems. [ OK ] Stopped target Initrd Root File System. [ OK ] Created slice system-getty.slice. [ OK ] Created slice system-sshd\x2dkeygen.slice. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Reached target Paths. [ OK ] Reached target Local Encrypted Volumes. Starting Apply Kernel Variables... [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Reached target RPC Port Mapper. [ OK ] Reached target Slices. [ OK ] Started Journal Service. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Mounted Huge Pages File System. [ OK ] Mounted Kernel Debug File System. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Apply Kernel Variables. [ OK ] Reached target Swap. Starting Configure read-only root support... Starting Create Static Device Nodes in /dev... Starting Flush Journal to Persistent Storage... [ OK ] Started udev Coldplug all Devices. [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Reached target Local File Systems (Pre). Mounting /home/green/git/lustre-release... Mounting /mnt... Starting udev Kernel Device Manager... [ OK ] Mounted /mnt. [ 28.330612] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 29.427050] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 29.591323] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 30.200226] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 30.280771] EDAC sbridge: Ver: 1.1.2 [* ] A start job is running for Configur…-only root support (7s / no limit) [** ] A start job is running for Configur…-only root support (8s / no limit) [*** ] A start job is running for Configur…-only root support (9s / no limit) [ *** ] A start job is running for Configur…-only root support (9s / no limit)[ 36.361163] Key type dns_resolver registered [ *** ] A start job is running for Configur…only root support (10s / no limit)[ 37.293577] NFS: Registering the id_resolver key type [ 37.297173] Key type id_resolver registered [ 37.301234] Key type id_legacy registered [ ***] A start job is running for Configur…only root support (11s / no limit) [ **] A start job is running for Configur…only root support (11s / no limit) [ OK ] Started Configure read-only root support. Starting Load/Save Random Seed... [ OK ] Reached target Local File Systems. Starting Mark the need to relabel after reboot... Starting Rebuild Dynamic Linker Cache... Starting Create Volatile Files and Directories... [ OK ] Started Load/Save Random Seed. [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Create Volatile Files and Directories. Starting RPC Bind... Starting Update UTMP about System Boot/Shutdown... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Started dnf makecache --timer. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. Starting Restore /run/initramfs on shutdown... Starting Login Service... [ OK ] Started irqbalance daemon. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Reached target Timers. [ OK ] Reached target sshd-keygen.target. [ OK ] Started D-Bus System Message Bus. Starting Network Manager... [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Network Manager. [ OK ] Reached target Network. Starting Dynamic System Tuning Daemon... Starting OpenSSH server daemon... Starting GSSAPI Proxy Daemon... Starting Network Manager Wait Online... [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Started Login Service. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... Starting Hostname Service... [ OK ] Started OpenSSH server daemon. [ OK ] Started Permit User Sessions. [ OK ] Started Serial Getty on ttyS1. [ OK ] Started Command Scheduler. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Getty on tty1. [ OK ] Reached target Login Prompts. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting System Logging Service... Starting Crash recovery kernel arming... Starting Notify NFS peers of a restart... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg350-server login: [ 70.239783] spl: loading out-of-tree module taints kernel. [ 73.572435] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 79.578283] Key type ._llcrypt registered [ 79.580711] Key type .llcrypt registered [ 79.643847] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_hostid [ 88.880517] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing load_modules_local [ 89.562248] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 89.573970] alg: No test for adler32 (adler32-zlib) [ 90.670436] Lustre: Lustre: Build Version: 2.17.51_74_g68f2299 [ 91.182134] LNet: Added LNI 192.168.203.150@tcp [8/256/0/180] [ 92.871230] Key type lgssc registered [ 93.844745] Lustre: Echo OBD driver; http://www.lustre.org/ [ 99.438444] vdc: vdc1 vdc9 [ 104.978857] vde: vde1 vde9 [ 110.444556] vdf: vdf1 vdf9 [ 120.699352] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing load_modules_local [ 126.120108] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 127.289165] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 127.444336] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 127.498678] Lustre: lustre-MDT0000: new disk, initializing [ 127.780495] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 127.826057] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 130.686210] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 133.956936] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 137.052344] Lustre: lustre-OST0000: new disk, initializing [ 137.055361] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 137.059147] Lustre: Skipped 1 previous similar message [ 137.119583] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 140.416507] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 142.966782] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:0:ost [ 142.975844] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:0:ost] [ 143.051088] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x240000400 [ 146.427987] Lustre: lustre-OST0001: new disk, initializing [ 146.432824] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 146.490115] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 148.107142] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:1:ost [ 148.114364] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:1:ost] [ 148.218281] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x280000400 [ 149.903248] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 157.493539] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 160.940734] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 168.683868] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing check_logdir /tmp/testlogs/ [ 170.704417] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing yml_node [ 172.748989] Lustre: DEBUG MARKER: Client: 2.17.51.74 [ 174.163623] Lustre: DEBUG MARKER: MDS: 2.17.51.74 [ 175.632694] Lustre: DEBUG MARKER: OSS: 2.17.51.74 [ 176.548340] Lustre: DEBUG MARKER: -----============= acceptance-small: replay-single ============----- Thu Apr 23 00:42:08 EDT 2026 [ 187.458605] Lustre: DEBUG MARKER: excepting tests: 59 36 [ 188.280184] Lustre: DEBUG MARKER: === replay-single: start setup 00:42:20 (1776919340) === [ 189.933088] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing check_config_client /mnt/lustre [ 198.500793] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 200.487506] Lustre: 10983:0:(mgs_llog.c:1348:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 202.556493] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 204.543114] Lustre: DEBUG MARKER: === replay-single: finish setup 00:42:36 (1776919356) === [ 205.650584] Lustre: DEBUG MARKER: == replay-single test 0a: empty replay =================== 00:42:37 (1776919357) [ 207.575709] LustreError: 11459:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 208.102908] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 209.317368] Lustre: Failing over lustre-MDT0000 [ 209.376758] 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 [ 209.389307] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 209.396891] Lustre: Skipped 1 previous similar message [ 209.501544] Lustre: server umount lustre-MDT0000 complete [ 223.799934] LustreError: MGC192.168.203.150@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 224.042393] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 226.143470] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 226.187505] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 226.399660] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 230.368963] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 230.670378] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 231.537528] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 236.582617] Lustre: DEBUG MARKER: == replay-single test 0b: ensure object created after recover exists. (3284) ========================================================== 00:43:08 (1776919388) [ 237.943740] Lustre: Failing over lustre-OST0000 [ 238.031874] Lustre: server umount lustre-OST0000 complete [ 239.586099] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 239.593203] 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 [ 239.605226] Lustre: Skipped 1 previous similar message [ 245.728680] LustreError: 6530:0:(ldlm_lib.c:1179: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. [ 245.753150] LustreError: 6530:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 4 previous similar messages [ 246.589861] LustreError: 12254:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.203.50@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 250.852369] LustreError: 6531:0:(ldlm_lib.c:1179: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. [ 252.685382] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 254.366262] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 254.580496] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 254.581630] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 254.596171] Lustre: Skipped 1 previous similar message [ 256.179829] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 261.056456] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 262.126321] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 268.689259] Lustre: DEBUG MARKER: == replay-single test 0c: check replay-barrier =========== 00:43:40 (1776919420) [ 270.559855] LustreError: 14173:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 271.119494] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 272.553938] Lustre: Failing over lustre-MDT0000 [ 273.378585] 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 [ 273.380828] LustreError: 13691:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 273.395503] Lustre: Skipped 1 previous similar message [ 273.404678] LustreError: 13691:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 1 previous similar message [ 274.916893] Lustre: server umount lustre-MDT0000 complete [ 288.737866] Lustre: 3296:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776919425/real 1776919425] req@ffff9e89274ca300 x1863234872216832/t0(0) o400->MGC192.168.203.150@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1776919441 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 288.767169] LustreError: MGC192.168.203.150@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 299.373271] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 302.178790] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 303.778219] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 303.788684] Lustre: lustre-MDT0000: Denying connection for new client 3889d9ea-2d91-4563-b737-8671272e393d (at 192.168.203.50@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:59 [ 309.050613] Lustre: lustre-MDT0000: Denying connection for new client 3889d9ea-2d91-4563-b737-8671272e393d (at 192.168.203.50@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:54 [ 313.825978] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 314.172029] Lustre: lustre-MDT0000: Denying connection for new client 3889d9ea-2d91-4563-b737-8671272e393d (at 192.168.203.50@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:49 [ 319.291205] Lustre: lustre-MDT0000: Denying connection for new client 3889d9ea-2d91-4563-b737-8671272e393d (at 192.168.203.50@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:44 [ 324.410821] Lustre: lustre-MDT0000: Denying connection for new client 3889d9ea-2d91-4563-b737-8671272e393d (at 192.168.203.50@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:39 [ 334.649248] Lustre: lustre-MDT0000: Denying connection for new client 3889d9ea-2d91-4563-b737-8671272e393d (at 192.168.203.50@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:28 [ 334.660856] Lustre: Skipped 1 previous similar message [ 355.132867] Lustre: lustre-MDT0000: Denying connection for new client 3889d9ea-2d91-4563-b737-8671272e393d (at 192.168.203.50@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:08 [ 355.149261] Lustre: Skipped 3 previous similar messages [ 363.500311] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 363.504608] Lustre: 14775:0:(genops.c:1620:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 2a8ecf35-c2ba-4aa7-9dd0-f27a340f0622@ [ 363.511725] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 363.544205] Lustre: lustre-MDT0000: Recovery over after 1:00, of 1 clients 0 recovered and 1 was evicted. [ 363.565575] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:44 to 0x280000400:65) [ 363.565613] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:44 to 0x240000400:65) [ 371.255701] Lustre: DEBUG MARKER: == replay-single test 0d: expired recovery with no clients ========================================================== 00:45:22 (1776919522) [ 372.777293] LustreError: 15498:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 373.236081] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 374.290348] Lustre: Failing over lustre-MDT0000 [ 374.457659] Lustre: server umount lustre-MDT0000 complete [ 388.830466] LustreError: MGC192.168.203.150@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 389.035719] 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 [ 389.043544] Lustre: Skipped 1 previous similar message [ 389.141121] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 391.071265] Lustre: 3299:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776919527/real 1776919527] req@ffff9e8940e31500 x1863234872239360/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1776919543 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 391.437705] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 392.782922] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 392.790882] Lustre: lustre-MDT0000: Denying connection for new client fad0afe6-b350-498f-8db0-9a178a7cb52d (at 192.168.203.50@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:59 [ 392.808312] Lustre: Skipped 1 previous similar message [ 394.215575] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 394.220901] Lustre: Skipped 1 previous similar message [ 396.255198] Lustre: 3298:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776919532/real 1776919532] req@ffff9e8927787480 x1863234872239744/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1776919548 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 396.274307] Lustre: 3298:0:(client.c:2479:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 402.399283] Lustre: 3296:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776919538/real 1776919538] req@ffff9e8940e33480 x1863234872240128/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1776919554 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 402.416935] Lustre: 3296:0:(client.c:2479:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 452.500121] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 452.506356] Lustre: 16092:0:(genops.c:1620:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 3889d9ea-2d91-4563-b737-8671272e393d@ [ 452.516285] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 452.551952] Lustre: lustre-MDT0000: Recovery over after 1:00, of 1 clients 0 recovered and 1 was evicted. [ 452.577472] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:44 to 0x280000400:97) [ 452.577589] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:44 to 0x240000400:97) [ 460.187521] Lustre: DEBUG MARKER: == replay-single test 1: simple create =================== 00:46:51 (1776919611) [ 461.964255] LustreError: 16810:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 462.514705] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 463.538492] Lustre: Failing over lustre-MDT0000 [ 463.711915] Lustre: server umount lustre-MDT0000 complete [ 477.866097] LustreError: MGC192.168.203.150@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 478.022558] 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 [ 478.134177] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 480.085984] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 480.151353] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 480.191600] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:44 to 0x240000400:129) [ 480.197569] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:44 to 0x280000400:129) [ 480.360927] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 482.143106] Lustre: 3296:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776919618/real 1776919618] req@ffff9e89063b0700 x1863234872260992/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1776919634 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 483.298412] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 483.306463] Lustre: Skipped 1 previous similar message [ 484.919701] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 485.820937] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 490.482363] Lustre: DEBUG MARKER: == replay-single test 2a: touch ========================== 00:47:22 (1776919642) [ 491.487122] Lustre: 3297:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776919628/real 1776919628] req@ffff9e8936ba7100 x1863234872261632/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1776919644 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 491.506942] Lustre: 3297:0:(client.c:2479:ptlrpc_expire_one_request()) Skipped 4 previous similar messages [ 491.915835] LustreError: 18227:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 492.400318] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 493.444553] Lustre: Failing over lustre-MDT0000 [ 493.537221] 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 [ 493.538054] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 493.547867] Lustre: Skipped 2 previous similar messages [ 493.553252] Lustre: Skipped 1 previous similar message [ 493.661113] Lustre: server umount lustre-MDT0000 complete [ 507.336852] LustreError: MGC192.168.203.150@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 509.443385] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 510.620685] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 510.720154] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 510.742859] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:131 to 0x240000400:161) [ 510.743296] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:44 to 0x280000400:161) [ 513.789434] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 514.021686] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 514.025887] Lustre: Skipped 1 previous similar message [ 514.733358] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 519.298155] Lustre: DEBUG MARKER: == replay-single test 2b: touch ========================== 00:47:51 (1776919671) [ 520.770370] LustreError: 19643:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 521.284903] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 522.318758] Lustre: Failing over lustre-MDT0000 [ 522.491732] Lustre: server umount lustre-MDT0000 complete [ 536.083973] LustreError: MGC192.168.203.150@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 536.227797] 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 [ 536.236737] Lustre: Skipped 1 previous similar message [ 536.396592] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 536.477395] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 536.500070] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:163 to 0x240000400:193) [ 536.500220] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:44 to 0x280000400:193) [ 538.078078] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 540.320271] Lustre: 3298:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776919676/real 1776919676] req@ffff9e893bcb2680 x1863234872285312/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1776919692 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 541.665082] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 541.668800] Lustre: Skipped 1 previous similar message [ 542.072793] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 542.828420] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 547.253937] Lustre: DEBUG MARKER: == replay-single test 2c: setstripe replay =============== 00:48:19 (1776919699) [ 548.656662] LustreError: 21064:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 549.094428] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 550.017810] Lustre: Failing over lustre-MDT0000 [ 550.222447] Lustre: server umount lustre-MDT0000 complete [ 563.648811] LustreError: MGC192.168.203.150@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 563.849281] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 563.852771] Lustre: Skipped 2 previous similar messages [ 565.724056] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 567.217828] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:225) [ 567.218213] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:225) [ 569.901642] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 570.665062] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 572.895162] Lustre: 3297:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776919709/real 1776919709] req@ffff9e89063b3b80 x1863234872297984/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1776919725 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 572.908045] Lustre: 3297:0:(client.c:2479:ptlrpc_expire_one_request()) Skipped 7 previous similar messages [ 574.508448] Lustre: DEBUG MARKER: == replay-single test 2d: setdirstripe replay ============ 00:48:46 (1776919726) [ 576.328845] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 577.260679] Lustre: Failing over lustre-MDT0000 [ 577.344501] Lustre: lustre-MDT0000: Not available for connect from 192.168.203.50@tcp (stopping) [ 577.464255] Lustre: server umount lustre-MDT0000 complete [ 591.284540] 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 [ 591.292664] Lustre: Skipped 3 previous similar messages [ 593.465304] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 596.450047] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 596.458668] Lustre: Skipped 3 previous similar messages [ 596.794656] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 596.800443] Lustre: Skipped 1 previous similar message [ 596.863975] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 596.870590] Lustre: Skipped 1 previous similar message [ 596.902203] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:257) [ 596.902203] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:257) [ 598.888260] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 599.788102] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 604.649383] Lustre: DEBUG MARKER: == replay-single test 2e: O_CREAT|O_EXCL create replay === 00:49:16 (1776919756) [ 605.192827] Lustre: *** cfs_fail_loc=13b, val=315*** [ 605.198131] Lustre: *** cfs_fail_loc=13b, val=2147483648*** [ 605.200304] LustreError: 23040:0:(ldlm_lib.c:3326:target_send_reply_msg()) @@@ dropping reply req@ffff9e89274b6d80 x1863234862813952/t38654705666(0) o35->fad0afe6-b350-498f-8db0-9a178a7cb52d@192.168.203.50@tcp:94/0 lens 392/456 e 0 to 0 dl 1776919774 ref 1 fl Interpret:/600/0 rc 0/0 job:'openfile.0' uid:0 gid:0 projid:0 [ 607.623092] LustreError: 23957:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 607.629718] LustreError: 23957:0:(osd_handler.c:720:osd_ro()) Skipped 1 previous similar message [ 608.158708] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 609.167723] Lustre: Failing over lustre-MDT0000 [ 609.371206] Lustre: server umount lustre-MDT0000 complete [ 623.185863] LustreError: MGC192.168.203.150@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 623.190468] LustreError: Skipped 1 previous similar message [ 623.515434] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 625.635504] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 627.605772] Lustre: 24509:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9e8936ba6680 x1863234862813952/t38654705666(0) o35->fad0afe6-b350-498f-8db0-9a178a7cb52d@192.168.203.50@tcp:117/0 lens 392/456 e 0 to 0 dl 1776919797 ref 1 fl Interpret:/602/0 rc 0/0 job:'openfile.0' uid:0 gid:0 projid:0 [ 627.609472] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:289) [ 627.609478] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:289) [ 630.001520] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 630.839680] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 635.447306] Lustre: DEBUG MARKER: == replay-single test 3a: replay failed open(O_DIRECTORY) ========================================================== 00:49:47 (1776919787) [ 637.615713] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 637.922262] Lustre: 3299:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776919774/real 1776919774] req@ffff9e89274b6a00 x1863234872323456/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1776919790 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 637.940124] Lustre: 3299:0:(client.c:2479:ptlrpc_expire_one_request()) Skipped 14 previous similar messages [ 638.563663] Lustre: Failing over lustre-MDT0000 [ 638.794085] Lustre: server umount lustre-MDT0000 complete [ 652.638881] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 653.183960] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:321) [ 653.183990] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:321) [ 654.356863] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 658.846756] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 659.724941] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 664.439881] Lustre: DEBUG MARKER: == replay-single test 3b: replay failed open -ENOMEM ===== 00:50:16 (1776919816) [ 666.371207] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 666.896599] Lustre: *** cfs_fail_loc=114, val=0*** [ 668.335665] Lustre: Failing over lustre-MDT0000 [ 668.507879] Lustre: server umount lustre-MDT0000 complete [ 682.474840] 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 [ 682.482547] Lustre: Skipped 5 previous similar messages [ 682.596816] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 684.327111] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 687.585589] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 687.592397] Lustre: Skipped 5 previous similar messages [ 693.048216] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 693.051650] Lustre: Skipped 2 previous similar messages [ 693.078753] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 693.084471] Lustre: Skipped 2 previous similar messages [ 693.105498] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:353) [ 693.106332] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:353) [ 694.930790] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 695.633874] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 700.063252] Lustre: DEBUG MARKER: == replay-single test 3c: replay failed open -ENOMEM ===== 00:50:51 (1776919851) [ 701.453131] LustreError: 28319:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 701.457420] LustreError: 28319:0:(osd_handler.c:720:osd_ro()) Skipped 2 previous similar messages [ 701.863770] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 702.295936] Lustre: *** cfs_fail_loc=128, val=0*** [ 703.672833] Lustre: Failing over lustre-MDT0000 [ 703.861902] Lustre: server umount lustre-MDT0000 complete [ 716.790586] LustreError: MGC192.168.203.150@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 716.794358] LustreError: Skipped 2 previous similar messages [ 716.973487] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 716.977947] Lustre: Skipped 4 previous similar messages [ 717.013777] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 718.571403] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 718.691878] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:385) [ 718.693254] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:385) [ 722.302352] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 723.174181] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 727.390439] Lustre: DEBUG MARKER: == replay-single test 4a: |x| 10 open(O_CREAT)s ========== 00:51:19 (1776919879) [ 729.302163] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 730.385335] Lustre: Failing over lustre-MDT0000 [ 730.598142] Lustre: server umount lustre-MDT0000 complete [ 744.239162] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 744.398366] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:391 to 0x240000400:417) [ 744.398769] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:391 to 0x280000400:417) [ 745.821949] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 749.509644] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 750.287275] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 754.481718] Lustre: DEBUG MARKER: == replay-single test 4b: |x| rm 10 files ================ 00:51:46 (1776919906) [ 756.335804] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 757.169532] Lustre: Failing over lustre-MDT0000 [ 757.336504] Lustre: server umount lustre-MDT0000 complete [ 770.713381] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 772.461167] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 774.824631] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:423 to 0x240000400:449) [ 774.824669] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:423 to 0x280000400:449) [ 776.625611] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 776.672125] Lustre: 3296:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776919912/real 1776919912] req@ffff9e8911305f80 x1863234872384256/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1776919928 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 776.692043] Lustre: 3296:0:(client.c:2479:ptlrpc_expire_one_request()) Skipped 21 previous similar messages [ 777.482948] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 782.210616] Lustre: DEBUG MARKER: == replay-single test 5: |x| 220 open(O_CREAT) =========== 00:52:14 (1776919934) [ 784.029748] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 788.305251] Lustre: Failing over lustre-MDT0000 [ 788.521567] Lustre: server umount lustre-MDT0000 complete [ 802.442826] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 804.279726] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 807.619932] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:577) [ 807.622022] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:577) [ 809.332225] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 810.114862] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 826.414529] Lustre: DEBUG MARKER: == replay-single test 6a: mkdir + contained create ======= 00:52:58 (1776919978) [ 828.760932] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 830.005710] Lustre: Failing over lustre-MDT0000 [ 830.252332] Lustre: server umount lustre-MDT0000 complete [ 844.419933] Lustre: lustre-MDT0000-lwp-OST0000: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 844.430201] Lustre: Skipped 9 previous similar messages [ 844.554823] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 846.300403] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 846.652325] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 846.657589] Lustre: Skipped 4 previous similar messages [ 846.707879] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 846.712398] Lustre: Skipped 4 previous similar messages [ 846.731121] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:609) [ 846.732154] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:609) [ 849.896921] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 849.906332] Lustre: Skipped 9 previous similar messages [ 850.662749] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 851.541313] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 858.322507] Lustre: DEBUG MARKER: == replay-single test 6b: |X| rmdir ====================== 00:53:30 (1776920010) [ 859.855888] LustreError: 35552:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 859.860017] LustreError: 35552:0:(osd_handler.c:720:osd_ro()) Skipped 4 previous similar messages [ 860.292954] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 861.172683] Lustre: Failing over lustre-MDT0000 [ 861.359953] Lustre: server umount lustre-MDT0000 complete [ 874.706839] LustreError: MGC192.168.203.150@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 874.710899] LustreError: Skipped 4 previous similar messages [ 876.828615] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 877.456910] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:641) [ 877.456915] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:641) [ 880.881721] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 881.596194] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 885.802343] Lustre: DEBUG MARKER: == replay-single test 7: mkdir |X| contained create ====== 00:53:57 (1776920037) [ 887.504107] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 888.395208] Lustre: Failing over lustre-MDT0000 [ 888.564198] Lustre: server umount lustre-MDT0000 complete [ 903.070294] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:673) [ 903.074136] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:673) [ 904.531666] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 908.790675] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 909.813107] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 914.818826] Lustre: DEBUG MARKER: == replay-single test 8: creat open |X| close ============ 00:54:26 (1776920066) [ 916.646742] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 917.607128] Lustre: Failing over lustre-MDT0000 [ 917.845849] Lustre: server umount lustre-MDT0000 complete [ 931.443831] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 931.447921] Lustre: Skipped 2 previous similar messages [ 933.293911] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 933.799417] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:705) [ 933.799855] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:705) [ 937.572623] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 938.380781] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 942.498246] Lustre: DEBUG MARKER: == replay-single test 9: |X| create (same inum/gen) ====== 00:54:54 (1776920094) [ 944.075733] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 944.891253] Lustre: Failing over lustre-MDT0000 [ 945.099894] Lustre: server umount lustre-MDT0000 complete [ 959.368541] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:737) [ 959.368597] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:737) [ 960.678239] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 964.387913] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 965.158857] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 969.288230] Lustre: DEBUG MARKER: == replay-single test 10: create |X| rename unlink ======= 00:55:21 (1776920121) [ 971.003577] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 971.890790] Lustre: Failing over lustre-MDT0000 [ 972.072469] Lustre: server umount lustre-MDT0000 complete [ 985.752797] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 985.756452] Lustre: Skipped 8 previous similar messages [ 987.697497] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 990.120641] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:769) [ 990.120680] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:769) [ 991.912409] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 992.750480] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 996.967656] Lustre: DEBUG MARKER: == replay-single test 11: create open write rename |X| create-old-name read ========================================================== 00:55:48 (1776920148) [ 999.194238] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1000.409279] Lustre: Failing over lustre-MDT0000 [ 1000.738925] Lustre: server umount lustre-MDT0000 complete [ 1027.043063] LustreError: 3295:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9e89048a5c00 x1863234872551936/t0(0) o250->MGC192.168.203.150@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 0 ref 1 fl Rpc:NQU/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1031.698270] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:771 to 0x240000400:801) [ 1031.700372] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:771 to 0x280000400:801) [ 1032.845939] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1039.663151] hrtimer: interrupt took 3965565 ns [ 1040.207926] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1042.238314] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1051.033242] Lustre: DEBUG MARKER: == replay-single test 12: open, unlink |X| close ========= 00:56:42 (1776920202) [ 1055.800968] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1058.505918] Lustre: Failing over lustre-MDT0000 [ 1058.971058] Lustre: server umount lustre-MDT0000 complete [ 1076.571914] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1076.584918] Lustre: Skipped 3 previous similar messages [ 1077.267054] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:771 to 0x240000400:833) [ 1077.267298] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:771 to 0x280000400:833) [ 1078.559099] Lustre: 3296:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776920215/real 1776920215] req@ffff9e89048a5880 x1863234872566272/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1776920231 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1078.588161] Lustre: 3296:0:(client.c:2479:ptlrpc_expire_one_request()) Skipped 52 previous similar messages [ 1079.763919] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1086.389751] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1087.606861] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1094.471351] Lustre: DEBUG MARKER: == replay-single test 13: open chmod 0 |x| write close === 00:57:25 (1776920245) [ 1097.558710] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1099.088716] Lustre: Failing over lustre-MDT0000 [ 1099.292461] Lustre: server umount lustre-MDT0000 complete [ 1114.705197] 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 [ 1114.715322] Lustre: Skipped 14 previous similar messages [ 1117.967071] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1118.025977] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1118.034268] Lustre: Skipped 7 previous similar messages [ 1118.127091] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1118.133024] Lustre: Skipped 7 previous similar messages [ 1118.159164] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:835 to 0x240000400:865) [ 1118.159464] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:771 to 0x280000400:865) [ 1120.227264] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 1120.236517] Lustre: Skipped 15 previous similar messages [ 1123.192463] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1124.078255] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1129.928913] Lustre: DEBUG MARKER: == replay-single test 14: open(O_CREAT), unlink |X| close ========================================================== 00:58:01 (1776920281) [ 1132.220443] LustreError: 46940:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 1132.226021] LustreError: 46940:0:(osd_handler.c:720:osd_ro()) Skipped 7 previous similar messages [ 1132.874435] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1134.242675] Lustre: Failing over lustre-MDT0000 [ 1134.476059] Lustre: server umount lustre-MDT0000 complete [ 1150.076680] LustreError: MGC192.168.203.150@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1150.088154] LustreError: Skipped 7 previous similar messages [ 1153.830090] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1154.064426] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:771 to 0x280000400:897) [ 1154.065504] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:867 to 0x240000400:897) [ 1160.095263] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1161.333190] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1167.898295] Lustre: DEBUG MARKER: == replay-single test 15: open(O_CREAT), unlink |X| touch new, close ========================================================== 00:58:39 (1776920319) [ 1170.985663] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1172.659614] Lustre: Failing over lustre-MDT0000 [ 1172.958463] Lustre: server umount lustre-MDT0000 complete [ 1191.142491] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:899 to 0x280000400:929) [ 1191.142567] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:899 to 0x240000400:929) [ 1192.644962] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1198.753084] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1200.075104] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1205.989761] Lustre: DEBUG MARKER: == replay-single test 16: |X| open(O_CREAT), unlink, touch new, unlink new ========================================================== 00:59:17 (1776920357) [ 1208.807856] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1210.208237] Lustre: Failing over lustre-MDT0000 [ 1210.338039] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1210.349481] Lustre: Skipped 1 previous similar message [ 1210.449238] Lustre: server umount lustre-MDT0000 complete [ 1225.626624] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:931 to 0x240000400:961) [ 1225.627334] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:899 to 0x280000400:961) [ 1226.256418] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1230.272427] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1230.949326] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1234.913037] Lustre: DEBUG MARKER: == replay-single test 17: |X| open(O_CREAT), |replay| close ========================================================== 00:59:46 (1776920386) [ 1236.555274] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1237.398328] Lustre: Failing over lustre-MDT0000 [ 1237.655696] Lustre: server umount lustre-MDT0000 complete [ 1252.840490] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:963 to 0x240000400:993) [ 1252.840745] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:899 to 0x280000400:993) [ 1252.919190] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1256.896935] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1257.651965] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1262.001686] Lustre: DEBUG MARKER: == replay-single test 18: open(O_CREAT), unlink, touch new, close, touch, unlink ========================================================== 01:00:13 (1776920413) [ 1263.780208] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1264.741835] Lustre: Failing over lustre-MDT0000 [ 1264.888815] Lustre: server umount lustre-MDT0000 complete [ 1280.316205] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1281.937283] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:995 to 0x240000400:1025) [ 1281.939851] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:995 to 0x280000400:1025) [ 1284.400600] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1285.159801] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1289.556213] Lustre: DEBUG MARKER: == replay-single test 19: mcreate, open, write, rename === 01:00:41 (1776920441) [ 1291.282626] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1292.197281] Lustre: Failing over lustre-MDT0000 [ 1292.390499] Lustre: server umount lustre-MDT0000 complete [ 1307.564736] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1027 to 0x280000400:1057) [ 1307.565166] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1027 to 0x240000400:1057) [ 1307.728729] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1311.880721] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1312.609498] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1317.196617] Lustre: DEBUG MARKER: == replay-single test 20a: |X| open(O_CREAT), unlink, replay, close (test mds_cleanup_orphans) ========================================================== 01:01:08 (1776920468) [ 1319.177439] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1320.231062] Lustre: Failing over lustre-MDT0000 [ 1320.433356] Lustre: server umount lustre-MDT0000 complete [ 1334.331505] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1334.334994] Lustre: Skipped 7 previous similar messages [ 1336.283655] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1338.269082] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1059 to 0x240000400:1089) [ 1338.269120] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1027 to 0x280000400:1089) [ 1340.168761] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1340.910497] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1345.016293] Lustre: DEBUG MARKER: == replay-single test 20b: write, unlink, eviction, replay (test mds_cleanup_orphans) ========================================================== 01:01:36 (1776920496) [ 1347.042859] Lustre: 56937:0:(genops.c:1793:obd_export_evict_by_uuid()) lustre-MDT0000: evicting fad0afe6-b350-498f-8db0-9a178a7cb52d at adminstrative request [ 1349.736762] Lustre: Failing over lustre-MDT0000 [ 1349.927444] Lustre: server umount lustre-MDT0000 complete [ 1365.339473] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1027 to 0x280000400:1121) [ 1365.340347] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1091 to 0x240000400:1121) [ 1365.848480] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1370.367910] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1371.345322] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1374.589722] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 1383.645310] Lustre: DEBUG MARKER: before 4096, after 4096 [ 1386.358887] Lustre: DEBUG MARKER: == replay-single test 20c: check that client eviction does not affect file content ========================================================== 01:02:18 (1776920538) [ 1386.832277] Lustre: 58724:0:(genops.c:1793:obd_export_evict_by_uuid()) lustre-MDT0000: evicting fad0afe6-b350-498f-8db0-9a178a7cb52d at adminstrative request [ 1392.623961] Lustre: DEBUG MARKER: == replay-single test 21: |X| open(O_CREAT), unlink touch new, replay, close (test mds_cleanup_orphans) ========================================================== 01:02:24 (1776920544) [ 1394.724134] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1395.932892] Lustre: Failing over lustre-MDT0000 [ 1396.100599] Lustre: server umount lustre-MDT0000 complete [ 1410.018951] LustreError: 59621:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1412.264432] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1414.830191] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1123 to 0x280000400:1153) [ 1414.830413] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1124 to 0x240000400:1153) [ 1416.572031] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1417.308935] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1422.036846] Lustre: DEBUG MARKER: == replay-single test 22: open(O_CREAT), |X| unlink, replay, close (test mds_cleanup_orphans) ========================================================== 01:02:53 (1776920573) [ 1424.215322] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1425.330959] Lustre: Failing over lustre-MDT0000 [ 1425.518781] Lustre: server umount lustre-MDT0000 complete [ 1440.687511] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1155 to 0x240000400:1185) [ 1440.687511] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1155 to 0x280000400:1185) [ 1441.721288] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1445.817589] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1446.622424] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1451.466912] Lustre: DEBUG MARKER: == replay-single test 23: open(O_CREAT), |X| unlink touch new, replay, close (test mds_cleanup_orphans) ========================================================== 01:03:23 (1776920603) [ 1453.395352] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1454.401966] Lustre: Failing over lustre-MDT0000 [ 1454.607053] Lustre: server umount lustre-MDT0000 complete [ 1469.823315] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1471.341089] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1187 to 0x240000400:1217) [ 1471.341177] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1187 to 0x280000400:1217) [ 1473.156862] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1473.750569] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1477.643806] Lustre: DEBUG MARKER: == replay-single test 24: open(O_CREAT), replay, unlink, close (test mds_cleanup_orphans) ========================================================== 01:03:49 (1776920629) [ 1479.312873] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1480.036526] Lustre: Failing over lustre-MDT0000 [ 1480.285272] Lustre: server umount lustre-MDT0000 complete [ 1495.458558] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1496.961749] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1219 to 0x240000400:1249) [ 1496.962250] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1219 to 0x280000400:1249) [ 1499.323727] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1500.027803] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1503.791267] Lustre: DEBUG MARKER: == replay-single test 25: open(O_CREAT), unlink, replay, close (test mds_cleanup_orphans) ========================================================== 01:04:15 (1776920655) [ 1505.329407] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1506.115144] Lustre: Failing over lustre-MDT0000 [ 1506.242711] Lustre: server umount lustre-MDT0000 complete [ 1519.616864] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1519.620196] Lustre: Skipped 15 previous similar messages [ 1521.315969] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1522.541816] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1251 to 0x240000400:1281) [ 1522.542038] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1219 to 0x280000400:1281) [ 1525.020755] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1525.752961] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1529.792234] Lustre: DEBUG MARKER: == replay-single test 26: |X| open(O_CREAT), unlink two, close one, replay, close one (test mds_cleanup_orphans) ========================================================== 01:04:41 (1776920681) [ 1531.290436] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1532.238067] Lustre: Failing over lustre-MDT0000 [ 1532.419415] Lustre: server umount lustre-MDT0000 complete [ 1547.054550] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1548.144962] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1283 to 0x240000400:1313) [ 1548.145162] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1283 to 0x280000400:1313) [ 1550.283691] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1550.839918] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1554.522785] Lustre: DEBUG MARKER: == replay-single test 27: |X| open(O_CREAT), unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 01:05:06 (1776920706) [ 1555.970902] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1556.764122] Lustre: Failing over lustre-MDT0000 [ 1557.011133] Lustre: server umount lustre-MDT0000 complete [ 1571.256143] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1573.479646] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1315 to 0x280000400:1345) [ 1573.479805] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1315 to 0x240000400:1345) [ 1574.849666] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1575.500549] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1579.285884] Lustre: DEBUG MARKER: == replay-single test 28: open(O_CREAT), |X| unlink two, close one, replay, close one (test mds_cleanup_orphans) ========================================================== 01:05:31 (1776920731) [ 1580.837574] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1581.596478] Lustre: Failing over lustre-MDT0000 [ 1581.764906] Lustre: server umount lustre-MDT0000 complete [ 1595.919858] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1597.996133] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1347 to 0x240000400:1377) [ 1597.996478] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1347 to 0x280000400:1377) [ 1599.321473] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1599.944779] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1600.671148] Lustre: 3296:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776920737/real 1776920737] req@ffff9e8928c2d500 x1863234872782592/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1776920753 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1600.682018] Lustre: 3296:0:(client.c:2479:ptlrpc_expire_one_request()) Skipped 85 previous similar messages [ 1603.653142] Lustre: DEBUG MARKER: == replay-single test 29: open(O_CREAT), |X| unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 01:05:55 (1776920755) [ 1605.183440] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1606.006067] Lustre: Failing over lustre-MDT0000 [ 1606.210175] Lustre: server umount lustre-MDT0000 complete [ 1619.825104] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1379 to 0x280000400:1409) [ 1619.827369] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1379 to 0x240000400:1409) [ 1620.467754] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1623.910155] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1624.508818] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1627.899522] Lustre: DEBUG MARKER: == replay-single test 30: open(O_CREAT) two, unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 01:06:19 (1776920779) [ 1629.176733] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1629.864306] Lustre: Failing over lustre-MDT0000 [ 1630.008122] Lustre: lustre-MDT0000: Not available for connect from 192.168.203.50@tcp (stopping) [ 1630.041455] Lustre: server umount lustre-MDT0000 complete [ 1642.410730] 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 [ 1642.416682] Lustre: Skipped 36 previous similar messages [ 1643.776704] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1647.585397] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 1647.590176] Lustre: Skipped 35 previous similar messages [ 1650.487168] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1650.490474] Lustre: Skipped 17 previous similar messages [ 1650.510575] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1650.514378] Lustre: Skipped 17 previous similar messages [ 1650.528072] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1411 to 0x240000400:1441) [ 1650.528072] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1411 to 0x280000400:1441) [ 1651.719521] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1652.324662] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1655.780711] Lustre: DEBUG MARKER: == replay-single test 31: open(O_CREAT) two, unlink one, |X| unlink one, close two (test mds_cleanup_orphans) ========================================================== 01:06:47 (1776920807) [ 1656.936631] LustreError: 73274:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 1656.940688] LustreError: 73274:0:(osd_handler.c:720:osd_ro()) Skipped 16 previous similar messages [ 1657.286045] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1658.019639] Lustre: Failing over lustre-MDT0000 [ 1658.174946] Lustre: lustre-MDT0000: Not available for connect from 192.168.203.50@tcp (stopping) [ 1658.233229] Lustre: server umount lustre-MDT0000 complete [ 1670.881216] LustreError: MGC192.168.203.150@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1670.884864] LustreError: Skipped 17 previous similar messages [ 1672.459928] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1676.132362] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1443 to 0x280000400:1473) [ 1676.132362] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1443 to 0x240000400:1473) [ 1677.328163] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1677.921369] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1681.670111] Lustre: DEBUG MARKER: == replay-single test 32: close() notices client eviction; close() after client eviction ========================================================== 01:07:13 (1776920833) [ 1682.031638] Lustre: 74600:0:(genops.c:1793:obd_export_evict_by_uuid()) lustre-MDT0000: evicting fad0afe6-b350-498f-8db0-9a178a7cb52d at adminstrative request [ 1686.787509] Lustre: DEBUG MARKER: == replay-single test 33a: fid seq shouldn't be reused after abort recovery ========================================================== 01:07:18 (1776920838) [ 1688.054083] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1688.765171] Lustre: Failing over lustre-MDT0000 [ 1688.972233] Lustre: server umount lustre-MDT0000 complete [ 1691.616867] LustreError: 75472:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1691.629890] LustreError: 75472:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 2 previous similar messages [ 1691.778306] Lustre: lustre-MDT0000: Aborting client recovery [ 1691.780271] LustreError: 75461:0:(ldlm_lib.c:2984:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 1691.783560] Lustre: 75511:0:(ldlm_lib.c:2387:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 1691.786789] Lustre: 75511:0:(genops.c:1620:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client fad0afe6-b350-498f-8db0-9a178a7cb52d@ [ 1691.791582] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 1691.806649] Lustre: lustre-MDT0000-osd: cancel update llog [0x200000400:0x1:0x0] [ 1691.860348] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1479 to 0x280000400:1505) [ 1691.860396] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1480 to 0x240000400:1505) [ 1693.226856] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1699.243279] Lustre: DEBUG MARKER: == replay-single test 33b: test fid seq allocation ======= 01:07:31 (1776920851) [ 1700.752681] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1701.465744] Lustre: Failing over lustre-MDT0000 [ 1701.650621] Lustre: server umount lustre-MDT0000 complete [ 1704.911821] Lustre: *** cfs_fail_loc=1311, val=0*** [ 1704.928710] Lustre: lustre-MDT0000: Aborting client recovery [ 1704.930876] LustreError: 76751:0:(ldlm_lib.c:2984:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 1704.934733] Lustre: 76801:0:(ldlm_lib.c:2387:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 1704.940696] Lustre: 76801:0:(ldlm_lib.c:2387:target_recovery_overseer()) Skipped 2 previous similar messages [ 1704.944039] Lustre: 76801:0:(genops.c:1620:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client fad0afe6-b350-498f-8db0-9a178a7cb52d@ [ 1704.950828] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 1704.974911] Lustre: lustre-MDT0000-osd: cancel update llog [0x200015bc0:0x1:0x0] [ 1705.017651] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1516 to 0x280000400:1537) [ 1705.017773] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1516 to 0x240000400:1537) [ 1706.422840] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1709.825162] Lustre: *** cfs_fail_loc=1311, val=0*** [ 1712.383172] Lustre: DEBUG MARKER: == replay-single test 34: abort recovery before client does replay (test mds_cleanup_orphans) ========================================================== 01:07:44 (1776920864) [ 1713.941955] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1714.591099] Lustre: Failing over lustre-MDT0000 [ 1714.684901] Lustre: server umount lustre-MDT0000 complete [ 1717.712695] Lustre: lustre-MDT0000: Aborting client recovery [ 1717.715097] LustreError: 78047:0:(ldlm_lib.c:2984:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 1717.719054] Lustre: 78096:0:(ldlm_lib.c:2387:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 1717.722878] Lustre: 78096:0:(ldlm_lib.c:2387:target_recovery_overseer()) Skipped 2 previous similar messages [ 1717.726252] Lustre: 78096:0:(genops.c:1620:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client fad0afe6-b350-498f-8db0-9a178a7cb52d@ [ 1717.730261] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 1717.747461] Lustre: lustre-MDT0000-osd: cancel update llog [0x200016778:0x1:0x0] [ 1717.799708] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1544 to 0x280000400:1569) [ 1717.799830] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1543 to 0x240000400:1569) [ 1719.239140] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1724.940102] Lustre: DEBUG MARKER: == replay-single test 35: test recovery from llog for unlink op ========================================================== 01:07:56 (1776920876) [ 1725.341925] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 1725.343968] LustreError: 78057:0:(ldlm_lib.c:3326:target_send_reply_msg()) @@@ dropping reply req@ffff9e89274b5c00 x1863234863705472/t201863462916(0) o36->fad0afe6-b350-498f-8db0-9a178a7cb52d@192.168.203.50@tcp:453/0 lens 512/456 e 0 to 0 dl 1776920888 ref 1 fl Interpret:/200/0 rc 0/0 job:'rm.0' uid:0 gid:0 projid:4294967295 [ 1728.052961] Lustre: Failing over lustre-MDT0000 [ 1728.221289] Lustre: server umount lustre-MDT0000 complete [ 1730.931080] Lustre: lustre-MDT0000: Aborting client recovery [ 1730.932974] LustreError: 79195:0:(ldlm_lib.c:2984:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 1730.935922] Lustre: 79244:0:(ldlm_lib.c:2387:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 1730.940408] Lustre: 79244:0:(ldlm_lib.c:2387:target_recovery_overseer()) Skipped 2 previous similar messages [ 1730.944547] Lustre: 79244:0:(genops.c:1620:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client fad0afe6-b350-498f-8db0-9a178a7cb52d@ [ 1730.949495] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 1730.964052] Lustre: lustre-MDT0000-osd: cancel update llog [0x200017330:0x1:0x0] [ 1731.002666] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1543 to 0x240000400:1601) [ 1731.002747] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1571 to 0x280000400:1601) [ 1732.310661] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1737.778684] Lustre: DEBUG MARKER: SKIP: replay-single test_36 skipping ALWAYS excluded test 36 [ 1738.359135] Lustre: DEBUG MARKER: == replay-single test 37: abort recovery before client does replay (test mds_cleanup_orphans for directories) ========================================================== 01:08:10 (1776920890) [ 1739.872558] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1740.942087] Lustre: Failing over lustre-MDT0000 [ 1741.165866] Lustre: server umount lustre-MDT0000 complete [ 1743.949100] Lustre: lustre-MDT0000: Aborting client recovery [ 1743.951135] LustreError: 80595:0:(ldlm_lib.c:2984:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 1743.954186] Lustre: 80644:0:(ldlm_lib.c:2387:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 1743.958108] Lustre: 80644:0:(ldlm_lib.c:2387:target_recovery_overseer()) Skipped 2 previous similar messages [ 1743.961507] Lustre: 80644:0:(genops.c:1620:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client fad0afe6-b350-498f-8db0-9a178a7cb52d@ [ 1743.966276] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 1743.983105] Lustre: lustre-MDT0000-osd: cancel update llog [0x200017b00:0x1:0x0] [ 1744.023812] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1543 to 0x240000400:1633) [ 1744.023936] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1571 to 0x280000400:1633) [ 1745.362550] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1751.315904] Lustre: DEBUG MARKER: == replay-single test 38: test recovery from unlink llog (test llog_gen_rec) ========================================================== 01:08:23 (1776920903) [ 1761.348705] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1761.997048] Lustre: Failing over lustre-MDT0000 [ 1762.268553] Lustre: server umount lustre-MDT0000 complete [ 1776.149105] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1778.096185] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2034 to 0x240000400:2049) [ 1778.096408] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2034 to 0x280000400:2049) [ 1779.321793] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1779.873945] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1788.233250] Lustre: DEBUG MARKER: == replay-single test 39: test recovery from unlink llog (test llog_gen_rec) ========================================================== 01:09:00 (1776920940) [ 1792.960742] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1796.122334] Lustre: Failing over lustre-MDT0000 [ 1796.422560] Lustre: server umount lustre-MDT0000 complete [ 1810.018383] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2450 to 0x240000400:2465) [ 1810.018441] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2450 to 0x280000400:2465) [ 1810.393263] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1813.374200] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1813.864978] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1821.712215] Lustre: DEBUG MARKER: == replay-single test 41: read from a valid osc while other oscs are invalid ========================================================== 01:09:33 (1776920973) [ 1822.376877] Lustre: setting import lustre-OST0001_UUID INACTIVE by administrator request [ 1822.682638] Lustre: lustre-OST0001: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnecting [ 1822.685417] LustreError: lustre-OST0001-osc-MDT0000: This client was evicted by lustre-OST0001; in progress operations using this service will fail. [ 1824.563102] Lustre: DEBUG MARKER: == replay-single test 42: recovery after ost failure ===== 01:09:36 (1776920976) [ 1829.697623] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 1832.917134] Lustre: Failing over lustre-OST0000 [ 1832.963617] Lustre: server umount lustre-OST0000 complete [ 1834.810130] LustreError: 33773:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.203.50@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1834.976229] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 1839.928075] LustreError: 13994:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.203.50@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1839.933436] LustreError: 13994:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 1 previous similar message [ 1845.047689] LustreError: 33804:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.203.50@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1845.053244] LustreError: 33804:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 1 previous similar message [ 1847.056170] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1893.654700] Lustre: DEBUG MARKER: == replay-single test 43: mds osc import failure during recovery; don't LBUG ========================================================== 01:10:45 (1776921045) [ 1895.317703] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1896.380310] Lustre: Failing over lustre-MDT0000 [ 1896.415754] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1896.419506] Lustre: Skipped 1 previous similar message [ 1896.580436] Lustre: server umount lustre-MDT0000 complete [ 1912.623618] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1912.637099] Lustre: Skipped 30 previous similar messages [ 1916.540686] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1917.322798] Lustre: *** cfs_fail_loc=204, val=2147483648*** [ 1917.323292] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2866 to 0x280000400:2881) [ 1923.710567] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1925.014889] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1932.772163] LustreError: 87996:0:(osp_precreate.c:969:osp_precreate_cleanup_orphans()) lustre-OST0000-osc-MDT0000: cannot cleanup orphans: rc = -11 [ 1932.774357] Lustre: lustre-OST0000: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnecting [ 1933.792843] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2867 to 0x240000400:2913) [ 1942.614837] Lustre: DEBUG MARKER: == replay-single test 44a: race in target handle connect ========================================================== 01:11:33 (1776921093) [ 1946.034562] LustreError: 87974:0:(ldlm_lib.c:1165:target_handle_connect()) cfs_race id 701 sleeping [ 1951.199135] LustreError: 87974:0:(ldlm_lib.c:1165:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 1951.214254] Lustre: lustre-MDT0000: Client fad0afe6-b350-498f-8db0-9a178a7cb52d (at 192.168.203.50@tcp) reconnecting [ 1951.279927] LustreError: 33768:0:(ldlm_lib.c:1165:target_handle_connect()) cfs_fail_race id 701 waking [ 1953.668084] LustreError: 87973:0:(ldlm_lib.c:1165:target_handle_connect()) cfs_race id 701 sleeping [ 1958.879276] LustreError: 87973:0:(ldlm_lib.c:1165:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 1958.890680] Lustre: lustre-MDT0000: Client fad0afe6-b350-498f-8db0-9a178a7cb52d (at 192.168.203.50@tcp) reconnecting [ 1960.909511] LustreError: 87972:0:(ldlm_lib.c:1165:target_handle_connect()) cfs_race id 701 sleeping [ 1966.047415] LustreError: 87972:0:(ldlm_lib.c:1165:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 1966.055517] Lustre: lustre-MDT0000: Client fad0afe6-b350-498f-8db0-9a178a7cb52d (at 192.168.203.50@tcp) reconnecting [ 1967.339125] LustreError: 88350:0:(ldlm_lib.c:1165:target_handle_connect()) cfs_race id 701 sleeping [ 1972.703138] LustreError: 88350:0:(ldlm_lib.c:1165:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 1973.721199] LustreError: 87974:0:(ldlm_lib.c:1165:target_handle_connect()) cfs_race id 701 sleeping [ 1978.847269] LustreError: 87974:0:(ldlm_lib.c:1165:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 1978.852860] Lustre: lustre-MDT0000: Client fad0afe6-b350-498f-8db0-9a178a7cb52d (at 192.168.203.50@tcp) reconnecting [ 1978.860267] Lustre: Skipped 1 previous similar message [ 1986.724469] LustreError: 87974:0:(ldlm_lib.c:1165:target_handle_connect()) cfs_race id 701 sleeping [ 1986.736165] LustreError: 87974:0:(ldlm_lib.c:1165:target_handle_connect()) Skipped 1 previous similar message [ 1992.159146] LustreError: 87974:0:(ldlm_lib.c:1165:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 1992.166794] LustreError: 87974:0:(ldlm_lib.c:1165:target_handle_connect()) Skipped 1 previous similar message [ 1998.304526] Lustre: lustre-MDT0000: Client fad0afe6-b350-498f-8db0-9a178a7cb52d (at 192.168.203.50@tcp) reconnecting [ 1998.311460] Lustre: Skipped 2 previous similar messages [ 2005.832455] LustreError: 87973:0:(ldlm_lib.c:1165:target_handle_connect()) cfs_race id 701 sleeping [ 2005.837492] LustreError: 87973:0:(ldlm_lib.c:1165:target_handle_connect()) Skipped 2 previous similar messages [ 2011.104437] LustreError: 87973:0:(ldlm_lib.c:1165:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 2011.111109] LustreError: 87973:0:(ldlm_lib.c:1165:target_handle_connect()) Skipped 2 previous similar messages [ 2016.331958] Lustre: DEBUG MARKER: == replay-single test 44b: race in target handle connect ========================================================== 01:12:47 (1776921167) [ 2017.506837] LustreError: 87973:0:(ldlm_lib.c:1419:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 2027.833220] Lustre: lustre-MDT0000: Export ffff9e890867a000 already connecting from 192.168.203.50@tcp [ 2032.954063] Lustre: lustre-MDT0000: Export ffff9e890867a000 already connecting from 192.168.203.50@tcp [ 2038.072955] Lustre: lustre-MDT0000: Export ffff9e890867a000 already connecting from 192.168.203.50@tcp [ 2043.193130] Lustre: lustre-MDT0000: Export ffff9e890867a000 already connecting from 192.168.203.50@tcp [ 2043.198067] Lustre: Skipped 1 previous similar message [ 2048.314442] Lustre: lustre-MDT0000: Export ffff9e890867a000 already connecting from 192.168.203.50@tcp [ 2057.607132] LustreError: 87973:0:(ldlm_lib.c:1419:target_handle_connect()) cfs_fail_timeout id 704 awake [ 2057.613404] Lustre: 87973:0:(service.c:2561:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/20s); client may timeout req@ffff9e8911245180 x1863234866323840/t0(0) o38->fad0afe6-b350-498f-8db0-9a178a7cb52d@192.168.203.50@tcp:0/0 lens 520/416 e 0 to 0 dl 1776921190 ref 1 fl Complete:H/200/0 rc 0/0 job:'lctl.0' uid:0 gid:0 projid:4294967295 [ 2058.554216] Lustre: lustre-MDT0000: Client fad0afe6-b350-498f-8db0-9a178a7cb52d (at 192.168.203.50@tcp) reconnecting [ 2058.559622] Lustre: Skipped 3 previous similar messages [ 2058.564161] LustreError: 87972:0:(ldlm_lib.c:1419:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 2084.151839] Lustre: lustre-MDT0000: Export ffff9e890867a000 already connecting from 192.168.203.50@tcp [ 2084.156137] Lustre: Skipped 1 previous similar message [ 2098.631134] LustreError: 87972:0:(ldlm_lib.c:1419:target_handle_connect()) cfs_fail_timeout id 704 awake [ 2098.638798] Lustre: 87972:0:(service.c:2561:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/20s); client may timeout req@ffff9e8803960a80 x1863234866327168/t0(0) o38->fad0afe6-b350-498f-8db0-9a178a7cb52d@192.168.203.50@tcp:0/0 lens 520/416 e 0 to 0 dl 1776921231 ref 1 fl Complete:H/200/0 rc 0/0 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2099.513059] LustreError: 90279:0:(ldlm_lib.c:1419:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 2125.114170] Lustre: lustre-MDT0000: Export ffff9e890867a000 already connecting from 192.168.203.50@tcp [ 2125.127267] Lustre: Skipped 2 previous similar messages [ 2139.575134] LustreError: 90279:0:(ldlm_lib.c:1419:target_handle_connect()) cfs_fail_timeout id 704 awake [ 2139.579926] Lustre: 90279:0:(service.c:2561:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/20s); client may timeout req@ffff9e8936cace00 x1863234866328960/t0(0) o38->fad0afe6-b350-498f-8db0-9a178a7cb52d@192.168.203.50@tcp:0/0 lens 520/416 e 0 to 0 dl 1776921272 ref 1 fl Complete:H/200/0 rc 0/0 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2140.473665] Lustre: lustre-MDT0000: Client fad0afe6-b350-498f-8db0-9a178a7cb52d (at 192.168.203.50@tcp) reconnecting [ 2140.479670] Lustre: Skipped 1 previous similar message [ 2140.483192] LustreError: 87973:0:(ldlm_lib.c:1419:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 2165.051307] Lustre: lustre-MDT0000: Export ffff9e890867a000 already connecting from 192.168.203.50@tcp [ 2165.062369] Lustre: Skipped 3 previous similar messages [ 2180.495115] LustreError: 87973:0:(ldlm_lib.c:1419:target_handle_connect()) cfs_fail_timeout id 704 awake [ 2180.500033] Lustre: 87973:0:(service.c:2561:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/21s); client may timeout req@ffff9e8940c6d500 x1863234866330880/t0(0) o38->fad0afe6-b350-498f-8db0-9a178a7cb52d@192.168.203.50@tcp:0/0 lens 520/416 e 0 to 0 dl 1776921312 ref 1 fl Complete:H/200/0 rc 0/0 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2185.527678] LustreError: 88350:0:(ldlm_lib.c:1419:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 2225.599774] LustreError: 88350:0:(ldlm_lib.c:1419:target_handle_connect()) cfs_fail_timeout id 704 awake [ 2225.608864] Lustre: 88350:0:(service.c:2561:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/20s); client may timeout req@ffff9e8936cb0a80 x1863234866333056/t0(0) o38->fad0afe6-b350-498f-8db0-9a178a7cb52d@192.168.203.50@tcp:0/0 lens 520/416 e 0 to 0 dl 1776921358 ref 1 fl Complete:H/200/0 rc 0/0 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2226.487869] LustreError: 90279:0:(ldlm_lib.c:1419:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 2235.562751] LustreError: 90279:0:(ldlm_lib.c:1419:target_handle_connect()) cfs_fail_timeout interrupted [ 2239.201796] Lustre: DEBUG MARKER: == replay-single test 44c: race in target handle connect ========================================================== 01:16:30 (1776921390) [ 2242.168413] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2245.644844] Lustre: Failing over lustre-MDT0000 [ 2245.861993] Lustre: server umount lustre-MDT0000 complete [ 2251.355542] Lustre: *** cfs_fail_loc=712, val=0*** [ 2251.356701] 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 [ 2251.360074] LustreError: 33769:0:(service.c:1390:ptlrpc_check_req()) @@@ Invalid replay without recovery req@ffff9e8906aa3100 x1863234873403904/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 [ 2251.368105] Lustre: Skipped 21 previous similar messages [ 2251.508371] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 2251.514959] Lustre: Skipped 15 previous similar messages [ 2251.579252] Lustre: lustre-MDT0000: Aborting client recovery [ 2251.582598] LustreError: 92350:0:(ldlm_lib.c:2984:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 2251.590461] Lustre: 92398:0:(ldlm_lib.c:2387:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 2251.598704] Lustre: 92398:0:(ldlm_lib.c:2387:target_recovery_overseer()) Skipped 2 previous similar messages [ 2251.603939] Lustre: 92398:0:(genops.c:1620:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client fad0afe6-b350-498f-8db0-9a178a7cb52d@ [ 2251.610486] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 2251.656880] Lustre: lustre-MDT0000-osd: cancel update llog [0x2000182d0:0x1:0x0] [ 2251.764534] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2866 to 0x280000400:2913) [ 2251.775160] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2867 to 0x240000400:2945) [ 2255.219888] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2256.876949] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 2256.885418] Lustre: Skipped 22 previous similar messages [ 2261.459568] Lustre: Failing over lustre-MDT0000 [ 2261.707641] Lustre: server umount lustre-MDT0000 complete [ 2277.338278] LustreError: MGC192.168.203.150@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2277.350255] LustreError: Skipped 9 previous similar messages [ 2277.355853] LustreError: 3295:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9e893bf5d880 x1863234873413248/t0(0) o250->MGC192.168.203.150@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 0 ref 1 fl Rpc:NQU/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2278.431232] Lustre: 3298:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776921414/real 1776921414] req@ffff9e8928b0dc00 x1863234873412224/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1776921430 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2278.454758] Lustre: 3298:0:(client.c:2479:ptlrpc_expire_one_request()) Skipped 31 previous similar messages [ 2278.963808] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 2278.970955] Lustre: Skipped 5 previous similar messages [ 2279.074104] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 2279.082432] Lustre: Skipped 5 previous similar messages [ 2279.115795] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2867 to 0x240000400:2977) [ 2279.116567] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2866 to 0x280000400:2945) [ 2281.624316] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2287.738425] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2288.821663] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2295.481275] Lustre: DEBUG MARKER: == replay-single test 45: Handle failed close ============ 01:17:26 (1776921446) [ 2295.603256] Lustre: lustre-MDT0000: Client fad0afe6-b350-498f-8db0-9a178a7cb52d (at 192.168.203.50@tcp) reconnecting [ 2295.610323] Lustre: Skipped 2 previous similar messages [ 2301.660812] Lustre: DEBUG MARKER: == replay-single test 46: Don't leak file handle after open resend (3325) ========================================================== 01:17:32 (1776921452) [ 2302.408632] Lustre: *** cfs_fail_loc=122, val=2147483648*** [ 2302.412217] LustreError: 93249:0:(ldlm_lib.c:3326:target_send_reply_msg()) @@@ dropping reply req@ffff9e8906aa1f80 x1863234866388352/t0(0) o700->fad0afe6-b350-498f-8db0-9a178a7cb52d@192.168.203.50@tcp:275/0 lens 264/248 e 0 to 0 dl 1776921465 ref 1 fl Interpret:/200/0 rc 0/0 job:'touch.0' uid:0 gid:0 projid:4294967295 [ 2319.519517] Lustre: Failing over lustre-MDT0000 [ 2319.765782] Lustre: server umount lustre-MDT0000 complete [ 2334.029649] LustreError: 94783:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.203.50@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 2336.164553] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2979 to 0x240000400:3009) [ 2336.168981] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2947 to 0x280000400:2977) [ 2336.444343] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2340.606642] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2341.453394] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2347.534499] Lustre: DEBUG MARKER: == replay-single test 47: MDS->OSC failure during precreate cleanup (2824) ========================================================== 01:18:19 (1776921499) [ 2348.990492] Lustre: Failing over lustre-OST0000 [ 2349.061801] Lustre: server umount lustre-OST0000 complete [ 2354.489354] LustreError: 33773:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.203.50@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 2354.503495] LustreError: 33773:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 2 previous similar messages [ 2367.715097] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2372.955564] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 2373.923665] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 2442.245223] Lustre: DEBUG MARKER: == replay-single test 48: MDS->OSC failure during precreate cleanup (2824) ========================================================== 01:19:53 (1776921593) [ 2444.251614] LustreError: 97021:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 2444.257187] LustreError: 97021:0:(osd_handler.c:720:osd_ro()) Skipped 9 previous similar messages [ 2444.823658] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2446.161815] Lustre: Failing over lustre-MDT0000 [ 2446.369323] Lustre: server umount lustre-MDT0000 complete [ 2462.326467] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2998 to 0x280000400:3041) [ 2462.328269] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3030 to 0x240000400:3073) [ 2463.388944] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2531.117618] Lustre: DEBUG MARKER: == replay-single test 50: Double OSC recovery, don't LASSERT (3812) ========================================================== 01:21:22 (1776921682) [ 2540.868309] Lustre: DEBUG MARKER: == replay-single test 52: time out lock replay (3764) ==== 01:21:32 (1776921692) [ 2542.503122] Lustre: Failing over lustre-MDT0000 [ 2542.722632] Lustre: server umount lustre-MDT0000 complete [ 2556.831763] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 2556.838107] Lustre: Skipped 7 previous similar messages [ 2558.854129] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2559.301918] Lustre: *** cfs_fail_loc=157, val=2147483648*** [ 2559.305054] LustreError: 99165:0:(ldlm_lib.c:3326:target_send_reply_msg()) @@@ dropping reply req@ffff9e8805e53800 x1863234866501888/t0(0) o101->fad0afe6-b350-498f-8db0-9a178a7cb52d@192.168.203.50@tcp:532/0 lens 328/344 e 0 to 0 dl 1776921722 ref 1 fl Complete:/240/0 rc 0/0 job:'ldlm_lock_repla.0' uid:0 gid:0 projid:4294967295 [ 2574.648090] Lustre: lustre-MDT0000: Client fad0afe6-b350-498f-8db0-9a178a7cb52d (at 192.168.203.50@tcp) reconnected, waiting for 1 clients in recovery for 1:24 [ 2574.701631] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3084 to 0x240000400:3105) [ 2574.701647] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3053 to 0x280000400:3073) [ 2576.694888] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2577.478377] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2582.452494] Lustre: DEBUG MARKER: == replay-single test 53a: |X| close request while two MDC requests in flight ========================================================== 01:22:14 (1776921734) [ 2584.076399] Lustre: *** cfs_fail_loc=115, val=2147483648*** [ 2586.593290] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2587.587129] Lustre: Failing over lustre-MDT0000 [ 2587.617177] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2587.626245] Lustre: Skipped 1 previous similar message [ 2587.765420] Lustre: server umount lustre-MDT0000 complete [ 2603.481383] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2610.534452] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3053 to 0x280000400:3105) [ 2610.535191] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3107 to 0x240000400:3137) [ 2612.282312] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2613.157817] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2618.314583] Lustre: DEBUG MARKER: == replay-single test 53b: |X| open request while two MDC requests in flight ========================================================== 01:22:50 (1776921770) [ 2618.849438] Lustre: *** cfs_fail_loc=107, val=2147483648*** [ 2622.126429] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2623.013931] Lustre: Failing over lustre-MDT0000 [ 2623.164362] Lustre: server umount lustre-MDT0000 complete [ 2639.266396] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2645.361354] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3107 to 0x280000400:3137) [ 2645.361588] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3107 to 0x240000400:3169) [ 2647.148515] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2647.957432] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2652.864809] Lustre: DEBUG MARKER: == replay-single test 53c: |X| open request and close request while two MDC requests in flight ========================================================== 01:23:24 (1776921804) [ 2653.450500] Lustre: *** cfs_fail_loc=107, val=2147483648*** [ 2656.751743] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2657.747349] Lustre: Failing over lustre-MDT0000 [ 2657.760462] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2657.766666] Lustre: Skipped 1 previous similar message [ 2657.889050] Lustre: server umount lustre-MDT0000 complete [ 2673.853438] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2679.150162] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3107 to 0x280000400:3169) [ 2679.155865] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3171 to 0x240000400:3201) [ 2685.017715] Lustre: DEBUG MARKER: == replay-single test 53d: close reply while two MDC requests in flight ========================================================== 01:23:56 (1776921836) [ 2686.702209] Lustre: *** cfs_fail_loc=13b, val=315*** [ 2686.706457] Lustre: *** cfs_fail_loc=13b, val=2147483648*** [ 2686.708995] LustreError: 103764:0:(ldlm_lib.c:3326:target_send_reply_msg()) @@@ dropping reply req@ffff9e880270ca80 x1863234866545920/t257698037777(0) o35->fad0afe6-b350-498f-8db0-9a178a7cb52d@192.168.203.50@tcp:660/0 lens 392/456 e 0 to 0 dl 1776921850 ref 1 fl Interpret:/600/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 2688.254858] Lustre: Failing over lustre-MDT0000 [ 2688.480963] LustreError: 104303:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 2688.491848] LustreError: 104303:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 4 previous similar messages [ 2688.521180] Lustre: server umount lustre-MDT0000 complete [ 2703.225664] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3107 to 0x280000400:3201) [ 2703.226234] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3203 to 0x240000400:3233) [ 2703.236369] Lustre: 105004:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9e8928e0df80 x1863234866545920/t257698037777(0) o35->fad0afe6-b350-498f-8db0-9a178a7cb52d@192.168.203.50@tcp:676/0 lens 392/456 e 0 to 0 dl 1776921866 ref 1 fl Interpret:/602/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 2704.504939] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2708.676030] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2709.568828] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2714.399084] Lustre: DEBUG MARKER: == replay-single test 53e: |X| open reply while two MDC requests in flight ========================================================== 01:24:26 (1776921866) [ 2714.955525] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 2714.962381] LustreError: 105001:0:(ldlm_lib.c:3326:target_send_reply_msg()) @@@ dropping reply req@ffff9e89048a7b80 x1863234866558720/t261993005072(0) o36->fad0afe6-b350-498f-8db0-9a178a7cb52d@192.168.203.50@tcp:688/0 lens 504/448 e 0 to 0 dl 1776921878 ref 1 fl Interpret:/200/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 2718.305260] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2719.267421] Lustre: Failing over lustre-MDT0000 [ 2719.467356] Lustre: server umount lustre-MDT0000 complete [ 2736.169245] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2740.613696] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3203 to 0x280000400:3233) [ 2740.614057] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3203 to 0x240000400:3265) [ 2740.621970] Lustre: 106518:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9e8936cb1880 x1863234866558720/t261993005072(0) o36->fad0afe6-b350-498f-8db0-9a178a7cb52d@192.168.203.50@tcp:714/0 lens 504/2880 e 0 to 0 dl 1776921904 ref 1 fl Interpret:/202/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 2742.727565] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2743.633534] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2748.682785] Lustre: DEBUG MARKER: == replay-single test 53f: |X| open reply and close reply while two MDC requests in flight ========================================================== 01:25:00 (1776921900) [ 2749.254588] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 2749.257972] LustreError: 106520:0:(ldlm_lib.c:3326:target_send_reply_msg()) @@@ dropping reply req@ffff9e8928e0c000 x1863234866572032/t266287972368(0) o36->fad0afe6-b350-498f-8db0-9a178a7cb52d@192.168.203.50@tcp:722/0 lens 504/448 e 0 to 0 dl 1776921912 ref 1 fl Interpret:/200/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 2750.701707] Lustre: *** cfs_fail_loc=13b, val=315*** [ 2752.550826] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2753.507125] Lustre: Failing over lustre-MDT0000 [ 2753.664233] Lustre: server umount lustre-MDT0000 complete [ 2769.746359] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2774.850162] Lustre: 108051:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9e8927966680 x1863234866572288/t266287972369(0) o35->fad0afe6-b350-498f-8db0-9a178a7cb52d@192.168.203.50@tcp:748/0 lens 392/456 e 0 to 0 dl 1776921938 ref 1 fl Interpret:/602/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 2774.860685] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3203 to 0x240000400:3297) [ 2774.867660] Lustre: 108051:0:(mdt_recovery.c:102:mdt_req_from_lrd()) Skipped 1 previous similar message [ 2774.870400] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3235 to 0x280000400:3265) [ 2781.539218] Lustre: DEBUG MARKER: == replay-single test 53g: |X| drop open reply and close request while close and open are both in flight ========================================================== 01:25:33 (1776921933) [ 2782.171761] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 2782.174313] Lustre: Skipped 1 previous similar message [ 2782.177773] LustreError: 108497:0:(ldlm_lib.c:3326:target_send_reply_msg()) @@@ dropping reply req@ffff9e8805e53480 x1863234866584192/t270582939664(0) o36->fad0afe6-b350-498f-8db0-9a178a7cb52d@192.168.203.50@tcp:0/0 lens 504/448 e 0 to 0 dl 1776921945 ref 1 fl Interpret:/200/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 2782.197831] LustreError: 108497:0:(ldlm_lib.c:3326:target_send_reply_msg()) Skipped 1 previous similar message [ 2783.703372] Lustre: *** cfs_fail_loc=115, val=2147483648*** [ 2783.706564] Lustre: Skipped 1 previous similar message [ 2786.479280] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2787.690898] Lustre: Failing over lustre-MDT0000 [ 2787.846122] Lustre: server umount lustre-MDT0000 complete [ 2804.609303] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2807.677193] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3235 to 0x280000400:3297) [ 2807.678095] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3299 to 0x240000400:3329) [ 2807.681039] Lustre: 109525:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9e8936cb2300 x1863234866584192/t270582939664(0) o36->fad0afe6-b350-498f-8db0-9a178a7cb52d@192.168.203.50@tcp:26/0 lens 504/2880 e 0 to 0 dl 1776921971 ref 1 fl Interpret:/202/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 2812.834753] Lustre: DEBUG MARKER: == replay-single test 53h: open request and close reply while two MDC requests in flight ========================================================== 01:26:04 (1776921964) [ 2813.392140] Lustre: *** cfs_fail_loc=107, val=2147483648*** [ 2814.773667] Lustre: *** cfs_fail_loc=13b, val=315*** [ 2814.777479] LustreError: 109526:0:(ldlm_lib.c:3326:target_send_reply_msg()) @@@ dropping reply req@ffff9e8927787b80 x1863234866596224/t274877906960(0) o35->fad0afe6-b350-498f-8db0-9a178a7cb52d@192.168.203.50@tcp:33/0 lens 392/456 e 0 to 0 dl 1776921978 ref 1 fl Interpret:/600/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 2817.446132] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2818.269063] Lustre: Failing over lustre-MDT0000 [ 2818.412744] Lustre: server umount lustre-MDT0000 complete [ 2833.806781] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2838.880567] Lustre: 110901:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9e8936ba7800 x1863234866596224/t274877906960(0) o35->fad0afe6-b350-498f-8db0-9a178a7cb52d@192.168.203.50@tcp:57/0 lens 392/456 e 0 to 0 dl 1776922002 ref 1 fl Interpret:/602/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 2838.887979] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3331 to 0x240000400:3361) [ 2838.888264] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3235 to 0x280000400:3329) [ 2844.081402] Lustre: DEBUG MARKER: == replay-single test 55: let MDS_CHECK_RESENT return the original return code instead of 0 ========================================================== 01:26:35 (1776921995) [ 2844.497214] Lustre: *** cfs_fail_loc=12b, val=2147483991*** [ 2859.831528] Lustre: lustre-MDT0000: Client fad0afe6-b350-498f-8db0-9a178a7cb52d (at 192.168.203.50@tcp) reconnecting [ 2859.837280] Lustre: Skipped 4 previous similar messages [ 2859.849791] Lustre: 110899:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9e89274b7480 x1863234866606720/t279172874255(0) o101->fad0afe6-b350-498f-8db0-9a178a7cb52d@192.168.203.50@tcp:78/0 lens 664/3488 e 0 to 0 dl 1776922023 ref 1 fl Interpret:/602/0 rc 0/0 job:'touch.0' uid:0 gid:0 projid:0 [ 2862.967075] Lustre: DEBUG MARKER: == replay-single test 56: don't replay a symlink open request (3440) ========================================================== 01:26:54 (1776922014) [ 2864.634605] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2865.486853] Lustre: Failing over lustre-MDT0000 [ 2865.625633] Lustre: server umount lustre-MDT0000 complete [ 2879.403835] LustreError: MGC192.168.203.150@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2879.409557] LustreError: Skipped 11 previous similar messages [ 2879.570690] 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 [ 2879.581514] Lustre: Skipped 29 previous similar messages [ 2879.659253] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 2879.662327] Lustre: Skipped 13 previous similar messages [ 2880.322356] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 2880.327476] Lustre: Skipped 12 previous similar messages [ 2880.371842] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 2880.376044] Lustre: Skipped 12 previous similar messages [ 2880.396878] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3331 to 0x280000400:3361) [ 2880.401147] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3331 to 0x240000400:3393) [ 2881.670337] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2883.679148] Lustre: 3298:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776922020/real 1776922020] req@ffff9e8936ba5500 x1863234873627136/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1776922036 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2883.697531] Lustre: 3298:0:(client.c:2479:ptlrpc_expire_one_request()) Skipped 48 previous similar messages [ 2885.088865] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 2885.091951] Lustre: Skipped 28 previous similar messages [ 2885.542738] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2886.213885] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2900.583548] Lustre: DEBUG MARKER: == replay-single test 57: test recovery from llog for setattr op ========================================================== 01:27:32 (1776922052) [ 2902.848215] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2903.636413] Lustre: Failing over lustre-MDT0000 [ 2903.791191] Lustre: server umount lustre-MDT0000 complete [ 2919.553131] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2921.337786] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3363 to 0x280000400:3393) [ 2921.337843] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3331 to 0x240000400:3425) [ 2923.439429] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2924.190991] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2927.296496] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 2933.633935] Lustre: DEBUG MARKER: == replay-single test 58a: test recovery from llog for setattr op (test llog_gen_rec) ========================================================== 01:28:05 (1776922085) [ 2952.401927] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2953.331891] Lustre: Failing over lustre-MDT0000 [ 2953.758848] Lustre: server umount lustre-MDT0000 complete [ 2967.359863] LustreError: 116031:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.203.50@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 2968.961164] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:4676 to 0x240000400:4705) [ 2968.961294] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:4644 to 0x280000400:4673) [ 2969.257487] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2973.195835] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2973.956623] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2998.402357] Lustre: DEBUG MARKER: == replay-single test 58b: test replay of setxattr op ==== 01:29:10 (1776922150) [ 3000.459977] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3001.242684] Lustre: Failing over lustre-MDT0000 [ 3001.468922] Lustre: server umount lustre-MDT0000 complete [ 3016.579744] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3019.147765] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:4676 to 0x240000400:4737) [ 3019.147789] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:4675 to 0x280000400:4705) [ 3020.549350] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3021.260638] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3025.070550] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount FULL mgc.*.mgs_server_uuid [ 3025.789475] Lustre: DEBUG MARKER: mgc.*.mgs_server_uuid in FULL state after 0 sec [ 3028.483260] Lustre: DEBUG MARKER: == replay-single test 58c: resend/reconstruct setxattr op ========================================================== 01:29:40 (1776922180) [ 3034.251106] Lustre: *** cfs_fail_loc=123, val=2147483648*** [ 3050.870181] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 3050.872527] Lustre: Skipped 2 previous similar messages [ 3050.874637] LustreError: 117705:0:(ldlm_lib.c:3326:target_send_reply_msg()) @@@ dropping reply req@ffff9e891173b850 x1863234869377536/t296352743435(0) o36->fad0afe6-b350-498f-8db0-9a178a7cb52d@192.168.203.50@tcp:269/0 lens 66040/440 e 0 to 0 dl 1776922214 ref 1 fl Interpret:/600/0 rc 0/0 job:'setfattr.0' uid:0 gid:0 projid:0 [ 3050.885473] LustreError: 117705:0:(ldlm_lib.c:3326:target_send_reply_msg()) Skipped 1 previous similar message [ 3067.195204] Lustre: 117682:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9e893bea2680 x1863234869377536/t296352743435(0) o36->fad0afe6-b350-498f-8db0-9a178a7cb52d@192.168.203.50@tcp:285/0 lens 66040/440 e 0 to 0 dl 1776922230 ref 1 fl Interpret:/602/0 rc 0/0 job:'setfattr.0' uid:0 gid:0 projid:0 [ 3071.709333] Lustre: DEBUG MARKER: SKIP: replay-single test_59 skipping ALWAYS excluded test 59 [ 3072.490683] Lustre: DEBUG MARKER: == replay-single test 60: test llog post recovery init vs llog unlink ========================================================== 01:30:24 (1776922224) [ 3076.634208] LustreError: 119348:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 3076.639861] LustreError: 119348:0:(osd_handler.c:720:osd_ro()) Skipped 11 previous similar messages [ 3077.035464] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3078.334149] Lustre: Failing over lustre-MDT0000 [ 3078.478577] Lustre: server umount lustre-MDT0000 complete [ 3093.559160] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:4838 to 0x240000400:4865) [ 3093.559296] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:4807 to 0x280000400:4833) [ 3094.107158] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3098.251292] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3098.987711] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3104.267925] Lustre: DEBUG MARKER: == replay-single test 61a: test race llog recovery vs llog cleanup ========================================================== 01:30:55 (1776922255) [ 3114.259241] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 3120.340528] Lustre: Failing over lustre-OST0000 [ 3120.402061] Lustre: server umount lustre-OST0000 complete [ 3122.657456] LustreError: 33764:0:(ldlm_lib.c:1179: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. [ 3122.657970] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 3136.412086] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3148.393896] Lustre: Failing over lustre-OST0000 [ 3148.445832] Lustre: server umount lustre-OST0000 complete [ 3161.951428] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 3161.954631] Lustre: Skipped 14 previous similar messages [ 3165.021293] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3169.141120] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 3169.958973] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 3205.229927] Lustre: DEBUG MARKER: == replay-single test 61b: test race mds llog sync vs llog cleanup ========================================================== 01:32:37 (1776922357) [ 3206.666319] Lustre: Failing over lustre-MDT0000 [ 3206.898036] Lustre: server umount lustre-MDT0000 complete [ 3223.406455] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3225.997403] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5266 to 0x240000400:5281) [ 3225.997481] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5234 to 0x280000400:5249) [ 3235.494372] Lustre: Failing over lustre-MDT0000 [ 3235.635450] Lustre: server umount lustre-MDT0000 complete [ 3251.232923] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3251.585766] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5234 to 0x280000400:5281) [ 3251.586355] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5266 to 0x240000400:5313) [ 3255.427947] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3256.169679] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3260.812450] Lustre: DEBUG MARKER: == replay-single test 61c: test race mds llog sync vs llog cleanup ========================================================== 01:33:32 (1776922412) [ 3272.830251] Lustre: Failing over lustre-OST0000 [ 3272.879686] Lustre: server umount lustre-OST0000 complete [ 3275.232428] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 3288.787422] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3292.893027] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 3293.614413] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 3298.503508] Lustre: DEBUG MARKER: == replay-single test 61d: error in llog_setup should cleanup the llog context correctly ========================================================== 01:34:10 (1776922450) [ 3299.516509] Lustre: Failing over lustre-MDT0000 [ 3301.846488] Lustre: server umount lustre-MDT0000 complete [ 3306.366210] Lustre: *** cfs_fail_loc=605, val=0*** [ 3306.368275] LustreError: 127653:0:(llog_obd.c:190:llog_setup()) MGS: ctxt 0 lop_setup=ffffffffc1097680 failed: rc = -95 [ 3306.373053] LustreError: 127653:0:(obd_config.c:843:class_setup()) setup MGS failed (-95) [ 3306.375956] LustreError: 127653:0:(obd_mount.c:250:lustre_start_simple()) MGS setup error -95 [ 3306.379519] LustreError: 127653:0:(tgt_mount.c:114:server_deregister_mount()) MGS not registered [ 3306.385914] LustreError: Failed to start MGS 'MGS' (-95). Is the 'mgs' module loaded? [ 3306.392254] LustreError: 127653:0:(tgt_mount.c:2063:server_put_super()) no obd lustre-MDT0000 [ 3306.447099] Lustre: server umount lustre-MDT0000 complete [ 3306.448764] LustreError: 127653:0:(super25.c:184:lustre_fill_super()) llite: Unable to mount : rc = -95 [ 3311.736611] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3313.020846] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5283 to 0x280000400:5313) [ 3313.021066] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5315 to 0x240000400:5345) [ 3315.825166] Lustre: DEBUG MARKER: == replay-single test 62: don't mis-drop resent replay === 01:34:27 (1776922467) [ 3317.918862] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3319.677358] Lustre: Failing over lustre-MDT0000 [ 3319.776781] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 3319.896623] Lustre: server umount lustre-MDT0000 complete [ 3333.439764] Lustre: *** cfs_fail_loc=707, val=0*** [ 3334.834518] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3348.803486] Lustre: lustre-MDT0000: Client fad0afe6-b350-498f-8db0-9a178a7cb52d (at 192.168.203.50@tcp) reconnected, waiting for 1 clients in recovery for 0:54 [ 3349.025875] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5327 to 0x280000400:5345) [ 3349.030780] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5358 to 0x240000400:5377) [ 3350.688543] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3351.344907] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3355.816663] Lustre: DEBUG MARKER: == replay-single test 65a: AT: verify early replies ====== 01:35:07 (1776922507) [ 3380.383663] LustreError: 129228:0:(service.c:2537:ptlrpc_server_handle_request()) @@@ HIT req@ffff9e8911304000 x1863234870238336/t0(0) o101->fad0afe6-b350-498f-8db0-9a178a7cb52d@192.168.203.50@tcp:598/0 lens 664/0 e 0 to 0 dl 1776922543 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 3380.394484] LustreError: 129228:0:(service.c:2538:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a sleeping for 11000ms [ 3391.423210] LustreError: 129228:0:(service.c:2538:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a awake [ 3391.435598] LustreError: 129233:0:(service.c:2537:ptlrpc_server_handle_request()) @@@ HIT req@ffff9e8808bcdc00 x1863234870239104/t0(0) o35->fad0afe6-b350-498f-8db0-9a178a7cb52d@192.168.203.50@tcp:615/0 lens 392/0 e 0 to 0 dl 1776922560 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 3395.056276] LustreError: 33765:0:(service.c:2537:ptlrpc_server_handle_request()) @@@ HIT req@ffff9e8940648a80 x1863234874600576/t0(0) o6->lustre-MDT0000-mdtlov_UUID@0@lo:613/0 lens 544/0 e 0 to 0 dl 1776922558 ref 1 fl Interpret:/200/ffffffff rc 0/-1 job:'osp-syn-1-0.0' uid:0 gid:0 projid:4294967295 [ 3395.067582] LustreError: 33765:0:(service.c:2537:ptlrpc_server_handle_request()) Skipped 56 previous similar messages [ 3403.893585] Lustre: DEBUG MARKER: == replay-single test 65b: AT: verify early replies on packed reply / bulk ========================================================== 01:35:55 (1776922555) [ 3427.868367] LustreError: 6536:0:(tgt_handler.c:2787:tgt_brw_write()) cfs_fail_timeout id 224 sleeping for 11000ms [ 3438.895109] LustreError: 6536:0:(tgt_handler.c:2787:tgt_brw_write()) cfs_fail_timeout id 224 awake [ 3442.417905] Lustre: DEBUG MARKER: == replay-single test 66a: AT: verify MDT service time adjusts with no early replies ========================================================== 01:36:34 (1776922594) [ 3466.050604] LustreError: 129230:0:(service.c:2537:ptlrpc_server_handle_request()) @@@ HIT req@ffff9e8809ca9180 x1863234870259072/t0(0) o101->fad0afe6-b350-498f-8db0-9a178a7cb52d@192.168.203.50@tcp:684/0 lens 576/0 e 0 to 0 dl 1776922629 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 3466.060660] LustreError: 129230:0:(service.c:2538:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a sleeping for 5000ms [ 3471.159115] LustreError: 129230:0:(service.c:2538:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a awake [ 3471.165324] LustreError: 130407:0:(service.c:2537:ptlrpc_server_handle_request()) @@@ HIT req@ffff9e8805356300 x1863234870259584/t0(0) o101->fad0afe6-b350-498f-8db0-9a178a7cb52d@192.168.203.50@tcp:689/0 lens 664/0 e 0 to 0 dl 1776922634 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 3482.159127] LustreError: 129289:0:(service.c:2538:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a awake [ 3482.165339] LustreError: 129228:0:(service.c:2537:ptlrpc_server_handle_request()) @@@ HIT req@ffff9e8940648380 x1863234870281088/t0(0) o101->fad0afe6-b350-498f-8db0-9a178a7cb52d@192.168.203.50@tcp:740/0 lens 664/0 e 0 to 0 dl 1776922685 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 3482.176178] LustreError: 129228:0:(service.c:2537:ptlrpc_server_handle_request()) Skipped 119 previous similar messages [ 3494.512448] Lustre: DEBUG MARKER: == replay-single test 66b: AT: verify net latency adjusts ========================================================== 01:37:26 (1776922646) [ 3590.150222] Lustre: DEBUG MARKER: == replay-single test 67a: AT: verify slow request processing doesn't induce reconnects ========================================================== 01:39:02 (1776922742) [ 3613.167195] LustreError: 130407:0:(service.c:2537:ptlrpc_server_handle_request()) @@@ HIT req@ffff9e8940e75880 x1863234870333696/t0(0) o101->fad0afe6-b350-498f-8db0-9a178a7cb52d@192.168.203.50@tcp:76/0 lens 576/0 e 0 to 0 dl 1776922776 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 3613.175994] LustreError: 130407:0:(service.c:2537:ptlrpc_server_handle_request()) Skipped 98 previous similar messages [ 3613.180431] LustreError: 130407:0:(service.c:2538:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a sleeping for 400ms [ 3613.184415] LustreError: 130407:0:(service.c:2538:ptlrpc_server_handle_request()) Skipped 1 previous similar message [ 3613.607096] LustreError: 130407:0:(service.c:2538:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a awake [ 3629.424621] LustreError: 129228:0:(service.c:2538:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a sleeping for 400ms [ 3629.427675] LustreError: 129228:0:(service.c:2538:ptlrpc_server_handle_request()) Skipped 38 previous similar messages [ 3629.847098] LustreError: 129228:0:(service.c:2538:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a awake [ 3629.850024] LustreError: 129228:0:(service.c:2538:ptlrpc_server_handle_request()) Skipped 38 previous similar messages [ 3645.259910] LustreError: 129230:0:(service.c:2537:ptlrpc_server_handle_request()) @@@ HIT req@ffff9e8805354380 x1863234870352128/t0(0) o36->fad0afe6-b350-498f-8db0-9a178a7cb52d@192.168.203.50@tcp:108/0 lens 504/0 e 0 to 0 dl 1776922808 ref 1 fl Interpret:/200/ffffffff rc 0/-1 job:'unlinkmany.0' uid:0 gid:0 projid:4294967295 [ 3645.267955] LustreError: 129230:0:(service.c:2537:ptlrpc_server_handle_request()) Skipped 80 previous similar messages [ 3657.210421] Lustre: DEBUG MARKER: == replay-single test 67b: AT: verify instant slowdown doesn't induce reconnects ========================================================== 01:40:09 (1776922809) [ 3681.858844] Lustre: DEBUG MARKER: phase 2 [ 3685.015206] Lustre: DEBUG MARKER: == replay-single test 68: AT: verify slowing locks ======= 01:40:37 (1776922837) [ 3755.070937] Lustre: DEBUG MARKER: == replay-single test 70a: check multi client t-f ======== 01:41:47 (1776922907) [ 3755.554195] Lustre: DEBUG MARKER: SKIP: replay-single test_70a Need two or more clients, have 1 [ 3756.124760] Lustre: DEBUG MARKER: == replay-single test 70b: dbench 1mdts recovery; 1 clients ========================================================== 01:41:48 (1776922908) [ 3757.887663] Lustre: DEBUG MARKER: Started rundbench load pid=126727 ... [ 3759.990041] LustreError: 135908:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 3759.992599] LustreError: 135908:0:(osd_handler.c:720:osd_ro()) Skipped 2 previous similar messages [ 3760.327959] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3761.881660] Lustre: DEBUG MARKER: test_70b fail mds1 1 times [ 3762.549216] Lustre: Failing over lustre-MDT0000 [ 3762.562840] Lustre: lustre-MDT0000: Not available for connect from 192.168.203.50@tcp (stopping) [ 3762.565233] Lustre: Skipped 1 previous similar message [ 3762.750310] Lustre: server umount lustre-MDT0000 complete [ 3775.094687] LustreError: MGC192.168.203.150@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3775.099217] LustreError: Skipped 8 previous similar messages [ 3775.194455] 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 [ 3775.201760] Lustre: Skipped 20 previous similar messages [ 3775.241035] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3775.243185] Lustre: Skipped 11 previous similar messages [ 3775.264278] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 3775.267243] Lustre: Skipped 5 previous similar messages [ 3776.496159] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3778.871217] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 3778.874310] Lustre: Skipped 11 previous similar messages [ 3779.055341] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 3779.059310] Lustre: Skipped 11 previous similar messages [ 3779.074857] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5500 to 0x240000400:5537) [ 3779.075060] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5447 to 0x280000400:5473) [ 3780.276141] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3780.577639] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 3780.579712] Lustre: Skipped 20 previous similar messages [ 3780.808279] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3781.088087] Lustre: 3298:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776922917/real 1776922917] req@ffff9e8937971180 x1863234874772608/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1776922933 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3781.098393] Lustre: 3298:0:(client.c:2479:ptlrpc_expire_one_request()) Skipped 40 previous similar messages [ 3784.674676] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3786.247239] Lustre: DEBUG MARKER: test_70b fail mds1 2 times [ 3786.963139] Lustre: Failing over lustre-MDT0000 [ 3787.174461] Lustre: server umount lustre-MDT0000 complete [ 3801.375991] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3804.694901] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5602 to 0x240000400:5633) [ 3804.694991] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5538 to 0x280000400:5569) [ 3805.922632] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3806.543286] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3810.331648] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3811.918779] Lustre: DEBUG MARKER: test_70b fail mds1 3 times [ 3812.630080] Lustre: Failing over lustre-MDT0000 [ 3812.804508] Lustre: server umount lustre-MDT0000 complete [ 3826.869572] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3830.331319] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5627 to 0x280000400:5665) [ 3830.331327] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5691 to 0x240000400:5729) [ 3831.654663] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3832.259072] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3836.045451] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3837.581605] Lustre: DEBUG MARKER: test_70b fail mds1 4 times [ 3838.294514] Lustre: Failing over lustre-MDT0000 [ 3838.469778] Lustre: server umount lustre-MDT0000 complete [ 3852.576955] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3854.867492] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5791 to 0x240000400:5825) [ 3854.867557] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5726 to 0x280000400:5761) [ 3856.121702] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3856.699692] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3860.569237] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3862.117661] Lustre: DEBUG MARKER: test_70b fail mds1 5 times [ 3862.783091] Lustre: Failing over lustre-MDT0000 [ 3863.033183] Lustre: server umount lustre-MDT0000 complete [ 3876.942393] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3880.425409] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5822 to 0x280000400:5857) [ 3880.425409] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5885 to 0x240000400:5921) [ 3881.618802] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3882.266342] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3903.730943] Lustre: DEBUG MARKER: == replay-single test 70c: tar 1mdts recovery ============ 01:44:15 (1776923055) [ 4025.628283] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4036.433670] Lustre: DEBUG MARKER: test_70c fail mds1 1 times [ 4037.103710] Lustre: Failing over lustre-MDT0000 [ 4037.140751] LustreError: 3297:0:(client.c:1380:ptlrpc_import_delay_req()) @@@ IMP_CLOSED req@ffff9e893af9ed80 x1863234877413376/t0(0) o6->lustre-OST0000-osc-MDT0000@0@lo:28/4 lens 544/432 e 0 to 0 dl 0 ref 1 fl Rpc:QU/200/ffffffff rc 0/-1 job:'osp-syn-0-0.0' uid:0 gid:0 projid:4294967295 [ 4037.341584] Lustre: server umount lustre-MDT0000 complete [ 4051.143955] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4058.100715] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:8576 to 0x240000400:8609) [ 4058.100727] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:8511 to 0x280000400:8545) [ 4059.248684] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4059.772764] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4182.646424] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4193.425727] Lustre: DEBUG MARKER: test_70c fail mds1 2 times [ 4194.042586] Lustre: Failing over lustre-MDT0000 [ 4194.239647] Lustre: lustre-MDT0000: Not available for connect from 192.168.203.50@tcp (stopping) [ 4194.278298] Lustre: server umount lustre-MDT0000 complete [ 4208.086147] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4218.020413] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:11484 to 0x240000400:11521) [ 4218.021960] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:11420 to 0x280000400:11457) [ 4219.215479] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4219.786728] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4236.416209] Lustre: DEBUG MARKER: == replay-single test 70d: mkdir/rmdir striped dir 1mdts recovery ========================================================== 01:49:48 (1776923388) [ 4236.903434] Lustre: DEBUG MARKER: SKIP: replay-single test_70d needs >= 2 MDTs [ 4237.483745] Lustre: DEBUG MARKER: == replay-single test 70e: rename cross-MDT with random fails ========================================================== 01:49:49 (1776923389) [ 4237.987506] Lustre: DEBUG MARKER: SKIP: replay-single test_70e needs >= 2 MDTs [ 4238.545305] Lustre: DEBUG MARKER: == replay-single test 70f: OSS O_DIRECT recovery with 1 clients ========================================================== 01:49:50 (1776923390) [ 4243.251567] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 4244.709305] Lustre: DEBUG MARKER: test_70f failing OST 1 times [ 4245.324041] Lustre: Failing over lustre-OST0000 [ 4245.358741] Lustre: server umount lustre-OST0000 complete [ 4248.031975] LustreError: 33764:0:(ldlm_lib.c:1179: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.039669] LustreError: 33764:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 15 previous similar messages [ 4259.332623] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4262.516925] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 4263.119240] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4270.665757] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 4272.149545] Lustre: DEBUG MARKER: test_70f failing OST 2 times [ 4272.754766] Lustre: Failing over lustre-OST0000 [ 4272.778058] Lustre: server umount lustre-OST0000 complete [ 4283.359536] LustreError: 33770:0:(ldlm_lib.c:1179: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. [ 4283.363985] LustreError: 33770:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 7 previous similar messages [ 4286.744387] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4289.866749] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 4290.434966] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4297.998964] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 4299.505907] Lustre: DEBUG MARKER: test_70f failing OST 3 times [ 4300.084957] Lustre: Failing over lustre-OST0000 [ 4300.088838] Lustre: lustre-OST0000: Not available for connect from 192.168.203.50@tcp (stopping) [ 4300.104118] Lustre: server umount lustre-OST0000 complete [ 4314.300968] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4317.545701] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 4318.121329] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4323.474223] Lustre: DEBUG MARKER: == replay-single test 71a: mkdir/rmdir striped dir with 2 mdts recovery ========================================================== 01:51:15 (1776923475) [ 4323.956830] Lustre: DEBUG MARKER: SKIP: replay-single test_71a needs >= 2 MDTs [ 4324.481533] Lustre: DEBUG MARKER: == replay-single test 73a: open(O_CREAT), unlink, replay, reconnect before open replay, close ========================================================== 01:51:16 (1776923476) [ 4325.771108] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4326.678970] Lustre: Failing over lustre-MDT0000 [ 4326.770887] Lustre: server umount lustre-MDT0000 complete [ 4340.662306] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4341.049376] Lustre: *** cfs_fail_loc=302, val=2147483648*** [ 4357.438747] Lustre: lustre-MDT0000: Client fad0afe6-b350-498f-8db0-9a178a7cb52d (at 192.168.203.50@tcp) reconnected, waiting for 1 clients in recovery for 0:54 [ 4357.474089] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:11725 to 0x240000400:11745) [ 4357.474327] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:11661 to 0x280000400:11681) [ 4358.839364] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4359.410780] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4362.724865] Lustre: DEBUG MARKER: == replay-single test 73b: open(O_CREAT), unlink, replay, reconnect at open_replay reply, close ========================================================== 01:51:54 (1776923514) [ 4363.701365] LustreError: 151678:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 4363.705113] LustreError: 151678:0:(osd_handler.c:720:osd_ro()) Skipped 10 previous similar messages [ 4364.030322] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4364.984047] Lustre: Failing over lustre-MDT0000 [ 4365.173481] Lustre: server umount lustre-MDT0000 complete [ 4377.424926] LustreError: MGC192.168.203.150@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4377.428730] LustreError: Skipped 7 previous similar messages [ 4377.516585] 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 [ 4377.522727] Lustre: Skipped 18 previous similar messages [ 4377.559153] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4377.561671] Lustre: Skipped 10 previous similar messages [ 4377.584715] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4377.587427] Lustre: Skipped 10 previous similar messages [ 4378.823381] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4380.781892] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4380.784992] Lustre: Skipped 10 previous similar messages [ 4380.796236] Lustre: *** cfs_fail_loc=157, val=2147483648*** [ 4380.798482] LustreError: 152301:0:(ldlm_lib.c:3326:target_send_reply_msg()) @@@ dropping reply req@ffff9e8911781500 x1863234915901184/t352187318275(352187318275) o101->fad0afe6-b350-498f-8db0-9a178a7cb52d@192.168.203.50@tcp:89/0 lens 592/608 e 0 to 0 dl 1776923544 ref 1 fl Interpret:/604/0 rc 301/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 4382.688704] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 4382.693031] Lustre: Skipped 18 previous similar messages [ 4385.695113] Lustre: 3297:0:(client.c:2479:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1776923522/real 1776923522] req@ffff9e890677c000 x1863234880214912/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1776923538 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4385.702761] Lustre: 3297:0:(client.c:2479:ptlrpc_expire_one_request()) Skipped 35 previous similar messages [ 4397.377692] Lustre: lustre-MDT0000: Client fad0afe6-b350-498f-8db0-9a178a7cb52d (at 192.168.203.50@tcp) reconnected, waiting for 1 clients in recovery for 0:53 [ 4397.384983] Lustre: 152273:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff9e880d70aa00 x1863234915901184/t352187318275(352187318275) o101->fad0afe6-b350-498f-8db0-9a178a7cb52d@192.168.203.50@tcp:105/0 lens 592/3488 e 0 to 0 dl 1776923560 ref 1 fl Interpret:/606/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 4397.404035] Lustre: lustre-MDT0000: Recovery over after 0:17, of 1 clients 1 recovered and 0 were evicted. [ 4397.407171] Lustre: Skipped 10 previous similar messages [ 4397.421648] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:11683 to 0x280000400:11713) [ 4397.421653] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:11725 to 0x240000400:11777) [ 4398.716379] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4399.219065] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4402.605081] Lustre: DEBUG MARKER: == replay-single test 74: Ensure applications don't fail waiting for OST recovery ========================================================== 01:52:34 (1776923554) [ 4403.499179] Lustre: Failing over lustre-OST0000 [ 4403.541314] Lustre: server umount lustre-OST0000 complete [ 4404.830833] Lustre: Failing over lustre-MDT0000 [ 4404.948980] Lustre: server umount lustre-MDT0000 complete [ 4417.399213] LustreError: 33765:0:(ldlm_lib.c:1179: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. [ 4417.406457] LustreError: 33765:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 6 previous similar messages [ 4417.466809] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:11683 to 0x280000400:11745) [ 4418.745081] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4422.144930] Lustre: lustre-OST0000: Denying connection for new client 6e54325f-a8a9-4164-b948-f8a7b3b46b42 (at 192.168.203.50@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 1:00 [ 4422.150294] Lustre: Skipped 11 previous similar messages [ 4422.471367] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:11725 to 0x240000400:11809) [ 4422.819715] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4428.334420] Lustre: DEBUG MARKER: == replay-single test 80a: DNE: create remote dir, drop update rep from MDT0, fail MDT0 ========================================================== 01:53:00 (1776923580) [ 4428.811584] Lustre: DEBUG MARKER: SKIP: replay-single test_80a needs >= 2 MDTs [ 4429.368923] Lustre: DEBUG MARKER: == replay-single test 80b: DNE: create remote dir, drop update rep from MDT0, fail MDT1 ========================================================== 01:53:01 (1776923581) [ 4429.855966] Lustre: DEBUG MARKER: SKIP: replay-single test_80b needs >= 2 MDTs [ 4430.392044] Lustre: DEBUG MARKER: == replay-single test 80c: DNE: create remote dir, drop update rep from MDT1, fail MDT[0,1] ========================================================== 01:53:02 (1776923582) [ 4430.878681] Lustre: DEBUG MARKER: SKIP: replay-single test_80c needs >= 2 MDTs [ 4431.421606] Lustre: DEBUG MARKER: == replay-single test 80d: DNE: create remote dir, drop update rep from MDT1, fail 2 MDTs ========================================================== 01:53:03 (1776923583) [ 4431.935335] Lustre: DEBUG MARKER: SKIP: replay-single test_80d needs >= 2 MDTs [ 4432.469419] Lustre: DEBUG MARKER: == replay-single test 80e: DNE: create remote dir, drop MDT1 rep, fail MDT0 ========================================================== 01:53:04 (1776923584) [ 4432.939736] Lustre: DEBUG MARKER: SKIP: replay-single test_80e needs >= 2 MDTs [ 4433.482195] Lustre: DEBUG MARKER: == replay-single test 80f: DNE: create remote dir, drop MDT1 rep, fail MDT1 ========================================================== 01:53:05 (1776923585) [ 4433.977068] Lustre: DEBUG MARKER: SKIP: replay-single test_80f needs >= 2 MDTs [ 4434.509397] Lustre: DEBUG MARKER: == replay-single test 80g: DNE: create remote dir, drop MDT1 rep, fail MDT0, then MDT1 ========================================================== 01:53:06 (1776923586) [ 4434.981750] Lustre: DEBUG MARKER: SKIP: replay-single test_80g needs >= 2 MDTs [ 4435.529661] Lustre: DEBUG MARKER: == replay-single test 80h: DNE: create remote dir, drop MDT1 rep, fail 2 MDTs ========================================================== 01:53:07 (1776923587) [ 4436.029741] Lustre: DEBUG MARKER: SKIP: replay-single test_80h needs >= 2 MDTs [ 4436.600130] Lustre: DEBUG MARKER: == replay-single test 81a: DNE: unlink remote dir, drop MDT0 update rep, fail MDT1 ========================================================== 01:53:08 (1776923588) [ 4437.114879] Lustre: DEBUG MARKER: SKIP: replay-single test_81a needs >= 2 MDTs [ 4437.672393] Lustre: DEBUG MARKER: == replay-single test 81b: DNE: unlink remote dir, drop MDT0 update reply, fail MDT0 ========================================================== 01:53:09 (1776923589) [ 4438.195963] Lustre: DEBUG MARKER: SKIP: replay-single test_81b needs >= 2 MDTs [ 4438.771880] Lustre: DEBUG MARKER: == replay-single test 81c: DNE: unlink remote dir, drop MDT0 update reply, fail MDT0,MDT1 ========================================================== 01:53:10 (1776923590) [ 4439.305764] Lustre: DEBUG MARKER: SKIP: replay-single test_81c needs >= 2 MDTs [ 4439.877258] Lustre: DEBUG MARKER: == replay-single test 81d: DNE: unlink remote dir, drop MDT0 update reply, fail 2 MDTs ========================================================== 01:53:11 (1776923591) [ 4440.355410] Lustre: DEBUG MARKER: SKIP: replay-single test_81d needs >= 2 MDTs [ 4440.916592] Lustre: DEBUG MARKER: == replay-single test 81e: DNE: unlink remote dir, drop MDT1 req reply, fail MDT0 ========================================================== 01:53:12 (1776923592) [ 4441.391349] Lustre: DEBUG MARKER: SKIP: replay-single test_81e needs >= 2 MDTs [ 4441.935124] Lustre: DEBUG MARKER: == replay-single test 81f: DNE: unlink remote dir, drop MDT1 req reply, fail MDT1 ========================================================== 01:53:13 (1776923593) [ 4442.410340] Lustre: DEBUG MARKER: SKIP: replay-single test_81f needs >= 2 MDTs [ 4442.960226] Lustre: DEBUG MARKER: == replay-single test 81g: DNE: unlink remote dir, drop req reply, fail M0, then M1 ========================================================== 01:53:14 (1776923594) [ 4443.418447] Lustre: DEBUG MARKER: SKIP: replay-single test_81g needs >= 2 MDTs [ 4443.947356] Lustre: DEBUG MARKER: == replay-single test 81h: DNE: unlink remote dir, drop request reply, fail 2 MDTs ========================================================== 01:53:15 (1776923595) [ 4444.393795] Lustre: DEBUG MARKER: SKIP: replay-single test_81h needs >= 2 MDTs [ 4444.873623] Lustre: DEBUG MARKER: == replay-single test 84a: stale open during export disconnect ========================================================== 01:53:16 (1776923596) [ 4445.420471] Lustre: 156641:0:(genops.c:1793:obd_export_evict_by_uuid()) lustre-MDT0000: evicting 6e54325f-a8a9-4164-b948-f8a7b3b46b42 at adminstrative request [ 4449.957385] Lustre: DEBUG MARKER: == replay-single test 85a: check the cancellation of unused locks during recovery(IBITS) ========================================================== 01:53:21 (1776923601) [ 4451.661842] Lustre: Failing over lustre-MDT0000 [ 4451.807763] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4451.809341] Lustre: Skipped 1 previous similar message [ 4451.868715] Lustre: server umount lustre-MDT0000 complete [ 4465.697224] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4466.142525] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:11797 to 0x280000400:11841) [ 4466.142550] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:11861 to 0x240000400:11905) [ 4468.736372] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4469.248937] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4472.448792] Lustre: DEBUG MARKER: == replay-single test 85b: check the cancellation of unused locks during recovery(EXTENT) ========================================================== 01:53:44 (1776923624) [ 4476.010446] Lustre: Failing over lustre-OST0000 [ 4476.059979] Lustre: server umount lustre-OST0000 complete [ 4489.984161] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4492.927610] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 4493.423773] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4496.745266] Lustre: DEBUG MARKER: == replay-single test 86: umount server after clear nid_stats should not hit LBUG ========================================================== 01:54:08 (1776923648) [ 4497.942664] Lustre: Failing over lustre-MDT0000 [ 4498.063158] Lustre: server umount lustre-MDT0000 complete [ 4500.101194] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:11797 to 0x280000400:11873) [ 4500.107194] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:12006 to 0x240000400:12033) [ 4501.229804] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4503.854103] Lustre: DEBUG MARKER: == replay-single test 87a: write replay ================== 01:54:15 (1776923655) [ 4505.318122] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 4506.129620] Lustre: Failing over lustre-OST0000 [ 4506.151066] Lustre: server umount lustre-OST0000 complete [ 4510.176273] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 4520.183879] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4523.225689] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 4523.732715] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4527.176281] Lustre: DEBUG MARKER: == replay-single test 87b: write replay with changed data (checksum resend) ========================================================== 01:54:39 (1776923679) [ 4528.707185] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 4530.544727] Lustre: Failing over lustre-OST0000 [ 4530.561930] Lustre: server umount lustre-OST0000 complete [ 4544.180742] LustreError: lustre-OST0000: BAD WRITE CHECKSUM: from 12345-192.168.203.50@tcp inode [0x20002a3e1:0x5:0x0] object 0x240000400:12035 extent [0-1048575]: client csum 3b150b5f, server csum c54abf37 [ 4544.398859] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4547.413682] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 4547.931641] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4551.283815] Lustre: DEBUG MARKER: == replay-single test 88: MDS should not assign same objid to different files ========================================================== 01:55:03 (1776923703) [ 4552.546772] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 4553.820317] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4555.893205] Lustre: Failing over lustre-MDT0000 [ 4556.139318] Lustre: server umount lustre-MDT0000 complete [ 4557.380472] LustreError: 5736:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1776923709 with bad export cookie 16592531352303526289 [ 4566.496408] Lustre: Failing over lustre-OST0000 [ 4566.525312] Lustre: server umount lustre-OST0000 complete [ 4568.377192] LustreError: 33768:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.203.50@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4568.383603] LustreError: 33768:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 16 previous similar messages [ 4581.855370] LustreError: 3295:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff9e893c3a9180 x1863234880308992/t0(0) o250->MGC192.168.203.150@tcp@0@lo:26/25 lens 520/544 e 0 to 0 dl 0 ref 1 fl Rpc:NQU/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4581.861430] LustreError: 3295:0:(client.c:1390:ptlrpc_import_delay_req()) Skipped 2 previous similar messages [ 4583.316773] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4584.848143] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:11881 to 0x280000400:11905) [ 4597.794722] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4603.281252] Lustre: DEBUG MARKER: == replay-single test 89: no disk space leak on late ost connection ========================================================== 01:55:55 (1776923755) [ 4612.828649] Lustre: Failing over lustre-OST0000 [ 4612.870941] Lustre: server umount lustre-OST0000 complete [ 4613.087415] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 4614.162868] Lustre: Failing over lustre-MDT0000 [ 4614.341441] Lustre: server umount lustre-MDT0000 complete [ 4627.977127] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4628.705350] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:11881 to 0x280000400:11937) [ 4634.733962] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4635.440227] Lustre: lustre-OST0000: Denying connection for new client 6435a170-9378-4b70-bc8e-a8a8b85d104c (at 192.168.203.50@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 1:09 [ 4655.927405] Lustre: lustre-OST0000: Denying connection for new client 6435a170-9378-4b70-bc8e-a8a8b85d104c (at 192.168.203.50@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 0:48 [ 4655.933020] Lustre: Skipped 4 previous similar messages [ 4691.767318] Lustre: lustre-OST0000: Denying connection for new client 6435a170-9378-4b70-bc8e-a8a8b85d104c (at 192.168.203.50@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 0:12 [ 4691.772654] Lustre: Skipped 6 previous similar messages [ 4704.500139] Lustre: lustre-OST0000: recovery is timed out, evict stale exports [ 4704.502457] Lustre: 167832:0:(genops.c:1620:class_disconnect_stale_exports()) lustre-OST0000: disconnect stale client c99e43cc-0c47-4a30-9129-353a698eb248@ [ 4704.506940] Lustre: lustre-OST0000: disconnecting 1 stale clients [ 4704.520984] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:12077 to 0x240000400:12098) [ 4707.787831] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 69 sec [ 4722.712840] Lustre: DEBUG MARKER: free_before: 7520256 free_after: 7520256 [ 4724.965296] Lustre: DEBUG MARKER: == replay-single test 90: lfs find identifies the missing striped file segments ========================================================== 01:57:56 (1776923876) [ 4726.421353] Lustre: Failing over lustre-OST0000 [ 4726.453807] Lustre: server umount lustre-OST0000 complete [ 4730.335476] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 4740.927559] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4744.760708] Lustre: DEBUG MARKER: == replay-single test 93a: replay + reconnect ============ 01:58:16 (1776923896) [ 4745.994721] Lustre: Failing over lustre-OST0000 [ 4746.041809] Lustre: server umount lustre-OST0000 complete [ 4746.207359] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 4759.594165] LustreError: 170786:0:(ldlm_lib.c:2885:target_recovery_thread()) cfs_fail_timeout id 715 sleeping for 40000ms [ 4759.597742] LustreError: 170786:0:(ldlm_lib.c:2885:target_recovery_thread()) Skipped 76 previous similar messages [ 4760.332740] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4765.663116] Lustre: *** cfs_fail_loc=715, val=40*** [ 4775.735163] Lustre: lustre-OST0000: Client 6435a170-9378-4b70-bc8e-a8a8b85d104c (at 192.168.203.50@tcp) reconnected, waiting for 2 clients in recovery for 1:24 [ 4782.047118] Lustre: *** cfs_fail_loc=715, val=40*** [ 4782.048851] Lustre: Skipped 1 previous similar message [ 4792.119200] Lustre: lustre-OST0000: Client 6435a170-9378-4b70-bc8e-a8a8b85d104c (at 192.168.203.50@tcp) reconnected, waiting for 2 clients in recovery for 1:08 [ 4792.124563] Lustre: Skipped 1 previous similar message [ 4798.431142] Lustre: *** cfs_fail_loc=715, val=40*** [ 4798.432329] Lustre: Skipped 1 previous similar message [ 4799.639126] LustreError: 170786:0:(ldlm_lib.c:2885:target_recovery_thread()) cfs_fail_timeout id 715 awake [ 4799.642478] LustreError: 170786:0:(ldlm_lib.c:2885:target_recovery_thread()) Skipped 76 previous similar messages [ 4801.151645] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 4801.726535] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4805.231460] Lustre: DEBUG MARKER: == replay-single test 93b: replay + reconnect on mds ===== 01:59:17 (1776923957) [ 4806.554328] Lustre: Failing over lustre-MDT0000 [ 4806.798384] Lustre: server umount lustre-MDT0000 complete [ 4820.624071] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4822.568293] LustreError: 172225:0:(ldlm_lib.c:2885:target_recovery_thread()) cfs_fail_timeout id 715 sleeping for 80000ms [ 4828.639126] Lustre: *** cfs_fail_loc=715, val=80*** [ 4828.640491] Lustre: Skipped 1 previous similar message [ 4839.223080] Lustre: lustre-MDT0000: Client 6435a170-9378-4b70-bc8e-a8a8b85d104c (at 192.168.203.50@tcp) reconnected, waiting for 1 clients in recovery for 0:53 [ 4839.227077] Lustre: Skipped 1 previous similar message [ 4845.535132] Lustre: *** cfs_fail_loc=715, val=80*** [ 4854.584322] Lustre: lustre-MDT0000: Client 6435a170-9378-4b70-bc8e-a8a8b85d104c (at 192.168.203.50@tcp) reconnected, waiting for 1 clients in recovery for 0:37 [ 4860.895118] Lustre: *** cfs_fail_loc=715, val=80*** [ 4870.967189] Lustre: lustre-MDT0000: Client 6435a170-9378-4b70-bc8e-a8a8b85d104c (at 192.168.203.50@tcp) reconnected, waiting for 1 clients in recovery for 0:21 [ 4877.279109] Lustre: *** cfs_fail_loc=715, val=80*** [ 4902.655115] LustreError: 172225:0:(ldlm_lib.c:2885:target_recovery_thread()) cfs_fail_timeout id 715 awake [ 4902.668667] Lustre: 172225:0:(ldlm_lib.c:2931:target_recovery_thread()) too long recovery - read logs [ 4902.672456] LustreError: dumping log to /tmp/lustre-log.1776924055.172225 [ 4902.730848] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:11950 to 0x280000400:11969) [ 4902.730858] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:12112 to 0x240000400:12130) [ 4904.103823] Lustre: DEBUG MARKER: oleg350-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4904.693438] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4908.540669] Lustre: DEBUG MARKER: == replay-single test complete, duration 4731 sec ======== 02:01:00 (1776924060) [ 4909.164422] Lustre: DEBUG MARKER: === replay-single: start cleanup 02:01:01 (1776924061) === [ 4912.307316] Lustre: DEBUG MARKER: === replay-single: finish cleanup 02:01:04 (1776924064) === [ 4944.883678] Lustre: server umount lustre-MDT0000 complete [ 4946.270662] LustreError: 5736:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1776924098 with bad export cookie 16592531352303539022 [ 4955.646483] Lustre: server umount lustre-OST0000 complete [ 4967.309912] Lustre: server umount lustre-OST0001 complete [ 4971.555187] Lustre: DEBUG MARKER: oleg350-server.virtnet: executing unload_modules_local [ 4972.684376] Key type lgssc unregistered [ 4972.813316] LNet: 174233:0:(lib-ptl.c:967:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 4972.816577] LNetError: 174233:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 4972.828384] LNet: Removed LNI 192.168.203.150@tcp [ 4973.115109] Key type .llcrypt unregistered [ 4973.116286] Key type ._llcrypt unregistered