[ 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 422359812 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.001013] APIC: Switch to symmetric I/O mode setup [ 0.002363] x2apic enabled [ 0.003009] Switched APIC routing to physical x2apic. [ 0.004015] kvm-guest: setup PV IPIs [ 0.006934] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.007000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.007023] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.009008] pid_max: default: 32768 minimum: 301 [ 0.010138] LSM: Security Framework initializing [ 0.011053] Yama: becoming mindful. [ 0.012037] SELinux: Initializing. [ 0.013080] *** VALIDATE selinux *** [ 0.022236] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.026894] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.028032] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.029116] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.030115] *** VALIDATE tmpfs *** [ 0.031499] *** VALIDATE proc *** [ 0.032251] *** VALIDATE cgroup *** [ 0.033012] *** VALIDATE cgroup2 *** [ 0.035185] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.036159] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.037011] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.038034] Spectre V2 : User space: Vulnerable [ 0.039010] Speculative Store Bypass: Vulnerable [ 0.042134] debug: unmapping init [mem 0xffffffffab659000-0xffffffffab660fff] [ 0.044817] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.045691] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.046027] ... version: 2 [ 0.047014] ... bit width: 48 [ 0.048014] ... generic registers: 4 [ 0.049019] ... value mask: 0000ffffffffffff [ 0.050014] ... max period: 00007fffffffffff [ 0.051012] ... fixed-purpose events: 3 [ 0.051871] ... event mask: 000000070000000f [ 0.052324] rcu: Hierarchical SRCU implementation. [ 0.054532] smp: Bringing up secondary CPUs ... [ 0.055596] x86: Booting SMP configuration: [ 0.056030] .... node #0, CPUs: #1 #2 #3 [ 0.059615] smp: Brought up 1 node, 4 CPUs [ 0.061013] smpboot: Max logical packages: 1 [ 0.062024] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.152261] node 0 deferred pages initialised in 87ms [ 0.156105] devtmpfs: initialized [ 0.158183] x86/mm: Memory block size: 128MB [ 0.160843] gcov: version magic: 0x41383552 [ 0.163367] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.167092] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.169432] pinctrl core: initialized pinctrl subsystem [ 0.172197] [ 0.172830] ************************************************************* [ 0.175014] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.177011] ** ** [ 0.180014] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.182014] ** ** [ 0.185018] ** This means that this kernel is built to expose internal ** [ 0.187013] ** IOMMU data structures, which may compromise security on ** [ 0.189016] ** your system. ** [ 0.192014] ** ** [ 0.194014] ** If you see this message and you are not debugging the ** [ 0.197020] ** kernel, report this immediately to your vendor! ** [ 0.199013] ** ** [ 0.201014] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.204012] ************************************************************* [ 0.207243] NET: Registered protocol family 16 [ 0.208434] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.211075] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.214070] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.218029] cpuidle: using governor menu [ 0.220000] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.222485] PCI: Using configuration type 1 for base access [ 0.224122] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.235049] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.237095] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.241027] cryptd: max_cpu_qlen set to 1000 [ 0.243274] ACPI: Added _OSI(Module Device) [ 0.245019] ACPI: Added _OSI(Processor Device) [ 0.247017] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.248012] ACPI: Added _OSI(Processor Aggregator Device) [ 0.253891] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.260284] ACPI: Interpreter enabled [ 0.262058] ACPI: PM: (supports S0 S3 S4 S5) [ 0.264016] ACPI: Using IOAPIC for interrupt routing [ 0.265143] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.269450] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.280119] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.282049] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.285022] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.289085] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.293443] acpiphp: Slot [2] registered [ 0.295108] acpiphp: Slot [5] registered [ 0.296099] acpiphp: Slot [6] registered [ 0.298144] acpiphp: Slot [3] registered [ 0.299172] acpiphp: Slot [4] registered [ 0.301105] acpiphp: Slot [7] registered [ 0.302098] acpiphp: Slot [8] registered [ 0.304120] acpiphp: Slot [9] registered [ 0.305106] acpiphp: Slot [10] registered [ 0.307139] acpiphp: Slot [11] registered [ 0.309100] acpiphp: Slot [12] registered [ 0.310106] acpiphp: Slot [13] registered [ 0.311141] acpiphp: Slot [14] registered [ 0.313134] acpiphp: Slot [15] registered [ 0.315103] acpiphp: Slot [16] registered [ 0.316102] acpiphp: Slot [17] registered [ 0.318128] acpiphp: Slot [18] registered [ 0.319111] acpiphp: Slot [19] registered [ 0.321131] acpiphp: Slot [20] registered [ 0.323172] acpiphp: Slot [21] registered [ 0.324116] acpiphp: Slot [22] registered [ 0.326110] acpiphp: Slot [23] registered [ 0.327175] acpiphp: Slot [24] registered [ 0.329143] acpiphp: Slot [25] registered [ 0.331108] acpiphp: Slot [26] registered [ 0.333114] acpiphp: Slot [27] registered [ 0.334131] acpiphp: Slot [28] registered [ 0.336172] acpiphp: Slot [29] registered [ 0.337127] acpiphp: Slot [30] registered [ 0.339130] acpiphp: Slot [31] registered [ 0.340065] PCI host bridge to bus 0000:00 [ 0.342022] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.344028] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.347025] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.349026] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.352029] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.355044] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.357177] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.359972] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.363043] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.368409] pci 0000:00:01.1: reg 0x20: [io 0xc120-0xc12f] [ 0.371893] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.374041] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.377022] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.379017] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.381604] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.384736] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.388064] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.391276] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.394017] pci 0000:00:02.0: reg 0x10: [io 0xc100-0xc11f] [ 0.401016] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.404458] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.408164] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.412019] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.417016] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.429017] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.438000] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.446016] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.450018] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.465021] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.475685] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.477258] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.479294] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.481258] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.482196] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.488735] iommu: Default domain type: Passthrough [ 0.490461] SCSI subsystem initialized [ 0.491215] ACPI: bus type USB registered [ 0.492139] usbcore: registered new interface driver usbfs [ 0.495125] usbcore: registered new interface driver hub [ 0.497081] usbcore: registered new device driver usb [ 0.498154] pps_core: LinuxPPS API ver. 1 registered [ 0.500012] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.503072] PTP clock support registered [ 0.505141] EDAC MC: Ver: 3.0.0 [ 0.507140] PCI: Using ACPI for IRQ routing [ 0.508785] NetLabel: Initializing [ 0.510009] NetLabel: domain hash size = 128 [ 0.511007] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.512067] NetLabel: unlabeled traffic allowed by default [ 0.515052] vgaarb: loaded [ 0.516292] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.518016] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.525334] clocksource: Switched to clocksource kvm-clock [ 0.623474] VFS: Disk quotas dquot_6.6.0 [ 0.625313] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.627845] *** VALIDATE ramfs *** [ 0.629294] *** VALIDATE hugetlbfs *** [ 0.630887] pnp: PnP ACPI init [ 0.633436] pnp: PnP ACPI: found 6 devices [ 0.655602] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.658715] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.660620] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.662675] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.665080] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.667467] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.670275] NET: Registered protocol family 2 [ 0.672620] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.677055] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.680132] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.685137] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.688612] TCP: Hash tables configured (established 65536 bind 65536) [ 0.691473] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.693794] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.696308] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.699023] NET: Registered protocol family 1 [ 0.700876] RPC: Registered named UNIX socket transport module. [ 0.702970] RPC: Registered udp transport module. [ 0.704664] RPC: Registered tcp transport module. [ 0.706518] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.709157] NET: Registered protocol family 44 [ 0.711022] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.713358] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.715372] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.717293] PCI: CLS 0 bytes, default 64 [ 0.718744] Unpacking initramfs... [ 3.384636] debug: unmapping init [mem 0xffff8acc3cc64000-0xffff8acc3ffcffff] [ 3.396181] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 3.400845] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 3.407698] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 6.443830] Initialise system trusted keyrings [ 6.446108] Key type blacklist registered [ 6.449081] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 6.482077] zbud: loaded [ 6.498295] *** VALIDATE nfs *** [ 6.500295] *** VALIDATE nfs4 *** [ 6.505289] pstore: using deflate compression [ 6.515595] Platform Keyring initialized [ 6.821849] NET: Registered protocol family 38 [ 6.823707] Key type asymmetric registered [ 6.825101] Asymmetric key parser 'x509' registered [ 6.839608] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 6.848298] io scheduler mq-deadline registered [ 6.851697] io scheduler kyber registered [ 6.855544] io scheduler bfq registered [ 6.861521] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 6.869102] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 6.876633] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 6.883878] ACPI: Power Button [PWRF] [ 6.913125] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 6.933574] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 6.958366] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 6.998138] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 7.030938] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 7.036950] Non-volatile memory driver v1.3 [ 7.039240] Linux agpgart interface v0.103 [ 7.114565] virtio_blk virtio1: [vda] 145792 512-byte logical blocks (74.6 MB/71.2 MiB) [ 7.122546] vda: detected capacity change from 0 to 74645504 [ 7.177989] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 7.192835] vdb: detected capacity change from 0 to 1073741824 [ 7.228501] libphy: Fixed MDIO Bus: probed [ 7.250153] usbcore: registered new interface driver usbserial_generic [ 7.260090] usbserial: USB Serial support registered for generic [ 7.266129] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 7.281356] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 7.291084] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 7.295720] mousedev: PS/2 mouse device common for all mice [ 7.308531] rtc_cmos 00:05: RTC can wake from S4 [ 7.313182] rtc_cmos 00:05: registered as rtc0 [ 7.318623] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 7.323803] intel_pstate: CPU model not supported [ 7.336148] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 7.352091] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 7.370177] hid: raw HID events driver (C) Jiri Kosina [ 7.373289] usbcore: registered new interface driver usbhid [ 7.375940] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 7.383032] usbhid: USB HID core driver [ 7.407756] drop_monitor: Initializing network drop monitor service [ 7.419281] Initializing XFRM netlink socket [ 7.430451] NET: Registered protocol family 10 [ 7.454530] Segment Routing with IPv6 [ 7.458320] NET: Registered protocol family 17 [ 7.462481] mpls_gso: MPLS GSO support [ 7.500183] RAS: Correctable Errors collector initialized. [ 7.507829] AVX version of gcm_enc/dec engaged. [ 7.517660] AES CTR mode by8 optimization enabled [ 7.863473] sched_clock: Marking stable (7863440636, 0)->(8743963302, -880522666) [ 7.892668] registered taskstats version 1 [ 7.898693] Loading compiled-in X.509 certificates [ 7.904862] zswap: loaded using pool lzo/zbud [ 8.038396] Key type big_key registered [ 8.098655] Key type encrypted registered [ 8.101364] ima: No TPM chip found, activating TPM-bypass! [ 8.104659] ima: Allocated hash algorithm: sha1 [ 8.107451] ima: No architecture policies found [ 8.110151] evm: Initialising EVM extended attributes: [ 8.112872] evm: security.selinux [ 8.114517] evm: security.ima [ 8.115927] evm: security.capability [ 8.117929] evm: HMAC attrs: 0x1 [ 8.121968] rtc_cmos 00:05: setting system clock to 2026-07-13 19:01:20 UTC (1783969280) [ 8.137089] debug: unmapping init [mem 0xffffffffac603000-0xffffffffac7fffff] [ 8.145104] debug: unmapping init [mem 0xffffffffab382000-0xffffffffab658fff] [ 8.158208] Write protecting the kernel read-only data: 28672k [ 8.167666] debug: unmapping init [mem 0xffffffffa9a03000-0xffffffffa9bfffff] [ 8.173888] debug: unmapping init [mem 0xffffffffaa314000-0xffffffffaa3fffff] [ 8.300374] 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) [ 8.349906] systemd[1]: Detected virtualization kvm. [ 8.351952] systemd[1]: Detected architecture x86-64. [ 8.378949] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 8.469780] systemd[1]: No hostname configured. [ 8.471476] systemd[1]: Set hostname to . [ 8.475863] random: systemd: uninitialized urandom read (16 bytes read) [ 8.480116] systemd[1]: Initializing machine ID from random generator. [ 8.660521] random: ln: uninitialized urandom read (6 bytes read) [ 9.181512] random: systemd: uninitialized urandom read (16 bytes read) [ 9.184406] systemd[1]: Listening on Journal Socket. [ OK ] Listening on Journal Socket. [ 9.198464] systemd[1]: Listening on udev Kernel Socket. [ OK ] Listening on udev Kernel Socket. [ 9.215230] systemd[1]: Started Memstrack Anylazing Service. [ OK ] Started Memstrack Anylazing Service. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Reached target Timers. Starting Apply Kernel Variables... Starting Setup Virtual Console... [ OK ] Listening on udev Control Socket. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Paths. [ OK ] Listening on Journal Socket (/dev/log). Starting Journal Service... [ OK ] Reached target Sockets. [ OK ] Reached target Swap. [ OK ] Reached target Local File Systems. Starting Create Volatile Files and Directories... [ OK ] Reached target Slices. [ OK ] Reached target Initrd Root Device. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Apply Kernel Variables. [ OK ] Started Setup Virtual Console. [ OK ] Started Create Volatile Files and Directories. Starting dracut cmdline hook... Starting Create Static Device Nodes in /dev... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started Journal Service. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 10.904188] device-mapper: uevent: version 1.0.3 [ 10.907477] device-mapper: ioctl: 4.46.0-ioctl (2022-02-22) initialised: dm-devel@redhat.com [ OK ] Started dracut pre-udev hook. Starting udev Kernel Device Manager... [ OK ] Started udev Kernel Device Manager. Starting dracut pre-trigger hook... [ OK ] Started dracut pre-trigger hook. Starting udev Coldplug all Devices... Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ 13.410703] random: fast init done [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting dracut initqueue hook... [ 13.587293] virtio_net virtio0 ens2: renamed from eth0 [ 14.040988] scsi host0: ata_piix [ 14.069465] scsi host1: ata_piix [ 14.071184] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc120 irq 14 [ 14.078492] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc128 irq 15 [ 19.648717] random: crng init done [ 19.655100] random: 7 urandom warning(s) missed due to ratelimiting [ 21.278339] dracut-initqueue[583]: RTNETLINK answers: File exists Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. Mounting /sysroot... [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. [ 24.123362] 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 target Timers. [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped dracut initqueue hook. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Sockets. [ OK ] Stopped target System Initialization. [ OK ] Stopped target Swap. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. Stopping udev Kernel Device Manager... [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped target Slices. [ OK ] Stopped target Paths. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped 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... [ 28.340408] printk: systemd: 26 output lines suppressed due to ratelimiting [ 29.786145] SELinux: Disabled at runtime. [ 29.991339] 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) [ 30.010076] systemd[1]: Detected virtualization kvm. [ 30.011857] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 31.641213] systemd[1]: initrd-switch-root.service: Succeeded. [ 31.648656] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 31.657655] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 31.666161] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 31.674434] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 31.684453] systemd[1]: Starting Journal Service... Starting Journal Service... [ 31.696693] systemd[1]: Starting Create list of required static device nodes for the current kernel... Starting Create list of required st…ce nodes for the current kernel... [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Paths. [ OK ] Created slice User and Session Slice. Starting Apply Kernel Variables... [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Reached target Slices. Mounting POSIX Message Queue File System... Activating swap /dev/disk/by-label/SWAP... [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Reached target RPC Port Mapper. [ OK ] Created slice system-serial\x2dgetty.slice. Mounting Huge Pages File System... [ OK ] Stopped target Switch Root. Starting Remount Root and Kernel File Systems... [ OK ] Listening on udev Control Socket. [ OK ] Stopped target Initrd File Systems. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Listening on udev Kernel Socket. Starting udev Coldplug all Devices... [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Listening on Process Core Dump Socket. Mounting Kernel Debug File System... [ OK ] Stopped target Initrd Root File System. [ OK ] Reached target rpc_pipefs.target. [ OK ] Created slice system-getty.slice. [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ 32.354178] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Journal Service. [ OK ] Started Apply Kernel Variables. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Mounted Huge Pages File System. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Mounted Kernel Debug File System. Starting Configure read-only root support... [ OK ] Reached target Swap. Starting Flush Journal to Persistent Storage... Starting Create Static Device Nodes in /dev... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Reached target Local File Systems (Pre). Mounting /home/green/git/lustre-release... Mounting /mnt... Starting udev Kernel Device Manager... [ OK ] Started udev Coldplug all Devices. [ OK ] Mounted /mnt. [ 33.346650] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 34.035529] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 34.058722] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 34.668278] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 34.993321] EDAC sbridge: Ver: 1.1.2 [ 39.021754] Key type dns_resolver registered [* ] A start job is running for Configur…-only root support (7s / no limit)[ 39.544808] NFS: Registering the id_resolver key type [ 39.548070] Key type id_resolver registered [ 39.551908] Key type id_legacy registered [** ] 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) [ OK ] Started Configure read-only root support. Starting Load/Save Random Seed... [ 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... [ OK ] Started Load/Save Random Seed. [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Create Volatile Files and Directories. Starting RPC Bind... Starting Update UTMP about System Boot/Shutdown... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Started dnf makecache --timer. [ OK ] Reached target Basic System. Starting Login Service... [ OK ] Started D-Bus System Message Bus. Starting Network Manager... [ OK ] Started irqbalance daemon. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Reached target Timers. Starting Restore /run/initramfs on shutdown... [ OK ] Reached target sshd-keygen.target. [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Network Manager. [ OK ] Reached target Network. Starting Dynamic System Tuning Daemon... Starting OpenSSH server daemon... Starting GSSAPI Proxy Daemon... Starting Network Manager Wait Online... [ OK ] Started 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 Serial Getty on ttyS1. [ OK ] Started Command Scheduler. [ OK ] Started Getty on tty1. [ OK ] Reached target Login Prompts. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting System Logging Service... Starting Notify NFS peers of a restart... Starting Crash recovery kernel arming... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Starting Authorization Manager... Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg140-client login: [ 58.288258] hrtimer: interrupt took 9659067 ns [ 112.026600] libcfs: loading out-of-tree module taints kernel. [ 112.127117] Key type ._llcrypt registered [ 112.161299] Key type .llcrypt registered [ 113.026523] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [ 113.043398] alg: No test for adler32 (adler32-zlib) [ 114.789439] Lustre: Lustre: Build Version: 2.17.54_162_g313aea1 [ 115.817531] LNet: Added LNI 192.168.201.40@tcp [8/256/0/180] [ 117.663285] Key type lgssc registered [ 119.712583] Lustre: Echo OBD driver; http://www.lustre.org/ [ 310.986494] Lustre: Mounted lustre-client [ 317.587662] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 334.934263] Lustre: DEBUG MARKER: oleg140-client.virtnet: executing check_logdir /tmp/testlogs/ [ 336.864170] Lustre: lustre-OST0000-osc-ffff8acc84fa3000: disconnect after 23s idle [ 342.931743] Lustre: DEBUG MARKER: oleg140-client.virtnet: executing yml_node [ 347.871888] Lustre: DEBUG MARKER: Client: 2.17.54.162 [ 351.060225] Lustre: DEBUG MARKER: MDS: 2.17.54.162 [ 354.140765] Lustre: DEBUG MARKER: OSS: 2.17.54.162 [ 356.382718] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity ============----- Mon Jul 13 15:07:06 EDT 2026 [ 378.149799] Lustre: DEBUG MARKER: - need MDS1_VERSION <= 2.16.61-1-g89cf292a8c2 (34682530 <= 34618625) for LU-18938, skip 360 [ 380.011467] Lustre: DEBUG MARKER: - need MDS1_VERSION < v2_14_55-100-g8a84c7f9c7 (34682530 < 34486116) for LU-14927, skip 0f [ 381.773481] Lustre: DEBUG MARKER: - need OST1_VERSION < v2_17_50-410-gbd8e7b9555 (34682530 < 34681754) for LU-12550, skip 216 [ 383.494874] Lustre: DEBUG MARKER: excepting tests: 225 255 256 400a 42a 42c 42b 118c 118d 407 119i 216 817 411a [ 385.341909] Lustre: DEBUG MARKER: skipping tests SLOW=no: 27m 60i 64b 68 71 135 136 230d 300o 842 51c 51e 834 [ 387.187888] Lustre: DEBUG MARKER: === sanity: start setup 15:07:38 (1783969658) === [ 393.890865] Lustre: DEBUG MARKER: oleg140-client.virtnet: executing check_config_client /mnt/lustre [ 416.443919] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 430.726683] Lustre: DEBUG MARKER: === sanity: finish setup 15:08:21 (1783969701) === [ 445.043381] Lustre: DEBUG MARKER: == sanity test 200: OST pools ============================ 15:08:35 (1783969715) [ 454.623343] Lustre: lustre-OST0000-osc-ffff8acc84fa3000: disconnect after 24s idle [ 454.634893] Lustre: Skipped 1 previous similar message [ 484.133134] Lustre: DEBUG MARKER: == sanity test 204a: Print default stripe attributes ===== 15:09:14 (1783969754) [ 493.127712] Lustre: DEBUG MARKER: == sanity test 204b: Print default stripe size and offset ========================================================== 15:09:23 (1783969763) [ 495.587138] Lustre: lustre-OST0000-osc-ffff8acc84fa3000: disconnect after 22s idle [ 502.786372] Lustre: DEBUG MARKER: == sanity test 204c: Print default stripe count and offset ========================================================== 15:09:33 (1783969773) [ 510.803336] Lustre: DEBUG MARKER: == sanity test 204d: Print default stripe count and size ========================================================== 15:09:41 (1783969781) [ 520.617308] Lustre: DEBUG MARKER: == sanity test 204e: Print raw stripe attributes ========= 15:09:50 (1783969790) [ 532.334511] Lustre: DEBUG MARKER: == sanity test 204f: Print raw stripe size and offset ==== 15:10:01 (1783969801) [ 542.745683] Lustre: DEBUG MARKER: == sanity test 204g: Print raw stripe count and offset === 15:10:13 (1783969813) [ 551.190001] Lustre: DEBUG MARKER: == sanity test 204h: Print raw stripe count and size ===== 15:10:22 (1783969822) [ 559.542868] Lustre: DEBUG MARKER: == sanity test 205a: Verify job stats ==================== 15:10:30 (1783969830) [ 574.728271] Lustre: DEBUG MARKER: Test: /home/green/git/lustre-release/lustre/utils/lfs mkdir -i 0 -c 1 /mnt/lustre/d205a.sanity [ 576.886411] Lustre: DEBUG MARKER: Using JobID environment nodelocal=id.205a.lfs.32202 [ 579.992399] Lustre: DEBUG MARKER: Test: rmdir /mnt/lustre/d205a.sanity [ 581.482890] Lustre: DEBUG MARKER: Using JobID environment nodelocal=id.205a.rmdir.31182 [ 584.438937] Lustre: DEBUG MARKER: Test: lfs mkdir -i 1 /mnt/lustre/d205a.sanity.remote [ 586.076765] Lustre: DEBUG MARKER: Using JobID environment nodelocal=id.205a.lfs.18405 [ 589.518663] Lustre: DEBUG MARKER: Test: mknod /mnt/lustre/f205a.sanity c 1 3 [ 591.955359] Lustre: DEBUG MARKER: Using JobID environment nodelocal=id.205a.mknod.8208 [ 595.010556] Lustre: DEBUG MARKER: Test: rm -f /mnt/lustre/f205a.sanity [ 597.007482] Lustre: DEBUG MARKER: Using JobID environment nodelocal=id.205a.rm.9008 [ 599.750700] Lustre: DEBUG MARKER: Test: /home/green/git/lustre-release/lustre/utils/lfs setstripe -i 0 -c 1 /mnt/lustre/f205a.sanity [ 601.547834] Lustre: DEBUG MARKER: Using JobID environment nodelocal=id.205a.lfs.15607 [ 604.316972] Lustre: DEBUG MARKER: Test: touch /mnt/lustre/f205a.sanity [ 606.150494] Lustre: DEBUG MARKER: Using JobID environment nodelocal=id.205a.touch.10293 [ 610.259668] Lustre: DEBUG MARKER: Test: dd if=/dev/zero of=/mnt/lustre/f205a.sanity bs=1M count=1 oflag=sync [ 612.514553] Lustre: DEBUG MARKER: Using JobID environment nodelocal=id.205a.dd.18484 [ 616.798549] Lustre: DEBUG MARKER: Test: dd if=/mnt/lustre/f205a.sanity of=/dev/null bs=1M count=1 iflag=direct [ 619.875870] Lustre: DEBUG MARKER: Using JobID environment nodelocal=id.205a.dd.340 [ 623.262574] Lustre: DEBUG MARKER: Test: /home/green/git/lustre-release/lustre/tests/truncate /mnt/lustre/f205a.sanity 0 [ 625.055425] Lustre: DEBUG MARKER: Using JobID environment nodelocal=id.205a.truncate.14524 [ 629.354901] Lustre: DEBUG MARKER: Test: mv -f /mnt/lustre/f205a.sanity /mnt/lustre/d205a.sanity.rename [ 631.074227] Lustre: DEBUG MARKER: Using JobID environment nodelocal=id.205a.mv.19503 [ 634.511741] Lustre: DEBUG MARKER: Test: /home/green/git/lustre-release/lustre/utils/lfs mkdir -i 0 -c 1 /mnt/lustre/d205a.sanity.expire [ 636.592246] Lustre: DEBUG MARKER: Using JobID environment nodelocal=id.205a.lfs.14971 [ 646.023643] Lustre: DEBUG MARKER: Test: touch /mnt/lustre/f205a.sanity [ 647.673164] Lustre: DEBUG MARKER: Using JobID environment USER=S.root.touch.0.oleg140-client.v [ 650.985200] Lustre: DEBUG MARKER: Test: touch /mnt/lustre/f205a.sanity [ 652.643500] Lustre: DEBUG MARKER: Using JobID environment USER=S.root.touch.0.oleg140-client.E [ 656.122809] Lustre: DEBUG MARKER: Test: touch /mnt/lustre/f205a.sanity [ 658.165348] Lustre: DEBUG MARKER: Using JobID environment session=S.root.touch.0.oleg140-client.v [ 678.087273] Lustre: DEBUG MARKER: == sanity test 205b: Verify job stats jobid and output format ========================================================== 15:12:28 (1783969948) [ 694.516700] Lustre: DEBUG MARKER: == sanity test 205c: Verify client stats format ========== 15:12:44 (1783969964) [ 704.520629] Lustre: DEBUG MARKER: == sanity test 205d: verify the format of some stats files ========================================================== 15:12:54 (1783969974) [ 723.512540] Lustre: DEBUG MARKER: == sanity test 205e: verify the output of lljobstat ====== 15:13:13 (1783969993) [ 743.763758] Lustre: DEBUG MARKER: == sanity test 205f: verify qos_ost_weights YAML format == 15:13:34 (1783970014) [ 753.401881] Lustre: DEBUG MARKER: == sanity test 205g: stress test for job_stats procfile == 15:13:44 (1783970024) [ 859.992403] Lustre: DEBUG MARKER: == sanity test 205h: check jobid xattr is stored correctly ========================================================== 15:15:30 (1783970130) [ 876.777879] Lustre: DEBUG MARKER: == sanity test 205i: check job_xattr parameter accepts and rejects values correctly ========================================================== 15:15:46 (1783970146) [ 893.337345] Lustre: DEBUG MARKER: == sanity test 205k: Verify '?' operator on job stats ==== 15:16:03 (1783970163) [ 907.102924] Lustre: DEBUG MARKER: == sanity test 205l: Verify job stats can scale ========== 15:16:17 (1783970177) [ 1047.274434] Lustre: DEBUG MARKER: == sanity test 205m: Test width parsing of job_stats ===== 15:18:37 (1783970317) [ 1072.539574] Lustre: DEBUG MARKER: == sanity test 206: fail lov_init_raid0() doesn't lbug === 15:19:03 (1783970343) [ 1073.018728] Lustre: *** cfs_fail_loc=1403, val=1*** [ 1073.023336] LustreError: 38334:0:(lcommon_cl.c:187:cl_file_inode_init()) lustre: failed to initialize cl_object [0x200000402:0x2e7:0x0]: rc = -5 [ 1073.035188] LustreError: 38334:0:(llite_lib.c:3878:ll_prep_inode()) lustre: new_inode - fatal error: rc = -5 [ 1082.312586] Lustre: DEBUG MARKER: == sanity test 207a: can refresh layout at glimpse ======= 15:19:12 (1783970352) [ 1091.934706] Lustre: DEBUG MARKER: == sanity test 207b: can refresh layout at open ========== 15:19:22 (1783970362) [ 1101.285372] Lustre: DEBUG MARKER: == sanity test 208: Exclusive open ======================= 15:19:31 (1783970371) [ 1115.103683] Lustre: lustre-OST0001-osc-ffff8acc84fa3000: disconnect after 22s idle [ 1115.111444] Lustre: Skipped 1 previous similar message [ 1115.119161] Lustre: lustre-MDT0000-mdc-ffff8acc84fa3000: Connection to lustre-MDT0000 (at 192.168.201.140@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1120.223622] Lustre: lustre-OST0000-osc-ffff8acc84fa3000: disconnect after 22s idle [ 1131.487774] Lustre: 2403:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1783970387/real 1783970387] req@ffff8acc85625180 x1870627486656256/t0(0) o400->MGC192.168.201.140@tcp@192.168.201.140@tcp:26/25 lens 224/224 e 0 to 1 dl 1783970403 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1131.530201] LustreError: MGC192.168.201.140@tcp: Connection to MGS (at 192.168.201.140@tcp) was lost; in progress operations using this service will fail [ 1140.724312] Lustre: Evicted from MGS (at 192.168.201.140@tcp) after server handle changed from 0xa8caa59ee2b8db21 to 0xa8caa59ee2bb22d6 [ 1140.743592] Lustre: MGC192.168.201.140@tcp: Connection restored to 192.168.201.140@tcp (at 192.168.201.140@tcp) [ 1140.833408] LustreError: 2401:0:(mdc_request.c:668:mdc_replay_open()) @@@ cannot properly replay without open data req@ffff8acc85625c00 x1870627486639616/t4294970627(4294970627) o101->lustre-MDT0000-mdc-ffff8acc84fa3000@192.168.201.140@tcp:12/10 lens 608/608 e 0 to 0 dl 1783970429 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'touch.0' uid:0 gid:0 projid:0 [ 1140.874504] LustreError: 2401:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff8acc85625c00 x1870627486639616/t4294970627(4294970627) o101->lustre-MDT0000-mdc-ffff8acc84fa3000@192.168.201.140@tcp:12/10 lens 608/608 e 0 to 0 dl 1783970429 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'touch.0' uid:0 gid:0 projid:0 [ 1143.276745] Lustre: lustre-MDT0000-mdc-ffff8acc84fa3000: Connection restored to 192.168.201.140@tcp (at 192.168.201.140@tcp) [ 1156.337086] Lustre: DEBUG MARKER: oleg140-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1158.393499] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1166.341141] Lustre: lustre-MDT0000-mdc-ffff8acc84fa3000: Connection to lustre-MDT0000 (at 192.168.201.140@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1181.664297] Lustre: 2404:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1783970438/real 1783970438] req@ffff8acc88d74000 x1870627486666240/t0(0) o400->MGC192.168.201.140@tcp@192.168.201.140@tcp:26/25 lens 224/224 e 0 to 1 dl 1783970454 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1181.665678] Lustre: lustre-OST0000-osc-ffff8acc84fa3000: disconnect after 22s idle [ 1181.736489] LustreError: MGC192.168.201.140@tcp: Connection to MGS (at 192.168.201.140@tcp) was lost; in progress operations using this service will fail [ 1191.930261] Lustre: Evicted from MGS (at 192.168.201.140@tcp) after server handle changed from 0xa8caa59ee2bb22d6 to 0xa8caa59ee2bb25ca [ 1191.948671] Lustre: MGC192.168.201.140@tcp: Connection restored to 192.168.201.140@tcp (at 192.168.201.140@tcp) [ 1193.199484] Lustre: 6178:0:(mgc_request.c:1899:mgc_process_log()) MGC192.168.201.140@tcp: IR log lustre-cliir failed, not fatal: rc = -2 [ 1195.810458] LustreError: 2401:0:(mdc_request.c:668:mdc_replay_open()) @@@ cannot properly replay without open data req@ffff8acc85625c00 x1870627486639616/t4294970627(4294970627) o101->lustre-MDT0000-mdc-ffff8acc84fa3000@192.168.201.140@tcp:12/10 lens 608/608 e 0 to 0 dl 1783970484 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'touch.0' uid:0 gid:0 projid:0 [ 1195.865817] LustreError: 2401:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff8acc85c37100 x1870627486664832/t8589934595(8589934595) o101->lustre-MDT0000-mdc-ffff8acc84fa3000@192.168.201.140@tcp:12/10 lens 584/608 e 0 to 0 dl 1783970484 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'multiop.0' uid:0 gid:0 projid:0 [ 1195.901321] LustreError: 2401:0:(client.c:3448:ptlrpc_replay_interpret()) Skipped 2 previous similar messages [ 1200.185335] Lustre: lustre-MDT0000-mdc-ffff8acc84fa3000: Connection restored to 192.168.201.140@tcp (at 192.168.201.140@tcp) [ 1212.901064] Lustre: DEBUG MARKER: oleg140-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1214.567541] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1226.274510] Lustre: DEBUG MARKER: == sanity test 209: read-only open/close requests should be freed promptly ========================================================== 15:21:36 (1783970496) [ 1232.609074] bash (42141): drop_caches: 3 [ 1241.059796] Lustre: lustre-OST0000-osc-ffff8acc84fa3000: disconnect after 24s idle [ 1241.075342] Lustre: Skipped 1 previous similar message [ 1246.079598] bash (42141): drop_caches: 3 [ 1257.322984] Lustre: DEBUG MARKER: == sanity test 210: lfs getstripe does not break leases == 15:22:07 (1783970527) [ 1269.780199] Lustre: DEBUG MARKER: == sanity test 212: Sendfile test ======================== 15:22:19 (1783970539) [ 1293.629358] Lustre: DEBUG MARKER: == sanity test 213: OSC lock completion and cancel race don't crash - bug 18829 ========================================================== 15:22:43 (1783970563) [ 1294.193220] LustreError: 2402:0:(osc_request.c:3157:osc_enqueue_interpret()) cfs_fail_timeout id 40f sleeping for 10000ms [ 1304.273454] LustreError: 2402:0:(osc_request.c:3157:osc_enqueue_interpret()) cfs_fail_timeout id 40f awake [ 1307.632660] Lustre: lustre-OST0000-osc-ffff8acc84fa3000: disconnect after 21s idle [ 1313.557685] Lustre: DEBUG MARKER: == sanity test 214: hash-indexed directory test - bug 20133 ========================================================== 15:23:04 (1783970584) [ 1355.625546] Lustre: DEBUG MARKER: == sanity test 215: lnet exists and has proper content - bugs 18102, 21079, 21517 ========================================================== 15:23:46 (1783970626) [ 1358.816414] Lustre: lustre-OST0000-osc-ffff8acc84fa3000: disconnect after 24s idle [ 1364.425902] Lustre: DEBUG MARKER: SKIP: sanity test_216 skipping ALWAYS excluded test 216 [ 1367.294119] Lustre: DEBUG MARKER: == sanity test 217: check lctl ping for hostnames with embedded hyphen ('-') ========================================================== 15:23:57 (1783970637) [ 1378.057405] Lustre: DEBUG MARKER: == sanity test 218: parallel read and truncate should not deadlock ========================================================== 15:24:08 (1783970648) [ 1379.993761] Lustre: DEBUG MARKER: creating a 10 Mb file [ 1473.078630] Lustre: DEBUG MARKER: starting reads [ 1476.216864] Lustre: DEBUG MARKER: truncating the file [ 1478.762349] Lustre: DEBUG MARKER: killing dd [ 1480.583164] Lustre: DEBUG MARKER: removing the temporary file [ 1488.587837] Lustre: DEBUG MARKER: == sanity test 219: LU-394: Write partial won't cause uncontiguous pages vec at LND ========================================================== 15:25:59 (1783970759) [ 1488.852199] Lustre: *** cfs_fail_loc=411, val=0*** [ 1497.957650] Lustre: DEBUG MARKER: == sanity test 220: preallocated MDS objects still used if ENOSPC from OST ========================================================== 15:26:08 (1783970768) [ 1529.183647] Lustre: DEBUG MARKER: == sanity test 221: make sure fault and truncate race to not cause OOM ========================================================== 15:26:39 (1783970799) [ 1543.574992] Lustre: DEBUG MARKER: == sanity test 222a: AGL for ls should not trigger CLIO lock failure ========================================================== 15:26:53 (1783970813) [ 1553.195653] Lustre: DEBUG MARKER: == sanity test 222b: AGL for rmdir should not trigger CLIO lock failure ========================================================== 15:27:03 (1783970823) [ 1562.767846] Lustre: DEBUG MARKER: == sanity test 223: osc reenqueue if without AGL lock granted ================================================================================= 15:27:13 (1783970833) [ 1568.744502] Lustre: lustre-OST0001-osc-ffff8acc84fa3000: disconnect after 24s idle [ 1571.595950] Lustre: DEBUG MARKER: == sanity test 224a: Don't panic on bulk IO failure ====== 15:27:22 (1783970842) [ 1571.928822] Lustre: *** cfs_fail_loc=508, val=2147483648*** [ 1571.937058] LustreError: 2397:0:(events.c:192:client_bulk_callback()) event type 1, status -5, req ffff8acc88e6ad80 desc ffff8acc85c3d000 mbits 1870627487349120 [ 1571.946281] Lustre: 2402:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has failed due to network error: [sent 1783970844/real 1783970844] req@ffff8acc88e6ad80 x1870627487349120/t4294968439(4294968439) o4->lustre-OST0000-osc-ffff8acc84fa3000@192.168.201.140@tcp:6/4 lens 488/448 e 0 to 1 dl 1783970860 ref 3 fl Bulk:ReXQU/604/0 rc 0/0 job:'dd.0' uid:0 gid:0 projid:0 [ 1571.967980] Lustre: lustre-OST0000-osc-ffff8acc84fa3000: Connection to lustre-OST0000 (at 192.168.201.140@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1571.984179] LustreError: 2402:0:(client.c:2361:ptlrpc_check_set()) @@@ bulk transfer failed 0/1048576/0 req@ffff8acc88e6ad80 x1870627487349120/t4294968439(4294968439) o4->lustre-OST0000-osc-ffff8acc84fa3000@192.168.201.140@tcp:6/4 lens 488/448 e 0 to 1 dl 1783970860 ref 3 fl Bulk:ReXQU/604/0 rc 0/0 job:'dd.0' uid:0 gid:0 projid:0 [ 1572.004661] LustreError: 2402:0:(osc_request.c:2450:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff8acc88e6ad80 x1870627487349120/t4294968439(4294968439) o4->lustre-OST0000-osc-ffff8acc84fa3000@192.168.201.140@tcp:6/4 lens 488/448 e 0 to 1 dl 1783970860 ref 3 fl Interpret:ReXQU/604/0 rc -5/0 job:'dd.0' uid:0 gid:0 projid:0 [ 1572.008050] Lustre: lustre-OST0000-osc-ffff8acc84fa3000: Connection restored to 192.168.201.140@tcp (at 192.168.201.140@tcp) [ 1582.352840] Lustre: DEBUG MARKER: == sanity test 224b: Don't panic on bulk IO failure ====== 15:27:31 (1783970851) [ 1606.098796] Lustre: DEBUG MARKER: == sanity test 224c: Don't hang if one of md lost during large bulk RPC ========================================================== 15:27:55 (1783970875) [ 1626.592063] Lustre: 2402:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1783970893/real 1783970893] req@ffff8acc85c36680 x1870627487365504/t0(0) o4->lustre-OST0000-osc-ffff8acc84fa3000@192.168.201.140@tcp:6/4 lens 488/448 e 0 to 1 dl 1783970898 ref 2 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'dd.0' uid:0 gid:0 projid:0 [ 1626.641257] Lustre: lustre-OST0000-osc-ffff8acc84fa3000: Connection to lustre-OST0000 (at 192.168.201.140@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1626.697099] Lustre: lustre-OST0000-osc-ffff8acc84fa3000: Connection restored to 192.168.201.140@tcp (at 192.168.201.140@tcp) [ 1645.356039] Lustre: DEBUG MARKER: == sanity test 224d: Don't corrupt data on bulk IO timeout ========================================================== 15:28:36 (1783970916) [ 1671.647154] Lustre: 2402:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1783970924/real 1783970924] req@ffff8acc85c35c00 x1870627487381248/t0(0) o3->lustre-OST0000-osc-ffff8acc84fa3000@192.168.201.140@tcp:6/4 lens 488/440 e 0 to 1 dl 1783970944 ref 2 fl Bulk:RXMQU/600/0 rc 0/0 job:'dd.0' uid:0 gid:0 projid:0 [ 1671.687896] Lustre: lustre-OST0000-osc-ffff8acc84fa3000: Connection to lustre-OST0000 (at 192.168.201.140@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1671.733044] LustreError: 2402:0:(client.c:2361:ptlrpc_check_set()) @@@ bulk transfer failed 0/1048576/0 req@ffff8acc85c35c00 x1870627487381248/t0(0) o3->lustre-OST0000-osc-ffff8acc84fa3000@192.168.201.140@tcp:6/4 lens 488/440 e 0 to 1 dl 1783970944 ref 2 fl Bulk:ReXMQU/600/0 rc 0/0 job:'dd.0' uid:0 gid:0 projid:0 [ 1671.744297] Lustre: lustre-OST0000-osc-ffff8acc84fa3000: Connection restored to 192.168.201.140@tcp (at 192.168.201.140@tcp) [ 1671.780536] LustreError: 2402:0:(osc_request.c:2450:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff8acc85c35c00 x1870627487381248/t0(0) o3->lustre-OST0000-osc-ffff8acc84fa3000@192.168.201.140@tcp:6/4 lens 488/440 e 0 to 1 dl 1783970944 ref 2 fl Interpret:ReXMQU/600/0 rc -5/0 job:'dd.0' uid:0 gid:0 projid:0 [ 1687.010552] Lustre: DEBUG MARKER: SKIP: sanity test_225a skipping excluded test 225a (base 225) [ 1689.784196] Lustre: DEBUG MARKER: SKIP: sanity test_225b skipping excluded test 225b (base 225) [ 1691.925548] Lustre: DEBUG MARKER: == sanity test 226a: call path2fid and fid2path on files of all type ========================================================== 15:29:22 (1783970962) [ 1700.941104] Lustre: DEBUG MARKER: == sanity test 226b: call path2fid and fid2path on files of all type under remote dir ========================================================== 15:29:31 (1783970971) [ 1709.666295] Lustre: DEBUG MARKER: == sanity test 226c: call path2fid and fid2path under remote dir with subdir mount ========================================================== 15:29:40 (1783970980) [ 1710.754814] Lustre: lustre-OST0000-osc-ffff8acc84fa3000: disconnect after 21s idle [ 1710.803332] Lustre: Mounted lustre-client [ 1717.761306] Lustre: Unmounted lustre-client [ 1720.036352] Lustre: DEBUG MARKER: == sanity test 226d: verify fid2path with -n and -fn option ========================================================== 15:29:50 (1783970990) [ 1729.141820] Lustre: DEBUG MARKER: == sanity test 226e: Verify path2fid -0 option with newline and space ========================================================== 15:30:00 (1783971000) [ 1738.059191] Lustre: DEBUG MARKER: == sanity test 227: running truncated executable does not cause OOM ========================================================== 15:30:08 (1783971008) [ 1747.858659] Lustre: DEBUG MARKER: == sanity test 228a: try to reuse idle OI blocks ========= 15:30:18 (1783971018) [ 1751.318488] Lustre: *** cfs_fail_loc=1002, val=0*** [ 1999.735731] Lustre: DEBUG MARKER: == sanity test 228b: idle OI blocks can be reused after MDT restart ========================================================== 15:34:29 (1783971269) [ 2003.685646] Lustre: *** cfs_fail_loc=1002, val=0*** [ 2130.912377] Lustre: lustre-OST0000-osc-ffff8acc84fa3000: disconnect after 23s idle [ 2130.915156] Lustre: Skipped 1 previous similar message [ 2192.357202] Lustre: lustre-MDT0000-mdc-ffff8acc84fa3000: Connection to lustre-MDT0000 (at 192.168.201.140@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 2202.609979] LustreError: MGC192.168.201.140@tcp: Connection to MGS (at 192.168.201.140@tcp) was lost; in progress operations using this service will fail [ 2202.647598] Lustre: Evicted from MGS (at 192.168.201.140@tcp) after server handle changed from 0xa8caa59ee2bb25ca to 0xa8caa59ee2d25e91 [ 2202.665303] LustreError: 2401:0:(mdc_request.c:668:mdc_replay_open()) @@@ cannot properly replay without open data req@ffff8acc85625c00 x1870627486639616/t4294970627(4294970627) o101->lustre-MDT0000-mdc-ffff8acc84fa3000@192.168.201.140@tcp:12/10 lens 608/608 e 0 to 0 dl 1783971490 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'touch.0' uid:0 gid:0 projid:0 [ 2202.666051] Lustre: MGC192.168.201.140@tcp: Connection restored to 192.168.201.140@tcp (at 192.168.201.140@tcp) [ 2252.925253] Lustre: DEBUG MARKER: == sanity test 228c: NOT shrink the last entry in OI index node to recycle idle leaf ========================================================== 15:38:43 (1783971523) [ 2256.563757] Lustre: *** cfs_fail_loc=1002, val=0*** [ 2351.072672] Lustre: lustre-OST0001-osc-ffff8acc84fa3000: disconnect after 20s idle [ 2351.089351] Lustre: Skipped 1 previous similar message [ 2637.791204] Lustre: lustre-OST0001-osc-ffff8acc84fa3000: disconnect after 20s idle [ 2637.799978] Lustre: Skipped 1 previous similar message [ 2657.446809] Lustre: DEBUG MARKER: == sanity test 229: getstripe/stat/rm/attr changes work on released files ========================================================== 15:45:28 (1783971928) [ 2666.153290] Lustre: DEBUG MARKER: == sanity test 230a: Create remote directory and files under the remote directory ========================================================== 15:45:36 (1783971936) [ 2676.137784] Lustre: DEBUG MARKER: == sanity test 230b: migrate directory =================== 15:45:46 (1783971946) [ 2747.634723] Lustre: DEBUG MARKER: == sanity test 230c: check directory accessiblity if migration failed ========================================================== 15:46:58 (1783972018) [ 2766.673213] Lustre: DEBUG MARKER: SKIP: sanity test_230d skipping SLOW test 230d [ 2769.377769] Lustre: DEBUG MARKER: == sanity test 230e: migrate mulitple local link files === 15:47:19 (1783972039) [ 2780.299117] Lustre: DEBUG MARKER: == sanity test 230f: migrate mulitple remote link files == 15:47:30 (1783972050) [ 2792.758178] Lustre: DEBUG MARKER: == sanity test 230g: migrate dir to non-exist MDT ======== 15:47:43 (1783972063) [ 2800.532884] Lustre: DEBUG MARKER: == sanity test 230h: migrate .. and root ================= 15:47:50 (1783972070) [ 2808.632588] Lustre: DEBUG MARKER: == sanity test 230i: lfs migrate -m tolerates trailing slashes ========================================================== 15:47:59 (1783972079) [ 2816.670105] Lustre: DEBUG MARKER: == sanity test 230j: DoM file data not changed after dir migration ========================================================== 15:48:07 (1783972087) [ 2825.809252] Lustre: DEBUG MARKER: == sanity test 230k: file data not changed after dir migration ========================================================== 15:48:16 (1783972096) [ 2827.295304] Lustre: DEBUG MARKER: SKIP: sanity test_230k needs >= 4 MDTs [ 2829.153750] Lustre: DEBUG MARKER: == sanity test 230l: readdir between MDTs won't crash ==== 15:48:20 (1783972100) [ 2939.002556] Lustre: DEBUG MARKER: == sanity test 230m: xattrs not changed after dir migration ========================================================== 15:50:09 (1783972209) [ 2950.330325] bash (71506): drop_caches: 3 [ 2952.328820] bash (71506): drop_caches: 3 [ 2963.441827] Lustre: DEBUG MARKER: == sanity test 230n: Dir migration with mirrored file ==== 15:50:33 (1783972233) [ 2974.650275] Lustre: DEBUG MARKER: == sanity test 230o: dir split =========================== 15:50:44 (1783972244) [ 3001.444255] Lustre: DEBUG MARKER: == sanity test 230p: dir merge =========================== 15:51:12 (1783972272) [ 3020.284617] LustreError: 73980:0:(llite_lib.c:2014:ll_update_lsm_md()) lustre: [0x200001b71:0x5b44:0x0] dir layout mismatch: [ 3020.292766] LustreError: 73980:0:(lustre_lmv.h:160:lmv_stripe_object_dump()) dump LMV: magic=0xcd20cd0 refs=1 count=1 index=0 hash=crush:0x2000003 max_inherit=0 max_inherit_rr=0 version=3 migrate_offset=0 migrate_hash=invalid:0 pool= [ 3020.326434] LustreError: 73980:0:(lustre_lmv.h:167:lmv_stripe_object_dump()) stripe[0] [0x200001b70:0x18:0x0] [ 3020.333331] LustreError: 73980:0:(lustre_lmv.h:160:lmv_stripe_object_dump()) dump LMV: magic=0xcd20cd0 refs=1 count=2 index=0 hash=crush:0x88000003 max_inherit=0 max_inherit_rr=0 version=3 migrate_offset=1 migrate_hash=crush:86000003 pool= [ 3020.359154] LustreError: 73980:0:(llite_lib.c:3878:ll_prep_inode()) lustre: new_inode - fatal error: rc = -22 [ 3039.139307] Lustre: DEBUG MARKER: == sanity test 230q: dir auto split ====================== 15:51:49 (1783972309) [ 3085.404753] Lustre: DEBUG MARKER: == sanity test 230r: migrate with too many local locks === 15:52:35 (1783972355) [ 3096.606175] Lustre: DEBUG MARKER: == sanity test 230s: lfs mkdir should return -EEXIST if target exists ========================================================== 15:52:47 (1783972367) [ 3108.795732] Lustre: DEBUG MARKER: == sanity test 230t: migrate directory with project ID set ========================================================== 15:52:59 (1783972379) [ 3119.996948] Lustre: DEBUG MARKER: == sanity test 230u: migrate directory by QOS ============ 15:53:10 (1783972390) [ 3121.853381] Lustre: DEBUG MARKER: SKIP: sanity test_230u needs >= 4 MDTs [ 3124.540584] Lustre: DEBUG MARKER: == sanity test 230v: subdir migrated to the MDT where its parent is located ========================================================== 15:53:15 (1783972395) [ 3126.899456] Lustre: DEBUG MARKER: SKIP: sanity test_230v needs >= 4 MDTs [ 3129.337971] Lustre: DEBUG MARKER: == sanity test 230w: non-recursive mode dir migration ==== 15:53:19 (1783972399) [ 3141.790593] Lustre: DEBUG MARKER: == sanity test 230x: dir migration check space =========== 15:53:31 (1783972411) [ 3170.271270] Lustre: lustre-OST0001-osc-ffff8acc84fa3000: disconnect after 22s idle [ 3170.281133] Lustre: Skipped 4 previous similar messages [ 3205.091370] Lustre: DEBUG MARKER: == sanity test 230y: unlink dir with bad hash type ======= 15:54:35 (1783972475) [ 3228.762277] Lustre: DEBUG MARKER: == sanity test 230z: resume dir migration with bad hash type ========================================================== 15:54:58 (1783972498) [ 3286.038686] Lustre: DEBUG MARKER: == sanity test 230A: dir migrate should update lmm_oi ==== 15:55:55 (1783972555) [ 3295.267496] Lustre: DEBUG MARKER: == sanity test 230B: create duplicated entries in a migrating dir ========================================================== 15:56:05 (1783972565) [ 3316.450660] Lustre: DEBUG MARKER: == sanity test 231a: checking that reading/writing of BRW RPC size results in one RPC ========================================================== 15:56:26 (1783972586) [ 3327.739251] Lustre: DEBUG MARKER: == sanity test 231b: must not assert on fully utilized OST request buffer ========================================================== 15:56:38 (1783972598) [ 3389.316306] Lustre: DEBUG MARKER: == sanity test 232a: failed lock should not block umount ========================================================== 15:57:40 (1783972660) [ 3390.589245] LustreError: lustre-OST0000-osc-ffff8acc84fa3000: operation ldlm_enqueue to node 192.168.201.140@tcp failed: rc = -12 [ 3394.406498] Lustre: Unmounted lustre-client [ 3395.110969] Lustre: Mounted lustre-client [ 3400.176606] Lustre: lustre-OST0000-osc-ffff8acc993d0000: Connection to lustre-OST0000 (at 192.168.201.140@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 3407.589568] Lustre: lustre-OST0000-osc-ffff8acc993d0000: Connection restored to 192.168.201.140@tcp (at 192.168.201.140@tcp) [ 3407.600157] Lustre: Skipped 1 previous similar message [ 3421.896421] Lustre: DEBUG MARKER: == sanity test 232b: failed data version lock should not block umount ========================================================== 15:58:12 (1783972692) [ 3427.393980] Lustre: Unmounted lustre-client [ 3427.952989] Lustre: Mounted lustre-client [ 3433.462684] Lustre: lustre-OST0000-osc-ffff8acc91a84800: Connection to lustre-OST0000 (at 192.168.201.140@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 3441.100532] Lustre: lustre-OST0000-osc-ffff8acc91a84800: Connection restored to 192.168.201.140@tcp (at 192.168.201.140@tcp) [ 3458.067159] Lustre: DEBUG MARKER: == sanity test 233a: checking that OBF of the FS root succeeds ========================================================== 15:58:48 (1783972728) [ 3464.186207] Lustre: DEBUG MARKER: == sanity test 233b: checking that OBF of the FS .lustre succeeds ========================================================== 15:58:55 (1783972735) [ 3472.856418] Lustre: DEBUG MARKER: == sanity test 234: xattr cache should not crash on ENOMEM ========================================================== 15:59:03 (1783972743) [ 3473.662953] Lustre: *** cfs_fail_loc=1405, val=0*** [ 3481.898909] Lustre: DEBUG MARKER: == sanity test 235: LU-1715: flock deadlock detection does not work properly ========================================================== 15:59:12 (1783972752) [ 3492.152665] Lustre: DEBUG MARKER: == sanity test 236: Layout swap on open unlinked file ==== 15:59:22 (1783972762) [ 3501.445033] Lustre: DEBUG MARKER: == sanity test 238: Verify linkea consistency ============ 15:59:32 (1783972772) [ 3509.949995] Lustre: DEBUG MARKER: == sanity test 239A: osp_sync test ======================= 15:59:40 (1783972780) [ 3614.577684] Lustre: DEBUG MARKER: == sanity test 239a: process invalid osp sync record correctly ========================================================== 16:01:25 (1783972885) [ 3633.314125] Lustre: DEBUG MARKER: == sanity test 239b: process osp sync record with ENOMEM error correctly ========================================================== 16:01:43 (1783972903) [ 3651.293989] Lustre: DEBUG MARKER: == sanity test 240: race between ldlm enqueue and the connection RPC (no ASSERT) ========================================================== 16:02:02 (1783972922) [ 3654.444733] Lustre: Unmounted lustre-client [ 3656.147766] Lustre: Mounted lustre-client [ 3667.750606] Lustre: DEBUG MARKER: == sanity test 241a: bio vs dio ========================== 16:02:18 (1783972938) [ 3780.418989] Lustre: DEBUG MARKER: == sanity test 241b: dio vs dio ========================== 16:04:11 (1783973051) [ 3835.461187] Lustre: DEBUG MARKER: == sanity test 242: mdt_readpage failure should not cause directory unreadable ========================================================== 16:05:06 (1783973106) [ 3836.865926] LustreError: lustre-MDT0000-mdc-ffff8acca0243000: operation mds_readpage to node 192.168.201.140@tcp failed: rc = -12 [ 3845.718713] Lustre: DEBUG MARKER: == sanity test 243: various group lock tests ============= 16:05:16 (1783973116) [ 3859.070160] Lustre: 104013:0:(file.c:3020:ll_get_grouplock()) lustre: group lock already exists with gid 97486 on [0x240000408:0x2:0x0]: rc = -22 [ 3859.080890] Lustre: 104013:0:(file.c:3095:ll_put_grouplock()) lustre: no group lock held on [0x240000408:0x2:0x0]: rc = -22 [ 3859.086855] Lustre: 104013:0:(file.c:3002:ll_get_grouplock()) lustre: group id for group lock on [0x240000408:0x2:0x0] is 0: rc = -22 [ 3859.101709] Lustre: 104013:0:(file.c:3105:ll_put_grouplock()) lustre: group lock 4294967286 doesn't match current id 3543 on [0x240000408:0x2:0x0]: rc = -22 [ 4189.763826] Lustre: 104013:0:(file.c:3095:ll_put_grouplock()) lustre: no group lock held on [0x240000408:0x9:0x0]: rc = -22 [ 4189.831240] Lustre: 104013:0:(file.c:3002:ll_get_grouplock()) lustre: group id for group lock on [0x240000408:0x9:0x0] is 0: rc = -22 [ 4199.510312] Lustre: DEBUG MARKER: == sanity test 244a: sendfile with group lock tests ====== 16:11:10 (1783973470) [ 4291.396281] Lustre: DEBUG MARKER: == sanity test 244b: multi-threaded write with group lock ========================================================== 16:12:42 (1783973562) [ 4300.447174] Lustre: DEBUG MARKER: == sanity test 245a: check mdc connection flag/data: multiple modify RPCs ========================================================== 16:12:51 (1783973571) [ 4308.297458] Lustre: DEBUG MARKER: == sanity test 245b: check osp connection flag/data: multiple modify RPCs ========================================================== 16:12:59 (1783973579) [ 4317.760703] Lustre: DEBUG MARKER: == sanity test 247a: mount subdir as fileset ============= 16:13:08 (1783973588) [ 4318.366852] Lustre: Mounted lustre-client [ 4321.600075] Lustre: Unmounted lustre-client [ 4329.480800] Lustre: DEBUG MARKER: == sanity test 247b: mount subdir that dose not exist ==== 16:13:20 (1783973600) [ 4330.077906] LustreError: 107794:0:(llite_lib.c:613:client_common_fill_super()) lustre-clilmv-ffff8acc8755b800: cannot mds_connect: rc = -2 [ 4330.134107] Lustre: Unmounted lustre-client [ 4330.136574] LustreError: 107794:0:(super25.c:178:lustre_fill_super()) llite: Unable to mount : rc = -2 [ 4336.694314] Lustre: DEBUG MARKER: == sanity test 247c: running fid2path outside subdirectory root ========================================================== 16:13:27 (1783973607) [ 4337.412683] Lustre: Mounted lustre-client [ 4339.196402] Lustre: Unmounted lustre-client [ 4345.747920] Lustre: DEBUG MARKER: == sanity test 247d: running fid2path inside subdirectory root ========================================================== 16:13:36 (1783973616) [ 4346.460591] Lustre: Mounted lustre-client [ 4348.464892] Lustre: Unmounted lustre-client [ 4355.278478] Lustre: DEBUG MARKER: == sanity test 247e: mount .. as fileset ================= 16:13:46 (1783973626) [ 4355.839501] LustreError: lustre-MDT0000-mdc-ffff8accb3508000: operation mds_get_root to node 192.168.201.140@tcp failed: rc = -22 [ 4355.848057] LustreError: 109686:0:(llite_lib.c:613:client_common_fill_super()) lustre-clilmv-ffff8accb3508000: cannot mds_connect: rc = -22 [ 4355.945042] Lustre: Unmounted lustre-client [ 4355.956212] LustreError: 109686:0:(super25.c:178:lustre_fill_super()) llite: Unable to mount : rc = -22 [ 4363.265939] Lustre: DEBUG MARKER: == sanity test 247f: mount striped or remote directory as fileset ========================================================== 16:13:54 (1783973634) [ 4365.886208] Lustre: Mounted lustre-client [ 4368.178156] Lustre: Unmounted lustre-client [ 4371.108247] Lustre: Mounted lustre-client [ 4371.109867] Lustre: Skipped 1 previous similar message [ 4386.563331] Lustre: DEBUG MARKER: == sanity test 247g: striped directory submount revalidate ROOT from cache ========================================================== 16:14:17 (1783973657) [ 4387.396635] Lustre: Mounted lustre-client [ 4387.399528] Lustre: Skipped 2 previous similar messages [ 4396.121281] Lustre: Unmounted lustre-client [ 4396.124084] Lustre: Skipped 4 previous similar messages [ 4398.485856] Lustre: DEBUG MARKER: == sanity test 247h: remote directory submount revalidate ROOT from cache ========================================================== 16:14:28 (1783973668) [ 4403.844791] Lustre: Mounted lustre-client [ 4403.848608] Lustre: Skipped 1 previous similar message [ 4414.613447] Lustre: DEBUG MARKER: == sanity test 248a: fast read verification ============== 16:14:45 (1783973685) [ 4547.720462] Lustre: DEBUG MARKER: == sanity test 248b: test short_io read and write for both small and large sizes ========================================================== 16:16:58 (1783973818) [ 4601.181152] Lustre: DEBUG MARKER: == sanity test 248c: verify whole file read behavior ===== 16:17:52 (1783973872) [ 4629.442780] Lustre: DEBUG MARKER: == sanity test 248d: fast read serves tiny reads from cache without failures ========================================================== 16:18:19 (1783973899) [ 4639.262880] Lustre: DEBUG MARKER: == sanity test 249: Write above 2T file size ============= 16:18:29 (1783973909) [ 4648.127346] Lustre: DEBUG MARKER: == sanity test 250: Write above 16T limit ================ 16:18:39 (1783973919) [ 4656.041941] Lustre: DEBUG MARKER: == sanity test 251a: Handling short read and write correctly ========================================================== 16:18:46 (1783973926) [ 4658.090622] Lustre: *** cfs_fail_loc=1407, val=0*** [ 4666.089144] Lustre: DEBUG MARKER: == sanity test 252: check lr_reader tool ================= 16:18:57 (1783973937) [ 4680.828324] Lustre: DEBUG MARKER: == sanity test 253: Check object allocation limit ======== 16:19:11 (1783973951) [ 4795.313920] Lustre: DEBUG MARKER: == sanity test 254: Check changelog size ================= 16:21:05 (1783974065) [ 4819.187536] Lustre: DEBUG MARKER: SKIP: sanity test_255a skipping excluded test 255a (base 255) [ 4821.070622] Lustre: DEBUG MARKER: SKIP: sanity test_255b skipping excluded test 255b (base 255) [ 4822.824553] Lustre: DEBUG MARKER: SKIP: sanity test_255c skipping excluded test 255c (base 255) [ 4824.825286] Lustre: DEBUG MARKER: SKIP: sanity test_256 skipping excluded test 256 [ 4826.585537] Lustre: DEBUG MARKER: == sanity test 257: xattr locks are not lost ============= 16:21:37 (1783974097) [ 4829.028591] LustreError: lustre-MDT0001-mdc-ffff8acca0243000: operation ldlm_enqueue to node 192.168.201.140@tcp failed: rc = -14 [ 4834.294219] Lustre: lustre-MDT0001-mdc-ffff8acca0243000: Connection to lustre-MDT0001 (at 192.168.201.140@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 4852.201175] Lustre: lustre-MDT0001-mdc-ffff8acca0243000: Connection restored to 192.168.201.140@tcp (at 192.168.201.140@tcp) [ 4867.542290] Lustre: DEBUG MARKER: == sanity test 258a: verify i_mutex security behavior when suid attributes is set ========================================================== 16:22:18 (1783974138) [ 4875.883163] Lustre: DEBUG MARKER: == sanity test 258b: verify i_mutex security behavior ==== 16:22:26 (1783974146) [ 4884.131131] Lustre: DEBUG MARKER: == sanity test 259: crash at delayed truncate ============ 16:22:34 (1783974154) [ 4910.054929] Lustre: lustre-OST0000-osc-ffff8acca0243000: Connection to lustre-OST0000 (at 192.168.201.140@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 4943.199497] Lustre: DEBUG MARKER: == sanity test 260: Check mdc_close fail ================= 16:23:33 (1783974213) [ 4943.577204] Lustre: *** cfs_fail_loc=806, val=0*** [ 4943.580314] Lustre: 124146:0:(mdc_request.c:919:mdc_close()) lustre-MDT0000-mdc-ffff8acca0243000: close of FID [0x200001b74:0x45:0x0] failed, file reference will be dropped when this client unmounts or is evicted [ 4943.595921] LustreError: 124146:0:(file.c:251:ll_close_inode_openhandle()) lustre-clilmv-ffff8acca0243000: inode [0x200001b74:0x45:0x0] mdc close failed: rc = -12 [ 4951.060978] Lustre: DEBUG MARKER: == sanity test 270a: DoM: basic functionality tests ====== 16:23:41 (1783974221) [ 4971.126628] Lustre: DEBUG MARKER: == sanity test 270b: DoM: maximum size overflow checks for DoM-only file ========================================================== 16:24:01 (1783974241) [ 4980.600407] Lustre: DEBUG MARKER: == sanity test 270c: DoM: DoM EA inheritance tests ======= 16:24:11 (1783974251) [ 4989.642886] Lustre: DEBUG MARKER: == sanity test 270d: DoM: change striping from DoM to RAID0 ========================================================== 16:24:19 (1783974259) [ 4997.763885] Lustre: DEBUG MARKER: == sanity test 270e: DoM: lfs find with DoM files test === 16:24:28 (1783974268) [ 5008.090710] Lustre: DEBUG MARKER: == sanity test 270f: DoM: maximum DoM stripe size checks ========================================================== 16:24:39 (1783974279) [ 5029.215197] Lustre: DEBUG MARKER: == sanity test 270g: DoM: default DoM stripe size depends on free space ========================================================== 16:24:59 (1783974299) [ 5061.456317] Lustre: DEBUG MARKER: == sanity test 270h: DoM: DoM stripe removal when disabled on server ========================================================== 16:25:32 (1783974332) [ 5073.718408] Lustre: DEBUG MARKER: == sanity test 270i: DoM: setting invalid DoM striping should fail ========================================================== 16:25:44 (1783974344) [ 5081.429357] Lustre: DEBUG MARKER: == sanity test 270j: DoM migration: DOM file to the OST-striped file (plain) ========================================================== 16:25:52 (1783974352) [ 5090.918506] Lustre: DEBUG MARKER: == sanity test 271a: DoM: data is cached for read after write ========================================================== 16:26:01 (1783974361) [ 5099.194946] Lustre: DEBUG MARKER: == sanity test 271b: DoM: no glimpse RPC for stat (DoM only file) ========================================================== 16:26:09 (1783974369) [ 5108.427399] Lustre: DEBUG MARKER: == sanity test 271ba: DoM: no glimpse RPC for stat (combined file) ========================================================== 16:26:19 (1783974379) [ 5117.201352] Lustre: DEBUG MARKER: == sanity test 271c: DoM: IO lock at open saves enqueue RPCs ========================================================== 16:26:28 (1783974388) [ 5269.766852] Lustre: DEBUG MARKER: == sanity test 271d: DoM: read on open (1K file in reply buffer) ========================================================== 16:29:00 (1783974540) [ 5278.240685] Lustre: DEBUG MARKER: == sanity test 271f: DoM: read on open (200K file and read tail) ========================================================== 16:29:09 (1783974549) [ 5289.859301] Lustre: DEBUG MARKER: == sanity test 271g: Discard DoM data vs client flush race ========================================================== 16:29:19 (1783974559) [ 5291.324499] Lustre: *** cfs_fail_loc=314, val=0*** [ 5304.937566] Lustre: DEBUG MARKER: == sanity test 272a: DoM migration: new layout with the same DOM component ========================================================== 16:29:35 (1783974575) [ 5316.684481] Lustre: DEBUG MARKER: == sanity test 272b: DoM migration: DOM file to the OST-striped file (plain) ========================================================== 16:29:46 (1783974586) [ 5329.551683] Lustre: DEBUG MARKER: == sanity test 272c: DoM migration: DOM file to the OST-striped file (composite) ========================================================== 16:30:00 (1783974600) [ 5343.358675] Lustre: DEBUG MARKER: == sanity test 272d: DoM mirroring: OST-striped mirror to DOM file ========================================================== 16:30:13 (1783974613) [ 5347.486173] LustreError: 137953:0:(file.c:251:ll_close_inode_openhandle()) lustre-clilmv-ffff8acca0243000: inode [0x240000408:0x817:0x0] mdc close failed: rc = -22 [ 5358.800621] Lustre: DEBUG MARKER: == sanity test 272e: DoM mirroring: DOM mirror to the OST-striped file ========================================================== 16:30:29 (1783974629) [ 5361.597223] LustreError: 138571:0:(file.c:251:ll_close_inode_openhandle()) lustre-clilmv-ffff8acca0243000: inode [0x200001b74:0x90:0x0] mdc close failed: rc = -22 [ 5369.242421] Lustre: DEBUG MARKER: == sanity test 272f: DoM migration: OST-striped file to DOM file ========================================================== 16:30:39 (1783974639) [ 5371.389382] LustreError: 139174:0:(file.c:251:ll_close_inode_openhandle()) lustre-clilmv-ffff8acca0243000: inode [0x240000408:0x81b:0x0] mdc close failed: rc = -22 [ 5378.401624] Lustre: DEBUG MARKER: == sanity test 273a: DoM: layout swapping should fail with DOM ========================================================== 16:30:48 (1783974648) [ 5387.659759] Lustre: DEBUG MARKER: == sanity test 273b: DoM: race writeback and object destroy ========================================================== 16:30:58 (1783974658) [ 5399.360674] Lustre: DEBUG MARKER: == sanity test 273c: race writeback and object destroy === 16:31:10 (1783974670) [ 5410.622701] Lustre: DEBUG MARKER: == sanity test 275: Read on a canceled duplicate lock ==== 16:31:21 (1783974681) [ 5412.075057] LustreError: 93197:0:(ldlm_lockd.c:2890:ldlm_bl_thread_blwi()) cfs_fail_timeout id 31f sleeping for 4000ms [ 5415.648057] LustreError: 93197:0:(ldlm_lockd.c:2890:ldlm_bl_thread_blwi()) cfs_fail_timeout interrupted [ 5422.269398] Lustre: DEBUG MARKER: == sanity test 276: Race between mount and obd_statfs ==== 16:31:32 (1783974692) [ 5568.657373] Lustre: DEBUG MARKER: == sanity test 277: Direct IO shall drop page cache ====== 16:33:58 (1783974838) [ 5577.399647] Lustre: DEBUG MARKER: == sanity test 278: Race starting MDS between MDTs stop/start ========================================================== 16:34:08 (1783974848) [ 5580.774806] Lustre: lustre-MDT0000-mdc-ffff8acca0243000: Connection to lustre-MDT0000 (at 192.168.201.140@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 5596.137319] LustreError: MGC192.168.201.140@tcp: Connection to MGS (at 192.168.201.140@tcp) was lost; in progress operations using this service will fail [ 5596.176554] Lustre: Evicted from MGS (at 192.168.201.140@tcp) after server handle changed from 0xa8caa59ee2f60890 to 0xa8caa59ee300d6ee [ 5596.191239] Lustre: MGC192.168.201.140@tcp: Connection restored to 192.168.201.140@tcp (at 192.168.201.140@tcp) [ 5611.589895] LustreError: 2401:0:(client.c:3448:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff8accb2b25f80 x1870627540804608/t17179944553(17179944553) o101->lustre-MDT0000-mdc-ffff8acca0243000@192.168.201.140@tcp:12/10 lens 584/608 e 0 to 0 dl 1783974899 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'touch.0' uid:0 gid:0 projid:0 [ 5611.638056] LustreError: 2401:0:(client.c:3448:ptlrpc_replay_interpret()) Skipped 2 previous similar messages [ 5617.656676] Lustre: lustre-MDT0001-mdc-ffff8acca0243000: Connection restored to 192.168.201.140@tcp (at 192.168.201.140@tcp) [ 5634.043404] Lustre: DEBUG MARKER: == sanity test 280: Race between MGS umount and client llog processing ========================================================== 16:35:04 (1783974904) [ 5636.489832] Lustre: Unmounted lustre-client [ 5636.495922] Lustre: Skipped 2 previous similar messages [ 5657.055413] Lustre: 145956:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1783974913/real 1783974913] req@ffff8acc9f684700 x1870627544610432/t0(0) o502->MGC192.168.201.140@tcp@192.168.201.140@tcp:26/25 lens 272/8472 e 0 to 1 dl 1783974929 ref 2 fl Rpc:XQr/200/ffffffff rc 0/-1 job:'llog_process_th.0' uid:0 gid:0 projid:4294967295 [ 5657.098521] LustreError: MGC192.168.201.140@tcp: Connection to MGS (at 192.168.201.140@tcp) was lost; in progress operations using this service will fail [ 5657.125251] LustreError: MGC192.168.201.140@tcp: Confguration from log lustre-client failed from MGS -5. Communication error between node & MGS, a bad configuration, or other errors. See syslog for more info [ 5657.145688] Lustre: Evicted from MGS (at 192.168.201.140@tcp) after server handle changed from 0xa8caa59ee300db78 to 0xa8caa59ee300dd38 [ 5657.168896] Lustre: MGC192.168.201.140@tcp: Connection restored to 192.168.201.140@tcp (at 192.168.201.140@tcp) [ 5657.178273] Lustre: Skipped 1 previous similar message [ 5657.205841] Lustre: Unmounted lustre-client [ 5657.228398] LustreError: 145937:0:(super25.c:178:lustre_fill_super()) llite: Unable to mount : rc = -5 [ 5680.686130] Lustre: Mounted lustre-client [ 5690.431561] Lustre: DEBUG MARKER: == sanity test 300a: basic striped dir sanity test ======= 16:36:00 (1783974960) [ 5704.265665] Lustre: DEBUG MARKER: == sanity test 300b: check ctime/mtime for striped dir === 16:36:13 (1783974973) [ 5740.398717] Lustre: DEBUG MARKER: == sanity test 300c: chown [ 5956.842865] Lustre: DEBUG MARKER: == sanity test 300d: check default stripe under striped directory ========================================================== 16:40:27 (1783975227) [ 5968.237061] Lustre: DEBUG MARKER: == sanity test 300e: check rename under striped directory ========================================================== 16:40:38 (1783975238) [ 5980.046731] Lustre: DEBUG MARKER: == sanity test 300f: check rename cross striped directory ========================================================== 16:40:50 (1783975250) [ 5990.479564] Lustre: DEBUG MARKER: == sanity test 300g: check default striped directory for normal directory ========================================================== 16:41:01 (1783975261) [ 6014.426725] Lustre: DEBUG MARKER: == sanity test 300h: check default striped directory for striped directory ========================================================== 16:41:25 (1783975285) [ 6036.060592] Lustre: DEBUG MARKER: == sanity test 300i: client handle unknown hash type striped directory ========================================================== 16:41:45 (1783975305) [ 6039.332549] Lustre: Unmounted lustre-client [ 6039.998507] Lustre: Mounted lustre-client [ 6041.454822] Lustre: *** cfs_fail_loc=1901, val=99*** [ 6041.511605] Lustre: *** cfs_fail_loc=1901, val=99*** [ 6042.546677] Lustre: *** cfs_fail_loc=1901, val=99*** [ 6042.553851] Lustre: Skipped 1 previous similar message [ 6071.602858] Lustre: Unmounted lustre-client [ 6072.181274] Lustre: Mounted lustre-client [ 6080.547323] Lustre: DEBUG MARKER: == sanity test 300j: test large update record ============ 16:42:31 (1783975351) [ 6088.878611] Lustre: DEBUG MARKER: == sanity test 300k: test large striped directory ======== 16:42:39 (1783975359) [ 6098.380257] Lustre: DEBUG MARKER: == sanity test 300l: non-root user to create dir under striped dir with stale layout ========================================================== 16:42:49 (1783975369) [ 6108.794748] Lustre: DEBUG MARKER: == sanity test 300m: setstriped directory on single MDT FS ========================================================== 16:42:59 (1783975379) [ 6111.020622] Lustre: DEBUG MARKER: SKIP: sanity test_300m Only for single MDT [ 6112.995798] Lustre: DEBUG MARKER: == sanity test 300n: non-root user to create dir under striped dir with default EA ========================================================== 16:43:03 (1783975383) [ 6128.968846] Lustre: DEBUG MARKER: == sanity test 300ne: create remote dir with various mdt.enable_remote_gid ========================================================== 16:43:19 (1783975399) [ 6159.970819] Lustre: DEBUG MARKER: SKIP: sanity test_300o skipping SLOW test 300o [ 6161.963393] Lustre: DEBUG MARKER: == sanity test 300p: create striped directory without space ========================================================== 16:43:52 (1783975432) [ 6172.011446] Lustre: DEBUG MARKER: == sanity test 300q: create remote directory under orphan directory ========================================================== 16:44:02 (1783975442) [ 6181.169913] Lustre: DEBUG MARKER: == sanity test 300r: test -1 striped directory =========== 16:44:12 (1783975452) [ 6188.650548] Lustre: DEBUG MARKER: == sanity test 300s: test lfs mkdir -c without -i ======== 16:44:19 (1783975459) [ 6197.553251] Lustre: DEBUG MARKER: == sanity test 300t: test max_mdt_stripecount ============ 16:44:28 (1783975468) [ 6211.617630] Lustre: DEBUG MARKER: == sanity test 300ua: basic overstriped dir sanity test == 16:44:42 (1783975482) [ 6223.507958] Lustre: DEBUG MARKER: == sanity test 300ub: test MDT overstriping interface [ 6232.533064] Lustre: DEBUG MARKER: == sanity test 300uc: test MDT overstriping as default [ 6240.030715] Lustre: DEBUG MARKER: == sanity test 300ud: dir split ========================== 16:45:11 (1783975511) [ 6360.762534] Lustre: DEBUG MARKER: == sanity test 300ue: dir merge ========================== 16:47:11 (1783975631) [ 6450.792624] Lustre: DEBUG MARKER: == sanity test 300uf: migrate with too many local locks == 16:48:41 (1783975721) [ 6450.982379] Lustre: DEBUG MARKER: touch/create [ 6451.544114] Lustre: DEBUG MARKER: hardlinks [ 6452.306605] Lustre: DEBUG MARKER: cancel lru [ 6452.417445] Lustre: DEBUG MARKER: migrate [ 6460.332939] Lustre: DEBUG MARKER: == sanity test 300ug: migrate overstriped dirs =========== 16:48:51 (1783975731) [ 6473.519774] Lustre: DEBUG MARKER: == sanity test 300uh: overstripe tunable max_stripes_per_mdt ========================================================== 16:49:03 (1783975743) [ 6485.576320] Lustre: DEBUG MARKER: == sanity test 300ui: overstripe is not supported on one MDT system ========================================================== 16:49:16 (1783975756) [ 6487.432855] Lustre: DEBUG MARKER: SKIP: sanity test_300ui 1 MDT only [ 6489.361303] Lustre: DEBUG MARKER: == sanity test 300uj: overstriped dir with -C -N sanity test ========================================================== 16:49:20 (1783975760) [ 6498.206708] Lustre: DEBUG MARKER: == sanity test 310a: open unlink remote file ============= 16:49:29 (1783975769) [ 6507.234704] Lustre: DEBUG MARKER: == sanity test 310b: unlink remote file with multiple links while open ========================================================== 16:49:37 (1783975777) [ 6516.107769] Lustre: DEBUG MARKER: == sanity test 310c: open-unlink remote file with multiple links ========================================================== 16:49:46 (1783975786) [ 6518.535560] Lustre: DEBUG MARKER: SKIP: sanity test_310c needs >= 4 MDTs [ 6520.748538] Lustre: DEBUG MARKER: == sanity test 311: disable OSP precreate, and unlink should destroy objs ========================================================== 16:49:51 (1783975791) [ 6570.769905] Lustre: DEBUG MARKER: == sanity test 312: make sure ZFS adjusts its block size by write pattern ========================================================== 16:50:41 (1783975841) [ 6572.946636] Lustre: DEBUG MARKER: SKIP: sanity test_312 the test only applies to zfs [ 6575.296311] Lustre: DEBUG MARKER: == sanity test 313: io should fail after last_rcvd update fail ========================================================== 16:50:45 (1783975845) [ 6586.271496] Lustre: DEBUG MARKER: == sanity test 314: OSP shouldn't fail after last_rcvd update failure ========================================================== 16:50:57 (1783975857) [ 6612.541753] Lustre: DEBUG MARKER: == sanity test 315: read should be accounted ============= 16:51:23 (1783975883) [ 6630.759322] Lustre: DEBUG MARKER: == sanity test 316: lfs migrate of file with large_xattr enabled ========================================================== 16:51:41 (1783975901) [ 6639.858410] Lustre: DEBUG MARKER: == sanity test 317: Verify blocks get correctly update after truncate ========================================================== 16:51:50 (1783975910) [ 6650.363973] Lustre: DEBUG MARKER: == sanity test 318: Verify async readahead tunables ====== 16:52:00 (1783975920) [ 6651.007659] LustreError: 175197:0:(lproc_llite.c:1876:read_ahead_async_file_threshold_mb_store()) lustre: can't set read_ahead_async_file_threshold_mb=65 > max_read_readahead_per_file_mb=64 [ 6658.249426] Lustre: DEBUG MARKER: == sanity test 319: lost lease lock on migrate error ===== 16:52:08 (1783975928) [ 6658.806221] LustreError: 175782:0:(ldlm_request.c:1804:ldlm_cli_cancel()) cfs_fail_timeout id 32c sleeping for 5000ms [ 6663.839186] LustreError: 175782:0:(ldlm_request.c:1804:ldlm_cli_cancel()) cfs_fail_timeout id 32c awake [ 6673.397154] Lustre: DEBUG MARKER: == sanity test 350: force NID mismatch path to be exercised ========================================================== 16:52:23 (1783975943) [ 6815.363292] Lustre: DEBUG MARKER: == sanity test 398a: direct IO should cancel lock otherwise lockless ========================================================== 16:54:46 (1783976086) [ 6825.938616] Lustre: DEBUG MARKER: == sanity test 398b: DIO and buffer IO race ============== 16:54:56 (1783976096) [ 7090.173502] Lustre: DEBUG MARKER: == sanity test 398c: run fio to test AIO ================= 16:59:20 (1783976360) [ 7140.145408] Lustre: DEBUG MARKER: == sanity test 398d: run aiocp to verify block size > stripe size ========================================================== 17:00:11 (1783976411) [ 7156.639154] Lustre: 2402:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1783976412/real 1783976412] req@ffff8acc9f424e00 x1870627559556224/t0(0) o10->lustre-OST0000-osc-ffff8acc986eb000@192.168.201.140@tcp:6/4 lens 440/432 e 0 to 1 dl 1783976428 ref 1 fl Rpc:XQr/600/ffffffff rc 0/-1 job:'dd.0' uid:0 gid:0 projid:0 [ 7156.650890] Lustre: lustre-OST0000-osc-ffff8acc986eb000: Connection to lustre-OST0000 (at 192.168.201.140@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 7156.657529] Lustre: Skipped 1 previous similar message [ 7157.663145] Lustre: 2402:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1783976414/real 1783976414] req@ffff8acc9f427800 x1870627559556480/t0(0) o400->lustre-MDT0000-mdc-ffff8acc986eb000@192.168.201.140@tcp:12/10 lens 224/224 e 0 to 1 dl 1783976430 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 7157.673950] Lustre: lustre-MDT0000-mdc-ffff8acc986eb000: Connection to lustre-MDT0000 (at 192.168.201.140@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 7157.727519] LustreError: MGC192.168.201.140@tcp: Connection to MGS (at 192.168.201.140@tcp) was lost; in progress operations using this service will fail [ 7162.847217] Lustre: 2403:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1783976419/real 1783976419] req@ffff8acc9f425180 x1870627559557248/t0(0) o400->lustre-MDT0001-mdc-ffff8acc986eb000@192.168.201.140@tcp:12/10 lens 224/224 e 0 to 1 dl 1783976435 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 7162.860847] Lustre: 2403:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 4 previous similar messages [ 7167.969301] Lustre: 2403:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1783976424/real 1783976424] req@ffff8accad994000 x1870627559557760/t0(0) o400->lustre-MDT0000-mdc-ffff8acc986eb000@192.168.201.140@tcp:12/10 lens 224/224 e 0 to 1 dl 1783976440 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 7167.988710] Lustre: 2403:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 7173.087153] Lustre: 2404:0:(client.c:2490:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1783976429/real 1783976429] req@ffff8acc8e342300 x1870627559558400/t0(0) o400->lustre-MDT0000-mdc-ffff8acc986eb000@192.168.201.140@tcp:12/10 lens 224/224 e 0 to 1 dl 1783976445 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 7173.097932] Lustre: 2404:0:(client.c:2490:ptlrpc_expire_one_request()) Skipped 3 previous similar messages [ 7373.791169] INFO: task dd:180330 blocked for more than 120 seconds. [ 7373.793957] Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 7373.796921] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 7373.799586] task:dd state:D stack:0 pid:180330 ppid:180182 flags:0x80004000 [ 7373.802505] Call Trace: [ 7373.803502] __schedule+0x351/0xcb0 [ 7373.806066] ? wait_for_completion+0xae/0x1e0 [ 7373.807398] schedule+0xc0/0x180 [ 7373.808229] schedule_timeout+0x126/0x190 [ 7373.809204] ? __prepare_to_swait+0x5b/0x90 [ 7373.810397] ? do_raw_spin_unlock+0x75/0x190 [ 7373.811447] wait_for_completion+0xf0/0x1e0 [ 7373.812795] osc_io_setattr_end+0x21b/0x320 [osc] [ 7373.814789] cl_io_end+0x5a/0x190 [obdclass] [ 7373.816827] ? lov_comp_index+0xa0/0xa0 [lov] [ 7373.818174] lov_io_end_wrapper+0x10f/0x120 [lov] [ 7373.819379] lov_io_call.isra.11+0x91/0x1c0 [lov] [ 7373.820866] lov_io_end+0xba/0x190 [lov] [ 7373.822020] cl_io_end+0x5a/0x190 [obdclass] [ 7373.823597] cl_io_loop+0xf7/0x2f0 [obdclass] [ 7373.825314] cl_setattr_ost+0x3b5/0x520 [lustre] [ 7373.826980] ll_setattr_raw+0x11f6/0x16d0 [lustre] [ 7373.828486] ll_setattr+0x72/0x240 [lustre] [ 7373.830285] notify_change+0x3f0/0x790 [ 7373.831785] do_truncate+0x96/0x120 [ 7373.833121] do_last+0x8d0/0xfc0 [ 7373.834383] ? nd_jump_root+0xe5/0x160 [ 7373.835569] ? path_init+0x437/0x520 [ 7373.836676] path_openat+0xf7/0x500 [ 7373.837640] do_filp_open+0x99/0x140 [ 7373.838880] ? getname_flags+0x6e/0x330 [ 7373.840434] ? __check_object_size+0xff/0x256 [ 7373.842204] ? do_raw_spin_unlock+0x75/0x190 [ 7373.844067] ? _raw_spin_unlock+0x12/0x30 [ 7373.845505] do_sys_openat2+0x2b4/0x410 [ 7373.846545] do_sys_open+0x73/0xa0 [ 7373.847902] __x64_sys_openat+0x24/0x30 [ 7373.848957] do_syscall_64+0xc1/0x440 [ 7373.850197] entry_SYSCALL_64_after_hwframe+0x49/0xae [ 7373.851639] RIP: 0033:0x7f3231fd9332 [ 7373.852717] Code: Unable to access opcode bytes at RIP 0x7f3231fd9308. [ 7373.854700] RSP: 002b:00007ffe2cf6d4b0 EFLAGS: 00000246 ORIG_RAX: 0000000000000101 [ 7373.856980] RAX: ffffffffffffffda RBX: 000056149c3a6120 RCX: 00007f3231fd9332 [ 7373.859777] RDX: 0000000000000241 RSI: 00007ffe2cf6fae9 RDI: 00000000ffffff9c [ 7373.862971] RBP: 0000000000000001 R08: 00007ffe2cf6fb10 R09: 0000000000000000 [ 7373.865008] R10: 00000000000001b6 R11: 0000000000000246 R12: 0000000000000241 [ 7373.867304] R13: 00007ffe2cf6fae9 R14: 0000000000000001 R15: 00007ffe2cf6d790 [ 7496.671142] INFO: task dd:180330 blocked for more than 120 seconds. [ 7496.673529] Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 7496.676072] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 7496.678469] task:dd state:D stack:0 pid:180330 ppid:180182 flags:0x80004000 [ 7496.681069] Call Trace: [ 7496.682261] __schedule+0x351/0xcb0 [ 7496.683605] ? wait_for_completion+0xae/0x1e0 [ 7496.685082] schedule+0xc0/0x180 [ 7496.686225] schedule_timeout+0x126/0x190 [ 7496.687197] ? __prepare_to_swait+0x5b/0x90 [ 7496.688370] ? do_raw_spin_unlock+0x75/0x190 [ 7496.689812] wait_for_completion+0xf0/0x1e0 [ 7496.691178] osc_io_setattr_end+0x21b/0x320 [osc] [ 7496.692729] cl_io_end+0x5a/0x190 [obdclass] [ 7496.694204] ? lov_comp_index+0xa0/0xa0 [lov] [ 7496.696376] lov_io_end_wrapper+0x10f/0x120 [lov] [ 7496.697970] lov_io_call.isra.11+0x91/0x1c0 [lov] [ 7496.700045] lov_io_end+0xba/0x190 [lov] [ 7496.701927] cl_io_end+0x5a/0x190 [obdclass] [ 7496.703465] cl_io_loop+0xf7/0x2f0 [obdclass] [ 7496.705143] cl_setattr_ost+0x3b5/0x520 [lustre] [ 7496.706818] ll_setattr_raw+0x11f6/0x16d0 [lustre] [ 7496.708419] ll_setattr+0x72/0x240 [lustre] [ 7496.710403] notify_change+0x3f0/0x790 [ 7496.711806] do_truncate+0x96/0x120 [ 7496.713211] do_last+0x8d0/0xfc0 [ 7496.714750] ? nd_jump_root+0xe5/0x160 [ 7496.715962] ? path_init+0x437/0x520 [ 7496.716851] path_openat+0xf7/0x500 [ 7496.717542] do_filp_open+0x99/0x140 [ 7496.718355] ? getname_flags+0x6e/0x330 [ 7496.719301] ? __check_object_size+0xff/0x256 [ 7496.720356] ? do_raw_spin_unlock+0x75/0x190 [ 7496.721324] ? _raw_spin_unlock+0x12/0x30 [ 7496.722515] do_sys_openat2+0x2b4/0x410 [ 7496.723571] do_sys_open+0x73/0xa0 [ 7496.724338] __x64_sys_openat+0x24/0x30 [ 7496.725546] do_syscall_64+0xc1/0x440 [ 7496.726837] entry_SYSCALL_64_after_hwframe+0x49/0xae [ 7496.728608] RIP: 0033:0x7f3231fd9332 [ 7496.729610] Code: Unable to access opcode bytes at RIP 0x7f3231fd9308. [ 7496.731240] RSP: 002b:00007ffe2cf6d4b0 EFLAGS: 00000246 ORIG_RAX: 0000000000000101 [ 7496.733314] RAX: ffffffffffffffda RBX: 000056149c3a6120 RCX: 00007f3231fd9332 [ 7496.735428] RDX: 0000000000000241 RSI: 00007ffe2cf6fae9 RDI: 00000000ffffff9c [ 7496.737827] RBP: 0000000000000001 R08: 00007ffe2cf6fb10 R09: 0000000000000000 [ 7496.739690] R10: 00000000000001b6 R11: 0000000000000246 R12: 0000000000000241 [ 7496.742407] R13: 00007ffe2cf6fae9 R14: 0000000000000001 R15: 00007ffe2cf6d790 [ 7619.551155] INFO: task dd:180330 blocked for more than 120 seconds. [ 7619.556277] Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 7619.559197] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 7619.562272] task:dd state:D stack:0 pid:180330 ppid:180182 flags:0x80004000 [ 7619.565145] Call Trace: [ 7619.565920] __schedule+0x351/0xcb0 [ 7619.567137] ? wait_for_completion+0xae/0x1e0 [ 7619.568633] schedule+0xc0/0x180 [ 7619.570552] schedule_timeout+0x126/0x190 [ 7619.572358] ? __prepare_to_swait+0x5b/0x90 [ 7619.574053] ? do_raw_spin_unlock+0x75/0x190 [ 7619.575355] wait_for_completion+0xf0/0x1e0 [ 7619.576912] osc_io_setattr_end+0x21b/0x320 [osc] [ 7619.578428] cl_io_end+0x5a/0x190 [obdclass] [ 7619.579844] ? lov_comp_index+0xa0/0xa0 [lov] [ 7619.581277] lov_io_end_wrapper+0x10f/0x120 [lov] [ 7619.582879] lov_io_call.isra.11+0x91/0x1c0 [lov] [ 7619.584459] lov_io_end+0xba/0x190 [lov] [ 7619.585847] cl_io_end+0x5a/0x190 [obdclass] [ 7619.586913] cl_io_loop+0xf7/0x2f0 [obdclass] [ 7619.588370] cl_setattr_ost+0x3b5/0x520 [lustre] [ 7619.589890] ll_setattr_raw+0x11f6/0x16d0 [lustre] [ 7619.591516] ll_setattr+0x72/0x240 [lustre] [ 7619.593081] notify_change+0x3f0/0x790 [ 7619.594449] do_truncate+0x96/0x120 [ 7619.595651] do_last+0x8d0/0xfc0 [ 7619.596827] ? nd_jump_root+0xe5/0x160 [ 7619.598087] ? path_init+0x437/0x520 [ 7619.599354] path_openat+0xf7/0x500 [ 7619.600577] do_filp_open+0x99/0x140 [ 7619.601808] ? getname_flags+0x6e/0x330 [ 7619.603189] ? __check_object_size+0xff/0x256 [ 7619.605014] ? do_raw_spin_unlock+0x75/0x190 [ 7619.606422] ? _raw_spin_unlock+0x12/0x30 [ 7619.607851] do_sys_openat2+0x2b4/0x410 [ 7619.609114] do_sys_open+0x73/0xa0 [ 7619.610280] __x64_sys_openat+0x24/0x30 [ 7619.611628] do_syscall_64+0xc1/0x440 [ 7619.613087] entry_SYSCALL_64_after_hwframe+0x49/0xae [ 7619.614895] RIP: 0033:0x7f3231fd9332 [ 7619.616017] Code: Unable to access opcode bytes at RIP 0x7f3231fd9308. [ 7619.617872] RSP: 002b:00007ffe2cf6d4b0 EFLAGS: 00000246 ORIG_RAX: 0000000000000101 [ 7619.619995] RAX: ffffffffffffffda RBX: 000056149c3a6120 RCX: 00007f3231fd9332 [ 7619.622096] RDX: 0000000000000241 RSI: 00007ffe2cf6fae9 RDI: 00000000ffffff9c [ 7619.623699] RBP: 0000000000000001 R08: 00007ffe2cf6fb10 R09: 0000000000000000 [ 7619.625433] R10: 00000000000001b6 R11: 0000000000000246 R12: 0000000000000241 [ 7619.627439] R13: 00007ffe2cf6fae9 R14: 0000000000000001 R15: 00007ffe2cf6d790 [ 7742.431377] INFO: task dd:180330 blocked for more than 120 seconds. [ 7742.438459] Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 7742.440970] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 7742.443522] task:dd state:D stack:0 pid:180330 ppid:180182 flags:0x80004000 [ 7742.446319] Call Trace: [ 7742.447368] __schedule+0x351/0xcb0 [ 7742.449195] ? wait_for_completion+0xae/0x1e0 [ 7742.451685] schedule+0xc0/0x180 [ 7742.453464] schedule_timeout+0x126/0x190 [ 7742.455369] ? __prepare_to_swait+0x5b/0x90 [ 7742.456894] ? do_raw_spin_unlock+0x75/0x190 [ 7742.458884] wait_for_completion+0xf0/0x1e0 [ 7742.460290] osc_io_setattr_end+0x21b/0x320 [osc] [ 7742.462021] cl_io_end+0x5a/0x190 [obdclass] [ 7742.463574] ? lov_comp_index+0xa0/0xa0 [lov] [ 7742.466344] lov_io_end_wrapper+0x10f/0x120 [lov] [ 7742.467920] lov_io_call.isra.11+0x91/0x1c0 [lov] [ 7742.470077] lov_io_end+0xba/0x190 [lov] [ 7742.472184] cl_io_end+0x5a/0x190 [obdclass] [ 7742.474363] cl_io_loop+0xf7/0x2f0 [obdclass] [ 7742.476518] cl_setattr_ost+0x3b5/0x520 [lustre] [ 7742.477740] ll_setattr_raw+0x11f6/0x16d0 [lustre] [ 7742.478882] ll_setattr+0x72/0x240 [lustre] [ 7742.480207] notify_change+0x3f0/0x790 [ 7742.482367] do_truncate+0x96/0x120 [ 7742.483949] do_last+0x8d0/0xfc0 [ 7742.485969] ? nd_jump_root+0xe5/0x160 [ 7742.488071] ? path_init+0x437/0x520 [ 7742.489900] path_openat+0xf7/0x500 [ 7742.491048] do_filp_open+0x99/0x140 [ 7742.491886] ? getname_flags+0x6e/0x330 [ 7742.493225] ? __check_object_size+0xff/0x256 [ 7742.495022] ? do_raw_spin_unlock+0x75/0x190 [ 7742.496849] ? _raw_spin_unlock+0x12/0x30 [ 7742.498396] do_sys_openat2+0x2b4/0x410 [ 7742.500236] do_sys_open+0x73/0xa0 [ 7742.501928] __x64_sys_openat+0x24/0x30 [ 7742.503547] do_syscall_64+0xc1/0x440 [ 7742.504992] entry_SYSCALL_64_after_hwframe+0x49/0xae [ 7742.507049] RIP: 0033:0x7f3231fd9332 [ 7742.508389] Code: Unable to access opcode bytes at RIP 0x7f3231fd9308. [ 7742.511224] RSP: 002b:00007ffe2cf6d4b0 EFLAGS: 00000246 ORIG_RAX: 0000000000000101 [ 7742.514254] RAX: ffffffffffffffda RBX: 000056149c3a6120 RCX: 00007f3231fd9332 [ 7742.517335] RDX: 0000000000000241 RSI: 00007ffe2cf6fae9 RDI: 00000000ffffff9c [ 7742.520409] RBP: 0000000000000001 R08: 00007ffe2cf6fb10 R09: 0000000000000000 [ 7742.523738] R10: 00000000000001b6 R11: 0000000000000246 R12: 0000000000000241 [ 7742.526795] R13: 00007ffe2cf6fae9 R14: 0000000000000001 R15: 00007ffe2cf6d790 [ 7865.311390] INFO: task dd:180330 blocked for more than 120 seconds. [ 7865.314824] Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 7865.317799] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 7865.320328] task:dd state:D stack:0 pid:180330 ppid:180182 flags:0x80004000 [ 7865.322202] Call Trace: [ 7865.322935] __schedule+0x351/0xcb0 [ 7865.324126] ? wait_for_completion+0xae/0x1e0 [ 7865.325836] schedule+0xc0/0x180 [ 7865.327020] schedule_timeout+0x126/0x190 [ 7865.328360] ? __prepare_to_swait+0x5b/0x90 [ 7865.329950] ? do_raw_spin_unlock+0x75/0x190 [ 7865.331353] wait_for_completion+0xf0/0x1e0 [ 7865.332678] osc_io_setattr_end+0x21b/0x320 [osc] [ 7865.334697] cl_io_end+0x5a/0x190 [obdclass] [ 7865.336503] ? lov_comp_index+0xa0/0xa0 [lov] [ 7865.338319] lov_io_end_wrapper+0x10f/0x120 [lov] [ 7865.339557] lov_io_call.isra.11+0x91/0x1c0 [lov] [ 7865.340874] lov_io_end+0xba/0x190 [lov] [ 7865.342092] cl_io_end+0x5a/0x190 [obdclass] [ 7865.343654] cl_io_loop+0xf7/0x2f0 [obdclass] [ 7865.345293] cl_setattr_ost+0x3b5/0x520 [lustre] [ 7865.346909] ll_setattr_raw+0x11f6/0x16d0 [lustre] [ 7865.349101] ll_setattr+0x72/0x240 [lustre] [ 7865.351097] notify_change+0x3f0/0x790 [ 7865.352716] do_truncate+0x96/0x120 [ 7865.354598] do_last+0x8d0/0xfc0 [ 7865.355876] ? nd_jump_root+0xe5/0x160 [ 7865.357152] ? path_init+0x437/0x520 [ 7865.358294] path_openat+0xf7/0x500 [ 7865.359882] do_filp_open+0x99/0x140 [ 7865.361277] ? getname_flags+0x6e/0x330 [ 7865.362639] ? __check_object_size+0xff/0x256 [ 7865.364381] ? do_raw_spin_unlock+0x75/0x190 [ 7865.366506] ? _raw_spin_unlock+0x12/0x30 [ 7865.367995] do_sys_openat2+0x2b4/0x410 [ 7865.369625] do_sys_open+0x73/0xa0 [ 7865.370945] __x64_sys_openat+0x24/0x30 [ 7865.372732] do_syscall_64+0xc1/0x440 [ 7865.374017] entry_SYSCALL_64_after_hwframe+0x49/0xae [ 7865.375380] RIP: 0033:0x7f3231fd9332 [ 7865.376644] Code: Unable to access opcode bytes at RIP 0x7f3231fd9308. [ 7865.379314] RSP: 002b:00007ffe2cf6d4b0 EFLAGS: 00000246 ORIG_RAX: 0000000000000101 [ 7865.382621] RAX: ffffffffffffffda RBX: 000056149c3a6120 RCX: 00007f3231fd9332 [ 7865.385587] RDX: 0000000000000241 RSI: 00007ffe2cf6fae9 RDI: 00000000ffffff9c [ 7865.388568] RBP: 0000000000000001 R08: 00007ffe2cf6fb10 R09: 0000000000000000 [ 7865.391195] R10: 00000000000001b6 R11: 0000000000000246 R12: 0000000000000241 [ 7865.393914] R13: 00007ffe2cf6fae9 R14: 0000000000000001 R15: 00007ffe2cf6d790 [ 7988.191365] INFO: task dd:180330 blocked for more than 120 seconds. [ 7988.193965] Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 7988.196423] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 7988.198844] task:dd state:D stack:0 pid:180330 ppid:180182 flags:0x80004000 [ 7988.201391] Call Trace: [ 7988.202226] __schedule+0x351/0xcb0 [ 7988.203235] ? wait_for_completion+0xae/0x1e0 [ 7988.204691] schedule+0xc0/0x180 [ 7988.206050] schedule_timeout+0x126/0x190 [ 7988.207107] ? __prepare_to_swait+0x5b/0x90 [ 7988.208461] ? do_raw_spin_unlock+0x75/0x190 [ 7988.209586] wait_for_completion+0xf0/0x1e0 [ 7988.210931] osc_io_setattr_end+0x21b/0x320 [osc] [ 7988.212803] cl_io_end+0x5a/0x190 [obdclass] [ 7988.214343] ? lov_comp_index+0xa0/0xa0 [lov] [ 7988.215540] lov_io_end_wrapper+0x10f/0x120 [lov] [ 7988.218057] lov_io_call.isra.11+0x91/0x1c0 [lov] [ 7988.219521] lov_io_end+0xba/0x190 [lov] [ 7988.220626] cl_io_end+0x5a/0x190 [obdclass] [ 7988.222022] cl_io_loop+0xf7/0x2f0 [obdclass] [ 7988.223674] cl_setattr_ost+0x3b5/0x520 [lustre] [ 7988.225287] ll_setattr_raw+0x11f6/0x16d0 [lustre] [ 7988.226881] ll_setattr+0x72/0x240 [lustre] [ 7988.228418] notify_change+0x3f0/0x790 [ 7988.229879] do_truncate+0x96/0x120 [ 7988.231213] do_last+0x8d0/0xfc0 [ 7988.232458] ? nd_jump_root+0xe5/0x160 [ 7988.233692] ? path_init+0x437/0x520 [ 7988.234990] path_openat+0xf7/0x500 [ 7988.236132] do_filp_open+0x99/0x140 [ 7988.237326] ? getname_flags+0x6e/0x330 [ 7988.238897] ? __check_object_size+0xff/0x256 [ 7988.240691] ? do_raw_spin_unlock+0x75/0x190 [ 7988.242141] ? _raw_spin_unlock+0x12/0x30 [ 7988.243577] do_sys_openat2+0x2b4/0x410 [ 7988.244703] do_sys_open+0x73/0xa0 [ 7988.245724] __x64_sys_openat+0x24/0x30 [ 7988.247048] do_syscall_64+0xc1/0x440 [ 7988.248298] entry_SYSCALL_64_after_hwframe+0x49/0xae [ 7988.250543] RIP: 0033:0x7f3231fd9332 [ 7988.251862] Code: Unable to access opcode bytes at RIP 0x7f3231fd9308. [ 7988.254156] RSP: 002b:00007ffe2cf6d4b0 EFLAGS: 00000246 ORIG_RAX: 0000000000000101 [ 7988.256924] RAX: ffffffffffffffda RBX: 000056149c3a6120 RCX: 00007f3231fd9332 [ 7988.259201] RDX: 0000000000000241 RSI: 00007ffe2cf6fae9 RDI: 00000000ffffff9c [ 7988.261631] RBP: 0000000000000001 R08: 00007ffe2cf6fb10 R09: 0000000000000000 [ 7988.263900] R10: 00000000000001b6 R11: 0000000000000246 R12: 0000000000000241 [ 7988.266202] R13: 00007ffe2cf6fae9 R14: 0000000000000001 R15: 00007ffe2cf6d790 [ 8111.071162] INFO: task dd:180330 blocked for more than 120 seconds. [ 8111.073628] Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 8111.076733] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 8111.078771] task:dd state:D stack:0 pid:180330 ppid:180182 flags:0x80004000 [ 8111.080781] Call Trace: [ 8111.081996] __schedule+0x351/0xcb0 [ 8111.083090] ? wait_for_completion+0xae/0x1e0 [ 8111.084356] schedule+0xc0/0x180 [ 8111.085465] schedule_timeout+0x126/0x190 [ 8111.086956] ? __prepare_to_swait+0x5b/0x90 [ 8111.088497] ? do_raw_spin_unlock+0x75/0x190 [ 8111.089526] wait_for_completion+0xf0/0x1e0 [ 8111.091029] osc_io_setattr_end+0x21b/0x320 [osc] [ 8111.092700] cl_io_end+0x5a/0x190 [obdclass] [ 8111.094180] ? lov_comp_index+0xa0/0xa0 [lov] [ 8111.095367] lov_io_end_wrapper+0x10f/0x120 [lov] [ 8111.096545] lov_io_call.isra.11+0x91/0x1c0 [lov] [ 8111.098237] lov_io_end+0xba/0x190 [lov] [ 8111.099360] cl_io_end+0x5a/0x190 [obdclass] [ 8111.100671] cl_io_loop+0xf7/0x2f0 [obdclass] [ 8111.101911] cl_setattr_ost+0x3b5/0x520 [lustre] [ 8111.103465] ll_setattr_raw+0x11f6/0x16d0 [lustre] [ 8111.105174] ll_setattr+0x72/0x240 [lustre] [ 8111.106538] notify_change+0x3f0/0x790 [ 8111.107775] do_truncate+0x96/0x120 [ 8111.108890] do_last+0x8d0/0xfc0 [ 8111.109826] ? nd_jump_root+0xe5/0x160 [ 8111.110991] ? path_init+0x437/0x520 [ 8111.111888] path_openat+0xf7/0x500 [ 8111.112609] do_filp_open+0x99/0x140 [ 8111.113742] ? getname_flags+0x6e/0x330 [ 8111.115242] ? __check_object_size+0xff/0x256 [ 8111.116984] ? do_raw_spin_unlock+0x75/0x190 [ 8111.118434] ? _raw_spin_unlock+0x12/0x30 [ 8111.119453] do_sys_openat2+0x2b4/0x410 [ 8111.120401] do_sys_open+0x73/0xa0 [ 8111.121187] __x64_sys_openat+0x24/0x30 [ 8111.121958] do_syscall_64+0xc1/0x440 [ 8111.123169] entry_SYSCALL_64_after_hwframe+0x49/0xae [ 8111.124698] RIP: 0033:0x7f3231fd9332 [ 8111.125973] Code: Unable to access opcode bytes at RIP 0x7f3231fd9308. [ 8111.127904] RSP: 002b:00007ffe2cf6d4b0 EFLAGS: 00000246 ORIG_RAX: 0000000000000101 [ 8111.130561] RAX: ffffffffffffffda RBX: 000056149c3a6120 RCX: 00007f3231fd9332 [ 8111.133051] RDX: 0000000000000241 RSI: 00007ffe2cf6fae9 RDI: 00000000ffffff9c [ 8111.135740] RBP: 0000000000000001 R08: 00007ffe2cf6fb10 R09: 0000000000000000 [ 8111.138267] R10: 00000000000001b6 R11: 0000000000000246 R12: 0000000000000241 [ 8111.140532] R13: 00007ffe2cf6fae9 R14: 0000000000000001 R15: 00007ffe2cf6d790 [ 8233.952074] INFO: task dd:180330 blocked for more than 120 seconds. [ 8233.959354] Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 8233.964672] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 8233.967555] task:dd state:D stack:0 pid:180330 ppid:180182 flags:0x80004000 [ 8233.970433] Call Trace: [ 8233.971437] __schedule+0x351/0xcb0 [ 8233.972444] ? wait_for_completion+0xae/0x1e0 [ 8233.974114] schedule+0xc0/0x180 [ 8233.975267] schedule_timeout+0x126/0x190 [ 8233.977089] ? __prepare_to_swait+0x5b/0x90 [ 8233.978417] ? do_raw_spin_unlock+0x75/0x190 [ 8233.979869] wait_for_completion+0xf0/0x1e0 [ 8233.981702] osc_io_setattr_end+0x21b/0x320 [osc] [ 8233.983516] cl_io_end+0x5a/0x190 [obdclass] [ 8233.986329] ? lov_comp_index+0xa0/0xa0 [lov] [ 8233.987564] lov_io_end_wrapper+0x10f/0x120 [lov] [ 8233.989386] lov_io_call.isra.11+0x91/0x1c0 [lov] [ 8233.993318] lov_io_end+0xba/0x190 [lov] [ 8233.994721] cl_io_end+0x5a/0x190 [obdclass] [ 8233.996924] cl_io_loop+0xf7/0x2f0 [obdclass] [ 8233.998676] cl_setattr_ost+0x3b5/0x520 [lustre] [ 8234.000392] ll_setattr_raw+0x11f6/0x16d0 [lustre] [ 8234.002375] ll_setattr+0x72/0x240 [lustre] [ 8234.004439] notify_change+0x3f0/0x790 [ 8234.006121] do_truncate+0x96/0x120 [ 8234.007383] do_last+0x8d0/0xfc0 [ 8234.009281] ? nd_jump_root+0xe5/0x160 [ 8234.010626] ? path_init+0x437/0x520 [ 8234.011995] path_openat+0xf7/0x500 [ 8234.013244] do_filp_open+0x99/0x140 [ 8234.014510] ? getname_flags+0x6e/0x330 [ 8234.015593] ? __check_object_size+0xff/0x256 [ 8234.016950] ? do_raw_spin_unlock+0x75/0x190 [ 8234.018408] ? _raw_spin_unlock+0x12/0x30 [ 8234.020133] do_sys_openat2+0x2b4/0x410 [ 8234.021335] do_sys_open+0x73/0xa0 [ 8234.022524] __x64_sys_openat+0x24/0x30 [ 8234.024132] do_syscall_64+0xc1/0x440 [ 8234.025256] entry_SYSCALL_64_after_hwframe+0x49/0xae [ 8234.027071] RIP: 0033:0x7f3231fd9332 [ 8234.027871] Code: Unable to access opcode bytes at RIP 0x7f3231fd9308. [ 8234.029984] RSP: 002b:00007ffe2cf6d4b0 EFLAGS: 00000246 ORIG_RAX: 0000000000000101 [ 8234.033017] RAX: ffffffffffffffda RBX: 000056149c3a6120 RCX: 00007f3231fd9332 [ 8234.035888] RDX: 0000000000000241 RSI: 00007ffe2cf6fae9 RDI: 00000000ffffff9c [ 8234.037811] RBP: 0000000000000001 R08: 00007ffe2cf6fb10 R09: 0000000000000000 [ 8234.040425] R10: 00000000000001b6 R11: 0000000000000246 R12: 0000000000000241 [ 8234.043207] R13: 00007ffe2cf6fae9 R14: 0000000000000001 R15: 00007ffe2cf6d790 [ 8356.831156] INFO: task dd:180330 blocked for more than 120 seconds. [ 8356.834521] Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 8356.836609] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 8356.839266] task:dd state:D stack:0 pid:180330 ppid:180182 flags:0x80004000 [ 8356.842436] Call Trace: [ 8356.843135] __schedule+0x351/0xcb0 [ 8356.844112] ? wait_for_completion+0xae/0x1e0 [ 8356.845799] schedule+0xc0/0x180 [ 8356.846970] schedule_timeout+0x126/0x190 [ 8356.850122] ? __prepare_to_swait+0x5b/0x90 [ 8356.851860] ? do_raw_spin_unlock+0x75/0x190 [ 8356.853276] wait_for_completion+0xf0/0x1e0 [ 8356.854423] osc_io_setattr_end+0x21b/0x320 [osc] [ 8356.856118] cl_io_end+0x5a/0x190 [obdclass] [ 8356.857915] ? lov_comp_index+0xa0/0xa0 [lov] [ 8356.859620] lov_io_end_wrapper+0x10f/0x120 [lov] [ 8356.861115] lov_io_call.isra.11+0x91/0x1c0 [lov] [ 8356.862691] lov_io_end+0xba/0x190 [lov] [ 8356.863930] cl_io_end+0x5a/0x190 [obdclass] [ 8356.865251] cl_io_loop+0xf7/0x2f0 [obdclass] [ 8356.866512] cl_setattr_ost+0x3b5/0x520 [lustre] [ 8356.867837] ll_setattr_raw+0x11f6/0x16d0 [lustre] [ 8356.869163] ll_setattr+0x72/0x240 [lustre] [ 8356.870455] notify_change+0x3f0/0x790 [ 8356.871331] do_truncate+0x96/0x120 [ 8356.872254] do_last+0x8d0/0xfc0 [ 8356.873158] ? nd_jump_root+0xe5/0x160 [ 8356.874344] ? path_init+0x437/0x520 [ 8356.875591] path_openat+0xf7/0x500 [ 8356.876470] do_filp_open+0x99/0x140 [ 8356.877507] ? getname_flags+0x6e/0x330 [ 8356.878597] ? __check_object_size+0xff/0x256 [ 8356.879953] ? do_raw_spin_unlock+0x75/0x190 [ 8356.881229] ? _raw_spin_unlock+0x12/0x30 [ 8356.882365] do_sys_openat2+0x2b4/0x410 [ 8356.883327] do_sys_open+0x73/0xa0 [ 8356.884392] __x64_sys_openat+0x24/0x30 [ 8356.885601] do_syscall_64+0xc1/0x440 [ 8356.886527] entry_SYSCALL_64_after_hwframe+0x49/0xae [ 8356.887902] RIP: 0033:0x7f3231fd9332 [ 8356.888587] Code: Unable to access opcode bytes at RIP 0x7f3231fd9308. [ 8356.890229] RSP: 002b:00007ffe2cf6d4b0 EFLAGS: 00000246 ORIG_RAX: 0000000000000101 [ 8356.891929] RAX: ffffffffffffffda RBX: 000056149c3a6120 RCX: 00007f3231fd9332 [ 8356.894364] RDX: 0000000000000241 RSI: 00007ffe2cf6fae9 RDI: 00000000ffffff9c [ 8356.896354] RBP: 0000000000000001 R08: 00007ffe2cf6fb10 R09: 0000000000000000 [ 8356.898269] R10: 00000000000001b6 R11: 0000000000000246 R12: 0000000000000241 [ 8356.899901] R13: 00007ffe2cf6fae9 R14: 0000000000000001 R15: 00007ffe2cf6d790 [ 8479.711147] INFO: task dd:180330 blocked for more than 120 seconds. [ 8479.713257] Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 8479.716110] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 8479.718510] task:dd state:D stack:0 pid:180330 ppid:180182 flags:0x80004000 [ 8479.724230] Call Trace: [ 8479.725192] __schedule+0x351/0xcb0 [ 8479.726744] ? wait_for_completion+0xae/0x1e0 [ 8479.728425] schedule+0xc0/0x180 [ 8479.729476] schedule_timeout+0x126/0x190 [ 8479.730832] ? __prepare_to_swait+0x5b/0x90 [ 8479.732046] ? do_raw_spin_unlock+0x75/0x190 [ 8479.733290] wait_for_completion+0xf0/0x1e0 [ 8479.734803] osc_io_setattr_end+0x21b/0x320 [osc] [ 8479.736114] cl_io_end+0x5a/0x190 [obdclass] [ 8479.737419] ? lov_comp_index+0xa0/0xa0 [lov] [ 8479.738622] lov_io_end_wrapper+0x10f/0x120 [lov] [ 8479.740888] lov_io_call.isra.11+0x91/0x1c0 [lov] [ 8479.744155] lov_io_end+0xba/0x190 [lov] [ 8479.745627] cl_io_end+0x5a/0x190 [obdclass] [ 8479.747180] cl_io_loop+0xf7/0x2f0 [obdclass] [ 8479.748773] cl_setattr_ost+0x3b5/0x520 [lustre] [ 8479.750093] ll_setattr_raw+0x11f6/0x16d0 [lustre] [ 8479.751462] ll_setattr+0x72/0x240 [lustre] [ 8479.752761] notify_change+0x3f0/0x790 [ 8479.753770] do_truncate+0x96/0x120 [ 8479.754768] do_last+0x8d0/0xfc0 [ 8479.755787] ? nd_jump_root+0xe5/0x160 [ 8479.756897] ? path_init+0x437/0x520 [ 8479.757984] path_openat+0xf7/0x500 [ 8479.759033] do_filp_open+0x99/0x140 [ 8479.759919] ? getname_flags+0x6e/0x330 [ 8479.760905] ? __check_object_size+0xff/0x256 [ 8479.762444] ? do_raw_spin_unlock+0x75/0x190 [ 8479.763909] ? _raw_spin_unlock+0x12/0x30 [ 8479.765250] do_sys_openat2+0x2b4/0x410 [ 8479.766790] do_sys_open+0x73/0xa0 [ 8479.768135] __x64_sys_openat+0x24/0x30 [ 8479.769483] do_syscall_64+0xc1/0x440 [ 8479.770946] entry_SYSCALL_64_after_hwframe+0x49/0xae [ 8479.772951] RIP: 0033:0x7f3231fd9332 [ 8479.774192] Code: Unable to access opcode bytes at RIP 0x7f3231fd9308. [ 8479.776070] RSP: 002b:00007ffe2cf6d4b0 EFLAGS: 00000246 ORIG_RAX: 0000000000000101 [ 8479.778324] RAX: ffffffffffffffda RBX: 000056149c3a6120 RCX: 00007f3231fd9332 [ 8479.780919] RDX: 0000000000000241 RSI: 00007ffe2cf6fae9 RDI: 00000000ffffff9c [ 8479.783124] RBP: 0000000000000001 R08: 00007ffe2cf6fb10 R09: 0000000000000000 [ 8479.785409] R10: 00000000000001b6 R11: 0000000000000246 R12: 0000000000000241 [ 8479.787876] R13: 00007ffe2cf6fae9 R14: 0000000000000001 R15: 00007ffe2cf6d790