[ 0.000000] Linux version 4.18.0rh8.10-debug (green@maintenance) (gcc version 8.5.0 20210514 (Red Hat 8.5.0-26) (GCC)) #2 SMP Mon Jul 14 01:24:22 EDT 2025 [ 0.000000] Command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers' [ 0.000000] x86/fpu: xstate_offset[2]: 576, xstate_sizes[2]: 256 [ 0.000000] x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'standard' format. [ 0.000000] signal: max sigframe size: 1776 [ 0.000000] BIOS-provided physical RAM map: [ 0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable [ 0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000000100000-0x00000000bffcdfff] usable [ 0.000000] BIOS-e820: [mem 0x00000000bffce000-0x00000000bfffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000100000000-0x0000000146dfffff] usable [ 0.000000] NX (Execute Disable) protection: active [ 0.000000] SMBIOS 2.8 present. [ 0.000000] DMI: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.17.0-10.fc44 06/10/2025 [ 0.000000] Hypervisor detected: KVM [ 0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00 [ 0.000000] kvm-clock: using sched offset of 484577886 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2399.998 MHz processor [ 0.000000] last_pfn = 0x146e00 max_arch_pfn = 0x400000000 [ 0.000000] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT [ 0.000000] last_pfn = 0xbffce max_arch_pfn = 0x400000000 [ 0.000000] found SMP MP-table at [mem 0x000f54b0-0x000f54bf] [ 0.000000] RAMDISK: [mem 0xbcc54000-0xbffbffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F52D0 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE247C 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE2318 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 0022D8 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE238C 000090 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE241C 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE2454 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe2318-0xbffe238b] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe2317] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe238c-0xbffe241b] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe241c-0xbffe2453] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe2454-0xbffe247b] [ 0.000000] No NUMA configuration found [ 0.000000] Faking a node at [mem 0x0000000000000000-0x0000000146dfffff] [ 0.000000] NODE_DATA(0) allocated [mem 0x1465a3000-0x1465cdfff] [ 0.000000] Reserving 256MB of memory at 2752MB for crashkernel (System RAM: 4205MB) [ 0.000000] Zone ranges: [ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.000000] DMA32 [mem 0x0000000001000000-0x00000000ffffffff] [ 0.000000] Normal [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Device empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff] [ 0.000000] node 0: [mem 0x0000000000100000-0x00000000bffcdfff] [ 0.000000] node 0: [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Zeroed struct page in unavailable ranges: 4756 pages [ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x0000000146dfffff] [ 0.000000] ACPI: PM-Timer IO Port: 0x608 [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) [ 0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) [ 0.000000] Using ACPI (MADT) for SMP configuration information [ 0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000] TSC deadline timer available [ 0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs [ 0.000000] kvm-guest: KVM setup pv remote TLB flush [ 0.000000] kvm-guest: setup PV sched yield [ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff] [ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff] [ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff] [ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff] [ 0.000000] PM: Registered nosave memory: [mem 0xbffce000-0xbfffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xc0000000-0xfeffbfff] [ 0.000000] PM: Registered nosave memory: [mem 0xfeffc000-0xfeffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xff000000-0xfffbffff] [ 0.000000] PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff] [ 0.000000] [mem 0xc0000000-0xfeffbfff] available for PCI devices [ 0.000000] Booting paravirtualized kernel on KVM [ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns [ 0.000000] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1 [ 0.000000] percpu: Embedded 63 pages/cpu s221184 r8192 d28672 u524288 [ 0.000000] kvm-guest: PV spinlocks enabled [ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1059606 [ 0.000000] Policy zone: Normal [ 0.000000] Kernel command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] Specific versions of hardware are certified with Red Hat Enterprise Linux 8. Please see the list of hardware certified with Red Hat Enterprise Linux 8 at https://catalog.redhat.com. [ 0.000000] audit: disabled (until reboot) [ 0.000000] software IO TLB: area num 4. [ 0.000000] Memory: 2829652K/4306352K available (18435K kernel code, 11221K rwdata, 7248K rodata, 2908K init, 18040K bss, 524588K 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.001010] APIC: Switch to symmetric I/O mode setup [ 0.002372] x2apic enabled [ 0.003010] Switched APIC routing to physical x2apic. [ 0.004015] kvm-guest: setup PV IPIs [ 0.007332] ..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.008022] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.009011] pid_max: default: 32768 minimum: 301 [ 0.010138] LSM: Security Framework initializing [ 0.011054] Yama: becoming mindful. [ 0.012041] SELinux: Initializing. [ 0.013074] *** VALIDATE selinux *** [ 0.021465] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.026050] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.027165] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.028110] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.029113] *** VALIDATE tmpfs *** [ 0.031460] *** VALIDATE proc *** [ 0.032238] *** VALIDATE cgroup *** [ 0.033010] *** VALIDATE cgroup2 *** [ 0.034256] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.035153] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.036011] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.037032] Spectre V2 : User space: Vulnerable [ 0.038011] Speculative Store Bypass: Vulnerable [ 0.041269] debug: unmapping init [mem 0xffffffff84259000-0xffffffff84260fff] [ 0.043206] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.044730] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.045026] ... version: 2 [ 0.046015] ... bit width: 48 [ 0.047012] ... generic registers: 4 [ 0.048013] ... value mask: 0000ffffffffffff [ 0.049015] ... max period: 00007fffffffffff [ 0.050014] ... fixed-purpose events: 3 [ 0.051011] ... event mask: 000000070000000f [ 0.052303] rcu: Hierarchical SRCU implementation. [ 0.054538] smp: Bringing up secondary CPUs ... [ 0.055571] x86: Booting SMP configuration: [ 0.056026] .... node #0, CPUs: #1 #2 #3 [ 0.060013] smp: Brought up 1 node, 4 CPUs [ 0.062016] smpboot: Max logical packages: 1 [ 0.063019] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.125000] node 0 deferred pages initialised in 60ms [ 0.130130] devtmpfs: initialized [ 0.131159] x86/mm: Memory block size: 128MB [ 0.133560] gcov: version magic: 0x41383552 [ 0.135255] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.136080] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.137249] pinctrl core: initialized pinctrl subsystem [ 0.138216] [ 0.138797] ************************************************************* [ 0.139012] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.140014] ** ** [ 0.141013] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.142013] ** ** [ 0.143013] ** This means that this kernel is built to expose internal ** [ 0.144017] ** IOMMU data structures, which may compromise security on ** [ 0.145015] ** your system. ** [ 0.146013] ** ** [ 0.147014] ** If you see this message and you are not debugging the ** [ 0.148015] ** kernel, report this immediately to your vendor! ** [ 0.149012] ** ** [ 0.150014] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.151013] ************************************************************* [ 0.152839] NET: Registered protocol family 16 [ 0.153450] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.154058] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.155062] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.156447] cpuidle: using governor menu [ 0.159434] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.162435] PCI: Using configuration type 1 for base access [ 0.164134] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.176069] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.177022] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.179208] cryptd: max_cpu_qlen set to 1000 [ 0.184120] ACPI: Added _OSI(Module Device) [ 0.185036] ACPI: Added _OSI(Processor Device) [ 0.186000] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.187024] ACPI: Added _OSI(Processor Aggregator Device) [ 0.190000] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.193577] ACPI: Interpreter enabled [ 0.195071] ACPI: PM: (supports S0 S3 S4 S5) [ 0.196014] ACPI: Using IOAPIC for interrupt routing [ 0.198106] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.200305] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.207947] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.209036] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.211022] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.214072] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.219360] acpiphp: Slot [2] registered [ 0.221120] acpiphp: Slot [5] registered [ 0.222122] acpiphp: Slot [6] registered [ 0.223154] acpiphp: Slot [7] registered [ 0.225138] acpiphp: Slot [8] registered [ 0.226128] acpiphp: Slot [9] registered [ 0.227128] acpiphp: Slot [10] registered [ 0.229123] acpiphp: Slot [3] registered [ 0.230136] acpiphp: Slot [4] registered [ 0.232114] acpiphp: Slot [11] registered [ 0.233138] acpiphp: Slot [12] registered [ 0.235125] acpiphp: Slot [13] registered [ 0.236116] acpiphp: Slot [14] registered [ 0.238110] acpiphp: Slot [15] registered [ 0.239116] acpiphp: Slot [16] registered [ 0.241112] acpiphp: Slot [17] registered [ 0.242137] acpiphp: Slot [18] registered [ 0.243105] acpiphp: Slot [19] registered [ 0.245104] acpiphp: Slot [20] registered [ 0.246119] acpiphp: Slot [21] registered [ 0.248174] acpiphp: Slot [22] registered [ 0.249134] acpiphp: Slot [23] registered [ 0.251175] acpiphp: Slot [24] registered [ 0.253187] acpiphp: Slot [25] registered [ 0.254187] acpiphp: Slot [26] registered [ 0.255109] acpiphp: Slot [27] registered [ 0.257090] acpiphp: Slot [28] registered [ 0.258094] acpiphp: Slot [29] registered [ 0.259128] acpiphp: Slot [30] registered [ 0.261091] acpiphp: Slot [31] registered [ 0.262080] PCI host bridge to bus 0000:00 [ 0.264019] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.266024] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.268024] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.271025] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.273021] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.276026] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.278184] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.281031] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.283766] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.294000] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.299513] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.302019] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.305018] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.309023] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.311570] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.315074] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.318050] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.322920] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.328017] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.340978] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.346019] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.352335] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.360015] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.367016] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.384017] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.394467] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.401017] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.406017] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.422019] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.433570] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.440014] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.446017] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.458013] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.466195] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.471018] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.476013] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.489016] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.496000] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.502013] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.507023] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.526021] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 0.535915] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.541017] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.547019] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.563023] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 0.573363] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.574252] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.576227] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.577272] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.579189] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.582225] iommu: Default domain type: Passthrough [ 0.583471] SCSI subsystem initialized [ 0.585089] ACPI: bus type USB registered [ 0.586079] usbcore: registered new interface driver usbfs [ 0.588066] usbcore: registered new interface driver hub [ 0.590088] usbcore: registered new device driver usb [ 0.592229] pps_core: LinuxPPS API ver. 1 registered [ 0.594012] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.596061] PTP clock support registered [ 0.598078] EDAC MC: Ver: 3.0.0 [ 0.599469] PCI: Using ACPI for IRQ routing [ 0.600852] NetLabel: Initializing [ 0.602010] NetLabel: domain hash size = 128 [ 0.603007] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.605070] NetLabel: unlabeled traffic allowed by default [ 0.607138] vgaarb: loaded [ 0.608254] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.610014] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.615025] clocksource: Switched to clocksource kvm-clock [ 0.722698] VFS: Disk quotas dquot_6.6.0 [ 0.724305] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.727168] *** VALIDATE ramfs *** [ 0.728386] *** VALIDATE hugetlbfs *** [ 0.729798] pnp: PnP ACPI init [ 0.731657] pnp: PnP ACPI: found 6 devices [ 0.744872] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.748316] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.749922] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.751573] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.753105] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.754529] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.756144] NET: Registered protocol family 2 [ 0.757975] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.761467] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.763965] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.768477] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.770720] TCP: Hash tables configured (established 65536 bind 65536) [ 0.772608] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.774520] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.776447] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.778335] NET: Registered protocol family 1 [ 0.780266] RPC: Registered named UNIX socket transport module. [ 0.781488] RPC: Registered udp transport module. [ 0.782430] RPC: Registered tcp transport module. [ 0.783396] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.784813] NET: Registered protocol family 44 [ 0.785871] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.787047] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.788202] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.789587] PCI: CLS 0 bytes, default 64 [ 0.791341] Unpacking initramfs... [ 2.142915] debug: unmapping init [mem 0xffff93c63cc54000-0xffff93c63ffbffff] [ 2.146979] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.149364] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.151745] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 2.651467] Initialise system trusted keyrings [ 2.653191] Key type blacklist registered [ 2.655925] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.666925] zbud: loaded [ 2.670764] *** VALIDATE nfs *** [ 2.671900] *** VALIDATE nfs4 *** [ 2.673478] pstore: using deflate compression [ 2.679288] Platform Keyring initialized [ 2.779826] NET: Registered protocol family 38 [ 2.781564] Key type asymmetric registered [ 2.783044] Asymmetric key parser 'x509' registered [ 2.785070] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 2.788084] io scheduler mq-deadline registered [ 2.790028] io scheduler kyber registered [ 2.791612] io scheduler bfq registered [ 2.793515] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 2.796422] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 2.799663] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 2.802684] ACPI: Power Button [PWRF] [ 2.808245] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 2.815252] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 2.828759] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 2.836579] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 2.851900] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 2.881432] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 2.908849] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 2.913506] Non-volatile memory driver v1.3 [ 2.915260] Linux agpgart interface v0.103 [ 2.949628] virtio_blk virtio1: [vda] 147000 512-byte logical blocks (75.3 MB/71.8 MiB) [ 2.952813] vda: detected capacity change from 0 to 75264000 [ 2.967111] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 2.969277] vdb: detected capacity change from 0 to 1073741824 [ 2.982972] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 2.985408] vdc: detected capacity change from 0 to 2621440000 [ 3.001515] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 3.003971] vdd: detected capacity change from 0 to 2621440000 [ 3.023479] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.026432] vde: detected capacity change from 0 to 4294967296 [ 3.041763] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 3.045038] vdf: detected capacity change from 0 to 4294967296 [ 3.053154] libphy: Fixed MDIO Bus: probed [ 3.066511] usbcore: registered new interface driver usbserial_generic [ 3.069290] usbserial: USB Serial support registered for generic [ 3.071773] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.075527] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.077391] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.079832] mousedev: PS/2 mouse device common for all mice [ 3.082328] rtc_cmos 00:05: RTC can wake from S4 [ 3.084359] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.087750] rtc_cmos 00:05: registered as rtc0 [ 3.089585] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.092854] intel_pstate: CPU model not supported [ 3.095965] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.098555] hid: raw HID events driver (C) Jiri Kosina [ 3.101576] usbcore: registered new interface driver usbhid [ 3.103622] usbhid: USB HID core driver [ 3.104547] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.105319] drop_monitor: Initializing network drop monitor service [ 3.110484] Initializing XFRM netlink socket [ 3.112503] NET: Registered protocol family 10 [ 3.114708] Segment Routing with IPv6 [ 3.116190] NET: Registered protocol family 17 [ 3.118074] mpls_gso: MPLS GSO support [ 3.124571] RAS: Correctable Errors collector initialized. [ 3.126537] AVX version of gcm_enc/dec engaged. [ 3.128032] AES CTR mode by8 optimization enabled [ 3.195221] sched_clock: Marking stable (3195200090, 0)->(4128528487, -933328397) [ 3.199043] registered taskstats version 1 [ 3.201118] Loading compiled-in X.509 certificates [ 3.203064] zswap: loaded using pool lzo/zbud [ 3.220431] Key type big_key registered [ 3.230626] Key type encrypted registered [ 3.231834] ima: No TPM chip found, activating TPM-bypass! [ 3.232977] ima: Allocated hash algorithm: sha1 [ 3.233896] ima: No architecture policies found [ 3.234830] evm: Initialising EVM extended attributes: [ 3.235871] evm: security.selinux [ 3.236467] evm: security.ima [ 3.237131] evm: security.capability [ 3.237914] evm: HMAC attrs: 0x1 [ 3.239776] rtc_cmos 00:05: setting system clock to 2026-08-27 20:27:09 UTC (1787862429) [ 3.245525] debug: unmapping init [mem 0xffffffff85203000-0xffffffff853fffff] [ 3.247961] debug: unmapping init [mem 0xffffffff83f82000-0xffffffff84258fff] [ 3.255059] Write protecting the kernel read-only data: 28672k [ 3.258662] debug: unmapping init [mem 0xffffffff82603000-0xffffffff827fffff] [ 3.261099] debug: unmapping init [mem 0xffffffff82f14000-0xffffffff82ffffff] [ 3.289371] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 3.294940] systemd[1]: Detected virtualization kvm. [ 3.296095] systemd[1]: Detected architecture x86-64. [ 3.297331] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.322561] systemd[1]: No hostname configured. [ 3.323697] systemd[1]: Set hostname to . [ 3.324941] random: systemd: uninitialized urandom read (16 bytes read) [ 3.326470] systemd[1]: Initializing machine ID from random generator. [ 3.366790] random: ln: uninitialized urandom read (6 bytes read) [ 3.445453] random: systemd: uninitialized urandom read (16 bytes read) [ 3.447818] systemd[1]: Reached target Local File Systems. [ OK ] Reached target Local File Systems. [ 3.451472] systemd[1]: Listening on udev Control Socket. [ OK ] Listening on udev Control Socket. [ 3.454851] systemd[1]: Reached target Timers. [ OK ] Reached target Timers. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Listening on Journal Socket. Starting Create list of required st…ce nodes for the current kernel... Starting Setup Virtual Console... [ OK ] Reached target Local Encrypted Volumes. [ OK ] Listening on udev Kernel Socket. Starting Apply Kernel Variables... [ OK ] Reached target Swap. [ OK ] Listening on Journal Socket (/dev/log). [ OK ] Reached target Sockets. Starting Journal Service... [ OK ] Reached target Paths. Starting Create Volatile Files and Directories... [ OK ] Reached target Initrd Root Device. [ OK ] Started Memstrack Anylazing Service. [ OK ] Reached target Slices. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Setup Virtual Console. [ OK ] Started Apply Kernel Variables. [ OK ] Started Create Volatile Files and Directories. Starting dracut cmdline hook... Starting Create Static Device Nodes in /dev... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started Journal Service. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 4.010811] device-mapper: uevent: version 1.0.3 [ 4.012651] 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. [ 4.620603] virtio_net virtio0 ens2: renamed from eth0 [ 4.630100] random: fast init done [ 4.662240] scsi host0: ata_piix [ 4.714595] scsi host1: ata_piix [ 4.716679] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 4.718941] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 8.868300] dracut-initqueue[590]: RTNETLINK answers: File exists [ 9.744878] random: crng init done [ 9.745724] random: 7 urandom warning(s) missed due to ratelimiting Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Mounting /sysroot... [ 9.996772] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped target Timers. [ OK ] Stopped dracut pre-pivot and cleanup hook. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Slices. [ OK ] Stopped target Paths. [ OK ] Stopped target Sockets. [ OK ] Stopped target System Initialization. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped target Swap. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. Stopping udev Kernel Device Manager... [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Closed udev Kernel Socket. [ OK ] Closed udev Control Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 11.088945] printk: systemd: 26 output lines suppressed due to ratelimiting [ 11.290649] SELinux: Disabled at runtime. [ 11.350112] 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) [ 11.359412] systemd[1]: Detected virtualization kvm. [ 11.361554] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 11.776133] systemd[1]: initrd-switch-root.service: Succeeded. [ 11.779064] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 11.785061] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 11.792704] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 11.796352] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 11.804828] systemd[1]: Starting Journal Service... Starting Journal Service... [ 11.809542] systemd[1]: Listening on initctl Compatibility Named Pipe. [ OK ] Listening on initctl Compatibility Named Pipe. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target rpc_pipefs.target. Starting Apply Kernel Variables... Starting Remount Root and Kernel File Systems... Mounting Huge Pages File System... Mounting POSIX Message Queue File System... [ OK ] Created slice User and Session Slice. [ OK ] Reached target Slices. Mounting Kernel Debug File System... [ OK ] Stopped target Switch Root. [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Reached target Paths. [ OK ] Created slice system-getty.slice. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Listening on Process Core Dump Socket. [ OK ] Created slice system-sshd\x2dkeygen.slice. Activating swap /dev/disk/by-label/SWAP... [ OK ] Stopped target Initrd Root File System. [ OK ] Stopped target Initrd File Systems. [ OK ] Listening on udev Control Socket. [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Reached target RPC Port Mapper. [FAILED] Failed to set up automount[ 11.952111] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Listening on udev Kernel Socket. Starting udev Coldplug all Devices... [ OK ] Started Journal Service. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Apply Kernel Variables. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Mounted Huge Pages File System. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Mounted Kernel Debug File System. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Reached target Swap. Starting Configure read-only root support... Starting Create Static Device Nodes in /dev... Starting Flush Journal to Persistent Storage... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. Starting udev Kernel Device Manager... [ OK ] Reached target Local File Systems (Pre). Mounting /home/green/git/lustre-release... Mounting /mnt... [ OK ] Mounted /mnt. [ 12.216414] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Coldplug all Devices. [ OK ] Started udev Kernel Device Manager. [ 12.491949] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 12.564977] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 12.661054] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 12.671867] EDAC sbridge: Ver: 1.1.2 [ 14.109408] Key type dns_resolver registered [ 14.411943] NFS: Registering the id_resolver key type [ 14.413407] Key type id_resolver registered [ 14.414580] Key type id_legacy registered [ OK ] Started Configure read-only root support. Starting Load/Save Random Seed... [ OK ] Reached target Local File Systems. Starting Mark the need to relabel after reboot... Starting Rebuild Dynamic Linker Cache... Starting Create Volatile Files and Directories... [ OK ] Started Load/Save Random Seed. [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Create Volatile Files and Directories. Starting Update UTMP about System Boot/Shutdown... Starting RPC Bind... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. Starting Restore /run/initramfs on shutdown... [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Started dnf makecache --timer. [ OK ] Reached target Timers. [ OK ] Reached target sshd-keygen.target. [ OK ] Started D-Bus System Message Bus. Starting Network Manager... Starting Login Service... [ OK ] Started irqbalance daemon. [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Login Service. [ OK ] Started Network Manager. Starting Network Manager Wait Online... [ OK ] Reached target Network. Starting OpenSSH server daemon... Starting GSSAPI Proxy Daemon... Starting Dynamic System Tuning Daemon... Starting Hostname Service... [ OK ] Started OpenSSH server daemon. [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... [ OK ] Started Permit User Sessions. [ OK ] Started Serial Getty on ttyS1. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Command Scheduler. [ OK ] Started Getty on tty1. [ OK ] Reached target Login Prompts. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting System Logging Service... Starting Crash recovery kernel arming... Starting Notify NFS peers of a restart... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Starting Authorization Manager... [ OK ] Started Authorization Manager. [ OK ] Started Dynamic System Tuning Daemon. [ OK ] Reached target Multi-User System. [ OK ] Reached target Graphical Interface. Starting Update UTMP about System Runlevel Changes... [ OK ] Started Update UTMP about System Runlevel Changes. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg128-server login: [ 31.713775] spl: loading out-of-tree module taints kernel. [ 34.230351] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 38.913529] Key type ._llcrypt registered [ 38.914367] Key type .llcrypt registered [ 38.968339] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_hostid [ 47.680233] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing load_modules_local [ 48.359929] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 48.370756] alg: No test for adler32 (adler32-zlib) [ 49.427539] Lustre: Lustre: Build Version: 2.17.57_108_ga833322 [ 49.797272] LNet: Added LNI 192.168.201.128@tcp [8/256/0/180] [ 51.431251] Key type lgssc registered [ 52.272995] Lustre: Echo OBD driver; http://www.lustre.org/ [ 62.461870] vdc: vdc1 vdc9 [ 73.868970] vde: vde1 vde9 [ 77.928979] hrtimer: interrupt took 7128851 ns [ 85.902721] vdf: vdf1 vdf9 [ 85.931709] vdf: vdf1 vdf9 [ 104.856991] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing load_modules_local [ 114.405104] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 115.608944] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 115.808707] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 115.865433] Lustre: lustre-MDT0000: new disk, initializing [ 116.138200] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 116.195573] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 120.648044] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 125.849413] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 133.219610] Lustre: lustre-OST0000: new disk, initializing [ 133.227329] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 133.230882] Lustre: Skipped 1 previous similar message [ 133.418346] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 140.762091] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 141.179693] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:0:ost [ 141.185693] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:0:ost] [ 141.535523] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x240000400 [ 152.440201] Lustre: lustre-OST0001: new disk, initializing [ 152.455573] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 152.590677] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 159.222782] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 162.639631] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000280000400-0x00000002c0000400]:1:ost [ 162.655316] Lustre: cli-lustre-OST0001-super: Allocated super-sequence [0x0000000280000400-0x00000002c0000400]:1:ost] [ 162.917919] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x280000400 [ 172.048453] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 183.335981] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 189.651184] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing check_logdir /tmp/testlogs/ [ 194.599201] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing yml_node [ 198.947789] Lustre: DEBUG MARKER: Client: 2.17.57.108 [ 201.303889] Lustre: DEBUG MARKER: MDS: 2.17.57.108 [ 203.593515] Lustre: DEBUG MARKER: OSS: 2.17.57.108 [ 205.223884] Lustre: DEBUG MARKER: -----============= acceptance-small: replay-single ============----- Thu Aug 27 16:30:29 EDT 2026 [ 221.816637] Lustre: DEBUG MARKER: excepting tests: 59 36 [ 224.041298] Lustre: DEBUG MARKER: === replay-single: start setup 16:30:48 (1787862648) === [ 229.814560] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing check_config_client /mnt/lustre [ 246.357245] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 249.532191] Lustre: 11288:0:(mgs_llog.c:1450:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 253.266752] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 256.617950] Lustre: DEBUG MARKER: === replay-single: finish setup 16:31:21 (1787862681) === [ 258.381444] Lustre: DEBUG MARKER: == replay-single test 0a: empty replay =================== 16:31:22 (1787862682) [ 261.210916] LustreError: 11784:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 262.370561] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 264.585984] Lustre: Failing over lustre-MDT0000 [ 264.672489] 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 [ 264.674485] Lustre: lustre-MDT0000: Not available for connect from 192.168.201.28@tcp (stopping) [ 264.694204] Lustre: Skipped 2 previous similar messages [ 264.907123] Lustre: server umount lustre-MDT0000 complete [ 284.754589] LustreError: MGC192.168.201.128@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 285.303269] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 286.182709] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 288.976667] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 304.596448] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 304.669880] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 310.361329] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 311.916530] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 319.496561] Lustre: DEBUG MARKER: == replay-single test 0b: ensure object created after recover exists. (3284) ========================================================== 16:32:24 (1787862744) [ 321.506423] Lustre: Failing over lustre-OST0000 [ 321.663916] Lustre: server umount lustre-OST0000 complete [ 322.017391] 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 [ 322.041304] Lustre: Skipped 1 previous similar message [ 327.135847] LustreError: 8193:0:(ldlm_lib.c:1228: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. [ 327.156898] LustreError: 8193:0:(ldlm_lib.c:1228:target_handle_connect()) Skipped 3 previous similar messages [ 330.199240] LustreError: 6675:0:(ldlm_lib.c:1228:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.201.28@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 332.257534] LustreError: 6676:0:(ldlm_lib.c:1228: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. [ 335.340914] LustreError: 12807:0:(ldlm_lib.c:1228:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.201.28@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 339.804871] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 340.432089] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 341.276743] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 341.283699] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 341.308846] Lustre: Skipped 1 previous similar message [ 346.705409] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 357.538311] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 359.007653] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 369.252984] Lustre: DEBUG MARKER: == replay-single test 0c: check replay-barrier =========== 16:33:13 (1787862793) [ 372.435385] LustreError: 14858:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 373.501970] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 375.978993] Lustre: Failing over lustre-MDT0000 [ 376.503472] Lustre: server umount lustre-MDT0000 complete [ 397.218669] Lustre: 3284:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787862807/real 1787862807] req@ffff93c69ca030c0 x1874709683721728/t0(0) o400->MGC192.168.201.128@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1787862823 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 397.230702] LustreError: MGC192.168.201.128@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 397.234941] 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 [ 402.399414] Lustre: 3284:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787862812/real 1787862812] req@ffff93c69489f480 x1874709683722240/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787862828 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 402.432546] Lustre: 3284:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 407.391204] Lustre: 3283:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787862817/real 1787862817] req@ffff93c683055e00 x1874709683722752/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787862833 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 407.443697] Lustre: 3283:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 407.996536] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 411.999120] Lustre: 3281:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787862822/real 1787862822] req@ffff93c683055a40 x1874709683723008/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787862838 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 412.041703] Lustre: 3281:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 413.104913] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 415.544050] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 415.549732] Lustre: lustre-MDT0000: Denying connection for new client 3439310d-6791-49c1-8832-62480ab40e3e (at 192.168.201.28@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:59 [ 420.816968] Lustre: lustre-MDT0000: Denying connection for new client 3439310d-6791-49c1-8832-62480ab40e3e (at 192.168.201.28@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:54 [ 422.372321] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 425.939599] Lustre: lustre-MDT0000: Denying connection for new client 3439310d-6791-49c1-8832-62480ab40e3e (at 192.168.201.28@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:49 [ 431.059066] Lustre: lustre-MDT0000: Denying connection for new client 3439310d-6791-49c1-8832-62480ab40e3e (at 192.168.201.28@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:44 [ 436.177810] Lustre: lustre-MDT0000: Denying connection for new client 3439310d-6791-49c1-8832-62480ab40e3e (at 192.168.201.28@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:39 [ 446.432684] Lustre: lustre-MDT0000: Denying connection for new client 3439310d-6791-49c1-8832-62480ab40e3e (at 192.168.201.28@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:29 [ 446.454111] Lustre: Skipped 1 previous similar message [ 466.899640] Lustre: lustre-MDT0000: Denying connection for new client 3439310d-6791-49c1-8832-62480ab40e3e (at 192.168.201.28@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:08 [ 466.923873] Lustre: Skipped 3 previous similar messages [ 475.501114] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 475.512154] Lustre: 15500:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 7f435183-71da-4394-8190-9f3d857d16f1@ [ 475.530451] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 475.631241] Lustre: lustre-MDT0000: Recovery over after 1:00, of 1 clients 0 recovered and 1 was evicted. [ 475.693137] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:44 to 0x280000400:65) [ 475.697996] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:44 to 0x240000400:65) [ 487.758605] Lustre: DEBUG MARKER: == replay-single test 0d: expired recovery with no clients ========================================================== 16:35:11 (1787862911) [ 490.557963] LustreError: 16241:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 491.439137] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 493.543687] Lustre: Failing over lustre-MDT0000 [ 494.039761] Lustre: server umount lustre-MDT0000 complete [ 510.303307] Lustre: 3282:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787862920/real 1787862920] req@ffff93c682f22d00 x1874709683746560/t0(0) o400->MGC192.168.201.128@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1787862936 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 510.336845] Lustre: 3282:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 2 previous similar messages [ 510.346929] LustreError: MGC192.168.201.128@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 511.391186] 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 [ 511.407614] Lustre: Skipped 1 previous similar message [ 521.292771] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 522.080506] Lustre: 3281:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787862930/real 1787862930] req@ffff93c6c0b670c0 x1874709683747584/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787862946 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 522.102698] Lustre: 3281:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 4 previous similar messages [ 522.229490] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 522.244566] Lustre: Skipped 1 previous similar message [ 526.607826] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 529.346769] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 529.352613] Lustre: lustre-MDT0000: Denying connection for new client 228e9f17-f086-45bd-bc43-7b46e1c29118 (at 192.168.201.28@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 1:00 [ 529.363449] Lustre: Skipped 1 previous similar message [ 589.502091] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 589.507607] Lustre: 16877:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 3439310d-6791-49c1-8832-62480ab40e3e@ [ 589.549509] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 589.669741] Lustre: lustre-MDT0000: Recovery over after 1:00, of 1 clients 0 recovered and 1 was evicted. [ 589.755438] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:44 to 0x280000400:97) [ 589.756089] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:44 to 0x240000400:97) [ 600.332914] Lustre: DEBUG MARKER: == replay-single test 1: simple create =================== 16:37:04 (1787863024) [ 603.558670] LustreError: 17614:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 604.441754] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 606.599837] Lustre: Failing over lustre-MDT0000 [ 606.884217] Lustre: server umount lustre-MDT0000 complete [ 625.631556] Lustre: 3283:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787863035/real 1787863035] req@ffff93c6aaf13840 x1874709683771520/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787863051 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 625.632203] 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 [ 625.663029] Lustre: 3283:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 7 previous similar messages [ 625.664546] LustreError: MGC192.168.201.128@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 625.693547] Lustre: Skipped 2 previous similar messages [ 635.356394] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 635.486031] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 637.904652] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 638.064464] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 638.135660] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:44 to 0x240000400:129) [ 638.136202] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:44 to 0x280000400:129) [ 640.703729] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 650.354343] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 650.595829] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 650.600053] Lustre: Skipped 1 previous similar message [ 651.762215] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 659.897793] Lustre: DEBUG MARKER: == replay-single test 2a: touch ========================== 16:38:04 (1787863084) [ 663.409751] LustreError: 19223:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 664.439412] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 666.563673] Lustre: Failing over lustre-MDT0000 [ 666.827468] Lustre: server umount lustre-MDT0000 complete [ 685.691566] LustreError: MGC192.168.201.128@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 685.928345] 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 [ 686.229632] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 687.007452] Lustre: 3281:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787863097/real 1787863097] req@ffff93c6bff31a40 x1874709683788160/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787863113 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 687.039979] Lustre: 3281:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 7 previous similar messages [ 690.626790] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 691.171118] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 691.175593] Lustre: Skipped 1 previous similar message [ 695.246675] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 695.455034] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 695.490630] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:131 to 0x280000400:161) [ 695.491286] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:44 to 0x240000400:161) [ 701.126587] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 703.034345] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 711.678682] Lustre: DEBUG MARKER: == replay-single test 2b: touch ========================== 16:38:56 (1787863136) [ 715.037166] LustreError: 20809:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 715.981616] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 718.493146] Lustre: Failing over lustre-MDT0000 [ 718.961724] Lustre: server umount lustre-MDT0000 complete [ 738.272716] 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 [ 738.273726] LustreError: MGC192.168.201.128@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 738.284265] Lustre: Skipped 2 previous similar messages [ 748.513297] LustreError: 3280:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff93c6916bed00 x1874709683805824/t0(0) o250->MGC192.168.201.128@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 [ 748.945935] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 748.948594] Lustre: Skipped 1 previous similar message [ 748.996428] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 752.754419] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 752.927091] Lustre: 3283:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787863163/real 1787863163] req@ffff93c6c0b66d00 x1874709683805312/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787863179 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 752.944670] Lustre: 3283:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 12 previous similar messages [ 761.810534] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 762.114517] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 762.153319] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:44 to 0x240000400:193) [ 762.153319] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:163 to 0x280000400:193) [ 763.365800] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 763.368891] Lustre: Skipped 1 previous similar message [ 769.149630] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 771.587609] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 782.797483] Lustre: DEBUG MARKER: == replay-single test 2c: setstripe replay =============== 16:40:07 (1787863207) [ 786.367773] LustreError: 22411:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 787.466294] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 790.201763] Lustre: Failing over lustre-MDT0000 [ 790.898727] Lustre: server umount lustre-MDT0000 complete [ 810.463435] 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 [ 810.470777] Lustre: Skipped 1 previous similar message [ 810.472635] LustreError: MGC192.168.201.128@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 820.751806] Lustre: MGS: Client a9b20336-9a01-47df-8d49-589a6dff6491 (at 0@lo) reconnecting [ 820.754809] Lustre: MGC192.168.201.128@tcp: Connection restored to 0@lo (at 0@lo) [ 820.760732] Lustre: Skipped 1 previous similar message [ 821.763403] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 827.331253] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 833.492850] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 833.764602] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 833.841507] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:225) [ 833.845791] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:225) [ 840.316061] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 841.814762] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 849.723282] Lustre: DEBUG MARKER: == replay-single test 2d: setdirstripe replay ============ 16:41:14 (1787863274) [ 852.552753] LustreError: 24000:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 853.541490] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 855.866859] Lustre: Failing over lustre-MDT0000 [ 856.031767] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 856.238511] Lustre: server umount lustre-MDT0000 complete [ 874.996682] LustreError: MGC192.168.201.128@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 875.004247] LustreError: Skipped 1 previous similar message [ 875.889928] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 877.377137] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:257) [ 877.379214] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:257) [ 881.381387] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 892.459874] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 894.473088] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 904.684434] Lustre: DEBUG MARKER: == replay-single test 2e: O_CREAT|O_EXCL create replay === 16:42:08 (1787863328) [ 905.656274] Lustre: *** cfs_fail_loc=13b, val=315*** [ 905.667051] Lustre: *** cfs_fail_loc=13b, val=2147483648*** [ 905.672729] LustreError: 24600:0:(ldlm_lib.c:3411:target_send_reply_msg()) @@@ dropping reply req@ffff93c6830543c0 x1874709673269760/t38654705666(0) o35->228e9f17-f086-45bd-bc43-7b46e1c29118@192.168.201.28@tcp:698/0 lens 392/456 e 0 to 0 dl 1787863348 ref 1 fl Interpret:/600/0 rc 0/0 job:'openfile.0' uid:0 gid:0 projid:0 [ 910.404504] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 912.099544] Lustre: Failing over lustre-MDT0000 [ 912.476738] Lustre: server umount lustre-MDT0000 complete [ 929.250844] Lustre: 3283:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787863339/real 1787863339] req@ffff93c6c199c000 x1874709683855872/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787863355 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 929.254451] 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 [ 929.271796] Lustre: 3283:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 11 previous similar messages [ 929.281162] Lustre: Skipped 2 previous similar messages [ 932.038304] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 932.042302] Lustre: Skipped 2 previous similar messages [ 932.097490] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 937.140838] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 937.361778] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 937.367820] Lustre: Skipped 1 previous similar message [ 937.472341] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 937.475331] Lustre: Skipped 1 previous similar message [ 937.538786] Lustre: 26242:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff93c6830570c0 x1874709673269760/t38654705666(0) o35->228e9f17-f086-45bd-bc43-7b46e1c29118@192.168.201.28@tcp:730/0 lens 392/456 e 0 to 0 dl 1787863380 ref 1 fl Interpret:/602/0 rc 0/0 job:'openfile.0' uid:0 gid:0 projid:0 [ 937.570462] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:289) [ 937.577221] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:289) [ 939.042799] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 939.055638] Lustre: Skipped 4 previous similar messages [ 947.788381] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 949.913356] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 958.927747] Lustre: DEBUG MARKER: == replay-single test 3a: replay failed open(O_DIRECTORY) ========================================================== 16:43:03 (1787863383) [ 961.676743] LustreError: 27220:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 961.682372] LustreError: 27220:0:(osd_handler.c:715:osd_ro()) Skipped 1 previous similar message [ 962.523348] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 964.471464] Lustre: Failing over lustre-MDT0000 [ 964.588375] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 964.596668] Lustre: Skipped 2 previous similar messages [ 964.817811] Lustre: server umount lustre-MDT0000 complete [ 983.200323] LustreError: MGC192.168.201.128@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 983.206942] LustreError: Skipped 1 previous similar message [ 983.745826] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 985.787725] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:321) [ 985.790117] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:321) [ 988.165327] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 998.150635] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 999.895742] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1008.792346] Lustre: DEBUG MARKER: == replay-single test 3b: replay failed open -ENOMEM ===== 16:43:53 (1787863433) [ 1012.701594] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1013.713613] Lustre: *** cfs_fail_loc=114, val=0*** [ 1016.343689] Lustre: Failing over lustre-MDT0000 [ 1016.567456] Lustre: server umount lustre-MDT0000 complete [ 1036.892644] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1042.093349] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1046.079841] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:353) [ 1046.081345] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:353) [ 1054.151059] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1055.896988] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1065.412782] Lustre: DEBUG MARKER: == replay-single test 3c: replay failed open -ENOMEM ===== 16:44:49 (1787863489) [ 1069.900967] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1071.197864] Lustre: *** cfs_fail_loc=128, val=0*** [ 1074.122398] Lustre: Failing over lustre-MDT0000 [ 1074.387841] Lustre: server umount lustre-MDT0000 complete [ 1093.579162] 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 [ 1093.617287] Lustre: Skipped 5 previous similar messages [ 1093.647566] LustreError: 31186:0:(ldlm_lib.c:1228: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. [ 1093.675240] LustreError: 31186:0:(ldlm_lib.c:1228:target_handle_connect()) Skipped 1 previous similar message [ 1098.145857] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 1098.160901] Lustre: Skipped 5 previous similar messages [ 1099.279143] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1103.311537] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1103.323215] Lustre: Skipped 2 previous similar messages [ 1103.445347] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1103.449506] Lustre: Skipped 2 previous similar messages [ 1103.485161] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:385) [ 1103.488588] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:385) [ 1110.987642] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1113.426063] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1123.742022] Lustre: DEBUG MARKER: == replay-single test 4a: |x| 10 open(O_CREAT)s ========== 16:45:47 (1787863547) [ 1127.585117] LustreError: 32166:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 1127.592978] LustreError: 32166:0:(osd_handler.c:715:osd_ro()) Skipped 2 previous similar messages [ 1128.584310] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1131.240048] Lustre: Failing over lustre-MDT0000 [ 1131.707836] Lustre: server umount lustre-MDT0000 complete [ 1150.432608] LustreError: MGC192.168.201.128@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1150.449787] LustreError: Skipped 2 previous similar messages [ 1160.675090] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xae04f0eb1c094a8 [ 1161.287802] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1161.297124] Lustre: Skipped 1 previous similar message [ 1166.005744] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1174.814844] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:391 to 0x280000400:417) [ 1174.819301] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:391 to 0x240000400:417) [ 1181.252993] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1183.517413] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1193.907537] Lustre: DEBUG MARKER: == replay-single test 4b: |x| rm 10 files ================ 16:46:57 (1787863617) [ 1198.216419] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1200.978649] Lustre: Failing over lustre-MDT0000 [ 1201.122117] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1201.127765] Lustre: Skipped 1 previous similar message [ 1201.516745] Lustre: server umount lustre-MDT0000 complete [ 1222.239775] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1222.244735] Lustre: Skipped 4 previous similar messages [ 1227.227792] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:423 to 0x240000400:449) [ 1227.227959] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:423 to 0x280000400:449) [ 1227.678617] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1238.045100] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1239.880866] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1249.281627] Lustre: DEBUG MARKER: == replay-single test 5: |x| 220 open(O_CREAT) =========== 16:47:53 (1787863673) [ 1253.880660] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1261.349575] Lustre: Failing over lustre-MDT0000 [ 1261.749649] Lustre: server umount lustre-MDT0000 complete [ 1278.367116] Lustre: 3282:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787863688/real 1787863688] req@ffff93c6bff30f00 x1874709683960320/t0(0) o400->MGC192.168.201.128@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1787863704 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1278.407588] Lustre: 3282:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 31 previous similar messages [ 1288.677095] LustreError: 3280:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff93c6aaf12580 x1874709683962752/t0(0) o250->MGC192.168.201.128@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 [ 1289.372045] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1289.389220] Lustre: Skipped 1 previous similar message [ 1293.955815] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1306.552685] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:577) [ 1306.552881] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:577) [ 1312.935131] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1314.391204] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1335.913804] Lustre: DEBUG MARKER: == replay-single test 6a: mkdir + contained create ======= 16:49:20 (1787863760) [ 1339.535318] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1341.288065] Lustre: Failing over lustre-MDT0000 [ 1341.648191] Lustre: server umount lustre-MDT0000 complete [ 1359.842033] 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 [ 1359.851074] Lustre: Skipped 6 previous similar messages [ 1370.019367] LustreError: 3280:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff93c581a4a940 x1874709684038400/t0(0) o250->MGC192.168.201.128@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 [ 1371.498297] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 1371.511023] Lustre: Skipped 8 previous similar messages [ 1374.687531] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1384.914300] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1384.939439] Lustre: Skipped 3 previous similar messages [ 1385.098525] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1385.103967] Lustre: Skipped 3 previous similar messages [ 1385.182651] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:609) [ 1385.188860] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:609) [ 1391.140784] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1393.300874] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1404.823132] Lustre: DEBUG MARKER: == replay-single test 6b: |X| rmdir ====================== 16:50:28 (1787863828) [ 1407.787280] LustreError: 38596:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 1407.795338] LustreError: 38596:0:(osd_handler.c:715:osd_ro()) Skipped 3 previous similar messages [ 1408.835455] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1411.168792] Lustre: Failing over lustre-MDT0000 [ 1411.475314] Lustre: server umount lustre-MDT0000 complete [ 1430.816380] LustreError: MGC192.168.201.128@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1430.842397] LustreError: Skipped 3 previous similar messages [ 1447.070922] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1456.798809] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:641) [ 1456.798992] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:641) [ 1462.136912] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1463.721112] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1472.111760] Lustre: DEBUG MARKER: == replay-single test 7: mkdir |X| contained create ====== 16:51:36 (1787863896) [ 1476.503821] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1478.167031] Lustre: Failing over lustre-MDT0000 [ 1478.411968] Lustre: server umount lustre-MDT0000 complete [ 1509.169875] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:673) [ 1509.172882] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:673) [ 1513.363946] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1523.424250] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1525.221200] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1534.510756] Lustre: DEBUG MARKER: == replay-single test 8: creat open |X| close ============ 16:52:38 (1787863958) [ 1538.658353] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1540.945819] Lustre: Failing over lustre-MDT0000 [ 1541.382560] Lustre: server umount lustre-MDT0000 complete [ 1568.845836] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1568.856272] Lustre: Skipped 3 previous similar messages [ 1571.673234] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:705) [ 1571.674085] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:705) [ 1574.692264] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1584.772891] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1586.411259] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1595.936805] Lustre: DEBUG MARKER: == replay-single test 9: |X| create (same inum/gen) ====== 16:53:39 (1787864019) [ 1600.085952] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1602.469910] Lustre: Failing over lustre-MDT0000 [ 1602.890528] Lustre: server umount lustre-MDT0000 complete [ 1633.972183] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:737) [ 1633.973014] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:737) [ 1635.013469] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1645.303903] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1646.768723] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1655.351956] Lustre: DEBUG MARKER: == replay-single test 10: create |X| rename unlink ======= 16:54:39 (1787864079) [ 1659.644823] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1661.818473] Lustre: Failing over lustre-MDT0000 [ 1662.145458] Lustre: server umount lustre-MDT0000 complete [ 1687.793729] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1690.195289] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:769) [ 1690.214197] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:769) [ 1697.965574] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1699.578720] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1706.986824] Lustre: DEBUG MARKER: == replay-single test 11: create open write rename |X| create-old-name read ========================================================== 16:55:31 (1787864131) [ 1711.386309] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1713.690500] Lustre: Failing over lustre-MDT0000 [ 1714.036457] Lustre: server umount lustre-MDT0000 complete [ 1733.616574] LustreError: 47137:0:(ldlm_lib.c:1228: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. [ 1739.614116] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1741.513269] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:771 to 0x280000400:801) [ 1741.515579] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:771 to 0x240000400:801) [ 1749.899250] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1752.073272] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1761.420247] Lustre: DEBUG MARKER: == replay-single test 12: open, unlink |X| close ========= 16:56:26 (1787864186) [ 1765.727875] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1767.851095] Lustre: Failing over lustre-MDT0000 [ 1768.239629] Lustre: server umount lustre-MDT0000 complete [ 1791.456069] Lustre: 3283:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787864201/real 1787864201] req@ffff93c6ba7ead00 x1874709684152832/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787864217 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1791.493400] Lustre: 3283:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 67 previous similar messages [ 1796.577731] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xae04f0eb1c15c7c [ 1797.143763] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1797.148765] Lustre: Skipped 8 previous similar messages [ 1797.821603] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:771 to 0x280000400:833) [ 1797.825264] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:771 to 0x240000400:833) [ 1802.584906] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1812.995931] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1814.526147] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1823.548983] Lustre: DEBUG MARKER: == replay-single test 13: open chmod 0 |x| write close === 16:57:27 (1787864247) [ 1827.685802] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1829.639621] Lustre: Failing over lustre-MDT0000 [ 1829.861472] Lustre: server umount lustre-MDT0000 complete [ 1849.179273] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:771 to 0x240000400:865) [ 1849.179817] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:835 to 0x280000400:865) [ 1855.163573] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1866.620537] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1868.634186] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1878.329808] Lustre: DEBUG MARKER: == replay-single test 14: open(O_CREAT), unlink |X| close ========================================================== 16:58:22 (1787864302) [ 1882.220300] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1884.105744] Lustre: Failing over lustre-MDT0000 [ 1884.416770] Lustre: server umount lustre-MDT0000 complete [ 1900.003636] 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 [ 1900.020849] Lustre: Skipped 17 previous similar messages [ 1910.055712] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1910.239624] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1910.253941] Lustre: Skipped 8 previous similar messages [ 1910.570081] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 1910.576456] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1910.588770] Lustre: Skipped 18 previous similar messages [ 1910.607887] Lustre: Skipped 8 previous similar messages [ 1910.663869] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:835 to 0x280000400:897) [ 1910.664616] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:867 to 0x240000400:897) [ 1919.824725] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1921.927629] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1931.109637] Lustre: DEBUG MARKER: == replay-single test 15: open(O_CREAT), unlink |X| touch new, close ========================================================== 16:59:15 (1787864355) [ 1934.531627] LustreError: 52881:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 1934.537987] LustreError: 52881:0:(osd_handler.c:715:osd_ro()) Skipped 8 previous similar messages [ 1935.592665] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1937.660690] Lustre: Failing over lustre-MDT0000 [ 1938.026742] Lustre: server umount lustre-MDT0000 complete [ 1956.838692] LustreError: MGC192.168.201.128@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1956.852812] LustreError: Skipped 8 previous similar messages [ 1967.084617] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xae04f0eb1c16b08 [ 1972.785226] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1982.158645] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:899 to 0x240000400:929) [ 1982.160544] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:899 to 0x280000400:929) [ 1987.841103] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1989.427219] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1998.412951] Lustre: DEBUG MARKER: == replay-single test 16: |X| open(O_CREAT), unlink, touch new, unlink new ========================================================== 17:00:22 (1787864422) [ 2002.005935] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2003.769695] Lustre: Failing over lustre-MDT0000 [ 2004.033795] Lustre: server umount lustre-MDT0000 complete [ 2033.123109] LustreError: 55071:0:(ldlm_lib.c:1228:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.201.28@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 2033.150487] LustreError: 55071:0:(ldlm_lib.c:1228:target_handle_connect()) Skipped 1 previous similar message [ 2035.085313] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:899 to 0x280000400:961) [ 2035.087482] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:931 to 0x240000400:961) [ 2039.535795] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2051.603759] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2053.595794] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2062.561726] Lustre: DEBUG MARKER: == replay-single test 17: |X| open(O_CREAT), |replay| close ========================================================== 17:01:26 (1787864486) [ 2066.277100] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2068.201339] Lustre: Failing over lustre-MDT0000 [ 2068.545398] Lustre: server umount lustre-MDT0000 complete [ 2097.864695] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 2097.882532] Lustre: Skipped 8 previous similar messages [ 2103.199908] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2110.199381] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:963 to 0x240000400:993) [ 2110.200398] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:899 to 0x280000400:993) [ 2116.039913] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2117.571536] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2126.251693] Lustre: DEBUG MARKER: == replay-single test 18: open(O_CREAT), unlink, touch new, close, touch, unlink ========================================================== 17:02:30 (1787864550) [ 2130.226079] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2131.847297] Lustre: Failing over lustre-MDT0000 [ 2132.130436] Lustre: server umount lustre-MDT0000 complete [ 2151.890647] Lustre: MGS: Not available for connect from 192.168.201.28@tcp (not set up) [ 2161.586116] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:995 to 0x240000400:1025) [ 2161.586834] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:995 to 0x280000400:1025) [ 2162.349328] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2171.800950] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2173.418951] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2181.554915] Lustre: DEBUG MARKER: == replay-single test 19: mcreate, open, write, rename === 17:03:26 (1787864606) [ 2185.474415] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2187.380930] Lustre: Failing over lustre-MDT0000 [ 2187.649361] Lustre: server umount lustre-MDT0000 complete [ 2213.868755] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xae04f0eb1c18055 [ 2217.649596] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1027 to 0x240000400:1057) [ 2217.649648] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1027 to 0x280000400:1057) [ 2218.189290] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2229.872567] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2231.534321] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2240.524551] Lustre: DEBUG MARKER: == replay-single test 20a: |X| open(O_CREAT), unlink, replay, close (test mds_cleanup_orphans) ========================================================== 17:04:24 (1787864664) [ 2244.508321] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2246.712605] Lustre: Failing over lustre-MDT0000 [ 2247.314744] Lustre: server umount lustre-MDT0000 complete [ 2272.339181] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2274.901112] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1059 to 0x280000400:1089) [ 2274.907085] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1027 to 0x240000400:1089) [ 2281.880346] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2283.530074] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2292.456517] Lustre: DEBUG MARKER: == replay-single test 20b: write, unlink, eviction, replay (test mds_cleanup_orphans) ========================================================== 17:05:16 (1787864716) [ 2297.263038] Lustre: 62454:0:(genops.c:1774:obd_export_evict_by_uuid()) lustre-MDT0000: evicting 228e9f17-f086-45bd-bc43-7b46e1c29118 at adminstrative request [ 2304.196248] Lustre: Failing over lustre-MDT0000 [ 2304.431988] Lustre: server umount lustre-MDT0000 complete [ 2338.231361] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2346.571688] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1091 to 0x240000400:1121) [ 2346.578470] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1059 to 0x280000400:1121) [ 2352.045954] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2353.698980] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2360.117726] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 2374.485097] Lustre: DEBUG MARKER: before 4096, after 4096 [ 2381.317838] Lustre: DEBUG MARKER: == replay-single test 20c: check that client eviction does not affect file content ========================================================== 17:06:45 (1787864805) [ 2382.426202] Lustre: 64543:0:(genops.c:1774:obd_export_evict_by_uuid()) lustre-MDT0000: evicting 228e9f17-f086-45bd-bc43-7b46e1c29118 at adminstrative request [ 2393.626947] Lustre: DEBUG MARKER: == replay-single test 21: |X| open(O_CREAT), unlink touch new, replay, close (test mds_cleanup_orphans) ========================================================== 17:06:57 (1787864817) [ 2397.507336] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2399.411434] Lustre: Failing over lustre-MDT0000 [ 2399.716268] LustreError: 63063:0:(ldlm_lib.c:1228: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. [ 2399.780921] Lustre: server umount lustre-MDT0000 complete [ 2418.982533] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 2418.986991] Lustre: Skipped 9 previous similar messages [ 2423.923727] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2428.627853] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1123 to 0x280000400:1153) [ 2428.628692] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1124 to 0x240000400:1153) [ 2434.718406] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2436.045575] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2445.348748] Lustre: DEBUG MARKER: == replay-single test 22: open(O_CREAT), |X| unlink, replay, close (test mds_cleanup_orphans) ========================================================== 17:07:49 (1787864869) [ 2449.292750] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2451.264017] Lustre: Failing over lustre-MDT0000 [ 2451.521269] Lustre: server umount lustre-MDT0000 complete [ 2471.839125] Lustre: 3281:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787864881/real 1787864881] req@ffff93c6aa45de00 x1874709684342144/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787864897 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2471.872788] Lustre: 3281:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 78 previous similar messages [ 2476.341410] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2479.801848] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1155 to 0x280000400:1185) [ 2479.805438] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1155 to 0x240000400:1185) [ 2486.531499] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2488.495263] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2497.913213] Lustre: DEBUG MARKER: == replay-single test 23: open(O_CREAT), |X| unlink touch new, replay, close (test mds_cleanup_orphans) ========================================================== 17:08:42 (1787864922) [ 2502.868296] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2504.941139] Lustre: Failing over lustre-MDT0000 [ 2505.181961] Lustre: lustre-MDT0000: Not available for connect from 192.168.201.28@tcp (stopping) [ 2505.276752] Lustre: server umount lustre-MDT0000 complete [ 2524.771124] 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 [ 2524.781159] Lustre: Skipped 19 previous similar messages [ 2524.787551] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 2524.794515] Lustre: Skipped 21 previous similar messages [ 2525.651456] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 2525.653625] Lustre: Skipped 9 previous similar messages [ 2525.953246] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 2525.969425] Lustre: Skipped 9 previous similar messages [ 2526.037412] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1187 to 0x280000400:1217) [ 2526.037509] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1187 to 0x240000400:1217) [ 2528.138233] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2538.991996] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2540.731461] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2550.381714] Lustre: DEBUG MARKER: == replay-single test 24: open(O_CREAT), replay, unlink, close (test mds_cleanup_orphans) ========================================================== 17:09:34 (1787864974) [ 2553.611625] LustreError: 69639:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 2553.621595] LustreError: 69639:0:(osd_handler.c:715:osd_ro()) Skipped 8 previous similar messages [ 2554.520922] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2556.512867] Lustre: Failing over lustre-MDT0000 [ 2556.728145] Lustre: server umount lustre-MDT0000 complete [ 2575.110669] LustreError: MGC192.168.201.128@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2575.120205] LustreError: Skipped 9 previous similar messages [ 2577.027403] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1219 to 0x240000400:1249) [ 2577.030388] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1219 to 0x280000400:1249) [ 2580.648393] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2591.482659] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2593.092830] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2601.961782] Lustre: DEBUG MARKER: == replay-single test 25: open(O_CREAT), unlink, replay, close (test mds_cleanup_orphans) ========================================================== 17:10:26 (1787865026) [ 2606.890688] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2608.876807] Lustre: Failing over lustre-MDT0000 [ 2609.277912] Lustre: server umount lustre-MDT0000 complete [ 2639.620121] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1251 to 0x280000400:1281) [ 2639.620404] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1219 to 0x240000400:1281) [ 2642.766835] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2652.204242] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2653.766198] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2662.354894] Lustre: DEBUG MARKER: == replay-single test 26: |X| open(O_CREAT), unlink two, close one, replay, close one (test mds_cleanup_orphans) ========================================================== 17:11:27 (1787865087) [ 2666.532804] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2669.108861] Lustre: Failing over lustre-MDT0000 [ 2669.405288] Lustre: server umount lustre-MDT0000 complete [ 2698.212734] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xae04f0eb1c1a7ae [ 2699.293686] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 2699.304649] Lustre: Skipped 9 previous similar messages [ 2705.974797] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2711.270429] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1283 to 0x280000400:1313) [ 2711.278311] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1283 to 0x240000400:1313) [ 2717.562413] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2719.672414] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2729.147665] Lustre: DEBUG MARKER: == replay-single test 27: |X| open(O_CREAT), unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 17:12:33 (1787865153) [ 2734.907377] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2737.065325] Lustre: Failing over lustre-MDT0000 [ 2737.386567] Lustre: server umount lustre-MDT0000 complete [ 2764.773040] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xae04f0eb1c1ad11 [ 2767.638367] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1315 to 0x240000400:1345) [ 2767.638378] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1315 to 0x280000400:1345) [ 2770.602699] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2780.167740] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2781.972370] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2791.758896] Lustre: DEBUG MARKER: == replay-single test 28: open(O_CREAT), |X| unlink two, close one, replay, close one (test mds_cleanup_orphans) ========================================================== 17:13:35 (1787865215) [ 2797.733746] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2800.046593] Lustre: Failing over lustre-MDT0000 [ 2800.326876] Lustre: server umount lustre-MDT0000 complete [ 2828.575668] LustreError: 3280:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff93c684226580 x1874709684444416/t0(0) o250->MGC192.168.201.128@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 [ 2830.061232] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1347 to 0x280000400:1377) [ 2830.062070] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1347 to 0x240000400:1377) [ 2834.929525] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2844.623488] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2846.382380] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2855.020731] Lustre: DEBUG MARKER: == replay-single test 29: open(O_CREAT), |X| unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 17:14:39 (1787865279) [ 2858.980294] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2860.682834] Lustre: Failing over lustre-MDT0000 [ 2861.113644] Lustre: server umount lustre-MDT0000 complete [ 2889.704868] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xae04f0eb1c1b7e5 [ 2891.568816] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1379 to 0x240000400:1409) [ 2891.570545] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1379 to 0x280000400:1409) [ 2896.265274] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2906.695983] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2908.629390] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2918.984694] Lustre: DEBUG MARKER: == replay-single test 30: open(O_CREAT) two, unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 17:15:43 (1787865343) [ 2923.634527] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2925.981720] Lustre: Failing over lustre-MDT0000 [ 2926.433391] Lustre: server umount lustre-MDT0000 complete [ 2945.509122] LustreError: 79763:0:(ldlm_lib.c:1228: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. [ 2951.228222] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2952.717573] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1411 to 0x240000400:1441) [ 2952.721140] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1411 to 0x280000400:1441) [ 2962.552431] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 2964.467433] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2974.034954] Lustre: DEBUG MARKER: == replay-single test 31: open(O_CREAT) two, unlink one, |X| unlink one, close two (test mds_cleanup_orphans) ========================================================== 17:16:38 (1787865398) [ 2978.891819] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2981.566102] Lustre: Failing over lustre-MDT0000 [ 2981.888965] Lustre: server umount lustre-MDT0000 complete [ 3000.791495] LustreError: 81345:0:(ldlm_lib.c:1228:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.201.28@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3000.816323] LustreError: 81345:0:(ldlm_lib.c:1228:target_handle_connect()) Skipped 1 previous similar message [ 3002.444508] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1443 to 0x240000400:1473) [ 3002.447446] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1443 to 0x280000400:1473) [ 3006.016142] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3016.804166] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3018.928816] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3029.601853] Lustre: DEBUG MARKER: == replay-single test 32: close() notices client eviction; close() after client eviction ========================================================== 17:17:34 (1787865454) [ 3030.752433] Lustre: 82232:0:(genops.c:1774:obd_export_evict_by_uuid()) lustre-MDT0000: evicting 228e9f17-f086-45bd-bc43-7b46e1c29118 at adminstrative request [ 3039.021324] Lustre: DEBUG MARKER: == replay-single test 33a: fid seq shouldn't be reused after abort recovery ========================================================== 17:17:43 (1787865463) [ 3041.994382] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3043.849493] Lustre: Failing over lustre-MDT0000 [ 3044.164214] Lustre: server umount lustre-MDT0000 complete [ 3055.560499] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3055.568510] Lustre: Skipped 10 previous similar messages [ 3055.706738] Lustre: lustre-MDT0000: Aborting client recovery [ 3055.719579] LustreError: 83149:0:(ldlm_lib.c:3067:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 3055.739693] Lustre: 83196:0:(ldlm_lib.c:2467:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 3055.759548] Lustre: 83196:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 228e9f17-f086-45bd-bc43-7b46e1c29118@ [ 3055.778213] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 3055.901898] Lustre: lustre-MDT0000-osd: cancel update llog [0x200000400:0x1:0x0] [ 3056.180482] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1480 to 0x280000400:1505) [ 3056.186247] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1479 to 0x240000400:1505) [ 3062.354806] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3078.202922] Lustre: DEBUG MARKER: == replay-single test 33b: test fid seq allocation ======= 17:18:22 (1787865502) [ 3082.885407] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3084.646588] Lustre: Failing over lustre-MDT0000 [ 3085.112923] Lustre: server umount lustre-MDT0000 complete [ 3096.842544] Lustre: *** cfs_fail_loc=1311, val=0*** [ 3096.927492] Lustre: lustre-MDT0000: Aborting client recovery [ 3096.929964] LustreError: 84510:0:(ldlm_lib.c:3067:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 3096.934847] Lustre: 84555:0:(ldlm_lib.c:2467:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 3096.939403] Lustre: 84555:0:(ldlm_lib.c:2467:target_recovery_overseer()) Skipped 2 previous similar messages [ 3096.944993] Lustre: 84555:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 228e9f17-f086-45bd-bc43-7b46e1c29118@ [ 3096.951175] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 3097.026452] Lustre: lustre-MDT0000-osd: cancel update llog [0x200015bc0:0x1:0x0] [ 3097.188383] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1516 to 0x280000400:1537) [ 3097.195679] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1516 to 0x240000400:1537) [ 3102.069992] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3102.687297] Lustre: 3283:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787865512/real 1787865512] req@ffff93c6913e3840 x1874709684532736/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787865528 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3102.719908] Lustre: 3283:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 87 previous similar messages [ 3108.097200] Lustre: *** cfs_fail_loc=1311, val=0*** [ 3115.057377] Lustre: DEBUG MARKER: == replay-single test 34: abort recovery before client does replay (test mds_cleanup_orphans) ========================================================== 17:18:59 (1787865539) [ 3119.478449] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3121.430892] Lustre: Failing over lustre-MDT0000 [ 3121.730698] Lustre: server umount lustre-MDT0000 complete [ 3132.386038] 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 [ 3132.396996] Lustre: Skipped 22 previous similar messages [ 3132.405316] LustreError: 85903:0:(ldlm_lib.c:1228: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. [ 3133.040364] Lustre: lustre-MDT0000: Aborting client recovery [ 3133.043506] LustreError: 85892:0:(ldlm_lib.c:3067:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 3133.050611] Lustre: 85938:0:(ldlm_lib.c:2467:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 3133.055582] Lustre: 85938:0:(ldlm_lib.c:2467:target_recovery_overseer()) Skipped 2 previous similar messages [ 3133.060875] Lustre: 85938:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 228e9f17-f086-45bd-bc43-7b46e1c29118@ [ 3133.067612] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 3133.160532] Lustre: lustre-MDT0000-osd: cancel update llog [0x200016778:0x1:0x0] [ 3133.350063] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1544 to 0x280000400:1569) [ 3133.352533] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1543 to 0x240000400:1569) [ 3138.017722] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 3138.027896] Lustre: Skipped 24 previous similar messages [ 3139.573856] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3152.813706] Lustre: DEBUG MARKER: == replay-single test 35: test recovery from llog for unlink op ========================================================== 17:19:37 (1787865577) [ 3154.063686] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 3154.065638] LustreError: 86360:0:(ldlm_lib.c:3411:target_send_reply_msg()) @@@ dropping reply req@ffff93c58420f480 x1874709674273408/t201863462916(0) o36->228e9f17-f086-45bd-bc43-7b46e1c29118@192.168.201.28@tcp:676/0 lens 512/456 e 0 to 0 dl 1787865591 ref 1 fl Interpret:/200/0 rc 0/0 job:'rm.0' uid:0 gid:0 projid:4294967295 [ 3158.208280] Lustre: Failing over lustre-MDT0000 [ 3158.581638] Lustre: server umount lustre-MDT0000 complete [ 3168.749640] Lustre: lustre-MDT0000: Aborting client recovery [ 3168.751035] LustreError: 87102:0:(ldlm_lib.c:3067:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 3168.753442] Lustre: 87149:0:(ldlm_lib.c:2467:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 3168.755495] Lustre: 87149:0:(ldlm_lib.c:2467:target_recovery_overseer()) Skipped 2 previous similar messages [ 3168.762257] Lustre: 87149:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 228e9f17-f086-45bd-bc43-7b46e1c29118@ [ 3168.769623] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 3168.799737] Lustre: lustre-MDT0000-osd: cancel update llog [0x200017330:0x1:0x0] [ 3168.916702] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1544 to 0x280000400:1601) [ 3168.920636] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1571 to 0x240000400:1601) [ 3173.700389] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3186.462970] Lustre: DEBUG MARKER: SKIP: replay-single test_36 skipping ALWAYS excluded test 36 [ 3188.275796] Lustre: DEBUG MARKER: == replay-single test 37: abort recovery before client does replay (test mds_cleanup_orphans for directories) ========================================================== 17:20:12 (1787865612) [ 3192.573956] LustreError: 87901:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 3192.584115] LustreError: 87901:0:(osd_handler.c:715:osd_ro()) Skipped 10 previous similar messages [ 3194.021656] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3198.157157] Lustre: Failing over lustre-MDT0000 [ 3198.607721] Lustre: server umount lustre-MDT0000 complete [ 3208.097746] LustreError: MGC192.168.201.128@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3208.111910] LustreError: Skipped 11 previous similar messages [ 3208.726954] Lustre: lustre-MDT0000: Aborting client recovery [ 3208.730637] LustreError: 88565:0:(ldlm_lib.c:3067:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 3208.735452] Lustre: 88611:0:(ldlm_lib.c:2467:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 3208.738610] Lustre: 88611:0:(ldlm_lib.c:2467:target_recovery_overseer()) Skipped 2 previous similar messages [ 3208.746549] Lustre: 88611:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 228e9f17-f086-45bd-bc43-7b46e1c29118@ [ 3208.760256] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 3208.824462] Lustre: lustre-MDT0000-osd: cancel update llog [0x200017b00:0x1:0x0] [ 3208.995062] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1571 to 0x240000400:1633) [ 3208.995494] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1544 to 0x280000400:1633) [ 3213.614502] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3227.783717] Lustre: DEBUG MARKER: == replay-single test 38: test recovery from unlink llog (test llog_gen_rec) ========================================================== 17:20:52 (1787865652) [ 3257.379754] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3258.941049] Lustre: Failing over lustre-MDT0000 [ 3259.199271] Lustre: server umount lustre-MDT0000 complete [ 3286.498024] LustreError: 3280:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff93c581c71a40 x1874709684654208/t0(0) o250->MGC192.168.201.128@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 [ 3288.024965] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 3288.031784] Lustre: Skipped 8 previous similar messages [ 3288.210140] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 3288.213010] Lustre: Skipped 8 previous similar messages [ 3288.240443] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2034 to 0x240000400:2049) [ 3288.240443] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2034 to 0x280000400:2049) [ 3291.791867] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3302.076439] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3304.513370] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3324.496280] Lustre: DEBUG MARKER: == replay-single test 39: test recovery from unlink llog (test llog_gen_rec) ========================================================== 17:22:29 (1787865749) [ 3345.146454] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3356.410656] Lustre: Failing over lustre-MDT0000 [ 3356.696027] Lustre: server umount lustre-MDT0000 complete [ 3383.286109] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xae04f0eb1c4354e [ 3383.945813] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 3383.957062] Lustre: Skipped 21 previous similar messages [ 3388.481606] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3391.135596] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2450 to 0x280000400:2465) [ 3391.141654] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2450 to 0x240000400:2465) [ 3397.894624] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3399.341987] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3425.265518] Lustre: DEBUG MARKER: == replay-single test 41: read from a valid osc while other oscs are invalid ========================================================== 17:24:09 (1787865849) [ 3427.989786] Lustre: setting import lustre-OST0001_UUID INACTIVE by administrator request [ 3429.268158] Lustre: lustre-OST0001: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnecting [ 3429.278084] LustreError: lustre-OST0001-osc-MDT0000: This client was evicted by lustre-OST0001; in progress operations using this service will fail. [ 3436.846454] Lustre: DEBUG MARKER: == replay-single test 42: recovery after ost failure ===== 17:24:21 (1787865861) [ 3457.159271] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 3468.166241] Lustre: Failing over lustre-OST0000 [ 3468.257733] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -19 [ 3468.264464] Lustre: lustre-OST0000: Not available for connect from 0@lo (stopping) [ 3468.392677] Lustre: server umount lustre-OST0000 complete [ 3473.370857] LustreError: 36657:0:(ldlm_lib.c:1228:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.201.28@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3473.381974] LustreError: 36657:0:(ldlm_lib.c:1228:target_handle_connect()) Skipped 1 previous similar message [ 3493.556308] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3552.684996] Lustre: DEBUG MARKER: == replay-single test 43: mds osc import failure during recovery; don't LBUG ========================================================== 17:26:17 (1787865977) [ 3556.770716] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3560.035708] Lustre: Failing over lustre-MDT0000 [ 3560.316794] Lustre: server umount lustre-MDT0000 complete [ 3580.092043] Lustre: *** cfs_fail_loc=204, val=2147483648*** [ 3580.096187] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2866 to 0x280000400:2881) [ 3584.135979] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3594.600437] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3596.202487] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3596.260605] LustreError: 96565:0:(osp_precreate.c:974:osp_precreate_cleanup_orphans()) lustre-OST0000-osc-MDT0000: cannot cleanup orphans: rc = -11 [ 3596.268153] Lustre: lustre-OST0000: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnecting [ 3597.279630] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2867 to 0x240000400:2913) [ 3615.756984] Lustre: DEBUG MARKER: == replay-single test 44a: race in target handle connect ========================================================== 17:27:19 (1787866039) [ 3621.593225] LustreError: 96541:0:(ldlm_lib.c:1214:target_handle_connect()) cfs_race id 701 sleeping [ 3626.975889] LustreError: 96541:0:(ldlm_lib.c:1214:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 3626.982194] Lustre: lustre-MDT0000: Client 228e9f17-f086-45bd-bc43-7b46e1c29118 (at 192.168.201.28@tcp) reconnecting [ 3627.025385] LustreError: 36656:0:(ldlm_lib.c:1214:target_handle_connect()) cfs_fail_race id 701 waking [ 3628.827716] LustreError: 96542:0:(ldlm_lib.c:1214:target_handle_connect()) cfs_race id 701 sleeping [ 3634.143119] LustreError: 96542:0:(ldlm_lib.c:1214:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 3634.147303] Lustre: lustre-MDT0000: Client 228e9f17-f086-45bd-bc43-7b46e1c29118 (at 192.168.201.28@tcp) reconnecting [ 3635.880044] LustreError: 96543:0:(ldlm_lib.c:1214:target_handle_connect()) cfs_race id 701 sleeping [ 3641.313871] LustreError: 96543:0:(ldlm_lib.c:1214:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 3641.342630] Lustre: lustre-MDT0000: Client 228e9f17-f086-45bd-bc43-7b46e1c29118 (at 192.168.201.28@tcp) reconnecting [ 3643.989040] LustreError: 96542:0:(ldlm_lib.c:1214:target_handle_connect()) cfs_race id 701 sleeping [ 3649.503159] LustreError: 96542:0:(ldlm_lib.c:1214:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 3649.511829] Lustre: lustre-MDT0000: Client 228e9f17-f086-45bd-bc43-7b46e1c29118 (at 192.168.201.28@tcp) reconnecting [ 3651.871947] LustreError: 96542:0:(ldlm_lib.c:1214:target_handle_connect()) cfs_race id 701 sleeping [ 3657.183846] LustreError: 96542:0:(ldlm_lib.c:1214:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 3666.069544] LustreError: 96543:0:(ldlm_lib.c:1214:target_handle_connect()) cfs_race id 701 sleeping [ 3666.081659] LustreError: 96543:0:(ldlm_lib.c:1214:target_handle_connect()) Skipped 1 previous similar message [ 3671.523462] LustreError: 96543:0:(ldlm_lib.c:1214:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 3671.532929] LustreError: 96543:0:(ldlm_lib.c:1214:target_handle_connect()) Skipped 1 previous similar message [ 3671.549439] Lustre: lustre-MDT0000: Client 228e9f17-f086-45bd-bc43-7b46e1c29118 (at 192.168.201.28@tcp) reconnecting [ 3671.569370] Lustre: Skipped 2 previous similar messages [ 3687.662521] LustreError: 97654:0:(ldlm_lib.c:1214:target_handle_connect()) cfs_race id 701 sleeping [ 3687.668210] LustreError: 97654:0:(ldlm_lib.c:1214:target_handle_connect()) Skipped 2 previous similar messages [ 3693.024745] LustreError: 97654:0:(ldlm_lib.c:1214:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 3693.029616] LustreError: 97654:0:(ldlm_lib.c:1214:target_handle_connect()) Skipped 2 previous similar messages [ 3701.148526] Lustre: DEBUG MARKER: == replay-single test 44b: race in target handle connect ========================================================== 17:28:45 (1787866125) [ 3702.836804] LustreError: 97957:0:(ldlm_lib.c:1472:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 3712.976157] Lustre: lustre-MDT0000: Export ffff93c686bd8800 already connecting from 192.168.201.28@tcp [ 3718.108414] Lustre: lustre-MDT0000: Export ffff93c686bd8800 already connecting from 192.168.201.28@tcp [ 3723.214862] Lustre: lustre-MDT0000: Export ffff93c686bd8800 already connecting from 192.168.201.28@tcp [ 3726.394343] Lustre: lustre-MDT0000: Export ffff93c686bd8800 already connecting from 192.168.201.28@tcp [ 3733.455886] Lustre: lustre-MDT0000: Export ffff93c686bd8800 already connecting from 192.168.201.28@tcp [ 3733.458907] Lustre: Skipped 1 previous similar message [ 3742.919224] LustreError: 97957:0:(ldlm_lib.c:1472:target_handle_connect()) cfs_fail_timeout id 704 awake [ 3742.934345] Lustre: 97957:0:(service.c:2582:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/20s); client may timeout req@ffff93c58420c3c0 x1874709676914432/t0(0) o38->228e9f17-f086-45bd-bc43-7b46e1c29118@192.168.201.28@tcp:0/0 lens 520/416 e 0 to 0 dl 1787866149 ref 1 fl Complete:H/200/0 rc 0/0 job:'lctl.0' uid:0 gid:0 projid:4294967295 [ 3743.699514] Lustre: lustre-MDT0000: Client 228e9f17-f086-45bd-bc43-7b46e1c29118 (at 192.168.201.28@tcp) reconnecting [ 3743.707956] Lustre: Skipped 4 previous similar messages [ 3743.725140] LustreError: 97654:0:(ldlm_lib.c:1472:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 3768.280141] Lustre: lustre-MDT0000: Export ffff93c686bd8800 already connecting from 192.168.201.28@tcp [ 3768.291523] Lustre: Skipped 1 previous similar message [ 3783.817223] LustreError: 97654:0:(ldlm_lib.c:1472:target_handle_connect()) cfs_fail_timeout id 704 awake [ 3783.831049] Lustre: 97654:0:(service.c:2582:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/21s); client may timeout req@ffff93c5842312c0 x1874709676917760/t0(0) o38->228e9f17-f086-45bd-bc43-7b46e1c29118@192.168.201.28@tcp:0/0 lens 520/416 e 0 to 0 dl 1787866189 ref 1 fl Complete:H/200/0 rc 0/0 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3788.752138] LustreError: 96543:0:(ldlm_lib.c:1472:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 3813.342562] Lustre: lustre-MDT0000: Export ffff93c686bd8800 already connecting from 192.168.201.28@tcp [ 3813.357089] Lustre: Skipped 4 previous similar messages [ 3828.791149] LustreError: 96543:0:(ldlm_lib.c:1472:target_handle_connect()) cfs_fail_timeout id 704 awake [ 3828.804118] Lustre: 96543:0:(service.c:2582:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/20s); client may timeout req@ffff93c6880c03c0 x1874709676919936/t0(0) o38->228e9f17-f086-45bd-bc43-7b46e1c29118@192.168.201.28@tcp:0/0 lens 520/416 e 0 to 0 dl 1787866235 ref 1 fl Complete:H/200/0 rc 0/0 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3833.300863] Lustre: lustre-MDT0000: Client 228e9f17-f086-45bd-bc43-7b46e1c29118 (at 192.168.201.28@tcp) reconnecting [ 3833.321919] Lustre: Skipped 1 previous similar message [ 3833.339045] LustreError: 97654:0:(ldlm_lib.c:1472:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 3858.895921] Lustre: lustre-MDT0000: Export ffff93c686bd8800 already connecting from 192.168.201.28@tcp [ 3858.905882] Lustre: Skipped 3 previous similar messages [ 3873.391139] LustreError: 97654:0:(ldlm_lib.c:1472:target_handle_connect()) cfs_fail_timeout id 704 awake [ 3873.401685] Lustre: 97654:0:(service.c:2582:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/20s); client may timeout req@ffff93c58420cb40 x1874709676921984/t0(0) o38->228e9f17-f086-45bd-bc43-7b46e1c29118@192.168.201.28@tcp:0/0 lens 520/416 e 0 to 0 dl 1787866279 ref 1 fl Complete:H/200/0 rc 0/0 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3874.263863] LustreError: 96542:0:(ldlm_lib.c:1472:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 3914.343145] LustreError: 96542:0:(ldlm_lib.c:1472:target_handle_connect()) cfs_fail_timeout id 704 awake [ 3914.367402] Lustre: 96542:0:(service.c:2582:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/20s); client may timeout req@ffff93c6ba40bc00 x1874709676923904/t0(0) o38->228e9f17-f086-45bd-bc43-7b46e1c29118@192.168.201.28@tcp:0/0 lens 520/416 e 0 to 0 dl 1787866320 ref 1 fl Complete:H/200/0 rc 0/0 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3914.708085] LustreError: 99563:0:(ldlm_lib.c:1472:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 3931.535155] LustreError: 99563:0:(ldlm_lib.c:1472:target_handle_connect()) cfs_fail_timeout interrupted [ 3936.123486] Lustre: DEBUG MARKER: == replay-single test 44c: race in target handle connect ========================================================== 17:32:40 (1787866360) [ 3939.088576] LustreError: 100409:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 3939.096527] LustreError: 100409:0:(osd_handler.c:715:osd_ro()) Skipped 4 previous similar messages [ 3939.995154] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3943.709288] Lustre: Failing over lustre-MDT0000 [ 3944.067259] Lustre: server umount lustre-MDT0000 complete [ 3951.815307] LustreError: MGC192.168.201.128@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3951.825734] LustreError: Skipped 3 previous similar messages [ 3952.183715] Lustre: *** cfs_fail_loc=712, val=0*** [ 3952.184814] 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 [ 3952.191916] LustreError: 14774:0:(service.c:1394:ptlrpc_check_req()) @@@ Invalid replay without recovery req@ffff93c6b7f070c0 x1874709685149056/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 [ 3952.222918] Lustre: Skipped 14 previous similar messages [ 3952.372459] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3952.377274] Lustre: Skipped 8 previous similar messages [ 3952.471612] Lustre: lustre-MDT0000: Aborting client recovery [ 3952.477677] LustreError: 101070:0:(ldlm_lib.c:3067:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 3952.491523] Lustre: 101117:0:(ldlm_lib.c:2467:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 3952.498741] Lustre: 101117:0:(ldlm_lib.c:2467:target_recovery_overseer()) Skipped 2 previous similar messages [ 3952.502765] Lustre: 101117:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 228e9f17-f086-45bd-bc43-7b46e1c29118@ [ 3952.512329] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 3952.627610] Lustre: lustre-MDT0000-osd: cancel update llog [0x2000182d0:0x1:0x0] [ 3952.778728] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2866 to 0x280000400:2913) [ 3952.790356] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2867 to 0x240000400:2945) [ 3957.621587] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3957.729533] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 3957.745354] Lustre: Skipped 15 previous similar messages [ 3965.156138] Lustre: Failing over lustre-MDT0000 [ 3965.454145] Lustre: server umount lustre-MDT0000 complete [ 3984.677821] Lustre: 3283:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787866394/real 1787866394] req@ffff93c6916df840 x1874709685158528/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787866410 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3984.706671] Lustre: 3283:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 39 previous similar messages [ 3987.881583] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3991.440503] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 3991.448067] Lustre: Skipped 3 previous similar messages [ 3991.525637] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 3991.536379] Lustre: Skipped 3 previous similar messages [ 3991.621174] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2867 to 0x240000400:2977) [ 3991.622094] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2866 to 0x280000400:2945) [ 3995.951783] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 3997.314861] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4005.888096] Lustre: DEBUG MARKER: == replay-single test 45: Handle failed close ============ 17:33:50 (1787866430) [ 4006.002655] Lustre: lustre-MDT0000: Client 228e9f17-f086-45bd-bc43-7b46e1c29118 (at 192.168.201.28@tcp) reconnecting [ 4006.015593] Lustre: Skipped 2 previous similar messages [ 4013.903579] Lustre: DEBUG MARKER: == replay-single test 46: Don't leak file handle after open resend (3325) ========================================================== 17:33:58 (1787866438) [ 4014.999275] Lustre: *** cfs_fail_loc=122, val=2147483648*** [ 4015.003528] LustreError: 102043:0:(ldlm_lib.c:3411:target_send_reply_msg()) @@@ dropping reply req@ffff93c584230b40 x1874709676980992/t0(0) o700->228e9f17-f086-45bd-bc43-7b46e1c29118@192.168.201.28@tcp:27/0 lens 264/248 e 0 to 0 dl 1787866452 ref 1 fl Interpret:/200/0 rc 0/0 job:'touch.0' uid:0 gid:0 projid:4294967295 [ 4033.311530] Lustre: Failing over lustre-MDT0000 [ 4033.684556] Lustre: server umount lustre-MDT0000 complete [ 4051.931162] LustreError: 103743:0:(ldlm_lib.c:1228:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.201.28@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4051.957110] LustreError: 103743:0:(ldlm_lib.c:1228:target_handle_connect()) Skipped 5 previous similar messages [ 4052.500545] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4052.504420] Lustre: Skipped 6 previous similar messages [ 4053.849493] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2979 to 0x240000400:3009) [ 4053.850590] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2947 to 0x280000400:2977) [ 4057.339325] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4066.738522] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4068.099303] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4079.001376] Lustre: DEBUG MARKER: == replay-single test 47: MDS->OSC failure during precreate cleanup (2824) ========================================================== 17:35:03 (1787866503) [ 4081.162722] Lustre: Failing over lustre-OST0000 [ 4081.300437] Lustre: server umount lustre-OST0000 complete [ 4083.169231] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 4105.130280] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4114.995952] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 4116.561653] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4187.996579] Lustre: DEBUG MARKER: == replay-single test 48: MDS->OSC failure during precreate cleanup (2824) ========================================================== 17:36:52 (1787866612) [ 4191.586282] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4193.712550] Lustre: Failing over lustre-MDT0000 [ 4193.978934] Lustre: server umount lustre-MDT0000 complete [ 4212.054241] LustreError: 106847:0:(ldlm_lib.c:1228: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. [ 4212.064320] LustreError: 106847:0:(ldlm_lib.c:1228:target_handle_connect()) Skipped 7 previous similar messages [ 4216.810423] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4221.645889] Lustre: *** cfs_fail_loc=216, val=0*** [ 4221.647341] LustreError: 106874:0:(osp_precreate.c:974:osp_precreate_cleanup_orphans()) lustre-OST0001-osc-MDT0000: cannot cleanup orphans: rc = -30 [ 4221.650043] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3030 to 0x240000400:3073) [ 4222.687626] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2998 to 0x280000400:3041) [ 4289.119971] Lustre: DEBUG MARKER: == replay-single test 50: Double OSC recovery, don't LASSERT (3812) ========================================================== 17:38:33 (1787866713) [ 4290.946792] Lustre: lustre-OST0000: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnecting [ 4290.954671] Lustre: Skipped 2 previous similar messages [ 4306.896820] Lustre: DEBUG MARKER: == replay-single test 52: time out lock replay (3764) ==== 17:38:50 (1787866730) [ 4310.099363] Lustre: Failing over lustre-MDT0000 [ 4310.430695] Lustre: server umount lustre-MDT0000 complete [ 4336.186112] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4338.655340] Lustre: *** cfs_fail_loc=157, val=2147483648*** [ 4338.664049] LustreError: 108512:0:(ldlm_lib.c:3411:target_send_reply_msg()) @@@ dropping reply req@ffff93c6916dc3c0 x1874709677100800/t0(0) o101->228e9f17-f086-45bd-bc43-7b46e1c29118@192.168.201.28@tcp:350/0 lens 328/344 e 0 to 0 dl 1787866775 ref 1 fl Complete:/240/0 rc 0/0 job:'ldlm_lock_repla.0' uid:0 gid:0 projid:4294967295 [ 4355.023735] Lustre: lustre-MDT0000: Client 228e9f17-f086-45bd-bc43-7b46e1c29118 (at 192.168.201.28@tcp) reconnected, waiting for 1 clients in recovery for 1:24 [ 4355.137449] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3052 to 0x280000400:3073) [ 4355.139392] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3085 to 0x240000400:3105) [ 4361.112379] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4362.510508] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4371.508677] Lustre: DEBUG MARKER: == replay-single test 53a: |X| close request while two MDC requests in flight ========================================================== 17:39:55 (1787866795) [ 4373.533893] Lustre: *** cfs_fail_loc=115, val=2147483648*** [ 4377.305856] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4379.029197] Lustre: Failing over lustre-MDT0000 [ 4379.317370] Lustre: server umount lustre-MDT0000 complete [ 4397.029161] Lustre: lustre-MDT0000: Not available for connect from 0@lo (not set up) [ 4397.032363] Lustre: Skipped 1 previous similar message [ 4400.205147] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3052 to 0x280000400:3105) [ 4400.214420] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3107 to 0x240000400:3137) [ 4401.178766] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4409.957720] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4411.105479] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4420.565353] Lustre: DEBUG MARKER: == replay-single test 53b: |X| open request while two MDC requests in flight ========================================================== 17:40:44 (1787866844) [ 4421.953609] Lustre: *** cfs_fail_loc=107, val=2147483648*** [ 4426.984584] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4428.699606] Lustre: Failing over lustre-MDT0000 [ 4428.928754] Lustre: server umount lustre-MDT0000 complete [ 4448.872291] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3139 to 0x240000400:3169) [ 4448.873606] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3052 to 0x280000400:3137) [ 4451.032301] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4460.701623] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4462.684644] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4470.998147] Lustre: DEBUG MARKER: == replay-single test 53c: |X| open request and close request while two MDC requests in flight ========================================================== 17:41:35 (1787866895) [ 4471.890923] Lustre: *** cfs_fail_loc=107, val=2147483648*** [ 4477.355793] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4479.377563] Lustre: Failing over lustre-MDT0000 [ 4479.444674] Lustre: lustre-MDT0000: Not available for connect from 192.168.201.28@tcp (stopping) [ 4479.635424] Lustre: server umount lustre-MDT0000 complete [ 4508.158132] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xae04f0eb1c658e4 [ 4513.471734] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4519.573727] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3171 to 0x240000400:3201) [ 4519.575416] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3052 to 0x280000400:3169) [ 4529.813748] Lustre: DEBUG MARKER: == replay-single test 53d: close reply while two MDC requests in flight ========================================================== 17:42:34 (1787866954) [ 4532.369542] Lustre: *** cfs_fail_loc=13b, val=315*** [ 4532.382450] Lustre: *** cfs_fail_loc=13b, val=2147483648*** [ 4532.396417] LustreError: 114082:0:(ldlm_lib.c:3411:target_send_reply_msg()) @@@ dropping reply req@ffff93c6ba7eb0c0 x1874709677151488/t257698037777(0) o35->228e9f17-f086-45bd-bc43-7b46e1c29118@192.168.201.28@tcp:544/0 lens 392/456 e 0 to 0 dl 1787866969 ref 1 fl Interpret:/600/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 4535.969637] Lustre: Failing over lustre-MDT0000 [ 4536.373657] Lustre: server umount lustre-MDT0000 complete [ 4554.720146] LustreError: MGC192.168.201.128@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 4554.722358] 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 [ 4554.731611] LustreError: Skipped 7 previous similar messages [ 4554.761062] Lustre: Skipped 18 previous similar messages [ 4563.937335] LustreError: 3280:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff93c6a61e2940 x1874709685323648/t0(0) o250->MGC192.168.201.128@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 [ 4564.533230] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 4564.538160] Lustre: Skipped 8 previous similar messages [ 4565.480170] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 4565.487298] Lustre: Skipped 19 previous similar messages [ 4568.493459] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4573.163929] Lustre: 114944:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff93c6ba7ead00 x1874709677151488/t257698037777(0) o35->228e9f17-f086-45bd-bc43-7b46e1c29118@192.168.201.28@tcp:585/0 lens 392/456 e 0 to 0 dl 1787867010 ref 1 fl Interpret:/602/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 4573.198632] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3171 to 0x240000400:3233) [ 4573.198835] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3171 to 0x280000400:3201) [ 4580.606280] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4582.341637] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4591.821988] Lustre: DEBUG MARKER: == replay-single test 53e: |X| open reply while two MDC requests in flight ========================================================== 17:43:35 (1787867015) [ 4593.129918] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 4593.140523] LustreError: 114942:0:(ldlm_lib.c:3411:target_send_reply_msg()) @@@ dropping reply req@ffff93c6ba7e8f00 x1874709677166848/t261993005072(0) o36->228e9f17-f086-45bd-bc43-7b46e1c29118@192.168.201.28@tcp:605/0 lens 504/448 e 0 to 0 dl 1787867030 ref 1 fl Interpret:/200/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 4598.064798] LustreError: 116024:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 4598.069478] LustreError: 116024:0:(osd_handler.c:715:osd_ro()) Skipped 4 previous similar messages [ 4599.104562] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4601.502129] Lustre: Failing over lustre-MDT0000 [ 4601.840277] Lustre: server umount lustre-MDT0000 complete [ 4621.778184] Lustre: 3284:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787867032/real 1787867032] req@ffff93c5831da940 x1874709685340288/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787867048 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 4621.824701] Lustre: 3284:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 63 previous similar messages [ 4626.635807] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4634.382727] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 4634.390290] Lustre: Skipped 8 previous similar messages [ 4634.479117] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 4634.486726] Lustre: Skipped 8 previous similar messages [ 4634.532802] Lustre: 116633:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff93c6b9603c00 x1874709677166848/t261993005072(0) o36->228e9f17-f086-45bd-bc43-7b46e1c29118@192.168.201.28@tcp:646/0 lens 504/2880 e 0 to 0 dl 1787867071 ref 1 fl Interpret:/202/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 4634.544477] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3171 to 0x240000400:3265) [ 4634.550426] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3203 to 0x280000400:3233) [ 4639.903272] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4641.481484] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4648.907766] Lustre: DEBUG MARKER: == replay-single test 53f: |X| open reply and close reply while two MDC requests in flight ========================================================== 17:44:33 (1787867073) [ 4650.223988] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 4650.229383] LustreError: 116635:0:(ldlm_lib.c:3411:target_send_reply_msg()) @@@ dropping reply req@ffff93c6a6bb4f00 x1874709677181952/t266287972368(0) o36->228e9f17-f086-45bd-bc43-7b46e1c29118@192.168.201.28@tcp:662/0 lens 504/448 e 0 to 0 dl 1787867087 ref 1 fl Interpret:/200/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 4652.177217] Lustre: *** cfs_fail_loc=13b, val=315*** [ 4655.750317] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4657.816465] Lustre: Failing over lustre-MDT0000 [ 4658.041356] Lustre: server umount lustre-MDT0000 complete [ 4677.369321] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 4677.376346] Lustre: Skipped 8 previous similar messages [ 4677.731904] Lustre: 118321:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff93c58420e940 x1874709677182208/t266287972369(0) o35->228e9f17-f086-45bd-bc43-7b46e1c29118@192.168.201.28@tcp:689/0 lens 392/456 e 0 to 0 dl 1787867114 ref 1 fl Interpret:/602/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 4677.735846] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3171 to 0x240000400:3297) [ 4677.738426] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3235 to 0x280000400:3265) [ 4677.760936] Lustre: 118321:0:(mdt_recovery.c:102:mdt_req_from_lrd()) Skipped 1 previous similar message [ 4682.105974] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4695.238415] Lustre: DEBUG MARKER: == replay-single test 53g: |X| drop open reply and close request while close and open are both in flight ========================================================== 17:45:19 (1787867119) [ 4696.660571] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 4696.673282] Lustre: Skipped 1 previous similar message [ 4696.683229] LustreError: 118320:0:(ldlm_lib.c:3411:target_send_reply_msg()) @@@ dropping reply req@ffff93c6a61e2940 x1874709677193984/t270582939664(0) o36->228e9f17-f086-45bd-bc43-7b46e1c29118@192.168.201.28@tcp:708/0 lens 504/448 e 0 to 0 dl 1787867133 ref 1 fl Interpret:/200/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 4696.707668] LustreError: 118320:0:(ldlm_lib.c:3411:target_send_reply_msg()) Skipped 1 previous similar message [ 4698.754047] Lustre: *** cfs_fail_loc=115, val=2147483648*** [ 4698.757056] Lustre: Skipped 1 previous similar message [ 4702.999209] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4704.627246] Lustre: Failing over lustre-MDT0000 [ 4704.835837] Lustre: server umount lustre-MDT0000 complete [ 4729.017751] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4737.559727] Lustre: 119852:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff93c685887840 x1874709677193984/t270582939664(0) o36->228e9f17-f086-45bd-bc43-7b46e1c29118@192.168.201.28@tcp:749/0 lens 504/2880 e 0 to 0 dl 1787867174 ref 1 fl Interpret:/202/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 4737.570407] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3171 to 0x240000400:3329) [ 4737.571418] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3267 to 0x280000400:3297) [ 4746.278906] Lustre: DEBUG MARKER: == replay-single test 53h: open request and close reply while two MDC requests in flight ========================================================== 17:46:10 (1787867170) [ 4747.270858] Lustre: *** cfs_fail_loc=107, val=2147483648*** [ 4749.181367] Lustre: *** cfs_fail_loc=13b, val=315*** [ 4749.183098] Lustre: *** cfs_fail_loc=13b, val=2147483648*** [ 4749.188743] LustreError: 119855:0:(ldlm_lib.c:3411:target_send_reply_msg()) @@@ dropping reply req@ffff93c6913e12c0 x1874709677206784/t274877906960(0) o35->228e9f17-f086-45bd-bc43-7b46e1c29118@192.168.201.28@tcp:6/0 lens 392/456 e 0 to 0 dl 1787867186 ref 1 fl Interpret:/600/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 4754.021791] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4755.807635] Lustre: Failing over lustre-MDT0000 [ 4756.029968] Lustre: server umount lustre-MDT0000 complete [ 4774.173242] LustreError: 121298:0:(ldlm_lib.c:1228:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.201.28@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4774.194152] LustreError: 121298:0:(ldlm_lib.c:1228:target_handle_connect()) Skipped 1 previous similar message [ 4778.381450] Lustre: 121302:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff93c585cd43c0 x1874709677206784/t274877906960(0) o35->228e9f17-f086-45bd-bc43-7b46e1c29118@192.168.201.28@tcp:35/0 lens 392/456 e 0 to 0 dl 1787867215 ref 1 fl Interpret:/602/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 4778.389857] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3299 to 0x280000400:3329) [ 4778.424743] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3171 to 0x240000400:3361) [ 4779.802868] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4790.918124] Lustre: DEBUG MARKER: == replay-single test 55: let MDS_CHECK_RESENT return the original return code instead of 0 ========================================================== 17:46:55 (1787867215) [ 4791.775541] Lustre: *** cfs_fail_loc=12b, val=2147483991*** [ 4791.784327] LustreError: 121300:0:(ldlm_lib.c:3411:target_send_reply_msg()) @@@ dropping reply req@ffff93c688ba6580 x1874709677216640/t279172874255(0) o101->228e9f17-f086-45bd-bc43-7b46e1c29118@192.168.201.28@tcp:49/0 lens 664/608 e 0 to 0 dl 1787867229 ref 1 fl Interpret:/600/0 rc 301/0 job:'touch.0' uid:0 gid:0 projid:0 [ 4807.135896] Lustre: lustre-MDT0000: Client 228e9f17-f086-45bd-bc43-7b46e1c29118 (at 192.168.201.28@tcp) reconnecting [ 4807.146817] Lustre: Skipped 1 previous similar message [ 4807.178374] Lustre: 121299:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff93c6aa45e940 x1874709677216640/t279172874255(0) o101->228e9f17-f086-45bd-bc43-7b46e1c29118@192.168.201.28@tcp:64/0 lens 664/3488 e 0 to 0 dl 1787867244 ref 1 fl Interpret:/602/0 rc 0/0 job:'touch.0' uid:0 gid:0 projid:0 [ 4815.964977] Lustre: DEBUG MARKER: == replay-single test 56: don't replay a symlink open request (3440) ========================================================== 17:47:20 (1787867240) [ 4819.831263] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4821.836366] Lustre: Failing over lustre-MDT0000 [ 4822.051961] Lustre: server umount lustre-MDT0000 complete [ 4844.839561] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4848.199124] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3363 to 0x240000400:3393) [ 4848.199669] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3299 to 0x280000400:3361) [ 4853.534560] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4855.204633] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4874.168833] Lustre: DEBUG MARKER: == replay-single test 57: test recovery from llog for setattr op ========================================================== 17:48:18 (1787867298) [ 4878.235459] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4880.043108] Lustre: Failing over lustre-MDT0000 [ 4880.468560] Lustre: server umount lustre-MDT0000 complete [ 4909.801738] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3299 to 0x280000400:3393) [ 4909.801997] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3395 to 0x240000400:3425) [ 4915.648984] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4927.112314] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 4928.749539] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4935.176483] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 4949.930689] Lustre: DEBUG MARKER: == replay-single test 58a: test recovery from llog for setattr op (test llog_gen_rec) ========================================================== 17:49:34 (1787867374) [ 4986.462572] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4988.506456] Lustre: Failing over lustre-MDT0000 [ 4989.039381] Lustre: server umount lustre-MDT0000 complete [ 5016.032952] LustreError: 3280:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff93c6ba35f0c0 x1874709685459968/t0(0) o250->MGC192.168.201.128@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 [ 5018.521436] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:4644 to 0x280000400:4673) [ 5018.528733] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:4676 to 0x240000400:4705) [ 5021.505368] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5031.277504] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5033.153640] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5087.445660] Lustre: DEBUG MARKER: == replay-single test 58b: test replay of setxattr op ==== 17:51:51 (1787867511) [ 5093.351091] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5095.715584] Lustre: Failing over lustre-MDT0000 [ 5096.151271] Lustre: server umount lustre-MDT0000 complete [ 5123.042601] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xae04f0eb1ca8d86 [ 5126.315177] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5132.443150] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:4676 to 0x240000400:4737) [ 5132.445366] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:4675 to 0x280000400:4705) [ 5137.640931] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5139.281926] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5148.880020] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount FULL mgc.*.mgs_server_uuid 1475 0 [ 5150.425315] Lustre: DEBUG MARKER: mgc.*.mgs_server_uuid in FULL state after 0 sec [ 5157.913686] Lustre: DEBUG MARKER: == replay-single test 58c: resend/reconstruct setxattr op ========================================================== 17:53:02 (1787867582) [ 5165.240399] Lustre: *** cfs_fail_loc=123, val=2147483648*** [ 5183.298088] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 5183.302486] Lustre: Skipped 1 previous similar message [ 5183.305655] LustreError: 129531:0:(ldlm_lib.c:3411:target_send_reply_msg()) @@@ dropping reply req@ffff93c582de4450 x1874709680000000/t296352743435(0) o36->228e9f17-f086-45bd-bc43-7b46e1c29118@192.168.201.28@tcp:440/0 lens 66040/440 e 0 to 0 dl 1787867620 ref 1 fl Interpret:/600/0 rc 0/0 job:'setfattr.0' uid:0 gid:0 projid:0 [ 5199.859482] Lustre: 129531:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff93c58a627c00 x1874709680000000/t296352743435(0) o36->228e9f17-f086-45bd-bc43-7b46e1c29118@192.168.201.28@tcp:457/0 lens 66040/440 e 0 to 0 dl 1787867637 ref 1 fl Interpret:/602/0 rc 0/0 job:'setfattr.0' uid:0 gid:0 projid:0 [ 5210.938982] Lustre: DEBUG MARKER: SKIP: replay-single test_59 skipping ALWAYS excluded test 59 [ 5212.578361] Lustre: DEBUG MARKER: == replay-single test 60: test llog post recovery init vs llog unlink ========================================================== 17:53:57 (1787867637) [ 5221.197336] LustreError: 130604:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 5221.206350] LustreError: 130604:0:(osd_handler.c:715:osd_ro()) Skipped 7 previous similar messages [ 5222.011947] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5224.343539] Lustre: Failing over lustre-MDT0000 [ 5224.929623] 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 [ 5224.941494] Lustre: Skipped 16 previous similar messages [ 5224.946340] LustreError: 129531:0:(ldlm_lib.c:1228: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. [ 5224.956910] LustreError: 129531:0:(ldlm_lib.c:1228:target_handle_connect()) Skipped 1 previous similar message [ 5226.790159] Lustre: server umount lustre-MDT0000 complete [ 5246.252248] LustreError: MGC192.168.201.128@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 5246.259886] LustreError: Skipped 8 previous similar messages [ 5246.792765] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 5246.795741] Lustre: Skipped 8 previous similar messages [ 5250.927019] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5265.124035] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 5265.131983] Lustre: Skipped 18 previous similar messages [ 5265.360901] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 5265.375354] Lustre: Skipped 7 previous similar messages [ 5266.603721] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 5266.611335] Lustre: Skipped 7 previous similar messages [ 5266.694257] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:4806 to 0x280000400:4833) [ 5266.718150] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:4839 to 0x240000400:4865) [ 5273.849419] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5275.166483] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5286.115280] Lustre: DEBUG MARKER: == replay-single test 61a: test race llog recovery vs llog cleanup ========================================================== 17:55:10 (1787867710) [ 5306.957936] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 5319.363125] Lustre: Failing over lustre-OST0000 [ 5319.468515] Lustre: server umount lustre-OST0000 complete [ 5339.569878] Lustre: lustre-OST0000: in recovery but waiting for the first client to connect [ 5339.575918] Lustre: Skipped 7 previous similar messages [ 5347.891927] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5362.690859] Lustre: Failing over lustre-OST0000 [ 5362.962755] Lustre: server umount lustre-OST0000 complete [ 5363.173476] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 5386.816721] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5395.506406] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 5396.996338] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 5435.759195] Lustre: DEBUG MARKER: == replay-single test 61b: test race mds llog sync vs llog cleanup ========================================================== 17:57:40 (1787867860) [ 5438.350585] Lustre: Failing over lustre-MDT0000 [ 5438.420949] Lustre: lustre-MDT0000: Not available for connect from 192.168.201.28@tcp (stopping) [ 5438.586736] Lustre: server umount lustre-MDT0000 complete [ 5458.399593] Lustre: 3281:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787867868/real 1787867868] req@ffff93c685df6940 x1874709686338048/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787867884 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5458.409343] Lustre: 3281:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 56 previous similar messages [ 5459.048762] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5266 to 0x240000400:5281) [ 5459.060215] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5234 to 0x280000400:5249) [ 5463.572247] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5478.333424] Lustre: Failing over lustre-MDT0000 [ 5478.759622] Lustre: server umount lustre-MDT0000 complete [ 5501.570264] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5506.221913] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5266 to 0x240000400:5313) [ 5506.228231] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5234 to 0x280000400:5281) [ 5513.092763] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5514.549410] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5523.895892] Lustre: DEBUG MARKER: == replay-single test 61c: test race mds llog sync vs llog cleanup ========================================================== 17:59:08 (1787867948) [ 5538.635377] Lustre: Failing over lustre-OST0000 [ 5540.872151] Lustre: server umount lustre-OST0000 complete [ 5563.064477] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5570.998775] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 5572.554450] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 5581.322305] Lustre: DEBUG MARKER: == replay-single test 61d: error in llog_setup should cleanup the llog context correctly ========================================================== 18:00:05 (1787868005) [ 5583.372780] Lustre: Failing over lustre-MDT0000 [ 5583.620203] Lustre: server umount lustre-MDT0000 complete [ 5593.075578] Lustre: *** cfs_fail_loc=605, val=0*** [ 5593.079720] LustreError: 139785:0:(llog_obd.c:192:llog_setup()) MGS: ctxt 0 lop_setup=ffffffffc1394020 failed: rc = -95 [ 5593.089872] LustreError: 139785:0:(obd_config.c:845:class_setup()) setup MGS failed (-95) [ 5593.095856] LustreError: 139785:0:(obd_mount.c:259:lustre_start_simple()) MGS setup error -95 [ 5593.101667] LustreError: 139785:0:(tgt_mount.c:116:server_deregister_mount()) MGS not registered [ 5593.109136] LustreError: Failed to start MGS 'MGS' (-95). Is the 'mgs' module loaded? [ 5593.115312] LustreError: 139785:0:(tgt_mount.c:2129:server_put_super()) no obd lustre-MDT0000 [ 5593.274578] Lustre: server umount lustre-MDT0000 complete [ 5593.276236] LustreError: 139785:0:(super25.c:179:lustre_fill_super()) llite: Unable to mount : rc = -95 [ 5603.350285] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5283 to 0x280000400:5313) [ 5603.350860] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5315 to 0x240000400:5345) [ 5603.601401] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5611.567056] Lustre: DEBUG MARKER: == replay-single test 62: don't mis-drop resent replay === 18:00:36 (1787868036) [ 5615.206643] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 5617.645306] Lustre: Failing over lustre-MDT0000 [ 5617.921290] Lustre: server umount lustre-MDT0000 complete [ 5635.036977] Lustre: *** cfs_fail_loc=707, val=0*** [ 5642.121189] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 5650.466674] Lustre: lustre-MDT0000: Client 228e9f17-f086-45bd-bc43-7b46e1c29118 (at 192.168.201.28@tcp) reconnected, waiting for 1 clients in recovery for 0:55 [ 5651.512726] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5327 to 0x280000400:5345) [ 5651.515332] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5358 to 0x240000400:5377) [ 5660.852562] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 5662.965954] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 5674.811921] Lustre: DEBUG MARKER: == replay-single test 65a: AT: verify early replies ====== 18:01:39 (1787868099) [ 5706.575905] LustreError: 142189:0:(service.c:2558:ptlrpc_server_handle_request()) @@@ HIT req@ffff93c588f121c0 x1874709680873600/t0(0) o101->228e9f17-f086-45bd-bc43-7b46e1c29118@192.168.201.28@tcp:208/0 lens 664/0 e 0 to 0 dl 1787868143 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 5706.590692] LustreError: 142189:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a sleeping for 11000ms [ 5717.623340] LustreError: 142189:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a awake [ 5717.654739] LustreError: 141485:0:(service.c:2558:ptlrpc_server_handle_request()) @@@ HIT req@ffff93c69ca00000 x1874709680874496/t0(0) o35->228e9f17-f086-45bd-bc43-7b46e1c29118@192.168.201.28@tcp:225/0 lens 392/0 e 0 to 0 dl 1787868160 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 5719.421205] LustreError: 141482:0:(service.c:2558:ptlrpc_server_handle_request()) @@@ HIT req@ffff93c69ca00000 x1874709680880384/t0(0) o101->228e9f17-f086-45bd-bc43-7b46e1c29118@192.168.201.28@tcp:261/0 lens 576/0 e 0 to 0 dl 1787868196 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'unlinkmany.0' uid:0 gid:0 projid:0 [ 5719.436170] LustreError: 141482:0:(service.c:2558:ptlrpc_server_handle_request()) Skipped 27 previous similar messages [ 5723.176115] LustreError: 6675:0:(service.c:2558:ptlrpc_server_handle_request()) @@@ HIT req@ffff93c584230780 x1874709686422784/t0(0) o6->lustre-MDT0000-mdtlov_UUID@0@lo:225/0 lens 544/0 e 0 to 0 dl 1787868160 ref 1 fl Interpret:/200/ffffffff rc 0/-1 job:'osp-syn-1-0.0' uid:0 gid:0 projid:4294967295 [ 5723.203229] LustreError: 6675:0:(service.c:2558:ptlrpc_server_handle_request()) Skipped 20 previous similar messages [ 5728.313146] LustreError: 36661:0:(service.c:2558:ptlrpc_server_handle_request()) @@@ HIT req@ffff93c688ba7c00 x1874709686424064/t0(0) o6->lustre-MDT0000-mdtlov_UUID@0@lo:230/0 lens 544/0 e 0 to 0 dl 1787868165 ref 1 fl Interpret:/200/ffffffff rc 0/-1 job:'osp-syn-0-0.0' uid:0 gid:0 projid:4294967295 [ 5728.345632] LustreError: 36661:0:(service.c:2558:ptlrpc_server_handle_request()) Skipped 7 previous similar messages [ 5734.853487] Lustre: DEBUG MARKER: == replay-single test 65b: AT: verify early replies on packed reply / bulk ========================================================== 18:02:39 (1787868159) [ 5765.658759] LustreError: 6681:0:(tgt_handler.c:2903:tgt_brw_write()) cfs_fail_timeout id 224 sleeping for 11000ms [ 5776.759162] LustreError: 6681:0:(tgt_handler.c:2903:tgt_brw_write()) cfs_fail_timeout id 224 awake [ 5786.875053] Lustre: DEBUG MARKER: == replay-single test 66a: AT: verify MDT service time adjusts with no early replies ========================================================== 18:03:31 (1787868211) [ 5816.006445] LustreError: 144370:0:(service.c:2558:ptlrpc_server_handle_request()) @@@ HIT req@ffff93c6aa45fc00 x1874709680896128/t0(0) o101->228e9f17-f086-45bd-bc43-7b46e1c29118@192.168.201.28@tcp:318/0 lens 576/0 e 0 to 0 dl 1787868253 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 5816.017092] LustreError: 144370:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a sleeping for 5000ms [ 5821.035600] LustreError: 144370:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a awake [ 5833.920516] LustreError: 141482:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a awake [ 5833.957537] LustreError: 142189:0:(service.c:2558:ptlrpc_server_handle_request()) @@@ HIT req@ffff93c6ba417840 x1874709680918016/t0(0) o101->228e9f17-f086-45bd-bc43-7b46e1c29118@192.168.201.28@tcp:375/0 lens 664/0 e 0 to 0 dl 1787868310 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 5834.026935] LustreError: 142189:0:(service.c:2558:ptlrpc_server_handle_request()) Skipped 120 previous similar messages [ 5855.825258] Lustre: DEBUG MARKER: == replay-single test 66b: AT: verify net latency adjusts ========================================================== 18:04:40 (1787868280) [ 5961.640949] Lustre: DEBUG MARKER: == replay-single test 67a: AT: verify slow request processing doesn't induce reconnects ========================================================== 18:06:26 (1787868386) [ 5991.265162] LustreError: 141483:0:(service.c:2558:ptlrpc_server_handle_request()) @@@ HIT req@ffff93c6b140da40 x1874709680973184/t0(0) o101->228e9f17-f086-45bd-bc43-7b46e1c29118@192.168.201.28@tcp:493/0 lens 576/0 e 0 to 0 dl 1787868428 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 5991.280878] LustreError: 141483:0:(service.c:2558:ptlrpc_server_handle_request()) Skipped 100 previous similar messages [ 5991.285759] LustreError: 141483:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a sleeping for 400ms [ 5991.290809] LustreError: 141483:0:(service.c:2559:ptlrpc_server_handle_request()) Skipped 1 previous similar message [ 5991.711165] LustreError: 141483:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a awake [ 6007.623994] LustreError: 143604:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a sleeping for 400ms [ 6007.638992] LustreError: 143604:0:(service.c:2559:ptlrpc_server_handle_request()) Skipped 37 previous similar messages [ 6008.071146] LustreError: 143604:0:(service.c:2559:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a awake [ 6008.083738] LustreError: 143604:0:(service.c:2559:ptlrpc_server_handle_request()) Skipped 37 previous similar messages [ 6043.565574] Lustre: DEBUG MARKER: == replay-single test 67b: AT: verify instant slowdown doesn't induce reconnects ========================================================== 18:07:47 (1787868467) [ 6077.791219] Lustre: DEBUG MARKER: phase 2 [ 6086.970462] Lustre: DEBUG MARKER: == replay-single test 68: AT: verify slowing locks ======= 18:08:31 (1787868511) [ 6169.732301] Lustre: DEBUG MARKER: == replay-single test 70a: check multi client t-f ======== 18:09:54 (1787868594) [ 6171.030609] Lustre: DEBUG MARKER: SKIP: replay-single test_70a Need two or more clients, have 1 [ 6172.599798] Lustre: DEBUG MARKER: == replay-single test 70b: dbench 1mdts recovery; 1 clients ========================================================== 18:09:57 (1787868597) [ 6176.928066] Lustre: DEBUG MARKER: Started rundbench load pid=128802 ... [ 6180.700340] LustreError: 148287:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 6180.705518] LustreError: 148287:0:(osd_handler.c:715:osd_ro()) Skipped 2 previous similar messages [ 6181.620770] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 6183.950939] Lustre: DEBUG MARKER: test_70b fail mds1 1 times [ 6185.674933] Lustre: Failing over lustre-MDT0000 [ 6185.917835] Lustre: server umount lustre-MDT0000 complete [ 6204.383113] Lustre: 3283:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787868614/real 1787868614] req@ffff93c688ba5e00 x1874709686558976/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1787868630 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6204.398982] LustreError: MGC192.168.201.128@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 6204.418720] LustreError: Skipped 4 previous similar messages [ 6204.421110] Lustre: 3283:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 27 previous similar messages [ 6204.452416] 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 [ 6204.479726] Lustre: Skipped 11 previous similar messages [ 6214.637748] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xae04f0eb1cc3d4f [ 6214.660813] Lustre: MGC192.168.201.128@tcp: Connection restored to 0@lo (at 0@lo) [ 6214.682097] Lustre: Skipped 12 previous similar messages [ 6215.809523] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 6215.816725] Lustre: Skipped 7 previous similar messages [ 6215.976159] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 6216.004049] Lustre: Skipped 6 previous similar messages [ 6221.541261] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6222.866785] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 6222.872460] Lustre: Skipped 7 previous similar messages [ 6223.937720] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 6223.952216] Lustre: Skipped 7 previous similar messages [ 6224.013721] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5480 to 0x240000400:5505) [ 6224.025158] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5427 to 0x280000400:5473) [ 6231.475705] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6233.113031] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6240.877479] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 6243.465192] Lustre: DEBUG MARKER: test_70b fail mds1 2 times [ 6245.650357] Lustre: Failing over lustre-MDT0000 [ 6245.987127] Lustre: server umount lustre-MDT0000 complete [ 6270.945713] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6284.183502] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5504 to 0x280000400:5537) [ 6284.186978] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5537 to 0x240000400:5569) [ 6291.128917] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6292.734931] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6327.772588] Lustre: DEBUG MARKER: == replay-single test 70c: tar 1mdts recovery ============ 18:12:32 (1787868752) [ 6454.250594] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 6466.837549] Lustre: DEBUG MARKER: test_70c fail mds1 1 times [ 6468.816681] Lustre: Failing over lustre-MDT0000 [ 6468.902151] Lustre: lustre-MDT0000: Not available for connect from 192.168.201.28@tcp (stopping) [ 6469.122542] Lustre: server umount lustre-MDT0000 complete [ 6501.873356] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6512.818138] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6339 to 0x240000400:6369) [ 6512.819256] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6306 to 0x280000400:6337) [ 6519.951478] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6521.499841] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6597.638356] Lustre: DEBUG MARKER: == replay-single test 70d: mkdir/rmdir striped dir 1mdts recovery ========================================================== 18:17:02 (1787869022) [ 6598.848355] Lustre: DEBUG MARKER: SKIP: replay-single test_70d needs >= 2 MDTs [ 6600.266430] Lustre: DEBUG MARKER: == replay-single test 70e: rename cross-MDT with random fails ========================================================== 18:17:04 (1787869024) [ 6602.029981] Lustre: DEBUG MARKER: SKIP: replay-single test_70e needs >= 2 MDTs [ 6603.691673] Lustre: DEBUG MARKER: == replay-single test 70f: OSS O_DIRECT recovery with 1 clients ========================================================== 18:17:08 (1787869028) [ 6612.016918] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 6614.682553] Lustre: DEBUG MARKER: test_70f failing OST 1 times [ 6616.533544] Lustre: Failing over lustre-OST0000 [ 6616.633439] Lustre: server umount lustre-OST0000 complete [ 6618.595162] LustreError: 36657:0:(ldlm_lib.c:1228: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. [ 6618.615521] LustreError: 36657:0:(ldlm_lib.c:1228:target_handle_connect()) Skipped 21 previous similar messages [ 6642.025497] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6652.385950] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 6654.337637] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 6665.725191] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 6668.559915] Lustre: DEBUG MARKER: test_70f failing OST 2 times [ 6670.503313] Lustre: Failing over lustre-OST0000 [ 6670.581523] Lustre: server umount lustre-OST0000 complete [ 6686.680074] LustreError: 36655:0:(ldlm_lib.c:1228:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.201.28@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 6686.695771] LustreError: 36655:0:(ldlm_lib.c:1228:target_handle_connect()) Skipped 13 previous similar messages [ 6696.954711] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6706.938613] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 6708.712780] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 6719.388181] Lustre: DEBUG MARKER: == replay-single test 71a: mkdir/rmdir striped dir with 2 mdts recovery ========================================================== 18:19:03 (1787869143) [ 6720.608853] Lustre: DEBUG MARKER: SKIP: replay-single test_71a needs >= 2 MDTs [ 6722.189988] Lustre: DEBUG MARKER: == replay-single test 73a: open(O_CREAT), unlink, replay, reconnect before open replay, close ========================================================== 18:19:06 (1787869146) [ 6726.200696] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 6729.006959] Lustre: Failing over lustre-MDT0000 [ 6729.295767] Lustre: server umount lustre-MDT0000 complete [ 6758.561154] Lustre: Evicted from MGS (at 0@lo) after server handle changed from 0x0 to 0xae04f0eb1d4d261 [ 6764.168890] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6773.724868] Lustre: *** cfs_fail_loc=302, val=2147483648*** [ 6789.114323] Lustre: lustre-MDT0000: Client 228e9f17-f086-45bd-bc43-7b46e1c29118 (at 192.168.201.28@tcp) reconnected, waiting for 1 clients in recovery for 0:54 [ 6789.424650] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6586 to 0x280000400:6625) [ 6789.427319] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6619 to 0x240000400:6657) [ 6796.092555] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6797.671748] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6806.254588] Lustre: DEBUG MARKER: == replay-single test 73b: open(O_CREAT), unlink, replay, reconnect at open_replay reply, close ========================================================== 18:20:30 (1787869230) [ 6809.339305] LustreError: 158481:0:(osd_handler.c:715:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 6809.345757] LustreError: 158481:0:(osd_handler.c:715:osd_ro()) Skipped 5 previous similar messages [ 6810.508426] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 6813.408509] Lustre: Failing over lustre-MDT0000 [ 6813.801748] Lustre: server umount lustre-MDT0000 complete [ 6830.559099] Lustre: 3283:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787869240/real 1787869240] req@ffff93c58e6ced00 x1874709687678464/t0(0) o400->MGC192.168.201.128@tcp@0@lo:26/25 lens 224/224 e 0 to 1 dl 1787869256 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 6830.562367] 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 [ 6830.597728] Lustre: 3283:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 37 previous similar messages [ 6830.597799] LustreError: MGC192.168.201.128@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 6830.597802] LustreError: Skipped 3 previous similar messages [ 6830.632669] Lustre: Skipped 9 previous similar messages [ 6840.375954] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 6840.379454] Lustre: Skipped 5 previous similar messages [ 6840.438766] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 6840.441686] Lustre: Skipped 5 previous similar messages [ 6841.294712] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 6841.302744] Lustre: Skipped 5 previous similar messages [ 6841.397457] Lustre: *** cfs_fail_loc=157, val=2147483648*** [ 6841.404430] LustreError: 159142:0:(ldlm_lib.c:3411:target_send_reply_msg()) @@@ dropping reply req@ffff93c685fa1a40 x1874709689693568/t335007449091(335007449091) o101->228e9f17-f086-45bd-bc43-7b46e1c29118@192.168.201.28@tcp:588/0 lens 592/608 e 0 to 0 dl 1787869278 ref 1 fl Interpret:/604/0 rc 301/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 6845.236114] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6855.527743] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 6855.539543] Lustre: Skipped 11 previous similar messages [ 6857.701909] Lustre: lustre-MDT0000: Client 228e9f17-f086-45bd-bc43-7b46e1c29118 (at 192.168.201.28@tcp) reconnected, waiting for 1 clients in recovery for 0:53 [ 6857.715992] Lustre: 159142:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff93c584201e00 x1874709689693568/t335007449091(335007449091) o101->228e9f17-f086-45bd-bc43-7b46e1c29118@192.168.201.28@tcp:604/0 lens 592/3488 e 0 to 0 dl 1787869294 ref 1 fl Interpret:/606/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 6857.786415] Lustre: lustre-MDT0000: Recovery over after 0:16, of 1 clients 1 recovered and 0 were evicted. [ 6857.792740] Lustre: Skipped 5 previous similar messages [ 6857.848409] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6586 to 0x280000400:6657) [ 6857.852157] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6659 to 0x240000400:6689) [ 6864.116169] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 6865.542559] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 6874.398464] Lustre: DEBUG MARKER: == replay-single test 74: Ensure applications don't fail waiting for OST recovery ========================================================== 18:21:38 (1787869298) [ 6878.554583] Lustre: Failing over lustre-OST0000 [ 6878.692397] Lustre: server umount lustre-OST0000 complete [ 6878.698396] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 6878.711229] LustreError: 36654:0:(ldlm_lib.c:1228: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. [ 6882.541295] Lustre: Failing over lustre-MDT0000 [ 6882.896471] Lustre: server umount lustre-MDT0000 complete [ 6902.531309] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6586 to 0x280000400:6689) [ 6907.059604] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6917.107518] Lustre: lustre-OST0000: Denying connection for new client c1eb502c-1584-4a7c-95c5-a1b2c749e241 (at 192.168.201.28@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 1:00 [ 6917.139056] Lustre: Skipped 11 previous similar messages [ 6920.345479] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6659 to 0x240000400:6721) [ 6922.580932] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 6932.749813] Lustre: DEBUG MARKER: == replay-single test 80a: DNE: create remote dir, drop update rep from MDT0, fail MDT0 ========================================================== 18:22:37 (1787869357) [ 6934.240397] Lustre: DEBUG MARKER: SKIP: replay-single test_80a needs >= 2 MDTs [ 6935.649741] Lustre: DEBUG MARKER: == replay-single test 80b: DNE: create remote dir, drop update rep from MDT0, fail MDT1 ========================================================== 18:22:40 (1787869360) [ 6937.066182] Lustre: DEBUG MARKER: SKIP: replay-single test_80b needs >= 2 MDTs [ 6938.673924] Lustre: DEBUG MARKER: == replay-single test 80c: DNE: create remote dir, drop update rep from MDT1, fail MDT[0,1] ========================================================== 18:22:43 (1787869363) [ 6940.600198] Lustre: DEBUG MARKER: SKIP: replay-single test_80c needs >= 2 MDTs [ 6942.270824] Lustre: DEBUG MARKER: == replay-single test 80d: DNE: create remote dir, drop update rep from MDT1, fail 2 MDTs ========================================================== 18:22:46 (1787869366) [ 6943.536315] Lustre: DEBUG MARKER: SKIP: replay-single test_80d needs >= 2 MDTs [ 6945.242324] Lustre: DEBUG MARKER: == replay-single test 80e: DNE: create remote dir, drop MDT1 rep, fail MDT0 ========================================================== 18:22:49 (1787869369) [ 6946.728950] Lustre: DEBUG MARKER: SKIP: replay-single test_80e needs >= 2 MDTs [ 6948.464582] Lustre: DEBUG MARKER: == replay-single test 80f: DNE: create remote dir, drop MDT1 rep, fail MDT1 ========================================================== 18:22:52 (1787869372) [ 6949.947283] Lustre: DEBUG MARKER: SKIP: replay-single test_80f needs >= 2 MDTs [ 6951.697921] Lustre: DEBUG MARKER: == replay-single test 80g: DNE: create remote dir, drop MDT1 rep, fail MDT0, then MDT1 ========================================================== 18:22:56 (1787869376) [ 6953.577533] Lustre: DEBUG MARKER: SKIP: replay-single test_80g needs >= 2 MDTs [ 6955.278687] Lustre: DEBUG MARKER: == replay-single test 80h: DNE: create remote dir, drop MDT1 rep, fail 2 MDTs ========================================================== 18:22:59 (1787869379) [ 6956.935620] Lustre: DEBUG MARKER: SKIP: replay-single test_80h needs >= 2 MDTs [ 6958.685749] Lustre: DEBUG MARKER: == replay-single test 81a: DNE: unlink remote dir, drop MDT0 update rep, fail MDT1 ========================================================== 18:23:03 (1787869383) [ 6960.242878] Lustre: DEBUG MARKER: SKIP: replay-single test_81a needs >= 2 MDTs [ 6962.225171] Lustre: DEBUG MARKER: == replay-single test 81b: DNE: unlink remote dir, drop MDT0 update reply, fail MDT0 ========================================================== 18:23:06 (1787869386) [ 6963.962435] Lustre: DEBUG MARKER: SKIP: replay-single test_81b needs >= 2 MDTs [ 6965.473832] Lustre: DEBUG MARKER: == replay-single test 81c: DNE: unlink remote dir, drop MDT0 update reply, fail MDT0,MDT1 ========================================================== 18:23:10 (1787869390) [ 6966.678283] Lustre: DEBUG MARKER: SKIP: replay-single test_81c needs >= 2 MDTs [ 6968.170211] Lustre: DEBUG MARKER: == replay-single test 81d: DNE: unlink remote dir, drop MDT0 update reply, fail 2 MDTs ========================================================== 18:23:12 (1787869392) [ 6969.753360] Lustre: DEBUG MARKER: SKIP: replay-single test_81d needs >= 2 MDTs [ 6971.821289] Lustre: DEBUG MARKER: == replay-single test 81e: DNE: unlink remote dir, drop MDT1 req reply, fail MDT0 ========================================================== 18:23:16 (1787869396) [ 6973.372519] Lustre: DEBUG MARKER: SKIP: replay-single test_81e needs >= 2 MDTs [ 6975.122875] Lustre: DEBUG MARKER: == replay-single test 81f: DNE: unlink remote dir, drop MDT1 req reply, fail MDT1 ========================================================== 18:23:19 (1787869399) [ 6976.502031] Lustre: DEBUG MARKER: SKIP: replay-single test_81f needs >= 2 MDTs [ 6978.281354] Lustre: DEBUG MARKER: == replay-single test 81g: DNE: unlink remote dir, drop req reply, fail M0, then M1 ========================================================== 18:23:22 (1787869402) [ 6980.061132] Lustre: DEBUG MARKER: SKIP: replay-single test_81g needs >= 2 MDTs [ 6981.860302] Lustre: DEBUG MARKER: == replay-single test 81h: DNE: unlink remote dir, drop request reply, fail 2 MDTs ========================================================== 18:23:26 (1787869406) [ 6983.348639] Lustre: DEBUG MARKER: SKIP: replay-single test_81h needs >= 2 MDTs [ 6985.071774] Lustre: DEBUG MARKER: == replay-single test 84a: stale open during export disconnect ========================================================== 18:23:29 (1787869409) [ 6986.831974] Lustre: 163768:0:(genops.c:1774:obd_export_evict_by_uuid()) lustre-MDT0000: evicting c1eb502c-1584-4a7c-95c5-a1b2c749e241 at adminstrative request [ 6996.161817] Lustre: DEBUG MARKER: == replay-single test 85a: check the cancellation of unused locks during recovery(IBITS) ========================================================== 18:23:41 (1787869421) [ 7002.151091] Lustre: Failing over lustre-MDT0000 [ 7002.821524] Lustre: server umount lustre-MDT0000 complete [ 7024.994100] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6773 to 0x240000400:6817) [ 7024.995431] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6741 to 0x280000400:6785) [ 7027.165912] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7036.732419] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 7038.674346] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7047.266953] Lustre: DEBUG MARKER: == replay-single test 85b: check the cancellation of unused locks during recovery(EXTENT) ========================================================== 18:24:31 (1787869471) [ 7059.939761] Lustre: Failing over lustre-OST0000 [ 7060.081646] Lustre: server umount lustre-OST0000 complete [ 7063.011363] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 7086.743258] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7096.932372] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 7098.849266] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 7109.674415] Lustre: DEBUG MARKER: == replay-single test 86: umount server after clear nid_stats should not hit LBUG ========================================================== 18:25:33 (1787869533) [ 7115.449739] Lustre: Failing over lustre-MDT0000 [ 7115.746869] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 7115.752054] Lustre: Skipped 1 previous similar message [ 7115.916749] Lustre: server umount lustre-MDT0000 complete [ 7126.532205] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6918 to 0x240000400:6945) [ 7126.538083] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6741 to 0x280000400:6817) [ 7130.934509] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7140.772924] Lustre: DEBUG MARKER: == replay-single test 87a: write replay ================== 18:26:05 (1787869565) [ 7145.744645] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 7148.682541] Lustre: Failing over lustre-OST0000 [ 7148.774860] Lustre: server umount lustre-OST0000 complete [ 7149.024081] LustreError: 6675:0:(ldlm_lib.c:1228:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.201.28@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 7149.045400] LustreError: 6675:0:(ldlm_lib.c:1228:target_handle_connect()) Skipped 12 previous similar messages [ 7173.924703] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7184.181030] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 7186.038628] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 7194.340935] Lustre: DEBUG MARKER: == replay-single test 87b: write replay with changed data (checksum resend) ========================================================== 18:26:58 (1787869618) [ 7198.490770] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 7202.110938] Lustre: Failing over lustre-OST0000 [ 7202.198139] Lustre: server umount lustre-OST0000 complete [ 7221.350037] LustreError: lustre-OST0000: BAD WRITE CHECKSUM: from 12345-192.168.201.28@tcp inode [0x2000284a1:0x5:0x0] object 0x240000400:6947 extent [0-1048575]: client csum 9dc30f05, server csum 3a3c099b [ 7226.326524] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7234.928680] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 7236.371536] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 7243.466208] Lustre: DEBUG MARKER: == replay-single test 88: MDS should not assign same objid to different files ========================================================== 18:27:48 (1787869668) [ 7247.246890] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 7250.835041] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 7256.141759] Lustre: Failing over lustre-MDT0000 [ 7256.562182] Lustre: server umount lustre-MDT0000 complete [ 7260.279387] LustreError: 5809:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787869686 with bad export cookie 783713259694143506 [ 7269.856803] Lustre: Failing over lustre-OST0000 [ 7270.003591] Lustre: server umount lustre-OST0000 complete [ 7305.119817] LustreError: 3280:0:(client.c:1404:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff93c6bffc9680 x1874709687816320/t0(0) o250->MGC192.168.201.128@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 [ 7309.958353] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7318.660243] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6856 to 0x280000400:6881) [ 7332.955169] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6948 to 0x240000400:6977) [ 7333.690693] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7347.676107] Lustre: DEBUG MARKER: == replay-single test 89: no disk space leak on late ost connection ========================================================== 18:29:32 (1787869772) [ 7363.996292] Lustre: Failing over lustre-OST0000 [ 7364.070195] Lustre: lustre-OST0000: Not available for connect from 192.168.201.28@tcp (stopping) [ 7364.159667] Lustre: server umount lustre-OST0000 complete [ 7368.160415] Lustre: Failing over lustre-MDT0000 [ 7368.512086] Lustre: server umount lustre-MDT0000 complete [ 7391.782473] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7396.008322] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6856 to 0x280000400:6913) [ 7406.067624] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7408.341683] Lustre: lustre-OST0000: Denying connection for new client ec918303-dc1c-492b-8350-b16651b14c5e (at 192.168.201.28@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 1:07 [ 7408.359167] Lustre: Skipped 1 previous similar message [ 7429.072719] Lustre: lustre-OST0000: Denying connection for new client ec918303-dc1c-492b-8350-b16651b14c5e (at 192.168.201.28@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 0:46 [ 7429.095986] Lustre: Skipped 3 previous similar messages [ 7464.916244] Lustre: lustre-OST0000: Denying connection for new client ec918303-dc1c-492b-8350-b16651b14c5e (at 192.168.201.28@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 0:10 [ 7464.930328] Lustre: Skipped 6 previous similar messages [ 7475.500281] Lustre: lustre-OST0000: recovery is timed out, evict stale exports [ 7475.511210] Lustre: 176142:0:(genops.c:1601:class_disconnect_stale_exports()) lustre-OST0000: disconnect stale client 5664783a-e70f-4cdc-a03f-3b5ee270c94c@ [ 7475.530401] Lustre: lustre-OST0000: disconnecting 1 stale clients [ 7475.613752] Lustre: lustre-OST0000: Recovery over after 1:10, of 2 clients 1 recovered and 1 was evicted. [ 7475.616423] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 7475.626037] Lustre: Skipped 8 previous similar messages [ 7475.635510] Lustre: Skipped 13 previous similar messages [ 7475.636394] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:6988 to 0x240000400:7009) [ 7482.891400] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 65 sec [ 7497.834328] Lustre: DEBUG MARKER: free_before: 7520256 free_after: 7520256 [ 7504.174956] Lustre: DEBUG MARKER: == replay-single test 90: lfs find identifies the missing striped file segments ========================================================== 18:32:08 (1787869928) [ 7508.348050] Lustre: Failing over lustre-OST0001 [ 7508.518951] Lustre: server umount lustre-OST0001 complete [ 7508.962306] LustreError: lustre-OST0001-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 7508.969753] Lustre: lustre-OST0001-osc-MDT0000: Connection to lustre-OST0001 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete [ 7509.000598] Lustre: Skipped 12 previous similar messages [ 7529.321446] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 7529.325590] Lustre: Skipped 11 previous similar messages [ 7529.335677] Lustre: lustre-OST0001: in recovery but waiting for the first client to connect [ 7529.338392] Lustre: Skipped 9 previous similar messages [ 7531.168913] Lustre: lustre-OST0001: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 7531.171975] Lustre: Skipped 9 previous similar messages [ 7535.812450] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7548.085577] Lustre: DEBUG MARKER: == replay-single test 93a: replay + reconnect ============ 18:32:52 (1787869972) [ 7551.905551] Lustre: Failing over lustre-OST0000 [ 7552.066218] Lustre: server umount lustre-OST0000 complete [ 7552.479867] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 7572.600819] LustreError: 179224:0:(ldlm_lib.c:2968:target_recovery_thread()) cfs_fail_timeout id 715 sleeping for 40000ms [ 7572.611619] LustreError: 179224:0:(ldlm_lib.c:2968:target_recovery_thread()) Skipped 81 previous similar messages [ 7577.710362] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7578.591112] Lustre: *** cfs_fail_loc=715, val=40*** [ 7587.809915] Lustre: 3280:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1787869998/real 1787869998] req@ffff93c683035a40 x1874709687890048/t0(0) o400->lustre-OST0000-osc-MDT0000@0@lo:28/4 lens 224/224 e 0 to 1 dl 1787870014 ref 1 fl Rpc:XQr/2c0/ffffffff rc 0/-1 job:'ldlm_lock_repla.0' uid:0 gid:0 projid:4294967295 [ 7587.861194] Lustre: 3280:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 24 previous similar messages [ 7587.878143] Lustre: lustre-OST0000: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnected, waiting for 2 clients in recovery for 1:25 [ 7588.846368] Lustre: lustre-OST0000: Client ec918303-dc1c-492b-8350-b16651b14c5e (at 192.168.201.28@tcp) reconnected, waiting for 2 clients in recovery for 1:24 [ 7593.951311] Lustre: *** cfs_fail_loc=715, val=40*** [ 7593.958699] Lustre: Skipped 1 previous similar message [ 7594.976376] Lustre: *** cfs_fail_loc=715, val=40*** [ 7604.180901] Lustre: lustre-OST0000: Client ec918303-dc1c-492b-8350-b16651b14c5e (at 192.168.201.28@tcp) reconnected, waiting for 2 clients in recovery for 1:09 [ 7604.197467] Lustre: Skipped 1 previous similar message [ 7610.335725] Lustre: *** cfs_fail_loc=715, val=40*** [ 7612.687110] LustreError: 179224:0:(ldlm_lib.c:2968:target_recovery_thread()) cfs_fail_timeout id 715 awake [ 7612.694380] LustreError: 179224:0:(ldlm_lib.c:2968:target_recovery_thread()) Skipped 81 previous similar messages [ 7620.100423] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 7621.829278] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 7630.404416] Lustre: DEBUG MARKER: == replay-single test 93b: replay + reconnect on mds ===== 18:34:14 (1787870054) [ 7634.975423] Lustre: Failing over lustre-MDT0000 [ 7635.391431] Lustre: server umount lustre-MDT0000 complete [ 7650.783372] LustreError: MGC192.168.201.128@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 7650.791098] LustreError: Skipped 5 previous similar messages [ 7665.648478] LustreError: 180826:0:(ldlm_lib.c:2968:target_recovery_thread()) cfs_fail_timeout id 715 sleeping for 80000ms [ 7668.439391] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 7671.784408] Lustre: *** cfs_fail_loc=715, val=80*** [ 7671.786061] Lustre: Skipped 1 previous similar message [ 7681.999230] Lustre: lustre-MDT0000: Client ec918303-dc1c-492b-8350-b16651b14c5e (at 192.168.201.28@tcp) reconnected, waiting for 1 clients in recovery for 0:53 [ 7688.161064] Lustre: *** cfs_fail_loc=715, val=80*** [ 7697.362701] Lustre: lustre-MDT0000: Client ec918303-dc1c-492b-8350-b16651b14c5e (at 192.168.201.28@tcp) reconnected, waiting for 1 clients in recovery for 0:38 [ 7713.743506] Lustre: lustre-MDT0000: Client ec918303-dc1c-492b-8350-b16651b14c5e (at 192.168.201.28@tcp) reconnected, waiting for 1 clients in recovery for 0:21 [ 7719.924053] Lustre: *** cfs_fail_loc=715, val=80*** [ 7719.925516] Lustre: Skipped 1 previous similar message [ 7745.492659] Lustre: lustre-MDT0000: Recovery already passed deadline 0:09. If you do not want to wait more, you may force taget eviction via 'lctl --device lustre-MDT0000 abort_recovery. [ 7745.703206] LustreError: 180826:0:(ldlm_lib.c:2968:target_recovery_thread()) cfs_fail_timeout id 715 awake [ 7745.796425] Lustre: 180826:0:(ldlm_lib.c:3014:target_recovery_thread()) too long recovery - read logs [ 7745.801720] LustreError: dumping log to /tmp/lustre-log.1787870172.180826 [ 7746.014193] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:6926 to 0x280000400:6945) [ 7746.015254] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:7023 to 0x240000400:7041) [ 7752.352760] Lustre: DEBUG MARKER: oleg128-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 7754.014757] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 7763.252860] Lustre: DEBUG MARKER: == replay-single test complete, duration 7556 sec ======== 18:36:27 (1787870187) [ 7764.975927] Lustre: DEBUG MARKER: === replay-single: start cleanup 18:36:29 (1787870189) === [ 7775.974170] Lustre: DEBUG MARKER: === replay-single: finish cleanup 18:36:39 (1787870199) === [ 7808.338783] Lustre: server umount lustre-MDT0000 complete [ 7812.907450] LustreError: 127714:0:(ldlm_lockd.c:2564:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1787870239 with bad export cookie 783713259694155826 [ 7823.522669] Lustre: server umount lustre-OST0000 complete [ 7827.836176] Lustre: server umount lustre-OST0001 complete [ 7839.970164] Lustre: DEBUG MARKER: oleg128-server.virtnet: executing unload_modules_local [ 7842.387449] Key type lgssc unregistered [ 7842.616882] LNet: 182961:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 7842.630969] LNetError: 182961:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 7843.691427] LNet: Removed LNI 192.168.201.128@tcp [ 7844.786190] Key type .llcrypt unregistered [ 7844.788207] Key type ._llcrypt unregistered