[ 0.000000] Linux version 4.18.0rh8.10-debug (green@maintenance) (gcc version 8.5.0 20210514 (Red Hat 8.5.0-26) (GCC)) #2 SMP Mon Jul 14 01:24:22 EDT 2025 [ 0.000000] Command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] x86/fpu: Supporting XSAVE feature 0x001: 'x87 floating point registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x002: 'SSE registers' [ 0.000000] x86/fpu: Supporting XSAVE feature 0x004: 'AVX registers' [ 0.000000] x86/fpu: xstate_offset[2]: 576, xstate_sizes[2]: 256 [ 0.000000] x86/fpu: Enabled xstate features 0x7, context size is 832 bytes, using 'standard' format. [ 0.000000] signal: max sigframe size: 1776 [ 0.000000] BIOS-provided physical RAM map: [ 0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable [ 0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000000f0000-0x00000000000fffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000000100000-0x00000000bffcdfff] usable [ 0.000000] BIOS-e820: [mem 0x00000000bffce000-0x00000000bfffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000100000000-0x0000000146dfffff] usable [ 0.000000] NX (Execute Disable) protection: active [ 0.000000] SMBIOS 2.8 present. [ 0.000000] DMI: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.17.0-8.fc42 06/10/2025 [ 0.000000] Hypervisor detected: KVM [ 0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00 [ 0.000000] kvm-clock: using sched offset of 506768271 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2399.998 MHz processor [ 0.000000] last_pfn = 0x146e00 max_arch_pfn = 0x400000000 [ 0.000000] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT [ 0.000000] last_pfn = 0xbffce max_arch_pfn = 0x400000000 [ 0.000000] found SMP MP-table at [mem 0x000f54b0-0x000f54bf] [ 0.000000] RAMDISK: [mem 0xbcc54000-0xbffbffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F52D0 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE2439 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE22D5 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 002295 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE2349 000090 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE23D9 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE2411 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe22d5-0xbffe2348] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe22d4] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe2349-0xbffe23d8] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe23d9-0xbffe2410] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe2411-0xbffe2438] [ 0.000000] No NUMA configuration found [ 0.000000] Faking a node at [mem 0x0000000000000000-0x0000000146dfffff] [ 0.000000] NODE_DATA(0) allocated [mem 0x1465a3000-0x1465cdfff] [ 0.000000] Reserving 256MB of memory at 2752MB for crashkernel (System RAM: 4205MB) [ 0.000000] Zone ranges: [ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.000000] DMA32 [mem 0x0000000001000000-0x00000000ffffffff] [ 0.000000] Normal [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Device empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff] [ 0.000000] node 0: [mem 0x0000000000100000-0x00000000bffcdfff] [ 0.000000] node 0: [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Zeroed struct page in unavailable ranges: 4756 pages [ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x0000000146dfffff] [ 0.000000] ACPI: PM-Timer IO Port: 0x608 [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) [ 0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) [ 0.000000] Using ACPI (MADT) for SMP configuration information [ 0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000] TSC deadline timer available [ 0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs [ 0.000000] kvm-guest: KVM setup pv remote TLB flush [ 0.000000] kvm-guest: setup PV sched yield [ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff] [ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff] [ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff] [ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff] [ 0.000000] PM: Registered nosave memory: [mem 0xbffce000-0xbfffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xc0000000-0xfeffbfff] [ 0.000000] PM: Registered nosave memory: [mem 0xfeffc000-0xfeffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xff000000-0xfffbffff] [ 0.000000] PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff] [ 0.000000] [mem 0xc0000000-0xfeffbfff] available for PCI devices [ 0.000000] Booting paravirtualized kernel on KVM [ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns [ 0.000000] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1 [ 0.000000] percpu: Embedded 63 pages/cpu s221184 r8192 d28672 u524288 [ 0.000000] kvm-guest: PV spinlocks enabled [ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1059606 [ 0.000000] Policy zone: Normal [ 0.000000] Kernel command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] Specific versions of hardware are certified with Red Hat Enterprise Linux 8. Please see the list of hardware certified with Red Hat Enterprise Linux 8 at https://catalog.redhat.com. [ 0.000000] audit: disabled (until reboot) [ 0.000000] software IO TLB: area num 4. [ 0.000000] Memory: 2829652K/4306352K available (18435K kernel code, 11221K rwdata, 7248K rodata, 2908K init, 18040K bss, 524580K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] ftrace: allocating 41240 entries in 162 pages [ 0.000000] ftrace: allocated 162 pages with 3 groups [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] rcu: RCU event tracing is enabled. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ 0.000000] rcu: RCU callback double-/use-after-free debug enabled. [ 0.000000] Rude variant of Tasks RCU enabled. [ 0.000000] Tracing variant of Tasks RCU enabled. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 0.000000] NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16 [ 0.000000] random: get_random_bytes called from start_kernel+0x622/0x9a8 with crng_init=0 [ 0.001000] Console: colour *CGA 80x25 [ 0.001000] printk: console [ttyS1] enabled [ 0.001000] ACPI: Core revision 20220331 [ 0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.001009] APIC: Switch to symmetric I/O mode setup [ 0.003148] x2apic enabled [ 0.004005] Switched APIC routing to physical x2apic. [ 0.005019] kvm-guest: setup PV IPIs [ 0.008445] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.009000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.009021] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.010009] pid_max: default: 32768 minimum: 301 [ 0.011136] LSM: Security Framework initializing [ 0.012047] Yama: becoming mindful. [ 0.013040] SELinux: Initializing. [ 0.014050] *** VALIDATE selinux *** [ 0.023538] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.027697] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.028120] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.029072] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.030083] *** VALIDATE tmpfs *** [ 0.031388] *** VALIDATE proc *** [ 0.032171] *** VALIDATE cgroup *** [ 0.033005] *** VALIDATE cgroup2 *** [ 0.034190] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.035117] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.036003] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.037018] Spectre V2 : User space: Vulnerable [ 0.038005] Speculative Store Bypass: Vulnerable [ 0.041073] debug: unmapping init [mem 0xffffffffa6459000-0xffffffffa6460fff] [ 0.043966] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.044572] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.045015] ... version: 2 [ 0.046006] ... bit width: 48 [ 0.047005] ... generic registers: 4 [ 0.047946] ... value mask: 0000ffffffffffff [ 0.048008] ... max period: 00007fffffffffff [ 0.049006] ... fixed-purpose events: 3 [ 0.050005] ... event mask: 000000070000000f [ 0.051335] rcu: Hierarchical SRCU implementation. [ 0.053343] smp: Bringing up secondary CPUs ... [ 0.054506] x86: Booting SMP configuration: [ 0.055013] .... node #0, CPUs: #1 #2 #3 [ 0.069119] smp: Brought up 1 node, 4 CPUs [ 0.071010] smpboot: Max logical packages: 1 [ 0.072008] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.104412] node 0 deferred pages initialised in 30ms [ 0.108180] devtmpfs: initialized [ 0.109318] x86/mm: Memory block size: 128MB [ 0.112207] gcov: version magic: 0x41383552 [ 0.114132] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.115081] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.116399] pinctrl core: initialized pinctrl subsystem [ 0.117385] [ 0.118012] ************************************************************* [ 0.119049] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.120019] ** ** [ 0.121024] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.122027] ** ** [ 0.123010] ** This means that this kernel is built to expose internal ** [ 0.124010] ** IOMMU data structures, which may compromise security on ** [ 0.125010] ** your system. ** [ 0.126011] ** ** [ 0.127011] ** If you see this message and you are not debugging the ** [ 0.128009] ** kernel, report this immediately to your vendor! ** [ 0.129008] ** ** [ 0.130009] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.131008] ************************************************************* [ 0.133025] NET: Registered protocol family 16 [ 0.134553] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.135076] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.136180] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.137704] cpuidle: using governor menu [ 0.140015] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.141849] PCI: Using configuration type 1 for base access [ 0.145123] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.163262] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.165016] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.168115] cryptd: max_cpu_qlen set to 1000 [ 0.169756] ACPI: Added _OSI(Module Device) [ 0.170007] ACPI: Added _OSI(Processor Device) [ 0.171010] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.173010] ACPI: Added _OSI(Processor Aggregator Device) [ 0.179018] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.187425] ACPI: Interpreter enabled [ 0.188106] ACPI: PM: (supports S0 S3 S4 S5) [ 0.189010] ACPI: Using IOAPIC for interrupt routing [ 0.190197] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.191512] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.202895] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.203033] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.204018] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.205075] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.207580] acpiphp: Slot [2] registered [ 0.208137] acpiphp: Slot [5] registered [ 0.209124] acpiphp: Slot [6] registered [ 0.210103] acpiphp: Slot [7] registered [ 0.211103] acpiphp: Slot [8] registered [ 0.212076] acpiphp: Slot [9] registered [ 0.213089] acpiphp: Slot [10] registered [ 0.214201] acpiphp: Slot [3] registered [ 0.215109] acpiphp: Slot [4] registered [ 0.216087] acpiphp: Slot [11] registered [ 0.217073] acpiphp: Slot [12] registered [ 0.218089] acpiphp: Slot [13] registered [ 0.219144] acpiphp: Slot [14] registered [ 0.220061] acpiphp: Slot [15] registered [ 0.221063] acpiphp: Slot [16] registered [ 0.222062] acpiphp: Slot [17] registered [ 0.223168] acpiphp: Slot [18] registered [ 0.224063] acpiphp: Slot [19] registered [ 0.225073] acpiphp: Slot [20] registered [ 0.226062] acpiphp: Slot [21] registered [ 0.227083] acpiphp: Slot [22] registered [ 0.228064] acpiphp: Slot [23] registered [ 0.229092] acpiphp: Slot [24] registered [ 0.230129] acpiphp: Slot [25] registered [ 0.231140] acpiphp: Slot [26] registered [ 0.232064] acpiphp: Slot [27] registered [ 0.233068] acpiphp: Slot [28] registered [ 0.234059] acpiphp: Slot [29] registered [ 0.235066] acpiphp: Slot [30] registered [ 0.236087] acpiphp: Slot [31] registered [ 0.237044] PCI host bridge to bus 0000:00 [ 0.238021] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.239010] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.240010] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.241012] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.242013] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.243013] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.244157] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.245905] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.247340] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.255787] pci 0000:00:01.1: reg 0x20: [io 0xc320-0xc32f] [ 0.260046] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.261010] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.263010] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.266010] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.268327] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.270723] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.273027] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.275799] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.281013] pci 0000:00:02.0: reg 0x10: [io 0xc300-0xc31f] [ 0.297025] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.304015] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.310058] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.322017] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.332016] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.354012] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.372252] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.379016] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.388016] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.421023] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.435103] pci 0000:00:07.0: [1af4:1001] type 00 class 0x010000 [ 0.440014] pci 0000:00:07.0: reg 0x10: [io 0xc100-0xc17f] [ 0.445010] pci 0000:00:07.0: reg 0x14: [mem 0xfebc2000-0xfebc2fff] [ 0.458015] pci 0000:00:07.0: reg 0x20: [mem 0xe000000c000-0xe000000ffff 64bit pref] [ 0.471115] pci 0000:00:08.0: [1af4:1001] type 00 class 0x010000 [ 0.482016] pci 0000:00:08.0: reg 0x10: [io 0xc180-0xc1ff] [ 0.490015] pci 0000:00:08.0: reg 0x14: [mem 0xfebc3000-0xfebc3fff] [ 0.501016] pci 0000:00:08.0: reg 0x20: [mem 0xe0000010000-0xe0000013fff 64bit pref] [ 0.507785] pci 0000:00:09.0: [1af4:1001] type 00 class 0x010000 [ 0.512014] pci 0000:00:09.0: reg 0x10: [io 0xc200-0xc27f] [ 0.516013] pci 0000:00:09.0: reg 0x14: [mem 0xfebc4000-0xfebc4fff] [ 0.526012] pci 0000:00:09.0: reg 0x20: [mem 0xe0000014000-0xe0000017fff 64bit pref] [ 0.533000] pci 0000:00:0a.0: [1af4:1001] type 00 class 0x010000 [ 0.537022] pci 0000:00:0a.0: reg 0x10: [io 0xc280-0xc2ff] [ 0.544013] pci 0000:00:0a.0: reg 0x14: [mem 0xfebc5000-0xfebc5fff] [ 0.557014] pci 0000:00:0a.0: reg 0x20: [mem 0xe0000018000-0xe000001bfff 64bit pref] [ 0.565032] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.567347] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.570325] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.572319] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.574336] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.579700] iommu: Default domain type: Passthrough [ 0.592861] SCSI subsystem initialized [ 0.594167] ACPI: bus type USB registered [ 0.597113] usbcore: registered new interface driver usbfs [ 0.598059] usbcore: registered new interface driver hub [ 0.601127] usbcore: registered new device driver usb [ 0.603198] pps_core: LinuxPPS API ver. 1 registered [ 0.606009] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.610062] PTP clock support registered [ 0.613251] EDAC MC: Ver: 3.0.0 [ 0.615232] PCI: Using ACPI for IRQ routing [ 0.618715] NetLabel: Initializing [ 0.621011] NetLabel: domain hash size = 128 [ 0.622019] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.625196] NetLabel: unlabeled traffic allowed by default [ 0.627365] vgaarb: loaded [ 0.630497] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.633011] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.639690] clocksource: Switched to clocksource kvm-clock [ 0.784560] VFS: Disk quotas dquot_6.6.0 [ 0.787093] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.790312] *** VALIDATE ramfs *** [ 0.791873] *** VALIDATE hugetlbfs *** [ 0.793649] pnp: PnP ACPI init [ 0.796509] pnp: PnP ACPI: found 6 devices [ 0.813081] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.817265] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.820068] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.822843] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.825855] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.829055] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.833029] NET: Registered protocol family 2 [ 0.836348] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.843019] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.847696] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.853242] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.857346] TCP: Hash tables configured (established 65536 bind 65536) [ 0.861539] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.867262] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.871098] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.875460] NET: Registered protocol family 1 [ 0.879439] RPC: Registered named UNIX socket transport module. [ 0.882169] RPC: Registered udp transport module. [ 0.885314] RPC: Registered tcp transport module. [ 0.887613] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.891592] NET: Registered protocol family 44 [ 0.893577] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.896182] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.899326] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.902480] PCI: CLS 0 bytes, default 64 [ 0.905318] Unpacking initramfs... [ 3.392914] debug: unmapping init [mem 0xffff93befcc54000-0xffff93befffbffff] [ 3.397285] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 3.399527] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 3.402495] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 3.921389] Initialise system trusted keyrings [ 3.923151] Key type blacklist registered [ 3.924961] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 3.934422] zbud: loaded [ 3.937476] *** VALIDATE nfs *** [ 3.938536] *** VALIDATE nfs4 *** [ 3.940114] pstore: using deflate compression [ 3.943665] Platform Keyring initialized [ 4.370358] NET: Registered protocol family 38 [ 4.372506] Key type asymmetric registered [ 4.374644] Asymmetric key parser 'x509' registered [ 4.376491] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 4.380721] io scheduler mq-deadline registered [ 4.382600] io scheduler kyber registered [ 4.384553] io scheduler bfq registered [ 4.386529] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 4.389967] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 4.393215] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 4.396235] ACPI: Power Button [PWRF] [ 4.402405] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 4.409857] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 4.430566] ACPI: \_SB_.LNKC: Enabled at IRQ 11 [ 4.443511] ACPI: \_SB_.LNKD: Enabled at IRQ 10 [ 4.488510] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 4.520028] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 4.554846] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 4.559953] Non-volatile memory driver v1.3 [ 4.561519] Linux agpgart interface v0.103 [ 4.592830] virtio_blk virtio1: [vda] 134592 512-byte logical blocks (68.9 MB/65.7 MiB) [ 4.594811] vda: detected capacity change from 0 to 68911104 [ 4.625824] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 4.628130] vdb: detected capacity change from 0 to 1073741824 [ 4.665094] virtio_blk virtio3: [vdc] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 4.667693] vdc: detected capacity change from 0 to 2621440000 [ 4.688588] virtio_blk virtio4: [vdd] 5120000 512-byte logical blocks (2.62 GB/2.44 GiB) [ 4.691921] vdd: detected capacity change from 0 to 2621440000 [ 4.707842] virtio_blk virtio5: [vde] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 4.710271] vde: detected capacity change from 0 to 4294967296 [ 4.729910] virtio_blk virtio6: [vdf] 8388608 512-byte logical blocks (4.29 GB/4.00 GiB) [ 4.733127] vdf: detected capacity change from 0 to 4294967296 [ 4.750804] libphy: Fixed MDIO Bus: probed [ 4.771996] usbcore: registered new interface driver usbserial_generic [ 4.777932] usbserial: USB Serial support registered for generic [ 4.781152] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 4.788823] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 4.790222] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 4.792294] mousedev: PS/2 mouse device common for all mice [ 4.795182] rtc_cmos 00:05: RTC can wake from S4 [ 4.801580] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 4.802804] rtc_cmos 00:05: registered as rtc0 [ 4.808427] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 4.810535] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 4.814690] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 4.816361] intel_pstate: CPU model not supported [ 4.822617] hid: raw HID events driver (C) Jiri Kosina [ 4.824360] usbcore: registered new interface driver usbhid [ 4.825858] usbhid: USB HID core driver [ 4.827123] drop_monitor: Initializing network drop monitor service [ 4.828850] Initializing XFRM netlink socket [ 4.831477] NET: Registered protocol family 10 [ 4.838902] Segment Routing with IPv6 [ 4.841450] NET: Registered protocol family 17 [ 4.844254] mpls_gso: MPLS GSO support [ 4.850659] RAS: Correctable Errors collector initialized. [ 4.853300] AVX version of gcm_enc/dec engaged. [ 4.855227] AES CTR mode by8 optimization enabled [ 4.962232] sched_clock: Marking stable (4962212648, 0)->(5972293049, -1010080401) [ 4.966511] registered taskstats version 1 [ 4.968693] Loading compiled-in X.509 certificates [ 4.979445] zswap: loaded using pool lzo/zbud [ 5.039225] Key type big_key registered [ 5.069534] Key type encrypted registered [ 5.073110] ima: No TPM chip found, activating TPM-bypass! [ 5.074650] ima: Allocated hash algorithm: sha1 [ 5.076674] ima: No architecture policies found [ 5.079325] evm: Initialising EVM extended attributes: [ 5.081111] evm: security.selinux [ 5.082357] evm: security.ima [ 5.083399] evm: security.capability [ 5.084449] evm: HMAC attrs: 0x1 [ 5.086641] rtc_cmos 00:05: setting system clock to 2026-01-10 01:21:37 UTC (1768008097) [ 5.094140] debug: unmapping init [mem 0xffffffffa7403000-0xffffffffa75fffff] [ 5.097218] debug: unmapping init [mem 0xffffffffa6182000-0xffffffffa6458fff] [ 5.105139] Write protecting the kernel read-only data: 28672k [ 5.109509] debug: unmapping init [mem 0xffffffffa4803000-0xffffffffa49fffff] [ 5.111889] debug: unmapping init [mem 0xffffffffa5114000-0xffffffffa51fffff] [ 5.156176] 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) [ 5.163559] systemd[1]: Detected virtualization kvm. [ 5.165770] systemd[1]: Detected architecture x86-64. [ 5.168168] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 5.200196] systemd[1]: No hostname configured. [ 5.202075] systemd[1]: Set hostname to . [ 5.204515] random: systemd: uninitialized urandom read (16 bytes read) [ 5.207385] systemd[1]: Initializing machine ID from random generator. [ 5.308690] random: ln: uninitialized urandom read (6 bytes read) [ 5.547797] random: systemd: uninitialized urandom read (16 bytes read) [ 5.549966] systemd[1]: Listening on udev Kernel Socket. [ OK ] Listening on udev Kernel Socket. [ 5.564543] systemd[1]: Reached target Initrd Root Device. [ OK ] Reached target Initrd Root Device. [ 5.579317] systemd[1]: Listening on udev Control Socket. [ OK ] Listening on udev Control Socket. [ OK ] Listening on Journal Socket. [ OK ] Started Memstrack Anylazing Service. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Listening on Journal Socket (/dev/log). [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Slices. [ OK ] Reached target Swap. [ OK ] Reached target Sockets. [ OK ] Reached target Timers. Starting Journal Service... Starting Apply Kernel Variables... [ OK ] Reached target Local File Systems. Starting Create Volatile Files and Directories... [ OK ] Reached target Local Encrypted Volumes. Starting Setup Virtual Console... [ OK ] Reached target Paths. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Apply Kernel Variables. [ OK ] Started Create Volatile Files and Directories. [ OK ] Started Setup Virtual Console. 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... [ 7.103495] device-mapper: uevent: version 1.0.3 [ 7.106401] 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... [ OK ] Started udev Coldplug all Devices. [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting dracut initqueue hook... Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ 8.909709] virtio_net virtio0 ens2: renamed from eth0 [ 9.036991] random: fast init done [ 9.234889] scsi host0: ata_piix [ 9.370240] scsi host1: ata_piix [ 9.378273] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc320 irq 14 [ 9.381588] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc328 irq 15 [ 13.600228] random: crng init done [ 13.601762] random: 7 urandom warning(s) missed due to ratelimiting [ 16.490893] dracut-initqueue[575]: RTNETLINK answers: File exists Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. Mounting /sysroot... [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. [ 17.874393] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Timers. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Sockets. [ OK ] Stopped target Paths. [ OK ] Stopped target Slices. [ OK ] Stopped target System Initialization. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. [ OK ] Stopped target Swap. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. Stopping udev Kernel Device Manager... [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Closed udev Control Socket. [ OK ] Closed udev Kernel Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 20.531848] printk: systemd: 26 output lines suppressed due to ratelimiting [ 21.189957] SELinux: Disabled at runtime. [ 21.249511] 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) [ 21.258729] systemd[1]: Detected virtualization kvm. [ 21.296641] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 23.151506] systemd[1]: initrd-switch-root.service: Succeeded. [ 23.156167] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 23.173897] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 23.182319] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 23.190271] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 23.216460] systemd[1]: Starting Journal Service... Starting Journal Service... [ 23.229888] systemd[1]: Activating swap /dev/disk/by-label/SWAP... Activating swap /dev/disk/by-label/SWAP... [ OK ] Created slice system-sshd\x2dkeygen.slice. [ 23.452894] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Created slice system-serial\x2dgetty.slice. [ OK ] Stopped target Switch Root. Mounting Kernel Debug File System... [ OK ] Stopped target Initrd Root File System. [ OK ] Listening on udev Control Socket. Starting Remount Root and Kernel File Systems... [ OK ] Stopped target Initrd File Systems. Starting Apply Kernel Variables... [ OK ] Created slice User and Session Slice. [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Listening on udev Kernel Socket. [ OK ] Listening on Process Core Dump Socket. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Reached target Slices. [ OK ] Reached target rpc_pipefs.target. Starting udev Coldplug all Devices... [ OK ] Started Forward Password Requests to Wall Directory Watch. [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Created slice system-getty.slice. Mounting POSIX Message Queue File System... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Paths. [ OK ] Reached target Local Encrypted Volumes. Mounting Huge Pages File System... [ OK ] Reached target RPC Port Mapper. [ OK ] Started Journal Service. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Mounted Kernel Debug File System. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Started Apply Kernel Variables. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Mounted POSIX Message Queue File System. [ OK [0[ 24.727450] hrtimer: interrupt took 6442293 ns m] Mounted Huge Pages File System. Starting Create Static Device Nodes in /dev... Starting Configure read-only root support... [ OK ] Reached target Swap. Starting Flush Journal to Persistent Storage... [ OK ] Started udev Coldplug all Devices. [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Reached target Local File Systems (Pre). Mounting /mnt... Mounting /home/green/git/lustre-release... Starting udev Kernel Device Manager... [ OK ] Mounted /mnt. [ 25.726197] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 26.780237] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 27.023837] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 27.310086] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 27.363253] EDAC sbridge: Ver: 1.1.2 [* ] A start job is running for Configur…-only root support (8s / no limit)[ 32.130165] Key type dns_resolver registered [** ] A start job is running for Configur…-only root support (9s / no limit)[ 32.889701] NFS: Registering the id_resolver key type [ 32.892238] Key type id_resolver registered [ 32.897244] Key type id_legacy registered [*** ] A start job is running for Configur…-only root support (9s / no limit) [ *** ] A start job is running for Configur…only root support (10s / no limit) [ 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 ] Started dnf makecache --timer. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Reached target Timers. [ 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 ] Reached target sshd-keygen.target. Starting Login Service... [ OK ] Started irqbalance daemon. [ OK ] Started D-Bus System Message Bus. Starting Network Manager... [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Network Manager. [ OK ] Started Login Service. Starting Hostname Service... Starting Network Manager Wait Online... [ OK ] Reached target Network. Starting Dynamic System Tuning Daemon... Starting OpenSSH server daemon... Starting GSSAPI Proxy 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 OpenSSH server daemon. [ OK ] Started Permit User Sessions. [ OK ] Started Serial Getty on ttyS1. [ OK ] Started Getty on tty1. [ OK ] Started Command Scheduler. [ OK ] Started Serial Getty on ttyS0. [ OK ] Reached target Login Prompts. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting System Logging Service... Starting Crash recovery kernel arming... Starting Notify NFS peers of a restart... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg334-server login: [ 55.575836] spl: loading out-of-tree module taints kernel. [ 58.050638] ZFS: Loaded module v2.3.2-1, ZFS pool version 5000, ZFS filesystem version 5 [ 62.822154] Key type ._llcrypt registered [ 62.824349] Key type .llcrypt registered [ 62.880861] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_hostid [ 71.229429] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing load_modules_local [ 71.827426] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 1 [ 71.835360] alg: No test for adler32 (adler32-zlib) [ 72.875555] Lustre: Lustre: Build Version: 2.17.0_RC3_1_g8820be3 [ 73.228400] LNet: Added LNI 192.168.203.134@tcp [8/256/0/180] [ 74.847158] Key type lgssc registered [ 75.439763] Lustre: Echo OBD driver; http://www.lustre.org/ [ 79.649083] vdc: vdc1 vdc9 [ 79.656140] vdc: vdc1 vdc9 [ 83.965132] vde: vde1 vde9 [ 88.461550] vdf: vdf1 vdf9 [ 88.473699] vdf: vdf1 vdf9 [ 96.327544] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing load_modules_local [ 100.407525] Lustre: lustre-MDT0000: mounting server target with '-t lustre' deprecated, use '-t lustre_tgt' [ 101.593223] Lustre: Setting parameter lustre-MDT0000.mdt.identity_upcall=/home/green/git/lustre-release/lustre/utils/l_getidentity in log lustre-MDT0000 [ 101.731180] Lustre: ctl-lustre-MDT0000: No data found on store. Initialize space. [ 101.786795] Lustre: lustre-MDT0000: new disk, initializing [ 101.988458] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 102.027867] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400]:0:mdt [ 103.904126] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 106.547654] Lustre: Modifying parameter general.debug_raw_pointers=Y in log params [ 108.828217] Lustre: lustre-OST0000: new disk, initializing [ 108.830069] Lustre: srv-lustre-OST0000: No data found on store. Initialize space. [ 108.831704] Lustre: Skipped 1 previous similar message [ 108.857973] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 111.296488] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 115.951113] Lustre: lustre-OST0001: new disk, initializing [ 115.953125] Lustre: srv-lustre-OST0001: No data found on store. Initialize space. [ 115.983411] Lustre: lustre-OST0001: Imperative Recovery not enabled, recovery window 60-180 [ 116.418155] Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000240000400-0x0000000280000400]:0:ost [ 116.421090] Lustre: cli-lustre-OST0000-super: Allocated super-sequence [0x0000000240000400-0x0000000280000400]:0:ost] [ 116.502156] Lustre: lustre-OST0000-osc-MDT0000: update sequence from 0x100000000 to 0x240000400 [ 116.521476] Lustre: lustre-OST0001-osc-MDT0000: update sequence from 0x100010000 to 0x280000400 [ 118.586967] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 125.164062] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 128.453797] Lustre: Setting parameter general.lod.*.mdt_hash=crush in log params [ 135.394868] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing check_logdir /tmp/testlogs/ [ 136.819620] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing yml_node [ 139.037174] Lustre: DEBUG MARKER: Client: 2.17.0.RC3 [ 140.161298] Lustre: DEBUG MARKER: MDS: 2.17.0.RC3 [ 141.576463] Lustre: DEBUG MARKER: OSS: 2.17.0.RC3 [ 142.628940] Lustre: DEBUG MARKER: -----============= acceptance-small: replay-single ============----- Fri Jan 9 20:23:53 EST 2026 [ 156.069546] Lustre: DEBUG MARKER: excepting tests: 59 36 [ 157.410650] Lustre: DEBUG MARKER: === replay-single: start setup 20:24:08 (1768008248) === [ 160.491814] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing check_config_client /mnt/lustre [ 173.829334] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 176.036763] Lustre: 10979:0:(mgs_llog.c:1348:mgs_modify_param()) MGS: modify general/lod.*.mdt_hash=crush (mode = 0) failed: rc = -17 [ 177.855856] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 179.742403] Lustre: DEBUG MARKER: === replay-single: finish setup 20:24:31 (1768008271) === [ 180.701320] Lustre: DEBUG MARKER: == replay-single test 0a: empty replay =================== 20:24:32 (1768008272) [ 182.088618] LustreError: 11455:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 182.465809] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 183.367170] Lustre: Failing over lustre-MDT0000 [ 183.454394] LustreError: 11606:0:(obd_class.h:479:obd_check_dev()) Device 17 not setup [ 183.493669] Lustre: server umount lustre-MDT0000 complete [ 197.235373] LustreError: MGC192.168.203.134@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 197.427283] 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 [ 197.537698] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 199.291722] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 199.339345] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 199.573337] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 202.725915] Lustre: lustre-MDT0000-lwp-OST0000: Connection restored to 0@lo (at 0@lo) [ 203.679189] Lustre: 3281:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1768008280/real 1768008280] req@ffff93bf76899c00 x1853890929665280/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1768008296 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 204.212573] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 204.575157] Lustre: 3280:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1768008280/real 1768008280] req@ffff93bf76898700 x1853890929665152/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1768008296 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 205.176775] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 208.863305] Lustre: 3280:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1768008285/real 1768008285] req@ffff93bf7f89b100 x1853890929665536/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1768008301 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 210.197986] Lustre: DEBUG MARKER: == replay-single test 0b: ensure object created after recover exists. (3284) ========================================================== 20:25:01 (1768008301) [ 211.326062] Lustre: Failing over lustre-OST0000 [ 211.380249] LustreError: 12822:0:(obd_class.h:479:obd_check_dev()) Device 12 not setup [ 211.382709] LustreError: 12822:0:(obd_class.h:479:obd_check_dev()) Skipped 5 previous similar messages [ 211.403545] Lustre: server umount lustre-OST0000 complete [ 212.960420] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 212.960429] 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 [ 212.960436] Lustre: Skipped 1 previous similar message [ 218.079759] LustreError: 7458:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 218.091557] LustreError: 7458:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 3 previous similar messages [ 219.738868] LustreError: 6538:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.203.34@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 223.200272] LustreError: 6538:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 225.205931] Lustre: lustre-OST0000: Imperative Recovery not enabled, recovery window 60-180 [ 226.486824] Lustre: lustre-OST0000: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 227.316983] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 227.318471] Lustre: lustre-OST0000: Recovery over after 0:01, of 2 clients 2 recovered and 0 were evicted. [ 227.323092] Lustre: Skipped 1 previous similar message [ 229.062415] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 233.898293] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 234.870761] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 240.900316] Lustre: DEBUG MARKER: == replay-single test 0c: check replay-barrier =========== 20:25:32 (1768008332) [ 242.606812] LustreError: 14150:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 243.096209] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 244.279665] Lustre: Failing over lustre-MDT0000 [ 244.401420] LustreError: 14297:0:(obd_class.h:479:obd_check_dev()) Device 16 not setup [ 244.408270] LustreError: 14297:0:(obd_class.h:479:obd_check_dev()) Skipped 1 previous similar message [ 244.465172] Lustre: server umount lustre-MDT0000 complete [ 258.069682] LustreError: MGC192.168.203.134@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 258.214387] 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 [ 258.226201] Lustre: Skipped 1 previous similar message [ 258.305497] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 260.348318] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 261.428277] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 261.436123] Lustre: lustre-MDT0000: Denying connection for new client e64efb67-165c-4001-83a7-56326702e0dc (at 192.168.203.34@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 1:00 [ 262.367284] Lustre: 3279:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1768008338/real 1768008338] req@ffff93bf6fe69180 x1853890929689344/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1768008354 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 262.390489] Lustre: 3279:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 263.650290] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 266.841626] Lustre: lustre-MDT0000: Denying connection for new client e64efb67-165c-4001-83a7-56326702e0dc (at 192.168.203.34@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:54 [ 267.424456] Lustre: 3281:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1768008343/real 1768008343] req@ffff93bf6fe6b480 x1853890929689728/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1768008359 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 267.436595] Lustre: 3281:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 271.966438] Lustre: lustre-MDT0000: Denying connection for new client e64efb67-165c-4001-83a7-56326702e0dc (at 192.168.203.34@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:49 [ 277.083289] Lustre: lustre-MDT0000: Denying connection for new client e64efb67-165c-4001-83a7-56326702e0dc (at 192.168.203.34@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:44 [ 282.201917] Lustre: lustre-MDT0000: Denying connection for new client e64efb67-165c-4001-83a7-56326702e0dc (at 192.168.203.34@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:39 [ 292.442306] Lustre: lustre-MDT0000: Denying connection for new client e64efb67-165c-4001-83a7-56326702e0dc (at 192.168.203.34@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:29 [ 292.457243] Lustre: Skipped 1 previous similar message [ 312.921343] Lustre: lustre-MDT0000: Denying connection for new client e64efb67-165c-4001-83a7-56326702e0dc (at 192.168.203.34@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 0:08 [ 312.928259] Lustre: Skipped 3 previous similar messages [ 321.500550] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 321.513647] Lustre: 14754:0:(genops.c:1618:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client 81b7fac3-5adc-426c-8200-b5e9d236b144@ [ 321.524449] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 321.548383] Lustre: lustre-MDT0000: Recovery over after 1:00, of 1 clients 0 recovered and 1 was evicted. [ 321.570751] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:44 to 0x240000400:65) [ 321.570816] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:44 to 0x280000400:65) [ 328.397321] Lustre: DEBUG MARKER: == replay-single test 0d: expired recovery with no clients ========================================================== 20:26:59 (1768008419) [ 330.071820] LustreError: 15471:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 330.579302] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 331.607944] Lustre: Failing over lustre-MDT0000 [ 331.735594] LustreError: 15617:0:(obd_class.h:479:obd_check_dev()) Device 16 not setup [ 331.737693] LustreError: 15617:0:(obd_class.h:479:obd_check_dev()) Skipped 5 previous similar messages [ 331.777789] Lustre: server umount lustre-MDT0000 complete [ 345.756691] LustreError: MGC192.168.203.134@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 346.045407] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 348.075600] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 349.350120] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 349.356543] Lustre: lustre-MDT0000: Denying connection for new client c4330d47-e9c3-460b-9b23-f34cc6c89b63 (at 192.168.203.34@tcp), waiting for 1 known clients (0 recovered, 0 in progress, and 0 evicted) to recover in 1:00 [ 349.366468] Lustre: Skipped 1 previous similar message [ 351.073120] Lustre: 3279:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1768008427/real 1768008427] req@ffff93bf7689ad80 x1853890929713024/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1768008443 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 351.087934] Lustre: 3279:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 351.091495] 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 [ 351.098402] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 351.105476] Lustre: Skipped 1 previous similar message [ 409.500463] Lustre: lustre-MDT0000: recovery is timed out, evict stale exports [ 409.503879] Lustre: 16063:0:(genops.c:1618:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client e64efb67-165c-4001-83a7-56326702e0dc@ [ 409.515171] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 409.569391] Lustre: lustre-MDT0000: Recovery over after 1:00, of 1 clients 0 recovered and 1 was evicted. [ 409.604993] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:44 to 0x280000400:97) [ 409.606685] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:44 to 0x240000400:97) [ 416.276801] Lustre: DEBUG MARKER: == replay-single test 1: simple create =================== 20:28:27 (1768008507) [ 418.021133] LustreError: 16780:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 418.546428] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 419.659452] Lustre: Failing over lustre-MDT0000 [ 419.786095] LustreError: 16926:0:(obd_class.h:479:obd_check_dev()) Device 16 not setup [ 419.790520] LustreError: 16926:0:(obd_class.h:479:obd_check_dev()) Skipped 5 previous similar messages [ 419.840594] Lustre: server umount lustre-MDT0000 complete [ 433.543065] LustreError: MGC192.168.203.134@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 433.819903] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 435.911976] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 436.358743] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 436.479977] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 436.509874] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:44 to 0x240000400:129) [ 436.510760] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:44 to 0x280000400:129) [ 438.752464] 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 [ 438.759259] Lustre: Skipped 1 previous similar message [ 438.762714] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 438.764384] Lustre: Skipped 1 previous similar message [ 439.775347] Lustre: 3282:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1768008515/real 1768008515] req@ffff93bf6fe6b800 x1853890929733504/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1768008531 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 439.792529] Lustre: 3282:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 6 previous similar messages [ 440.167476] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 440.944300] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 445.978317] Lustre: DEBUG MARKER: == replay-single test 2a: touch ========================== 20:28:57 (1768008537) [ 447.346346] LustreError: 18197:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 447.760114] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 448.675396] Lustre: Failing over lustre-MDT0000 [ 448.821910] LustreError: 18345:0:(obd_class.h:479:obd_check_dev()) Device 16 not setup [ 448.823975] LustreError: 18345:0:(obd_class.h:479:obd_check_dev()) Skipped 5 previous similar messages [ 448.873974] Lustre: server umount lustre-MDT0000 complete [ 462.514695] LustreError: MGC192.168.203.134@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 462.652930] 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 [ 462.661298] Lustre: Skipped 1 previous similar message [ 464.477704] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 466.776946] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 466.857167] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 466.891193] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:131 to 0x280000400:161) [ 466.891548] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:44 to 0x240000400:161) [ 467.937967] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 467.942705] Lustre: Skipped 1 previous similar message [ 468.480837] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 469.209672] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 473.582232] Lustre: DEBUG MARKER: == replay-single test 2b: touch ========================== 20:29:25 (1768008565) [ 474.962376] LustreError: 19615:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 475.103304] Lustre: 3279:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1768008551/real 1768008551] req@ffff93bf7ec1ca80 x1853890929745280/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1768008567 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 475.126196] Lustre: 3279:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 9 previous similar messages [ 475.385098] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 476.380179] Lustre: Failing over lustre-MDT0000 [ 476.545573] LustreError: 19761:0:(obd_class.h:479:obd_check_dev()) Device 16 not setup [ 476.548720] LustreError: 19761:0:(obd_class.h:479:obd_check_dev()) Skipped 5 previous similar messages [ 476.603883] Lustre: server umount lustre-MDT0000 complete [ 489.904620] LustreError: MGC192.168.203.134@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 490.058633] 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 [ 490.071160] Lustre: Skipped 2 previous similar messages [ 491.787662] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 492.672926] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 492.749454] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 492.768094] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:131 to 0x280000400:193) [ 492.768445] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:163 to 0x240000400:193) [ 495.589926] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 495.594146] Lustre: Skipped 1 previous similar message [ 496.209360] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 497.006419] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 501.911043] Lustre: DEBUG MARKER: == replay-single test 2c: setstripe replay =============== 20:29:53 (1768008593) [ 503.436793] LustreError: 21028:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 503.869641] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 504.708405] Lustre: Failing over lustre-MDT0000 [ 504.860513] Lustre: server umount lustre-MDT0000 complete [ 518.166190] LustreError: MGC192.168.203.134@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 518.257843] LustreError: 21583:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.203.34@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 518.265199] LustreError: 21583:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 1 previous similar message [ 518.396213] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 518.398986] Lustre: Skipped 2 previous similar messages [ 520.140776] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:225) [ 520.140827] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:225) [ 520.209307] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 524.642176] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 525.566892] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 530.292903] Lustre: DEBUG MARKER: == replay-single test 2d: setdirstripe replay ============ 20:30:21 (1768008621) [ 531.981023] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 532.943257] Lustre: Failing over lustre-MDT0000 [ 533.095079] LustreError: 22595:0:(obd_class.h:479:obd_check_dev()) Device 16 not setup [ 533.098360] LustreError: 22595:0:(obd_class.h:479:obd_check_dev()) Skipped 11 previous similar messages [ 533.130285] Lustre: server umount lustre-MDT0000 complete [ 547.092771] 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 [ 547.097082] Lustre: Skipped 3 previous similar messages [ 548.971266] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 548.976743] Lustre: Skipped 1 previous similar message [ 549.004810] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 549.043703] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 549.046086] Lustre: Skipped 1 previous similar message [ 549.060961] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:257) [ 549.064210] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:257) [ 550.175333] Lustre: 3281:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1768008626/real 1768008626] req@ffff93bf6fe6a300 x1853890929779712/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1768008642 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 550.192392] Lustre: 3281:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 12 previous similar messages [ 552.422156] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 552.429025] Lustre: Skipped 3 previous similar messages [ 553.263273] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 554.207446] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 559.054855] Lustre: DEBUG MARKER: == replay-single test 2e: O_CREAT|O_EXCL create replay === 20:30:50 (1768008650) [ 559.656223] Lustre: *** cfs_fail_loc=13b, val=315*** [ 559.661646] Lustre: *** cfs_fail_loc=13b, val=2147483648*** [ 559.663895] LustreError: 23000:0:(ldlm_lib.c:3326:target_send_reply_msg()) @@@ dropping reply req@ffff93bf6f446a00 x1853890921337088/t38654705666(0) o35->c4330d47-e9c3-460b-9b23-f34cc6c89b63@192.168.203.34@tcp:254/0 lens 392/456 e 0 to 0 dl 1768008669 ref 1 fl Interpret:/600/0 rc 0/0 job:'openfile.0' uid:0 gid:0 projid:0 [ 562.154374] LustreError: 23907:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 562.157294] LustreError: 23907:0:(osd_handler.c:720:osd_ro()) Skipped 1 previous similar message [ 562.564497] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 563.428376] Lustre: Failing over lustre-MDT0000 [ 563.620163] Lustre: server umount lustre-MDT0000 complete [ 577.285156] LustreError: MGC192.168.203.134@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 577.290289] LustreError: Skipped 1 previous similar message [ 579.607467] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 579.757521] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:289) [ 579.758121] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:289) [ 579.767079] Lustre: 24467:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff93bf7f898380 x1853890921337088/t38654705666(0) o35->c4330d47-e9c3-460b-9b23-f34cc6c89b63@192.168.203.34@tcp:274/0 lens 392/456 e 0 to 0 dl 1768008689 ref 1 fl Interpret:/602/0 rc 0/0 job:'openfile.0' uid:0 gid:0 projid:0 [ 584.050829] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 584.932471] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 589.578801] Lustre: DEBUG MARKER: == replay-single test 3a: replay failed open(O_DIRECTORY) ========================================================== 20:31:21 (1768008681) [ 591.608146] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 592.540472] Lustre: Failing over lustre-MDT0000 [ 592.779411] Lustre: server umount lustre-MDT0000 complete [ 606.189555] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 607.987817] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 610.381878] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:321) [ 610.383436] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:321) [ 612.001934] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 612.837959] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 616.961198] Lustre: DEBUG MARKER: == replay-single test 3b: replay failed open -ENOMEM ===== 20:31:48 (1768008708) [ 618.507794] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 618.898784] Lustre: *** cfs_fail_loc=114, val=0*** [ 620.069183] Lustre: Failing over lustre-MDT0000 [ 620.197078] LustreError: 26998:0:(obd_class.h:479:obd_check_dev()) Device 16 not setup [ 620.199686] LustreError: 26998:0:(obd_class.h:479:obd_check_dev()) Skipped 17 previous similar messages [ 620.232824] Lustre: server umount lustre-MDT0000 complete [ 633.591293] 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 [ 633.597823] Lustre: Skipped 4 previous similar messages [ 633.680750] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 635.356435] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 636.001673] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 636.007947] Lustre: Skipped 2 previous similar messages [ 636.050130] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 636.053319] Lustre: Skipped 2 previous similar messages [ 636.070612] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:353) [ 636.070634] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:353) [ 638.948452] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 638.952122] Lustre: Skipped 5 previous similar messages [ 639.110787] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 639.744345] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 643.609373] Lustre: DEBUG MARKER: == replay-single test 3c: replay failed open -ENOMEM ===== 20:32:15 (1768008735) [ 644.629969] LustreError: 28260:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 644.632205] LustreError: 28260:0:(osd_handler.c:720:osd_ro()) Skipped 2 previous similar messages [ 644.962125] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 645.339552] Lustre: *** cfs_fail_loc=128, val=0*** [ 646.371263] Lustre: Failing over lustre-MDT0000 [ 646.537502] Lustre: server umount lustre-MDT0000 complete [ 659.296543] LustreError: MGC192.168.203.134@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 659.300459] LustreError: Skipped 2 previous similar messages [ 659.471309] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 659.474111] Lustre: Skipped 4 previous similar messages [ 659.496683] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 660.982651] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 661.633647] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:195 to 0x240000400:385) [ 661.637287] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:195 to 0x280000400:385) [ 664.701992] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 665.322798] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 669.107612] Lustre: DEBUG MARKER: == replay-single test 4a: |x| 10 open(O_CREAT)s ========== 20:32:40 (1768008760) [ 670.729227] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 671.644248] Lustre: Failing over lustre-MDT0000 [ 671.817630] Lustre: server umount lustre-MDT0000 complete [ 685.024238] LustreError: 30306:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 685.180666] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 686.825804] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 687.383513] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:391 to 0x280000400:417) [ 687.383608] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:391 to 0x240000400:417) [ 690.434965] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 691.045988] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 691.167168] Lustre: 3279:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1768008767/real 1768008767] req@ffff93bf7ec1d180 x1853890929837952/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1768008783 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 691.177154] Lustre: 3279:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 26 previous similar messages [ 694.794586] Lustre: DEBUG MARKER: == replay-single test 4b: |x| rm 10 files ================ 20:33:06 (1768008786) [ 696.266096] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 697.013179] Lustre: Failing over lustre-MDT0000 [ 697.199702] Lustre: server umount lustre-MDT0000 complete [ 709.809644] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 711.148721] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 712.879446] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:423 to 0x240000400:449) [ 712.879477] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:423 to 0x280000400:449) [ 714.512633] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 715.126169] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 718.992283] Lustre: DEBUG MARKER: == replay-single test 5: |x| 220 open(O_CREAT) =========== 20:33:30 (1768008810) [ 720.448643] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 723.006394] Lustre: Failing over lustre-MDT0000 [ 723.036285] Lustre: lustre-MDT0000: Not available for connect from 192.168.203.34@tcp (stopping) [ 723.255806] Lustre: server umount lustre-MDT0000 complete [ 736.161727] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 737.624911] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 744.591247] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:577) [ 744.591292] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:577) [ 745.900587] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 746.506103] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 757.473841] Lustre: DEBUG MARKER: == replay-single test 6a: mkdir + contained create ======= 20:34:09 (1768008849) [ 759.066968] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 759.872116] Lustre: Failing over lustre-MDT0000 [ 760.014853] LustreError: 34174:0:(obd_class.h:479:obd_check_dev()) Device 16 not setup [ 760.017778] LustreError: 34174:0:(obd_class.h:479:obd_check_dev()) Skipped 29 previous similar messages [ 760.067450] Lustre: server umount lustre-MDT0000 complete [ 773.416226] 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 [ 773.425419] Lustre: Skipped 10 previous similar messages [ 773.525172] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 774.242526] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 774.247081] Lustre: Skipped 4 previous similar messages [ 774.295168] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 774.297946] Lustre: Skipped 4 previous similar messages [ 774.314068] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:609) [ 774.314587] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:609) [ 775.145666] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 778.721494] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 778.726118] Lustre: Skipped 9 previous similar messages [ 778.966319] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 779.602680] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 785.410933] Lustre: DEBUG MARKER: == replay-single test 6b: |X| rmdir ====================== 20:34:37 (1768008877) [ 786.518251] LustreError: 35443:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 786.521427] LustreError: 35443:0:(osd_handler.c:720:osd_ro()) Skipped 4 previous similar messages [ 786.842844] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 787.572935] Lustre: Failing over lustre-MDT0000 [ 787.752390] Lustre: server umount lustre-MDT0000 complete [ 800.714385] LustreError: MGC192.168.203.134@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 800.719910] LustreError: Skipped 4 previous similar messages [ 802.353389] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 804.554829] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:641) [ 804.555935] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:641) [ 806.000150] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 806.635406] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 810.354167] Lustre: DEBUG MARKER: == replay-single test 7: mkdir |X| contained create ====== 20:35:02 (1768008902) [ 811.895535] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 812.638064] Lustre: Failing over lustre-MDT0000 [ 812.852773] Lustre: server umount lustre-MDT0000 complete [ 825.976722] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 825.980203] Lustre: Skipped 1 previous similar message [ 827.492109] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 829.722649] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:673) [ 829.722676] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:673) [ 831.080218] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 831.652702] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 835.396273] Lustre: DEBUG MARKER: == replay-single test 8: creat open |X| close ============ 20:35:27 (1768008927) [ 836.925839] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 837.735396] Lustre: Failing over lustre-MDT0000 [ 837.947657] Lustre: server umount lustre-MDT0000 complete [ 851.106992] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:705) [ 851.106992] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:705) [ 852.370274] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 855.826180] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 856.459287] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 860.422798] Lustre: DEBUG MARKER: == replay-single test 9: |X| create (same inum/gen) ====== 20:35:52 (1768008952) [ 861.844866] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 862.569981] Lustre: Failing over lustre-MDT0000 [ 862.748271] Lustre: server umount lustre-MDT0000 complete [ 876.712487] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:737) [ 876.712651] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:737) [ 877.543301] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 881.074434] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 881.714783] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 885.499218] Lustre: DEBUG MARKER: == replay-single test 10: create |X| rename unlink ======= 20:36:17 (1768008977) [ 886.968562] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 887.737879] Lustre: Failing over lustre-MDT0000 [ 887.921574] Lustre: server umount lustre-MDT0000 complete [ 900.760058] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 900.761882] Lustre: Skipped 2 previous similar messages [ 902.193592] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 902.302634] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:560 to 0x280000400:769) [ 902.303714] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:560 to 0x240000400:769) [ 905.573208] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 906.178797] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 909.823276] Lustre: DEBUG MARKER: == replay-single test 11: create open write rename |X| create-old-name read ========================================================== 20:36:41 (1768009001) [ 911.359048] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 912.135914] Lustre: Failing over lustre-MDT0000 [ 912.332748] Lustre: server umount lustre-MDT0000 complete [ 925.254742] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 925.257536] Lustre: Skipped 9 previous similar messages [ 926.736282] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 927.903446] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:771 to 0x280000400:801) [ 927.903596] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:771 to 0x240000400:801) [ 930.138833] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 930.754658] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 934.824410] Lustre: DEBUG MARKER: == replay-single test 12: open, unlink |X| close ========= 20:37:06 (1768009026) [ 936.465551] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 937.260235] Lustre: Failing over lustre-MDT0000 [ 937.474110] Lustre: server umount lustre-MDT0000 complete [ 951.729531] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 953.481252] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:771 to 0x240000400:833) [ 953.481474] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:771 to 0x280000400:833) [ 955.114536] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 955.749518] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 956.383163] Lustre: 3281:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1768009032/real 1768009032] req@ffff93bf496fed80 x1853890930031360/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1768009048 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 956.393048] Lustre: 3281:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 44 previous similar messages [ 959.407992] Lustre: DEBUG MARKER: == replay-single test 13: open chmod 0 |x| write close === 20:37:31 (1768009051) [ 960.897841] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 961.588342] Lustre: Failing over lustre-MDT0000 [ 961.834174] Lustre: server umount lustre-MDT0000 complete [ 976.350274] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 978.519139] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:835 to 0x240000400:865) [ 978.519596] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:771 to 0x280000400:865) [ 979.829741] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 980.427600] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 984.113310] Lustre: DEBUG MARKER: == replay-single test 14: open(O_CREAT), unlink |X| close ========================================================== 20:37:55 (1768009075) [ 985.511442] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 986.243237] Lustre: Failing over lustre-MDT0000 [ 986.407317] Lustre: server umount lustre-MDT0000 complete [ 999.560841] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:771 to 0x280000400:897) [ 999.560868] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:867 to 0x240000400:897) [ 1000.634304] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1003.992710] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1004.599064] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1008.457329] Lustre: DEBUG MARKER: == replay-single test 15: open(O_CREAT), unlink |X| touch new, close ========================================================== 20:38:20 (1768009100) [ 1010.047323] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1010.823027] Lustre: Failing over lustre-MDT0000 [ 1011.073547] Lustre: server umount lustre-MDT0000 complete [ 1025.177976] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:899 to 0x240000400:929) [ 1025.182774] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:899 to 0x280000400:929) [ 1025.451843] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1028.954076] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1029.559132] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1033.407135] Lustre: DEBUG MARKER: == replay-single test 16: |X| open(O_CREAT), unlink, touch new, unlink new ========================================================== 20:38:45 (1768009125) [ 1034.981425] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1035.748092] Lustre: Failing over lustre-MDT0000 [ 1035.913152] LustreError: 49747:0:(obd_class.h:479:obd_check_dev()) Device 16 not setup [ 1035.915782] LustreError: 49747:0:(obd_class.h:479:obd_check_dev()) Skipped 65 previous similar messages [ 1035.947356] Lustre: server umount lustre-MDT0000 complete [ 1048.614789] 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 [ 1048.620031] Lustre: Skipped 21 previous similar messages [ 1048.680139] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1048.682854] Lustre: Skipped 5 previous similar messages [ 1050.041122] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1050.715666] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1050.718479] Lustre: Skipped 10 previous similar messages [ 1050.768211] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1050.772212] Lustre: Skipped 10 previous similar messages [ 1050.787108] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:931 to 0x240000400:961) [ 1050.787182] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:899 to 0x280000400:961) [ 1053.351681] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1053.665191] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 1053.667749] Lustre: Skipped 21 previous similar messages [ 1053.938745] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1057.725454] Lustre: DEBUG MARKER: == replay-single test 17: |X| open(O_CREAT), |replay| close ========================================================== 20:39:09 (1768009149) [ 1058.797819] LustreError: 51019:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 1058.800454] LustreError: 51019:0:(osd_handler.c:720:osd_ro()) Skipped 10 previous similar messages [ 1059.135917] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1059.885348] Lustre: Failing over lustre-MDT0000 [ 1060.102577] Lustre: server umount lustre-MDT0000 complete [ 1072.856195] LustreError: MGC192.168.203.134@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1072.860543] LustreError: Skipped 10 previous similar messages [ 1074.469733] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1076.382503] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:899 to 0x280000400:993) [ 1076.382527] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:963 to 0x240000400:993) [ 1077.962533] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1078.595975] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1082.304158] Lustre: DEBUG MARKER: == replay-single test 18: open(O_CREAT), unlink, touch new, close, touch, unlink ========================================================== 20:39:34 (1768009174) [ 1083.761309] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1084.497936] Lustre: Failing over lustre-MDT0000 [ 1084.734858] Lustre: server umount lustre-MDT0000 complete [ 1098.692820] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1100.764864] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:995 to 0x240000400:1025) [ 1100.766685] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:995 to 0x280000400:1025) [ 1101.911538] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1102.441529] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1106.024601] Lustre: DEBUG MARKER: == replay-single test 19: mcreate, open, write, rename === 20:39:57 (1768009197) [ 1107.389878] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1108.105778] Lustre: Failing over lustre-MDT0000 [ 1108.272816] Lustre: server umount lustre-MDT0000 complete [ 1122.445899] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1027 to 0x280000400:1057) [ 1122.446105] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1027 to 0x240000400:1057) [ 1122.530319] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1125.793461] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1126.331671] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1129.812173] Lustre: DEBUG MARKER: == replay-single test 20a: |X| open(O_CREAT), unlink, replay, close (test mds_cleanup_orphans) ========================================================== 20:40:21 (1768009221) [ 1131.216947] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1131.941982] Lustre: Failing over lustre-MDT0000 [ 1132.168477] Lustre: server umount lustre-MDT0000 complete [ 1146.187630] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1148.035163] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1027 to 0x280000400:1089) [ 1148.035199] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1059 to 0x240000400:1089) [ 1149.447563] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1150.092853] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1153.888783] Lustre: DEBUG MARKER: == replay-single test 20b: write, unlink, eviction, replay (test mds_cleanup_orphans) ========================================================== 20:40:45 (1768009245) [ 1155.187136] Lustre: 56679:0:(genops.c:1791:obd_export_evict_by_uuid()) lustre-MDT0000: evicting c4330d47-e9c3-460b-9b23-f34cc6c89b63 at adminstrative request [ 1158.808375] Lustre: Failing over lustre-MDT0000 [ 1158.991630] Lustre: server umount lustre-MDT0000 complete [ 1173.130771] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1173.623117] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1091 to 0x240000400:1121) [ 1173.626219] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1027 to 0x280000400:1121) [ 1176.510089] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1177.072746] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1179.408095] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 1186.784933] Lustre: DEBUG MARKER: before 6144, after 6144 [ 1189.322969] Lustre: DEBUG MARKER: == replay-single test 20c: check that client eviction does not affect file content ========================================================== 20:41:21 (1768009281) [ 1189.714272] Lustre: 58413:0:(genops.c:1791:obd_export_evict_by_uuid()) lustre-MDT0000: evicting c4330d47-e9c3-460b-9b23-f34cc6c89b63 at adminstrative request [ 1194.623037] Lustre: DEBUG MARKER: == replay-single test 21: |X| open(O_CREAT), unlink touch new, replay, close (test mds_cleanup_orphans) ========================================================== 20:41:26 (1768009286) [ 1196.060269] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1196.819132] Lustre: Failing over lustre-MDT0000 [ 1197.070793] Lustre: server umount lustre-MDT0000 complete [ 1211.043221] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1213.093025] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1124 to 0x240000400:1153) [ 1213.093066] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1123 to 0x280000400:1153) [ 1214.373720] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1214.948712] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1218.618750] Lustre: DEBUG MARKER: == replay-single test 22: open(O_CREAT), |X| unlink, replay, close (test mds_cleanup_orphans) ========================================================== 20:41:50 (1768009310) [ 1220.009376] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1220.730343] Lustre: Failing over lustre-MDT0000 [ 1221.004964] Lustre: server umount lustre-MDT0000 complete [ 1234.708605] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1235.077428] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1155 to 0x240000400:1185) [ 1235.077468] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1155 to 0x280000400:1185) [ 1237.648940] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1238.156129] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1241.606641] Lustre: DEBUG MARKER: == replay-single test 23: open(O_CREAT), |X| unlink touch new, replay, close (test mds_cleanup_orphans) ========================================================== 20:42:13 (1768009333) [ 1242.927497] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1243.588745] Lustre: Failing over lustre-MDT0000 [ 1243.615710] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1243.617974] Lustre: Skipped 1 previous similar message [ 1243.823545] Lustre: server umount lustre-MDT0000 complete [ 1257.450355] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1259.387840] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1187 to 0x240000400:1217) [ 1259.387933] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1187 to 0x280000400:1217) [ 1260.555604] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1261.082740] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1264.599477] Lustre: DEBUG MARKER: == replay-single test 24: open(O_CREAT), replay, unlink, close (test mds_cleanup_orphans) ========================================================== 20:42:36 (1768009356) [ 1265.888863] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1266.494132] Lustre: Failing over lustre-MDT0000 [ 1266.637352] Lustre: server umount lustre-MDT0000 complete [ 1280.571711] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1281.152799] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1219 to 0x240000400:1249) [ 1281.152854] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1219 to 0x280000400:1249) [ 1283.633655] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1284.167144] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1287.710085] Lustre: DEBUG MARKER: == replay-single test 25: open(O_CREAT), unlink, replay, close (test mds_cleanup_orphans) ========================================================== 20:42:59 (1768009379) [ 1289.140216] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1289.836990] Lustre: Failing over lustre-MDT0000 [ 1290.068425] Lustre: server umount lustre-MDT0000 complete [ 1304.389455] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1306.530098] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1219 to 0x280000400:1281) [ 1306.530116] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1251 to 0x240000400:1281) [ 1307.797215] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1308.392542] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1311.982821] Lustre: DEBUG MARKER: == replay-single test 26: |X| open(O_CREAT), unlink two, close one, replay, close one (test mds_cleanup_orphans) ========================================================== 20:43:23 (1768009403) [ 1313.304295] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1314.061202] Lustre: Failing over lustre-MDT0000 [ 1314.311160] Lustre: server umount lustre-MDT0000 complete [ 1327.103246] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1327.105865] Lustre: Skipped 10 previous similar messages [ 1327.261481] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1283 to 0x240000400:1313) [ 1327.261557] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1283 to 0x280000400:1313) [ 1328.444741] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1331.688515] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1332.238712] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1335.661918] Lustre: DEBUG MARKER: == replay-single test 27: |X| open(O_CREAT), unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 20:43:47 (1768009427) [ 1336.975268] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1337.708940] Lustre: Failing over lustre-MDT0000 [ 1337.964383] Lustre: server umount lustre-MDT0000 complete [ 1351.988439] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1352.842841] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1315 to 0x240000400:1345) [ 1352.842981] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1315 to 0x280000400:1345) [ 1355.199861] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1355.770637] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1359.105094] Lustre: DEBUG MARKER: == replay-single test 28: open(O_CREAT), |X| unlink two, close one, replay, close one (test mds_cleanup_orphans) ========================================================== 20:44:10 (1768009450) [ 1360.434912] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1361.090223] Lustre: Failing over lustre-MDT0000 [ 1361.334654] Lustre: server umount lustre-MDT0000 complete [ 1375.207575] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1377.249142] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1347 to 0x240000400:1377) [ 1377.250154] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1347 to 0x280000400:1377) [ 1378.399673] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1378.925223] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1382.346598] Lustre: DEBUG MARKER: == replay-single test 29: open(O_CREAT), |X| unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 20:44:34 (1768009474) [ 1383.737768] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1384.474766] Lustre: Failing over lustre-MDT0000 [ 1384.724960] Lustre: server umount lustre-MDT0000 complete [ 1398.486310] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1398.918182] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1379 to 0x240000400:1409) [ 1398.918194] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1379 to 0x280000400:1409) [ 1401.627595] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1402.237864] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1405.635773] Lustre: DEBUG MARKER: == replay-single test 30: open(O_CREAT) two, unlink two, replay, close two (test mds_cleanup_orphans) ========================================================== 20:44:57 (1768009497) [ 1407.026459] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1407.678702] Lustre: Failing over lustre-MDT0000 [ 1407.846046] Lustre: server umount lustre-MDT0000 complete [ 1421.781874] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1423.775731] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1411 to 0x280000400:1441) [ 1423.775734] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1411 to 0x240000400:1441) [ 1424.946429] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1425.461022] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1428.916819] Lustre: DEBUG MARKER: == replay-single test 31: open(O_CREAT) two, unlink one, |X| unlink one, close two (test mds_cleanup_orphans) ========================================================== 20:45:20 (1768009520) [ 1430.266803] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1430.941509] Lustre: Failing over lustre-MDT0000 [ 1431.108334] Lustre: server umount lustre-MDT0000 complete [ 1443.580987] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 1443.583914] Lustre: Skipped 20 previous similar messages [ 1444.807262] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1446.021252] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1443 to 0x240000400:1473) [ 1446.021264] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1443 to 0x280000400:1473) [ 1448.011657] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1448.555300] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1452.021611] Lustre: DEBUG MARKER: == replay-single test 32: close() notices client eviction; close() after client eviction ========================================================== 20:45:43 (1768009543) [ 1452.422258] Lustre: 74216:0:(genops.c:1791:obd_export_evict_by_uuid()) lustre-MDT0000: evicting c4330d47-e9c3-460b-9b23-f34cc6c89b63 at adminstrative request [ 1457.119623] Lustre: DEBUG MARKER: == replay-single test 33a: fid seq shouldn't be reused after abort recovery ========================================================== 20:45:48 (1768009548) [ 1458.170419] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1458.805996] Lustre: Failing over lustre-MDT0000 [ 1459.045544] Lustre: server umount lustre-MDT0000 complete [ 1461.765139] Lustre: lustre-MDT0000: Aborting client recovery [ 1461.766333] LustreError: 75076:0:(ldlm_lib.c:2984:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 1461.768455] Lustre: 75122:0:(ldlm_lib.c:2387:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 1461.770915] Lustre: 75122:0:(genops.c:1618:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client c4330d47-e9c3-460b-9b23-f34cc6c89b63@ [ 1461.774272] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 1461.787602] Lustre: lustre-MDT0000-osd: cancel update llog [0x200000400:0x1:0x0] [ 1461.828934] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1479 to 0x240000400:1505) [ 1461.832753] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1480 to 0x280000400:1505) [ 1463.144489] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1468.712068] Lustre: DEBUG MARKER: == replay-single test 33b: test fid seq allocation ======= 20:46:00 (1768009560) [ 1470.034681] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1470.693034] Lustre: Failing over lustre-MDT0000 [ 1470.878966] Lustre: server umount lustre-MDT0000 complete [ 1473.763508] Lustre: *** cfs_fail_loc=1311, val=0*** [ 1473.773316] Lustre: lustre-MDT0000: Aborting client recovery [ 1473.774634] LustreError: 76369:0:(ldlm_lib.c:2984:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 1473.777900] Lustre: 76416:0:(ldlm_lib.c:2387:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 1473.781201] Lustre: 76416:0:(ldlm_lib.c:2387:target_recovery_overseer()) Skipped 2 previous similar messages [ 1473.784392] Lustre: 76416:0:(genops.c:1618:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client c4330d47-e9c3-460b-9b23-f34cc6c89b63@ [ 1473.788716] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 1473.813493] Lustre: lustre-MDT0000-osd: cancel update llog [0x200015bc0:0x1:0x0] [ 1473.865315] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1516 to 0x240000400:1537) [ 1473.870073] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1516 to 0x280000400:1537) [ 1474.719570] Lustre: 3280:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1768009551/real 1768009551] req@ffff93bf7f898e00 x1853890930280192/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1768009567 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1474.731159] Lustre: 3280:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 82 previous similar messages [ 1475.161392] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1478.462156] Lustre: *** cfs_fail_loc=1311, val=0*** [ 1480.775534] Lustre: DEBUG MARKER: == replay-single test 34: abort recovery before client does replay (test mds_cleanup_orphans) ========================================================== 20:46:12 (1768009572) [ 1482.316313] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1483.153884] Lustre: Failing over lustre-MDT0000 [ 1483.283984] Lustre: server umount lustre-MDT0000 complete [ 1486.309503] Lustre: lustre-MDT0000: Aborting client recovery [ 1486.311897] LustreError: 77661:0:(ldlm_lib.c:2984:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 1486.314715] Lustre: 77706:0:(ldlm_lib.c:2387:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 1486.318905] Lustre: 77706:0:(ldlm_lib.c:2387:target_recovery_overseer()) Skipped 2 previous similar messages [ 1486.323535] Lustre: 77706:0:(genops.c:1618:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client c4330d47-e9c3-460b-9b23-f34cc6c89b63@ [ 1486.329280] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 1486.344583] Lustre: lustre-MDT0000-osd: cancel update llog [0x200016778:0x1:0x0] [ 1486.388503] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1543 to 0x240000400:1569) [ 1486.393237] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1544 to 0x280000400:1569) [ 1487.840275] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1493.671609] Lustre: DEBUG MARKER: == replay-single test 35: test recovery from llog for unlink op ========================================================== 20:46:25 (1768009585) [ 1494.100892] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 1494.103610] LustreError: 78055:0:(ldlm_lib.c:3326:target_send_reply_msg()) @@@ dropping reply req@ffff93bf6fe68e00 x1853890922210048/t201863462916(0) o36->c4330d47-e9c3-460b-9b23-f34cc6c89b63@192.168.203.34@tcp:427/0 lens 512/456 e 0 to 0 dl 1768009597 ref 1 fl Interpret:/200/0 rc 0/0 job:'rm.0' uid:0 gid:0 projid:4294967295 [ 1496.754434] Lustre: Failing over lustre-MDT0000 [ 1496.874885] Lustre: server umount lustre-MDT0000 complete [ 1499.764363] Lustre: lustre-MDT0000: Aborting client recovery [ 1499.766442] LustreError: 78808:0:(ldlm_lib.c:2984:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 1499.769698] Lustre: 78853:0:(ldlm_lib.c:2387:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 1499.772945] Lustre: 78853:0:(ldlm_lib.c:2387:target_recovery_overseer()) Skipped 2 previous similar messages [ 1499.776272] Lustre: 78853:0:(genops.c:1618:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client c4330d47-e9c3-460b-9b23-f34cc6c89b63@ [ 1499.780664] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 1499.791868] Lustre: lustre-MDT0000-osd: cancel update llog [0x200017330:0x1:0x0] [ 1499.836160] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1544 to 0x280000400:1601) [ 1499.842244] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1571 to 0x240000400:1601) [ 1501.196041] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1506.640438] Lustre: DEBUG MARKER: SKIP: replay-single test_36 skipping ALWAYS excluded test 36 [ 1507.202994] Lustre: DEBUG MARKER: == replay-single test 37: abort recovery before client does replay (test mds_cleanup_orphans for directories) ========================================================== 20:46:38 (1768009598) [ 1508.742250] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1509.778864] Lustre: Failing over lustre-MDT0000 [ 1509.855618] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 1509.858242] Lustre: Skipped 1 previous similar message [ 1509.937495] Lustre: server umount lustre-MDT0000 complete [ 1512.744427] Lustre: lustre-MDT0000: Aborting client recovery [ 1512.746520] LustreError: 80199:0:(ldlm_lib.c:2984:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 1512.750422] Lustre: 80245:0:(ldlm_lib.c:2387:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 1512.753114] Lustre: 80245:0:(ldlm_lib.c:2387:target_recovery_overseer()) Skipped 2 previous similar messages [ 1512.755621] Lustre: 80245:0:(genops.c:1618:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client c4330d47-e9c3-460b-9b23-f34cc6c89b63@ [ 1512.758549] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 1512.771751] Lustre: lustre-MDT0000-osd: cancel update llog [0x200017b00:0x1:0x0] [ 1512.813974] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:1571 to 0x240000400:1633) [ 1512.814022] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:1544 to 0x280000400:1633) [ 1514.208547] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1520.317792] Lustre: DEBUG MARKER: == replay-single test 38: test recovery from unlink llog (test llog_gen_rec) ========================================================== 20:46:52 (1768009612) [ 1529.566651] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1530.234614] Lustre: Failing over lustre-MDT0000 [ 1530.463079] Lustre: server umount lustre-MDT0000 complete [ 1543.303554] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2034 to 0x240000400:2049) [ 1543.303628] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2034 to 0x280000400:2049) [ 1544.408185] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1547.505669] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1548.076605] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1556.394143] Lustre: DEBUG MARKER: == replay-single test 39: test recovery from unlink llog (test llog_gen_rec) ========================================================== 20:47:28 (1768009648) [ 1562.261497] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1565.274431] Lustre: Failing over lustre-MDT0000 [ 1565.533973] LustreError: 83273:0:(obd_class.h:479:obd_check_dev()) Device 16 not setup [ 1565.536468] LustreError: 83273:0:(obd_class.h:479:obd_check_dev()) Skipped 137 previous similar messages [ 1565.568250] Lustre: server umount lustre-MDT0000 complete [ 1578.295550] 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 [ 1578.300423] Lustre: Skipped 45 previous similar messages [ 1579.100436] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 1579.104869] Lustre: Skipped 17 previous similar messages [ 1579.839993] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1580.314770] Lustre: lustre-MDT0000: Recovery over after 0:01, of 1 clients 1 recovered and 0 were evicted. [ 1580.317771] Lustre: Skipped 17 previous similar messages [ 1580.332894] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2450 to 0x240000400:2465) [ 1580.333274] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2450 to 0x280000400:2465) [ 1583.242461] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1583.585093] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 1583.587482] Lustre: Skipped 45 previous similar messages [ 1583.823384] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1592.162513] Lustre: DEBUG MARKER: == replay-single test 41: read from a valid osc while other oscs are invalid ========================================================== 20:48:03 (1768009683) [ 1592.903113] Lustre: setting import lustre-OST0001_UUID INACTIVE by administrator request [ 1593.278252] Lustre: lustre-OST0001: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnecting [ 1593.281482] LustreError: lustre-OST0001-osc-MDT0000: This client was evicted by lustre-OST0001; in progress operations using this service will fail. [ 1595.584723] Lustre: DEBUG MARKER: == replay-single test 42: recovery after ost failure ===== 20:48:07 (1768009687) [ 1602.345894] LustreError: 85189:0:(osd_handler.c:720:osd_ro()) lustre-OST0000: *** setting device osd-zfs read-only *** [ 1602.349304] LustreError: 85189:0:(osd_handler.c:720:osd_ro()) Skipped 20 previous similar messages [ 1602.716337] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 1606.706959] Lustre: Failing over lustre-OST0000 [ 1606.754377] Lustre: server umount lustre-OST0000 complete [ 1609.184818] LustreError: 33687:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1609.184834] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 1609.190733] LustreError: 33687:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 1 previous similar message [ 1614.303654] LustreError: 33690:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 1614.310239] LustreError: 33690:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 1 previous similar message [ 1621.720593] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1669.510597] Lustre: DEBUG MARKER: == replay-single test 43: mds osc import failure during recovery; don't LBUG ========================================================== 20:49:21 (1768009761) [ 1671.111964] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1672.205641] Lustre: Failing over lustre-MDT0000 [ 1672.427184] Lustre: server umount lustre-MDT0000 complete [ 1685.182216] LustreError: MGC192.168.203.134@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 1685.186526] LustreError: Skipped 22 previous similar messages [ 1686.667623] Lustre: *** cfs_fail_loc=204, val=2147483648*** [ 1686.668116] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2866 to 0x280000400:2881) [ 1687.050362] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1690.720691] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 1691.325955] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1702.879240] LustreError: 87558:0:(osp_precreate.c:969:osp_precreate_cleanup_orphans()) lustre-OST0000-osc-MDT0000: cannot cleanup orphans: rc = -11 [ 1702.879911] Lustre: lustre-OST0000: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnecting [ 1703.904654] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2867 to 0x240000400:2913) [ 1705.165184] Lustre: DEBUG MARKER: == replay-single test 44a: race in target handle connect ========================================================== 20:49:56 (1768009796) [ 1706.994434] LustreError: 87535:0:(ldlm_lib.c:1165:target_handle_connect()) cfs_race id 701 sleeping [ 1712.095114] LustreError: 87535:0:(ldlm_lib.c:1165:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 1712.098154] Lustre: lustre-MDT0000: Client c4330d47-e9c3-460b-9b23-f34cc6c89b63 (at 192.168.203.34@tcp) reconnecting [ 1712.783226] LustreError: 87535:0:(ldlm_lib.c:1165:target_handle_connect()) cfs_race id 701 sleeping [ 1718.239737] LustreError: 87535:0:(ldlm_lib.c:1165:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 1718.243054] Lustre: lustre-MDT0000: Client c4330d47-e9c3-460b-9b23-f34cc6c89b63 (at 192.168.203.34@tcp) reconnecting [ 1718.946475] LustreError: 87535:0:(ldlm_lib.c:1165:target_handle_connect()) cfs_race id 701 sleeping [ 1724.383161] LustreError: 87535:0:(ldlm_lib.c:1165:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 1724.388689] Lustre: lustre-MDT0000: Client c4330d47-e9c3-460b-9b23-f34cc6c89b63 (at 192.168.203.34@tcp) reconnecting [ 1725.074709] LustreError: 87535:0:(ldlm_lib.c:1165:target_handle_connect()) cfs_race id 701 sleeping [ 1730.527128] LustreError: 87535:0:(ldlm_lib.c:1165:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 1731.199562] LustreError: 87535:0:(ldlm_lib.c:1165:target_handle_connect()) cfs_race id 701 sleeping [ 1736.671140] LustreError: 87535:0:(ldlm_lib.c:1165:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 1736.674715] Lustre: lustre-MDT0000: Client c4330d47-e9c3-460b-9b23-f34cc6c89b63 (at 192.168.203.34@tcp) reconnecting [ 1736.677043] Lustre: Skipped 1 previous similar message [ 1743.469040] LustreError: 87535:0:(ldlm_lib.c:1165:target_handle_connect()) cfs_race id 701 sleeping [ 1743.471575] LustreError: 87535:0:(ldlm_lib.c:1165:target_handle_connect()) Skipped 1 previous similar message [ 1748.959134] LustreError: 87535:0:(ldlm_lib.c:1165:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 1748.961813] LustreError: 87535:0:(ldlm_lib.c:1165:target_handle_connect()) Skipped 1 previous similar message [ 1755.103136] Lustre: lustre-MDT0000: Client c4330d47-e9c3-460b-9b23-f34cc6c89b63 (at 192.168.203.34@tcp) reconnecting [ 1755.106945] Lustre: Skipped 2 previous similar messages [ 1761.876125] LustreError: 88076:0:(ldlm_lib.c:1165:target_handle_connect()) cfs_race id 701 sleeping [ 1761.878691] LustreError: 88076:0:(ldlm_lib.c:1165:target_handle_connect()) Skipped 2 previous similar messages [ 1767.391159] LustreError: 88076:0:(ldlm_lib.c:1165:target_handle_connect()) cfs_fail_race id 701 awake: rc=0 [ 1767.394855] LustreError: 88076:0:(ldlm_lib.c:1165:target_handle_connect()) Skipped 2 previous similar messages [ 1770.377987] Lustre: DEBUG MARKER: == replay-single test 44b: race in target handle connect ========================================================== 20:51:02 (1768009862) [ 1771.064134] LustreError: 87534:0:(ldlm_lib.c:1418:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 1781.337479] Lustre: lustre-MDT0000: Export ffff93bf78c12800 already connecting from 192.168.203.34@tcp [ 1786.457209] Lustre: lustre-MDT0000: Export ffff93bf78c12800 already connecting from 192.168.203.34@tcp [ 1791.577088] Lustre: lustre-MDT0000: Export ffff93bf78c12800 already connecting from 192.168.203.34@tcp [ 1796.696885] Lustre: lustre-MDT0000: Export ffff93bf78c12800 already connecting from 192.168.203.34@tcp [ 1796.700266] Lustre: Skipped 1 previous similar message [ 1801.817037] Lustre: lustre-MDT0000: Export ffff93bf78c12800 already connecting from 192.168.203.34@tcp [ 1811.103125] LustreError: 87534:0:(ldlm_lib.c:1418:target_handle_connect()) cfs_fail_timeout id 704 awake [ 1811.105486] Lustre: 87534:0:(service.c:2560:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/20s); client may timeout req@ffff93bf70945500 x1853890924825856/t0(0) o38->c4330d47-e9c3-460b-9b23-f34cc6c89b63@192.168.203.34@tcp:0/0 lens 520/416 e 0 to 0 dl 1768009883 ref 1 fl Complete:H/200/0 rc 0/0 job:'lctl.0' uid:0 gid:0 projid:4294967295 [ 1812.057169] Lustre: lustre-MDT0000: Client c4330d47-e9c3-460b-9b23-f34cc6c89b63 (at 192.168.203.34@tcp) reconnecting [ 1812.060713] Lustre: Skipped 3 previous similar messages [ 1812.062567] LustreError: 87534:0:(ldlm_lib.c:1418:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 1837.657274] Lustre: lustre-MDT0000: Export ffff93bf78c12800 already connecting from 192.168.203.34@tcp [ 1837.662133] Lustre: Skipped 1 previous similar message [ 1852.103158] LustreError: 87534:0:(ldlm_lib.c:1418:target_handle_connect()) cfs_fail_timeout id 704 awake [ 1852.105794] Lustre: 87534:0:(service.c:2560:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/20s); client may timeout req@ffff93be42f6a680 x1853890924829824/t0(0) o38->c4330d47-e9c3-460b-9b23-f34cc6c89b63@192.168.203.34@tcp:0/0 lens 520/416 e 0 to 0 dl 1768009924 ref 1 fl Complete:H/200/0 rc 0/0 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1853.017074] LustreError: 87534:0:(ldlm_lib.c:1418:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 1878.616942] Lustre: lustre-MDT0000: Export ffff93bf78c12800 already connecting from 192.168.203.34@tcp [ 1878.620344] Lustre: Skipped 2 previous similar messages [ 1893.063108] LustreError: 87534:0:(ldlm_lib.c:1418:target_handle_connect()) cfs_fail_timeout id 704 awake [ 1893.066230] Lustre: 87534:0:(service.c:2560:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/20s); client may timeout req@ffff93bf7a2f2d80 x1853890924831616/t0(0) o38->c4330d47-e9c3-460b-9b23-f34cc6c89b63@192.168.203.34@tcp:0/0 lens 520/416 e 0 to 0 dl 1768009965 ref 1 fl Complete:H/200/0 rc 0/0 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1893.977057] Lustre: lustre-MDT0000: Client c4330d47-e9c3-460b-9b23-f34cc6c89b63 (at 192.168.203.34@tcp) reconnecting [ 1893.980748] Lustre: Skipped 1 previous similar message [ 1893.982772] LustreError: 88076:0:(ldlm_lib.c:1418:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 1919.580060] Lustre: lustre-MDT0000: Export ffff93bf78c12800 already connecting from 192.168.203.34@tcp [ 1919.583241] Lustre: Skipped 2 previous similar messages [ 1934.023109] LustreError: 88076:0:(ldlm_lib.c:1418:target_handle_connect()) cfs_fail_timeout id 704 awake [ 1934.026244] Lustre: 88076:0:(service.c:2560:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/20s); client may timeout req@ffff93bf4b26d500 x1853890924833408/t0(0) o38->c4330d47-e9c3-460b-9b23-f34cc6c89b63@192.168.203.34@tcp:0/0 lens 520/416 e 0 to 0 dl 1768010006 ref 1 fl Complete:H/200/0 rc 0/0 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1934.937202] LustreError: 87536:0:(ldlm_lib.c:1418:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 1974.983062] LustreError: 87536:0:(ldlm_lib.c:1418:target_handle_connect()) cfs_fail_timeout id 704 awake [ 1974.985108] Lustre: 87536:0:(service.c:2560:ptlrpc_server_handle_request()) @@@ Request took longer than estimated (20/20s); client may timeout req@ffff93bf7a2f2a00 x1853890924835200/t0(0) o38->c4330d47-e9c3-460b-9b23-f34cc6c89b63@192.168.203.34@tcp:0/0 lens 520/416 e 0 to 0 dl 1768010047 ref 1 fl Complete:H/200/0 rc 0/0 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1975.896988] LustreError: 87536:0:(ldlm_lib.c:1418:target_handle_connect()) cfs_fail_timeout id 704 sleeping for 40000ms [ 1980.687060] LustreError: 87536:0:(ldlm_lib.c:1418:target_handle_connect()) cfs_fail_timeout interrupted [ 1982.146050] Lustre: DEBUG MARKER: == replay-single test 44c: race in target handle connect ========================================================== 20:54:33 (1768010073) [ 1983.497399] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 1984.830069] Lustre: Failing over lustre-MDT0000 [ 1984.945923] Lustre: server umount lustre-MDT0000 complete [ 1987.621523] Lustre: *** cfs_fail_loc=712, val=0*** [ 1987.623886] LustreError: 33688:0:(service.c:1389:ptlrpc_check_req()) @@@ Invalid replay without recovery req@ffff93bf76407800 x1853890930877568/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 [ 1987.683276] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 1987.683348] Lustre: lustre-MDT0000: Aborting client recovery [ 1987.685941] Lustre: Skipped 24 previous similar messages [ 1987.687708] LustreError: 91884:0:(ldlm_lib.c:2984:target_stop_recovery_thread()) lustre-MDT0000: Aborting recovery [ 1987.689340] Lustre: 91931:0:(ldlm_lib.c:2387:target_recovery_overseer()) recovery is aborted, evict exports in recovery [ 1987.696485] Lustre: 91931:0:(ldlm_lib.c:2387:target_recovery_overseer()) Skipped 2 previous similar messages [ 1987.699413] Lustre: 91931:0:(genops.c:1618:class_disconnect_stale_exports()) lustre-MDT0000: disconnect stale client c4330d47-e9c3-460b-9b23-f34cc6c89b63@ [ 1987.704134] Lustre: lustre-MDT0000: disconnecting 1 stale clients [ 1987.715798] Lustre: lustre-MDT0000-osd: cancel update llog [0x2000182d0:0x1:0x0] [ 1987.754649] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2866 to 0x280000400:2913) [ 1987.754673] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2867 to 0x240000400:2945) [ 1989.125261] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 1993.051888] Lustre: Failing over lustre-MDT0000 [ 1993.318292] Lustre: server umount lustre-MDT0000 complete [ 2006.647948] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2866 to 0x280000400:2945) [ 2006.647961] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2867 to 0x240000400:2977) [ 2007.190350] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2010.278118] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2010.879263] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2014.460786] Lustre: DEBUG MARKER: == replay-single test 45: Handle failed close ============ 20:55:06 (1768010106) [ 2017.813896] Lustre: DEBUG MARKER: == replay-single test 46: Don't leak file handle after open resend (3325) ========================================================== 20:55:09 (1768010109) [ 2018.158781] Lustre: *** cfs_fail_loc=122, val=2147483648*** [ 2018.161266] LustreError: 92777:0:(ldlm_lib.c:3326:target_send_reply_msg()) @@@ dropping reply req@ffff93bf79ed4700 x1853890924887040/t0(0) o700->c4330d47-e9c3-460b-9b23-f34cc6c89b63@192.168.203.34@tcp:196/0 lens 264/248 e 0 to 0 dl 1768010121 ref 1 fl Interpret:/200/0 rc 0/0 job:'touch.0' uid:0 gid:0 projid:4294967295 [ 2033.753716] Lustre: lustre-MDT0000: Client c4330d47-e9c3-460b-9b23-f34cc6c89b63 (at 192.168.203.34@tcp) reconnecting [ 2033.759174] Lustre: Skipped 4 previous similar messages [ 2035.010136] Lustre: Failing over lustre-MDT0000 [ 2035.251203] Lustre: server umount lustre-MDT0000 complete [ 2048.043142] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 2048.045866] Lustre: Skipped 11 previous similar messages [ 2049.370888] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2051.384635] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:2979 to 0x240000400:3009) [ 2051.384875] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2947 to 0x280000400:2977) [ 2052.579626] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2053.154114] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2057.284992] Lustre: DEBUG MARKER: == replay-single test 47: MDS->OSC failure during precreate cleanup (2824) ========================================================== 20:55:49 (1768010149) [ 2058.122839] Lustre: Failing over lustre-OST0000 [ 2058.159520] Lustre: server umount lustre-OST0000 complete [ 2058.208823] LustreError: 33694:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 2058.208858] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 2058.213732] LustreError: 33694:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 1 previous similar message [ 2062.426757] LustreError: 33695:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.203.34@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 2072.444567] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2075.598720] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 2076.248408] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 2141.815030] Lustre: DEBUG MARKER: == replay-single test 48: MDS->OSC failure during precreate cleanup (2824) ========================================================== 20:57:13 (1768010233) [ 2143.319931] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2144.211270] Lustre: Failing over lustre-MDT0000 [ 2144.334975] Lustre: server umount lustre-MDT0000 complete [ 2158.297460] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2159.845361] Lustre: *** cfs_fail_loc=216, val=0*** [ 2159.845504] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3030 to 0x240000400:3073) [ 2159.846617] LustreError: 97104:0:(osp_precreate.c:969:osp_precreate_cleanup_orphans()) lustre-OST0001-osc-MDT0000: cannot cleanup orphans: rc = -30 [ 2160.863462] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:2998 to 0x280000400:3041) [ 2163.103115] Lustre: 3282:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1768010239/real 1768010239] req@ffff93bf44b08a80 x1853890930934528/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1768010255 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2163.112218] Lustre: 3282:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 26 previous similar messages [ 2223.182891] Lustre: DEBUG MARKER: == replay-single test 50: Double OSC recovery, don't LASSERT (3812) ========================================================== 20:58:34 (1768010314) [ 2223.814570] 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 [ 2223.820017] Lustre: Skipped 14 previous similar messages [ 2223.822253] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 2223.824747] Lustre: Skipped 15 previous similar messages [ 2231.154446] Lustre: DEBUG MARKER: == replay-single test 52: time out lock replay (3764) ==== 20:58:42 (1768010322) [ 2232.169086] Lustre: Failing over lustre-MDT0000 [ 2232.389519] LustreError: 98232:0:(obd_class.h:479:obd_check_dev()) Device 16 not setup [ 2232.392029] LustreError: 98232:0:(obd_class.h:479:obd_check_dev()) Skipped 39 previous similar messages [ 2232.436430] Lustre: server umount lustre-MDT0000 complete [ 2246.087400] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2246.745930] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 2246.748837] Lustre: Skipped 6 previous similar messages [ 2246.752583] Lustre: *** cfs_fail_loc=157, val=2147483648*** [ 2246.754573] LustreError: 98672:0:(ldlm_lib.c:3326:target_send_reply_msg()) @@@ dropping reply req@ffff93bf78a5ad80 x1853890924996224/t0(0) o101->c4330d47-e9c3-460b-9b23-f34cc6c89b63@192.168.203.34@tcp:425/0 lens 328/344 e 0 to 0 dl 1768010350 ref 1 fl Complete:/240/0 rc 0/0 job:'ldlm_lock_repla.0' uid:0 gid:0 projid:4294967295 [ 2263.128980] Lustre: lustre-MDT0000: Client c4330d47-e9c3-460b-9b23-f34cc6c89b63 (at 192.168.203.34@tcp) reconnected, waiting for 1 clients in recovery for 1:24 [ 2263.147780] Lustre: lustre-MDT0000: Recovery over after 0:17, of 1 clients 1 recovered and 0 were evicted. [ 2263.150799] Lustre: Skipped 6 previous similar messages [ 2263.166832] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3053 to 0x280000400:3073) [ 2263.166832] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3084 to 0x240000400:3105) [ 2264.491870] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2265.037703] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2268.696293] Lustre: DEBUG MARKER: == replay-single test 53a: |X| close request while two MDC requests in flight ========================================================== 20:59:20 (1768010360) [ 2270.064829] Lustre: *** cfs_fail_loc=115, val=2147483648*** [ 2271.240959] LustreError: 99673:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 2271.243807] LustreError: 99673:0:(osd_handler.c:720:osd_ro()) Skipped 3 previous similar messages [ 2271.527137] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2272.117049] Lustre: Failing over lustre-MDT0000 [ 2272.345645] LustreError: 98633:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-MDT0000: not available for connect from 192.168.203.34@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 2272.352556] LustreError: 98633:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 3 previous similar messages [ 2272.373586] Lustre: server umount lustre-MDT0000 complete [ 2286.166960] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2291.828068] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3075 to 0x280000400:3105) [ 2291.828080] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3084 to 0x240000400:3137) [ 2292.983193] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2293.529657] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2296.914772] Lustre: DEBUG MARKER: == replay-single test 53b: |X| open request while two MDC requests in flight ========================================================== 20:59:48 (1768010388) [ 2297.282088] Lustre: *** cfs_fail_loc=107, val=2147483648*** [ 2299.712591] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2300.339739] Lustre: Failing over lustre-MDT0000 [ 2300.383707] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 2300.386942] Lustre: Skipped 1 previous similar message [ 2300.430544] Lustre: server umount lustre-MDT0000 complete [ 2312.675073] LustreError: MGC192.168.203.134@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 2312.679823] LustreError: Skipped 6 previous similar messages [ 2314.041719] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2314.688326] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3075 to 0x280000400:3137) [ 2314.690159] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3139 to 0x240000400:3169) [ 2317.017377] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2317.507438] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2320.780458] Lustre: DEBUG MARKER: == replay-single test 53c: |X| open request and close request while two MDC requests in flight ========================================================== 21:00:12 (1768010412) [ 2321.104427] Lustre: *** cfs_fail_loc=107, val=2147483648*** [ 2323.591135] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2324.225123] Lustre: Failing over lustre-MDT0000 [ 2324.324566] Lustre: server umount lustre-MDT0000 complete [ 2337.398633] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3171 to 0x240000400:3201) [ 2337.398671] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3075 to 0x280000400:3169) [ 2338.069925] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2343.058464] Lustre: DEBUG MARKER: == replay-single test 53d: close reply while two MDC requests in flight ========================================================== 21:00:34 (1768010434) [ 2344.426039] Lustre: *** cfs_fail_loc=13b, val=315*** [ 2344.427604] Lustre: *** cfs_fail_loc=13b, val=2147483648*** [ 2344.428970] LustreError: 103684:0:(ldlm_lib.c:3326:target_send_reply_msg()) @@@ dropping reply req@ffff93bf50b45c00 x1853890925038720/t257698037777(0) o35->c4330d47-e9c3-460b-9b23-f34cc6c89b63@192.168.203.34@tcp:522/0 lens 392/456 e 0 to 0 dl 1768010447 ref 1 fl Interpret:/600/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 2345.368207] Lustre: Failing over lustre-MDT0000 [ 2345.596793] Lustre: server umount lustre-MDT0000 complete [ 2359.369933] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2359.918059] Lustre: 104473:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff93bf7f0fb800 x1853890925038720/t257698037777(0) o35->c4330d47-e9c3-460b-9b23-f34cc6c89b63@192.168.203.34@tcp:538/0 lens 392/456 e 0 to 0 dl 1768010463 ref 1 fl Interpret:/602/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 2359.922920] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3171 to 0x240000400:3233) [ 2359.923243] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3171 to 0x280000400:3201) [ 2362.410462] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2362.925469] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2366.376540] Lustre: DEBUG MARKER: == replay-single test 53e: |X| open reply while two MDC requests in flight ========================================================== 21:00:58 (1768010458) [ 2366.733441] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 2366.735079] LustreError: 104999:0:(ldlm_lib.c:3326:target_send_reply_msg()) @@@ dropping reply req@ffff93bf7f0f9f80 x1853890925050624/t261993005072(0) o36->c4330d47-e9c3-460b-9b23-f34cc6c89b63@192.168.203.34@tcp:545/0 lens 504/448 e 0 to 0 dl 1768010470 ref 1 fl Interpret:/200/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 2369.197065] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2369.805954] Lustre: Failing over lustre-MDT0000 [ 2369.907720] Lustre: server umount lustre-MDT0000 complete [ 2383.414303] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2392.682455] Lustre: 106013:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff93be433da300 x1853890925050624/t261993005072(0) o36->c4330d47-e9c3-460b-9b23-f34cc6c89b63@192.168.203.34@tcp:571/0 lens 504/2880 e 0 to 0 dl 1768010496 ref 1 fl Interpret:/202/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 2392.688215] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3203 to 0x280000400:3233) [ 2392.688416] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3171 to 0x240000400:3265) [ 2393.763109] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2394.258721] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2397.450931] Lustre: DEBUG MARKER: == replay-single test 53f: |X| open reply and close reply while two MDC requests in flight ========================================================== 21:01:29 (1768010489) [ 2397.782527] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 2397.784202] LustreError: 105989:0:(ldlm_lib.c:3326:target_send_reply_msg()) @@@ dropping reply req@ffff93bf496fea00 x1853890925063040/t266287972368(0) o36->c4330d47-e9c3-460b-9b23-f34cc6c89b63@192.168.203.34@tcp:576/0 lens 504/448 e 0 to 0 dl 1768010501 ref 1 fl Interpret:/200/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 2399.030795] Lustre: *** cfs_fail_loc=13b, val=315*** [ 2400.096133] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2400.742096] Lustre: Failing over lustre-MDT0000 [ 2400.858337] Lustre: server umount lustre-MDT0000 complete [ 2414.189974] Lustre: 107515:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff93be43349180 x1853890925063808/t266287972369(0) o35->c4330d47-e9c3-460b-9b23-f34cc6c89b63@192.168.203.34@tcp:592/0 lens 392/456 e 0 to 0 dl 1768010517 ref 1 fl Interpret:/602/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 2414.196549] Lustre: 107515:0:(mdt_recovery.c:102:mdt_req_from_lrd()) Skipped 1 previous similar message [ 2414.197801] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3235 to 0x280000400:3265) [ 2414.198160] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3171 to 0x240000400:3297) [ 2414.684462] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2419.730996] Lustre: DEBUG MARKER: == replay-single test 53g: |X| drop open reply and close request while close and open are both in flight ========================================================== 21:01:51 (1768010511) [ 2420.091553] LustreError: 107513:0:(ldlm_lib.c:3326:target_send_reply_msg()) @@@ dropping reply req@ffff93bf44b08e00 x1853890925075072/t270582939664(0) o36->c4330d47-e9c3-460b-9b23-f34cc6c89b63@192.168.203.34@tcp:598/0 lens 504/448 e 0 to 0 dl 1768010523 ref 1 fl Interpret:/200/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 2420.098948] LustreError: 107513:0:(ldlm_lib.c:3326:target_send_reply_msg()) Skipped 1 previous similar message [ 2421.381218] Lustre: *** cfs_fail_loc=115, val=2147483648*** [ 2421.383334] Lustre: Skipped 1 previous similar message [ 2422.821370] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2423.448776] Lustre: Failing over lustre-MDT0000 [ 2423.544648] Lustre: server umount lustre-MDT0000 complete [ 2436.719080] Lustre: 108980:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff93bf496ff480 x1853890925075072/t270582939664(0) o36->c4330d47-e9c3-460b-9b23-f34cc6c89b63@192.168.203.34@tcp:615/0 lens 504/2880 e 0 to 0 dl 1768010540 ref 1 fl Interpret:/202/0 rc 0/0 job:'mcreate.0' uid:0 gid:0 projid:4294967295 [ 2436.725818] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3267 to 0x280000400:3297) [ 2436.727103] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3171 to 0x240000400:3329) [ 2437.541224] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2442.366184] Lustre: DEBUG MARKER: == replay-single test 53h: open request and close reply while two MDC requests in flight ========================================================== 21:02:14 (1768010534) [ 2442.721454] Lustre: *** cfs_fail_loc=107, val=2147483648*** [ 2444.036186] Lustre: *** cfs_fail_loc=13b, val=315*** [ 2444.037971] Lustre: *** cfs_fail_loc=13b, val=2147483648*** [ 2444.040054] Lustre: Skipped 2 previous similar messages [ 2446.273952] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2446.900852] Lustre: Failing over lustre-MDT0000 [ 2446.937962] Lustre: lustre-MDT0000: Not available for connect from 192.168.203.34@tcp (stopping) [ 2446.988366] Lustre: server umount lustre-MDT0000 complete [ 2460.607564] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2467.434277] Lustre: 110346:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff93bf7f898380 x1853890925086208/t274877906960(0) o35->c4330d47-e9c3-460b-9b23-f34cc6c89b63@192.168.203.34@tcp:645/0 lens 392/456 e 0 to 0 dl 1768010570 ref 1 fl Interpret:/602/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 2467.441563] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3171 to 0x240000400:3361) [ 2467.441563] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3299 to 0x280000400:3329) [ 2471.599023] Lustre: DEBUG MARKER: == replay-single test 55: let MDS_CHECK_RESENT return the original return code instead of 0 ========================================================== 21:02:43 (1768010563) [ 2471.897538] Lustre: *** cfs_fail_loc=12b, val=2147483991*** [ 2471.899210] LustreError: 110373:0:(ldlm_lib.c:3326:target_send_reply_msg()) @@@ dropping reply req@ffff93bf477ea680 x1853890925095040/t279172874255(0) o101->c4330d47-e9c3-460b-9b23-f34cc6c89b63@192.168.203.34@tcp:650/0 lens 664/608 e 0 to 0 dl 1768010575 ref 1 fl Interpret:/600/0 rc 301/0 job:'touch.0' uid:0 gid:0 projid:0 [ 2471.904259] LustreError: 110373:0:(ldlm_lib.c:3326:target_send_reply_msg()) Skipped 1 previous similar message [ 2488.408861] Lustre: lustre-MDT0000: Client c4330d47-e9c3-460b-9b23-f34cc6c89b63 (at 192.168.203.34@tcp) reconnecting [ 2488.411041] Lustre: Skipped 2 previous similar messages [ 2488.413637] Lustre: 111089:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff93bf78a59c00 x1853890925095040/t279172874255(0) o101->c4330d47-e9c3-460b-9b23-f34cc6c89b63@192.168.203.34@tcp:666/0 lens 664/3488 e 0 to 0 dl 1768010591 ref 1 fl Interpret:/602/0 rc 0/0 job:'touch.0' uid:0 gid:0 projid:0 [ 2490.462392] Lustre: DEBUG MARKER: == replay-single test 56: don't replay a symlink open request (3440) ========================================================== 21:03:02 (1768010582) [ 2491.633205] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2492.243629] Lustre: Failing over lustre-MDT0000 [ 2492.338133] Lustre: server umount lustre-MDT0000 complete [ 2505.817187] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2507.718069] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3171 to 0x240000400:3393) [ 2507.718258] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3331 to 0x280000400:3361) [ 2508.791470] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2509.308124] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2522.650504] Lustre: DEBUG MARKER: == replay-single test 57: test recovery from llog for setattr op ========================================================== 21:03:34 (1768010614) [ 2524.043854] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2524.603711] Lustre: Failing over lustre-MDT0000 [ 2524.855575] Lustre: server umount lustre-MDT0000 complete [ 2538.344159] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2539.636332] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:3395 to 0x240000400:3425) [ 2539.636430] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:3331 to 0x280000400:3393) [ 2541.366352] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2541.865683] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2544.069431] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing _wait_recovery_complete *.lustre-MDT0000.recovery_status 1475 [ 2548.872445] Lustre: DEBUG MARKER: == replay-single test 58a: test recovery from llog for setattr op (test llog_gen_rec) ========================================================== 21:04:00 (1768010640) [ 2555.892338] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2556.469412] Lustre: Failing over lustre-MDT0000 [ 2556.732677] Lustre: server umount lustre-MDT0000 complete [ 2570.113633] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2570.422701] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:4676 to 0x240000400:4705) [ 2570.422878] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:4644 to 0x280000400:4673) [ 2573.022128] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2573.510149] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2586.938153] Lustre: DEBUG MARKER: == replay-single test 58b: test replay of setxattr op ==== 21:04:38 (1768010678) [ 2588.467738] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2589.123916] Lustre: Failing over lustre-MDT0000 [ 2589.249375] Lustre: server umount lustre-MDT0000 complete [ 2601.856020] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 2601.858054] Lustre: Skipped 18 previous similar messages [ 2602.637238] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:4644 to 0x280000400:4705) [ 2602.637239] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:4707 to 0x240000400:4737) [ 2603.164662] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2606.223787] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2606.776660] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2609.643620] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount FULL mgc.*.mgs_server_uuid [ 2610.189994] Lustre: DEBUG MARKER: mgc.*.mgs_server_uuid in FULL state after 0 sec [ 2612.273177] Lustre: DEBUG MARKER: == replay-single test 58c: resend/reconstruct setxattr op ========================================================== 21:05:04 (1768010704) [ 2617.829197] Lustre: *** cfs_fail_loc=123, val=2147483648*** [ 2635.072327] Lustre: *** cfs_fail_loc=119, val=2147483648*** [ 2635.073689] Lustre: Skipped 1 previous similar message [ 2635.074774] LustreError: 117031:0:(ldlm_lib.c:3326:target_send_reply_msg()) @@@ dropping reply req@ffff93be436bf850 x1853890927860608/t296352743435(0) o36->c4330d47-e9c3-460b-9b23-f34cc6c89b63@192.168.203.34@tcp:58/0 lens 66040/440 e 0 to 0 dl 1768010738 ref 1 fl Interpret:/600/0 rc 0/0 job:'setfattr.0' uid:0 gid:0 projid:0 [ 2651.227041] Lustre: 117056:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff93be4a3e5c00 x1853890927860608/t296352743435(0) o36->c4330d47-e9c3-460b-9b23-f34cc6c89b63@192.168.203.34@tcp:74/0 lens 66040/440 e 0 to 0 dl 1768010754 ref 1 fl Interpret:/602/0 rc 0/0 job:'setfattr.0' uid:0 gid:0 projid:0 [ 2654.407355] Lustre: DEBUG MARKER: SKIP: replay-single test_59 skipping ALWAYS excluded test 59 [ 2654.989478] Lustre: DEBUG MARKER: == replay-single test 60: test llog post recovery init vs llog unlink ========================================================== 21:05:46 (1768010746) [ 2658.045509] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2658.911373] Lustre: Failing over lustre-MDT0000 [ 2659.022118] Lustre: server umount lustre-MDT0000 complete [ 2671.368651] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 2671.370371] Lustre: Skipped 15 previous similar messages [ 2671.875425] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:4807 to 0x280000400:4833) [ 2671.876137] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:4838 to 0x240000400:4865) [ 2672.529509] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2675.468687] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2675.951990] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2679.699616] Lustre: DEBUG MARKER: == replay-single test 61a: test race llog recovery vs llog cleanup ========================================================== 21:06:11 (1768010771) [ 2683.913671] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 2686.827403] Lustre: Failing over lustre-OST0000 [ 2686.852560] Lustre: server umount lustre-OST0000 complete [ 2686.944829] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 2686.945019] LustreError: 33693:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 2700.936320] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2712.396101] Lustre: Failing over lustre-OST0000 [ 2712.430337] Lustre: server umount lustre-OST0000 complete [ 2719.711552] LustreError: 14299:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 2719.715862] LustreError: 14299:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 8 previous similar messages [ 2726.666864] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2729.790585] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 2730.348226] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 2764.451944] Lustre: DEBUG MARKER: == replay-single test 61b: test race mds llog sync vs llog cleanup ========================================================== 21:07:36 (1768010856) [ 2765.496051] Lustre: Failing over lustre-MDT0000 [ 2765.630718] Lustre: server umount lustre-MDT0000 complete [ 2779.252705] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5234 to 0x280000400:5249) [ 2779.252905] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5266 to 0x240000400:5281) [ 2779.574862] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2782.175171] Lustre: 3281:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1768010858/real 1768010858] req@ffff93be49b63800 x1853890932137984/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1768010874 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 2782.184475] Lustre: 3281:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 70 previous similar messages [ 2791.054487] Lustre: Failing over lustre-MDT0000 [ 2791.161263] Lustre: server umount lustre-MDT0000 complete [ 2804.852222] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5234 to 0x280000400:5281) [ 2804.852222] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5266 to 0x240000400:5313) [ 2804.927804] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2807.987332] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2808.509219] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2811.846712] Lustre: DEBUG MARKER: == replay-single test 61c: test race mds llog sync vs llog cleanup ========================================================== 21:08:23 (1768010903) [ 2822.967990] Lustre: Failing over lustre-OST0000 [ 2824.159734] 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 [ 2824.159745] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 2824.164056] Lustre: Skipped 35 previous similar messages [ 2824.168424] Lustre: lustre-OST0000: Not available for connect from 0@lo (stopping) [ 2825.012318] Lustre: server umount lustre-OST0000 complete [ 2825.309098] LustreError: 33691:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.203.34@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 2825.314159] LustreError: 33691:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 1 previous similar message [ 2839.161671] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 2839.163602] Lustre: Skipped 35 previous similar messages [ 2839.171985] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2842.287071] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 2842.835063] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 2846.358442] Lustre: DEBUG MARKER: == replay-single test 61d: error in llog_setup should cleanup the llog context correctly ========================================================== 21:08:58 (1768010938) [ 2846.977113] Lustre: Failing over lustre-MDT0000 [ 2847.217422] LustreError: 126455:0:(obd_class.h:479:obd_check_dev()) Device 16 not setup [ 2847.219488] LustreError: 126455:0:(obd_class.h:479:obd_check_dev()) Skipped 101 previous similar messages [ 2847.248282] Lustre: server umount lustre-MDT0000 complete [ 2849.758980] Lustre: *** cfs_fail_loc=605, val=0*** [ 2849.760024] LustreError: 126920:0:(llog_obd.c:190:llog_setup()) MGS: ctxt 0 lop_setup=ffffffffc12c8dd0 failed: rc = -95 [ 2849.763981] LustreError: 126920:0:(obd_config.c:783:class_setup()) setup MGS failed (-95) [ 2849.767145] LustreError: 126920:0:(obd_mount.c:193:lustre_start_simple()) MGS setup error -95 [ 2849.768695] LustreError: 126920:0:(tgt_mount.c:117:server_deregister_mount()) MGS not registered [ 2849.770698] LustreError: Failed to start MGS 'MGS' (-95). Is the 'mgs' module loaded? [ 2849.772390] LustreError: 126920:0:(tgt_mount.c:1973:server_put_super()) no obd lustre-MDT0000 [ 2849.787455] Lustre: server umount lustre-MDT0000 complete [ 2849.788444] LustreError: 126920:0:(super25.c:199:lustre_fill_super()) llite: Unable to mount : rc = -95 [ 2852.692907] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2855.088586] Lustre: DEBUG MARKER: == replay-single test 62: don't mis-drop resent replay === 21:09:06 (1768010946) [ 2855.123775] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 2855.126061] Lustre: Skipped 18 previous similar messages [ 2855.157580] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5315 to 0x240000400:5345) [ 2855.157687] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5283 to 0x280000400:5313) [ 2856.321530] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 2857.247106] Lustre: Failing over lustre-MDT0000 [ 2857.432416] Lustre: server umount lustre-MDT0000 complete [ 2871.075916] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 2871.387928] Lustre: *** cfs_fail_loc=707, val=0*** [ 2886.753186] Lustre: lustre-MDT0000: Client c4330d47-e9c3-460b-9b23-f34cc6c89b63 (at 192.168.203.34@tcp) reconnected, waiting for 1 clients in recovery for 0:54 [ 2886.847857] Lustre: lustre-MDT0000: Recovery over after 0:15, of 1 clients 1 recovered and 0 were evicted. [ 2886.851359] Lustre: Skipped 19 previous similar messages [ 2886.870066] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5358 to 0x240000400:5377) [ 2886.872690] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5327 to 0x280000400:5345) [ 2888.157725] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 2888.662053] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 2892.210446] Lustre: DEBUG MARKER: == replay-single test 65a: AT: verify early replies ====== 21:09:44 (1768010984) [ 2915.630837] LustreError: 128494:0:(service.c:2536:ptlrpc_server_handle_request()) @@@ HIT req@ffff93be45814000 x1853890928717568/t0(0) o101->c4330d47-e9c3-460b-9b23-f34cc6c89b63@192.168.203.34@tcp:339/0 lens 664/0 e 0 to 0 dl 1768011019 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 2915.638041] LustreError: 128494:0:(service.c:2537:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a sleeping for 11000ms [ 2926.663062] LustreError: 128494:0:(service.c:2537:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a awake [ 2926.667917] LustreError: 128496:0:(service.c:2536:ptlrpc_server_handle_request()) @@@ HIT req@ffff93be4aefca80 x1853890928718592/t0(0) o35->c4330d47-e9c3-460b-9b23-f34cc6c89b63@192.168.203.34@tcp:356/0 lens 392/0 e 0 to 0 dl 1768011036 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 2928.105258] LustreError: 6539:0:(service.c:2536:ptlrpc_server_handle_request()) @@@ HIT req@ffff93bf78ea6a00 x1853890932202752/t0(0) o6->lustre-MDT0000-mdtlov_UUID@0@lo:351/0 lens 544/0 e 0 to 0 dl 1768011031 ref 1 fl Interpret:/200/ffffffff rc 0/-1 job:'osp-syn-0-0.0' uid:0 gid:0 projid:4294967295 [ 2928.113325] LustreError: 6539:0:(service.c:2536:ptlrpc_server_handle_request()) Skipped 48 previous similar messages [ 2933.216693] LustreError: 32394:0:(service.c:2536:ptlrpc_server_handle_request()) @@@ HIT req@ffff93bf6fe6b800 x1853890932203904/t0(0) o6->lustre-MDT0000-mdtlov_UUID@0@lo:356/0 lens 544/0 e 0 to 0 dl 1768011036 ref 1 fl Interpret:/200/ffffffff rc 0/-1 job:'osp-syn-1-0.0' uid:0 gid:0 projid:4294967295 [ 2933.223880] LustreError: 32394:0:(service.c:2536:ptlrpc_server_handle_request()) Skipped 7 previous similar messages [ 2938.241752] Lustre: DEBUG MARKER: == replay-single test 65b: AT: verify early replies on packed reply / bulk ========================================================== 21:10:30 (1768011030) [ 2961.455946] LustreError: 32645:0:(tgt_handler.c:2782:tgt_brw_write()) cfs_fail_timeout id 224 sleeping for 11000ms [ 2972.479104] LustreError: 32645:0:(tgt_handler.c:2782:tgt_brw_write()) cfs_fail_timeout id 224 awake [ 2975.333188] Lustre: DEBUG MARKER: == replay-single test 66a: AT: verify MDT service time adjusts with no early replies ========================================================== 21:11:07 (1768011067) [ 2998.076145] LustreError: 128494:0:(service.c:2536:ptlrpc_server_handle_request()) @@@ HIT req@ffff93be49eb5880 x1853890928739328/t0(0) o101->c4330d47-e9c3-460b-9b23-f34cc6c89b63@192.168.203.34@tcp:421/0 lens 576/0 e 0 to 0 dl 1768011101 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 2998.088273] LustreError: 128494:0:(service.c:2537:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a sleeping for 5000ms [ 3003.191083] LustreError: 128494:0:(service.c:2537:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a awake [ 3006.957255] LustreError: 33691:0:(service.c:2536:ptlrpc_server_handle_request()) @@@ HIT req@ffff93be43d28e00 x1853890932219904/t0(0) o6->lustre-MDT0000-mdtlov_UUID@0@lo:430/0 lens 544/0 e 0 to 0 dl 1768011110 ref 1 fl Interpret:/200/ffffffff rc 0/-1 job:'osp-syn-0-0.0' uid:0 gid:0 projid:4294967295 [ 3006.964936] LustreError: 33691:0:(service.c:2536:ptlrpc_server_handle_request()) Skipped 119 previous similar messages [ 3014.031080] LustreError: 128494:0:(service.c:2537:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a awake [ 3025.665204] Lustre: DEBUG MARKER: == replay-single test 66b: AT: verify net latency adjusts ========================================================== 21:11:57 (1768011117) [ 3110.596157] Lustre: DEBUG MARKER: == replay-single test 67a: AT: verify slow request processing doesn't induce reconnects ========================================================== 21:13:22 (1768011202) [ 3133.637125] LustreError: 128518:0:(service.c:2536:ptlrpc_server_handle_request()) @@@ HIT req@ffff93bf4456aa00 x1853890928812160/t0(0) o101->c4330d47-e9c3-460b-9b23-f34cc6c89b63@192.168.203.34@tcp:557/0 lens 576/0 e 0 to 0 dl 1768011237 ref 1 fl Interpret:/600/ffffffff rc 0/-1 job:'createmany.0' uid:0 gid:0 projid:0 [ 3133.646791] LustreError: 128518:0:(service.c:2536:ptlrpc_server_handle_request()) Skipped 99 previous similar messages [ 3133.650413] LustreError: 128518:0:(service.c:2537:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a sleeping for 400ms [ 3133.654094] LustreError: 128518:0:(service.c:2537:ptlrpc_server_handle_request()) Skipped 1 previous similar message [ 3134.071082] LustreError: 128518:0:(service.c:2537:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a awake [ 3149.889159] LustreError: 128493:0:(service.c:2537:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a sleeping for 400ms [ 3149.893131] LustreError: 128493:0:(service.c:2537:ptlrpc_server_handle_request()) Skipped 38 previous similar messages [ 3150.311061] LustreError: 128493:0:(service.c:2537:ptlrpc_server_handle_request()) cfs_fail_timeout id 50a awake [ 3150.313664] LustreError: 128493:0:(service.c:2537:ptlrpc_server_handle_request()) Skipped 38 previous similar messages [ 3165.676761] LustreError: 116304:0:(service.c:2536:ptlrpc_server_handle_request()) @@@ HIT req@ffff93bf4afc2680 x1853890932259840/t0(0) o6->lustre-MDT0000-mdtlov_UUID@0@lo:589/0 lens 544/0 e 0 to 0 dl 1768011269 ref 1 fl Interpret:/200/ffffffff rc 0/-1 job:'osp-syn-1-0.0' uid:0 gid:0 projid:4294967295 [ 3165.685655] LustreError: 116304:0:(service.c:2536:ptlrpc_server_handle_request()) Skipped 83 previous similar messages [ 3177.830570] Lustre: DEBUG MARKER: == replay-single test 67b: AT: verify instant slowdown doesn't induce reconnects ========================================================== 21:14:29 (1768011269) [ 3202.477965] Lustre: DEBUG MARKER: phase 2 [ 3205.459718] Lustre: DEBUG MARKER: == replay-single test 68: AT: verify slowing locks ======= 21:14:57 (1768011297) [ 3275.749260] Lustre: DEBUG MARKER: == replay-single test 70a: check multi client t-f ======== 21:16:07 (1768011367) [ 3276.234957] Lustre: DEBUG MARKER: SKIP: replay-single test_70a Need two or more clients, have 1 [ 3276.775565] Lustre: DEBUG MARKER: == replay-single test 70b: dbench 1mdts recovery; 1 clients ========================================================== 21:16:08 (1768011368) [ 3278.505957] Lustre: DEBUG MARKER: Started rundbench load pid=126250 ... [ 3280.612836] LustreError: 135168:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 3280.615987] LustreError: 135168:0:(osd_handler.c:720:osd_ro()) Skipped 13 previous similar messages [ 3280.971336] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3282.550196] Lustre: DEBUG MARKER: test_70b fail mds1 1 times [ 3283.288334] Lustre: Failing over lustre-MDT0000 [ 3283.315137] Lustre: lustre-MDT0000: Not available for connect from 192.168.203.34@tcp (stopping) [ 3283.595717] Lustre: server umount lustre-MDT0000 complete [ 3296.017541] LustreError: MGC192.168.203.134@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3296.021785] LustreError: Skipped 15 previous similar messages [ 3296.186127] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3296.190551] Lustre: Skipped 7 previous similar messages [ 3296.213891] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 3296.218301] Lustre: Skipped 8 previous similar messages [ 3297.527053] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3301.720140] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5505 to 0x240000400:5537) [ 3301.720212] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5452 to 0x280000400:5473) [ 3303.045788] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3303.611024] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3307.300699] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3308.794057] Lustre: DEBUG MARKER: test_70b fail mds1 2 times [ 3309.438985] Lustre: Failing over lustre-MDT0000 [ 3309.698449] Lustre: server umount lustre-MDT0000 complete [ 3323.520757] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3326.392448] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5557 to 0x280000400:5601) [ 3326.392448] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5620 to 0x240000400:5665) [ 3327.707367] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3328.305469] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3332.101193] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3333.665669] Lustre: DEBUG MARKER: test_70b fail mds1 3 times [ 3334.401054] Lustre: Failing over lustre-MDT0000 [ 3334.582548] Lustre: server umount lustre-MDT0000 complete [ 3348.386162] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3351.985798] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5740 to 0x240000400:5761) [ 3351.985802] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5677 to 0x280000400:5697) [ 3353.053979] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3353.588095] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3357.309410] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3358.779145] Lustre: DEBUG MARKER: test_70b fail mds1 4 times [ 3359.383399] Lustre: Failing over lustre-MDT0000 [ 3359.586722] Lustre: server umount lustre-MDT0000 complete [ 3373.195380] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3377.625325] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5835 to 0x240000400:5857) [ 3377.625374] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5772 to 0x280000400:5793) [ 3378.770623] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3379.321716] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3383.002776] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3384.529757] Lustre: DEBUG MARKER: test_70b fail mds1 5 times [ 3385.156939] Lustre: Failing over lustre-MDT0000 [ 3385.415405] Lustre: server umount lustre-MDT0000 complete [ 3385.487064] Lustre: 3282:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1768011460/real 1768011460] req@ffff93bf79371500 x1853890932873728/t0(0) o400->lustre-MDT0000-lwp-OST0001@0@lo:12/10 lens 224/224 e 0 to 1 dl 1768011476 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3385.497546] Lustre: 3282:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 34 previous similar messages [ 3398.980683] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3402.044399] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:5926 to 0x240000400:5953) [ 3402.044595] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:5862 to 0x280000400:5889) [ 3403.178645] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3403.682944] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3423.887070] Lustre: DEBUG MARKER: == replay-single test 70c: tar 1mdts recovery ============ 21:18:35 (1768011515) [ 3545.897190] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3556.689497] Lustre: DEBUG MARKER: test_70c fail mds1 1 times [ 3557.290743] Lustre: Failing over lustre-MDT0000 [ 3557.565121] LustreError: 142143:0:(obd_class.h:479:obd_check_dev()) Device 16 not setup [ 3557.567032] LustreError: 142143:0:(obd_class.h:479:obd_check_dev()) Skipped 41 previous similar messages [ 3557.600566] Lustre: server umount lustre-MDT0000 complete [ 3570.125108] 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 [ 3570.132243] Lustre: Skipped 14 previous similar messages [ 3571.499220] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3574.873103] Lustre: lustre-MDT0000: Will be in recovery for at least 1:00, or until 1 client reconnects [ 3574.875300] Lustre: Skipped 6 previous similar messages [ 3575.265507] Lustre: lustre-MDT0000-lwp-OST0001: Connection restored to 0@lo (at 0@lo) [ 3575.270249] Lustre: Skipped 14 previous similar messages [ 3579.307522] Lustre: lustre-MDT0000: Recovery over after 0:05, of 1 clients 1 recovered and 0 were evicted. [ 3579.310065] Lustre: Skipped 5 previous similar messages [ 3579.336463] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:9195 to 0x280000400:9217) [ 3579.336958] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:9259 to 0x240000400:9281) [ 3580.568259] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3581.110519] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3704.315001] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3715.199552] Lustre: DEBUG MARKER: test_70c fail mds1 2 times [ 3715.872249] Lustre: Failing over lustre-MDT0000 [ 3716.230696] Lustre: server umount lustre-MDT0000 complete [ 3730.148157] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3738.350142] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:12317 to 0x240000400:12353) [ 3738.350227] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:12254 to 0x280000400:12289) [ 3739.594353] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3740.145600] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3762.127185] Lustre: DEBUG MARKER: == replay-single test 70d: mkdir/rmdir striped dir 1mdts recovery ========================================================== 21:24:13 (1768011853) [ 3762.589221] Lustre: DEBUG MARKER: SKIP: replay-single test_70d needs >= 2 MDTs [ 3763.090701] Lustre: DEBUG MARKER: == replay-single test 70e: rename cross-MDT with random fails ========================================================== 21:24:14 (1768011854) [ 3763.558586] Lustre: DEBUG MARKER: SKIP: replay-single test_70e needs >= 2 MDTs [ 3764.076443] Lustre: DEBUG MARKER: == replay-single test 70f: OSS O_DIRECT recovery with 1 clients ========================================================== 21:24:15 (1768011855) [ 3768.653269] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 3770.200604] Lustre: DEBUG MARKER: test_70f failing OST 1 times [ 3770.834310] Lustre: Failing over lustre-OST0000 [ 3770.870799] Lustre: server umount lustre-OST0000 complete [ 3774.431526] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 3774.435960] LustreError: 32394:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3774.441941] LustreError: 32394:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 4 previous similar messages [ 3785.072752] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3788.428350] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 3789.100564] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 3796.814218] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 3798.363802] Lustre: DEBUG MARKER: test_70f failing OST 2 times [ 3799.006862] Lustre: Failing over lustre-OST0000 [ 3799.026925] Lustre: server umount lustre-OST0000 complete [ 3800.154253] LustreError: 32394:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.203.34@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3800.162188] LustreError: 32394:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 3 previous similar messages [ 3800.543561] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 3813.267211] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3816.703733] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 3817.397628] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 3825.016537] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 3826.498366] Lustre: DEBUG MARKER: test_70f failing OST 3 times [ 3827.113987] Lustre: Failing over lustre-OST0000 [ 3827.137154] Lustre: server umount lustre-OST0000 complete [ 3828.703575] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 3835.993101] LustreError: 33693:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.203.34@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3835.998204] LustreError: 33693:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 8 previous similar messages [ 3841.460161] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3844.800628] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 3845.441930] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 3851.069714] Lustre: DEBUG MARKER: == replay-single test 71a: mkdir/rmdir striped dir with 2 mdts recovery ========================================================== 21:25:42 (1768011942) [ 3851.608046] Lustre: DEBUG MARKER: SKIP: replay-single test_71a needs >= 2 MDTs [ 3852.183541] Lustre: DEBUG MARKER: == replay-single test 73a: open(O_CREAT), unlink, replay, reconnect before open replay, close ========================================================== 21:25:43 (1768011943) [ 3853.496451] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3854.418861] Lustre: Failing over lustre-MDT0000 [ 3854.521108] Lustre: server umount lustre-MDT0000 complete [ 3868.298047] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3870.186643] Lustre: *** cfs_fail_loc=302, val=2147483648*** [ 3886.112155] Lustre: lustre-MDT0000: Client c4330d47-e9c3-460b-9b23-f34cc6c89b63 (at 192.168.203.34@tcp) reconnected, waiting for 1 clients in recovery for 0:54 [ 3886.146767] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:12638 to 0x280000400:12673) [ 3886.146797] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:12704 to 0x240000400:12737) [ 3887.414704] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3887.908023] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3891.153928] Lustre: DEBUG MARKER: == replay-single test 73b: open(O_CREAT), unlink, replay, reconnect at open_replay reply, close ========================================================== 21:26:22 (1768011982) [ 3892.146261] LustreError: 150942:0:(osd_handler.c:720:osd_ro()) lustre-MDT0000: *** setting device osd-zfs read-only *** [ 3892.148630] LustreError: 150942:0:(osd_handler.c:720:osd_ro()) Skipped 10 previous similar messages [ 3892.436929] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 3893.339986] Lustre: Failing over lustre-MDT0000 [ 3893.554676] Lustre: server umount lustre-MDT0000 complete [ 3905.928603] LustreError: MGC192.168.203.134@tcp: Connection to MGS (at 0@lo) was lost; in progress operations using this service will fail [ 3905.932559] LustreError: Skipped 7 previous similar messages [ 3906.101761] Lustre: lustre-MDT0000: Imperative Recovery not enabled, recovery window 60-180 [ 3906.104107] Lustre: Skipped 10 previous similar messages [ 3906.124536] Lustre: lustre-MDT0000: in recovery but waiting for the first client to connect [ 3906.127122] Lustre: Skipped 10 previous similar messages [ 3907.366048] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3907.697934] Lustre: *** cfs_fail_loc=157, val=2147483648*** [ 3907.699222] LustreError: 151571:0:(ldlm_lib.c:3326:target_send_reply_msg()) @@@ dropping reply req@ffff93bf70ec5f80 x1853890981775232/t352187318275(352187318275) o101->c4330d47-e9c3-460b-9b23-f34cc6c89b63@192.168.203.34@tcp:576/0 lens 592/608 e 0 to 0 dl 1768012011 ref 1 fl Interpret:/604/0 rc 301/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 3923.041525] Lustre: lustre-MDT0000: Client c4330d47-e9c3-460b-9b23-f34cc6c89b63 (at 192.168.203.34@tcp) reconnected, waiting for 1 clients in recovery for 0:54 [ 3923.046142] Lustre: 151547:0:(mdt_recovery.c:102:mdt_req_from_lrd()) @@@ restoring transno req@ffff93bf7ab32a00 x1853890981775232/t352187318275(352187318275) o101->c4330d47-e9c3-460b-9b23-f34cc6c89b63@192.168.203.34@tcp:591/0 lens 592/3488 e 0 to 0 dl 1768012026 ref 1 fl Interpret:/606/0 rc 0/0 job:'multiop.0' uid:0 gid:0 projid:0 [ 3923.079517] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:12638 to 0x280000400:12705) [ 3923.079608] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:12739 to 0x240000400:12769) [ 3924.405865] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3924.953417] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 3928.373435] Lustre: DEBUG MARKER: == replay-single test 74: Ensure applications don't fail waiting for OST recovery ========================================================== 21:27:00 (1768012020) [ 3929.276826] Lustre: Failing over lustre-OST0000 [ 3929.316315] Lustre: server umount lustre-OST0000 complete [ 3930.559147] Lustre: Failing over lustre-MDT0000 [ 3930.681619] Lustre: server umount lustre-MDT0000 complete [ 3943.061181] LustreError: 6538:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-OST0000: not available for connect from 0@lo (no target). If you are running an HA pair check that the target is mounted on the other server. [ 3943.069471] LustreError: 6538:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 1 previous similar message [ 3943.131934] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:12638 to 0x280000400:12737) [ 3944.301516] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3947.969442] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:12739 to 0x240000400:12801) [ 3948.294238] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3952.629724] Lustre: DEBUG MARKER: == replay-single test 80a: DNE: create remote dir, drop update rep from MDT0, fail MDT0 ========================================================== 21:27:24 (1768012044) [ 3953.169184] Lustre: DEBUG MARKER: SKIP: replay-single test_80a needs >= 2 MDTs [ 3953.715177] Lustre: DEBUG MARKER: == replay-single test 80b: DNE: create remote dir, drop update rep from MDT0, fail MDT1 ========================================================== 21:27:25 (1768012045) [ 3954.197092] Lustre: DEBUG MARKER: SKIP: replay-single test_80b needs >= 2 MDTs [ 3954.784492] Lustre: DEBUG MARKER: == replay-single test 80c: DNE: create remote dir, drop update rep from MDT1, fail MDT[0,1] ========================================================== 21:27:26 (1768012046) [ 3955.292861] Lustre: DEBUG MARKER: SKIP: replay-single test_80c needs >= 2 MDTs [ 3955.851450] Lustre: DEBUG MARKER: == replay-single test 80d: DNE: create remote dir, drop update rep from MDT1, fail 2 MDTs ========================================================== 21:27:27 (1768012047) [ 3956.399102] Lustre: DEBUG MARKER: SKIP: replay-single test_80d needs >= 2 MDTs [ 3956.978627] Lustre: DEBUG MARKER: == replay-single test 80e: DNE: create remote dir, drop MDT1 rep, fail MDT0 ========================================================== 21:27:28 (1768012048) [ 3957.470598] Lustre: DEBUG MARKER: SKIP: replay-single test_80e needs >= 2 MDTs [ 3957.994527] Lustre: DEBUG MARKER: == replay-single test 80f: DNE: create remote dir, drop MDT1 rep, fail MDT1 ========================================================== 21:27:29 (1768012049) [ 3958.530119] Lustre: DEBUG MARKER: SKIP: replay-single test_80f needs >= 2 MDTs [ 3959.076188] Lustre: DEBUG MARKER: == replay-single test 80g: DNE: create remote dir, drop MDT1 rep, fail MDT0, then MDT1 ========================================================== 21:27:30 (1768012050) [ 3959.584469] Lustre: DEBUG MARKER: SKIP: replay-single test_80g needs >= 2 MDTs [ 3960.099945] Lustre: DEBUG MARKER: == replay-single test 80h: DNE: create remote dir, drop MDT1 rep, fail 2 MDTs ========================================================== 21:27:31 (1768012051) [ 3960.564894] Lustre: DEBUG MARKER: SKIP: replay-single test_80h needs >= 2 MDTs [ 3961.103403] Lustre: DEBUG MARKER: == replay-single test 81a: DNE: unlink remote dir, drop MDT0 update rep, fail MDT1 ========================================================== 21:27:32 (1768012052) [ 3961.577863] Lustre: DEBUG MARKER: SKIP: replay-single test_81a needs >= 2 MDTs [ 3962.148135] Lustre: DEBUG MARKER: == replay-single test 81b: DNE: unlink remote dir, drop MDT0 update reply, fail MDT0 ========================================================== 21:27:33 (1768012053) [ 3962.656933] Lustre: DEBUG MARKER: SKIP: replay-single test_81b needs >= 2 MDTs [ 3963.175194] Lustre: DEBUG MARKER: == replay-single test 81c: DNE: unlink remote dir, drop MDT0 update reply, fail MDT0,MDT1 ========================================================== 21:27:35 (1768012055) [ 3963.693124] Lustre: DEBUG MARKER: SKIP: replay-single test_81c needs >= 2 MDTs [ 3964.256105] Lustre: DEBUG MARKER: == replay-single test 81d: DNE: unlink remote dir, drop MDT0 update reply, fail 2 MDTs ========================================================== 21:27:36 (1768012056) [ 3964.777412] Lustre: DEBUG MARKER: SKIP: replay-single test_81d needs >= 2 MDTs [ 3965.328876] Lustre: DEBUG MARKER: == replay-single test 81e: DNE: unlink remote dir, drop MDT1 req reply, fail MDT0 ========================================================== 21:27:37 (1768012057) [ 3965.856541] Lustre: DEBUG MARKER: SKIP: replay-single test_81e needs >= 2 MDTs [ 3966.437676] Lustre: DEBUG MARKER: == replay-single test 81f: DNE: unlink remote dir, drop MDT1 req reply, fail MDT1 ========================================================== 21:27:38 (1768012058) [ 3966.983871] Lustre: DEBUG MARKER: SKIP: replay-single test_81f needs >= 2 MDTs [ 3967.562059] Lustre: DEBUG MARKER: == replay-single test 81g: DNE: unlink remote dir, drop req reply, fail M0, then M1 ========================================================== 21:27:39 (1768012059) [ 3968.067323] Lustre: DEBUG MARKER: SKIP: replay-single test_81g needs >= 2 MDTs [ 3968.649289] Lustre: DEBUG MARKER: == replay-single test 81h: DNE: unlink remote dir, drop request reply, fail 2 MDTs ========================================================== 21:27:40 (1768012060) [ 3969.157437] Lustre: DEBUG MARKER: SKIP: replay-single test_81h needs >= 2 MDTs [ 3969.711553] Lustre: DEBUG MARKER: == replay-single test 84a: stale open during export disconnect ========================================================== 21:27:41 (1768012061) [ 3970.317221] Lustre: 155902:0:(genops.c:1791:obd_export_evict_by_uuid()) lustre-MDT0000: evicting 197bc282-221b-4d56-9552-7ab182cb181d at adminstrative request [ 3973.798688] Lustre: DEBUG MARKER: == replay-single test 85a: check the cancellation of unused locks during recovery(IBITS) ========================================================== 21:27:45 (1768012065) [ 3975.679322] Lustre: Failing over lustre-MDT0000 [ 3975.770338] Lustre: lustre-MDT0000: Not available for connect from 192.168.203.34@tcp (stopping) [ 3975.946379] Lustre: server umount lustre-MDT0000 complete [ 3989.868781] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 3992.607161] Lustre: 3279:0:(client.c:2478:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1768012069/real 1768012069] req@ffff93be41e63100 x1853890938690816/t0(0) o400->lustre-MDT0000-lwp-OST0000@0@lo:12/10 lens 224/224 e 0 to 1 dl 1768012085 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 3992.614442] Lustre: 3279:0:(client.c:2478:ptlrpc_expire_one_request()) Skipped 27 previous similar messages [ 3996.422081] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:12789 to 0x280000400:12833) [ 3996.422275] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:12853 to 0x240000400:12897) [ 3997.568456] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 3998.088585] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4001.596416] Lustre: DEBUG MARKER: == replay-single test 85b: check the cancellation of unused locks during recovery(EXTENT) ========================================================== 21:28:13 (1768012093) [ 4005.295970] Lustre: Failing over lustre-OST0000 [ 4005.353940] Lustre: server umount lustre-OST0000 complete [ 4006.879664] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 4019.535229] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4022.611742] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 4023.221838] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4026.717400] Lustre: DEBUG MARKER: == replay-single test 86: umount server after clear nid_stats should not hit LBUG ========================================================== 21:28:38 (1768012118) [ 4027.993103] Lustre: Failing over lustre-MDT0000 [ 4028.130614] Lustre: server umount lustre-MDT0000 complete [ 4030.440247] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:12998 to 0x240000400:13025) [ 4030.440283] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:12789 to 0x280000400:12865) [ 4031.685469] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4034.479975] Lustre: DEBUG MARKER: == replay-single test 87a: write replay ================== 21:28:46 (1768012126) [ 4036.022403] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 4036.858829] Lustre: Failing over lustre-OST0000 [ 4036.876468] Lustre: server umount lustre-OST0000 complete [ 4040.671786] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 4050.915315] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4053.896274] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 4054.390201] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4057.663448] Lustre: DEBUG MARKER: == replay-single test 87b: write replay with changed data (checksum resend) ========================================================== 21:29:09 (1768012149) [ 4059.172659] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 4061.025719] Lustre: Failing over lustre-OST0000 [ 4061.046533] Lustre: server umount lustre-OST0000 complete [ 4061.151495] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 4074.736274] LustreError: lustre-OST0000: BAD WRITE CHECKSUM: from 12345-192.168.203.34@tcp inode [0x20002a3e1:0x5:0x0] object 0x240000400:13027 extent [0-1048575]: client csum c5c8b420, server csum 405fb4ea [ 4075.060641] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4078.041243] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 4078.569047] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4081.920373] Lustre: DEBUG MARKER: == replay-single test 88: MDS should not assign same objid to different files ========================================================== 21:29:33 (1768012173) [ 4083.155377] Lustre: DEBUG MARKER: ost1 REPLAY BARRIER on lustre-OST0000 [ 4084.336644] Lustre: DEBUG MARKER: mds1 REPLAY BARRIER on lustre-MDT0000 [ 4086.263051] Lustre: Failing over lustre-MDT0000 [ 4086.458437] Lustre: server umount lustre-MDT0000 complete [ 4087.708605] LustreError: 6554:0:(ldlm_lockd.c:2563:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1768012180 with bad export cookie 12644823783553202393 [ 4098.016404] Lustre: Failing over lustre-OST0000 [ 4099.162127] Lustre: lustre-OST0000: Not available for connect from 192.168.203.34@tcp (stopping) [ 4100.079788] Lustre: server umount lustre-OST0000 complete [ 4104.280951] LustreError: 32394:0:(ldlm_lib.c:1179:target_handle_connect()) lustre-OST0000: not available for connect from 192.168.203.34@tcp (no target). If you are running an HA pair check that the target is mounted on the other server. [ 4104.285716] LustreError: 32394:0:(ldlm_lib.c:1179:target_handle_connect()) Skipped 17 previous similar messages [ 4113.375421] LustreError: 3278:0:(client.c:1390:ptlrpc_import_delay_req()) @@@ invalidate in flight req@ffff93be45123100 x1853890938752640/t0(0) o250->MGC192.168.203.134@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 [ 4114.816382] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4115.618733] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:12789 to 0x280000400:12897) [ 4129.073702] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4134.619670] Lustre: DEBUG MARKER: == replay-single test 89: no disk space leak on late ost connection ========================================================== 21:30:26 (1768012226) [ 4144.337182] Lustre: Failing over lustre-OST0000 [ 4144.375125] Lustre: server umount lustre-OST0000 complete [ 4144.607602] LustreError: lustre-OST0000-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 4145.666316] Lustre: Failing over lustre-MDT0000 [ 4145.922689] Lustre: server umount lustre-MDT0000 complete [ 4159.700321] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4160.481650] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:12789 to 0x280000400:12929) [ 4165.970439] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4166.671848] Lustre: lustre-OST0000: Denying connection for new client 7cfd731b-affe-4894-941a-771982f054f7 (at 192.168.203.34@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 1:08 [ 4166.676100] Lustre: Skipped 11 previous similar messages [ 4176.985183] Lustre: lustre-OST0000: Denying connection for new client 7cfd731b-affe-4894-941a-771982f054f7 (at 192.168.203.34@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 0:58 [ 4176.990155] Lustre: Skipped 2 previous similar messages [ 4197.465338] Lustre: lustre-OST0000: Denying connection for new client 7cfd731b-affe-4894-941a-771982f054f7 (at 192.168.203.34@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 0:38 [ 4197.474297] Lustre: Skipped 3 previous similar messages [ 4233.304896] Lustre: lustre-OST0000: Denying connection for new client 7cfd731b-affe-4894-941a-771982f054f7 (at 192.168.203.34@tcp), waiting for 2 known clients (1 recovered, 0 in progress, and 0 evicted) to recover in 0:02 [ 4233.310531] Lustre: Skipped 6 previous similar messages [ 4235.500138] Lustre: lustre-OST0000: recovery is timed out, evict stale exports [ 4235.502283] Lustre: 167078:0:(genops.c:1618:class_disconnect_stale_exports()) lustre-OST0000: disconnect stale client b5683c54-76ce-4602-af2b-da7b95121ca8@ [ 4235.505900] Lustre: lustre-OST0000: disconnecting 1 stale clients [ 4235.518402] Lustre: lustre-OST0000-osc-MDT0000: Connection restored to 0@lo (at 0@lo) [ 4235.518407] Lustre: lustre-OST0000: Recovery over after 1:10, of 2 clients 1 recovered and 1 was evicted. [ 4235.518415] Lustre: Skipped 14 previous similar messages [ 4235.526527] Lustre: Skipped 22 previous similar messages [ 4235.530651] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:13076 to 0x240000400:13097) [ 4240.087628] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 70 sec [ 4249.161836] Lustre: DEBUG MARKER: free_before: 7517184 free_after: 7517184 [ 4251.259565] Lustre: DEBUG MARKER: == replay-single test 90: lfs find identifies the missing striped file segments ========================================================== 21:32:23 (1768012343) [ 4252.645436] Lustre: Failing over lustre-OST0001 [ 4252.676516] LustreError: 168235:0:(obd_class.h:479:obd_check_dev()) Device 15 not setup [ 4252.678446] LustreError: 168235:0:(obd_class.h:479:obd_check_dev()) Skipped 71 previous similar messages [ 4252.685899] Lustre: server umount lustre-OST0001 complete [ 4255.711566] LustreError: lustre-OST0001-osc-MDT0000: operation ost_statfs to node 0@lo failed: rc = -107 [ 4255.714050] 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 [ 4255.717014] Lustre: Skipped 21 previous similar messages [ 4267.114552] Lustre: lustre-OST0001: Will be in recovery for at least 1:00, or until 2 clients reconnect [ 4267.117151] Lustre: Skipped 15 previous similar messages [ 4267.507591] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4271.546777] Lustre: DEBUG MARKER: == replay-single test 93a: replay + reconnect ============ 21:32:43 (1768012363) [ 4272.834223] Lustre: Failing over lustre-OST0000 [ 4272.891698] Lustre: server umount lustre-OST0000 complete [ 4286.694921] LustreError: 169915:0:(ldlm_lib.c:2885:target_recovery_thread()) cfs_fail_timeout id 715 sleeping for 40000ms [ 4286.699277] LustreError: 169915:0:(ldlm_lib.c:2885:target_recovery_thread()) Skipped 74 previous similar messages [ 4287.027626] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4292.575188] Lustre: *** cfs_fail_loc=715, val=40*** [ 4293.599145] Lustre: *** cfs_fail_loc=715, val=40*** [ 4301.791590] Lustre: lustre-OST0000: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnected, waiting for 2 clients in recovery for 0:54 [ 4307.935138] Lustre: *** cfs_fail_loc=715, val=40*** [ 4318.175565] Lustre: lustre-OST0000: Client lustre-MDT0000-mdtlov_UUID (at 0@lo) reconnected, waiting for 2 clients in recovery for 0:38 [ 4318.178527] Lustre: Skipped 1 previous similar message [ 4324.319098] Lustre: *** cfs_fail_loc=715, val=40*** [ 4324.320649] Lustre: Skipped 1 previous similar message [ 4326.743110] LustreError: 169915:0:(ldlm_lib.c:2885:target_recovery_thread()) cfs_fail_timeout id 715 awake [ 4326.746130] LustreError: 169915:0:(ldlm_lib.c:2885:target_recovery_thread()) Skipped 74 previous similar messages [ 4328.139951] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid [ 4328.677869] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 4332.150447] Lustre: DEBUG MARKER: == replay-single test 93b: replay + reconnect on mds ===== 21:33:43 (1768012423) [ 4333.453479] Lustre: Failing over lustre-MDT0000 [ 4333.535647] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4333.537684] Lustre: Skipped 1 previous similar message [ 4333.714232] Lustre: server umount lustre-MDT0000 complete [ 4347.593857] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing set_default_debug vfstrace rpctrace dlmtrace neterror ha config ioctl super lfsck all [ 4354.139672] LustreError: 171349:0:(ldlm_lib.c:2885:target_recovery_thread()) cfs_fail_timeout id 715 sleeping for 80000ms [ 4360.159174] Lustre: *** cfs_fail_loc=715, val=80*** [ 4360.161291] Lustre: Skipped 1 previous similar message [ 4370.520932] Lustre: lustre-MDT0000: Client 7cfd731b-affe-4894-941a-771982f054f7 (at 192.168.203.34@tcp) reconnected, waiting for 1 clients in recovery for 0:53 [ 4370.523826] Lustre: Skipped 1 previous similar message [ 4376.543104] Lustre: *** cfs_fail_loc=715, val=80*** [ 4385.892498] Lustre: lustre-MDT0000: Client 7cfd731b-affe-4894-941a-771982f054f7 (at 192.168.203.34@tcp) reconnected, waiting for 1 clients in recovery for 0:38 [ 4402.264995] Lustre: lustre-MDT0000: Client 7cfd731b-affe-4894-941a-771982f054f7 (at 192.168.203.34@tcp) reconnected, waiting for 1 clients in recovery for 0:22 [ 4408.287131] Lustre: *** cfs_fail_loc=715, val=80*** [ 4408.289167] Lustre: Skipped 1 previous similar message [ 4434.008826] 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. [ 4434.223117] LustreError: 171349:0:(ldlm_lib.c:2885:target_recovery_thread()) cfs_fail_timeout id 715 awake [ 4434.234421] Lustre: 171349:0:(ldlm_lib.c:2931:target_recovery_thread()) too long recovery - read logs [ 4434.236920] LustreError: dumping log to /tmp/lustre-log.1768012526.171349 [ 4434.309076] Lustre: lustre-OST0001: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x280000400:12942 to 0x280000400:12961) [ 4434.309076] Lustre: lustre-OST0000: new connection from lustre-MDT0000-mdtlov (cleaning up unused objects from 0x240000400:13111 to 0x240000400:13129) [ 4435.620510] Lustre: DEBUG MARKER: oleg334-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid [ 4436.156286] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 4439.600650] Lustre: DEBUG MARKER: == replay-single test complete, duration 4296 sec ======== 21:35:31 (1768012531) [ 4440.116812] Lustre: DEBUG MARKER: === replay-single: start cleanup 21:35:31 (1768012531) === [ 4442.436483] Lustre: DEBUG MARKER: === replay-single: finish cleanup 21:35:34 (1768012534) === [ 4477.408063] Lustre: lustre-MDT0000: Not available for connect from 0@lo (stopping) [ 4477.411489] Lustre: Skipped 2 previous similar messages [ 4479.150390] Lustre: server umount lustre-MDT0000 complete [ 4480.588985] LustreError: 6554:0:(ldlm_lockd.c:2563:ldlm_cancel_handler()) ldlm_cancel from 0@lo arrived at 1768012573 with bad export cookie 12644823783553215140 [ 4480.595779] LustreError: 6554:0:(ldlm_lockd.c:2563:ldlm_cancel_handler()) Skipped 2 previous similar messages [ 4480.630859] Lustre: server umount lustre-OST0000 complete [ 4481.974728] Lustre: server umount lustre-OST0001 complete [ 4486.034975] Lustre: DEBUG MARKER: oleg334-server.virtnet: executing unload_modules_local [ 4487.038753] Key type lgssc unregistered [ 4487.166552] LNet: 173349:0:(lib-ptl.c:967:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 4487.169764] LNetError: 173349:0:(acceptor.c:264:lnet_acceptor_remove_socket()) Interface ens2 not found [ 4487.181407] LNet: Removed LNI 192.168.203.134@tcp [ 4487.451107] Key type .llcrypt unregistered [ 4487.452053] Key type ._llcrypt unregistered