[ 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-0x00000000bffd9fff] usable [ 0.000000] BIOS-e820: [mem 0x00000000bffda000-0x00000000bfffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000feffc000-0x00000000feffffff] reserved [ 0.000000] BIOS-e820: [mem 0x00000000fffc0000-0x00000000ffffffff] reserved [ 0.000000] BIOS-e820: [mem 0x0000000100000000-0x0000000146dfffff] usable [ 0.000000] NX (Execute Disable) protection: active [ 0.000000] SMBIOS 2.8 present. [ 0.000000] DMI: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.17.0-10.fc44 06/10/2025 [ 0.000000] Hypervisor detected: KVM [ 0.000000] kvm-clock: Using msrs 4b564d01 and 4b564d00 [ 0.000000] kvm-clock: using sched offset of 435685259 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 = 0xbffda max_arch_pfn = 0x400000000 [ 0.000000] found SMP MP-table at [mem 0x000f54d0-0x000f54df] [ 0.000000] RAMDISK: [mem 0xbcc64000-0xbffcffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F52F0 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE2464 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE2300 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 0022C0 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE2374 000090 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE2404 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE243C 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe2300-0xbffe2373] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe22ff] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe2374-0xbffe2403] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe2404-0xbffe243b] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe243c-0xbffe2463] [ 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-0x00000000bffd9fff] [ 0.000000] node 0: [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Zeroed struct page in unavailable ranges: 4744 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 0xbffda000-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: 1059618 [ 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: 2829700K/4306400K 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.001011] APIC: Switch to symmetric I/O mode setup [ 0.003139] x2apic enabled [ 0.004008] Switched APIC routing to physical x2apic. [ 0.005016] kvm-guest: setup PV IPIs [ 0.008468] ..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.010012] pid_max: default: 32768 minimum: 301 [ 0.011142] LSM: Security Framework initializing [ 0.013046] Yama: becoming mindful. [ 0.014051] SELinux: Initializing. [ 0.015067] *** VALIDATE selinux *** [ 0.024113] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.028835] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.029156] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.030128] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.031121] *** VALIDATE tmpfs *** [ 0.033389] *** VALIDATE proc *** [ 0.034275] *** VALIDATE cgroup *** [ 0.035011] *** VALIDATE cgroup2 *** [ 0.036276] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.037163] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.038010] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.039033] Spectre V2 : User space: Vulnerable [ 0.040011] Speculative Store Bypass: Vulnerable [ 0.043522] debug: unmapping init [mem 0xffffffff92459000-0xffffffff92460fff] [ 0.045198] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.046746] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.047026] ... version: 2 [ 0.048011] ... bit width: 48 [ 0.049010] ... generic registers: 4 [ 0.050012] ... value mask: 0000ffffffffffff [ 0.051000] ... max period: 00007fffffffffff [ 0.051021] ... fixed-purpose events: 3 [ 0.052026] ... event mask: 000000070000000f [ 0.053305] rcu: Hierarchical SRCU implementation. [ 0.055503] smp: Bringing up secondary CPUs ... [ 0.056609] x86: Booting SMP configuration: [ 0.057024] .... node #0, CPUs: #1 #2 #3 [ 0.061062] smp: Brought up 1 node, 4 CPUs [ 0.063018] smpboot: Max logical packages: 1 [ 0.064019] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.111026] node 0 deferred pages initialised in 45ms [ 0.113496] devtmpfs: initialized [ 0.114222] x86/mm: Memory block size: 128MB [ 0.117331] gcov: version magic: 0x41383552 [ 0.119250] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.123154] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.125334] pinctrl core: initialized pinctrl subsystem [ 0.126189] [ 0.126735] ************************************************************* [ 0.129012] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.131011] ** ** [ 0.133011] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.134010] ** ** [ 0.136009] ** This means that this kernel is built to expose internal ** [ 0.137007] ** IOMMU data structures, which may compromise security on ** [ 0.138008] ** your system. ** [ 0.140007] ** ** [ 0.141005] ** If you see this message and you are not debugging the ** [ 0.142007] ** kernel, report this immediately to your vendor! ** [ 0.143008] ** ** [ 0.145009] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.146008] ************************************************************* [ 0.147584] NET: Registered protocol family 16 [ 0.149298] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.150042] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.152040] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.154015] cpuidle: using governor menu [ 0.155549] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.156565] PCI: Using configuration type 1 for base access [ 0.157129] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.165217] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.167027] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.169110] cryptd: max_cpu_qlen set to 1000 [ 0.171281] ACPI: Added _OSI(Module Device) [ 0.173019] ACPI: Added _OSI(Processor Device) [ 0.175012] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.176013] ACPI: Added _OSI(Processor Aggregator Device) [ 0.180969] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.186210] ACPI: Interpreter enabled [ 0.187056] ACPI: PM: (supports S0 S3 S4 S5) [ 0.189013] ACPI: Using IOAPIC for interrupt routing [ 0.190109] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.193409] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.204047] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.206034] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.207012] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.210081] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.215388] acpiphp: Slot [2] registered [ 0.216117] acpiphp: Slot [5] registered [ 0.218114] acpiphp: Slot [6] registered [ 0.219138] acpiphp: Slot [3] registered [ 0.221089] acpiphp: Slot [4] registered [ 0.222098] acpiphp: Slot [7] registered [ 0.223084] acpiphp: Slot [8] registered [ 0.224074] acpiphp: Slot [9] registered [ 0.226094] acpiphp: Slot [10] registered [ 0.227104] acpiphp: Slot [11] registered [ 0.228107] acpiphp: Slot [12] registered [ 0.230089] acpiphp: Slot [13] registered [ 0.231000] acpiphp: Slot [14] registered [ 0.231000] acpiphp: Slot [15] registered [ 0.233102] acpiphp: Slot [16] registered [ 0.234114] acpiphp: Slot [17] registered [ 0.236130] acpiphp: Slot [18] registered [ 0.237094] acpiphp: Slot [19] registered [ 0.238098] acpiphp: Slot [20] registered [ 0.239120] acpiphp: Slot [21] registered [ 0.241082] acpiphp: Slot [22] registered [ 0.242088] acpiphp: Slot [23] registered [ 0.243190] acpiphp: Slot [24] registered [ 0.244097] acpiphp: Slot [25] registered [ 0.245080] acpiphp: Slot [26] registered [ 0.246090] acpiphp: Slot [27] registered [ 0.248084] acpiphp: Slot [28] registered [ 0.249073] acpiphp: Slot [29] registered [ 0.250089] acpiphp: Slot [30] registered [ 0.251102] acpiphp: Slot [31] registered [ 0.253092] PCI host bridge to bus 0000:00 [ 0.254021] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.257024] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.259068] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.261024] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.264023] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.266020] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.268176] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.269906] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.273251] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.279012] pci 0000:00:01.1: reg 0x20: [io 0xc120-0xc12f] [ 0.281361] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.283012] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.284011] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.286013] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.288340] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.290737] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.294089] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.296678] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.300882] pci 0000:00:02.0: reg 0x10: [io 0xc100-0xc11f] [ 0.313022] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.317015] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.323568] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.330021] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.335017] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.344016] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.350995] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.354017] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.359015] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.370015] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.377725] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.380376] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.382398] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.384353] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.387221] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.391671] iommu: Default domain type: Passthrough [ 0.392310] SCSI subsystem initialized [ 0.393099] ACPI: bus type USB registered [ 0.394090] usbcore: registered new interface driver usbfs [ 0.395054] usbcore: registered new interface driver hub [ 0.396071] usbcore: registered new device driver usb [ 0.397106] pps_core: LinuxPPS API ver. 1 registered [ 0.398008] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.400058] PTP clock support registered [ 0.402047] EDAC MC: Ver: 3.0.0 [ 0.403135] PCI: Using ACPI for IRQ routing [ 0.405726] NetLabel: Initializing [ 0.407011] NetLabel: domain hash size = 128 [ 0.408012] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.410085] NetLabel: unlabeled traffic allowed by default [ 0.412124] vgaarb: loaded [ 0.414034] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.415012] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.425798] clocksource: Switched to clocksource kvm-clock [ 0.531248] VFS: Disk quotas dquot_6.6.0 [ 0.532253] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.533900] *** VALIDATE ramfs *** [ 0.535092] *** VALIDATE hugetlbfs *** [ 0.536553] pnp: PnP ACPI init [ 0.538928] pnp: PnP ACPI: found 6 devices [ 0.555442] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.558586] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.560786] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.562882] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.565427] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.567943] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.570382] NET: Registered protocol family 2 [ 0.572886] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.577533] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.580598] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.585069] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.587819] TCP: Hash tables configured (established 65536 bind 65536) [ 0.589666] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.592276] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.594769] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.597464] NET: Registered protocol family 1 [ 0.600464] RPC: Registered named UNIX socket transport module. [ 0.602508] RPC: Registered udp transport module. [ 0.604050] RPC: Registered tcp transport module. [ 0.605618] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.607865] NET: Registered protocol family 44 [ 0.609551] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.611717] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.613912] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.616142] PCI: CLS 0 bytes, default 64 [ 0.617863] Unpacking initramfs... [ 1.965438] debug: unmapping init [mem 0xffff9bc2fcc64000-0xffff9bc2fffcffff] [ 1.968320] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 1.970593] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 1.972391] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 2.434709] Initialise system trusted keyrings [ 2.435848] Key type blacklist registered [ 2.438184] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.449180] zbud: loaded [ 2.452499] *** VALIDATE nfs *** [ 2.453741] *** VALIDATE nfs4 *** [ 2.455388] pstore: using deflate compression [ 2.459454] Platform Keyring initialized [ 2.561804] NET: Registered protocol family 38 [ 2.563394] Key type asymmetric registered [ 2.564607] Asymmetric key parser 'x509' registered [ 2.565755] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 2.568085] io scheduler mq-deadline registered [ 2.569943] io scheduler kyber registered [ 2.571571] io scheduler bfq registered [ 2.574159] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 2.577394] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 2.580467] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 2.584119] ACPI: Power Button [PWRF] [ 2.589854] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 2.596089] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 2.607249] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 2.636779] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 2.664223] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 2.669477] Non-volatile memory driver v1.3 [ 2.671451] Linux agpgart interface v0.103 [ 2.704027] virtio_blk virtio1: [vda] 146648 512-byte logical blocks (75.1 MB/71.6 MiB) [ 2.707305] vda: detected capacity change from 0 to 75083776 [ 2.724158] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 2.727467] vdb: detected capacity change from 0 to 1073741824 [ 2.735518] libphy: Fixed MDIO Bus: probed [ 2.751417] usbcore: registered new interface driver usbserial_generic [ 2.754068] usbserial: USB Serial support registered for generic [ 2.756601] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 2.761589] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 2.763674] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 2.766482] mousedev: PS/2 mouse device common for all mice [ 2.770093] rtc_cmos 00:05: RTC can wake from S4 [ 2.775342] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 2.779052] rtc_cmos 00:05: registered as rtc0 [ 2.783356] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 2.783660] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 2.787137] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 2.788951] intel_pstate: CPU model not supported [ 2.794570] hid: raw HID events driver (C) Jiri Kosina [ 2.797064] usbcore: registered new interface driver usbhid [ 2.798996] usbhid: USB HID core driver [ 2.800465] drop_monitor: Initializing network drop monitor service [ 2.802752] Initializing XFRM netlink socket [ 2.804731] NET: Registered protocol family 10 [ 2.807576] Segment Routing with IPv6 [ 2.808911] NET: Registered protocol family 17 [ 2.810984] mpls_gso: MPLS GSO support [ 2.815152] RAS: Correctable Errors collector initialized. [ 2.818055] AVX version of gcm_enc/dec engaged. [ 2.819410] AES CTR mode by8 optimization enabled [ 2.872581] sched_clock: Marking stable (2872563904, 0)->(3754074363, -881510459) [ 2.874588] registered taskstats version 1 [ 2.875617] Loading compiled-in X.509 certificates [ 2.876747] zswap: loaded using pool lzo/zbud [ 2.893697] Key type big_key registered [ 2.904120] Key type encrypted registered [ 2.906326] ima: No TPM chip found, activating TPM-bypass! [ 2.909201] ima: Allocated hash algorithm: sha1 [ 2.911535] ima: No architecture policies found [ 2.913513] evm: Initialising EVM extended attributes: [ 2.915322] evm: security.selinux [ 2.916546] evm: security.ima [ 2.917551] evm: security.capability [ 2.918631] evm: HMAC attrs: 0x1 [ 2.921800] rtc_cmos 00:05: setting system clock to 2026-09-06 20:07:55 UTC (1788725275) [ 2.928777] debug: unmapping init [mem 0xffffffff93403000-0xffffffff935fffff] [ 2.930704] debug: unmapping init [mem 0xffffffff92182000-0xffffffff92458fff] [ 2.939073] Write protecting the kernel read-only data: 28672k [ 2.941428] debug: unmapping init [mem 0xffffffff90803000-0xffffffff909fffff] [ 2.944218] debug: unmapping init [mem 0xffffffff91114000-0xffffffff911fffff] [ 2.973650] 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) [ 2.980417] systemd[1]: Detected virtualization kvm. [ 2.983137] systemd[1]: Detected architecture x86-64. [ 2.985853] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.010377] systemd[1]: No hostname configured. [ 3.011771] systemd[1]: Set hostname to . [ 3.013449] random: systemd: uninitialized urandom read (16 bytes read) [ 3.015284] systemd[1]: Initializing machine ID from random generator. [ 3.065704] random: ln: uninitialized urandom read (6 bytes read) [ 3.143891] random: systemd: uninitialized urandom read (16 bytes read) [ 3.146662] systemd[1]: Reached target Timers. [ OK ] Reached target Timers. [ 3.150453] systemd[1]: Reached target Slices. [ OK ] Reached target Slices. [ 3.154151] systemd[1]: Listening on Journal Socket (/dev/log). [ OK ] Listening on Journal Socket (/dev/log). [ OK ] Listening on Journal Socket. Starting Create list of required st…ce nodes for the current kernel... Starting Setup Virtual Console... [ OK ] Reached target Initrd Root Device. Starting Journal Service... [ OK ] Listening on udev Kernel Socket. [ OK ] Reached target Local File Systems. [ OK ] Reached target Swap. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Paths. [ OK ] Reached target Local Encrypted Volumes. Starting Apply Kernel Variables... Starting Create Volatile Files and Directories... [ OK ] Listening on udev Control Socket. [ OK ] Reached target Sockets. [ OK ] Started Memstrack Anylazing Service. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Setup Virtual Console. [ OK ] Started Apply Kernel Variables. [ OK ] Started Create Volatile Files and Directories. Starting dracut cmdline hook... Starting Create Static Device Nodes in /dev... [ OK ] Started Journal Service. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 3.705288] device-mapper: uevent: version 1.0.3 [ 3.707475] 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. [ 3.988698] random: fast init done Starting dracut pre-trigger hook... [ OK ] Started dracut pre-trigger hook. Starting udev Coldplug all Devices... Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. Starting dracut initqueue hook... [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ 4.382799] virtio_net virtio0 ens2: renamed from eth0 [ 4.425949] scsi host0: ata_piix [ 4.440264] scsi host1: ata_piix [ 4.441251] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc120 irq 14 [ 4.442605] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc128 irq 15 [ 8.507891] dracut-initqueue[582]: RTNETLINK answers: File exists [ 9.440318] random: crng init done [ 9.442262] random: 7 urandom warning(s) missed due to ratelimiting Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Mounting /sysroot... [ 10.725159] 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... Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped target Timers. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Paths. [ OK ] Stopped target Sockets. [ OK ] Stopped target Slices. [ OK ] Stopped target System Initialization. [ OK ] Stopped target Swap. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. Stopping udev Kernel Device Manager... [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Closed udev Kernel Socket. [ OK ] Closed udev Control Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 13.531879] printk: systemd: 25 output lines suppressed due to ratelimiting [ 14.722489] SELinux: Disabled at runtime. [ 15.011896] 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) [ 15.025232] systemd[1]: Detected virtualization kvm. [ 15.027044] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 16.889867] systemd[1]: initrd-switch-root.service: Succeeded. [ 16.903889] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 16.931521] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 16.944688] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 16.964747] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 17.002795] systemd[1]: Starting Journal Service... Starting Journal Service... [ 17.029239] systemd[1]: Reached target rpc_pipefs.target. [ OK ] Reached target rpc_pipefs.target. Activating swap /dev/disk/by-label/SWAP... Mounting POSIX Message Queue File System... [ 17.165801] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS [ OK ] Listening on RPCbind Server Activation Socket. Mounting Kernel Debug File System... [ OK ] Created slice system-serial\x2dgetty.slice. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd File Systems. [ OK ] Listening on udev Control Socket. [ OK ] Created slice User and Session Slice. [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Created slice system-getty.slice. [ OK ] Listening on udev Kernel Socket. Starting udev Coldplug all Devices... [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Reached target Slices. [ OK ] Stopped target Initrd Root File System. Starting Remount Root and Kernel File Systems... [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Reached target Paths. [ OK ] Listening on Process Core Dump Socket. [ OK ] Listening on initctl Compatibility Named Pipe. Mounting Huge Pages File System... Starting Apply Kernel Variables... [ OK ] Reached target RPC Port Mapper. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Started Journal Service. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Mounted Kernel Debug File System. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Mounted Huge Pages File System. [ OK ] Started Apply Kernel Variables. Starting Configure read-only root support... Starting Create Static Device Nodes in /dev... [ OK ] Reached target Swap. Starting Flush Journal to Persistent Storage... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started udev Coldplug all Devices. [ OK ] Started Create Static Device Nodes in /dev. Starting udev Kernel Device Manager... [ OK ] Reached target Local File Systems (Pre). Mounting /home/green/git/lustre-release... Mounting /mnt... [ OK ] Mounted /mnt. [ 18.963951] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 20.581146] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 20.618921] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 21.441733] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 21.547903] EDAC sbridge: Ver: 1.1.2 [* ] A start job is running for Configur…-only root support (8s / no limit) [** ] A start job is running for Configur…-only root support (8s / no limit) [*** ] A start job is running for Configur…-only root support (9s / no limit) [ *** ] A start job is running for Configur…-only root support (9s / no limit) [ *** ] A start job is running for Configur…only root support (10s / no limit)[ 27.118326] Key type dns_resolver registered [ ***] A start job is running for Configur…only root support (11s / no limit) [ **] A start job is running for Configur…only root support (11s / no limit)[ 28.496309] NFS: Registering the id_resolver key type [ 28.502321] Key type id_resolver registered [ 28.505680] Key type id_legacy registered [ *] A start job is running for Configur…only root support (12s / no limit) [ **] A start job is running for Configur…only root support (12s / no limit) [ OK ] Started Configure read-only root support. [ OK ] Reached target Local File Systems. Starting Rebuild Dynamic Linker Cache... Starting Mark the need to relabel after reboot... Starting Create Volatile Files and Directories... Starting Load/Save Random Seed... [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Load/Save Random Seed. [ OK ] Started Create Volatile Files and Directories. Starting Update UTMP about System Boot/Shutdown... Starting RPC Bind... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Started dnf makecache --timer. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. Starting Login Service... Starting Restore /run/initramfs on shutdown... [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Started irqbalance daemon. [ OK ] Reached target sshd-keygen.target. [ OK ] Started D-Bus System Message Bus. Starting Network Manager... [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Reached target Timers. [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Network Manager. [ OK ] Reached target Network. Starting Dynamic System Tuning Daemon... Starting GSSAPI Proxy Daemon... Starting OpenSSH server daemon... Starting Network Manager Wait Online... [ OK ] Started Login Service. Starting Hostname Service... [ OK ] Started OpenSSH server daemon. [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... [ OK ] Started Permit User Sessions. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Getty on tty1. [ OK ] Started Command Scheduler. [ OK ] Started Serial Getty on ttyS1. [ 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 Notify NFS peers of a restart... Starting Crash recovery kernel arming... Starting System Logging Service... [ 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 oleg219-client login: [ 94.877755] libcfs: loading out-of-tree module taints kernel. [ 95.241166] Key type ._llcrypt registered [ 95.242968] Key type .llcrypt registered [ 95.681396] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [ 95.696924] alg: No test for adler32 (adler32-zlib) [ 97.071951] Lustre: Lustre: Build Version: 2.17.57_103_g794a134 [ 98.273816] LNet: Added LNI 192.168.202.19@tcp [8/256/0/180] [ 100.015148] Key type lgssc registered [ 101.740803] Lustre: Echo OBD driver; http://www.lustre.org/ [ 106.527074] hrtimer: interrupt took 5066181 ns [ 263.008279] Lustre: Mounted lustre-client - version 2.17.57_103_g794a134 [ 267.951181] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 286.753458] Lustre: DEBUG MARKER: oleg219-client.virtnet: executing check_logdir /tmp/testlogs/ [ 288.742595] Lustre: lustre-OST0000-osc-ffff9bc359bd9000: disconnect after 24s idle [ 292.651249] Lustre: DEBUG MARKER: oleg219-client.virtnet: executing yml_node [ 297.363657] Lustre: DEBUG MARKER: Client: 2.17.57.103 [ 300.355325] Lustre: DEBUG MARKER: MDS: 2.17.57.103 [ 303.043423] Lustre: DEBUG MARKER: OSS: 2.17.57.103 [ 304.873840] Lustre: DEBUG MARKER: -----============= acceptance-small: sanityn ============----- Sun Sep 6 16:12:55 EDT 2026 [ 321.966315] Lustre: DEBUG MARKER: excepting tests: 27 40a [ 323.836447] Lustre: DEBUG MARKER: skipping tests SLOW=no: 33a [ 325.671934] Lustre: DEBUG MARKER: === sanityn: start setup 16:13:16 (1788725596) === [ 326.405389] Lustre: Mounted lustre-client - version 2.17.57_103_g794a134 [ 332.960483] Lustre: DEBUG MARKER: oleg219-client.virtnet: executing check_config_client /mnt/lustre [ 351.929213] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 370.210665] Lustre: DEBUG MARKER: === sanityn: finish setup 16:14:01 (1788725641) === [ 372.397767] Lustre: DEBUG MARKER: == sanityn test 0: do_node_vp() and do_facet_vp() do the right thing ========================================================== 16:14:03 (1788725643) [ 380.707469] Lustre: DEBUG MARKER: == sanityn test 1: Check attribute updates on 2 mount points ========================================================== 16:14:11 (1788725651) [ 387.739717] Lustre: DEBUG MARKER: == sanityn test 2a: check cached attribute updates on 2 mtpt's ================================================================== 16:14:18 (1788725658) [ 394.159945] Lustre: DEBUG MARKER: == sanityn test 2b: check cached attribute updates on 2 mtpt's ================================================================== 16:14:25 (1788725665) [ 400.338449] Lustre: DEBUG MARKER: == sanityn test 2c: check cached attribute updates on 2 mtpt's root ============================================================= 16:14:31 (1788725671) [ 407.595760] Lustre: DEBUG MARKER: == sanityn test 2d: check cached attribute updates on 2 mtpt's root ============================================================= 16:14:38 (1788725678) [ 413.879677] Lustre: DEBUG MARKER: == sanityn test 2e: check chmod on root is propagated to others ========================================================== 16:14:45 (1788725685) [ 420.314786] Lustre: DEBUG MARKER: == sanityn test 2f: check attr/owner updates on DNE with 2 mtpt's ========================================================== 16:14:51 (1788725691) [ 428.256184] Lustre: DEBUG MARKER: == sanityn test 2g: check blocks update on sync write ==== 16:14:59 (1788725699) [ 435.226031] Lustre: DEBUG MARKER: == sanityn test 3: symlink on one mtpt, readlink on another ===================================================================== 16:15:06 (1788725706) [ 441.764901] Lustre: DEBUG MARKER: == sanityn test 4: fstat validation on multiple mount points ==================================================================== 16:15:12 (1788725712) [ 449.508155] Lustre: lustre-OST0000-osc-ffff9bc359bd9000: disconnect after 21s idle [ 449.516687] Lustre: Skipped 1 previous similar message [ 450.126635] Lustre: DEBUG MARKER: == sanityn test 5: create a file on one mount, truncate it on the other ========================================================== 16:15:21 (1788725721) [ 457.394587] Lustre: DEBUG MARKER: == sanityn test 6: remove of open file on other node ============================================================================ 16:15:28 (1788725728) [ 463.650888] Lustre: DEBUG MARKER: == sanityn test 7: remove of open directory on other node ======================================================================= 16:15:35 (1788725735) [ 464.868485] Lustre: lustre-OST0001-osc-ffff9bc3467b9800: disconnect after 22s idle [ 469.876329] Lustre: DEBUG MARKER: == sanityn test 8: remove of open special file on other node ==================================================================== 16:15:41 (1788725741) [ 476.484321] Lustre: DEBUG MARKER: == sanityn test 9a: append of file with sub-page size on multiple mounts ========================================================== 16:15:47 (1788725747) [ 483.358668] Lustre: DEBUG MARKER: == sanityn test 9b: append to striped sparse file ======== 16:15:54 (1788725754) [ 490.075500] Lustre: DEBUG MARKER: == sanityn test 10a: write of file with sub-page size on multiple mounts ========================================================== 16:16:01 (1788725761) [ 498.470884] Lustre: DEBUG MARKER: == sanityn test 10b: write of file with sub-page size on multiple mounts ========================================================== 16:16:09 (1788725769) [ 505.692575] Lustre: DEBUG MARKER: == sanityn test 11: execution of file opened for write should return error ============================================================== 16:16:16 (1788725776) [ 512.879707] Lustre: DEBUG MARKER: == sanityn test 12: test lock ordering (link, stat, unlink) ========================================================== 16:16:23 (1788725783) [ 513.649921] Lustre: DEBUG MARKER: start dir: /mnt/lustre/lockdir=144115205289279518 file: /mnt/lustre/lockdir/lockfile=144115205289279517 [ 657.233492] Lustre: DEBUG MARKER: == sanityn test 13: test directory page revocation ======= 16:18:47 (1788725927) [ 665.719472] Lustre: DEBUG MARKER: == sanityn test 14aa: execution of file open for write returns -ETXTBSY ========================================================== 16:18:56 (1788725936) [ 673.070420] Lustre: DEBUG MARKER: == sanityn test 14ab: open(RDWR) of executing file returns -ETXTBSY ========================================================== 16:19:04 (1788725944) [ 680.472279] Lustre: DEBUG MARKER: == sanityn test 14b: truncate of executing file returns -ETXTBSY ================================================================ 16:19:11 (1788725951) [ 687.609543] Lustre: DEBUG MARKER: == sanityn test 14c: open(O_TRUNC) of executing file return -ETXTBSY ============================================================ 16:19:18 (1788725958) [ 694.909241] Lustre: DEBUG MARKER: == sanityn test 14d: chmod of executing file is still possible ================================================================== 16:19:26 (1788725966) [ 697.178808] Lustre: DEBUG MARKER: chmod [ 703.446246] Lustre: DEBUG MARKER: == sanityn test 15: test out-of-space with multiple writers ===================================================================== 16:19:34 (1788725974) [ 1659.358374] Lustre: DEBUG MARKER: == sanityn test 16a: 2500 iterations of dual-mount fsx === 16:35:30 (1788726930) [ 1806.306485] Lustre: lustre-OST0001-osc-ffff9bc3467b9800: disconnect after 22s idle [ 1870.752685] Lustre: DEBUG MARKER: == sanityn test 16b: 2500 iterations of dual-mount fsx at small size ========================================================== 16:39:02 (1788727142) [ 1980.342274] Lustre: DEBUG MARKER: == sanityn test 16c: verify data consistency on ldiskfs with cache disabled (b=17397) ========================================================== 16:40:51 (1788727251) [ 2111.712316] Lustre: DEBUG MARKER: == sanityn test 16d: Verify DIO and buffer IO with two clients ========================================================== 16:43:02 (1788727382) [ 2152.604715] Lustre: DEBUG MARKER: == sanityn test 16e: Verify size consistency for O_DIRECT write ========================================================== 16:43:43 (1788727423) [ 2154.463865] Lustre: lustre-OST0001-osc-ffff9bc3467b9800: disconnect after 24s idle [ 2159.689691] Lustre: DEBUG MARKER: == sanityn test 16f: rw sequential consistency vs drop_caches ========================================================== 16:43:50 (1788727430) [ 2160.813584] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2160.897812] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2161.003315] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2161.144162] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2161.212934] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2161.268197] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2161.348588] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2161.458175] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2161.506239] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2161.556816] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2161.600123] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2161.637536] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2161.670790] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2161.709025] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2161.755875] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2161.789883] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2161.824271] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2161.885661] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2161.923330] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2161.988787] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2162.029957] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2162.059754] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2162.097130] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2162.126484] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2162.156698] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2162.199861] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2162.260389] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2162.357302] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2162.425390] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2162.465251] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2162.515421] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2162.593267] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2162.671664] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2162.735571] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2162.798203] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2162.875271] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2162.953929] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2163.007242] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2163.088820] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2163.180766] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2163.238532] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2163.337639] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2163.439522] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2163.525957] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2163.662954] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2163.803609] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2163.938653] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2164.109794] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2164.225913] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2164.302920] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2164.350235] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2164.394136] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2164.451336] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2164.537865] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2164.581680] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2164.636206] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2164.684798] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2164.739708] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2164.787332] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2164.849844] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2164.914575] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2164.990457] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2165.055130] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2165.144835] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2165.210859] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2165.274627] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2165.379206] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2165.458193] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2165.520812] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2165.571531] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2165.640820] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2165.718443] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2165.788887] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2165.830699] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2165.882057] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2165.944675] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2166.014324] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2166.076917] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2166.117536] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2166.206120] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2166.360056] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2166.463860] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2166.575789] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2166.680067] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2166.762971] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2166.879601] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2166.987768] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2167.090730] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2167.182102] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2167.275515] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2167.332782] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2167.398987] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2167.451813] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2167.533313] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2167.609453] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2167.703640] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2167.771941] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2167.836548] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2167.959376] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2168.087370] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2168.177027] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2168.245336] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2168.328918] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2168.415826] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2168.543749] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2168.658686] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2168.757657] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2168.863526] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2168.956509] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2169.039414] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2169.118323] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2169.203291] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2169.282536] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2169.382021] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2169.511613] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2169.603211] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2169.688082] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2169.759937] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2169.862393] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2169.945377] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2170.006752] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2170.120248] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2170.257341] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2170.382724] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2170.529426] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2170.664698] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2170.723542] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2170.824744] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2170.915554] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2170.986689] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2171.071232] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2171.168050] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2171.232977] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2171.322479] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2171.428614] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2171.550734] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2171.622200] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2171.733712] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2171.852131] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2171.932195] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2172.042367] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2172.161210] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2172.318866] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2172.438957] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2172.572763] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2172.718320] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2172.883689] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2173.033609] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2173.169455] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2173.269605] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2173.413218] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2173.514766] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2173.600467] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2173.718573] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2173.882427] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2173.994098] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2174.169517] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2174.291233] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2174.433636] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2174.564879] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2174.688602] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2174.848591] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2174.937470] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2174.943694] Lustre: lustre-OST0000-osc-ffff9bc3467b9800: disconnect after 21s idle [ 2175.034179] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2175.148512] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2175.235569] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2175.306372] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2175.424691] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2175.544374] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2175.619738] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2175.715059] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2175.794479] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2175.846483] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2175.923157] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2175.998910] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2176.089440] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2176.162518] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2176.245281] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2176.328200] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2176.429921] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2176.511763] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2176.601096] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2176.721599] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2176.812960] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2176.918682] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2177.042653] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2177.150967] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2177.221756] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2177.307607] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2177.376967] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2177.458197] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2177.600707] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2177.710954] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2177.801215] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2177.890833] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2177.960712] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2178.073692] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2178.148608] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2178.237240] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2178.330692] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2178.407175] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2178.492912] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2178.568925] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2178.625657] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2178.691670] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2178.754452] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2178.833883] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2178.908087] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2179.004472] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2179.073859] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2179.183691] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2179.262461] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2179.339317] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2179.402529] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2179.512125] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2179.606302] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2179.717070] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2179.846571] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2179.958341] rw_seq_cst_vs_d (32399): drop_caches: 3 [ 2185.185706] Lustre: lustre-OST0000-osc-ffff9bc359bd9000: disconnect after 22s idle [ 2188.227649] Lustre: DEBUG MARKER: == sanityn test 16g: mmap rw sequential consistency vs drop_caches ========================================================== 16:44:19 (1788727459) [ 2188.777823] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2188.989620] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2189.119150] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2189.258564] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2189.392639] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2189.542843] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2189.705828] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2189.779158] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2189.835820] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2189.950100] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2190.054196] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2190.110493] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2190.309866] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2190.368474] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2190.464188] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2190.516359] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2190.631416] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2190.917367] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2191.100134] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2191.186818] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2191.251893] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2191.312241] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2191.398880] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2191.610800] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2191.679902] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2191.813932] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2191.920149] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2192.067402] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2192.180600] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2192.263250] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2192.612144] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2192.769174] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2192.937124] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2193.044887] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2193.109028] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2193.243533] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2193.328883] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2193.472506] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2193.586256] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2193.624936] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2193.711663] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2193.759960] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2193.884244] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2194.016745] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2194.133291] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2194.267715] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2194.410493] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2194.705490] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2194.758298] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2194.899315] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2194.984756] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2195.093124] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2195.173303] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2195.238590] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2195.391097] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2195.544877] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2195.813783] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2195.930389] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2196.186311] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2196.308035] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2196.390595] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2196.464133] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2196.601226] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2196.653756] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2196.735115] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2196.832171] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2196.878414] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2196.918447] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2196.964351] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2197.005851] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2197.099657] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2197.222659] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2197.265038] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2197.413141] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2197.521180] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2197.648322] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2197.787291] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2197.957637] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2198.360129] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2198.474612] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2198.549359] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2199.070113] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2199.218647] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2199.266574] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2199.389119] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2199.554686] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2199.679803] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2199.838671] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2199.963788] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2200.076796] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2200.172915] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2200.304094] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2200.362457] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2200.415134] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2200.539125] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2200.650525] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2200.773194] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2200.849186] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2200.911883] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2201.125037] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2201.164949] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2201.217873] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2201.340162] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2201.629388] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2201.730424] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2201.865755] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2202.139901] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2202.239862] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2202.414416] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2202.556766] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2202.723709] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2202.781987] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2203.087865] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2203.193593] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2203.325875] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2203.372598] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2203.461150] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2203.513660] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2203.631490] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2203.762111] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2203.841337] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2203.896515] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2204.021270] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2204.138940] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2204.216277] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2204.322807] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2204.419990] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2204.520160] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2204.814323] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2205.158692] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2205.280917] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2205.373514] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2205.426897] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2205.480928] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2205.550197] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2205.607688] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2205.655139] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2205.668829] Lustre: lustre-OST0001-osc-ffff9bc359bd9000: disconnect after 20s idle [ 2205.769587] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2205.868387] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2206.048460] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2206.130874] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2206.220418] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2206.348884] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2206.392699] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2206.523504] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2206.586197] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2206.632593] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2206.940567] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2207.013375] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2207.133472] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2207.228676] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2207.330428] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2207.548274] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2207.609242] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2207.671482] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2207.726470] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2207.803572] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2207.853882] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2207.967563] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2208.048653] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2208.146641] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2208.244782] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2208.355107] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2208.409781] rw_seq_cst_vs_d (32980): drop_caches: 3 [ 2217.706873] Lustre: DEBUG MARKER: == sanityn test 16h: mmap read after truncate file ======= 16:44:48 (1788727488) [ 2226.475814] Lustre: DEBUG MARKER: == sanityn test 16i: read after truncate file ============ 16:44:57 (1788727497) [ 2234.466961] Lustre: DEBUG MARKER: == sanityn test 16j: race dio with buffered i/o ========== 16:45:05 (1788727505) [ 2236.384524] Lustre: lustre-OST0000-osc-ffff9bc3467b9800: disconnect after 22s idle [ 2236.396055] Lustre: Skipped 1 previous similar message [ 2267.259318] Lustre: DEBUG MARKER: == sanityn test 16k: Parallel FSX and drop caches should not panic ========================================================== 16:45:38 (1788727538) [ 2267.740653] bash (35471): drop_caches: 3 [ 2270.976842] bash (35471): drop_caches: 3 [ 2274.155759] bash (35471): drop_caches: 3 [ 2277.254463] bash (35471): drop_caches: 3 [ 2280.394318] bash (35471): drop_caches: 3 [ 2283.657723] bash (35471): drop_caches: 3 [ 2286.806540] bash (35471): drop_caches: 3 [ 2289.962941] bash (35471): drop_caches: 3 [ 2292.704969] Lustre: lustre-OST0000-osc-ffff9bc3467b9800: disconnect after 23s idle [ 2293.168493] bash (35471): drop_caches: 3 [ 2296.775251] bash (35471): drop_caches: 3 [ 2300.166048] bash (35471): drop_caches: 3 [ 2303.531342] bash (35471): drop_caches: 3 [ 2306.671688] bash (35471): drop_caches: 3 [ 2309.871727] bash (35471): drop_caches: 3 [ 2312.987238] bash (35471): drop_caches: 3 [ 2318.001268] Lustre: DEBUG MARKER: == sanityn test 17: resource creation/LVB creation race ========================================================================= 16:46:28 (1788727588) [ 2328.133585] Lustre: DEBUG MARKER: == sanityn test 18: mmap sanity check =========================================================================================== 16:46:39 (1788727599) [ 2355.432288] Lustre: DEBUG MARKER: == sanityn test 19: test concurrent uncached read races ========================================================================= 16:47:06 (1788727626) [ 2364.575861] Lustre: DEBUG MARKER: loop 5 [ 2369.503404] Lustre: lustre-OST0001-osc-ffff9bc359bd9000: disconnect after 23s idle [ 2370.261968] Lustre: DEBUG MARKER: loop 10 [ 2375.482376] Lustre: DEBUG MARKER: loop 15 [ 2380.254176] Lustre: DEBUG MARKER: loop 20 [ 2389.844407] Lustre: DEBUG MARKER: == sanityn test 20: test extra readahead page left in cache ============================================================== 16:47:40 (1788727660) [ 2398.076667] Lustre: DEBUG MARKER: == sanityn test 21: Try to remove mountpoint on another dir ============================================================== 16:47:48 (1788727668) [ 2405.658101] Lustre: DEBUG MARKER: == sanityn test 23: others should see updated atime while another read============================================================== 16:47:56 (1788727676) [ 2475.328235] Lustre: DEBUG MARKER: == sanityn test 24a: lfs df [-ih] [path] test =================================================================================== 16:49:06 (1788727746) [ 2482.740317] Lustre: DEBUG MARKER: == sanityn test 24b: lfs df should show both filesystems ========================================================================= 16:49:13 (1788727753) [ 2489.365167] Lustre: DEBUG MARKER: == sanityn test 25a: change ACL on one mountpoint be seen on another ============================================================= 16:49:20 (1788727760) [ 2497.036522] Lustre: DEBUG MARKER: == sanityn test 25b: change ACL under remote dir on one mountpoint be seen on another ========================================================== 16:49:28 (1788727768) [ 2504.643966] Lustre: DEBUG MARKER: == sanityn test 26a: allow mtime to get older ============ 16:49:36 (1788727776) [ 2512.112879] Lustre: DEBUG MARKER: == sanityn test 26b: sync mtime between ost and mds ====== 16:49:43 (1788727783) [ 2517.983467] Lustre: lustre-OST0000-osc-ffff9bc359bd9000: disconnect after 22s idle [ 2517.995893] Lustre: Skipped 5 previous similar messages [ 2520.900416] Lustre: DEBUG MARKER: == sanityn test 26c: set-in-past on open file is not lost on close ========================================================== 16:49:52 (1788727792) [ 2527.468685] Lustre: DEBUG MARKER: SKIP: sanityn test_27 skipping excluded test 27 [ 2528.807596] Lustre: DEBUG MARKER: == sanityn test 30: recreate file race =================== 16:50:00 (1788727800) [ 2537.153403] Lustre: DEBUG MARKER: == sanityn test 31a: voluntary cancel / blocking ast race======================================================================== 16:50:08 (1788727808) [ 2537.679793] Lustre: *** cfs_fail_loc=314, val=0*** [ 2538.719271] Lustre: *** cfs_fail_loc=314, val=0*** [ 2538.722543] Lustre: Skipped 2 previous similar messages [ 2544.728476] Lustre: DEBUG MARKER: == sanityn test 31b: voluntary OST cancel / blocking ast race======================================================================== 16:50:15 (1788727815) [ 2554.098363] Lustre: *** cfs_fail_loc=314, val=0*** [ 2558.956609] Lustre: lustre-OST0000-osc-ffff9bc3467b9800: Connection to lustre-OST0000 (at 192.168.202.119@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 2558.980759] LustreError: lustre-OST0000-osc-ffff9bc3467b9800: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 2558.998457] Lustre: lustre-OST0000-osc-ffff9bc3467b9800: Connection restored to 192.168.202.119@tcp (at 192.168.202.119@tcp) [ 2561.176850] Lustre: DEBUG MARKER: == sanityn test 31r: open-rename(replace) race =========== 16:50:32 (1788727832) [ 2561.445403] LustreError: 46997:0:(file.c:850:ll_intent_file_open()) cfs_fail_timeout id 1419 sleeping for 3000ms [ 2564.471137] LustreError: 46997:0:(file.c:850:ll_intent_file_open()) cfs_fail_timeout id 1419 awake [ 2570.371825] Lustre: DEBUG MARKER: == sanityn test 31s: open should not revalidate invalid dentry ========================================================== 16:50:41 (1788727841) [ 2577.473963] Lustre: DEBUG MARKER: == sanityn test 31t: getattr should not revalidate invalid dentry ========================================================== 16:50:48 (1788727848) [ 2585.157680] Lustre: DEBUG MARKER: == sanityn test 32b: lockless i/o ======================== 16:50:56 (1788727856) [ 2586.825717] Lustre: DEBUG MARKER: SKIP: sanityn test_32b max_nolock_bytes is removed >= 2.17.53 [ 2588.431187] Lustre: DEBUG MARKER: == sanityn test 32c: contention detection ================ 16:50:59 (1788727859) [ 2616.779253] Lustre: DEBUG MARKER: SKIP: sanityn test_33a skipping SLOW test 33a [ 2618.220678] Lustre: DEBUG MARKER: == sanityn test 33b: COS: cross create/delete, 2 clients, benchmark under remote dir ========================================================== 16:51:29 (1788727889) [ 2619.721643] Lustre: DEBUG MARKER: SKIP: sanityn test_33b Need two or more clients, have 1 [ 2621.073058] Lustre: DEBUG MARKER: == sanityn test 33c: Cancel cross-MDT lock should trigger Sync-on-Lock-Cancel ========================================================== 16:51:32 (1788727892) [ 2625.510104] Lustre: lustre-MDT0000-mdc-ffff9bc3467b9800: Connection to lustre-MDT0000 (at 192.168.202.119@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 2635.767084] LustreError: MGC192.168.202.119@tcp: Connection to MGS (at 192.168.202.119@tcp) was lost; in progress operations using this service will fail [ 2635.795689] Lustre: Evicted from MGS (at 192.168.202.119@tcp) after server handle changed from 0x83d663da12da0a19 to 0x83d663da12e53982 [ 2635.803722] Lustre: MGC192.168.202.119@tcp: Connection restored to 192.168.202.119@tcp (at 192.168.202.119@tcp) [ 2637.030291] Lustre: lustre-MDT0000-mdc-ffff9bc359bd9000: Connection restored to 192.168.202.119@tcp (at 192.168.202.119@tcp) [ 2668.177769] Lustre: DEBUG MARKER: == sanityn test 33d: dependent transactions should trigger COS ========================================================== 16:52:19 (1788727939) [ 2671.583342] Lustre: lustre-OST0001-osc-ffff9bc3467b9800: disconnect after 21s idle [ 2671.589371] Lustre: Skipped 5 previous similar messages [ 2719.482841] Lustre: DEBUG MARKER: == sanityn test 33e: independent transactions shouldn't trigger COS ========================================================== 16:53:10 (1788727990) [ 2737.544451] Lustre: DEBUG MARKER: == sanityn test 34: no lock timeout under IO ============= 16:53:28 (1788728008) [ 2793.430253] Lustre: lustre-OST0000-osc-ffff9bc3467b9800: Connection to lustre-OST0000 (at 192.168.202.119@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 2793.436540] LustreError: lustre-OST0000-osc-ffff9bc359bd9000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 2793.452799] Lustre: Skipped 2 previous similar messages [ 2793.469217] Lustre: lustre-OST0000-osc-ffff9bc359bd9000: Connection restored to 192.168.202.119@tcp (at 192.168.202.119@tcp) [ 2793.472801] LustreError: lustre-OST0000-osc-ffff9bc3467b9800: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 2793.477339] Lustre: Skipped 1 previous similar message [ 2803.660376] Lustre: lustre-OST0001-osc-ffff9bc359bd9000: Connection to lustre-OST0001 (at 192.168.202.119@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 2803.703084] LustreError: lustre-OST0001-osc-ffff9bc359bd9000: This client was evicted by lustre-OST0001; in progress operations using this service will fail. [ 2803.726523] Lustre: lustre-OST0001-osc-ffff9bc359bd9000: Connection restored to 192.168.202.119@tcp (at 192.168.202.119@tcp) [ 2803.744496] Lustre: Skipped 1 previous similar message [ 2824.809349] Lustre: DEBUG MARKER: oleg219-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0000-osc-ffff9bc3467b9800.ost_server_uuid 50 [ 2826.304720] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9bc3467b9800.ost_server_uuid in IDLE state after 0 sec [ 2830.786953] Lustre: DEBUG MARKER: oleg219-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0001-osc-ffff9bc3467b9800.ost_server_uuid 50 [ 2832.118777] Lustre: DEBUG MARKER: osc.lustre-OST0001-osc-ffff9bc3467b9800.ost_server_uuid in FULL state after 0 sec [ 2837.426872] Lustre: DEBUG MARKER: oleg219-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0000-osc-ffff9bc3467b9800.ost_server_uuid 50 [ 2838.622080] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9bc3467b9800.ost_server_uuid in IDLE state after 0 sec [ 2843.856661] Lustre: DEBUG MARKER: oleg219-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0001-osc-ffff9bc3467b9800.ost_server_uuid 50 [ 2845.194414] Lustre: DEBUG MARKER: osc.lustre-OST0001-osc-ffff9bc3467b9800.ost_server_uuid in FULL state after 0 sec [ 2855.560479] Lustre: DEBUG MARKER: oleg219-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0000-osc-ffff9bc3467b9800.ost_server_uuid 50 [ 2857.283700] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9bc3467b9800.ost_server_uuid in IDLE state after 0 sec [ 2862.115973] Lustre: DEBUG MARKER: oleg219-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0001-osc-ffff9bc3467b9800.ost_server_uuid 50 [ 2863.237618] Lustre: DEBUG MARKER: osc.lustre-OST0001-osc-ffff9bc3467b9800.ost_server_uuid in FULL state after 0 sec [ 2864.380969] Lustre: DEBUG MARKER: == sanityn test 35: -EINTR cp_ast vs. bl_ast race does not evict client ========================================================== 16:55:36 (1788728136) [ 2866.586214] Lustre: DEBUG MARKER: Race attempt 0 [ 2869.275335] Lustre: DEBUG MARKER: Wait for 59603 59658 for 60 sec... [ 2935.419547] Lustre: DEBUG MARKER: == sanityn test 36: handle ESTALE/open-unlink correctly == 16:56:46 (1788728206) [ 2942.875967] Lustre: DEBUG MARKER: start test - cycle (0) [ 2962.651674] Lustre: DEBUG MARKER: start test - cycle (1) [ 2982.482125] Lustre: DEBUG MARKER: start test - cycle (2) [ 3004.139297] Lustre: DEBUG MARKER: start test - cycle (3) [ 3024.916881] Lustre: DEBUG MARKER: start test - cycle (4) [ 3044.213214] Lustre: DEBUG MARKER: start test - cycle (5) [ 3065.641940] Lustre: DEBUG MARKER: start test - cycle (6) [ 3070.943534] Lustre: lustre-OST0000-osc-ffff9bc3467b9800: disconnect after 20s idle [ 3070.952995] Lustre: Skipped 8 previous similar messages [ 3084.849574] Lustre: DEBUG MARKER: start test - cycle (7) [ 3105.618355] Lustre: DEBUG MARKER: start test - cycle (8) [ 3126.966193] Lustre: DEBUG MARKER: start test - cycle (9) [ 3150.574993] Lustre: DEBUG MARKER: start test - cycle (10) [ 3176.658657] Lustre: DEBUG MARKER: == sanityn test 37: check i_size is not updated for directory on close (bug 18695) ======================================================================== 17:00:48 (1788728448) [ 3230.753818] Lustre: DEBUG MARKER: == sanityn test 39a: file mtime does not change after rename ========================================================== 17:01:42 (1788728502) [ 3235.740212] Lustre: DEBUG MARKER: == sanityn test 39b: file mtime the same on clients with/out lock ========================================================== 17:01:47 (1788728507) [ 3241.191540] Lustre: DEBUG MARKER: == sanityn test 39c: check truncate mtime update ================================================================================ 17:01:52 (1788728512) [ 3246.471800] Lustre: DEBUG MARKER: == sanityn test 39d: sync write should update mtime ====== 17:01:58 (1788728518) [ 3246.675434] Lustre: *** cfs_fail_loc=411, val=0*** [ 3251.592474] Lustre: DEBUG MARKER: SKIP: sanityn test_40a skipping ALWAYS excluded test 40a [ 3252.824405] Lustre: DEBUG MARKER: == sanityn test 40b: pdirops: open|create and others ======================================================================== 17:02:04 (1788728524) [ 3266.911386] Lustre: DEBUG MARKER: == sanityn test 40c: pdirops: link and others ======================================================================== 17:02:18 (1788728538) [ 3281.249464] Lustre: DEBUG MARKER: == sanityn test 40d: pdirops: unlink and others ======================================================================== 17:02:32 (1788728552) [ 3294.611822] Lustre: DEBUG MARKER: == sanityn test 40e: pdirops: rename and others ======================================================================== 17:02:46 (1788728566) [ 3306.652978] Lustre: DEBUG MARKER: == sanityn test 41a: pdirops: create vs mkdir ======================================================================== 17:02:58 (1788728578) [ 3316.418899] Lustre: DEBUG MARKER: == sanityn test 41b: pdirops: create vs create ======================================================================== 17:03:07 (1788728587) [ 3326.234930] Lustre: DEBUG MARKER: == sanityn test 41c: pdirops: create vs link ======================================================================== 17:03:17 (1788728597) [ 3335.319445] Lustre: DEBUG MARKER: == sanityn test 41d: pdirops: create vs unlink ======================================================================== 17:03:26 (1788728606) [ 3343.979785] Lustre: DEBUG MARKER: == sanityn test 41e: pdirops: create and rename (tgt) ======================================================================== 17:03:35 (1788728615) [ 3352.991611] Lustre: DEBUG MARKER: == sanityn test 41f: pdirops: create and rename (src) ======================================================================== 17:03:44 (1788728624) [ 3362.098343] Lustre: DEBUG MARKER: == sanityn test 41g: pdirops: create vs getattr ======================================================================== 17:03:53 (1788728633) [ 3370.734254] Lustre: DEBUG MARKER: == sanityn test 41h: pdirops: create vs readdir ======================================================================== 17:04:02 (1788728642) [ 3380.349579] Lustre: DEBUG MARKER: == sanityn test 41i: reint_open: create vs create ======== 17:04:12 (1788728652) [ 3997.663249] Lustre: lustre-OST0000-osc-ffff9bc3467b9800: disconnect after 21s idle [ 3997.665940] Lustre: Skipped 11 previous similar messages [ 4229.532242] Lustre: DEBUG MARKER: == sanityn test 42a: pdirops: mkdir vs mkdir ======================================================================== 17:18:21 (1788729501) [ 4237.005660] Lustre: DEBUG MARKER: == sanityn test 42b: pdirops: mkdir vs create ======================================================================== 17:18:28 (1788729508) [ 4243.551321] Lustre: DEBUG MARKER: == sanityn test 42c: pdirops: mkdir vs link ======================================================================== 17:18:35 (1788729515) [ 4250.347180] Lustre: DEBUG MARKER: == sanityn test 42d: pdirops: mkdir vs unlink ======================================================================== 17:18:42 (1788729522) [ 4256.834850] Lustre: DEBUG MARKER: == sanityn test 42e: pdirops: mkdir and rename (tgt) ======================================================================== 17:18:48 (1788729528) [ 4263.426995] Lustre: DEBUG MARKER: == sanityn test 42f: pdirops: mkdir and rename (src) ======================================================================== 17:18:55 (1788729535) [ 4270.718851] Lustre: DEBUG MARKER: == sanityn test 42g: pdirops: mkdir vs getattr ======================================================================== 17:19:02 (1788729542) [ 4277.869502] Lustre: DEBUG MARKER: == sanityn test 42h: pdirops: mkdir vs readdir ======================================================================== 17:19:09 (1788729549) [ 4285.731644] Lustre: DEBUG MARKER: == sanityn test 43a: rmdir,mkdir doesn't return -EEXIST ======================================================================== 17:19:17 (1788729557) [ 4335.363500] Lustre: DEBUG MARKER: == sanityn test 43b: pdirops: unlink vs create ======================================================================== 17:20:07 (1788729607) [ 4341.481930] Lustre: DEBUG MARKER: == sanityn test 43c: pdirops: unlink vs link ======================================================================== 17:20:13 (1788729613) [ 4347.730540] Lustre: DEBUG MARKER: == sanityn test 43d: pdirops: unlink vs unlink ======================================================================== 17:20:19 (1788729619) [ 4354.018436] Lustre: DEBUG MARKER: == sanityn test 43e: pdirops: unlink and rename (tgt) ======================================================================== 17:20:25 (1788729625) [ 4360.355162] Lustre: DEBUG MARKER: == sanityn test 43f: pdirops: unlink and rename (src) ======================================================================== 17:20:32 (1788729632) [ 4366.530898] Lustre: DEBUG MARKER: == sanityn test 43g: pdirops: unlink vs getattr ======================================================================== 17:20:38 (1788729638) [ 4372.718524] Lustre: DEBUG MARKER: == sanityn test 43h: pdirops: unlink vs readdir ======================================================================== 17:20:44 (1788729644) [ 4378.988295] Lustre: DEBUG MARKER: == sanityn test 43i: pdirops: unlink vs remote mkdir ===== 17:20:50 (1788729650) [ 4384.918081] Lustre: DEBUG MARKER: == sanityn test 43j: racy mkdir return EEXIST ======================================================================== 17:20:56 (1788729656) [ 4437.057686] Lustre: DEBUG MARKER: == sanityn test 43k: unlink vs create ==================== 17:21:48 (1788729708) [ 4658.144164] Lustre: lustre-OST0000-osc-ffff9bc359bd9000: disconnect after 24s idle [ 4658.146548] Lustre: Skipped 7 previous similar messages [ 4928.559331] Lustre: DEBUG MARKER: == sanityn test 44a: pdirops: rename tgt vs mkdir ======================================================================== 17:30:00 (1788730200) [ 4933.813170] Lustre: DEBUG MARKER: == sanityn test 44b: pdirops: rename tgt vs create ======================================================================== 17:30:05 (1788730205) [ 4939.276198] Lustre: DEBUG MARKER: == sanityn test 44c: pdirops: rename tgt vs link ======================================================================== 17:30:11 (1788730211) [ 4944.779029] Lustre: DEBUG MARKER: == sanityn test 44d: pdirops: rename tgt vs unlink ======================================================================== 17:30:16 (1788730216) [ 4950.563709] Lustre: DEBUG MARKER: == sanityn test 44e: pdirops: rename tgt and rename (tgt) ======================================================================== 17:30:22 (1788730222) [ 4956.606913] Lustre: DEBUG MARKER: == sanityn test 44f: pdirops: rename tgt and rename (src) ======================================================================== 17:30:28 (1788730228) [ 4962.463734] Lustre: DEBUG MARKER: == sanityn test 44g: pdirops: rename tgt vs getattr ======================================================================== 17:30:34 (1788730234) [ 4968.071249] Lustre: DEBUG MARKER: == sanityn test 44h: pdirops: rename tgt vs readdir ======================================================================== 17:30:40 (1788730240) [ 4973.654894] Lustre: DEBUG MARKER: == sanityn test 44i: pdirops: rename tgt vs remote mkdir ========================================================== 17:30:45 (1788730245) [ 4979.448298] Lustre: DEBUG MARKER: == sanityn test 45a: rename,mkdir doesn't return -EEXIST ======================================================================== 17:30:51 (1788730251) [ 5031.412497] Lustre: DEBUG MARKER: == sanityn test 45b: pdirops: rename src vs create ======================================================================== 17:31:43 (1788730303) [ 5036.926700] Lustre: DEBUG MARKER: == sanityn test 45c: pdirops: rename src vs link ======================================================================== 17:31:49 (1788730309) [ 5042.298567] Lustre: DEBUG MARKER: == sanityn test 45d: pdirops: rename src vs unlink ======================================================================== 17:31:54 (1788730314) [ 5047.464872] Lustre: DEBUG MARKER: == sanityn test 45e: pdirops: rename src and rename (tgt) ======================================================================== 17:31:59 (1788730319) [ 5052.798081] Lustre: DEBUG MARKER: == sanityn test 45f: pdirops: rename src and rename (src) ======================================================================== 17:32:04 (1788730324) [ 5058.050821] Lustre: DEBUG MARKER: == sanityn test 45g: pdirops: rename src vs getattr ======================================================================== 17:32:10 (1788730330) [ 5063.442917] Lustre: DEBUG MARKER: == sanityn test 45h: pdirops: unlink vs readdir ======================================================================== 17:32:15 (1788730335) [ 5068.731677] Lustre: DEBUG MARKER: == sanityn test 45i: pdirops: rename src vs remote mkdir ========================================================== 17:32:20 (1788730340) [ 5074.384618] Lustre: DEBUG MARKER: == sanityn test 45j: read vs rename ====================== 17:32:26 (1788730346) [ 5498.681198] Lustre: DEBUG MARKER: == sanityn test 46a: pdirops: link vs mkdir ======================================================================== 17:39:30 (1788730770) [ 5503.496409] Lustre: DEBUG MARKER: == sanityn test 46b: pdirops: link vs create ======================================================================== 17:39:35 (1788730775) [ 5508.572546] Lustre: DEBUG MARKER: == sanityn test 46c: pdirops: link vs link ======================================================================== 17:39:40 (1788730780) [ 5513.500490] Lustre: DEBUG MARKER: == sanityn test 46d: pdirops: link vs unlink ======================================================================== 17:39:45 (1788730785) [ 5518.342160] Lustre: DEBUG MARKER: == sanityn test 46e: pdirops: link and rename (tgt) ======================================================================== 17:39:50 (1788730790) [ 5523.127838] Lustre: DEBUG MARKER: == sanityn test 46f: pdirops: link and rename (src) ======================================================================== 17:39:55 (1788730795) [ 5527.878378] Lustre: DEBUG MARKER: == sanityn test 46g: pdirops: link vs getattr ======================================================================== 17:40:00 (1788730800) [ 5532.640472] Lustre: DEBUG MARKER: == sanityn test 46h: pdirops: link vs readdir ======================================================================== 17:40:04 (1788730804) [ 5537.867678] Lustre: DEBUG MARKER: == sanityn test 46i: pdirops: link vs remote mkdir ======= 17:40:09 (1788730809) [ 5543.127040] Lustre: DEBUG MARKER: == sanityn test 47a: pdirops: remote mkdir vs mkdir ====== 17:40:15 (1788730815) [ 5548.411784] Lustre: DEBUG MARKER: == sanityn test 47b: pdirops: remote mkdir vs create ===== 17:40:20 (1788730820) [ 5554.335672] Lustre: DEBUG MARKER: == sanityn test 47c: pdirops: remote mkdir vs link ======= 17:40:26 (1788730826) [ 5559.130287] Lustre: DEBUG MARKER: == sanityn test 47d: pdirops: remote mkdir vs unlink ===== 17:40:31 (1788730831) [ 5563.837496] Lustre: DEBUG MARKER: == sanityn test 47e: pdirops: remote mkdir and rename (tgt) ========================================================== 17:40:36 (1788730836) [ 5568.724038] Lustre: DEBUG MARKER: == sanityn test 47f: pdirops: remote mkdir and rename (src) ========================================================== 17:40:40 (1788730840) [ 5573.585942] Lustre: DEBUG MARKER: == sanityn test 47g: pdirops: remote mkdir vs getattr ==== 17:40:45 (1788730845) [ 5579.743251] Lustre: lustre-OST0001-osc-ffff9bc359bd9000: disconnect after 22s idle [ 5579.745557] Lustre: Skipped 2 previous similar messages [ 5579.932776] Lustre: DEBUG MARKER: == sanityn test 50: osc lvb attrs: enqueue vs. CP AST ======================================================================== 17:40:51 (1788730851) [ 5580.026741] LustreError: 22732:0:(ldlm_lockd.c:2079:ldlm_handle_cp_callback()) cfs_fail_timeout id 410 sleeping for 2000ms [ 5582.111099] LustreError: 22732:0:(ldlm_lockd.c:2079:ldlm_handle_cp_callback()) cfs_fail_timeout id 410 awake [ 5586.965703] Lustre: DEBUG MARKER: == sanityn test 51a: layout lock: refresh layout should work ========================================================== 17:40:59 (1788730859) [ 5590.970079] Lustre: DEBUG MARKER: == sanityn test 51b: layout lock: glimpse should be able to restart if layout changed ========================================================== 17:41:03 (1788730863) [ 5591.047667] LustreError: 240710:0:(glimpse.c:206:__cl_glimpse_size()) cfs_fail_timeout id 1404 sleeping for 4000ms [ 5595.103088] LustreError: 240710:0:(glimpse.c:206:__cl_glimpse_size()) cfs_fail_timeout id 1404 awake [ 5595.108777] LustreError: 240710:0:(glimpse.c:206:__cl_glimpse_size()) cfs_fail_timeout id 1404 sleeping for 4000ms [ 5599.167100] LustreError: 240710:0:(glimpse.c:206:__cl_glimpse_size()) cfs_fail_timeout id 1404 awake [ 5599.179370] LustreError: 240717:0:(glimpse.c:206:__cl_glimpse_size()) cfs_fail_timeout id 1404 sleeping for 4000ms [ 5603.239076] LustreError: 240717:0:(glimpse.c:206:__cl_glimpse_size()) cfs_fail_timeout id 1404 awake [ 5605.508803] Lustre: DEBUG MARKER: == sanityn test 51c: layout lock: IT_LAYOUT blocked and correct layout can be returned ========================================================== 17:41:17 (1788730877) [ 5611.913178] Lustre: DEBUG MARKER: == sanityn test 51d: layout lock: losing layout lock should clean up memory map region ========================================================== 17:41:24 (1788730884) [ 5614.876092] Lustre: DEBUG MARKER: == sanityn test 51e: lfs getstripe does not break leases, part 2 ========================================================== 17:41:27 (1788730887) [ 5618.832810] Lustre: DEBUG MARKER: == sanityn test 54: rename locking ======================= 17:41:30 (1788730890) [ 5643.038710] Lustre: DEBUG MARKER: == sanityn test 55a: rename vs unlink target dir ========= 17:41:55 (1788730915) [ 5650.640574] Lustre: DEBUG MARKER: == sanityn test 55b: rename vs unlink source dir ========= 17:42:02 (1788730922) [ 5658.274808] Lustre: DEBUG MARKER: == sanityn test 55c: rename vs unlink orphan target dir == 17:42:10 (1788730930) [ 5671.263809] Lustre: DEBUG MARKER: == sanityn test 55d: rename file vs link ================= 17:42:23 (1788730943) [ 5680.831921] Lustre: DEBUG MARKER: == sanityn test 55e: rename race AB/BA under the same parent dir ========================================================== 17:42:32 (1788730952) [ 5693.875278] Lustre: DEBUG MARKER: == sanityn test 55f: rename: (P1/A -> P2/B) race with (P2/B -> P1/A) ========================================================== 17:42:45 (1788730965) [ 5706.778824] Lustre: DEBUG MARKER: == sanityn test 55g: rename: race with trylock =========== 17:42:58 (1788730978) [ 5720.511586] Lustre: DEBUG MARKER: == sanityn test 56a: test llverdev with single large stripe ========================================================== 17:43:12 (1788730992) [ 5726.851337] Lustre: DEBUG MARKER: == sanityn test 56b: test llverdev and partial verify of wide stripe file ========================================================== 17:43:19 (1788730999) [ 5754.466472] Lustre: DEBUG MARKER: == sanityn test 60: Verify data_version behaviour ======== 17:43:46 (1788731026) [ 5756.461045] Lustre: DEBUG MARKER: == sanityn test 70a: cd directory [ 5759.617780] Lustre: DEBUG MARKER: == sanityn test 70b: remove files after calling rm_entry ========================================================== 17:43:51 (1788731031) [ 5761.867486] Lustre: DEBUG MARKER: == sanityn test 71a: correct file map just after write operation is finished ========================================================== 17:43:54 (1788731034) [ 5763.973650] Lustre: DEBUG MARKER: == sanityn test 71b: check fiemap support for stripecount > 1 ========================================================== 17:43:56 (1788731036) [ 5765.867540] Lustre: DEBUG MARKER: == sanityn test 71c: check FIEMAP_EXTENT_LAST flag with different extents number ========================================================== 17:43:58 (1788731038) [ 5774.914086] Lustre: DEBUG MARKER: == sanityn test 71d: fiemap corruption test with fm_extent_count=0 ========================================================== 17:44:07 (1788731047) [ 5789.223543] Lustre: DEBUG MARKER: == sanityn test 72: getxattr/setxattr cache should be consistent between nodes ========================================================== 17:44:21 (1788731061) [ 5791.191719] Lustre: DEBUG MARKER: == sanityn test 73: getxattr should not cause xattr lock cancellation ========================================================== 17:44:23 (1788731063) [ 5793.330105] Lustre: DEBUG MARKER: == sanityn test 74: flock deadlock: different mounts ======================================================================== 17:44:25 (1788731065) [ 5796.397245] LustreError: lustre-MDT0000-mdc-ffff9bc3467b9800: operation ldlm_enqueue to node 192.168.202.119@tcp failed: rc = -35 [ 5799.234371] Lustre: DEBUG MARKER: == sanityn test 75: osc: upcall after unuse lock============================================================================= 17:44:31 (1788731071) [ 5799.362992] LustreError: 2390:0:(osc_request.c:3139:osc_enqueue_interpret()) cfs_fail_timeout id 31d sleeping for 2000ms [ 5801.447111] LustreError: 2390:0:(osc_request.c:3139:osc_enqueue_interpret()) cfs_fail_timeout id 31d awake [ 5806.382040] Lustre: DEBUG MARKER: == sanityn test 76: Verify MDT open_files listing ======== 17:44:38 (1788731078) [ 5852.296383] Lustre: DEBUG MARKER: == sanityn test 77a: check FIFO NRS policy =============== 17:45:24 (1788731124) [ 5855.349732] Lustre: DEBUG MARKER: == sanityn test 77b: check CRR-N NRS policy ============== 17:45:27 (1788731127) [ 5859.460608] Lustre: DEBUG MARKER: == sanityn test 77c: check ORR NRS policy ================ 17:45:31 (1788731131) [ 5864.669445] Lustre: DEBUG MARKER: == sanityn test 77d: check TRR nrs policy ================ 17:45:36 (1788731136) [ 5869.949937] Lustre: DEBUG MARKER: == sanityn test 77e: check TBF NID nrs policy ============ 17:45:42 (1788731142) [ 5877.620375] Lustre: DEBUG MARKER: == sanityn test 77f: check TBF JobID nrs policy ========== 17:45:49 (1788731149) [ 5885.776485] Lustre: DEBUG MARKER: == sanityn test 77g: Change TBF type directly ============ 17:45:57 (1788731157) [ 5889.313490] Lustre: DEBUG MARKER: == sanityn test 77h: Wrong policy name should report error, not LBUG ========================================================== 17:46:01 (1788731161) [ 5893.137902] Lustre: DEBUG MARKER: == sanityn test 77i: Change rank of TBF rule ============= 17:46:05 (1788731165) [ 5900.431824] Lustre: DEBUG MARKER: == sanityn test 77j: check TBF-OPCode NRS policy ========= 17:46:12 (1788731172) [ 5940.890551] Lustre: DEBUG MARKER: == sanityn test 77ja: check TBF-UID/GID NRS policy ======= 17:46:52 (1788731212) [ 6053.651486] Lustre: DEBUG MARKER: == sanityn test 77jb: check TBF-UID/GID NRS policy on files that don't belong to us ========================================================== 17:48:45 (1788731325) [ 6166.815395] Lustre: DEBUG MARKER: == sanityn test 77k: check TBF policy with UID/GID/JobID/OPCode expression ========================================================== 17:50:38 (1788731438) [ 6209.503274] Lustre: lustre-OST0001-osc-ffff9bc359bd9000: disconnect after 23s idle [ 6209.507175] Lustre: Skipped 10 previous similar messages [ 6433.790427] Lustre: DEBUG MARKER: == sanityn test 77kb: Check different granular TBF type combination: jobid+opcode ========================================================== 17:55:05 (1788731705) [ 6464.669645] Lustre: DEBUG MARKER: == sanityn test 77kc: Check different granular TBF type combination: nid+opcode ========================================================== 17:55:36 (1788731736) [ 6495.580519] Lustre: DEBUG MARKER: == sanityn test 77kd: Check different granular TBF type combination: nid+jobid ========================================================== 17:56:07 (1788731767) [ 6521.658034] Lustre: DEBUG MARKER: == sanityn test 77ke: Check different granular TBF type combination: jobid+opcode ========================================================== 17:56:33 (1788731793) [ 6582.096607] Lustre: DEBUG MARKER: == sanityn test 77kf: Check different granular TBF type combination: uid+gid ========================================================== 17:57:34 (1788731854) [ 6633.569445] Lustre: DEBUG MARKER: == sanityn test 77kg: check different granular TBF type combination: uid+opcode ========================================================== 17:58:25 (1788731905) [ 6721.035943] Lustre: DEBUG MARKER: == sanityn test 77kh: Verify that Project ID support for NRS TBF rule ========================================================== 17:59:53 (1788731993) [ 6722.096267] Lustre: Unmounted lustre-client [ 6722.800514] Lustre: Unmounted lustre-client [ 6780.354209] Lustre: Mounted lustre-client - version 2.17.57_103_g794a134 [ 6781.845661] Lustre: Mounted lustre-client - version 2.17.57_103_g794a134 [ 6782.776141] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 6838.439546] Lustre: DEBUG MARKER: == sanityn test 77ki: Add rule with unsupported TBF type should fail for generic TBF ========================================================== 18:01:50 (1788732110) [ 6846.037777] Lustre: DEBUG MARKER: == sanityn test 77kj: Verify nodemap support for NRS TBF rule ========================================================== 18:01:58 (1788732118) [ 6848.479155] Lustre: lustre-OST0000-osc-ffff9bc381495000: disconnect after 24s idle [ 6848.481169] Lustre: Skipped 11 previous similar messages [ 6932.400324] Lustre: DEBUG MARKER: == sanityn test 77l: check the output of NRS policies for generic TBF ========================================================== 18:03:24 (1788732204) [ 6935.498965] Lustre: DEBUG MARKER: == sanityn test 77m: check NRS Delay slows write RPC processing ========================================================== 18:03:27 (1788732207) [ 6985.596584] Lustre: DEBUG MARKER: == sanityn test 77n: check wildcard support for TBF JobID NRS policy ========================================================== 18:04:17 (1788732257) [ 7026.771738] Lustre: DEBUG MARKER: == sanityn test 77o: Changing rank should not panic ====== 18:04:58 (1788732298) [ 7030.893943] Lustre: DEBUG MARKER: == sanityn test 77q: Parallel TBF rule definitions should not panic ========================================================== 18:05:02 (1788732302) [ 7065.545237] Lustre: DEBUG MARKER: == sanityn test 77p: Check validity of rule names for TBF policies ========================================================== 18:05:37 (1788732337) [ 7076.031115] Lustre: DEBUG MARKER: == sanityn test 77r: Change type of tbf policy at run time ========================================================== 18:05:48 (1788732348) [ 7115.465238] Lustre: DEBUG MARKER: == sanityn test 77s: Check TBF LRU shrinker ============== 18:06:27 (1788732387) [ 7125.943815] Lustre: DEBUG MARKER: == sanityn test 78: Enable policy and specify tunings right away ========================================================== 18:06:38 (1788732398) [ 7128.566499] Lustre: DEBUG MARKER: == sanityn test 79: xattr: intent error ================== 18:06:40 (1788732400) [ 7141.406073] Lustre: DEBUG MARKER: == sanityn test 80a: migrate directory when some children is being opened ========================================================== 18:06:53 (1788732413) [ 7144.797444] Lustre: DEBUG MARKER: == sanityn test 80b: Accessing directory during migration ========================================================== 18:06:56 (1788732416) [ 7145.279073] LustreError: 314617:0:(file.c:251:ll_close_inode_openhandle()) lustre-clilmv-ffff9bc343864800: inode [0x2000013a1:0x7ba:0x0] mdc close failed: rc = -2 [ 7145.310102] LustreError: 314619:0:(lcommon_cl.c:187:cl_file_inode_init()) lustre: failed to initialize cl_object [0x240000bd0:0x40:0x0]: rc = -5 [ 7145.312967] LustreError: 314619:0:(llite_lib.c:3893:ll_prep_inode()) lustre: new_inode - fatal error: rc = -5 [ 7145.883818] LustreError: 314672:0:(lcommon_cl.c:187:cl_file_inode_init()) lustre: failed to initialize cl_object [0x240000bd0:0x48:0x0]: rc = -5 [ 7145.886890] LustreError: 314672:0:(lcommon_cl.c:187:cl_file_inode_init()) Skipped 7 previous similar messages [ 7145.889126] LustreError: 314672:0:(llite_lib.c:3893:ll_prep_inode()) lustre: new_inode - fatal error: rc = -5 [ 7145.891444] LustreError: 314672:0:(llite_lib.c:3893:ll_prep_inode()) Skipped 7 previous similar messages [ 7146.950317] LustreError: 314766:0:(lcommon_cl.c:187:cl_file_inode_init()) lustre: failed to initialize cl_object [0x240000bd0:0x77:0x0]: rc = -5 [ 7146.953644] LustreError: 314766:0:(lcommon_cl.c:187:cl_file_inode_init()) Skipped 17 previous similar messages [ 7146.955922] LustreError: 314766:0:(llite_lib.c:3893:ll_prep_inode()) lustre: new_inode - fatal error: rc = -5 [ 7146.958522] LustreError: 314766:0:(llite_lib.c:3893:ll_prep_inode()) Skipped 17 previous similar messages [ 7149.059832] LustreError: 314934:0:(lcommon_cl.c:187:cl_file_inode_init()) lustre: failed to initialize cl_object [0x240000bd0:0xcd:0x0]: rc = -5 [ 7149.062807] LustreError: 314934:0:(lcommon_cl.c:187:cl_file_inode_init()) Skipped 31 previous similar messages [ 7149.064815] LustreError: 314934:0:(llite_lib.c:3893:ll_prep_inode()) lustre: new_inode - fatal error: rc = -5 [ 7149.067871] LustreError: 314934:0:(llite_lib.c:3893:ll_prep_inode()) Skipped 31 previous similar messages [ 7153.130491] LustreError: 315272:0:(lcommon_cl.c:187:cl_file_inode_init()) lustre: failed to initialize cl_object [0x2000013a1:0x86a:0x0]: rc = -5 [ 7153.134274] LustreError: 315272:0:(lcommon_cl.c:187:cl_file_inode_init()) Skipped 65 previous similar messages [ 7153.136616] LustreError: 315272:0:(llite_lib.c:3893:ll_prep_inode()) lustre: new_inode - fatal error: rc = -5 [ 7153.139085] LustreError: 315272:0:(llite_lib.c:3893:ll_prep_inode()) Skipped 65 previous similar messages [ 7161.182800] LustreError: 316023:0:(lcommon_cl.c:187:cl_file_inode_init()) lustre: failed to initialize cl_object [0x240000bd0:0x25b:0x0]: rc = -5 [ 7161.187949] LustreError: 316023:0:(lcommon_cl.c:187:cl_file_inode_init()) Skipped 180 previous similar messages [ 7161.190769] LustreError: 316023:0:(llite_lib.c:3893:ll_prep_inode()) lustre: new_inode - fatal error: rc = -5 [ 7161.193321] LustreError: 316023:0:(llite_lib.c:3893:ll_prep_inode()) Skipped 180 previous similar messages [ 7177.243331] LustreError: 317759:0:(lcommon_cl.c:187:cl_file_inode_init()) lustre: failed to initialize cl_object [0x240000bd0:0x46e:0x0]: rc = -5 [ 7177.245994] LustreError: 317759:0:(lcommon_cl.c:187:cl_file_inode_init()) Skipped 667 previous similar messages [ 7177.248213] LustreError: 317759:0:(llite_lib.c:3893:ll_prep_inode()) lustre: new_inode - fatal error: rc = -5 [ 7177.250335] LustreError: 317759:0:(llite_lib.c:3893:ll_prep_inode()) Skipped 667 previous similar messages [ 7286.483541] LustreError: 318341:0:(lcommon_cl.c:187:cl_file_inode_init()) lustre: failed to initialize cl_object [0x2000013a1:0xc70:0x0]: rc = -5 [ 7286.487076] LustreError: 318341:0:(lcommon_cl.c:187:cl_file_inode_init()) Skipped 228 previous similar messages [ 7286.489620] LustreError: 318341:0:(llite_lib.c:3893:ll_prep_inode()) lustre: new_inode - fatal error: rc = -5 [ 7286.489747] LustreError: lustre-MDT0000-mdc-ffff9bc381495000: operation mds_getattr_lock to node 192.168.202.119@tcp failed: rc = -107 [ 7286.492068] LustreError: 318341:0:(llite_lib.c:3893:ll_prep_inode()) Skipped 228 previous similar messages [ 7286.498776] Lustre: lustre-MDT0000-mdc-ffff9bc381495000: Connection to lustre-MDT0000 (at 192.168.202.119@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 7286.506406] LustreError: lustre-MDT0000-mdc-ffff9bc381495000: This client was evicted by lustre-MDT0000; in progress operations using this service will fail. [ 7286.510373] LustreError: 318338:0:(file.c:251:ll_close_inode_openhandle()) lustre-clilmv-ffff9bc381495000: inode [0x2000013a1:0xc69:0x0] mdc close failed: rc = -108 [ 7286.515901] LustreError: 318338:0:(file.c:6167:ll_inode_revalidate_fini()) lustre: revalidate FID [0x200000007:0x1:0x0] error: rc = -108 [ 7286.525929] Lustre: lustre-MDT0000-mdc-ffff9bc381495000: Connection restored to 192.168.202.119@tcp (at 192.168.202.119@tcp) [ 7300.399117] Lustre: DEBUG MARKER: == sanityn test 81a: rename and stat under striped directory ========================================================== 18:09:32 (1788732572) [ 7302.596218] Lustre: DEBUG MARKER: == sanityn test 81b: rename under striped directory doesn't deadlock ========================================================== 18:09:34 (1788732574) [ 7346.485951] Lustre: DEBUG MARKER: == sanityn test 81c: rename revoke LOOKUP lock for remote object ========================================================== 18:10:18 (1788732618) [ 7346.975836] Lustre: DEBUG MARKER: SKIP: sanityn test_81c needs >= 4 MDTs [ 7347.562242] Lustre: DEBUG MARKER: == sanityn test 81d: parallel rename file cross-dir on same MDT ========================================================== 18:10:19 (1788732619) [ 7384.892335] Lustre: DEBUG MARKER: == sanityn test 82: fsetxattr and fgetxattr on orphan files ========================================================== 18:10:56 (1788732656) [ 7387.115378] Lustre: DEBUG MARKER: == sanityn test 83: access striped directory while it is being created/unlinked ========================================================== 18:10:59 (1788732659) [ 7509.101119] Lustre: DEBUG MARKER: == sanityn test 84: 0-nlink race in lu_object_find() ===== 18:13:01 (1788732781) [ 7516.514337] Lustre: DEBUG MARKER: == sanityn test 85: Lustre API root cache race =========== 18:13:08 (1788732788) [ 7519.414363] Lustre: DEBUG MARKER: == sanityn test 90: open/create and unlink striped directory ========================================================== 18:13:11 (1788732791) [ 7701.625620] Lustre: DEBUG MARKER: == sanityn test 91: chmod and unlink striped directory === 18:16:13 (1788732973) [ 7770.080095] Lustre: lustre-OST0000-osc-ffff9bc381495000: disconnect after 23s idle [ 7770.082642] Lustre: Skipped 8 previous similar messages [ 7883.840939] Lustre: DEBUG MARKER: == sanityn test 92: create remote directory under orphan directory ========================================================== 18:19:15 (1788733155) [ 7885.954620] Lustre: DEBUG MARKER: == sanityn test 93: alloc_rr should not allocate on same ost ========================================================== 18:19:18 (1788733158) [ 7894.815573] Lustre: DEBUG MARKER: == sanityn test 94: signal vs CP callback race =========== 18:19:26 (1788733166) [ 7894.856740] Lustre: DEBUG MARKER: write [ 7894.877630] LustreError: 289925:0:(ldlm_request.c:1533:ldlm_cli_cancel_req()) cfs_fail_timeout id 312 sleeping for 5000ms [ 7896.883226] Lustre: DEBUG MARKER: kill 381254 [ 7896.885128] LustreError: 381254:0:(ldlm_request.c:1393:ldlm_cli_cancel_local()) cfs_fail_timeout id 329 sleeping for 6000ms [ 7899.975102] LustreError: 289925:0:(ldlm_request.c:1533:ldlm_cli_cancel_req()) cfs_fail_timeout id 312 awake [ 7902.919108] LustreError: 381254:0:(ldlm_request.c:1393:ldlm_cli_cancel_local()) cfs_fail_timeout id 329 awake [ 7905.017473] Lustre: DEBUG MARKER: == sanityn test 95a: Check readpage() on a page that was removed from page cache ========================================================== 18:19:37 (1788733177) [ 7907.184982] LustreError: 381867:0:(rw.c:1865:ll_readpage()) cfs_fail_timeout id 1422 sleeping for 10000ms [ 7917.279129] LustreError: 381867:0:(rw.c:1865:ll_readpage()) cfs_fail_timeout id 1422 awake [ 7919.445551] Lustre: DEBUG MARKER: == sanityn test 95b: Check readpage() on a page that is no longer uptodate ========================================================== 18:19:51 (1788733191) [ 7919.555139] LustreError: 382454:0:(rw.c:2112:ll_readpage()) cfs_fail_timeout id 1424 sleeping for 5000ms [ 7921.639075] LustreError: 382454:0:(rw.c:2112:ll_readpage()) cfs_fail_timeout interrupted [ 7927.489541] Lustre: DEBUG MARKER: == sanityn test 100a: DoM: glimpse RPCs for stat without IO lock (DoM only file) ========================================================== 18:19:59 (1788733199) [ 7927.963795] Lustre: DEBUG MARKER: SKIP: sanityn test_100a Reserved for glimpse-ahead [ 7928.482102] Lustre: DEBUG MARKER: == sanityn test 100b: DoM: no glimpse RPC for stat with IO lock (DoM only file) ========================================================== 18:20:00 (1788733200) [ 7930.887482] Lustre: DEBUG MARKER: == sanityn test 100c: DoM: write vs stat without IO lock (combined file) ========================================================== 18:20:02 (1788733202) [ 7933.225736] Lustre: DEBUG MARKER: == sanityn test 100d: DoM: write+truncate vs stat without IO lock (combined file) ========================================================== 18:20:05 (1788733205) [ 7935.476248] Lustre: DEBUG MARKER: == sanityn test 100e: DoM: read on open and file size ==== 18:20:07 (1788733207) [ 7937.627483] Lustre: DEBUG MARKER: == sanityn test 101a: Discard DoM data on unlink ========= 18:20:09 (1788733209) [ 7939.757247] Lustre: DEBUG MARKER: == sanityn test 101b: Discard DoM data on rename ========= 18:20:11 (1788733211) [ 7941.872772] Lustre: DEBUG MARKER: == sanityn test 101c: Discard DoM data on close-unlink === 18:20:13 (1788733213) [ 7945.203180] Lustre: DEBUG MARKER: == sanityn test 102: Test open by handle of unlinked file ========================================================== 18:20:17 (1788733217) [ 7947.863286] Lustre: DEBUG MARKER: == sanityn test 103: Test size correctness with lockahead ========================================================== 18:20:19 (1788733219) [ 7948.506100] Lustre: *** cfs_fail_loc=415, val=0*** [ 7955.161550] Lustre: DEBUG MARKER: == sanityn test 104: Verify that MDS stores atime/mtime/ctime during close ========================================================== 18:20:27 (1788733227) [ 7974.140686] Lustre: DEBUG MARKER: == sanityn test 105: Glimpse and lock cancel race ======== 18:20:46 (1788733246) [ 7974.250633] LustreError: 289924:0:(osc_lock.c:435:__osc_dlm_blocking_ast()) cfs_fail_timeout id 416 sleeping for 5000ms [ 7974.252810] LustreError: 289924:0:(osc_lock.c:435:__osc_dlm_blocking_ast()) Skipped 3 previous similar messages [ 7979.343123] LustreError: 290444:0:(osc_lock.c:435:__osc_dlm_blocking_ast()) cfs_fail_timeout id 416 awake [ 7979.345322] LustreError: 290444:0:(osc_lock.c:435:__osc_dlm_blocking_ast()) Skipped 2 previous similar messages [ 7989.535101] LustreError: 294428:0:(osc_lock.c:435:__osc_dlm_blocking_ast()) cfs_fail_timeout id 416 awake [ 7989.539121] LustreError: 294428:0:(osc_lock.c:435:__osc_dlm_blocking_ast()) Skipped 5 previous similar messages [ 7991.831923] Lustre: DEBUG MARKER: == sanityn test 106a: Verify the btime via statx() ======= 18:21:03 (1788733263) [ 7994.329544] Lustre: DEBUG MARKER: == sanityn test 106b: Glimpse RPCs test for statx ======== 18:21:06 (1788733266) [ 7996.807977] Lustre: DEBUG MARKER: == sanityn test 106c: Verify statx attributes mask ======= 18:21:08 (1788733268) [ 7999.056614] Lustre: DEBUG MARKER: == sanityn test 107a: Basic grouplock conflict =========== 18:21:11 (1788733271) [ 8003.248985] Lustre: DEBUG MARKER: == sanityn test 107b: Grouplock is added to the head of waiting list ========================================================== 18:21:15 (1788733275) [ 8011.519325] Lustre: DEBUG MARKER: == sanityn test 108a: lseek: parallel updates ============ 18:21:23 (1788733283) [ 8011.653057] LustreError: 393184:0:(osc_request.c:2990:osc_build_rpc()) cfs_fail_timeout id 414 sleeping for 4000ms [ 8011.655916] LustreError: 393184:0:(osc_request.c:2990:osc_build_rpc()) Skipped 6 previous similar messages [ 8015.719198] LustreError: 393184:0:(osc_request.c:2990:osc_build_rpc()) cfs_fail_timeout id 414 awake [ 8015.721531] LustreError: 393184:0:(osc_request.c:2990:osc_build_rpc()) Skipped 1 previous similar message [ 8017.912502] Lustre: DEBUG MARKER: == sanityn test 109: Race with several mount instances on 1 node ========================================================== 18:21:30 (1788733290) [ 8019.084419] Lustre: Unmounted lustre-client [ 8019.655228] Lustre: Unmounted lustre-client [ 8020.118762] Lustre: DEBUG MARKER: Iteration 0 [ 8020.219381] LustreError: 394077:0:(llite_lib.c:1508:ll_fill_super()) cfs_race id 1417 sleeping [ 8020.222584] LustreError: 394078:0:(llite_lib.c:1508:ll_fill_super()) cfs_fail_race id 1417 waking [ 8020.224717] LustreError: 394077:0:(llite_lib.c:1508:ll_fill_super()) cfs_fail_race id 1417 awake: rc=4998 [ 8020.261392] Lustre: Mounted lustre-client - version 2.17.57_103_g794a134 [ 8020.859883] Lustre: Unmounted lustre-client [ 8021.813944] Key type lgssc unregistered [ 8021.929536] LNet: 394419:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 8021.931729] LNetError: 394419:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 8021.941842] LNet: Removed LNI 192.168.202.19@tcp [ 8022.265106] Key type .llcrypt unregistered [ 8022.266155] Key type ._llcrypt unregistered [ 8022.538172] Key type ._llcrypt registered [ 8022.539420] Key type .llcrypt registered [ 8022.784049] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [ 8022.790735] alg: No test for adler32 (adler32-zlib) [ 8023.766930] Lustre: Lustre: Build Version: 2.17.57_103_g794a134 [ 8024.061752] LNet: Added LNI 192.168.202.19@tcp [8/256/0/180] [ 8025.679162] Key type lgssc registered [ 8026.194438] Lustre: Echo OBD driver; http://www.lustre.org/ [ 8030.323779] Lustre: DEBUG MARKER: Iteration 1 [ 8030.419408] LustreError: 395245:0:(llite_lib.c:1508:ll_fill_super()) cfs_race id 1417 sleeping [ 8030.421110] LustreError: 395246:0:(llite_lib.c:1508:ll_fill_super()) cfs_fail_race id 1417 waking [ 8030.423283] LustreError: 395245:0:(llite_lib.c:1508:ll_fill_super()) cfs_fail_race id 1417 awake: rc=4998 [ 8031.466382] Lustre: Mounted lustre-client - version 2.17.57_103_g794a134 [ 8031.467712] Lustre: Skipped 1 previous similar message [ 8032.002120] Lustre: Unmounted lustre-client [ 8033.145335] Key type lgssc unregistered [ 8033.260506] LNet: 395590:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 8033.262586] LNetError: 395590:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 8033.269822] LNet: Removed LNI 192.168.202.19@tcp [ 8033.596148] Key type .llcrypt unregistered [ 8033.598192] Key type ._llcrypt unregistered [ 8033.916333] Key type ._llcrypt registered [ 8033.917191] Key type .llcrypt registered [ 8034.111722] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [ 8034.116647] alg: No test for adler32 (adler32-zlib) [ 8034.971641] Lustre: Lustre: Build Version: 2.17.57_103_g794a134 [ 8035.056212] LNet: Added LNI 192.168.202.19@tcp [8/256/0/180] [ 8036.639155] Key type lgssc registered [ 8036.998359] Lustre: Echo OBD driver; http://www.lustre.org/ [ 8040.588329] Lustre: DEBUG MARKER: Iteration 2 [ 8040.680324] LustreError: 396416:0:(llite_lib.c:1508:ll_fill_super()) cfs_race id 1417 sleeping [ 8040.680608] LustreError: 396417:0:(llite_lib.c:1508:ll_fill_super()) cfs_fail_race id 1417 waking [ 8040.685807] LustreError: 396416:0:(llite_lib.c:1508:ll_fill_super()) cfs_fail_race id 1417 awake: rc=4999 [ 8041.725626] Lustre: Mounted lustre-client - version 2.17.57_103_g794a134 [ 8041.728889] Lustre: Skipped 1 previous similar message [ 8042.212371] Lustre: Unmounted lustre-client [ 8043.131515] Key type lgssc unregistered [ 8043.242453] LNet: 396757:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 8043.245363] LNetError: 396757:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 8043.255716] LNet: Removed LNI 192.168.202.19@tcp [ 8043.472120] Key type .llcrypt unregistered [ 8043.473311] Key type ._llcrypt unregistered [ 8043.714519] Key type ._llcrypt registered [ 8043.715589] Key type .llcrypt registered [ 8043.932193] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [ 8043.938264] alg: No test for adler32 (adler32-zlib) [ 8044.787026] Lustre: Lustre: Build Version: 2.17.57_103_g794a134 [ 8044.871552] LNet: Added LNI 192.168.202.19@tcp [8/256/0/180] [ 8046.463130] Key type lgssc registered [ 8046.847887] Lustre: Echo OBD driver; http://www.lustre.org/ [ 8051.088479] Lustre: Mounted lustre-client - version 2.17.57_103_g794a134 [ 8053.381334] Lustre: DEBUG MARKER: == sanityn test 110: do not grant another lock on resend ========================================================== 18:22:05 (1788733325) [ 8070.111148] Lustre: 398094:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788733326/real 1788733326] req@ffff9bc37cd2f480 x1875622826616704/t0(0) o36->lustre-MDT0000-mdc-ffff9bc345872800@192.168.202.119@tcp:12/10 lens 496/440 e 0 to 1 dl 1788733342 ref 2 fl Rpc:XQr/200/ffffffff rc 0/-1 job:'ln.0' uid:0 gid:0 projid:4294967295 [ 8070.117738] Lustre: lustre-MDT0000-mdc-ffff9bc345872800: Connection to lustre-MDT0000 (at 192.168.202.119@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 8070.126600] Lustre: lustre-MDT0000-mdc-ffff9bc345872800: Connection restored to 192.168.202.119@tcp (at 192.168.202.119@tcp) [ 8085.471131] Lustre: 398094:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788733342/real 1788733342] req@ffff9bc37cd2f480 x1875622826616704/t0(0) o36->lustre-MDT0000-mdc-ffff9bc345872800@192.168.202.119@tcp:12/10 lens 496/440 e 0 to 1 dl 1788733358 ref 2 fl Rpc:XQr/202/ffffffff rc 0/-1 job:'ln.0' uid:0 gid:0 projid:4294967295 [ 8085.478617] Lustre: lustre-MDT0000-mdc-ffff9bc345872800: Connection to lustre-MDT0000 (at 192.168.202.119@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 8085.488462] Lustre: lustre-MDT0000-mdc-ffff9bc345872800: Connection restored to 192.168.202.119@tcp (at 192.168.202.119@tcp) [ 8101.855163] Lustre: 398094:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788733358/real 1788733358] req@ffff9bc37cd2f480 x1875622826616704/t0(0) o36->lustre-MDT0000-mdc-ffff9bc345872800@192.168.202.119@tcp:12/10 lens 496/440 e 0 to 1 dl 1788733374 ref 2 fl Rpc:XQr/202/ffffffff rc 0/-1 job:'ln.0' uid:0 gid:0 projid:4294967295 [ 8101.864575] Lustre: lustre-MDT0000-mdc-ffff9bc345872800: Connection to lustre-MDT0000 (at 192.168.202.119@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 8101.873714] Lustre: lustre-MDT0000-mdc-ffff9bc345872800: Connection restored to 192.168.202.119@tcp (at 192.168.202.119@tcp) [ 8118.239158] Lustre: 398094:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788733374/real 1788733374] req@ffff9bc37cd2f480 x1875622826616704/t0(0) o36->lustre-MDT0000-mdc-ffff9bc345872800@192.168.202.119@tcp:12/10 lens 496/440 e 0 to 1 dl 1788733390 ref 2 fl Rpc:XQr/202/ffffffff rc 0/-1 job:'ln.0' uid:0 gid:0 projid:4294967295 [ 8118.247760] Lustre: lustre-MDT0000-mdc-ffff9bc345872800: Connection to lustre-MDT0000 (at 192.168.202.119@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 8118.255824] Lustre: lustre-MDT0000-mdc-ffff9bc345872800: Connection restored to 192.168.202.119@tcp (at 192.168.202.119@tcp) [ 8118.774793] Lustre: DEBUG MARKER: == sanityn test 111: A racy rename/link an open file should not cause fs corruption ========================================================== 18:23:10 (1788733390) [ 8124.384405] Lustre: DEBUG MARKER: == sanityn test 112: update max-inherit in default LMV === 18:23:16 (1788733396) [ 8127.442389] Lustre: DEBUG MARKER: == sanityn test 113: check servers of specified fs ======= 18:23:19 (1788733399) [ 8129.479692] Lustre: DEBUG MARKER: == sanityn test 114: implicit default LMV inherit ======== 18:23:21 (1788733401) [ 8136.797051] Lustre: DEBUG MARKER: == sanityn test 115: ldiskfs doesn't check direntry for uniqueness ========================================================== 18:23:28 (1788733408) [ 8149.177161] Lustre: DEBUG MARKER: == sanityn test 116: DNE: Set default LMV layout from a remote client ========================================================== 18:23:41 (1788733421) [ 8151.455269] Lustre: DEBUG MARKER: == sanityn test 121: trunc append race =================== 18:23:43 (1788733423) [ 8151.521020] LustreError: 402867:0:(lcommon_cl.c:99:cl_setattr_ost()) cfs_fail_timeout id 1436 sleeping for 2000ms [ 8153.607124] LustreError: 402867:0:(lcommon_cl.c:99:cl_setattr_ost()) cfs_fail_timeout id 1436 awake [ 8155.621504] Lustre: DEBUG MARKER: == sanityn test 122: directory size is consistent across mounts ========================================================== 18:23:47 (1788733427) [ 8160.312366] Lustre: DEBUG MARKER: == sanityn test 200: service remains healthy while able to process request ========================================================== 18:23:52 (1788733432) [ 8177.567145] Lustre: 396948:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788733434/real 1788733434] req@ffff9bc37d776680 x1875622827662080/t0(0) o4->lustre-OST0000-osc-ffff9bc345872800@192.168.202.119@tcp:6/4 lens 4584/448 e 0 to 1 dl 1788733450 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'dd.0' uid:0 gid:0 projid:0 [ 8177.567178] Lustre: lustre-OST0000-osc-ffff9bc345872800: Connection to lustre-OST0000 (at 192.168.202.119@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 8177.574112] Lustre: 396948:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 1 previous similar message [ 8177.582861] Lustre: lustre-OST0000-osc-ffff9bc345872800: Connection restored to 192.168.202.119@tcp (at 192.168.202.119@tcp) [ 8194.015232] Lustre: 396946:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788733450/real 1788733450] req@ffff9bc37cd3b480 x1875622827662208/t0(0) o4->lustre-OST0000-osc-ffff9bc345872800@192.168.202.119@tcp:6/4 lens 4584/448 e 0 to 1 dl 1788733466 ref 2 fl Rpc:XQr/602/ffffffff rc -11/-1 job:'dd.0' uid:0 gid:0 projid:0 [ 8194.015297] Lustre: lustre-OST0000-osc-ffff9bc345872800: Connection to lustre-OST0000 (at 192.168.202.119@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 8194.028431] Lustre: 396946:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 5 previous similar messages [ 8194.042294] Lustre: lustre-OST0000-osc-ffff9bc345872800: Connection restored to 192.168.202.119@tcp (at 192.168.202.119@tcp) [ 8210.399088] Lustre: 396947:0:(client.c:2503:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1788733466/real 1788733466] req@ffff9bc3754f8e00 x1875622827661312/t0(0) o4->lustre-OST0000-osc-ffff9bc345872800@192.168.202.119@tcp:6/4 lens 4584/448 e 0 to 1 dl 1788733482 ref 2 fl Rpc:XQr/602/ffffffff rc 0/-1 job:'dd.0' uid:0 gid:0 projid:0 [ 8210.399125] Lustre: lustre-OST0000-osc-ffff9bc345872800: Connection to lustre-OST0000 (at 192.168.202.119@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 8210.407864] Lustre: 396947:0:(client.c:2503:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 8210.416768] Lustre: lustre-OST0000-osc-ffff9bc345872800: Connection restored to 192.168.202.119@tcp (at 192.168.202.119@tcp) [ 8249.419499] Lustre: DEBUG MARKER: oleg219-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0000-osc-ffff9bc345872800.ost_server_uuid 50 [ 8249.909413] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9bc345872800.ost_server_uuid in FULL state after 0 sec [ 8250.417815] Lustre: DEBUG MARKER: cleanup: ====================================================== [ 8250.949934] Lustre: DEBUG MARKER: == sanityn test complete, duration 7946 sec ============== 18:25:23 (1788733523) [ 8251.484163] Lustre: DEBUG MARKER: === sanityn: start cleanup 18:25:23 (1788733523) === [ 8309.388981] Lustre: Unmounted lustre-client [ 8310.644342] Lustre: DEBUG MARKER: === sanityn: finish cleanup 18:26:22 (1788733582) === [ 8310.968099] Lustre: Unmounted lustre-client [ 8348.582663] Key type lgssc unregistered [ 8348.709679] LNet: 406903:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [ 8348.712440] LNetError: 406903:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [ 8348.722606] LNet: Removed LNI 192.168.202.19@tcp [ 8348.998101] Key type .llcrypt unregistered [ 8348.999118] Key type ._llcrypt unregistered