[ 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 445734526 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, 524584K 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.002000] x2apic enabled [ 0.002013] Switched APIC routing to physical x2apic. [ 0.003018] kvm-guest: setup PV IPIs [ 0.006000] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.006000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.006031] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.008010] pid_max: default: 32768 minimum: 301 [ 0.010194] LSM: Security Framework initializing [ 0.011086] Yama: becoming mindful. [ 0.012053] SELinux: Initializing. [ 0.013090] *** VALIDATE selinux *** [ 0.022576] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.027104] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.028188] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.029134] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.031114] *** VALIDATE tmpfs *** [ 0.033037] *** VALIDATE proc *** [ 0.034298] *** VALIDATE cgroup *** [ 0.035015] *** VALIDATE cgroup2 *** [ 0.036303] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.037179] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.039003] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.040037] Spectre V2 : User space: Vulnerable [ 0.041012] Speculative Store Bypass: Vulnerable [ 0.044887] debug: unmapping init [mem 0xffffffffa3c59000-0xffffffffa3c60fff] [ 0.046283] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.047760] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.048025] ... version: 2 [ 0.049019] ... bit width: 48 [ 0.050017] ... generic registers: 4 [ 0.051017] ... value mask: 0000ffffffffffff [ 0.052018] ... max period: 00007fffffffffff [ 0.053017] ... fixed-purpose events: 3 [ 0.054011] ... event mask: 000000070000000f [ 0.056303] rcu: Hierarchical SRCU implementation. [ 0.058816] smp: Bringing up secondary CPUs ... [ 0.059661] x86: Booting SMP configuration: [ 0.060034] .... node #0, CPUs: #1 #2 #3 [ 0.067018] smp: Brought up 1 node, 4 CPUs [ 0.069030] smpboot: Max logical packages: 1 [ 0.070026] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.104549] node 0 deferred pages initialised in 32ms [ 0.109181] devtmpfs: initialized [ 0.110262] x86/mm: Memory block size: 128MB [ 0.113610] gcov: version magic: 0x41383552 [ 0.115429] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.117155] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.120517] pinctrl core: initialized pinctrl subsystem [ 0.124309] [ 0.125010] ************************************************************* [ 0.128018] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.131015] ** ** [ 0.134016] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.137015] ** ** [ 0.139011] ** This means that this kernel is built to expose internal ** [ 0.142015] ** IOMMU data structures, which may compromise security on ** [ 0.144012] ** your system. ** [ 0.147014] ** ** [ 0.149011] ** If you see this message and you are not debugging the ** [ 0.152016] ** kernel, report this immediately to your vendor! ** [ 0.157085] ** ** [ 0.160013] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.163055] ************************************************************* [ 0.167013] NET: Registered protocol family 16 [ 0.169575] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.174090] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.180126] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.187139] cpuidle: using governor menu [ 0.189000] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.194991] PCI: Using configuration type 1 for base access [ 0.197153] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.212209] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.213000] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.216587] cryptd: max_cpu_qlen set to 1000 [ 0.218278] ACPI: Added _OSI(Module Device) [ 0.220029] ACPI: Added _OSI(Processor Device) [ 0.223019] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.226019] ACPI: Added _OSI(Processor Aggregator Device) [ 0.233222] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.246838] ACPI: Interpreter enabled [ 0.251990] ACPI: PM: (supports S0 S3 S4 S5) [ 0.255029] ACPI: Using IOAPIC for interrupt routing [ 0.263158] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.268672] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.295024] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.299103] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.300029] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.304108] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.310790] acpiphp: Slot [2] registered [ 0.311156] acpiphp: Slot [5] registered [ 0.312223] acpiphp: Slot [6] registered [ 0.314116] acpiphp: Slot [3] registered [ 0.316153] acpiphp: Slot [4] registered [ 0.318270] acpiphp: Slot [7] registered [ 0.322282] acpiphp: Slot [8] registered [ 0.324268] acpiphp: Slot [9] registered [ 0.325372] acpiphp: Slot [10] registered [ 0.327352] acpiphp: Slot [11] registered [ 0.329363] acpiphp: Slot [12] registered [ 0.331243] acpiphp: Slot [13] registered [ 0.333341] acpiphp: Slot [14] registered [ 0.335154] acpiphp: Slot [15] registered [ 0.337127] acpiphp: Slot [16] registered [ 0.338148] acpiphp: Slot [17] registered [ 0.339000] acpiphp: Slot [18] registered [ 0.340144] acpiphp: Slot [19] registered [ 0.342149] acpiphp: Slot [20] registered [ 0.344134] acpiphp: Slot [21] registered [ 0.345120] acpiphp: Slot [22] registered [ 0.347129] acpiphp: Slot [23] registered [ 0.349141] acpiphp: Slot [24] registered [ 0.351136] acpiphp: Slot [25] registered [ 0.353146] acpiphp: Slot [26] registered [ 0.355144] acpiphp: Slot [27] registered [ 0.357167] acpiphp: Slot [28] registered [ 0.359140] acpiphp: Slot [29] registered [ 0.361317] acpiphp: Slot [30] registered [ 0.363135] acpiphp: Slot [31] registered [ 0.365184] PCI host bridge to bus 0000:00 [ 0.367032] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.370035] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.372029] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.375089] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.379038] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.382058] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.384264] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.388366] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.393726] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.403020] pci 0000:00:01.1: reg 0x20: [io 0xc120-0xc12f] [ 0.409058] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.411042] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.415023] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.418021] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.425717] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.430043] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.435061] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.442095] pci 0000:00:01.3: quirk_piix4_acpi+0x0/0x1e0 took 11718 usecs [ 0.452700] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.465021] pci 0000:00:02.0: reg 0x10: [io 0xc100-0xc11f] [ 0.483025] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.496022] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.513426] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.529000] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.543021] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.565065] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.583611] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.597019] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.608015] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.630016] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.642855] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.645369] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.647364] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.650233] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.651146] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.656127] iommu: Default domain type: Passthrough [ 0.658357] SCSI subsystem initialized [ 0.659121] ACPI: bus type USB registered [ 0.661119] usbcore: registered new interface driver usbfs [ 0.665096] usbcore: registered new interface driver hub [ 0.668111] usbcore: registered new device driver usb [ 0.670168] pps_core: LinuxPPS API ver. 1 registered [ 0.671010] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.674056] PTP clock support registered [ 0.676059] EDAC MC: Ver: 3.0.0 [ 0.678064] PCI: Using ACPI for IRQ routing [ 0.682159] NetLabel: Initializing [ 0.683009] NetLabel: domain hash size = 128 [ 0.686011] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.688078] NetLabel: unlabeled traffic allowed by default [ 0.691307] vgaarb: loaded [ 0.693339] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.694017] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.698341] clocksource: Switched to clocksource kvm-clock [ 0.811589] VFS: Disk quotas dquot_6.6.0 [ 0.814190] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.816716] *** VALIDATE ramfs *** [ 0.817982] *** VALIDATE hugetlbfs *** [ 0.819127] pnp: PnP ACPI init [ 0.821631] pnp: PnP ACPI: found 6 devices [ 0.836181] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.840250] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.845136] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.849707] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.853918] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.858825] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.861764] NET: Registered protocol family 2 [ 0.864572] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.871652] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.875863] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.892474] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.899704] TCP: Hash tables configured (established 65536 bind 65536) [ 0.903443] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.906957] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.909914] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.912809] NET: Registered protocol family 1 [ 0.916937] RPC: Registered named UNIX socket transport module. [ 0.919493] RPC: Registered udp transport module. [ 0.921051] RPC: Registered tcp transport module. [ 0.923506] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.925938] NET: Registered protocol family 44 [ 0.927385] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.929202] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.930952] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.933297] PCI: CLS 0 bytes, default 64 [ 0.935324] Unpacking initramfs... [ 3.205978] debug: unmapping init [mem 0xffff9b443cc64000-0xffff9b443ffcffff] [ 3.210741] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 3.214648] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 3.221351] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 3.967309] Initialise system trusted keyrings [ 3.970096] Key type blacklist registered [ 3.972289] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 3.986904] zbud: loaded [ 3.990942] *** VALIDATE nfs *** [ 3.993009] *** VALIDATE nfs4 *** [ 3.999574] pstore: using deflate compression [ 4.018492] Platform Keyring initialized [ 4.294777] NET: Registered protocol family 38 [ 4.296908] Key type asymmetric registered [ 4.299220] Asymmetric key parser 'x509' registered [ 4.301761] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 4.305487] io scheduler mq-deadline registered [ 4.307938] io scheduler kyber registered [ 4.310481] io scheduler bfq registered [ 4.312935] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 4.317037] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 4.319942] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 4.324803] ACPI: Power Button [PWRF] [ 4.337943] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 4.358476] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 4.395408] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 4.435439] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 4.511900] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 4.517244] Non-volatile memory driver v1.3 [ 4.519737] Linux agpgart interface v0.103 [ 4.622440] virtio_blk virtio1: [vda] 149960 512-byte logical blocks (76.8 MB/73.2 MiB) [ 4.629516] vda: detected capacity change from 0 to 76779520 [ 4.676020] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 4.683545] vdb: detected capacity change from 0 to 1073741824 [ 4.696631] libphy: Fixed MDIO Bus: probed [ 4.726309] usbcore: registered new interface driver usbserial_generic [ 4.731227] usbserial: USB Serial support registered for generic [ 4.736465] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 4.745890] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 4.748479] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 4.751852] mousedev: PS/2 mouse device common for all mice [ 4.757107] rtc_cmos 00:05: RTC can wake from S4 [ 4.762183] rtc_cmos 00:05: registered as rtc0 [ 4.763971] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 4.769689] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 4.772378] intel_pstate: CPU model not supported [ 4.784606] hid: raw HID events driver (C) Jiri Kosina [ 4.785676] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 4.790266] usbcore: registered new interface driver usbhid [ 4.790274] usbhid: USB HID core driver [ 4.790389] drop_monitor: Initializing network drop monitor service [ 4.790508] Initializing XFRM netlink socket [ 4.792262] NET: Registered protocol family 10 [ 4.801647] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 4.813267] Segment Routing with IPv6 [ 4.828900] NET: Registered protocol family 17 [ 4.832368] mpls_gso: MPLS GSO support [ 4.839730] RAS: Correctable Errors collector initialized. [ 4.843309] AVX version of gcm_enc/dec engaged. [ 4.845866] AES CTR mode by8 optimization enabled [ 4.974226] sched_clock: Marking stable (4974096336, 0)->(6200521460, -1226425124) [ 4.983416] registered taskstats version 1 [ 4.987587] Loading compiled-in X.509 certificates [ 4.990667] zswap: loaded using pool lzo/zbud [ 5.033620] Key type big_key registered [ 5.054991] Key type encrypted registered [ 5.058768] ima: No TPM chip found, activating TPM-bypass! [ 5.062921] ima: Allocated hash algorithm: sha1 [ 5.066498] ima: No architecture policies found [ 5.069705] evm: Initialising EVM extended attributes: [ 5.073348] evm: security.selinux [ 5.075231] evm: security.ima [ 5.077360] evm: security.capability [ 5.079425] evm: HMAC attrs: 0x1 [ 5.082817] rtc_cmos 00:05: setting system clock to 2026-09-14 09:27:18 UTC (1789378038) [ 5.093541] debug: unmapping init [mem 0xffffffffa4c03000-0xffffffffa4dfffff] [ 5.097676] debug: unmapping init [mem 0xffffffffa3982000-0xffffffffa3c58fff] [ 5.108408] Write protecting the kernel read-only data: 28672k [ 5.115169] debug: unmapping init [mem 0xffffffffa2003000-0xffffffffa21fffff] [ 5.123142] debug: unmapping init [mem 0xffffffffa2914000-0xffffffffa29fffff] [ 5.189499] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 5.206479] systemd[1]: Detected virtualization kvm. [ 5.209826] systemd[1]: Detected architecture x86-64. [ 5.213753] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 5.269060] systemd[1]: No hostname configured. [ 5.271844] systemd[1]: Set hostname to . [ 5.274822] random: systemd: uninitialized urandom read (16 bytes read) [ 5.279697] systemd[1]: Initializing machine ID from random generator. [ 5.373903] random: ln: uninitialized urandom read (6 bytes read) [ 5.511953] random: systemd: uninitialized urandom read (16 bytes read) [ 5.517299] systemd[1]: Started Dispatch Password Requests to Console Directory Watch. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ 5.532585] systemd[1]: Reached target Paths. [ OK ] Reached target Paths. [ 5.542715] systemd[1]: Reached target Initrd Root Device. [ OK ] Reached target Initrd Root Device. [ OK ] Reached target Local File Systems. [ OK ] Listening on udev Kernel Socket. [ OK ] Listening on udev Control Socket. [ OK ] Reached target Timers. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Listening on Journal Socket (/dev/log). [ OK ] Reached target Swap. [ OK ] Listening on Journal Socket. Starting Setup Virtual Console... Starting Create list of required st…ce nodes for the current kernel... [ OK ] Reached target Sockets. Starting Journal Service... [ OK ] Started Memstrack Anylazing Service. Starting Apply Kernel Variables... Starting Create Volatile Files and Directories... [ OK ] Reached target Slices. [ OK ] Started Setup Virtual Console. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Apply Kernel Variables. [ OK ] Started Create Volatile Files and Directories. Starting Create Static Device Nodes in /dev... Starting dracut cmdline hook... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started Journal Service. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 6.598141] device-mapper: uevent: version 1.0.3 [ 6.601885] device-mapper: ioctl: 4.46.0-ioctl (2022-02-22) initialised: dm-devel@redhat.com [ OK ] Started dracut pre-udev hook. Starting udev Kernel Device Manager... [ OK ] Started udev Kernel Device Manager. Starting dracut pre-trigger hook... [ OK ] Started dracut pre-trigger hook. Starting udev Coldplug all Devices... Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. Starting dracut initqueue hook... [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon.[ 8.152854] random: fast init done [ 8.289701] virtio_net virtio0 ens2: renamed from eth0 [ 8.391282] scsi host0: ata_piix [ 8.478044] scsi host1: ata_piix [ 8.481176] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc120 irq 14 [ 8.487435] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc128 irq 15 [ 13.371074] dracut-initqueue[580]: RTNETLINK answers: File exists [ 13.585455] random: crng init done [ 13.587078] random: 7 urandom warning(s) missed due to ratelimiting Starting nbd nbd0... [ OK ] Started nbd nbd0. [ OK ] Started dracut initqueue hook. Mounting /sysroot... [ OK ] Reached target Remote File Systems (Pre). [ 15.396428] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Reached target Remote File Systems. [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped target Timers. [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Remote File Systems. [ OK ] Stopped target Remote File Systems (Pre). [ OK ] Stopped dracut initqueue hook. Stopping Hardware RNG Entropy Gatherer Daemon... [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. [ OK ] Stopped Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Slices. [ OK ] Stopped target System Initialization. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. Stopping udev Kernel Device Manager... [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped target Swap. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped target Local File Systems. [ OK ] Stopped target Paths. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped target Sockets. [ OK ] Stopped udev Kernel Device Manager. [ OK ] Started Cleaning Up and Shutting Down Daemons. [ OK ] Stopped Create Static Device Nodes in /dev. [ OK ] Stopped Create list of required sta…vice nodes for the current kernel. [ OK ] Stopped dracut pre-udev hook. [ OK ] Stopped dracut cmdline hook. [ OK ] Closed udev Kernel Socket. [ OK ] Closed udev Control Socket. Starting Cleanup udevd DB... [ OK ] Started Cleanup udevd DB. [ OK ] Reached target Switch Root. Starting Switch Root... [ 17.550730] printk: systemd: 26 output lines suppressed due to ratelimiting [ 18.356899] SELinux: Disabled at runtime. [ 18.468170] 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) [ 18.486847] systemd[1]: Detected virtualization kvm. [ 18.490460] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 19.855363] hrtimer: interrupt took 4406877 ns [ 20.048724] systemd[1]: initrd-switch-root.service: Succeeded. [ 20.051746] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 20.095296] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 20.109381] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 20.125980] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 20.166336] systemd[1]: Starting Journal Service... Starting Journal Service... [ 20.216408] systemd[1]: Listening on initctl Compatibility Named Pipe. [ OK ] Listening on initctl Compatibility Named Pipe. Mounting POSIX Message Queue File System... [FAILED] Failed to set up automount Arbitrar…rmats File System Automount Point. See 'systemctl status proc-sys-fs-binfmt_misc.automount' for details. [ OK ] Created slice system-sshd\x2dkeygen.slice. Mounting Kernel Debug File System... [ OK ] Listening on Process Core Dump Socket. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd Root File System. Mounting Huge Pages File System... Activating swap /dev/disk/by-label/SWAP... [ OK ] Listening on udev Kernel Socket. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Stopped target Initrd File Systems. [ OK ] Created slice system-serial\x2dgetty.slice. [ 20.568503] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS [ OK ] Reached target rpc_pipefs.target. Starting Apply Kernel Variables... [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Created slice User and Session Slice. [ OK ] Reached target Slices. [ OK ] Listening on udev Control Socket. Starting udev Coldplug all Devices... [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Reached target RPC Port Mapper. [ OK ] Reached target Paths. [ OK ] Created slice system-getty.slice. Starting Remount Root and Kernel File Systems... [ OK ] Reached target Local Encrypted Volumes. [ OK ] Started Journal Service. [ OK ] Mounted POSIX Message Queue File System. [ OK ] Mounted Kernel Debug File System. [ OK ] Mounted Huge Pages File System. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Apply Kernel Variables. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. Starting Configure read-only root support... Starting Create Static Device Nodes in /dev... [ OK ] Reached target Swap. Starting Flush Journal to Persistent Storage... [ OK ] Started Flush Journal to Persistent Storage. [ OK ] Started Create Static Device Nodes in /dev. Starting udev Kernel Device Manager... [ OK ] Reached target Local File Systems (Pre). Mounting /home/green/git/lustre-release... Mounting /mnt... [ OK ] Started udev Coldplug all Devices. [ OK ] Mounted /mnt. [ 21.498557] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 22.525250] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 22.722236] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 23.210258] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 23.401863] EDAC sbridge: Ver: 1.1.2 [ 27.470249] Key type dns_resolver registered [* ] A start job is running for Configur…-only root support (7s / no limit) [** ] A start job is running for Configur…-only root support (8s / no limit)[ 28.825349] NFS: Registering the id_resolver key type [ 28.834979] Key type id_resolver registered [ 28.838205] 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 (9s / no limit) [ *** ] A start job is running for Configur…only root support (10s / no limit) [ OK ] Started Configure read-only root support. [ OK ] Reached target Local File Systems. Starting Mark the need to relabel after reboot... Starting Rebuild Dynamic Linker Cache... Starting Create Volatile Files and Directories... Starting Load/Save Random Seed... [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Load/Save Random Seed. [ OK ] Started Create Volatile Files and Directories. Starting RPC Bind... Starting Update UTMP about System Boot/Shutdown... [ OK ] Started Update UTMP about System Boot/Shutdown. [ OK ] Started RPC Bind. [ OK ] Started Rebuild Dynamic Linker Cache. Starting Update is Completed... [ OK ] Started Update is Completed. [ OK ] Reached target System Initialization. [ OK ] Started dnf makecache --timer. [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Reached target Timers. [ OK ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. Starting Restore /run/initramfs on shutdown... [ OK ] Started D-Bus System Message Bus. Starting Network Manager... [ OK ] Started irqbalance daemon. [ OK ] Reached target sshd-keygen.target. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting Login Service... [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Network Manager. Starting Network Manager Wait Online... [ OK ] Reached target Network. Starting Dynamic System Tuning Daemon... Starting GSSAPI Proxy Daemon... Starting OpenSSH server daemon... Starting Hostname Service... [ OK ] Started Login Service. [ OK ] Started OpenSSH server daemon. [ OK ] Started GSSAPI Proxy Daemon. [ OK ] Reached target NFS client services. [ OK ] Reached target Remote File Systems (Pre). [ OK ] Reached target Remote File Systems. Starting Permit User Sessions... [ OK ] Started Permit User Sessions. [ OK ] Started Serial Getty on ttyS1. [ OK ] Started Command Scheduler. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Getty on tty1. [ OK ] Reached target Login Prompts. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting System Logging Service... Starting Notify NFS peers of a restart... Starting Crash recovery kernel arming... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg329-client login: [ 91.953252] libcfs: loading out-of-tree module taints kernel. [ 92.153848] Key type ._llcrypt registered [ 92.156324] Key type .llcrypt registered [ 92.878934] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [ 92.892661] alg: No test for adler32 (adler32-zlib) [ 94.407508] Lustre: Lustre: Build Version: 2.17.58_39_gb3cb314 [ 94.989116] LNet: Added LNI 192.168.203.29@tcp [8/256/0/180] [ 96.722748] Key type lgssc registered [ 98.330192] Lustre: Echo OBD driver; http://www.lustre.org/ [ 254.938630] Lustre: Mounted lustre-client - version 2.17.58_39_gb3cb314 [ 255.177679] LustreError: 5619:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [ 255.192322] LustreError: 5619:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 0 [ 257.193693] LustreError: 5671:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [ 257.203732] LustreError: 5671:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 1 [ 259.834499] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 280.072647] Lustre: DEBUG MARKER: oleg329-client.virtnet: executing check_logdir /tmp/testlogs/ [ 280.545487] Lustre: lustre-OST0000-osc-ffff9b4483961000: disconnect after 23s idle [ 287.757451] Lustre: DEBUG MARKER: oleg329-client.virtnet: executing yml_node [ 294.451045] Lustre: DEBUG MARKER: Client: 2.17.58.39 [ 299.479597] Lustre: DEBUG MARKER: MDS: 2.17.58.39 [ 304.505659] Lustre: DEBUG MARKER: OSS: 2.17.58.39 [ 306.334572] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity ============----- Mon Sep 14 05:32:18 EDT 2026 [ 329.315831] Lustre: DEBUG MARKER: - need MDS1_VERSION <= 2.16.61-1-g89cf292a8c2 (34683431 <= 34618625) for LU-18938, skip 360 [ 331.615111] Lustre: DEBUG MARKER: - need MDS1_VERSION < v2_14_55-100-g8a84c7f9c7 (34683431 < 34486116) for LU-14927, skip 0f [ 333.079980] Lustre: DEBUG MARKER: - need OST1_VERSION < v2_17_50-410-gbd8e7b9555 (34683431 < 34681754) for LU-12550, skip 216 [ 335.038379] Lustre: DEBUG MARKER: excepting tests: 42a 42c 42b 118c 118d 407 119i 216 817 411a 130b 130c 130d 130e 130f 130g [ 337.521363] Lustre: DEBUG MARKER: skipping tests SLOW=no: 27m 60i 64b 68 71 135 136 230d 300o 842 51b 51c 51e 834 [ 339.558539] Lustre: DEBUG MARKER: === sanity: start setup 05:32:51 (1789378371) === [ 339.967662] LustreError: 7635:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [ 339.989740] LustreError: 7635:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 2 previous similar messages [ 340.014140] LustreError: 7635:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 1 [ 340.026721] LustreError: 7635:0:(namei.c:956:ll_intent_lock()) Skipped 2 previous similar messages [ 349.733458] Lustre: DEBUG MARKER: oleg329-client.virtnet: executing check_config_client /mnt/lustre [ 372.335567] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 384.253651] Lustre: DEBUG MARKER: === sanity: finish setup 05:33:35 (1789378415) === [ 384.465240] LustreError: 7635:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [ 384.474224] LustreError: 7635:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 3 previous similar messages [ 384.479861] LustreError: 7635:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 1 [ 384.483229] LustreError: 7635:0:(namei.c:956:ll_intent_lock()) Skipped 3 previous similar messages [ 384.509769] LustreError: 7635:0:(dcache.c:176:ll_intent_release()) intent ffffb69a01c638d0 released [ 384.696807] LustreError: 10438:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [ 385.008977] LustreError: 10441:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [ 385.087728] LustreError: 10441:0:(namei.c:1721:ll_create_it()) VFS Op:name=f7635, dir=[0x200000401:0x1:0x0](ffff9b448958ec08), intent=open|creat [ 385.102065] LustreError: 10441:0:(namei.c:1744:ll_create_it()) inode ffff9b4489591148 need_sync_to_mds [0x200000401:0x2:0x0] [ 385.115867] LustreError: 10441:0:(dcache.c:176:ll_intent_release()) intent ffff9b44a0b426c0 released [ 385.125260] LustreError: 10441:0:(dcache.c:176:ll_intent_release()) Skipped 4 previous similar messages [ 385.312640] LustreError: 10442:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [ 393.987776] Lustre: DEBUG MARKER: == sanity test 60a: llog_test run from kernel module and test llog_reader ========================================================== 05:33:45 (1789378425) [ 398.710186] Lustre: DEBUG MARKER: SKIP: sanity test_60a missing subtest run-llog.sh [ 401.661696] Lustre: DEBUG MARKER: == sanity test 60b: limit repeated messages from CERROR/CWARN ========================================================== 05:33:53 (1789378433) [ 401.918432] LustreError: 11304:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [ 401.941186] LustreError: 11304:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 44 previous similar messages [ 401.996280] LustreError: 11304:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 0 [ 402.008849] LustreError: 11304:0:(namei.c:956:ll_intent_lock()) Skipped 31 previous similar messages [ 402.022370] LustreError: 11304:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [ 402.123817] LustreError: 11304:0:(namei.c:1721:ll_create_it()) VFS Op:name=f60b.sanity, dir=[0x200000007:0x1:0x0](ffff9b4489529148), intent=open|creat [ 402.140349] LustreError: 11304:0:(namei.c:1744:ll_create_it()) inode ffff9b4489595348 need_sync_to_mds [0x200000401:0x3:0x0] [ 402.151648] LustreError: 11304:0:(dcache.c:176:ll_intent_release()) intent ffff9b44a0b428a0 released [ 402.183643] LustreError: 11304:0:(dcache.c:176:ll_intent_release()) Skipped 1 previous similar message [ 408.544399] Lustre: lustre-OST0000-osc-ffff9b4483961000: disconnect after 23s idle [ 408.560723] Lustre: Skipped 1 previous similar message [ 410.356394] Lustre: DEBUG MARKER: == sanity test 60c: unlink file when mds full ============ 05:34:02 (1789378442) [ 413.481512] LustreError: 12012:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [ 413.489107] LustreError: 12012:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 4 previous similar messages [ 413.522679] LustreError: 12012:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 0 [ 413.530928] LustreError: 12012:0:(namei.c:956:ll_intent_lock()) Skipped 3 previous similar messages [ 413.537815] LustreError: 12012:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [ 413.578946] LustreError: 12012:0:(namei.c:1721:ll_create_it()) VFS Op:name=f60c-0, dir=[0x200000007:0x1:0x0](ffff9b4489529148), intent=open|creat [ 413.585962] LustreError: 12012:0:(namei.c:1744:ll_create_it()) inode ffff9b448952d348 need_sync_to_mds [0x200000401:0x4:0x0] [ 413.592580] LustreError: 12012:0:(dcache.c:176:ll_intent_release()) intent ffff9b4489315de0 released [ 415.556358] LustreError: 12012:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [ 415.591237] LustreError: 12012:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 71 previous similar messages [ 415.711795] LustreError: 12012:0:(namei.c:1721:ll_create_it()) VFS Op:name=f60c-72, dir=[0x200000007:0x1:0x0](ffff9b4489529148), intent=open|creat [ 415.770311] LustreError: 12012:0:(namei.c:1721:ll_create_it()) Skipped 71 previous similar messages [ 415.811922] LustreError: 12012:0:(namei.c:1744:ll_create_it()) inode ffff9b448958f448 need_sync_to_mds [0x200000401:0x4c:0x0] [ 415.844121] LustreError: 12012:0:(namei.c:1744:ll_create_it()) Skipped 71 previous similar messages [ 417.595512] LustreError: 12012:0:(dcache.c:176:ll_intent_release()) intent ffff9b44989206c0 released [ 417.611499] LustreError: 12012:0:(dcache.c:176:ll_intent_release()) Skipped 124 previous similar messages [ 419.581096] LustreError: 12012:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [ 419.588118] LustreError: 12012:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 117 previous similar messages [ 419.756918] LustreError: 12012:0:(namei.c:1721:ll_create_it()) VFS Op:name=f60c-192, dir=[0x200000007:0x1:0x0](ffff9b4489529148), intent=open|creat [ 419.771781] LustreError: 12012:0:(namei.c:1721:ll_create_it()) Skipped 119 previous similar messages [ 419.817840] LustreError: 12012:0:(namei.c:1744:ll_create_it()) inode ffff9b448961e3c8 need_sync_to_mds [0x200000401:0xc5:0x0] [ 419.823034] LustreError: 12012:0:(namei.c:1744:ll_create_it()) Skipped 120 previous similar messages [ 425.634255] LustreError: 12012:0:(dcache.c:176:ll_intent_release()) intent ffff9b44864668a0 released [ 425.646513] LustreError: 12012:0:(dcache.c:176:ll_intent_release()) Skipped 272 previous similar messages [ 427.584337] LustreError: 12012:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [ 427.594927] LustreError: 12012:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 277 previous similar messages [ 427.757844] LustreError: 12012:0:(namei.c:1721:ll_create_it()) VFS Op:name=f60c-472, dir=[0x200000007:0x1:0x0](ffff9b4489529148), intent=open|creat [ 427.771422] LustreError: 12012:0:(namei.c:1721:ll_create_it()) Skipped 279 previous similar messages [ 427.828718] LustreError: 12012:0:(namei.c:1744:ll_create_it()) inode ffff9b44896ab248 need_sync_to_mds [0x200000401:0x1de:0x0] [ 427.850470] LustreError: 12012:0:(namei.c:1744:ll_create_it()) Skipped 280 previous similar messages [ 429.488330] LustreError: 12012:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [ 429.510209] LustreError: 12012:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 2216 previous similar messages [ 429.532659] LustreError: 12012:0:(namei.c:956:ll_intent_lock()) intent lock 3 on i1 [0x200000007:0x1:0x0] suppgids 0 -1: rc 0 [ 429.538730] LustreError: 12012:0:(namei.c:956:ll_intent_lock()) Skipped 1663 previous similar messages [ 441.654336] LustreError: 12012:0:(dcache.c:176:ll_intent_release()) intent ffff9b4490e140c0 released [ 441.662642] LustreError: 12012:0:(dcache.c:176:ll_intent_release()) Skipped 666 previous similar messages [ 443.592419] LustreError: 12012:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [ 443.599201] LustreError: 12012:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 665 previous similar messages [ 443.768546] LustreError: 12012:0:(namei.c:1721:ll_create_it()) VFS Op:name=f60c-1138, dir=[0x200000007:0x1:0x0](ffff9b4489529148), intent=open|creat [ 443.827057] LustreError: 12012:0:(namei.c:1721:ll_create_it()) Skipped 665 previous similar messages [ 443.855064] LustreError: 12012:0:(namei.c:1744:ll_create_it()) inode ffff9b4488c36c08 need_sync_to_mds [0x200000401:0x476:0x0] [ 443.879408] LustreError: 12012:0:(namei.c:1744:ll_create_it()) Skipped 663 previous similar messages [ 461.492359] LustreError: 12012:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [ 461.500094] LustreError: 12012:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 5391 previous similar messages [ 461.536650] LustreError: 12012:0:(namei.c:956:ll_intent_lock()) intent lock 3 on i1 [0x200000007:0x1:0x0] suppgids 0 -1: rc 0 [ 461.548223] LustreError: 12012:0:(namei.c:956:ll_intent_lock()) Skipped 4046 previous similar messages [ 473.661742] LustreError: 12012:0:(dcache.c:176:ll_intent_release()) intent ffff9b4487d5d7e0 released [ 473.668990] LustreError: 12012:0:(dcache.c:176:ll_intent_release()) Skipped 1321 previous similar messages [ 475.615143] LustreError: 12012:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [ 475.626761] LustreError: 12012:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 1346 previous similar messages [ 475.790228] LustreError: 12012:0:(namei.c:1721:ll_create_it()) VFS Op:name=f60c-2486, dir=[0x200000007:0x1:0x0](ffff9b4489529148), intent=open|creat [ 475.796624] LustreError: 12012:0:(namei.c:1721:ll_create_it()) Skipped 1347 previous similar messages [ 475.859248] LustreError: 12012:0:(namei.c:1744:ll_create_it()) inode ffff9b4488f55b88 need_sync_to_mds [0x200000401:0x9bc:0x0] [ 475.864695] LustreError: 12012:0:(namei.c:1744:ll_create_it()) Skipped 1349 previous similar messages [ 525.496604] LustreError: 12012:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [ 525.507561] LustreError: 12012:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 9975 previous similar messages [ 525.544875] LustreError: 12012:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 0 [ 525.550855] LustreError: 12012:0:(namei.c:956:ll_intent_lock()) Skipped 7482 previous similar messages [ 537.673116] LustreError: 12012:0:(dcache.c:176:ll_intent_release()) intent ffff9b448b3be660 released [ 537.683115] LustreError: 12012:0:(dcache.c:176:ll_intent_release()) Skipped 2476 previous similar messages [ 539.659461] LustreError: 12012:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [ 539.683870] LustreError: 12012:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 2461 previous similar messages [ 539.802708] LustreError: 12012:0:(namei.c:1721:ll_create_it()) VFS Op:name=f60c-4946, dir=[0x200000007:0x1:0x0](ffff9b4489529148), intent=open|creat [ 539.813140] LustreError: 12012:0:(namei.c:1721:ll_create_it()) Skipped 2459 previous similar messages [ 539.874120] LustreError: 12012:0:(namei.c:1744:ll_create_it()) inode ffff9b4483505348 need_sync_to_mds [0x200000401:0x1358:0x0] [ 539.887952] LustreError: 12012:0:(namei.c:1744:ll_create_it()) Skipped 2459 previous similar messages [ 653.497297] LustreError: 12221:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [ 653.528523] LustreError: 12221:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 16595 previous similar messages [ 653.566079] LustreError: 12221:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 0 [ 653.580548] LustreError: 12221:0:(namei.c:956:ll_intent_lock()) Skipped 11259 previous similar messages [ 670.963485] Lustre: DEBUG MARKER: == sanity test 60d: test printk console message masking == 05:38:22 (1789378702) [ 671.306797] Lustre: DEBUG MARKER: test message ID 16187 7635 [ 677.301751] Lustre: DEBUG MARKER: == sanity test 60e: no space while new llog is being created ========================================================== 05:38:29 (1789378709) [ 677.654647] LustreError: 13478:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [ 677.667952] LustreError: 13478:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 56 previous similar messages [ 677.743381] LustreError: 13478:0:(namei.c:1721:ll_create_it()) VFS Op:name=f60e.sanity, dir=[0x200000007:0x1:0x0](ffff9b4489529148), intent=open|creat [ 677.762095] LustreError: 13478:0:(namei.c:1721:ll_create_it()) Skipped 53 previous similar messages [ 677.773419] LustreError: 13478:0:(namei.c:1744:ll_create_it()) inode ffff9b44834fdb88 need_sync_to_mds [0x200000401:0x138c:0x0] [ 677.780111] LustreError: 13478:0:(namei.c:1744:ll_create_it()) Skipped 51 previous similar messages [ 677.788751] LustreError: 13478:0:(dcache.c:176:ll_intent_release()) intent ffff9b44a0bbf3c0 released [ 677.796558] LustreError: 13478:0:(dcache.c:176:ll_intent_release()) Skipped 135 previous similar messages [ 685.628905] Lustre: DEBUG MARKER: == sanity test 60f: change debug_path works ============== 05:38:37 (1789378717) [ 685.914047] LustreError: 14068:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [ 686.045970] LustreError: dumping log to /tmp/f60f.sanity.1789378719.13915 [ 686.145327] LustreError: 14075:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [ 693.117798] Lustre: DEBUG MARKER: == sanity test 60g: transaction abort won't cause MDT hung ========================================================== 05:38:45 (1789378725) [ 693.480482] LustreError: 14660:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [ 693.622153] LustreError: 14662:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [ 693.633321] LustreError: 14662:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 1 previous similar message [ 694.642929] LustreError: 14694:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [ 694.652583] LustreError: 14694:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 4 previous similar messages [ 695.511421] LustreError: 14712:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [ 695.519371] LustreError: 14712:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 21 previous similar messages [ 696.691959] LustreError: 14748:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [ 696.704129] LustreError: 14748:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 11 previous similar messages [ 699.550417] LustreError: 14834:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [ 699.561544] LustreError: 14834:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 51 previous similar messages [ 700.730768] LustreError: 14863:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [ 700.744095] LustreError: 14863:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 25 previous similar messages [ 707.691548] LustreError: 15062:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [ 707.702317] LustreError: 15062:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 108 previous similar messages [ 708.800669] LustreError: 15095:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [ 708.810774] LustreError: 15095:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 55 previous similar messages [ 723.773814] LustreError: 15577:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [ 723.787391] LustreError: 15577:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 233 previous similar messages [ 724.844915] LustreError: 15607:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [ 724.851429] LustreError: 15607:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 115 previous similar messages [ 755.816407] LustreError: 16503:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [ 755.825134] LustreError: 16503:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 409 previous similar messages [ 756.997694] LustreError: 16536:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [ 757.012975] LustreError: 16536:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 205 previous similar messages [ 803.872894] Lustre: DEBUG MARKER: == sanity test 60h: striped directory with missing stripes can be accessed ========================================================== 05:40:35 (1789378835) [ 805.467422] Lustre: DEBUG MARKER: SKIP: sanity test_60h Need at least 2 MDTs [ 807.607078] Lustre: DEBUG MARKER: SKIP: sanity test_60i skipping SLOW test 60i [ 809.173457] Lustre: DEBUG MARKER: == sanity test 60j: llog_reader reports corruptions ====== 05:40:41 (1789378841) [ 810.652759] Lustre: DEBUG MARKER: SKIP: sanity test_60j ldiskfs only test [ 812.811074] Lustre: DEBUG MARKER: == sanity test 61a: mmap() writes don't make sync hang ========================================================================== 05:40:44 (1789378844) [ 813.102167] LustreError: 18893:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [ 819.958356] Lustre: DEBUG MARKER: == sanity test 61b: mmap() of unstriped file is successful ========================================================== 05:40:51 (1789378851) [ 820.218314] LustreError: 19466:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [ 820.228285] LustreError: 19466:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 473 previous similar messages [ 826.182232] Lustre: DEBUG MARKER: == sanity test 63a: Verify oig_wait interruption does not crash ================================================================= 05:40:58 (1789378858) [ 832.437678] LustreError: 20043:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [ 898.904837] Lustre: DEBUG MARKER: == sanity test 63b: async write errors should be returned to fsync ============================================================= 05:42:10 (1789378930) [ 902.709704] Lustre: *** cfs_fail_loc=406, val=0*** [ 902.712449] LustreError: 20744:0:(osc_request.c:2918:osc_build_rpc()) lustre-OST0001-osc-ffff9b4483961000: prep_req failed: rc = -12 [ 902.728193] LustreError: 20744:0:(osc_cache.c:2419:osc_check_rpcs()) Write request failed with -12 [ 909.625171] LustreError: 20985:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [ 909.634226] LustreError: 20985:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 10742 previous similar messages [ 909.664241] LustreError: 20985:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 0 [ 909.674681] LustreError: 20985:0:(namei.c:956:ll_intent_lock()) Skipped 8162 previous similar messages [ 917.065726] Lustre: DEBUG MARKER: == sanity test 63c: test sync_on_close=1 ================= 05:42:28 (1789378948) [ 920.355741] LustreError: 21323:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [ 929.486064] LustreError: 21545:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [ 929.509054] LustreError: 21545:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 283 previous similar messages [ 929.817869] LustreError: 21323:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [ 929.823492] LustreError: 21323:0:(file.c:977:ll_kernel_to_mds_open_flags()) Skipped 20 previous similar messages [ 934.707777] LNet: 21562:0:(debug.c:375:cfs_str2mask()) unknown mask 'entry'. [ 934.707777] mask usage: [+|-] ... [ 934.868400] LustreError: 21565:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [ 934.881964] LustreError: 21565:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 127 previous similar messages [ 934.937283] LustreError: 21565:0:(namei.c:1721:ll_create_it()) VFS Op:name=f63c.sanity-striped, dir=[0x200000401:0x18b1:0x0](ffff9b44834f9988), intent=open|creat [ 934.949470] LustreError: 21565:0:(namei.c:1721:ll_create_it()) Skipped 26 previous similar messages [ 934.957748] LustreError: 21565:0:(namei.c:1744:ll_create_it()) inode ffff9b4483519988 need_sync_to_mds [0x200000401:0x18ee:0x0] [ 934.973949] LustreError: 21565:0:(namei.c:1744:ll_create_it()) Skipped 26 previous similar messages [ 934.979363] LustreError: 21565:0:(dcache.c:176:ll_intent_release()) intent ffff9b448b3d7900 released [ 935.011478] LustreError: 21565:0:(dcache.c:176:ll_intent_release()) Skipped 2276 previous similar messages [ 938.223490] LustreError: 21577:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [ 938.237933] LustreError: 21577:0:(file.c:977:ll_kernel_to_mds_open_flags()) Skipped 19 previous similar messages [ 951.913970] Lustre: DEBUG MARKER: == sanity test 63d: Verify Open honors O_TMPFILE flag ==== 05:43:02 (1789378982) [ 952.623422] LustreError: 22162:0:(llite_lib.c:4170:ll_prep_md_op_data()) debug: Setting bias to MDS_CREATE_VOLATILE: . :VOLATILE::l0u1s2t3 [ 952.634645] LustreError: 22162:0:(mdc_lib.c:326:mdc_open_pack()) debug: create_volatile changes to mds_open_volatile [ 965.337487] Lustre: DEBUG MARKER: == sanity test 64a: verify filter grant calculations (in kernel) =============================================================== 05:43:17 (1789378997) [ 976.940903] Lustre: DEBUG MARKER: SKIP: sanity test_64b skipping SLOW test 64b [ 978.993735] Lustre: DEBUG MARKER: == sanity test 64c: verify grant shrink ================== 05:43:30 (1789379010) [ 988.034046] Lustre: DEBUG MARKER: == sanity test 64d: check grant limit exceed ============= 05:43:40 (1789379020) [ 1053.748915] Lustre: DEBUG MARKER: == sanity test 64e: check grant consumption (no grant allocation) ========================================================== 05:44:45 (1789379085) [ 1057.260893] Lustre: Unmounted lustre-client [ 1057.777290] Lustre: Mounted lustre-client - version 2.17.58_39_gb3cb314 [ 1063.743214] Lustre: Unmounted lustre-client [ 1064.330653] Lustre: Mounted lustre-client - version 2.17.58_39_gb3cb314 [ 1075.106380] Lustre: DEBUG MARKER: == sanity test 64f: check grant consumption (with grant allocation) ========================================================== 05:45:06 (1789379106) [ 1077.415150] Lustre: Unmounted lustre-client [ 1078.002045] Lustre: Mounted lustre-client - version 2.17.58_39_gb3cb314 [ 1081.587126] Lustre: Unmounted lustre-client [ 1082.087309] Lustre: Mounted lustre-client - version 2.17.58_39_gb3cb314 [ 1090.140957] Lustre: DEBUG MARKER: == sanity test 64g: grant shrink on MDT ================== 05:45:22 (1789379122) [ 1171.713936] Lustre: DEBUG MARKER: == sanity test 64h: grant shrink on read ================= 05:46:43 (1789379203) [ 1192.934188] Lustre: DEBUG MARKER: == sanity test 64i: shrink on reconnect ================== 05:47:05 (1789379225) [ 1205.226077] Lustre: lustre-OST0000-osc-ffff9b4483967000: Connection to lustre-OST0000 (at 192.168.203.129@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1219.040205] Lustre: 2348:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789379236/real 1789379236] req@ffff9b4392307480 x1876298966431104/t0(0) o17->lustre-OST0000-osc-ffff9b4483967000@192.168.203.129@tcp:28/4 lens 456/432 e 0 to 1 dl 1789379252 ref 1 fl Rpc:XQr/200/ffffffff rc 0/-1 job:'lctl.0' uid:0 gid:0 projid:4294967295 [ 1240.875368] Lustre: DEBUG MARKER: oleg329-client.virtnet: executing wait_import_state_mount (FULL|IDLE) osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid 1475 0 [ 1242.460448] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-[-0-9a-f]*.ost_server_uuid in FULL state after 0 sec [ 1255.796597] Lustre: DEBUG MARKER: == sanity test 64j: check grants on re-done rpc ========== 05:48:07 (1789379287) [ 1257.411658] LustreError: 30762:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [ 1257.494315] LustreError: 2351:0:(osc_request.c:2451:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff9b43b72f5500 x1876298966442624/t0(0) o4->lustre-OST0000-osc-ffff9b4483967000@192.168.203.129@tcp:6/4 lens 4584/448 e 0 to 0 dl 1789379306 ref 2 fl Interpret:RMQU/600/0 rc -5/-5 job:'multiop.0' uid:0 gid:0 projid:0 [ 1268.473243] Lustre: DEBUG MARKER: == sanity test 65a: directory with no stripe info ======== 05:48:20 (1789379300) [ 1268.713064] LustreError: 31418:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [ 1268.719708] LustreError: 31418:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 1 previous similar message [ 1268.942934] LustreError: 31420:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [ 1268.949484] LustreError: 31420:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 2 previous similar messages [ 1276.535850] Lustre: DEBUG MARKER: == sanity test 65b: directory setstripe -S stripe_size*2 -i 0 -c 1 ========================================================== 05:48:28 (1789379308) [ 1284.224498] Lustre: DEBUG MARKER: == sanity test 65c: directory setstripe -S stripe_size*4 -i 1 -c 1 ========================================================== 05:48:36 (1789379316) [ 1292.347989] Lustre: DEBUG MARKER: == sanity test 65d: directory setstripe -S stripe_size -c stripe_count ========================================================== 05:48:43 (1789379323) [ 1292.813458] LustreError: 33147:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [ 1292.820961] LustreError: 33147:0:(file.c:977:ll_kernel_to_mds_open_flags()) Skipped 6 previous similar messages [ 1299.518698] Lustre: DEBUG MARKER: == sanity test 65e: directory setstripe defaults ========= 05:48:51 (1789379331) [ 1309.067118] Lustre: DEBUG MARKER: == sanity test 65f: dir setstripe permission (should return error) ============================================================= 05:49:00 (1789379340) [ 1317.059368] Lustre: DEBUG MARKER: == sanity test 65g: directory setstripe -d =============== 05:49:08 (1789379348) [ 1325.842601] Lustre: DEBUG MARKER: == sanity test 65h: directory stripe info inherit ============================================================================== 05:49:17 (1789379357) [ 1333.524773] Lustre: DEBUG MARKER: == sanity test 65i: various tests to set root directory striping ========================================================== 05:49:25 (1789379365) [ 1342.788330] Lustre: DEBUG MARKER: == sanity test 65j: set default striping on root directory (bug 6367)=========================================================== 05:49:34 (1789379374) [ 1353.655163] Lustre: DEBUG MARKER: == sanity test 65k: validate manual striping works properly with deactivated OSCs ========================================================== 05:49:45 (1789379385) [ 1422.853170] LustreError: 37931:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [ 1422.894766] LustreError: 37931:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 6597 previous similar messages [ 1422.906194] LustreError: 37931:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 1 [ 1422.911935] LustreError: 37931:0:(namei.c:956:ll_intent_lock()) Skipped 4032 previous similar messages [ 1446.869863] LustreError: 37931:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [ 1446.883103] LustreError: 37931:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 2073 previous similar messages [ 1446.967971] LustreError: 37931:0:(namei.c:1721:ll_create_it()) VFS Op:name=f65k.sanity.1.985, dir=[0x200000406:0x41a:0x0](ffff9b4489676c08), intent=open|creat [ 1446.996650] LustreError: 37931:0:(namei.c:1721:ll_create_it()) Skipped 2011 previous similar messages [ 1447.003255] LustreError: 37931:0:(namei.c:1744:ll_create_it()) inode ffff9b448349aa08 need_sync_to_mds [0x200000406:0x7f5:0x0] [ 1447.017662] LustreError: 37931:0:(namei.c:1744:ll_create_it()) Skipped 2011 previous similar messages [ 1447.021743] LustreError: 37931:0:(dcache.c:176:ll_intent_release()) intent ffff9b448b229300 released [ 1447.025652] LustreError: 37931:0:(dcache.c:176:ll_intent_release()) Skipped 2217 previous similar messages [ 1487.595936] Lustre: DEBUG MARKER: == sanity test 65l: lfs find on -1 stripe dir ================================================================================== 05:51:59 (1789379519) [ 1488.381902] LustreError: 38891:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [ 1488.396911] LustreError: 38891:0:(file.c:977:ll_kernel_to_mds_open_flags()) Skipped 31 previous similar messages [ 1496.333686] Lustre: DEBUG MARKER: == sanity test 65m: normal user can't set filesystem default stripe ========================================================== 05:52:08 (1789379528) [ 1504.024355] Lustre: DEBUG MARKER: == sanity test 65n: don't inherit default layout from root for new subdirectories ========================================================== 05:52:15 (1789379535) [ 1515.129475] Lustre: DEBUG MARKER: SKIP: sanity test_65n needs >= 2 MDTs [ 1528.967961] Lustre: DEBUG MARKER: == sanity test 65o: pool inheritance for mdt component === 05:52:40 (1789379560) [ 1535.897238] LustreError: 40621:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [ 1535.908519] LustreError: 40621:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 17 previous similar messages [ 1536.060671] LustreError: 40623:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [ 1536.067420] LustreError: 40623:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 42 previous similar messages [ 1557.779254] Lustre: DEBUG MARKER: == sanity test 65p: setstripe with yaml file and huge number ========================================================== 05:53:09 (1789379589) [ 1567.398859] Lustre: DEBUG MARKER: == sanity test 65q: setstripe with >=8E offset should fail ========================================================== 05:53:18 (1789379598) [ 1575.472854] Lustre: DEBUG MARKER: == sanity test 65r: prevent all-zero offsets ============= 05:53:27 (1789379607) [ 1584.625841] Lustre: DEBUG MARKER: == sanity test 66: update inode blocks count on client ========================================================================= 05:53:36 (1789379616) [ 1605.416715] Lustre: DEBUG MARKER: == sanity test 69: verify oa2dentry return -ENOENT doesn't LBUG ================================================================ 05:53:56 (1789379636) [ 1619.149231] Lustre: DEBUG MARKER: == sanity test 70a: verify health_check, health_write don't explode (on OST) ========================================================== 05:54:11 (1789379651) [ 1633.212927] Lustre: DEBUG MARKER: SKIP: sanity test_71 skipping SLOW test 71 [ 1634.793231] Lustre: DEBUG MARKER: == sanity test 72a: Test that remove suid works properly (bug5695) ============================================================== 05:54:26 (1789379666) [ 1645.503188] Lustre: DEBUG MARKER: == sanity test 72b: Test that we keep mode setting if without file data changed (bug 24226) ========================================================== 05:54:37 (1789379677) [ 1657.530287] Lustre: DEBUG MARKER: == sanity test 73: multiple MDC requests (should not deadlock) ========================================================== 05:54:48 (1789379688) [ 1693.238896] Lustre: DEBUG MARKER: == sanity test 74a: ldlm_enqueue freed-export error path, ls (shouldn't LBUG) ========================================================== 05:55:24 (1789379724) [ 1700.791842] Lustre: DEBUG MARKER: == sanity test 74b: ldlm_enqueue freed-export error path, touch (shouldn't LBUG) ========================================================== 05:55:32 (1789379732) [ 1708.322709] Lustre: DEBUG MARKER: == sanity test 74c: ldlm_lock_create error path, (shouldn't LBUG) ========================================================== 05:55:40 (1789379740) [ 1708.778104] Lustre: *** cfs_fail_loc=319, val=0*** [ 1715.583563] Lustre: DEBUG MARKER: == sanity test 76a: confirm clients recycle inodes properly ============================================================== 05:55:47 (1789379747) [ 1830.700414] Lustre: DEBUG MARKER: == sanity test 76b: confirm clients recycle directory inodes properly ============================================================== 05:57:42 (1789379862) [ 1914.582870] Lustre: DEBUG MARKER: == sanity test 77a: normal checksum read/write operation ========================================================== 05:59:05 (1789379945) [ 1927.470854] Lustre: DEBUG MARKER: == sanity test 77b: checksum error on client write, read ========================================================== 05:59:18 (1789379958) [ 1928.147338] Lustre: *** cfs_fail_loc=409, val=0*** [ 1928.248474] LustreError: lustre-OST0000-osc-ffff9b4483967000: BAD WRITE CHECKSUM: changed on the client after we checksummed it - likely false positive due to mmap IO (bug 11742): from 192.168.203.129@tcp inode [0x200000406:0xc34:0x0] object 0x240000400:3799 extent [0-1048575], original client csum ae41f64b (type 10), server csum ae41f64a (type 10), client csum now ae41f64a [ 1928.297151] LustreError: 2349:0:(osc_request.c:2451:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff9b44af297b80 x1876298969643520/t8589936171(8589936171) o4->lustre-OST0000-osc-ffff9b4483967000@192.168.203.129@tcp:6/4 lens 488/448 e 0 to 0 dl 1789379977 ref 3 fl Interpret:RQU/604/0 rc 0/0 job:'dd.0' uid:0 gid:0 projid:0 [ 1931.977877] Lustre: DEBUG MARKER: set checksum type to crc32, rc = 0 [ 1932.110757] LustreError: 52881:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [ 1932.129060] LustreError: 52881:0:(file.c:977:ll_kernel_to_mds_open_flags()) Skipped 11 previous similar messages [ 1932.830987] Lustre: *** cfs_fail_loc=408, val=0*** [ 1932.860336] LustreError: lustre-OST0000-osc-ffff9b4483967000: BAD READ CHECKSUM: from 192.168.203.129@tcp inode [0x200000406:0xc34:0x0] object 0x240000400:3799 extent [0-1048575], client 24e1f1fa/24e1f1fa, server cb5458d0, cksum_type 1 [ 1932.900703] LustreError: 2350:0:(osc_request.c:2451:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff9b44ad72ad80 x1876298969645952/t0(0) o3->lustre-OST0000-osc-ffff9b4483967000@192.168.203.129@tcp:6/4 lens 488/440 e 0 to 0 dl 1789379982 ref 2 fl Interpret:RMQU/600/0 rc 1048576/1048576 job:'cmp.0' uid:0 gid:0 projid:0 [ 1939.193772] Lustre: DEBUG MARKER: set checksum type to adler, rc = 0 [ 1939.794978] Lustre: *** cfs_fail_loc=408, val=0*** [ 1939.807379] LustreError: lustre-OST0000-osc-ffff9b4483967000: BAD READ CHECKSUM: from 192.168.203.129@tcp inode [0x200000406:0xc34:0x0] object 0x240000400:3799 extent [0-1048575], client 51cd9a9d/51cd9a9d, server 1e439b79, cksum_type 2 [ 1939.843555] LustreError: 2351:0:(osc_request.c:2451:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff9b44b813c000 x1876298969648512/t0(0) o3->lustre-OST0000-osc-ffff9b4483967000@192.168.203.129@tcp:6/4 lens 488/440 e 0 to 0 dl 1789379989 ref 2 fl Interpret:RMQU/600/0 rc 1048576/1048576 job:'cmp.0' uid:0 gid:0 projid:0 [ 1944.965428] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 1946.146589] Lustre: *** cfs_fail_loc=408, val=0*** [ 1946.173736] LustreError: lustre-OST0000-osc-ffff9b4483967000: BAD READ CHECKSUM: from 192.168.203.129@tcp inode [0x200000406:0xc34:0x0] object 0x240000400:3799 extent [0-1048575], client aa7a03f0/aa7a03f0, server 745cc858, cksum_type 4 [ 1946.212264] LustreError: 2349:0:(osc_request.c:2451:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff9b44af295500 x1876298969650944/t0(0) o3->lustre-OST0000-osc-ffff9b4483967000@192.168.203.129@tcp:6/4 lens 488/440 e 0 to 0 dl 1789379995 ref 2 fl Interpret:RMQU/600/0 rc 1048576/1048576 job:'cmp.0' uid:0 gid:0 projid:0 [ 1951.583364] Lustre: DEBUG MARKER: set checksum type to t10ip512, rc = 0 [ 1952.746708] Lustre: *** cfs_fail_loc=408, val=0*** [ 1952.773570] LustreError: lustre-OST0000-osc-ffff9b4483967000: BAD READ CHECKSUM: from 192.168.203.129@tcp inode [0x200000406:0xc34:0x0] object 0x240000400:3799 extent [0-1048575], client 7daff627/7daff627, server ae41f64a, cksum_type 10 [ 1952.801523] LustreError: 2350:0:(osc_request.c:2451:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff9b44ad72ad80 x1876298969653120/t0(0) o3->lustre-OST0000-osc-ffff9b4483967000@192.168.203.129@tcp:6/4 lens 488/440 e 0 to 0 dl 1789380002 ref 2 fl Interpret:RMQU/600/0 rc 1048576/1048576 job:'cmp.0' uid:0 gid:0 projid:0 [ 1957.945127] Lustre: DEBUG MARKER: set checksum type to t10ip4K, rc = 0 [ 1958.822735] LustreError: lustre-OST0000-osc-ffff9b4483967000: BAD READ CHECKSUM: from 192.168.203.129@tcp inode [0x200000406:0xc34:0x0] object 0x240000400:3799 extent [0-1048575], client 7e2d04c5/7e2d04c5, server c68203e9, cksum_type 20 [ 1963.621811] Lustre: DEBUG MARKER: set checksum type to t10ip512, rc = 0 [ 1975.068740] Lustre: DEBUG MARKER: == sanity test 77c: checksum error on client read with debug ========================================================== 06:00:06 (1789380006) [ 1983.132308] Lustre: *** cfs_fail_loc=408, val=0*** [ 1983.138949] Lustre: Skipped 1 previous similar message [ 1983.149978] Lustre: 2351:0:(osc_request.c:2035:dump_all_bulk_pages()) /tmp/lustre-log-checksum_dump-osc-[0x200000406:0xc35:0x0]:[0-1048575]-7daff627-ae41f64a: dumping checksum data [ 1983.195095] LustreError: dumping log to /tmp/lustre-log.1789380016.2351 [ 1989.332014] LustreError: lustre-OST0000-osc-ffff9b4483967000: BAD READ CHECKSUM: from 192.168.203.129@tcp inode [0x200000406:0xc35:0x0] object 0x240000400:3800 extent [0-1048575], client 7daff627/7daff627, server ae41f64a, cksum_type 10 [ 1989.364539] LustreError: 2351:0:(osc_request.c:2451:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff9b44ad72a680 x1876298969662848/t0(0) o3->lustre-OST0000-osc-ffff9b4483967000@192.168.203.129@tcp:6/4 lens 488/440 e 0 to 0 dl 1789380032 ref 2 fl Interpret:RMQU/600/0 rc 1048576/1048576 job:'dd.0' uid:0 gid:0 projid:0 [ 1989.412490] LustreError: 2351:0:(osc_request.c:2451:osc_brw_redo_request()) Skipped 1 previous similar message [ 2035.919480] Lustre: DEBUG MARKER: == sanity test 77d: checksum error on OST direct write, read ========================================================== 06:01:07 (1789380067) [ 2036.695354] LustreError: 54913:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [ 2036.713269] LustreError: 54913:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 16122 previous similar messages [ 2036.751809] LustreError: 54913:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 0 [ 2036.776259] LustreError: 54913:0:(namei.c:956:ll_intent_lock()) Skipped 11329 previous similar messages [ 2037.239818] Lustre: *** cfs_fail_loc=409, val=0*** [ 2037.247046] LustreError: 2347:0:(osc_request.c:1024:osc_init_grant()) lustre-OST0001-osc-ffff9b4483967000: granted 3407872 but already consumed 10223616 [ 2037.738611] LustreError: lustre-OST0001-osc-ffff9b4483967000: BAD WRITE CHECKSUM: changed on the client after we checksummed it - likely false positive due to mmap IO (bug 11742): from 192.168.203.129@tcp inode [0x200000406:0xc37:0x0] object 0x280000400:3788 extent [0-1048575], original client csum 3dbc503e (type 10), server csum 3dbc503d (type 10), client csum now 3dbc503d [ 2037.792536] LustreError: 2349:0:(osc_request.c:2451:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff9b44b0052d80 x1876298969668864/t4294971614(4294971614) o4->lustre-OST0001-osc-ffff9b4483967000@192.168.203.129@tcp:6/4 lens 488/448 e 0 to 0 dl 1789380086 ref 2 fl Interpret:RMQU/600/0 rc 0/0 job:'directio.0' uid:0 gid:0 projid:0 [ 2040.117890] LustreError: lustre-OST0001-osc-ffff9b4483967000: BAD READ CHECKSUM: from 192.168.203.129@tcp inode [0x200000406:0xc37:0x0] object 0x280000400:3788 extent [0-1048575], client 4e6150ce/4e6150ce, server 3dbc503d, cksum_type 10 [ 2052.141994] Lustre: DEBUG MARKER: == sanity test 77f: repeat checksum error on write (expect error) ========================================================== 06:01:23 (1789380083) [ 2055.673525] Lustre: DEBUG MARKER: set checksum type to crc32, rc = 0 [ 2056.015381] LustreError: 55652:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [ 2056.035335] LustreError: 55652:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 586 previous similar messages [ 2056.164623] LustreError: 55652:0:(namei.c:1721:ll_create_it()) VFS Op:name=f77f.sanity.crc32, dir=[0x200000007:0x1:0x0](ffff9b44834fdb88), intent=open|creat [ 2056.179560] LustreError: 55652:0:(namei.c:1721:ll_create_it()) Skipped 552 previous similar messages [ 2056.204434] LustreError: 55652:0:(namei.c:1744:ll_create_it()) inode ffff9b44a02880c8 need_sync_to_mds [0x200000406:0xc38:0x0] [ 2056.219689] LustreError: 55652:0:(namei.c:1744:ll_create_it()) Skipped 552 previous similar messages [ 2056.235929] LustreError: 55652:0:(dcache.c:176:ll_intent_release()) intent ffff9b44ba771f00 released [ 2056.249200] LustreError: 55652:0:(dcache.c:176:ll_intent_release()) Skipped 1670 previous similar messages [ 2056.618647] LustreError: 2347:0:(osc_request.c:1024:osc_init_grant()) lustre-OST0000-osc-ffff9b4483967000: granted 3407872 but already consumed 13631488 [ 2057.102847] LustreError: lustre-OST0000-osc-ffff9b4483967000: BAD WRITE CHECKSUM: changed in transit before arrival at OST: from 192.168.203.129@tcp inode [0x200000406:0xc38:0x0] object 0x240000400:3801 extent [2097152-3145727], original client csum b2f1b12 (type 1), server csum b2f1b11 (type 1), client csum now b2f1b12 [ 2058.719240] LustreError: 2350:0:(osc_request.c:2608:brw_interpret()) lustre-OST0000-osc-ffff9b4483967000: too many resent retries for object: 9663677440:3801: rc = -11 [ 2061.412807] Lustre: DEBUG MARKER: set checksum type to adler, rc = 0 [ 2062.110809] LustreError: lustre-OST0001-osc-ffff9b4483967000: BAD WRITE CHECKSUM: changed in transit before arrival at OST: from 192.168.203.129@tcp inode [0x200000406:0xc39:0x0] object 0x280000400:3789 extent [0-1048575], original client csum 19eeae62 (type 2), server csum 19eeae61 (type 2), client csum now 19eeae62 [ 2062.180491] LustreError: Skipped 15 previous similar messages [ 2063.423825] LustreError: 2351:0:(osc_request.c:2608:brw_interpret()) lustre-OST0001-osc-ffff9b4483967000: too many resent retries for object: 10737419264:3789: rc = -11 [ 2063.465517] LustreError: 2351:0:(osc_request.c:2608:brw_interpret()) Skipped 7 previous similar messages [ 2066.434824] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 2067.285901] LustreError: lustre-OST0000-osc-ffff9b4483967000: BAD WRITE CHECKSUM: changed in transit before arrival at OST: from 192.168.203.129@tcp inode [0x200000406:0xc3a:0x0] object 0x240000400:3802 extent [0-1048575], original client csum b5ea7f3c (type 4), server csum b5ea7f3b (type 4), client csum now b5ea7f3c [ 2067.333817] LustreError: Skipped 15 previous similar messages [ 2068.847709] LustreError: 2351:0:(osc_request.c:2608:brw_interpret()) lustre-OST0000-osc-ffff9b4483967000: too many resent retries for object: 9663677440:3802: rc = -11 [ 2068.882299] LustreError: 2351:0:(osc_request.c:2608:brw_interpret()) Skipped 7 previous similar messages [ 2072.383768] Lustre: DEBUG MARKER: set checksum type to t10ip512, rc = 0 [ 2072.968658] Lustre: *** cfs_fail_loc=409, val=0*** [ 2072.972228] Lustre: Skipped 97 previous similar messages [ 2073.234668] LustreError: 2350:0:(osc_request.c:2451:osc_brw_redo_request()) @@@ redo for recoverable error -11 req@ffff9b44b813e680 x1876298969684224/t4294971635(4294971635) o4->lustre-OST0001-osc-ffff9b4483967000@192.168.203.129@tcp:6/4 lens 488/448 e 0 to 0 dl 1789380122 ref 2 fl Interpret:RMQU/600/0 rc 0/0 job:'directio.0' uid:0 gid:0 projid:0 [ 2073.282343] LustreError: 2350:0:(osc_request.c:2451:osc_brw_redo_request()) Skipped 25 previous similar messages [ 2074.612625] LustreError: 2351:0:(osc_request.c:2608:brw_interpret()) lustre-OST0001-osc-ffff9b4483967000: too many resent retries for object: 10737419264:3790: rc = -11 [ 2074.643165] LustreError: 2351:0:(osc_request.c:2608:brw_interpret()) Skipped 5 previous similar messages [ 2077.531360] Lustre: DEBUG MARKER: set checksum type to t10ip4K, rc = 0 [ 2078.546886] LustreError: lustre-OST0000-osc-ffff9b4483967000: BAD WRITE CHECKSUM: changed in transit before arrival at OST: from 192.168.203.129@tcp inode [0x200000406:0xc3c:0x0] object 0x240000400:3803 extent [1048576-2097151], original client csum 30ec5402 (type 20), server csum 30ec5401 (type 20), client csum now 30ec5402 [ 2078.605219] LustreError: Skipped 31 previous similar messages [ 2080.166111] LustreError: 2350:0:(osc_request.c:2608:brw_interpret()) lustre-OST0000-osc-ffff9b4483967000: too many resent retries for object: 9663677440:3803: rc = -11 [ 2080.204993] LustreError: 2350:0:(osc_request.c:2608:brw_interpret()) Skipped 7 previous similar messages [ 2091.361705] Lustre: DEBUG MARKER: set checksum type to t10ip512, rc = 0 [ 2094.792301] Lustre: DEBUG MARKER: == sanity test 77g: checksum error on OST write, read ==== 06:02:05 (1789380125) [ 2097.572237] LustreError: lustre-OST0000-osc-ffff9b4483967000: BAD WRITE CHECKSUM: changed in transit before arrival at OST: from 192.168.203.129@tcp inode [0x200000406:0xc3d:0x0] object 0x240000400:3804 extent [0-1048575], original client csum ae41f64a (type 10), server csum 2250f0d8 (type 10), client csum now ae41f64a [ 2097.625479] LustreError: Skipped 15 previous similar messages [ 2104.487327] LustreError: lustre-OST0000-osc-ffff9b4483967000: BAD READ CHECKSUM: from 192.168.203.129@tcp inode [0x200000406:0xc3d:0x0] object 0x240000400:3804 extent [0-1048575], client ae41f64a/ae41f64a, server 195ef957, cksum_type 10 [ 2118.616295] Lustre: DEBUG MARKER: == sanity test 77k: enable/disable checksum correctly ==== 06:02:30 (1789380150) [ 2127.496127] Lustre: Unmounted lustre-client [ 2128.132644] LustreError: 2347:0:(lmv_obd.c:211:lmv_notify()) activation of lustre-MDT0000_UUID failed: -22 [ 2128.196130] Lustre: Mounted lustre-client - version 2.17.58_39_gb3cb314 [ 2135.593392] Lustre: Unmounted lustre-client [ 2136.403275] Lustre: Mounted lustre-client - version 2.17.58_39_gb3cb314 [ 2141.705123] Lustre: Unmounted lustre-client [ 2142.165882] Lustre: Mounted lustre-client - version 2.17.58_39_gb3cb314 [ 2144.570927] Lustre: Unmounted lustre-client [ 2145.078277] Lustre: Mounted lustre-client - version 2.17.58_39_gb3cb314 [ 2160.466056] Lustre: DEBUG MARKER: == sanity test 77l: preferred checksum type is remembered after reconnected ========================================================== 06:03:11 (1789380191) [ 2163.062739] Lustre: DEBUG MARKER: set checksum type to invalid, rc = 22 [ 2167.089594] Lustre: DEBUG MARKER: set checksum type to crc32, rc = 0 [ 2176.983766] Lustre: DEBUG MARKER: oleg329-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff9b4483966000.ost_server_uuid 50 [ 2178.926377] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9b4483966000.ost_server_uuid in IDLE state after 0 sec [ 2186.526879] Lustre: DEBUG MARKER: oleg329-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9b4483966000.ost_server_uuid 50 [ 2189.176065] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9b4483966000.ost_server_uuid in FULL state after 0 sec [ 2191.468886] Lustre: DEBUG MARKER: set checksum type to adler, rc = 0 [ 2201.548744] Lustre: DEBUG MARKER: oleg329-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff9b4483966000.ost_server_uuid 50 [ 2207.902534] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9b4483966000.ost_server_uuid in IDLE state after 3 sec [ 2215.513898] Lustre: DEBUG MARKER: oleg329-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9b4483966000.ost_server_uuid 50 [ 2218.308869] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9b4483966000.ost_server_uuid in FULL state after 0 sec [ 2220.729837] Lustre: DEBUG MARKER: set checksum type to crc32c, rc = 0 [ 2231.436309] Lustre: DEBUG MARKER: oleg329-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff9b4483966000.ost_server_uuid 50 [ 2238.181322] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9b4483966000.ost_server_uuid in IDLE state after 3 sec [ 2247.094522] Lustre: DEBUG MARKER: oleg329-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9b4483966000.ost_server_uuid 50 [ 2249.216374] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9b4483966000.ost_server_uuid in FULL state after 0 sec [ 2251.395846] Lustre: DEBUG MARKER: set checksum type to t10ip512, rc = 0 [ 2259.836993] Lustre: DEBUG MARKER: oleg329-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff9b4483966000.ost_server_uuid 50 [ 2268.764529] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9b4483966000.ost_server_uuid in IDLE state after 6 sec [ 2277.070671] Lustre: DEBUG MARKER: oleg329-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9b4483966000.ost_server_uuid 50 [ 2279.022254] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9b4483966000.ost_server_uuid in FULL state after 0 sec [ 2281.096254] Lustre: DEBUG MARKER: set checksum type to t10ip4K, rc = 0 [ 2287.293161] Lustre: DEBUG MARKER: oleg329-client.virtnet: executing wait_import_state IDLE osc.lustre-OST0000-osc-ffff9b4483966000.ost_server_uuid 50 [ 2292.948816] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9b4483966000.ost_server_uuid in IDLE state after 4 sec [ 2300.791997] Lustre: DEBUG MARKER: oleg329-client.virtnet: executing wait_import_state FULL osc.lustre-OST0000-osc-ffff9b4483966000.ost_server_uuid 50 [ 2303.570054] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9b4483966000.ost_server_uuid in FULL state after 0 sec [ 2314.586869] Lustre: DEBUG MARKER: set checksum type to t10ip512, rc = 0 [ 2316.899459] Lustre: DEBUG MARKER: == sanity test 77m: Verify checksum_speed is correctly read ========================================================== 06:05:48 (1789380348) [ 2324.967187] Lustre: DEBUG MARKER: == sanity test 77n: Verify read from a hole inside contiguous blocks with T10PI ========================================================== 06:05:56 (1789380356) [ 2325.741329] LustreError: 65152:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [ 2325.752888] LustreError: 65152:0:(file.c:977:ll_kernel_to_mds_open_flags()) Skipped 6 previous similar messages [ 2328.412251] Lustre: DEBUG MARKER: SKIP: sanity test_77n f77n.sanity blocks not contiguous around hole [ 2330.578030] Lustre: DEBUG MARKER: == sanity test 77o: Verify checksum_type for server (mdt and ofd(obdfilter)) ========================================================== 06:06:02 (1789380362) [ 2346.225160] Lustre: DEBUG MARKER: == sanity test 78: handle large O_DIRECT writes correctly ====================================================================== 06:06:17 (1789380377) [ 2360.256858] Lustre: DEBUG MARKER: == sanity test 79: df report consistency check =========== 06:06:31 (1789380391) [ 2389.008662] Lustre: DEBUG MARKER: == sanity test 80: Page eviction is equally fast at high offsets too ========================================================== 06:07:00 (1789380420) [ 2399.704074] Lustre: DEBUG MARKER: == sanity test 81a: OST should retry write when get -ENOSPC ========================================================================= 06:07:11 (1789380431) [ 2411.510611] Lustre: DEBUG MARKER: == sanity test 81b: OST should return -ENOSPC when retry still fails ================================================================= 06:07:22 (1789380442) [ 2424.424415] Lustre: DEBUG MARKER: == sanity test 99: cvs strange file/directory operations ========================================================== 06:07:36 (1789380456) [ 2424.806978] LustreError: 69604:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [ 2424.814941] LustreError: 69604:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 525 previous similar messages [ 2436.075887] LustreError: 69610:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [ 2436.089649] LustreError: 69610:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 23 previous similar messages [ 2465.755541] Lustre: DEBUG MARKER: == sanity test 100: check local port using privileged port ========================================================== 06:08:17 (1789380497) [ 2476.097514] Lustre: DEBUG MARKER: == sanity test 101a: check read-ahead for random reads === 06:08:27 (1789380507) [ 2674.595679] LustreError: 70905:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [ 2674.607097] LustreError: 70905:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 2326 previous similar messages [ 2674.793620] LustreError: 70941:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 0 [ 2674.805278] LustreError: 70941:0:(namei.c:956:ll_intent_lock()) Skipped 1930 previous similar messages [ 2684.099714] Lustre: DEBUG MARKER: == sanity test 101b: check stride-io mode read-ahead =========================================================================== 06:11:56 (1789380716) [ 2687.081359] LustreError: 71614:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [ 2687.101654] LustreError: 71614:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 202 previous similar messages [ 2687.158440] LustreError: 71614:0:(namei.c:1721:ll_create_it()) VFS Op:name=f101b.sanity, dir=[0x200000007:0x1:0x0](ffff9b448349ec08), intent=open|creat [ 2687.176176] LustreError: 71614:0:(namei.c:1721:ll_create_it()) Skipped 72 previous similar messages [ 2687.186325] LustreError: 71614:0:(namei.c:1744:ll_create_it()) inode ffff9b4483507448 need_sync_to_mds [0x200000407:0x55:0x0] [ 2687.195419] LustreError: 71614:0:(namei.c:1744:ll_create_it()) Skipped 72 previous similar messages [ 2687.211118] LustreError: 71614:0:(dcache.c:176:ll_intent_release()) intent ffff9b44be9add80 released [ 2687.219383] LustreError: 71614:0:(dcache.c:176:ll_intent_release()) Skipped 513 previous similar messages [ 2718.181968] Lustre: DEBUG MARKER: == sanity test 101c: check stripe_size aligned read-ahead ========================================================== 06:12:30 (1789380750) [ 2809.218780] Lustre: DEBUG MARKER: == sanity test 101d: file read with and without read-ahead enabled ========================================================== 06:14:00 (1789380840) [ 3134.771618] Lustre: DEBUG MARKER: == sanity test 101e: check read-ahead for small read(1k) for small files(500k) ========================================================== 06:19:26 (1789381166) [ 3196.210266] LustreError: 74324:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [ 3196.227861] LustreError: 74324:0:(file.c:977:ll_kernel_to_mds_open_flags()) Skipped 109 previous similar messages [ 3229.490181] Lustre: DEBUG MARKER: == sanity test 101f: check mmap read performance ========= 06:21:01 (1789381261) [ 3239.800392] Lustre: DEBUG MARKER: == sanity test 101g: Big bulk(4/16 MiB) readahead ======== 06:21:12 (1789381272) [ 3250.984184] Lustre: Unmounted lustre-client [ 3250.992261] Lustre: Skipped 1 previous similar message [ 3251.534799] Lustre: Mounted lustre-client - version 2.17.58_39_gb3cb314 [ 3251.541683] Lustre: Skipped 1 previous similar message [ 3276.925902] LustreError: 75989:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [ 3276.935581] LustreError: 75989:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 1593 previous similar messages [ 3277.163953] LustreError: 76000:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 1 [ 3277.173244] LustreError: 76000:0:(namei.c:956:ll_intent_lock()) Skipped 1029 previous similar messages [ 3292.862974] Lustre: Unmounted lustre-client [ 3293.382589] Lustre: Mounted lustre-client - version 2.17.58_39_gb3cb314 [ 3299.588271] LustreError: 76515:0:(dcache.c:176:ll_intent_release()) intent ffffb69a01543b20 released [ 3299.599861] LustreError: 76515:0:(dcache.c:176:ll_intent_release()) Skipped 340 previous similar messages [ 3342.980730] Lustre: DEBUG MARKER: == sanity test 101h: Readahead should cover current read window ========================================================== 06:22:54 (1789381374) [ 3343.170548] LustreError: 77297:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [ 3343.190805] LustreError: 77297:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 116 previous similar messages [ 3343.307770] LustreError: 77297:0:(namei.c:1721:ll_create_it()) VFS Op:name=f101h.sanity, dir=[0x200000007:0x1:0x0](ffff9b44834fb248), intent=open|creat [ 3343.327674] LustreError: 77297:0:(namei.c:1721:ll_create_it()) Skipped 105 previous similar messages [ 3343.343728] LustreError: 77297:0:(namei.c:1744:ll_create_it()) inode ffff9b448351e3c8 need_sync_to_mds [0x200000409:0x1:0x0] [ 3343.361947] LustreError: 77297:0:(namei.c:1744:ll_create_it()) Skipped 105 previous similar messages [ 3365.503744] Lustre: DEBUG MARKER: == sanity test 101i: allow current readahead to exceed reservation ========================================================== 06:23:16 (1789381396) [ 3376.979411] Lustre: DEBUG MARKER: == sanity test 101j: A complete read block should be submitted when no RA ========================================================== 06:23:29 (1789381409) [ 3440.074888] Lustre: DEBUG MARKER: == sanity test 101m: read ahead for small file and last stripe of the file ========================================================== 06:24:31 (1789381471) [ 3442.824737] Lustre: DEBUG MARKER: SKIP: sanity test_101m fallocate not supported [ 3444.391347] Lustre: DEBUG MARKER: == sanity test 102a: user xattr test ============================================================================================ 06:24:36 (1789381476) [ 3452.330389] Lustre: DEBUG MARKER: == sanity test 102b: getfattr/setfattr for trusted.lov EAs ========================================================== 06:24:44 (1789381484) [ 3453.207468] LustreError: 80042:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [ 3453.217865] LustreError: 80042:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 13 previous similar messages [ 3468.293708] Lustre: DEBUG MARKER: == sanity test 102c: non-root getfattr/setfattr for lustre.lov EAs ===================================================================== 06:24:59 (1789381499) [ 3469.562163] LustreError: 80968:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [ 3469.570809] LustreError: 80968:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 17 previous similar messages [ 3479.026668] Lustre: DEBUG MARKER: == sanity test 102d: tar restore stripe info from tarfile,not keep osts ========================================================== 06:25:10 (1789381510) [ 3501.290562] Lustre: DEBUG MARKER: == sanity test 102f: tar copy files, not keep osts ======= 06:25:33 (1789381533) [ 3530.099860] Lustre: DEBUG MARKER: == sanity test 102h: grow xattr from inside inode to external block ========================================================== 06:26:01 (1789381561) [ 3533.914732] Lustre: DEBUG MARKER: save trusted.big on /mnt/lustre/f102h.sanity [ 3536.644558] Lustre: DEBUG MARKER: save trusted.sml on /mnt/lustre/f102h.sanity [ 3538.769578] Lustre: DEBUG MARKER: grow trusted.sml on /mnt/lustre/f102h.sanity [ 3541.767575] Lustre: DEBUG MARKER: trusted.big still valid after growing trusted.sml [ 3553.794328] Lustre: DEBUG MARKER: == sanity test 102ha: grow xattr from inside inode to external inode ========================================================== 06:26:25 (1789381585) [ 3556.547705] Lustre: DEBUG MARKER: save trusted.big on /mnt/lustre/f102ha.sanity [ 3558.647921] Lustre: DEBUG MARKER: save trusted.sml on /mnt/lustre/f102ha.sanity [ 3561.335787] Lustre: DEBUG MARKER: grow trusted.sml on /mnt/lustre/f102ha.sanity [ 3563.105091] Lustre: DEBUG MARKER: trusted.big still valid after growing trusted.sml [ 3566.531650] Lustre: DEBUG MARKER: save trusted.big on /mnt/lustre/f102ha.sanity [ 3574.376794] Lustre: DEBUG MARKER: == sanity test 102i: lgetxattr test on symbolic link ====================================================================== 06:26:46 (1789381606) [ 3583.281669] Lustre: DEBUG MARKER: == sanity test 102j: non-root tar restore stripe info from tarfile, not keep osts ============================================================= 06:26:55 (1789381615) [ 3604.507924] Lustre: DEBUG MARKER: == sanity test 102k: setfattr without parameter of value shouldn't cause a crash ========================================================== 06:27:16 (1789381636) [ 3613.522852] Lustre: DEBUG MARKER: == sanity test 102l: listxattr size test ============================================================================================ 06:27:25 (1789381645) [ 3621.472617] Lustre: DEBUG MARKER: == sanity test 102m: Ensure listxattr fails on small bufffer ================================================================== 06:27:33 (1789381653) [ 3629.303312] Lustre: DEBUG MARKER: == sanity test 102n: silently ignore setxattr on internal trusted xattrs ========================================================== 06:27:41 (1789381661) [ 3638.932772] Lustre: DEBUG MARKER: == sanity test 102p: check setxattr(2) correctly fails without permission ========================================================== 06:27:50 (1789381670) [ 3647.345124] Lustre: DEBUG MARKER: == sanity test 102q: flistxattr should not return trusted.link EAs for orphans ========================================================== 06:27:58 (1789381678) [ 3654.754801] Lustre: DEBUG MARKER: == sanity test 102r: set EAs with empty values =========== 06:28:06 (1789381686) [ 3663.781271] Lustre: DEBUG MARKER: == sanity test 102s: getting nonexistent xattrs should fail ========================================================== 06:28:15 (1789381695) [ 3673.906105] Lustre: DEBUG MARKER: == sanity test 102t: zero length xattr values handled correctly ========================================================== 06:28:25 (1789381705) [ 3683.247705] Lustre: DEBUG MARKER: == sanity test 103a: acl test ============================ 06:28:35 (1789381715) [ 3876.926975] LustreError: 93395:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [ 3876.954649] LustreError: 93395:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 19714 previous similar messages [ 3877.174762] LustreError: 93396:0:(namei.c:956:ll_intent_lock()) intent lock 16 on i1 [0x200000409:0x37d:0x0] suppgids 0 -1: rc 0 [ 3877.190036] LustreError: 93396:0:(namei.c:956:ll_intent_lock()) Skipped 17380 previous similar messages [ 3899.663846] LustreError: 93534:0:(dcache.c:176:ll_intent_release()) intent ffff9b43abe3b840 released [ 3899.672303] LustreError: 93534:0:(dcache.c:176:ll_intent_release()) Skipped 6964 previous similar messages [ 3943.265569] LustreError: 93796:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [ 3943.280304] LustreError: 93796:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 4210 previous similar messages [ 3943.476497] LustreError: 93797:0:(namei.c:1721:ll_create_it()) VFS Op:name=file0, dir=[0x200000409:0x502:0x0](ffff9b43ab1342c8), intent=open|creat [ 3943.498496] LustreError: 93797:0:(namei.c:1721:ll_create_it()) Skipped 1025 previous similar messages [ 3943.512473] LustreError: 93797:0:(namei.c:1744:ll_create_it()) inode ffff9b43ab12c2c8 need_sync_to_mds [0x200000409:0x503:0x0] [ 3943.535089] LustreError: 93797:0:(namei.c:1744:ll_create_it()) Skipped 1025 previous similar messages [ 4004.971583] LustreError: 93971:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [ 4004.979785] LustreError: 93971:0:(file.c:977:ll_kernel_to_mds_open_flags()) Skipped 125 previous similar messages [ 4015.591594] Lustre: DEBUG MARKER: == sanity test 103b: umask lfs setstripe ================= 06:34:07 (1789382047) [ 4222.580562] Lustre: DEBUG MARKER: == sanity test 103c: 'cp -rp' won't set empty acl ======== 06:37:33 (1789382253) [ 4223.786136] LustreError: 103555:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [ 4223.805337] LustreError: 103555:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 210 previous similar messages [ 4223.979638] LustreError: 103556:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [ 4223.987138] LustreError: 103556:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 409 previous similar messages [ 4232.620981] Lustre: DEBUG MARKER: == sanity test 103e: inheritance of big amount of default ACLs ========================================================== 06:37:44 (1789382264) [ 4265.098262] Lustre: DEBUG MARKER: == sanity test 103f: changelog doesn't interfere with default ACLs buffers ========================================================== 06:38:16 (1789382296) [ 4280.559460] Lustre: DEBUG MARKER: == sanity test 103g: no MDS_GETXATTR storm for inodes without ACL_ACCESS (LU-17238) ========================================================== 06:38:31 (1789382311) [ 4291.106382] Lustre: DEBUG MARKER: == sanity test 104a: lfs df [-ih] [path] test =================================================================================== 06:38:42 (1789382322) [ 4291.950404] Lustre: setting import lustre-OST0000_UUID INACTIVE by administrator request [ 4292.008045] Lustre: lustre-OST0000-osc-ffff9b4491009000: Connection to lustre-OST0000 (at 192.168.203.129@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 4292.058072] LustreError: lustre-OST0000-osc-ffff9b4491009000: This client was evicted by lustre-OST0000; in progress operations using this service will fail. [ 4297.734774] Lustre: DEBUG MARKER: oleg329-client.virtnet: executing wait_import_state (FULL|IDLE) osc.lustre-OST0000-osc-ffff9b4491009000.ost_server_uuid 50 [ 4299.619310] Lustre: DEBUG MARKER: osc.lustre-OST0000-osc-ffff9b4491009000.ost_server_uuid in FULL state after 0 sec [ 4307.317713] Lustre: DEBUG MARKER: == sanity test 104b: runas -u 500 -g 500 lfs check servers test ============================================================================== 06:38:59 (1789382339) [ 4315.650787] Lustre: DEBUG MARKER: == sanity test 104c: Verify df vs lfs_df stays same after recordsize change ========================================================== 06:39:07 (1789382347) [ 4341.316964] Lustre: DEBUG MARKER: == sanity test 104d: runas -u 500 -g 500 lctl dl test ==== 06:39:32 (1789382372) [ 4349.125958] Lustre: DEBUG MARKER: == sanity test 105a: flock when mounted without -o flock test ================================================================== 06:39:41 (1789382381) [ 4357.486133] Lustre: DEBUG MARKER: == sanity test 105b: fcntl when mounted without -o flock test ================================================================== 06:39:49 (1789382389) [ 4366.164599] Lustre: DEBUG MARKER: == sanity test 105c: lockf when mounted without -o flock test ========================================================== 06:39:57 (1789382397) [ 4374.507981] Lustre: DEBUG MARKER: == sanity test 105d: flock race (should not freeze) ================================================================== 06:40:06 (1789382406) [ 4374.846266] LustreError: 110773:0:(ldlm_flock.c:850:ldlm_flock_completion_ast()) cfs_fail_timeout id 315 sleeping for 10000ms [ 4384.848130] LustreError: 110773:0:(ldlm_flock.c:850:ldlm_flock_completion_ast()) cfs_fail_timeout id 315 awake [ 4392.808168] Lustre: DEBUG MARKER: == sanity test 105e: Two conflicting flocks from same process ========================================================== 06:40:24 (1789382424) [ 4400.502553] Lustre: DEBUG MARKER: == sanity test 105f: Enqueue same range flocks =========== 06:40:32 (1789382432) [ 4410.222903] Lustre: DEBUG MARKER: == sanity test 105g: ldlm_lock_debug stack test ========== 06:40:41 (1789382441) [ 4410.901414] Lustre: *** cfs_fail_loc=32f, val=0*** [ 4410.903886] LustreError: 112602:0:(ldlm_flock.c:802:ldlm_flock_completion_ast()) ### Test ldlm error stack ns: lustre-MDT0000-mdc-ffff9b4491009000 lock: ffff9b4486425800/0xbd54752cbd902199 lrc: 4/0,1 mode: PW/PW res: [0x200000409:0xb6b:0x0].0xc rrc: 2 type: FLK pid: 112601 [0->9223372036854775807] flags: 0x0 nid: local remote: 0x2014044928a0152d expref: -99 pid: 112602 timeout: 0 [ 4410.932924] CPU: 3 PID: 112602 Comm: flocks_test Kdump: loaded Tainted: G O -------- - - 4.18.0rh8.10-debug #2 [ 4410.943733] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.17.0-10.fc44 06/10/2025 [ 4410.951958] Call Trace: [ 4410.953903] ? dump_stack+0xbb/0x10e [ 4410.955661] ? ldlm_flock_completion_ast.cold.17+0xd/0x27 [ptlrpc] [ 4410.962355] ? _raw_spin_unlock+0x12/0x30 [ 4410.967317] ? unlock_res_and_lock+0x23/0x30 [ptlrpc] [ 4410.970101] ? ldlm_lock_enqueue+0x3a1/0xcd0 [ptlrpc] [ 4410.972935] ? ldlm_cli_enqueue_fini+0xadc/0x1500 [ptlrpc] [ 4410.977906] ? ldlm_cli_enqueue+0x47f/0xe40 [ptlrpc] [ 4410.987309] ? ldlm_flock_completion_ast_async+0xb30/0xb30 [ptlrpc] [ 4411.001328] ? mdc_changelog_cdev_finish+0x2c0/0x2c0 [mdc] [ 4411.009788] ? mdc_enqueue_base+0x456/0x1dd0 [mdc] [ 4411.015606] ? mdc_enqueue+0x1c/0x30 [mdc] [ 4411.019638] ? lmv_enqueue+0x28a/0x530 [lmv] [ 4411.022844] ? ll_file_flock+0x962/0x1420 [lustre] [ 4411.025707] ? ldlm_flock_completion_ast_async+0xb30/0xb30 [ptlrpc] [ 4411.029817] ? mdc_changelog_cdev_finish+0x2c0/0x2c0 [mdc] [ 4411.031787] ? __mod_memcg_lruvec_state+0x5e/0x130 [ 4411.034750] ? __mod_lruvec_state+0x5a/0x80 [ 4411.037552] ? page_add_new_anon_rmap+0x77/0x1c0 [ 4411.046565] ? slab_post_alloc_hook+0x66/0x380 [ 4411.052216] ? locks_alloc_lock+0x1f/0x90 [ 4411.055123] ? kmem_cache_alloc+0x184/0x430 [ 4411.056605] ? vfs_lock_file+0x22/0x50 [ 4411.057800] ? fcntl_setlk+0xde/0x4e0 [ 4411.065730] ? __might_sleep+0x59/0xc0 [ 4411.066924] ? do_fcntl+0x7da/0xb80 [ 4411.069291] ? __x64_sys_fcntl+0xc4/0x110 [ 4411.071052] ? do_syscall_64+0xc1/0x440 [ 4411.075912] ? entry_SYSCALL_64_after_hwframe+0x49/0xae [ 4421.186202] Lustre: DEBUG MARKER: == sanity test 105h: Flock functional verify ============= 06:40:52 (1789382452) [ 4430.948915] Lustre: DEBUG MARKER: == sanity test 105i: Flock deadlock verify =============== 06:41:02 (1789382462) [ 4436.368737] LustreError: lustre-MDT0000-mdc-ffff9b4491009000: operation ldlm_enqueue to node 192.168.203.129@tcp failed: rc = -35 [ 4444.060448] Lustre: DEBUG MARKER: == sanity test 106: attempt exec of dir followed by chown of that dir ========================================================== 06:41:15 (1789382475) [ 4451.987843] Lustre: DEBUG MARKER: == sanity test 107: Coredump on SIG ====================== 06:41:23 (1789382483) [ 4462.889888] Lustre: DEBUG MARKER: == sanity test 110: filename length checking ============= 06:41:34 (1789382494) [ 4472.024687] Lustre: DEBUG MARKER: == sanity test 116a: stripe QOS: free space balance ============================================================================= 06:41:43 (1789382503) [ 4483.239799] LustreError: 115957:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [ 4483.248769] LustreError: 115957:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 43354 previous similar messages [ 4483.291545] LustreError: 115957:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 0 [ 4483.306806] LustreError: 115957:0:(namei.c:956:ll_intent_lock()) Skipped 34082 previous similar messages [ 4499.706407] LustreError: 116409:0:(dcache.c:176:ll_intent_release()) intent ffff9b43a5137360 released [ 4499.715114] LustreError: 116409:0:(dcache.c:176:ll_intent_release()) Skipped 10734 previous similar messages [ 4543.352715] LustreError: 116713:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [ 4543.378647] LustreError: 116713:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 2130 previous similar messages [ 4543.735518] LustreError: 116715:0:(namei.c:1721:ll_create_it()) VFS Op:name=f116a.sanity-190, dir=[0x200000409:0xb74:0x0](ffff9b43ab28d348), intent=open|creat [ 4543.743530] LustreError: 116715:0:(namei.c:1721:ll_create_it()) Skipped 1815 previous similar messages [ 4543.750143] LustreError: 116715:0:(namei.c:1744:ll_create_it()) inode ffff9b43ab13cb08 need_sync_to_mds [0x200000409:0xc34:0x0] [ 4543.761554] LustreError: 116715:0:(namei.c:1744:ll_create_it()) Skipped 1815 previous similar messages [ 4692.169493] LustreError: 118604:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [ 4692.194359] LustreError: 118604:0:(file.c:977:ll_kernel_to_mds_open_flags()) Skipped 25 previous similar messages [ 4758.404942] Lustre: DEBUG MARKER: == sanity test 116b: QoS shouldn't LBUG if not enough OSTs found on the 2nd pass ========================================================== 06:46:30 (1789382790) [ 4772.789084] Lustre: DEBUG MARKER: == sanity test 117: verify osd extend ==================== 06:46:43 (1789382803) [ 4782.083952] Lustre: DEBUG MARKER: == sanity test 118a: verify O_SYNC works ================= 06:46:53 (1789382813) [ 4791.644345] Lustre: DEBUG MARKER: == sanity test 118b: Reclaim dirty pages on fatal error ==================================================================== 06:47:03 (1789382823) [ 4802.965157] Lustre: DEBUG MARKER: SKIP: sanity test_118c skipping ALWAYS excluded test 118c [ 4805.459282] Lustre: DEBUG MARKER: SKIP: sanity test_118d skipping ALWAYS excluded test 118d [ 4808.919985] Lustre: DEBUG MARKER: == sanity test 118f: Simulate unrecoverable OSC side error ==================================================================== 06:47:19 (1789382839) [ 4809.774416] Lustre: *** cfs_fail_loc=40a, val=0*** [ 4809.784247] Lustre: Skipped 63 previous similar messages [ 4809.796418] LustreError: 122329:0:(osc_request.c:2918:osc_build_rpc()) lustre-OST0001-osc-ffff9b4491009000: prep_req failed: rc = -22 [ 4809.814420] LustreError: 122329:0:(osc_cache.c:2419:osc_check_rpcs()) Write request failed with -22 [ 4824.150199] Lustre: DEBUG MARKER: == sanity test 118g: Don't stay in wait if we got local -ENOMEM ==================================================================== 06:47:33 (1789382853) [ 4825.447809] Lustre: *** cfs_fail_loc=406, val=0*** [ 4825.456150] LustreError: 122919:0:(osc_request.c:2918:osc_build_rpc()) lustre-OST0000-osc-ffff9b4491009000: prep_req failed: rc = -12 [ 4825.496233] LustreError: 122919:0:(osc_cache.c:2419:osc_check_rpcs()) Write request failed with -12 [ 4836.970339] Lustre: DEBUG MARKER: == sanity test 118h: Verify timeout in handling recoverables errors ==================================================================== 06:47:47 (1789382867) [ 4839.437715] LustreError: lustre-OST0001-osc-ffff9b4491009000: operation ost_write to node 192.168.203.129@tcp failed: rc = -5 [ 4839.444320] LustreError: 2351:0:(osc_request.c:2451:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff9b43a8eb9880 x1876298985090048/t0(0) o4->lustre-OST0001-osc-ffff9b4491009000@192.168.203.129@tcp:6/4 lens 4584/224 e 0 to 0 dl 1789382888 ref 2 fl Interpret:RMQU/600/0 rc -5/-5 job:'multiop.0' uid:0 gid:0 projid:0 [ 4839.469398] LustreError: 2351:0:(osc_request.c:2451:osc_brw_redo_request()) Skipped 17 previous similar messages [ 4840.594703] LustreError: lustre-OST0001-osc-ffff9b4491009000: operation ost_write to node 192.168.203.129@tcp failed: rc = -5 [ 4842.678159] LustreError: lustre-OST0001-osc-ffff9b4491009000: operation ost_write to node 192.168.203.129@tcp failed: rc = -5 [ 4849.782609] LustreError: lustre-OST0001-osc-ffff9b4491009000: operation ost_write to node 192.168.203.129@tcp failed: rc = -5 [ 4849.802761] LustreError: Skipped 1 previous similar message [ 4849.816457] LustreError: 2350:0:(osc_request.c:2608:brw_interpret()) lustre-OST0001-osc-ffff9b4491009000: too many resent retries for object: 10737419264:6346: rc = -5 [ 4849.842731] LustreError: 2350:0:(osc_request.c:2608:brw_interpret()) Skipped 7 previous similar messages [ 4849.863574] Lustre: 2350:0:(llite_lib.c:4348:ll_dirty_page_discard_warn()) lustre: dirty page discard: 192.168.203.129@tcp:/lustre/fid: [0x200000409:0xf52:0x0]// may get corrupted (rc -5) [ 4860.863772] Lustre: DEBUG MARKER: == sanity test 118i: Fix error before timeout in recoverable error ==================================================================== 06:48:12 (1789382892) [ 4863.837094] LustreError: lustre-OST0001-osc-ffff9b4491009000: operation ost_write to node 192.168.203.129@tcp failed: rc = -5 [ 4863.851101] LustreError: 2350:0:(osc_request.c:2451:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff9b43a8eb9180 x1876298985098112/t0(0) o4->lustre-OST0001-osc-ffff9b4491009000@192.168.203.129@tcp:6/4 lens 4584/224 e 0 to 0 dl 1789382913 ref 2 fl Interpret:RMQU/600/0 rc -5/-5 job:'multiop.0' uid:0 gid:0 projid:0 [ 4863.895892] LustreError: 2350:0:(osc_request.c:2451:osc_brw_redo_request()) Skipped 3 previous similar messages [ 4879.716831] Lustre: DEBUG MARKER: == sanity test 118j: Simulate unrecoverable OST side error ==================================================================== 06:48:31 (1789382911) [ 4882.430943] LustreError: lustre-OST0001-osc-ffff9b4491009000: operation ost_write to node 192.168.203.129@tcp failed: rc = -14 [ 4882.442884] LustreError: Skipped 2 previous similar messages [ 4893.259676] Lustre: DEBUG MARKER: == sanity test 118k: bio alloc -ENOMEM and IO TERM handling =================================================================== 06:48:44 (1789382924) [ 4895.305613] LustreError: 125791:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [ 4895.320868] LustreError: 125791:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 12 previous similar messages [ 4895.590795] LustreError: 2351:0:(osc_request.c:2451:osc_brw_redo_request()) @@@ redo for recoverable error -5 req@ffff9b43a73bc380 x1876298985108992/t0(0) o4->lustre-OST0000-osc-ffff9b4491009000@192.168.203.129@tcp:6/4 lens 488/224 e 0 to 0 dl 1789382945 ref 2 fl Interpret:ReMQU/600/0 rc -5/-5 job:'dd.0' uid:0 gid:0 projid:0 [ 4895.618078] LustreError: 2351:0:(osc_request.c:2451:osc_brw_redo_request()) Skipped 2 previous similar messages [ 4901.788696] LustreError: 125864:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [ 4901.804947] LustreError: 125864:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 18 previous similar messages [ 4915.752322] Lustre: DEBUG MARKER: == sanity test 118l: fsync dir =========================== 06:49:07 (1789382947) [ 4923.952156] Lustre: DEBUG MARKER: == sanity test 118m: fdatasync dir ======================= 06:49:15 (1789382955) [ 4931.621230] Lustre: DEBUG MARKER: == sanity test 118n: statfs() sends OST_STATFS requests in parallel ========================================================== 06:49:23 (1789382963) [ 4944.881170] Lustre: DEBUG MARKER: == sanity test 119a: Short directIO read must return actual read amount ========================================================== 06:49:36 (1789382976) [ 4952.868582] Lustre: DEBUG MARKER: == sanity test 119b: Sparse directIO read must return actual read amount ========================================================== 06:49:44 (1789382984) [ 4961.344586] Lustre: DEBUG MARKER: == sanity test 119c: Testing for direct read hitting hole ========================================================== 06:49:52 (1789382992) [ 4968.781627] Lustre: DEBUG MARKER: == sanity test 119e: Basic tests of dio read and write at various sizes ========================================================== 06:50:00 (1789383000) [ 5016.273438] Lustre: DEBUG MARKER: == sanity test 119f: dio vs dio race ===================== 06:50:48 (1789383048) [ 5067.575192] Lustre: DEBUG MARKER: == sanity test 119g: dio vs buffered I/O race ============ 06:51:39 (1789383099) [ 5083.743940] LustreError: 131303:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [ 5083.751230] LustreError: 131303:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 6382 previous similar messages [ 5083.765585] LustreError: 131303:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 0 [ 5083.774176] LustreError: 131303:0:(namei.c:956:ll_intent_lock()) Skipped 2527 previous similar messages [ 5101.861960] LustreError: 131323:0:(dcache.c:176:ll_intent_release()) intent ffffb69a01c1bb20 released [ 5101.869064] LustreError: 131323:0:(dcache.c:176:ll_intent_release()) Skipped 1987 previous similar messages [ 5115.063505] Lustre: DEBUG MARKER: == sanity test 119h: basic tests of memory unaligned dio ========================================================== 06:52:26 (1789383146) [ 5148.700068] Lustre: DEBUG MARKER: SKIP: sanity test_119i skipping ALWAYS excluded test 119i [ 5150.598161] Lustre: DEBUG MARKER: == sanity test 119j: basic tests of hybrid IO switching == 06:53:02 (1789383182) [ 5150.796658] LustreError: 132662:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [ 5150.812497] LustreError: 132662:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 869 previous similar messages [ 5150.891161] LustreError: 132662:0:(namei.c:1721:ll_create_it()) VFS Op:name=f119j.sanity, dir=[0x200000007:0x1:0x0](ffff9b44834fb248), intent=open|creat [ 5150.900123] LustreError: 132662:0:(namei.c:1721:ll_create_it()) Skipped 827 previous similar messages [ 5150.909542] LustreError: 132662:0:(namei.c:1744:ll_create_it()) inode ffff9b43ab0bba88 need_sync_to_mds [0x200000409:0xf95:0x0] [ 5150.924789] LustreError: 132662:0:(namei.c:1744:ll_create_it()) Skipped 827 previous similar messages [ 5151.182333] Lustre: *** cfs_fail_loc=1429, val=0*** [ 5159.208902] Lustre: DEBUG MARKER: == sanity test 119k: hybrid IO counting with stats and disabling ========================================================== 06:53:10 (1789383190) [ 5179.237161] Lustre: DEBUG MARKER: == sanity test 119m: Test DIO readv/writev: exercise iter duplication ========================================================== 06:53:31 (1789383211) [ 5186.805531] Lustre: DEBUG MARKER: == sanity test 119n: Test Unaligned DIO readv() and writev() with unpatched ZFS ========================================================== 06:53:39 (1789383219) [ 5188.758867] Lustre: DEBUG MARKER: SKIP: sanity test_119n zfs server without 'unaligned_dio' support [ 5190.713490] Lustre: DEBUG MARKER: == sanity test 119o: Test Unaligned DIO readv() and writev() with unpatched servers ========================================================== 06:53:42 (1789383222) [ 5192.727765] Lustre: DEBUG MARKER: SKIP: sanity test_119o need ldiskfs without 'unaligned_dio' support [ 5194.975868] Lustre: DEBUG MARKER: == sanity test 119p: Test Unaligned DIO readv() and writev() with patched servers ========================================================== 06:53:46 (1789383226) [ 5203.834805] Lustre: DEBUG MARKER: == sanity test 119q: Test patchded Unaligned DIO readv() and writev() ========================================================== 06:53:55 (1789383235) [ 5222.987207] Lustre: DEBUG MARKER: == sanity test 119r: Test error handling in unaligned DIO user copy ========================================================== 06:54:14 (1789383254) [ 5223.683123] Lustre: *** cfs_fail_loc=1437, val=0*** [ 5223.685286] LustreError: 135091:0:(osc_cache.c:2419:osc_check_rpcs()) Write request failed with -14 [ 5231.239432] Lustre: DEBUG MARKER: == sanity test 119s: full-size unaligned DIO packs matching bulk MDs ========================================================== 06:54:23 (1789383263) [ 5233.342920] Lustre: DEBUG MARKER: SKIP: sanity test_119s need client page size larger than the server's [ 5235.124312] Lustre: DEBUG MARKER: == sanity test 120a: Early Lock Cancel: mkdir test ======= 06:54:27 (1789383267) [ 5247.280962] Lustre: DEBUG MARKER: == sanity test 120b: Early Lock Cancel: create test ====== 06:54:38 (1789383278) [ 5257.649606] Lustre: DEBUG MARKER: == sanity test 120c: Early Lock Cancel: link test ======== 06:54:49 (1789383289) [ 5270.107844] Lustre: DEBUG MARKER: == sanity test 120d: Early Lock Cancel: setattr test ===== 06:55:02 (1789383302) [ 5280.673758] Lustre: DEBUG MARKER: == sanity test 120e: Early Lock Cancel: unlink test ====== 06:55:12 (1789383312) [ 5299.121327] Lustre: DEBUG MARKER: == sanity test 120f: Early Lock Cancel: rename test ====== 06:55:30 (1789383330) [ 5317.972147] Lustre: DEBUG MARKER: == sanity test 120g: Early Lock Cancel: performance test ========================================================== 06:55:49 (1789383349) [ 5505.833889] LustreError: 141649:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [ 5505.843184] LustreError: 141649:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 3 previous similar messages [ 5683.748721] LustreError: 141649:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [ 5683.759183] LustreError: 141649:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 40893 previous similar messages [ 5683.785100] LustreError: 141649:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000409:0xfb9:0x0] suppgids 0 -1: rc 0 [ 5683.791138] LustreError: 141649:0:(namei.c:956:ll_intent_lock()) Skipped 25482 previous similar messages [ 5701.892615] LustreError: 141649:0:(dcache.c:176:ll_intent_release()) intent ffffb69a01e3bdf8 released [ 5701.906571] LustreError: 141649:0:(dcache.c:176:ll_intent_release()) Skipped 15667 previous similar messages [ 5868.142345] Lustre: DEBUG MARKER: == sanity test 121: read cancel race ===================== 07:05:00 (1789383900) [ 5868.382829] LustreError: 142637:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [ 5868.396551] LustreError: 142637:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 10029 previous similar messages [ 5868.462803] LustreError: 142637:0:(namei.c:1721:ll_create_it()) VFS Op:name=f121.sanity, dir=[0x200000007:0x1:0x0](ffff9b44834fb248), intent=open|creat [ 5868.483355] LustreError: 142637:0:(namei.c:1721:ll_create_it()) Skipped 10021 previous similar messages [ 5868.504338] LustreError: 142637:0:(namei.c:1744:ll_create_it()) inode ffff9b43977e7448 need_sync_to_mds [0x200000409:0x36ca:0x0] [ 5868.515614] LustreError: 142637:0:(namei.c:1744:ll_create_it()) Skipped 10021 previous similar messages [ 5868.667498] Lustre: *** cfs_fail_loc=310, val=0*** [ 5868.761567] LustreError: 142646:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [ 5868.767191] LustreError: 142646:0:(file.c:977:ll_kernel_to_mds_open_flags()) Skipped 73 previous similar messages [ 5876.120755] Lustre: DEBUG MARKER: == sanity test 123aa: verify statahead work ============== 07:05:07 (1789383907) [ 5879.072355] LustreError: 143359:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [ 5879.093869] LustreError: 143359:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 14 previous similar messages [ 5887.259634] Lustre: DEBUG MARKER: 'ls -l' 100 files without statahead: 4 sec [ 5890.480131] Lustre: DEBUG MARKER: 'ls -l' 100 files with statahead: 1 sec [ 5937.094303] Lustre: DEBUG MARKER: 'ls -l' 1000 files without statahead: 24 sec [ 5947.117622] Lustre: DEBUG MARKER: 'ls -l' 1000 files with statahead: 7 sec [ 5948.977394] Lustre: DEBUG MARKER: 'ls -l' done [ 5973.632153] Lustre: DEBUG MARKER: unlink + rm -r /mnt/lustre/d123aa.sanity: 23 seconds [ 5986.871184] Lustre: DEBUG MARKER: == sanity test 123ab: verify statahead work by using statx ========================================================== 07:06:58 (1789384018) [ 5997.717778] Lustre: DEBUG MARKER: 'statx -l' 100 files without statahead: 2 sec [ 6000.577836] Lustre: DEBUG MARKER: 'statx -l' 100 files with statahead: 1 sec [ 6048.542859] Lustre: DEBUG MARKER: 'statx -l' 1000 files without statahead: 27 sec [ 6058.645949] Lustre: DEBUG MARKER: 'statx -l' 1000 files with statahead: 6 sec [ 6060.503991] Lustre: DEBUG MARKER: 'statx -l' done [ 6085.554731] Lustre: DEBUG MARKER: unlink + rm -r /mnt/lustre/d123ab.sanity: 23 seconds [ 6101.746784] Lustre: DEBUG MARKER: == sanity test 123ac: verify statahead work by using statx without glimpse RPCs ========================================================== 07:08:53 (1789384133) [ 6113.736450] Lustre: DEBUG MARKER: 'statx -c 0 [ 6116.741415] Lustre: DEBUG MARKER: 'statx -c 0 [ 6152.105781] Lustre: DEBUG MARKER: 'statx -c 0 [ 6160.422648] Lustre: DEBUG MARKER: 'statx -c 0 [ 6162.487042] Lustre: DEBUG MARKER: 'statx -c 0 [ 6162.753972] LustreError: 150406:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [ 6162.774121] LustreError: 150406:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 9 previous similar messages [ 6184.023789] Lustre: DEBUG MARKER: unlink + rm -r /mnt/lustre/d123ac.sanity: 19 seconds [ 6191.834137] Lustre: DEBUG MARKER: 'statx --cached=always -D' 100 files without statahead: 0 sec [ 6194.371964] Lustre: DEBUG MARKER: 'statx --cached=always -D' 100 files with statahead: 0 sec [ 6216.365981] Lustre: DEBUG MARKER: 'statx --cached=always -D' 1000 files without statahead: 1 sec [ 6218.310356] Lustre: DEBUG MARKER: 'statx --cached=always -D' 1000 files with statahead: 0 sec [ 6283.756561] LustreError: 152598:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [ 6283.768648] LustreError: 152598:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 61102 previous similar messages [ 6283.789744] LustreError: 152598:0:(namei.c:956:ll_intent_lock()) intent lock 3 on i1 [0x200000409:0x4286:0x0] suppgids 0 -1: rc 0 [ 6283.807512] LustreError: 152598:0:(namei.c:956:ll_intent_lock()) Skipped 42104 previous similar messages [ 6301.900807] LustreError: 152598:0:(dcache.c:176:ll_intent_release()) intent ffff9b4396cfd6c0 released [ 6301.918732] LustreError: 152598:0:(dcache.c:176:ll_intent_release()) Skipped 26230 previous similar messages [ 6382.801322] Lustre: DEBUG MARKER: 'statx --cached=always -D' 10000 files without statahead: 1 sec [ 6385.224844] Lustre: DEBUG MARKER: 'statx --cached=always -D' 10000 files with statahead: 1 sec [ 6387.197691] Lustre: DEBUG MARKER: 'statx --cached=always -D' done [ 6741.131699] Lustre: DEBUG MARKER: unlink + rm -r /mnt/lustre/d123ac.sanity: 352 seconds [ 6758.419957] Lustre: DEBUG MARKER: == sanity test 123ad: Verify batching statahead works correctly ========================================================== 07:19:50 (1789384790) [ 6761.861361] LustreError: 164477:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [ 6761.873287] LustreError: 164477:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 3 previous similar messages [ 6762.011153] LustreError: 164484:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [ 6762.021744] LustreError: 164484:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 13014 previous similar messages [ 6762.076905] LustreError: 164484:0:(namei.c:1721:ll_create_it()) VFS Op:name=f123ad.sanity0, dir=[0x200000409:0x6997:0x0](ffff9b4391db4b08), intent=open|creat [ 6762.089214] LustreError: 164484:0:(namei.c:1721:ll_create_it()) Skipped 13000 previous similar messages [ 6762.097827] LustreError: 164484:0:(namei.c:1744:ll_create_it()) inode ffff9b4391e81988 need_sync_to_mds [0x200000409:0x6998:0x0] [ 6762.105541] LustreError: 164484:0:(namei.c:1744:ll_create_it()) Skipped 13000 previous similar messages [ 6765.306198] LustreError: 164497:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [ 6765.313405] LustreError: 164497:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 3 previous similar messages [ 6769.546724] Lustre: DEBUG MARKER: 'ls -l' 100 files without statahead: 3 sec [ 6772.898454] Lustre: DEBUG MARKER: 'ls -l' 100 files with statahead: 1 sec [ 6817.677433] Lustre: DEBUG MARKER: 'ls -l' 1000 files without statahead: 24 sec [ 6832.562438] Lustre: DEBUG MARKER: 'ls -l' 1000 files with statahead: 11 sec [ 6835.386767] Lustre: DEBUG MARKER: 'ls -l' done [ 6861.063488] Lustre: DEBUG MARKER: unlink + rm -r /mnt/lustre/d123ad.sanity: 24 seconds [ 6883.763448] LustreError: 166706:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [ 6883.779402] LustreError: 166706:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 62853 previous similar messages [ 6883.791410] LustreError: 166706:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 1 [ 6883.798724] LustreError: 166706:0:(namei.c:956:ll_intent_lock()) Skipped 43408 previous similar messages [ 6901.910575] LustreError: 166706:0:(dcache.c:176:ll_intent_release()) intent ffff9b4396d5ef00 released [ 6901.921090] LustreError: 166706:0:(dcache.c:176:ll_intent_release()) Skipped 21619 previous similar messages [ 7483.765046] LustreError: 166993:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [ 7483.780899] LustreError: 166993:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 121919 previous similar messages [ 7483.811918] LustreError: 166993:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000409:0x6d80:0x0] suppgids 0 -1: rc 0 [ 7483.822614] LustreError: 166993:0:(namei.c:956:ll_intent_lock()) Skipped 85168 previous similar messages [ 7501.919351] LustreError: 166993:0:(dcache.c:176:ll_intent_release()) intent ffffb69a01fdbdf8 released [ 7501.937317] LustreError: 166993:0:(dcache.c:176:ll_intent_release()) Skipped 75602 previous similar messages [ 7570.805991] LustreError: 167045:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [ 7570.826923] LustreError: 167045:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 1 previous similar message [ 7570.978977] LustreError: 167052:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [ 7570.987822] LustreError: 167052:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 10999 previous similar messages [ 7571.058159] LustreError: 167052:0:(namei.c:1721:ll_create_it()) VFS Op:name=f123ad.sanity0, dir=[0x200000409:0x9491:0x0](ffff9b43974e80c8), intent=open|creat [ 7571.066623] LustreError: 167052:0:(namei.c:1721:ll_create_it()) Skipped 10999 previous similar messages [ 7571.084506] LustreError: 167052:0:(namei.c:1744:ll_create_it()) inode ffff9b43974b80c8 need_sync_to_mds [0x200000409:0x9492:0x0] [ 7571.101399] LustreError: 167052:0:(namei.c:1744:ll_create_it()) Skipped 10999 previous similar messages [ 7574.846335] LustreError: 167064:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [ 7574.854557] LustreError: 167064:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 9 previous similar messages [ 7579.820336] Lustre: DEBUG MARKER: 'ls -l' 100 files without statahead: 3 sec [ 7583.688349] Lustre: DEBUG MARKER: 'ls -l' 100 files with statahead: 1 sec [ 7636.626877] Lustre: DEBUG MARKER: 'ls -l' 1000 files without statahead: 27 sec [ 7648.000470] Lustre: DEBUG MARKER: 'ls -l' 1000 files with statahead: 7 sec [ 7649.790478] Lustre: DEBUG MARKER: 'ls -l' done [ 7677.044166] Lustre: DEBUG MARKER: unlink + rm -r /mnt/lustre/d123ad.sanity: 25 seconds [ 8083.786231] LustreError: 169875:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [ 8083.796673] LustreError: 169875:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 132263 previous similar messages [ 8250.285971] LustreError: 169875:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 1 [ 8250.314572] LustreError: 169875:0:(namei.c:956:ll_intent_lock()) Skipped 93168 previous similar messages [ 8250.361030] LustreError: 169875:0:(dcache.c:176:ll_intent_release()) intent ffffb69a0149be00 released [ 8250.370856] LustreError: 169875:0:(dcache.c:176:ll_intent_release()) Skipped 77241 previous similar messages [ 8265.906614] Lustre: DEBUG MARKER: == sanity test 123b: not panic with network error in statahead enqueue (bug 15027) ========================================================== 07:44:57 (1789386297) [ 8266.098782] LustreError: 170480:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [ 8266.104672] LustreError: 170480:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 1 previous similar message [ 8269.510784] LustreError: 170613:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [ 8269.517076] LustreError: 170613:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 10999 previous similar messages [ 8269.541509] LustreError: 170613:0:(namei.c:1721:ll_create_it()) VFS Op:name=f123b.sanity-0, dir=[0x200000409:0xbf8b:0x0](ffff9b4398ecc2c8), intent=open|creat [ 8269.550853] LustreError: 170613:0:(namei.c:1721:ll_create_it()) Skipped 10999 previous similar messages [ 8269.556650] LustreError: 170613:0:(namei.c:1744:ll_create_it()) inode ffff9b4398ecd348 need_sync_to_mds [0x200000409:0xbf8c:0x0] [ 8269.563945] LustreError: 170613:0:(namei.c:1744:ll_create_it()) Skipped 10999 previous similar messages [ 8290.538694] LustreError: 170690:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [ 8290.556436] LustreError: 170690:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 9 previous similar messages [ 8299.548655] Lustre: DEBUG MARKER: ls done [ 8328.041990] Lustre: DEBUG MARKER: == sanity test 123c: Can not initialize inode warning on DNE statahead ========================================================== 07:46:00 (1789386360) [ 8329.905083] Lustre: DEBUG MARKER: SKIP: sanity test_123c needs >= 2 MDTs [ 8331.692227] Lustre: DEBUG MARKER: == sanity test 123d: Statahead on striped directories works correctly ========================================================== 07:46:03 (1789386363) [ 8336.094395] Lustre: Unmounted lustre-client [ 8336.603611] Lustre: Mounted lustre-client - version 2.17.58_39_gb3cb314 [ 8348.225855] Lustre: DEBUG MARKER: == sanity test 123e: statahead with large wide striping == 07:46:20 (1789386380) [ 8683.834263] LustreError: 172832:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [ 8683.848720] LustreError: 172832:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 25653 previous similar messages [ 8719.515750] Lustre: DEBUG MARKER: == sanity test 123f: Retry mechanism with large wide striping files ========================================================== 07:52:31 (1789386751) [ 8852.239568] LustreError: 173021:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 1 [ 8852.269620] LustreError: 173021:0:(namei.c:956:ll_intent_lock()) Skipped 11905 previous similar messages [ 8853.206493] LustreError: 173021:0:(dcache.c:176:ll_intent_release()) intent ffff9b44a06e9180 released [ 8853.220922] LustreError: 173021:0:(dcache.c:176:ll_intent_release()) Skipped 8341 previous similar messages [ 8870.711290] LustreError: 173021:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [ 8870.716763] LustreError: 173021:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 2044 previous similar messages [ 8871.554436] LustreError: 173021:0:(namei.c:1721:ll_create_it()) VFS Op:name=f123f.sanity.40, dir=[0x20000040a:0x3ec:0x0](ffff9b4398f9b248), intent=open|creat [ 8871.565546] LustreError: 173021:0:(namei.c:1721:ll_create_it()) Skipped 2040 previous similar messages [ 8871.745944] LustreError: 173021:0:(namei.c:1744:ll_create_it()) inode ffff9b4398e842c8 need_sync_to_mds [0x20000040a:0x416:0x0] [ 8871.754476] LustreError: 173021:0:(namei.c:1744:ll_create_it()) Skipped 2040 previous similar messages [ 9285.532512] LustreError: 173021:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [ 9285.542558] LustreError: 173021:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 1186 previous similar messages [ 9327.437602] LustreError: 173133:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [ 9327.443716] LustreError: 173133:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 7 previous similar messages [ 9454.154488] LustreError: 173133:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 1 [ 9454.169796] LustreError: 173133:0:(namei.c:956:ll_intent_lock()) Skipped 627 previous similar messages [ 9454.185937] LustreError: 173133:0:(dcache.c:176:ll_intent_release()) intent ffffb69a01ebb900 released [ 9454.196443] LustreError: 173133:0:(dcache.c:176:ll_intent_release()) Skipped 344 previous similar messages [ 9885.819193] LustreError: 173629:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [ 9885.836200] LustreError: 173629:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 984 previous similar messages [10312.737591] LustreError: 173629:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 1 [10312.758462] LustreError: 173629:0:(namei.c:956:ll_intent_lock()) Skipped 605 previous similar messages [10312.841647] LustreError: 173629:0:(dcache.c:176:ll_intent_release()) intent ffffb69a00dabe00 released [10312.851946] LustreError: 173629:0:(dcache.c:176:ll_intent_release()) Skipped 257 previous similar messages [10314.958559] Lustre: DEBUG MARKER: == sanity test 123g: Test for stat-ahead advise ========== 08:19:06 (1789388346) [10320.484509] LustreError: 173860:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [10320.498877] LustreError: 173860:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 103 previous similar messages [10326.618322] LustreError: 173988:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [10326.624765] LustreError: 173988:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 160 previous similar messages [10326.713767] LustreError: 173988:0:(namei.c:1721:ll_create_it()) VFS Op:name=f123g.sanity0, dir=[0x20000040a:0x4b7:0x0](ffff9b4393b7e3c8), intent=open|creat [10326.731069] LustreError: 173988:0:(namei.c:1721:ll_create_it()) Skipped 160 previous similar messages [10326.743751] LustreError: 173988:0:(namei.c:1744:ll_create_it()) inode ffff9b43ab3ef448 need_sync_to_mds [0x20000040a:0x4b8:0x0] [10326.760518] LustreError: 173988:0:(namei.c:1744:ll_create_it()) Skipped 160 previous similar messages [10402.221525] Lustre: DEBUG MARKER: == sanity test 123h: Verify statahead work with the fname pattern ========================================================== 08:20:33 (1789388433) [10402.677168] LustreError: 174678:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [10402.865378] LustreError: 174679:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [10402.890260] LustreError: 174679:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 1000 previous similar messages [10402.985170] LustreError: 174679:0:(namei.c:1721:ll_create_it()) VFS Op:name=f123h.sanity.0, dir=[0x20000040a:0x8a0:0x0](ffff9b43ab2863c8), intent=open|creat [10403.009864] LustreError: 174679:0:(namei.c:1721:ll_create_it()) Skipped 999 previous similar messages [10403.026791] LustreError: 174679:0:(namei.c:1744:ll_create_it()) inode ffff9b43ab281988 need_sync_to_mds [0x20000040a:0x8a1:0x0] [10403.043579] LustreError: 174679:0:(namei.c:1744:ll_create_it()) Skipped 999 previous similar messages [10485.835606] LustreError: 174679:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [10485.848354] LustreError: 174679:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 12917 previous similar messages [10552.912685] LustreError: 174679:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [10552.927180] LustreError: 174679:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 2416 previous similar messages [10552.986965] LustreError: 174679:0:(namei.c:1721:ll_create_it()) VFS Op:name=f123h.sanity.2417, dir=[0x20000040a:0x8a0:0x0](ffff9b43ab2863c8), intent=open|creat [10552.996357] LustreError: 174679:0:(namei.c:1721:ll_create_it()) Skipped 2416 previous similar messages [10553.064504] LustreError: 174679:0:(namei.c:1744:ll_create_it()) inode ffff9b4381569988 need_sync_to_mds [0x20000040a:0x1213:0x0] [10553.078335] LustreError: 174679:0:(namei.c:1744:ll_create_it()) Skipped 2417 previous similar messages [10852.913753] LustreError: 174679:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [10852.922595] LustreError: 174679:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 4918 previous similar messages [10853.074582] LustreError: 174679:0:(namei.c:1721:ll_create_it()) VFS Op:name=f123h.sanity.7337, dir=[0x20000040a:0x8a0:0x0](ffff9b43ab2863c8), intent=open|creat [10853.087221] LustreError: 174679:0:(namei.c:1721:ll_create_it()) Skipped 4919 previous similar messages [10853.103679] LustreError: 174679:0:(namei.c:1744:ll_create_it()) inode ffff9b43975eba88 need_sync_to_mds [0x20000040a:0x254a:0x0] [10853.113149] LustreError: 174679:0:(namei.c:1744:ll_create_it()) Skipped 4918 previous similar messages [10912.751087] LustreError: 174679:0:(namei.c:956:ll_intent_lock()) intent lock 3 on i1 [0x20000040a:0x8a0:0x0] suppgids 0 -1: rc 0 [10912.763412] LustreError: 174679:0:(namei.c:956:ll_intent_lock()) Skipped 28978 previous similar messages [10912.873536] LustreError: 174679:0:(dcache.c:176:ll_intent_release()) intent ffff9b4388bfcf60 released [10912.879879] LustreError: 174679:0:(dcache.c:176:ll_intent_release()) Skipped 12324 previous similar messages [11027.098757] LustreError: 174779:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [11027.109369] LustreError: 174779:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 2 previous similar messages [11085.841162] LustreError: 174779:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [11085.859905] LustreError: 174779:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 57663 previous similar messages [11109.967505] LustreError: 174810:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [11342.304856] LustreError: 174845:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [11452.970274] LustreError: 174846:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [11452.983452] LustreError: 174846:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 4431 previous similar messages [11453.087842] LustreError: 174846:0:(namei.c:1721:ll_create_it()) VFS Op:name=f123h.sanity.001768, dir=[0x20000040a:0x2fb2:0x0](ffff9b4391de9988), intent=open|creat [11453.098962] LustreError: 174846:0:(namei.c:1721:ll_create_it()) Skipped 4431 previous similar messages [11453.106602] LustreError: 174846:0:(namei.c:1744:ll_create_it()) inode ffff9b43975000c8 need_sync_to_mds [0x20000040a:0x369b:0x0] [11453.114944] LustreError: 174846:0:(namei.c:1744:ll_create_it()) Skipped 4431 previous similar messages [11512.759794] LustreError: 174846:0:(namei.c:956:ll_intent_lock()) intent lock 1024 on i1 [0x20000040a:0x3a10:0x0] suppgids 0 0: rc 0 [11512.771409] LustreError: 174846:0:(namei.c:956:ll_intent_lock()) Skipped 23035 previous similar messages [11512.899893] LustreError: 174846:0:(dcache.c:176:ll_intent_release()) intent ffff9b438a3d3660 released [11512.908295] LustreError: 174846:0:(dcache.c:176:ll_intent_release()) Skipped 34578 previous similar messages [11685.852327] LustreError: 174846:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [11685.866679] LustreError: 174846:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 43400 previous similar messages [11979.571594] LustreError: 174947:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [11979.579482] LustreError: 174947:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 1 previous similar message [12060.910062] LustreError: 174977:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [12285.861361] LustreError: 174977:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [12285.871701] LustreError: 174977:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 52615 previous similar messages [12289.498605] LustreError: 174977:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 1 [12289.508251] LustreError: 174977:0:(namei.c:956:ll_intent_lock()) Skipped 32068 previous similar messages [12289.536952] LustreError: 174977:0:(dcache.c:176:ll_intent_release()) intent ffffb69a02263e00 released [12289.547867] LustreError: 174977:0:(dcache.c:176:ll_intent_release()) Skipped 37590 previous similar messages [12296.974740] Lustre: DEBUG MARKER: == sanity test 123i: Verify statahead work with the fname indexing pattern ========================================================== 08:52:09 (1789390329) [12297.495114] LustreError: 175614:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [12300.029811] LustreError: 175731:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [12304.723611] LustreError: 175731:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [12304.734176] LustreError: 175731:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 477 previous similar messages [12312.252647] LustreError: 175444:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [12312.262222] LustreError: 175444:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 8233 previous similar messages [12350.977521] LustreError: 176126:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [12350.989332] LustreError: 176126:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 521 previous similar messages [12437.708664] Lustre: DEBUG MARKER: == sanity test 123j: -ENOENT error from batched statahead be handled correctly ========================================================== 08:54:29 (1789390469) [12438.923939] Lustre: DEBUG MARKER: SKIP: sanity test_123j needs >= 2 MDTs [12440.987792] Lustre: DEBUG MARKER: == sanity test 123k: Verify statahead work with mdtest shared stat() mode ========================================================== 08:54:33 (1789390473) [12443.711423] Lustre: DEBUG MARKER: SKIP: sanity test_123k mdtest not found [12446.766988] Lustre: DEBUG MARKER: == sanity test 123l: Avoid panic when revalidate a local cached entry ========================================================== 08:54:38 (1789390478) [12446.973586] LustreError: 177926:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [12446.996047] LustreError: 177926:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 999 previous similar messages [12447.169077] LustreError: 177930:0:(namei.c:1721:ll_create_it()) VFS Op:name=f123l.sanity.000000, dir=[0x20000040a:0x5e95:0x0](ffff9b43c38f63c8), intent=open|creat [12447.187661] LustreError: 177930:0:(namei.c:1721:ll_create_it()) Skipped 8232 previous similar messages [12447.204437] LustreError: 177930:0:(namei.c:1744:ll_create_it()) inode ffff9b43939542c8 need_sync_to_mds [0x20000040a:0x5e96:0x0] [12447.222898] LustreError: 177930:0:(namei.c:1744:ll_create_it()) Skipped 8232 previous similar messages [12454.845249] LustreError: 177964:0:(statahead.c:360:sa_put()) cfs_fail_timeout id 1433 sleeping for 35000ms [12489.880120] LustreError: 177964:0:(statahead.c:360:sa_put()) cfs_fail_timeout id 1433 awake [12527.416837] LustreError: 178570:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [12527.433097] LustreError: 178570:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 1 previous similar message [12530.814454] Lustre: DEBUG MARKER: == sanity test 124a: lru resize ================================================================================================= 08:56:02 (1789390562) [12531.034513] LustreError: 178728:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [12532.388418] Lustre: DEBUG MARKER: create 2000 files at /mnt/lustre/d124a.sanity [12590.662179] Lustre: DEBUG MARKER: NSDIR=ldlm.namespaces.lustre-MDT0000-mdc-ffff9b43a4ba0000 [12593.185473] Lustre: DEBUG MARKER: NS=ldlm.namespaces.lustre-MDT0000-mdc-ffff9b43a4ba0000 [12594.981560] Lustre: DEBUG MARKER: LRU=2003 [12596.702955] Lustre: DEBUG MARKER: LIMIT=61549 [12598.222091] Lustre: DEBUG MARKER: LVF=3687400 [12599.622088] Lustre: DEBUG MARKER: OLD_LVF=100 [12601.127683] Lustre: DEBUG MARKER: Sleep 50 sec [12653.291460] Lustre: DEBUG MARKER: Dropped 1065 locks in 50s [12655.748402] Lustre: DEBUG MARKER: unlink 2000 files at /mnt/lustre/d124a.sanity [12698.706827] Lustre: DEBUG MARKER: == sanity test 124b: lru resize (performance test) ================================================================================= 08:58:50 (1789390730) [12699.474741] LustreError: 181142:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [12841.735087] Lustre: DEBUG MARKER: doing ls -la /mnt/lustre/d124b.sanity/disable_lru_resize 3 times [12842.159188] LustreError: 181505:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [12842.165809] LustreError: 181505:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 2 previous similar messages [12885.862402] LustreError: 181511:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [12885.880540] LustreError: 181511:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 96580 previous similar messages [12889.504304] LustreError: 181505:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 1 [12889.516524] LustreError: 181505:0:(namei.c:956:ll_intent_lock()) Skipped 71333 previous similar messages [12889.579204] LustreError: 181511:0:(dcache.c:176:ll_intent_release()) intent ffffb69a02033b20 released [12889.591352] LustreError: 181511:0:(dcache.c:176:ll_intent_release()) Skipped 41062 previous similar messages [13029.305328] Lustre: DEBUG MARKER: ls -la time: 186 seconds [13031.794442] Lustre: DEBUG MARKER: lru_size = 400 [13166.463716] LustreError: 182030:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [13166.476559] LustreError: 182030:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 1 previous similar message [13169.200528] LustreError: 182152:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [13169.220931] LustreError: 182152:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 10102 previous similar messages [13169.302896] LustreError: 182152:0:(namei.c:1721:ll_create_it()) VFS Op:name=f0, dir=[0x20000040a:0x860e:0x0](ffff9b4393ac3248), intent=open|creat [13169.311810] LustreError: 182152:0:(namei.c:1721:ll_create_it()) Skipped 10100 previous similar messages [13169.328713] LustreError: 182152:0:(namei.c:1744:ll_create_it()) inode ffff9b4393af2a08 need_sync_to_mds [0x20000040a:0x860f:0x0] [13169.339710] LustreError: 182152:0:(namei.c:1744:ll_create_it()) Skipped 10100 previous similar messages [13303.550541] Lustre: DEBUG MARKER: doing ls -la /mnt/lustre/d124b.sanity/enable_lru_resize 3 times [13307.452643] LustreError: 182384:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [13307.459693] LustreError: 182384:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 2 previous similar messages [13392.449942] Lustre: DEBUG MARKER: ls -la time: 84 seconds [13394.873758] Lustre: DEBUG MARKER: lru_size = 8005 [13396.582301] Lustre: DEBUG MARKER: ls -la is 54% faster with lru resize enabled [13485.870492] LustreError: 183360:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [13485.879261] LustreError: 183360:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 202357 previous similar messages [13489.506317] LustreError: 183360:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 1 [13489.518122] LustreError: 183360:0:(namei.c:956:ll_intent_lock()) Skipped 164635 previous similar messages [13494.514661] Lustre: DEBUG MARKER: == sanity test 124c: LRUR cancel very aged locks ========= 09:12:06 (1789391526) [13495.008381] LustreError: 183603:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [13495.078187] LustreError: 183604:0:(dcache.c:176:ll_intent_release()) intent ffff9b43949206c0 released [13495.083369] LustreError: 183604:0:(dcache.c:176:ll_intent_release()) Skipped 58325 previous similar messages [13527.963450] Lustre: DEBUG MARKER: == sanity test 124d: cancel very aged locks if lru-resize disabled ========================================================== 09:12:40 (1789391560) [13561.754838] Lustre: DEBUG MARKER: == sanity test 124e: LFRU keep priv locks from eviction == 09:13:13 (1789391593) [13619.634517] Lustre: DEBUG MARKER: == sanity test 124f: LFRU priv threshold inc/dec adjustment ========================================================== 09:14:11 (1789391651) [13620.324851] LustreError: 185830:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [13620.334174] LustreError: 185830:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 7 previous similar messages [13724.833963] Lustre: DEBUG MARKER: == sanity test 124g: LFRU performance test =============== 09:15:55 (1789391755) [14085.883645] LustreError: 198211:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [14085.898042] LustreError: 198211:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 59729 previous similar messages [14089.516865] LustreError: 198316:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 1 [14089.527101] LustreError: 198316:0:(namei.c:956:ll_intent_lock()) Skipped 49216 previous similar messages [14112.057441] LustreError: 199199:0:(dcache.c:176:ll_intent_release()) intent ffffb69a0505bb20 released [14112.064423] LustreError: 199199:0:(dcache.c:176:ll_intent_release()) Skipped 21074 previous similar messages [14215.711798] LustreError: 201660:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [14215.737153] LustreError: 201660:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 9 previous similar messages [14218.122961] LustreError: 201788:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [14218.129703] LustreError: 201788:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 11099 previous similar messages [14218.186739] LustreError: 201788:0:(namei.c:1721:ll_create_it()) VFS Op:name=f0, dir=[0x20000040a:0xb176:0x0](ffff9b43974c8908), intent=open|creat [14218.191439] LustreError: 201788:0:(namei.c:1721:ll_create_it()) Skipped 11099 previous similar messages [14218.195168] LustreError: 201788:0:(namei.c:1744:ll_create_it()) inode ffff9b43974cf448 need_sync_to_mds [0x20000040a:0xb177:0x0] [14218.199546] LustreError: 201788:0:(namei.c:1744:ll_create_it()) Skipped 11099 previous similar messages [14679.413510] LustreError: 216089:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [14679.427819] LustreError: 216089:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 10 previous similar messages [14685.892762] LustreError: 216089:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [14685.916717] LustreError: 216089:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 42846 previous similar messages [14689.638832] LustreError: 216089:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x20000040a:0xb176:0x0] suppgids 0 -1: rc 0 [14689.650947] LustreError: 216089:0:(namei.c:956:ll_intent_lock()) Skipped 41209 previous similar messages [14722.422165] Lustre: DEBUG MARKER: == sanity test 125: don't return EPROTO when a dir has a non-default striping and ACLs ========================================================== 09:32:34 (1789392754) [14723.058311] LustreError: 217057:0:(dcache.c:176:ll_intent_release()) intent ffff9b4390bf4b40 released [14723.064152] LustreError: 217057:0:(dcache.c:176:ll_intent_release()) Skipped 6673 previous similar messages [14729.775241] Lustre: DEBUG MARKER: == sanity test 126: check that the fsgid provided by the client is taken into account ========================================================== 09:32:41 (1789392761) [14738.244617] Lustre: DEBUG MARKER: == sanity test 127a: verify the client stats are sane ==== 09:32:50 (1789392770) [14750.826581] Lustre: DEBUG MARKER: == sanity test 127b: verify the llite client stats are sane ========================================================== 09:33:02 (1789392782) [14751.287820] LustreError: 218799:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [14759.040738] Lustre: DEBUG MARKER: == sanity test 127c: test llite extent stats with regular [14795.783785] Lustre: DEBUG MARKER: == sanity test 127d: OSC RPC latency histograms for read and write latency ========================================================== 09:33:46 (1789392826) [14810.527034] Lustre: DEBUG MARKER: == sanity test 127e: client IO latency histograms by size ========================================================== 09:34:01 (1789392841) [14829.420737] Lustre: DEBUG MARKER: == sanity test 127f: OST IO latency histograms by size === 09:34:21 (1789392861) [14831.491368] Lustre: DEBUG MARKER: SKIP: sanity test_127f ldiskfs only [14833.283425] Lustre: DEBUG MARKER: == sanity test 127g: cached_read_bytes tracks page cache hits ========================================================== 09:34:25 (1789392865) [14833.669396] LustreError: 221711:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [14833.680074] LustreError: 221711:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 567 previous similar messages [14833.746395] LustreError: 221711:0:(namei.c:1721:ll_create_it()) VFS Op:name=f127g.sanity, dir=[0x200000007:0x1:0x0](ffff9b4398cd21c8), intent=open|creat [14833.763273] LustreError: 221711:0:(namei.c:1721:ll_create_it()) Skipped 522 previous similar messages [14833.775984] LustreError: 221711:0:(namei.c:1744:ll_create_it()) inode ffff9b4398ed5b88 need_sync_to_mds [0x20000040a:0xb38c:0x0] [14833.789830] LustreError: 221711:0:(namei.c:1744:ll_create_it()) Skipped 522 previous similar messages [14835.660923] bash (221564): drop_caches: 3 [14836.584705] bash (221564): drop_caches: 3 [14836.985565] LustreError: 221739:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [14836.997417] LustreError: 221739:0:(file.c:977:ll_kernel_to_mds_open_flags()) Skipped 17 previous similar messages [14837.921829] bash (221564): drop_caches: 3 [14845.624797] Lustre: DEBUG MARKER: == sanity test 128: interactive lfs for 2 consecutive find's ========================================================== 09:34:37 (1789392877) [14852.458335] Lustre: DEBUG MARKER: == sanity test 129: test directory size limit ================================================================================== 09:34:44 (1789392884) [14854.207683] Lustre: DEBUG MARKER: SKIP: sanity test_129 ldiskfs only test [14856.440475] Lustre: DEBUG MARKER: == sanity test 130a: FIEMAP (1-stripe file) ============== 09:34:48 (1789392888) [14859.301603] Lustre: DEBUG MARKER: SKIP: sanity test_130a LU-1941: FIEMAP unimplemented on ZFS [14861.123361] Lustre: DEBUG MARKER: SKIP: sanity test_130b skipping ALWAYS excluded test 130b [14863.229506] Lustre: DEBUG MARKER: SKIP: sanity test_130c skipping ALWAYS excluded test 130c [14865.093285] Lustre: DEBUG MARKER: SKIP: sanity test_130d skipping ALWAYS excluded test 130d [14867.076534] Lustre: DEBUG MARKER: SKIP: sanity test_130e skipping ALWAYS excluded test 130e [14869.440902] Lustre: DEBUG MARKER: SKIP: sanity test_130f skipping ALWAYS excluded test 130f [14871.233791] Lustre: DEBUG MARKER: SKIP: sanity test_130g skipping ALWAYS excluded test 130g [14872.785783] Lustre: DEBUG MARKER: == sanity test 130h: FIEMAP deadlock ===================== 09:35:04 (1789392904) [14874.657188] LustreError: 224358:0:(osc_object.c:271:osc_object_fiemap()) cfs_fail_timeout id 418 sleeping for 5000ms [14879.760329] LustreError: 224358:0:(osc_object.c:271:osc_object_fiemap()) cfs_fail_timeout id 418 awake [14885.757819] Lustre: DEBUG MARKER: == sanity test 130i: FIEMAP (DoM file) =================== 09:35:17 (1789392917) [14887.409901] Lustre: DEBUG MARKER: SKIP: sanity test_130i LU-1941: FIEMAP unimplemented on ZFS [14889.083946] Lustre: DEBUG MARKER: == sanity test 131a: test iov's crossing stripe boundary for writev/readv ========================================================== 09:35:21 (1789392921) [14896.501661] Lustre: DEBUG MARKER: == sanity test 131b: test append writev ================== 09:35:28 (1789392928) [14904.063968] Lustre: DEBUG MARKER: == sanity test 131c: test read/write on file w/o objects ========================================================== 09:35:35 (1789392935) [14912.256334] Lustre: DEBUG MARKER: == sanity test 131d: test short read ===================== 09:35:43 (1789392943) [14920.985155] Lustre: DEBUG MARKER: == sanity test 131e: test read hitting hole ============== 09:35:52 (1789392952) [14930.247652] Lustre: DEBUG MARKER: == sanity test 133a: Verifying MDT stats ================================================================================================== 09:36:02 (1789392962) [14932.367590] LustreError: 228151:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [14932.373673] LustreError: 228151:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 3 previous similar messages [14960.482607] Lustre: DEBUG MARKER: == sanity test 133b: Verifying extra MDT stats ============================================================================================ 09:36:32 (1789392992) [14985.503957] Lustre: DEBUG MARKER: == sanity test 133c: Verifying OST stats ================================================================================================== 09:36:57 (1789393017) [14999.836696] LustreError: 229965:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [14999.844156] LustreError: 229965:0:(file.c:977:ll_kernel_to_mds_open_flags()) Skipped 6 previous similar messages [15043.616494] Lustre: DEBUG MARKER: == sanity test 133d: Verifying rename_stats ================================================================================================== 09:37:54 (1789393074) [15094.634155] Lustre: DEBUG MARKER: == sanity test 133e: Verifying OST read_bytes write_bytes nid stats =========================================================================== 09:38:46 (1789393126) [15110.460592] Lustre: DEBUG MARKER: == sanity test 133f: Check reads/writes of client lustre proc files with bad area io ========================================================== 09:39:02 (1789393142) [15113.801590] LNet: 232659:0:(debug.c:375:cfs_str2mask()) unknown mask ''. [15113.801590] mask usage: [+|-] ... [15114.471864] LNet: 232700:0:(debug.c:375:cfs_str2mask()) unknown mask ''. [15114.471864] mask usage: [+|-] ... [15114.495449] LNet: 232700:0:(debug.c:375:cfs_str2mask()) Skipped 5 previous similar messages [15114.528851] Lustre: DEBUG MARKER:  [15130.219900] Lustre: Unmounted lustre-client [15160.850452] Key type lgssc unregistered [15161.079958] LNet: 233690:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [15161.090859] LNetError: 233690:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [15161.113750] LNet: Removed LNI 192.168.203.29@tcp [15162.434309] Key type .llcrypt unregistered [15162.440862] Key type ._llcrypt unregistered [15175.032717] Key type ._llcrypt registered [15175.036209] Key type .llcrypt registered [15175.526206] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [15175.553434] alg: No test for adler32 (adler32-zlib) [15177.138308] Lustre: Lustre: Build Version: 2.17.58_39_gb3cb314 [15178.209805] LNet: Added LNI 192.168.203.29@tcp [8/256/0/180] [15180.072803] Key type lgssc registered [15182.054927] Lustre: Echo OBD driver; http://www.lustre.org/ [15270.494810] Lustre: Mounted lustre-client - version 2.17.58_39_gb3cb314 [15270.882640] LustreError: 235759:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [15270.920817] LustreError: 235759:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 0 [15273.197123] LustreError: 235811:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [15273.207756] LustreError: 235811:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 1 [15277.521205] Lustre: DEBUG MARKER: Using TIMEOUT=20 [15292.873406] Lustre: DEBUG MARKER: == sanity test 133g: Check reads/writes of server lustre proc files with bad area io ========================================================== 09:42:04 (1789393324) [15295.968842] Lustre: lustre-OST0000-osc-ffff9b449100c000: disconnect after 23s idle [15368.452441] LustreError: 236979:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [15368.460420] LustreError: 236979:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 2 previous similar messages [15368.470162] LustreError: 236979:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 1 [15368.478178] LustreError: 236979:0:(namei.c:956:ll_intent_lock()) Skipped 2 previous similar messages [15370.544420] LustreError: 236980:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [15370.554564] LustreError: 236980:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 1 [15370.698209] Lustre: Unmounted lustre-client [15401.272360] Key type lgssc unregistered [15401.715175] LNet: 237460:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [15401.723339] LNetError: 237460:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [15401.742575] LNet: Removed LNI 192.168.203.29@tcp [15402.512341] Key type .llcrypt unregistered [15402.514670] Key type ._llcrypt unregistered [15413.447294] Key type ._llcrypt registered [15413.449298] Key type .llcrypt registered [15414.162120] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [15414.180542] alg: No test for adler32 (adler32-zlib) [15415.440852] Lustre: Lustre: Build Version: 2.17.58_39_gb3cb314 [15415.859825] LNet: Added LNI 192.168.203.29@tcp [8/256/0/180] [15417.608387] Key type lgssc registered [15419.382433] Lustre: Echo OBD driver; http://www.lustre.org/ [15508.166847] Lustre: Mounted lustre-client - version 2.17.58_39_gb3cb314 [15508.408553] LustreError: 239534:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [15508.424617] LustreError: 239534:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 0 [15510.450305] LustreError: 239587:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [15510.460872] LustreError: 239587:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 1 [15513.908327] Lustre: DEBUG MARKER: Using TIMEOUT=20 [15527.786726] Lustre: DEBUG MARKER: == sanity test 133h: Proc files should end with newlines ========================================================== 09:45:59 (1789393559) [15534.050490] Lustre: lustre-OST0000-osc-ffff9b4398427000: disconnect after 24s idle [15564.770758] Lustre: lustre-OST0000-osc-ffff9b4398427000: disconnect after 22s idle [15564.773557] Lustre: Skipped 1 previous similar message [15600.615482] Lustre: lustre-OST0000-osc-ffff9b4398427000: disconnect after 23s idle [15600.619727] Lustre: Skipped 1 previous similar message [15605.728498] Lustre: lustre-OST0001-osc-ffff9b4398427000: disconnect after 24s idle [16597.776996] Lustre: DEBUG MARKER: == sanity test 134a: Server reclaims locks when reaching lock_reclaim_threshold ========================================================== 10:03:49 (1789394629) [16598.398664] LustreError: 255570:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [16598.406356] LustreError: 255570:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 2 previous similar messages [16598.414469] LustreError: 255570:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 1 [16598.428278] LustreError: 255570:0:(namei.c:956:ll_intent_lock()) Skipped 2 previous similar messages [16598.463402] LustreError: 255570:0:(dcache.c:176:ll_intent_release()) intent ffffb69a07f5b930 released [16598.489268] LustreError: 255570:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [16601.375874] LustreError: 255702:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [16601.389653] LustreError: 255702:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 6 previous similar messages [16601.404631] LustreError: 255702:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 0 [16601.418087] LustreError: 255702:0:(namei.c:956:ll_intent_lock()) Skipped 5 previous similar messages [16601.455278] LustreError: 255702:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [16601.515503] LustreError: 255702:0:(namei.c:1721:ll_create_it()) VFS Op:name=f0, dir=[0x2000013a1:0x1:0x0](ffff9b44a10cd348), intent=open|creat [16601.532426] LustreError: 255702:0:(namei.c:1744:ll_create_it()) inode ffff9b44a10c9988 need_sync_to_mds [0x2000013a1:0x2:0x0] [16601.540981] LustreError: 255702:0:(dcache.c:176:ll_intent_release()) intent ffff9b4392791de0 released [16601.556167] LustreError: 255702:0:(dcache.c:176:ll_intent_release()) Skipped 1 previous similar message [16601.959480] LustreError: 255702:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [16601.967634] LustreError: 255702:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 16 previous similar messages [16602.047266] LustreError: 255702:0:(namei.c:1721:ll_create_it()) VFS Op:name=f18, dir=[0x2000013a1:0x1:0x0](ffff9b44a10cd348), intent=open|creat [16602.066140] LustreError: 255702:0:(namei.c:1721:ll_create_it()) Skipped 17 previous similar messages [16602.088598] LustreError: 255702:0:(namei.c:1744:ll_create_it()) inode ffff9b44a10cf448 need_sync_to_mds [0x2000013a1:0x14:0x0] [16602.099324] LustreError: 255702:0:(namei.c:1744:ll_create_it()) Skipped 17 previous similar messages [16602.383676] LustreError: 255702:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [16602.402134] LustreError: 255702:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 98 previous similar messages [16602.437718] LustreError: 255702:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 1 [16602.443513] LustreError: 255702:0:(namei.c:956:ll_intent_lock()) Skipped 66 previous similar messages [16602.558416] LustreError: 255702:0:(dcache.c:176:ll_intent_release()) intent ffff9b4487fe7c60 released [16602.568883] LustreError: 255702:0:(dcache.c:176:ll_intent_release()) Skipped 37 previous similar messages [16602.974370] LustreError: 255702:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [16602.998316] LustreError: 255702:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 45 previous similar messages [16603.060569] LustreError: 255702:0:(namei.c:1721:ll_create_it()) VFS Op:name=f63, dir=[0x2000013a1:0x1:0x0](ffff9b44a10cd348), intent=open|creat [16603.075368] LustreError: 255702:0:(namei.c:1721:ll_create_it()) Skipped 44 previous similar messages [16603.089391] LustreError: 255702:0:(namei.c:1744:ll_create_it()) inode ffff9b44a10c80c8 need_sync_to_mds [0x2000013a1:0x41:0x0] [16603.099729] LustreError: 255702:0:(namei.c:1744:ll_create_it()) Skipped 44 previous similar messages [16604.385511] LustreError: 255702:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [16604.395120] LustreError: 255702:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 264 previous similar messages [16604.451169] LustreError: 255702:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 1 [16604.474357] LustreError: 255702:0:(namei.c:956:ll_intent_lock()) Skipped 179 previous similar messages [16604.564455] LustreError: 255702:0:(dcache.c:176:ll_intent_release()) intent ffff9b43c22af000 released [16604.573742] LustreError: 255702:0:(dcache.c:176:ll_intent_release()) Skipped 87 previous similar messages [16604.978338] LustreError: 255702:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [16604.987844] LustreError: 255702:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 85 previous similar messages [16605.063158] LustreError: 255702:0:(namei.c:1721:ll_create_it()) VFS Op:name=f151, dir=[0x2000013a1:0x1:0x0](ffff9b44a10cd348), intent=open|creat [16605.073891] LustreError: 255702:0:(namei.c:1721:ll_create_it()) Skipped 87 previous similar messages [16605.093577] LustreError: 255702:0:(namei.c:1744:ll_create_it()) inode ffff9b4483421148 need_sync_to_mds [0x2000013a1:0x9a:0x0] [16605.109629] LustreError: 255702:0:(namei.c:1744:ll_create_it()) Skipped 88 previous similar messages [16608.385558] LustreError: 255702:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [16608.397863] LustreError: 255702:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 760 previous similar messages [16608.452269] LustreError: 255702:0:(namei.c:956:ll_intent_lock()) intent lock 3 on i1 [0x2000013a1:0x1:0x0] suppgids 0 -1: rc 0 [16608.458869] LustreError: 255702:0:(namei.c:956:ll_intent_lock()) Skipped 508 previous similar messages [16608.572664] LustreError: 255702:0:(dcache.c:176:ll_intent_release()) intent ffff9b44bcfc1720 released [16608.578941] LustreError: 255702:0:(dcache.c:176:ll_intent_release()) Skipped 254 previous similar messages [16608.988724] LustreError: 255702:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [16608.996974] LustreError: 255702:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 254 previous similar messages [16609.100394] LustreError: 255702:0:(namei.c:1721:ll_create_it()) VFS Op:name=f406, dir=[0x2000013a1:0x1:0x0](ffff9b44a10cd348), intent=open|creat [16609.110305] LustreError: 255702:0:(namei.c:1721:ll_create_it()) Skipped 254 previous similar messages [16609.117825] LustreError: 255702:0:(namei.c:1744:ll_create_it()) inode ffff9b4489a70908 need_sync_to_mds [0x2000013a1:0x198:0x0] [16609.124898] LustreError: 255702:0:(namei.c:1744:ll_create_it()) Skipped 253 previous similar messages [16616.397556] LustreError: 255702:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [16616.405965] LustreError: 255702:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 1394 previous similar messages [16616.455303] LustreError: 255702:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 1 [16616.460411] LustreError: 255702:0:(namei.c:956:ll_intent_lock()) Skipped 930 previous similar messages [16616.582443] LustreError: 255702:0:(dcache.c:176:ll_intent_release()) intent ffff9b449069dd20 released [16616.589739] LustreError: 255702:0:(dcache.c:176:ll_intent_release()) Skipped 470 previous similar messages [16616.993286] LustreError: 255702:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [16617.007558] LustreError: 255702:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 472 previous similar messages [16617.107951] LustreError: 255702:0:(namei.c:1721:ll_create_it()) VFS Op:name=f880, dir=[0x2000013a1:0x1:0x0](ffff9b44a10cd348), intent=open|creat [16617.117259] LustreError: 255702:0:(namei.c:1721:ll_create_it()) Skipped 473 previous similar messages [16617.124601] LustreError: 255702:0:(namei.c:1744:ll_create_it()) inode ffff9b44a0fef448 need_sync_to_mds [0x2000013a1:0x372:0x0] [16617.133275] LustreError: 255702:0:(namei.c:1744:ll_create_it()) Skipped 473 previous similar messages [16637.254861] LustreError: 255815:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [16637.271946] LustreError: 255815:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 485 previous similar messages [16637.294373] LustreError: 255815:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 0 [16637.302566] LustreError: 255815:0:(namei.c:956:ll_intent_lock()) Skipped 316 previous similar messages [16637.343242] LustreError: 255815:0:(dcache.c:176:ll_intent_release()) intent ffffb69a07fabb20 released [16637.349324] LustreError: 255815:0:(dcache.c:176:ll_intent_release()) Skipped 148 previous similar messages [16658.690598] Lustre: DEBUG MARKER: == sanity test 134b: Server rejects lock request when reaching lock_limit_mb ========================================================== 10:04:51 (1789394691) [16659.047271] LustreError: 256606:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [16660.448503] Lustre: lustre-OST0000-osc-ffff9b4398427000: disconnect after 21s idle [16664.753091] LustreError: 256763:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [16664.763169] LustreError: 256763:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 123 previous similar messages [16664.830578] LustreError: 256763:0:(namei.c:1721:ll_create_it()) VFS Op:name=f0, dir=[0x2000013a1:0x3eb:0x0](ffff9b44a0d3d348), intent=open|creat [16664.841820] LustreError: 256763:0:(namei.c:1721:ll_create_it()) Skipped 120 previous similar messages [16664.850096] LustreError: 256763:0:(namei.c:1744:ll_create_it()) inode ffff9b44a0d3db88 need_sync_to_mds [0x2000013a1:0x3ec:0x0] [16664.858285] LustreError: 256763:0:(namei.c:1744:ll_create_it()) Skipped 120 previous similar messages [16669.261523] LustreError: 256763:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [16669.270818] LustreError: 256763:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 3439 previous similar messages [16669.295166] LustreError: 256763:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 1 [16669.302441] LustreError: 256763:0:(namei.c:956:ll_intent_lock()) Skipped 2134 previous similar messages [16669.355582] LustreError: 256763:0:(dcache.c:176:ll_intent_release()) intent ffff9b44be0d4ba0 released [16669.364121] LustreError: 256763:0:(dcache.c:176:ll_intent_release()) Skipped 821 previous similar messages [16702.301447] Lustre: DEBUG MARKER: == sanity test 134c: Lock memory accounting includes associated structures ========================================================== 10:05:34 (1789394734) [16715.934620] Lustre: DEBUG MARKER: SKIP: sanity test_135 skipping SLOW test 135 [16717.114685] Lustre: DEBUG MARKER: SKIP: sanity test_136 skipping SLOW test 136 [16718.720325] Lustre: DEBUG MARKER: == sanity test 140: Check reasonable stack depth (shouldn't LBUG) ============================================================== 10:05:50 (1789394750) [16718.898453] LustreError: 258587:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [16719.045060] LustreError: 258590:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [16719.054988] LustreError: 258590:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 599 previous similar messages [16719.312224] LustreError: 258591:0:(namei.c:1721:ll_create_it()) VFS Op:name=stat, dir=[0x2000013a1:0x644:0x0](ffff9b44a12763c8), intent=open|creat [16719.324864] LustreError: 258591:0:(namei.c:1721:ll_create_it()) Skipped 599 previous similar messages [16719.331450] LustreError: 258591:0:(namei.c:1744:ll_create_it()) inode ffff9b44a1134b08 need_sync_to_mds [0x2000013a1:0x645:0x0] [16719.338060] LustreError: 258591:0:(namei.c:1744:ll_create_it()) Skipped 599 previous similar messages [16719.801109] LustreError: 258598:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [16720.823254] LustreError: 258618:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [16720.828844] LustreError: 258618:0:(file.c:977:ll_kernel_to_mds_open_flags()) Skipped 1 previous similar message [16720.974870] LustreError: 258623:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [16720.988297] LustreError: 258623:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 6 previous similar messages [16722.015684] LustreError: 258636:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [16722.023709] LustreError: 258636:0:(file.c:977:ll_kernel_to_mds_open_flags()) Skipped 1 previous similar message [16724.553691] LustreError: 258673:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [16724.563073] LustreError: 258673:0:(file.c:977:ll_kernel_to_mds_open_flags()) Skipped 3 previous similar messages [16725.425430] LustreError: 258687:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [16725.435915] LustreError: 258687:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 13 previous similar messages [16729.024996] LustreError: 258728:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [16729.032107] LustreError: 258728:0:(file.c:977:ll_kernel_to_mds_open_flags()) Skipped 5 previous similar messages [16733.267477] LustreError: 258765:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [16733.279451] LustreError: 258765:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 3861 previous similar messages [16733.300776] LustreError: 258765:0:(namei.c:956:ll_intent_lock()) intent lock 1 on i1 [0x2000013a1:0x656:0x0] suppgids 0 -1: rc 0 [16733.320864] LustreError: 258765:0:(namei.c:956:ll_intent_lock()) Skipped 2771 previous similar messages [16733.355989] LustreError: 258765:0:(dcache.c:176:ll_intent_release()) intent ffff9b44aaf19960 released [16733.363849] LustreError: 258765:0:(dcache.c:176:ll_intent_release()) Skipped 1142 previous similar messages [16733.531724] LustreError: 258770:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [16733.537587] LustreError: 258770:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 19 previous similar messages [16737.399678] LustreError: 258801:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [16737.409915] LustreError: 258801:0:(file.c:977:ll_kernel_to_mds_open_flags()) Skipped 9 previous similar messages [16750.430585] LustreError: 258899:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [16750.437209] LustreError: 258899:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 35 previous similar messages [16760.916472] Lustre: DEBUG MARKER: == sanity test 150a: truncate/append tests =============== 10:06:33 (1789394793) [16761.433912] LustreError: 259501:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [16761.440488] LustreError: 259501:0:(file.c:977:ll_kernel_to_mds_open_flags()) Skipped 15 previous similar messages [16783.328655] Lustre: lustre-OST0001-osc-ffff9b4398427000: disconnect after 22s idle [16783.573138] Lustre: Unmounted lustre-client [16783.967529] Lustre: Mounted lustre-client - version 2.17.58_39_gb3cb314 [16784.149087] LustreError: 259576:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [16784.162961] LustreError: 259576:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 1281 previous similar messages [16813.909916] Lustre: DEBUG MARKER: == sanity test 150b: Verify fallocate (prealloc) functionality ========================================================== 10:07:26 (1789394846) [16814.929904] LustreError: 260546:0:(namei.c:1721:ll_create_it()) VFS Op:name=f150b.sanity, dir=[0x200000007:0x1:0x0](ffff9b44a1277448), intent=open|creat [16814.938891] LustreError: 260546:0:(namei.c:1721:ll_create_it()) Skipped 1 previous similar message [16814.950229] LustreError: 260546:0:(namei.c:1744:ll_create_it()) inode ffff9b4489b2e3c8 need_sync_to_mds [0x2000013a2:0x2:0x0] [16814.956336] LustreError: 260546:0:(namei.c:1744:ll_create_it()) Skipped 1 previous similar message [16819.488641] Lustre: DEBUG MARKER: SKIP: sanity test_150b fallocate failed, error Operation not supported, mode 0, offset 41943040, len 4194304|check_fallocate failed [16839.710468] Lustre: DEBUG MARKER: == sanity test 150bb: Verify fallocate modes both zero space ========================================================== 10:07:51 (1789394871) [16841.591286] Lustre: DEBUG MARKER: SKIP: sanity test_150bb fallocate not supported [16843.485301] Lustre: DEBUG MARKER: == sanity test 150c: Verify fallocate Size and Blocks ==== 10:07:55 (1789394875) [16845.675848] Lustre: DEBUG MARKER: SKIP: sanity test_150c fallocate not supported [16847.404732] Lustre: DEBUG MARKER: == sanity test 150d: Verify fallocate Size and Blocks - Non zero start ========================================================== 10:07:59 (1789394879) [16849.616351] Lustre: DEBUG MARKER: SKIP: sanity test_150d fallocate not supported [16851.093646] Lustre: DEBUG MARKER: == sanity test 150e: Verify 60% of available OST space consumed by fallocate ========================================================== 10:08:03 (1789394883) [16853.121604] Lustre: DEBUG MARKER: SKIP: sanity test_150e fallocate not supported [16854.787904] Lustre: DEBUG MARKER: == sanity test 150f: Verify fallocate punch functionality ========================================================== 10:08:06 (1789394886) [16856.537148] LustreError: 262364:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [16856.545558] LustreError: 262364:0:(file.c:977:ll_kernel_to_mds_open_flags()) Skipped 1 previous similar message [16871.023364] LustreError: 262581:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [16871.032991] LustreError: 262581:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 3247 previous similar messages [16871.045163] LustreError: 262581:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 1 [16871.055114] LustreError: 262581:0:(namei.c:956:ll_intent_lock()) Skipped 3120 previous similar messages [16871.095358] LustreError: 262581:0:(dcache.c:176:ll_intent_release()) intent ffffb69a082d3b20 released [16871.099575] LustreError: 262581:0:(dcache.c:176:ll_intent_release()) Skipped 1284 previous similar messages [16916.903262] Lustre: DEBUG MARKER: == sanity test 150g: Verify fallocate punch on large range ========================================================== 10:09:08 (1789394948) [16920.778671] Lustre: DEBUG MARKER: SKIP: sanity test_150g fallocate not supported [16922.154368] Lustre: DEBUG MARKER: == sanity test 150h: Verify extend fallocate updates the file size ========================================================== 10:09:14 (1789394954) [16924.457871] Lustre: DEBUG MARKER: SKIP: sanity test_150h fallocate not supported [16926.297524] Lustre: DEBUG MARKER: == sanity test 150ia: Verify fallocate zero-range ZERO functionality ========================================================== 10:09:18 (1789394958) [16927.955695] Lustre: DEBUG MARKER: SKIP: sanity test_150ia zero-range mode is not implemented on OSD ZFS [16929.846990] Lustre: DEBUG MARKER: == sanity test 150ib: Verify fallocate zero-range PREALLOC functionality ========================================================== 10:09:21 (1789394961) [16931.198409] Lustre: DEBUG MARKER: SKIP: sanity test_150ib zero-range mode is not implemented on OSD ZFS [16932.722895] Lustre: DEBUG MARKER: == sanity test 150ic: Verify fallocate LARGE zero PREALLOC functionality ========================================================== 10:09:24 (1789394964) [16933.983217] Lustre: DEBUG MARKER: SKIP: sanity test_150ic zero-range mode is not implemented on OSD ZFS [16935.468454] Lustre: DEBUG MARKER: == sanity test 150id: fallocate that fails must not leave a dirty page behind ========================================================== 10:09:27 (1789394967) [16936.867972] Lustre: DEBUG MARKER: SKIP: sanity test_150id fallocate zero-range is ldiskfs only [16938.639422] Lustre: DEBUG MARKER: == sanity test 151: test cache on oss and controls ========================================================================================= 10:09:30 (1789394970) [16942.093706] Lustre: DEBUG MARKER: SKIP: sanity test_151 not cache-capable obdfilter [16943.774031] Lustre: DEBUG MARKER: == sanity test 152: test read/write with enomem ====================================================================================== 10:09:35 (1789394975) [16943.982418] LustreError: 265913:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [16943.996860] LustreError: 265913:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 9 previous similar messages [16944.047775] LustreError: 265913:0:(namei.c:1721:ll_create_it()) VFS Op:name=f152.sanity, dir=[0x200000007:0x1:0x0](ffff9b44a1277448), intent=open|creat [16944.054335] LustreError: 265913:0:(namei.c:1721:ll_create_it()) Skipped 2 previous similar messages [16944.059648] LustreError: 265913:0:(namei.c:1744:ll_create_it()) inode ffff9b4489b2e3c8 need_sync_to_mds [0x2000013a2:0x6:0x0] [16944.067754] LustreError: 265913:0:(namei.c:1744:ll_create_it()) Skipped 2 previous similar messages [16944.356577] LustreError: 265923:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [16944.367388] LustreError: 265923:0:(file.c:977:ll_kernel_to_mds_open_flags()) Skipped 5 previous similar messages [16950.751733] Lustre: DEBUG MARKER: == sanity test 153: test if fdatasync does not crash ================================================================================= 10:09:42 (1789394982) [16957.904466] Lustre: DEBUG MARKER: == sanity test 154A: lfs path2fid and fid2path basic checks ========================================================== 10:09:49 (1789394989) [16964.076609] Lustre: DEBUG MARKER: == sanity test 154B: verify the ll_decode_linkea tool ==== 10:09:56 (1789394996) [16964.236836] LustreError: 267636:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [16964.247578] LustreError: 267636:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 6 previous similar messages [16964.561477] LustreError: 267655:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [16970.553158] Lustre: DEBUG MARKER: == sanity test 154C: lfs fid2path on OST FID ============= 10:10:02 (1789395002) [16998.058516] Lustre: DEBUG MARKER: == sanity test 154a: Open-by-FID ========================= 10:10:30 (1789395030) [16998.659509] LustreError: 268984:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [16998.668506] LustreError: 268984:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 1 previous similar message [16999.683070] LustreError: 268984:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [16999.692339] LustreError: 268984:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 2 previous similar messages [17001.796719] LustreError: 268984:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [17001.801434] LustreError: 268984:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 7 previous similar messages [17008.114894] Lustre: DEBUG MARKER: == sanity test 154b: Open-by-FID for remote directory ==== 10:10:40 (1789395040) [17009.507385] Lustre: DEBUG MARKER: SKIP: sanity test_154b needs >= 2 MDTs [17010.886881] Lustre: DEBUG MARKER: == sanity test 154c: lfs path2fid and fid2path multiple arguments ========================================================== 10:10:43 (1789395043) [17016.497152] Lustre: DEBUG MARKER: == sanity test 154d: Verify open file fid ================ 10:10:48 (1789395048) [17023.771938] Lustre: DEBUG MARKER: == sanity test 154db: fid is stored in dir entries ======= 10:10:56 (1789395056) [17025.136467] Lustre: DEBUG MARKER: SKIP: sanity test_154db ldiskfs only test [17026.721464] Lustre: DEBUG MARKER: == sanity test 154e: .lustre is not returned by readdir == 10:10:58 (1789395058) [17034.399925] Lustre: DEBUG MARKER: == sanity test 154ea: .lustre is not returned by readdir (2) ========================================================== 10:11:05 (1789395065) [17042.838108] LustreError: 272587:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [17042.848890] LustreError: 272587:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 6 previous similar messages [17082.337582] LustreError: 272587:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [17082.346348] LustreError: 272587:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 43 previous similar messages [17098.394504] Lustre: DEBUG MARKER: == sanity test 154f: get parent fids by reading link ea == 10:12:09 (1789395129) [17099.377538] LustreError: 272860:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [17099.385669] LustreError: 272860:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 3 previous similar messages [17100.110659] LustreError: 272870:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [17100.124769] LustreError: 272870:0:(file.c:977:ll_kernel_to_mds_open_flags()) Skipped 7 previous similar messages [17100.880643] LustreError: 272898:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [17100.890207] LustreError: 272898:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 188 previous similar messages [17108.017666] Lustre: DEBUG MARKER: == sanity test 154g: various llapi FID tests ============= 10:12:20 (1789395140) [17109.102582] LustreError: 273490:0:(llite_lib.c:4170:ll_prep_md_op_data()) debug: Setting bias to MDS_CREATE_VOLATILE: . :VOLATILE::4A18624B [17109.113863] LustreError: 273490:0:(mdc_lib.c:326:mdc_open_pack()) debug: create_volatile changes to mds_open_volatile [17127.029451] LustreError: 273490:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [17127.037167] LustreError: 273490:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 6031 previous similar messages [17127.048571] LustreError: 273490:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 1 [17127.060335] LustreError: 273490:0:(namei.c:956:ll_intent_lock()) Skipped 3773 previous similar messages [17127.182343] LustreError: 273490:0:(dcache.c:176:ll_intent_release()) intent ffffb69a0813fb60 released [17127.188918] LustreError: 273490:0:(dcache.c:176:ll_intent_release()) Skipped 1786 previous similar messages [17227.384741] LustreError: 273490:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [17227.401526] LustreError: 273490:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 627 previous similar messages [17483.884414] LustreError: 273490:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [17483.903586] LustreError: 273490:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 596 previous similar messages [17639.067152] LustreError: 273490:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [17639.080648] LustreError: 273490:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 7716 previous similar messages [17639.091212] LustreError: 273490:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 1 [17639.100078] LustreError: 273490:0:(namei.c:956:ll_intent_lock()) Skipped 6428 previous similar messages [17639.295562] LustreError: 273490:0:(dcache.c:176:ll_intent_release()) intent ffffb69a0813fb60 released [17639.306027] LustreError: 273490:0:(dcache.c:176:ll_intent_release()) Skipped 1284 previous similar messages [17996.471358] LustreError: 273490:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [17996.484612] LustreError: 273490:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 716 previous similar messages [18076.347993] LustreError: 273639:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [18076.363386] LustreError: 273639:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 2 previous similar messages [18080.353959] LustreError: 273639:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [18080.362304] LustreError: 273639:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 132 previous similar messages [18088.400185] LustreError: 273639:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [18088.406116] LustreError: 273639:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 283 previous similar messages [18104.404245] LustreError: 273639:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [18104.412239] LustreError: 273639:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 613 previous similar messages [18136.434219] LustreError: 273639:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [18136.442638] LustreError: 273639:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 1259 previous similar messages [18200.436569] LustreError: 273639:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [18200.444726] LustreError: 273639:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 1962 previous similar messages [18239.067656] LustreError: 273639:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [18239.085794] LustreError: 273639:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 29578 previous similar messages [18239.137835] LustreError: 273639:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x2000013a2:0x301:0x0] suppgids 0 0: rc 1 [18239.162317] LustreError: 273639:0:(namei.c:956:ll_intent_lock()) Skipped 16284 previous similar messages [18239.300486] LustreError: 273639:0:(dcache.c:176:ll_intent_release()) intent ffffb69a082f3e00 released [18239.305328] LustreError: 273639:0:(dcache.c:176:ll_intent_release()) Skipped 1408 previous similar messages [18268.715681] LustreError: 273490:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [18268.732378] LustreError: 273490:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 55 previous similar messages [18268.845338] LustreError: 273490:0:(namei.c:1721:ll_create_it()) VFS Op:name=link0000, dir=[0x2000013a2:0x824:0x0](ffff9b44a0ce42c8), intent=open|creat [18268.860306] LustreError: 273490:0:(namei.c:1721:ll_create_it()) Skipped 32 previous similar messages [18268.875640] LustreError: 273490:0:(namei.c:1744:ll_create_it()) inode ffff9b4492ed0908 need_sync_to_mds [0x2000013a2:0x825:0x0] [18268.887854] LustreError: 273490:0:(namei.c:1744:ll_create_it()) Skipped 32 previous similar messages [18335.728677] LustreError: 273490:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [18335.739068] LustreError: 273490:0:(file.c:977:ll_kernel_to_mds_open_flags()) Skipped 13 previous similar messages [18335.885375] LustreError: 273490:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [18336.126534] LustreError: 277730:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [18336.135568] LustreError: 277730:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 1806 previous similar messages [18336.192505] LustreError: 273490:0:(namei.c:1721:ll_create_it()) VFS Op:name=llapi_fid_test_name_9585766, dir=[0x2000013a2:0x34:0x0](ffff9b4489623a88), intent=open|creat [18336.203971] LustreError: 273490:0:(namei.c:1744:ll_create_it()) inode ffff9b4492ed0908 need_sync_to_mds [0x2000013a2:0x827:0x0] [18363.630766] Lustre: DEBUG MARKER: == sanity test 154h: Verify interactive path2fid ========= 10:33:15 (1789396395) [18371.552485] Lustre: DEBUG MARKER: == sanity test 154i: fid2path for path longer than PATH_MAX ========================================================== 10:33:23 (1789396403) [18387.929212] LustreError: 278747:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [18387.934662] LustreError: 278747:0:(file.c:977:ll_kernel_to_mds_open_flags()) Skipped 106 previous similar messages [18401.109192] LustreError: 279510:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [18401.126450] LustreError: 279510:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 354 previous similar messages [18420.273219] Lustre: DEBUG MARKER: == sanity test 154j: fid2path for long path crossing MDT boundary ========================================================== 10:34:12 (1789396452) [18422.412166] Lustre: DEBUG MARKER: SKIP: sanity test_154j needs >= 2 MDTs [18424.428888] Lustre: DEBUG MARKER: == sanity test 155a: Verify small file correctness: read cache:on write_cache:on ========================================================== 10:34:16 (1789396456) [18429.113603] LustreError: 281383:0:(namei.c:1721:ll_create_it()) VFS Op:name=f155a.sanity, dir=[0x200000007:0x1:0x0](ffff9b44a1277448), intent=open|creat [18429.122691] LustreError: 281383:0:(namei.c:1721:ll_create_it()) Skipped 3 previous similar messages [18429.131106] LustreError: 281383:0:(namei.c:1744:ll_create_it()) inode ffff9b44a0ce1148 need_sync_to_mds [0x2000013a2:0x8db:0x0] [18429.140328] LustreError: 281383:0:(namei.c:1744:ll_create_it()) Skipped 3 previous similar messages [18438.635659] Lustre: DEBUG MARKER: == sanity test 155b: Verify small file correctness: read cache:on write_cache:off ========================================================== 10:34:30 (1789396470) [18453.559897] Lustre: DEBUG MARKER: == sanity test 155c: Verify small file correctness: read cache:off write_cache:on ========================================================== 10:34:45 (1789396485) [18458.857919] LustreError: 282864:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [18458.864161] LustreError: 282864:0:(file.c:977:ll_kernel_to_mds_open_flags()) Skipped 706 previous similar messages [18467.555871] Lustre: DEBUG MARKER: == sanity test 155d: Verify small file correctness: read cache:off write_cache:off ========================================================== 10:34:59 (1789396499) [18481.220981] Lustre: DEBUG MARKER: == sanity test 155e: Verify big file correctness: read cache:on write_cache:on ========================================================== 10:35:13 (1789396513) [18549.123279] Lustre: DEBUG MARKER: == sanity test 155f: Verify big file correctness: read cache:on write_cache:off ========================================================== 10:36:20 (1789396580) [18566.934686] LustreError: 285468:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [18566.941208] LustreError: 285468:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 55 previous similar messages [18566.994427] LustreError: 285468:0:(namei.c:1721:ll_create_it()) VFS Op:name=f155f.sanity, dir=[0x200000007:0x1:0x0](ffff9b44a1277448), intent=open|creat [18567.005496] LustreError: 285468:0:(namei.c:1721:ll_create_it()) Skipped 4 previous similar messages [18567.023187] LustreError: 285468:0:(namei.c:1744:ll_create_it()) inode ffff9b4489b2c2c8 need_sync_to_mds [0x2000013a2:0x8e4:0x0] [18567.037413] LustreError: 285468:0:(namei.c:1744:ll_create_it()) Skipped 4 previous similar messages [18611.172370] Lustre: DEBUG MARKER: == sanity test 155g: Verify big file correctness: read cache:off write_cache:on ========================================================== 10:37:22 (1789396642) [18630.074396] LustreError: 286405:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [18630.083602] LustreError: 286405:0:(file.c:977:ll_kernel_to_mds_open_flags()) Skipped 7 previous similar messages [18665.961778] Lustre: DEBUG MARKER: == sanity test 155h: Verify big file correctness: read cache:off write_cache:off ========================================================== 10:38:17 (1789396697) [18723.215715] Lustre: DEBUG MARKER: == sanity test 156: Verification of tunables ============= 10:39:14 (1789396754) [18725.284882] Lustre: DEBUG MARKER: SKIP: sanity test_156 LU-1956/LU-2261: stats not implemented on OSD ZFS [18727.562341] Lustre: DEBUG MARKER: == sanity test 157a: llapi pool pinning API tests ======== 10:39:19 (1789396759) [18728.022894] LustreError: 288264:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [18728.034465] LustreError: 288264:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 269 previous similar messages [18736.626492] Lustre: DEBUG MARKER: == sanity test 157b: lustre.pin inheritance on create ==== 10:39:28 (1789396768) [18745.726758] Lustre: DEBUG MARKER: == sanity test 160a: changelog sanity ==================== 10:39:37 (1789396777) [18778.618788] LustreError: MGC192.168.203.129@tcp: Connection to MGS (at 192.168.203.129@tcp) was lost; in progress operations using this service will fail [18778.629609] Lustre: lustre-MDT0000-mdc-ffff9b4483243000: Connection to lustre-MDT0000 (at 192.168.203.129@tcp) was lost; in progress operations using this service will wait for recovery to complete [18778.653446] Lustre: Evicted from MGS (at 192.168.203.129@tcp) after server handle changed from 0xe7a160aea94fa552 to 0xe7a160aea958c338 [18778.669426] Lustre: MGC192.168.203.129@tcp: Connection restored to 192.168.203.129@tcp (at 192.168.203.129@tcp) [18778.796548] LustreError: 237790:0:(client.c:3449:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9b44b6dcaa00 x1876315027974784/t12884908729(12884908729) o101->lustre-MDT0000-mdc-ffff9b4483243000@192.168.203.129@tcp:12/10 lens 968/608 e 0 to 0 dl 1789396828 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'lfs.0' uid:0 gid:0 projid:0 [18779.308461] LustreError: 237790:0:(client.c:3449:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9b44bbaa2d80 x1876315034742144/t12884924416(12884924416) o101->lustre-MDT0000-mdc-ffff9b4483243000@192.168.203.129@tcp:12/10 lens 968/608 e 0 to 0 dl 1789396828 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'bash.0' uid:0 gid:0 projid:0 [18779.340629] LustreError: 237790:0:(client.c:3449:ptlrpc_replay_interpret()) Skipped 32 previous similar messages [18780.482885] Lustre: lustre-MDT0000-mdc-ffff9b4483243000: Connection restored to 192.168.203.129@tcp (at 192.168.203.129@tcp) [18784.544353] Lustre: 237791:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789396801/real 1789396801] req@ffff9b44bbaa0700 x1876315035055360/t0(0) o400->lustre-MDT0000-mdc-ffff9b4483243000@192.168.203.129@tcp:12/10 lens 224/224 e 0 to 1 dl 1789396817 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [18788.832147] Lustre: 237794:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789396806/real 1789396806] req@ffff9b44b6e36300 x1876315035055872/t0(0) o400->lustre-MDT0000-mdc-ffff9b4483243000@192.168.203.129@tcp:12/10 lens 224/224 e 0 to 1 dl 1789396822 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [18796.481308] Lustre: DEBUG MARKER: == sanity test 160b: Verify that very long rename doesn't crash in changelog ========================================================== 10:40:28 (1789396828) [18812.950281] Lustre: DEBUG MARKER: == sanity test 160c: verify that changelog log catch the truncate event ========================================================== 10:40:44 (1789396844) [18831.741390] Lustre: DEBUG MARKER: == sanity test 160d: verify that changelog log catch the migrate event ========================================================== 10:41:03 (1789396863) [18834.907863] Lustre: DEBUG MARKER: SKIP: sanity test_160d needs >= 2 MDTs [18837.640252] Lustre: DEBUG MARKER: == sanity test 160e: changelog negative testing (should return errors) ========================================================== 10:41:08 (1789396868) [18855.735705] Lustre: DEBUG MARKER: == sanity test 160f: changelog garbage collect (timestamped users) ========================================================== 10:41:26 (1789396886) [18863.196210] LustreError: 293468:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [18863.209803] LustreError: 293468:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 23788 previous similar messages [18863.221499] LustreError: 293468:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 1 [18863.227837] LustreError: 293468:0:(namei.c:956:ll_intent_lock()) Skipped 16993 previous similar messages [18865.322330] Lustre: DEBUG MARKER: 1789396896: creating first dirs [18865.456400] LustreError: 293598:0:(dcache.c:176:ll_intent_release()) intent ffffb69a082dbb20 released [18865.464215] LustreError: 293598:0:(dcache.c:176:ll_intent_release()) Skipped 4745 previous similar messages [18865.506029] LustreError: 293598:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [18865.511124] LustreError: 293598:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 204 previous similar messages [18914.657565] Lustre: DEBUG MARKER: == sanity test 160g: changelog garbage collect on idle records ========================================================== 10:42:25 (1789396945) [18954.002503] Lustre: DEBUG MARKER: == sanity test 160h: changelog gc thread stop upon umount, orphan records delete ========================================================== 10:43:05 (1789396985) [18988.531682] Lustre: lustre-MDT0000-mdc-ffff9b4483243000: Connection to lustre-MDT0000 (at 192.168.203.129@tcp) was lost; in progress operations using this service will wait for recovery to complete [19009.006759] LustreError: MGC192.168.203.129@tcp: Connection to MGS (at 192.168.203.129@tcp) was lost; in progress operations using this service will fail [19009.037490] Lustre: Evicted from MGS (at 192.168.203.129@tcp) after server handle changed from 0xe7a160aea958c338 to 0xe7a160aea958d624 [19009.049743] Lustre: MGC192.168.203.129@tcp: Connection restored to 192.168.203.129@tcp (at 192.168.203.129@tcp) [19019.358474] LustreError: 237790:0:(client.c:3449:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9b44b832c700 x1876315034731008/t12884924387(12884924387) o101->lustre-MDT0000-mdc-ffff9b4483243000@192.168.203.129@tcp:12/10 lens 968/608 e 0 to 0 dl 1789397068 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'bash.0' uid:0 gid:0 projid:0 [19019.393093] LustreError: 237790:0:(client.c:3449:ptlrpc_replay_interpret()) Skipped 39 previous similar messages [19020.485854] Lustre: lustre-MDT0000-mdc-ffff9b4483243000: Connection restored to 192.168.203.129@tcp (at 192.168.203.129@tcp) [19037.710317] Lustre: DEBUG MARKER: == sanity test 160i: changelog user register/unregister race ========================================================== 10:44:29 (1789397069) [19064.598083] Lustre: DEBUG MARKER: == sanity test 160j: client can be umounted while its chanangelog is being used ========================================================== 10:44:56 (1789397096) [19065.716293] Lustre: Mounted lustre-client - version 2.17.58_39_gb3cb314 [19069.856034] Lustre: Unmounted lustre-client [19077.722202] Lustre: Mounted lustre-client - version 2.17.58_39_gb3cb314 [19082.339517] Lustre: Unmounted lustre-client [19084.550612] Lustre: DEBUG MARKER: == sanity test 160k: Verify that changelog records are not lost ========================================================== 10:45:16 (1789397116) [19085.006221] LustreError: 299091:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [19085.012738] LustreError: 299091:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 39 previous similar messages [19091.005455] LustreError: 299152:0:(namei.c:1721:ll_create_it()) VFS Op:name=2, dir=[0x200002341:0x4:0x0](ffff9b44a0ce7448), intent=open|creat [19091.014219] LustreError: 299152:0:(namei.c:1721:ll_create_it()) Skipped 13 previous similar messages [19091.021100] LustreError: 299152:0:(namei.c:1744:ll_create_it()) inode ffff9b4483423248 need_sync_to_mds [0x200002341:0x5:0x0] [19091.025884] LustreError: 299152:0:(namei.c:1744:ll_create_it()) Skipped 13 previous similar messages [19107.342440] Lustre: DEBUG MARKER: == sanity test 160l: Verify that MTIME changelog records contain the parent FID ========================================================== 10:45:39 (1789397139) [19116.697389] LustreError: 299983:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [19116.705492] LustreError: 299983:0:(file.c:977:ll_kernel_to_mds_open_flags()) Skipped 9 previous similar messages [19128.370108] Lustre: DEBUG MARKER: == sanity test 160m: Changelog clear race ================ 10:46:00 (1789397160) [19159.101380] Lustre: DEBUG MARKER: == sanity test 160n: Changelog destroy race ============== 10:46:31 (1789397191) [19463.218349] LustreError: 305344:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [19463.226531] LustreError: 305344:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 38751 previous similar messages [19463.234095] LustreError: 305344:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 1 [19463.242723] LustreError: 305344:0:(namei.c:956:ll_intent_lock()) Skipped 24899 previous similar messages [19465.517465] LustreError: 305380:0:(dcache.c:176:ll_intent_release()) intent ffffb69a0be53db8 released [19465.526035] LustreError: 305380:0:(dcache.c:176:ll_intent_release()) Skipped 7432 previous similar messages [20002.195466] LustreError: 312111:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [20002.217934] LustreError: 312111:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 10090 previous similar messages [20063.223575] LustreError: 312111:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [20063.236495] LustreError: 312111:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 76107 previous similar messages [20063.249660] LustreError: 312111:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 1 [20063.260383] LustreError: 312111:0:(namei.c:956:ll_intent_lock()) Skipped 52599 previous similar messages [20077.191350] LustreError: 312111:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [20077.198712] LustreError: 312111:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 8738 previous similar messages [20090.081910] LustreError: 312209:0:(dcache.c:176:ll_intent_release()) intent ffffb69a07f63db8 released [20090.100322] LustreError: 312209:0:(dcache.c:176:ll_intent_release()) Skipped 22654 previous similar messages [20663.223689] LustreError: 322098:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [20663.234283] LustreError: 322098:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 54737 previous similar messages [20663.261798] LustreError: 322098:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200002341:0x3c:0x0] suppgids 0 -1: rc 0 [20663.268869] LustreError: 322098:0:(namei.c:956:ll_intent_lock()) Skipped 42078 previous similar messages [20690.091965] LustreError: 322421:0:(dcache.c:176:ll_intent_release()) intent ffffb69a11863e00 released [20690.096841] LustreError: 322421:0:(dcache.c:176:ll_intent_release()) Skipped 20823 previous similar messages [20835.944668] LustreError: 322639:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [20835.958488] LustreError: 322639:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 1260 previous similar messages [21263.225373] LustreError: 328699:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [21263.232508] LustreError: 328699:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 80607 previous similar messages [21263.282960] LustreError: 328700:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 1 [21263.295092] LustreError: 328700:0:(namei.c:956:ll_intent_lock()) Skipped 54485 previous similar messages [21290.138566] LustreError: 329157:0:(dcache.c:176:ll_intent_release()) intent ffffb69a0e67bdb8 released [21290.160452] LustreError: 329157:0:(dcache.c:176:ll_intent_release()) Skipped 21934 previous similar messages [21689.019258] Lustre: DEBUG MARKER: == sanity test 160o: changelog user name and mask ======== 11:28:40 (1789399720) [21698.996925] LustreError: 333835:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [21699.014125] LustreError: 333835:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 9999 previous similar messages [21699.072706] LustreError: 333836:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [21699.080337] LustreError: 333836:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 6 previous similar messages [21699.172369] LustreError: 333836:0:(namei.c:1721:ll_create_it()) VFS Op:name=f160o.sanity, dir=[0x200002341:0x756d:0x0](ffff9b44be46b248), intent=open|creat [21699.197560] LustreError: 333836:0:(namei.c:1721:ll_create_it()) Skipped 2 previous similar messages [21699.215296] LustreError: 333836:0:(namei.c:1744:ll_create_it()) inode ffff9b44be4180c8 need_sync_to_mds [0x200002341:0x756e:0x0] [21699.223054] LustreError: 333836:0:(namei.c:1744:ll_create_it()) Skipped 2 previous similar messages [21722.621245] Lustre: DEBUG MARKER: == sanity test 160p: Changelog orphan cleanup with no users ========================================================== 11:29:14 (1789399754) [21724.513649] Lustre: DEBUG MARKER: SKIP: sanity test_160p ldiskfs only test [21726.299718] Lustre: DEBUG MARKER: == sanity test 160q: changelog effective mask is DEFMASK if not set ========================================================== 11:29:18 (1789399758) [21738.569869] Lustre: DEBUG MARKER: == sanity test 160s: changelog garbage collect on idle records * time ========================================================== 11:29:29 (1789399769) [21743.454404] LustreError: 335835:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [21743.460277] LustreError: 335835:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 16 previous similar messages [21774.339235] Lustre: DEBUG MARKER: == sanity test 160t: changelog garbage collect on lack of space ========================================================== 11:30:06 (1789399806) [21777.907941] LustreError: 336930:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [21780.358879] LustreError: 337056:0:(namei.c:1721:ll_create_it()) VFS Op:name=u1_0, dir=[0x200002341:0x7574:0x0](ffff9b44be46aa08), intent=open|creat [21780.373206] LustreError: 337056:0:(namei.c:1744:ll_create_it()) inode ffff9b44be4763c8 need_sync_to_mds [0x200002341:0x7576:0x0] [21868.452993] LustreError: 338073:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [21868.465039] LustreError: 338073:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 57955 previous similar messages [21868.474875] LustreError: 338073:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 1 [21868.481120] LustreError: 338073:0:(namei.c:956:ll_intent_lock()) Skipped 41364 previous similar messages [21904.800391] Lustre: DEBUG MARKER: == sanity test 160u: changelog rename record type name and sname strings are correct ========================================================== 11:32:15 (1789399935) [21905.501410] LustreError: 338177:0:(dcache.c:176:ll_intent_release()) intent ffffb69a080ab930 released [21905.510653] LustreError: 338177:0:(dcache.c:176:ll_intent_release()) Skipped 19761 previous similar messages [21905.937988] LustreError: 338360:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [21905.951439] LustreError: 338360:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 2510 previous similar messages [21912.339374] LustreError: 338177:0:(namei.c:1721:ll_create_it()) VFS Op:name=hw, dir=[0x200002341:0x7f3e:0x0](ffff9b44ab7aec08), intent=open|creat [21912.351814] LustreError: 338177:0:(namei.c:1721:ll_create_it()) Skipped 2503 previous similar messages [21912.366226] LustreError: 338177:0:(namei.c:1744:ll_create_it()) inode ffff9b4489a57448 need_sync_to_mds [0x200002341:0x7f40:0x0] [21912.377094] LustreError: 338177:0:(namei.c:1744:ll_create_it()) Skipped 2503 previous similar messages [21925.417642] Lustre: DEBUG MARKER: == sanity test 160v: setattr preserves mtime update despite inter-client clock skew ========================================================== 11:32:37 (1789399957) [21927.453430] Lustre: DEBUG MARKER: SKIP: sanity test_160v need >= 2 clients [21930.192282] Lustre: DEBUG MARKER: == sanity test 160w: lfs changelog --user --mask ========= 11:32:41 (1789399961) [21939.492174] LustreError: 339474:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [21939.501088] LustreError: 339474:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 3 previous similar messages [21956.821884] Lustre: DEBUG MARKER: == sanity test 160x: changelog users do not disappear ==== 11:33:08 (1789399988) [22009.228274] Lustre: DEBUG MARKER: == sanity test 161a: link ea sanity ====================== 11:34:01 (1789400041) [22055.561125] Lustre: DEBUG MARKER: == sanity test 161b: link ea sanity under remote directory ========================================================== 11:34:47 (1789400087) [22057.275325] Lustre: DEBUG MARKER: SKIP: sanity test_161b skipping remote directory test [22059.767889] Lustre: DEBUG MARKER: == sanity test 161c: check CL_RENME[UNLINK] changelog record flags ========================================================== 11:34:51 (1789400091) [22078.373814] Lustre: DEBUG MARKER: == sanity test 161d: create with concurrent .lustre/fid access ========================================================== 11:35:09 (1789400109) [22081.900057] LustreError: 343434:0:(namei.c:1680:ll_create_node()) cfs_fail_timeout id 140c sleeping for 5000ms [22084.641917] LustreError: 343434:0:(namei.c:1680:ll_create_node()) cfs_fail_timeout interrupted [22097.881835] Lustre: DEBUG MARKER: == sanity test 162a: path lookup sanity ================== 11:35:28 (1789400128) [22107.907568] Lustre: DEBUG MARKER: == sanity test 162b: striped directory path lookup sanity ========================================================== 11:35:39 (1789400139) [22110.941185] Lustre: DEBUG MARKER: SKIP: sanity test_162b needs >= 2 MDTs [22112.977612] Lustre: DEBUG MARKER: == sanity test 162c: fid2path works with paths 100 or more directories deep ========================================================== 11:35:44 (1789400144) [22156.640885] LustreError: 346828:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [22156.654288] LustreError: 346828:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 2 previous similar messages [22177.436868] Lustre: DEBUG MARKER: == sanity test 165a: ofd access log discovery ============ 11:36:49 (1789400209) [22191.602601] Lustre: lustre-OST0000-osc-ffff9b44904dc800: Connection to lustre-OST0000 (at 192.168.203.129@tcp) was lost; in progress operations using this service will wait for recovery to complete [22218.349368] Lustre: DEBUG MARKER: == sanity test 165b: ofd access log entries are produced and consumed ========================================================== 11:37:30 (1789400250) [22225.454152] LustreError: 348324:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [22225.466803] LustreError: 348324:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 1057 previous similar messages [22225.529235] LustreError: 348324:0:(namei.c:1721:ll_create_it()) VFS Op:name=f165b.sanity, dir=[0x200000007:0x1:0x0](ffff9b4482277448), intent=open|creat [22225.540561] LustreError: 348324:0:(namei.c:1721:ll_create_it()) Skipped 1013 previous similar messages [22225.554866] LustreError: 348324:0:(namei.c:1744:ll_create_it()) inode ffff9b44a0fa1988 need_sync_to_mds [0x200002341:0x8417:0x0] [22225.569117] LustreError: 348324:0:(namei.c:1744:ll_create_it()) Skipped 1013 previous similar messages [22237.458749] LustreError: 348352:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [22253.038780] Lustre: lustre-OST0000-osc-ffff9b44904dc800: Connection to lustre-OST0000 (at 192.168.203.129@tcp) was lost; in progress operations using this service will wait for recovery to complete [22261.993228] Lustre: lustre-OST0000-osc-ffff9b44904dc800: Connection restored to 192.168.203.129@tcp (at 192.168.203.129@tcp) [22269.739455] Lustre: DEBUG MARKER: == sanity test 165c: full ofd access logs do not block IOs ========================================================== 11:38:21 (1789400301) [22309.375944] Lustre: lustre-OST0000-osc-ffff9b44904dc800: Connection to lustre-OST0000 (at 192.168.203.129@tcp) was lost; in progress operations using this service will wait for recovery to complete [22316.115923] Lustre: lustre-OST0000-osc-ffff9b44904dc800: Connection restored to 192.168.203.129@tcp (at 192.168.203.129@tcp) [22324.288975] Lustre: DEBUG MARKER: == sanity test 165d: ofd_access_log mask works =========== 11:39:15 (1789400355) [22324.465224] LustreError: 350347:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [22324.480304] LustreError: 350347:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 233 previous similar messages [22335.014167] LustreError: 350405:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [22370.794734] Lustre: lustre-OST0000-osc-ffff9b44904dc800: Connection to lustre-OST0000 (at 192.168.203.129@tcp) was lost; in progress operations using this service will wait for recovery to complete [22383.600213] Lustre: lustre-OST0000-osc-ffff9b44904dc800: Connection restored to 192.168.203.129@tcp (at 192.168.203.129@tcp) [22392.571704] Lustre: DEBUG MARKER: == sanity test 165e: ofd_access_log MDT index filter works ========================================================== 11:40:24 (1789400424) [22394.091706] Lustre: DEBUG MARKER: SKIP: sanity test_165e needs >= 2 MDTs [22396.043769] Lustre: DEBUG MARKER: == sanity test 165f: ofd_access_log_reader --exit-on-close works ========================================================== 11:40:27 (1789400427) [22406.640854] Lustre: lustre-OST0000-osc-ffff9b44904dc800: Connection to lustre-OST0000 (at 192.168.203.129@tcp) was lost; in progress operations using this service will wait for recovery to complete [22426.194838] Lustre: lustre-OST0000-osc-ffff9b44904dc800: Connection restored to 192.168.203.129@tcp (at 192.168.203.129@tcp) [22434.432350] Lustre: DEBUG MARKER: == sanity test 165g: ofd_access_log_reader --keepalive works ========================================================== 11:41:06 (1789400466) [22483.437895] Lustre: lustre-OST0000-osc-ffff9b44904dc800: Connection to lustre-OST0000 (at 192.168.203.129@tcp) was lost; in progress operations using this service will wait for recovery to complete [22499.509484] Lustre: lustre-OST0000-osc-ffff9b44904dc800: Connection restored to 192.168.203.129@tcp (at 192.168.203.129@tcp) [22508.929530] Lustre: DEBUG MARKER: == sanity test 169: parallel read and truncate should not deadlock ========================================================== 11:42:20 (1789400540) [22510.968459] Lustre: DEBUG MARKER: creating a 10 Mb file [22511.028956] LustreError: 353585:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [22511.041663] LustreError: 353585:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 21989 previous similar messages [22511.056761] LustreError: 353585:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 1 [22511.065086] LustreError: 353585:0:(namei.c:956:ll_intent_lock()) Skipped 14979 previous similar messages [22511.089047] LustreError: 353585:0:(dcache.c:176:ll_intent_release()) intent ffff9b44be6cdf00 released [22511.109459] LustreError: 353585:0:(dcache.c:176:ll_intent_release()) Skipped 3515 previous similar messages [22589.353073] Lustre: DEBUG MARKER: starting reads [22591.568498] LustreError: 353743:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [22591.582955] LustreError: 353743:0:(file.c:977:ll_kernel_to_mds_open_flags()) Skipped 3 previous similar messages [22593.893447] Lustre: DEBUG MARKER: truncating the file [22596.990599] Lustre: DEBUG MARKER: killing dd [22599.912668] Lustre: DEBUG MARKER: removing the temporary file [22611.758950] Lustre: DEBUG MARKER: == sanity test 170a: test lctl df to handle corrupted log ========================================================== 11:44:02 (1789400642) [22611.969183] Lustre: debug daemon will attempt to start writing to /tmp/f170a.sanity_log_good (512000kB max) [22612.173171] Lustre: shutting down debug daemon thread... [22612.265159] Lustre: debug daemon will attempt to start writing to /tmp/f170a.sanity_log_good (512000kB max) [22612.375433] Lustre: shutting down debug daemon thread... [22620.233535] Lustre: DEBUG MARKER: == sanity test 170b: check filename encoding ============= 11:44:11 (1789400651) [22634.131190] LustreError: 355949:0:(llite_lib.c:4170:ll_prep_md_op_data()) debug: Setting bias to MDS_CREATE_VOLATILE: . :VOLATILE:0000:6DBC8AFC:fd=03 [22634.152634] LustreError: 355949:0:(lmv_obd.c:1943:lmv_locate_tgt()) debug: handling volatile file... [22634.171849] LustreError: 355949:0:(mdc_lib.c:326:mdc_open_pack()) debug: create_volatile changes to mds_open_volatile [22635.349058] LustreError: 355950:0:(llite_lib.c:4170:ll_prep_md_op_data()) debug: Setting bias to MDS_CREATE_VOLATILE: . :VOLATILE:0000:3CD59E91:fd=03 [22635.361921] LustreError: 355950:0:(lmv_obd.c:1943:lmv_locate_tgt()) debug: handling volatile file... [22635.368524] LustreError: 355950:0:(mdc_lib.c:326:mdc_open_pack()) debug: create_volatile changes to mds_open_volatile [22636.418447] LustreError: 355954:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [22636.427659] LustreError: 355954:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 603 previous similar messages [22661.386890] Lustre: DEBUG MARKER: == sanity test 171: test libcfs_debug_dumplog_thread stuck in do_exit() ================================================================ 11:44:52 (1789400692) [22661.688569] LustreError: 357057:0:(file.c:513:ll_file_release()) cfs_fail_timeout id 50e sleeping for 3000ms [22664.712671] LustreError: 357057:0:(file.c:513:ll_file_release()) cfs_fail_timeout id 50e awake [22664.722099] LustreError: dumping log to /tmp/lustre-log.1789400698.357057 [22672.511866] Lustre: DEBUG MARKER: == sanity test 172: manual device removal with lctl cleanup/detach ================================================================ 11:45:04 (1789400704) [22674.497272] Lustre: *** cfs_fail_loc=60e, val=0*** [22674.500880] Lustre: Unmounted lustre-client [22679.762846] Lustre: Mounted lustre-client - version 2.17.58_39_gb3cb314 [22681.304898] Lustre: DEBUG MARKER: == sanity test 180a: test obdecho on osc ================= 11:45:13 (1789400713) [22682.787723] Lustre: DEBUG MARKER: SKIP: sanity test_180a obdecho on osc is no longer supported [22684.534503] Lustre: DEBUG MARKER: == sanity test 180b: test obdecho directly on obdfilter == 11:45:16 (1789400716) [22706.520285] Lustre: DEBUG MARKER: == sanity test 180c: test huge bulk I/O size on obdfilter, don't LASSERT ========================================================== 11:45:38 (1789400738) [22736.592278] Lustre: DEBUG MARKER: == sanity test 181: Test open-unlinked dir ================================================================================== 11:46:08 (1789400768) [22739.373605] LustreError: 360198:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [22739.385906] LustreError: 360198:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 143 previous similar messages [22739.462701] LustreError: 360198:0:(namei.c:1721:ll_create_it()) VFS Op:name=foobar0, dir=[0x200002342:0x1:0x0](ffff9b44a0d94b08), intent=open|creat [22739.477200] LustreError: 360198:0:(namei.c:1721:ll_create_it()) Skipped 136 previous similar messages [22739.484112] LustreError: 360198:0:(namei.c:1744:ll_create_it()) inode ffff9b44a0d95348 need_sync_to_mds [0x200002342:0x2:0x0] [22739.492753] LustreError: 360198:0:(namei.c:1744:ll_create_it()) Skipped 136 previous similar messages [22855.725515] Lustre: DEBUG MARKER: == sanity test 182a: Test parallel modify metadata operations from mdc ========================================================== 11:48:07 (1789400887) [22965.021598] Lustre: DEBUG MARKER: == sanity test 182b: Test parallel modify metadata operations from osp ========================================================== 11:49:56 (1789400996) [22967.019972] Lustre: DEBUG MARKER: SKIP: sanity test_182b needs >= 2 MDTs [22968.597615] Lustre: DEBUG MARKER: == sanity test 183: No crash or request leak in case of strange dispositions ================================================================== 11:50:00 (1789401000) [22969.288056] LustreError: 365770:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [22969.292724] LustreError: 365770:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 16 previous similar messages [22979.540275] Lustre: DEBUG MARKER: == sanity test 184a: Basic layout swap =================== 11:50:11 (1789401011) [22979.875121] LustreError: 366368:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [22979.883854] LustreError: 366368:0:(file.c:977:ll_kernel_to_mds_open_flags()) Skipped 5 previous similar messages [22991.606705] Lustre: DEBUG MARKER: == sanity test 184b: Forbidden layout swap (will generate errors) ========================================================== 11:50:23 (1789401023) [23000.656839] Lustre: DEBUG MARKER: == sanity test 184c: Concurrent write and layout swap ==== 11:50:32 (1789401032) [23046.164468] Lustre: DEBUG MARKER: == sanity test 184d: allow stripeless layouts swap ======= 11:51:17 (1789401077) [23080.394092] Lustre: DEBUG MARKER: == sanity test 184e: Recreate layout after stripeless layout swaps ========================================================== 11:51:51 (1789401111) [23104.223191] Lustre: DEBUG MARKER: == sanity test 184f: IOC_MDC_GETFILEINFO for files with long names but no striping ========================================================== 11:52:15 (1789401135) [23110.358889] Lustre: DEBUG MARKER: == sanity test 185: Volatile file support ================ 11:52:22 (1789401142) [23110.690191] LustreError: 370091:0:(llite_lib.c:4170:ll_prep_md_op_data()) debug: Setting bias to MDS_CREATE_VOLATILE: . :VOLATILE::5188611 [23110.700692] LustreError: 370091:0:(mdc_lib.c:326:mdc_open_pack()) debug: create_volatile changes to mds_open_volatile [23112.051091] LustreError: 370100:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [23112.066374] LustreError: 370100:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 74951 previous similar messages [23112.075126] LustreError: 370100:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 1 [23112.083161] LustreError: 370100:0:(namei.c:956:ll_intent_lock()) Skipped 43309 previous similar messages [23117.988439] Lustre: DEBUG MARKER: == sanity test 185a: Volatile file creation in .lustre/fid/ ========================================================== 11:52:30 (1789401150) [23118.124210] LustreError: 370671:0:(llite_lib.c:4170:ll_prep_md_op_data()) debug: Setting bias to MDS_CREATE_VOLATILE: . :VOLATILE:0000:4E7BC48 [23118.131987] LustreError: 370671:0:(llite_lib.c:4170:ll_prep_md_op_data()) Skipped 1 previous similar message [23118.136471] LustreError: 370671:0:(lmv_obd.c:1943:lmv_locate_tgt()) debug: handling volatile file... [23118.143595] LustreError: 370671:0:(mdc_lib.c:326:mdc_open_pack()) debug: create_volatile changes to mds_open_volatile [23118.149189] LustreError: 370671:0:(mdc_lib.c:326:mdc_open_pack()) Skipped 1 previous similar message [23118.173440] LustreError: 370671:0:(dcache.c:176:ll_intent_release()) intent ffff9b44aa6b9cc0 released [23118.179122] LustreError: 370671:0:(dcache.c:176:ll_intent_release()) Skipped 14267 previous similar messages [23126.027719] Lustre: DEBUG MARKER: == sanity test 187a: Test data version change ============ 11:52:38 (1789401158) [23134.451472] Lustre: DEBUG MARKER: == sanity test 187b: Test data version change on volatile file ========================================================== 11:52:46 (1789401166) [23134.998648] LustreError: 371892:0:(llite_lib.c:4170:ll_prep_md_op_data()) debug: Setting bias to MDS_CREATE_VOLATILE: . :VOLATILE::53B993F6 [23135.011235] LustreError: 371892:0:(mdc_lib.c:326:mdc_open_pack()) debug: create_volatile changes to mds_open_volatile [23141.085870] Lustre: DEBUG MARKER: == sanity test 190a: check lfs project -p works with project name ========================================================== 11:52:53 (1789401173) [23147.341771] Lustre: DEBUG MARKER: == sanity test 190b: check lfs find --project works with project name ========================================================== 11:52:59 (1789401179) [23161.905265] LustreError: 373320:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [23161.918830] LustreError: 373320:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 97 previous similar messages [23256.794819] Lustre: DEBUG MARKER: == sanity test 190c: check lfs project -p works with u:USERNAME ========================================================== 11:54:47 (1789401287) [23275.732995] Lustre: DEBUG MARKER: == sanity test complete, duration 22967 sec ============== 11:55:07 (1789401307) [23277.480302] Lustre: DEBUG MARKER: === sanity: start cleanup 11:55:09 (1789401309) === [23324.679238] Lustre: DEBUG MARKER: === sanity: finish cleanup 11:55:56 (1789401356) === [23327.638959] Lustre: Unmounted lustre-client [23356.478352] Key type lgssc unregistered [23356.912522] LNet: 376132:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [23356.925594] LNetError: 376132:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [23356.980740] LNet: Removed LNI 192.168.203.29@tcp [23358.411331] Key type .llcrypt unregistered [23358.416425] Key type ._llcrypt unregistered