[ 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 462478871 cycles [ 0.000000] clocksource: kvm-clock: mask: 0xffffffffffffffff max_cycles: 0x1cd42e4dffb, max_idle_ns: 881590591483 ns [ 0.000000] tsc: Detected 2399.998 MHz processor [ 0.000000] last_pfn = 0x146e00 max_arch_pfn = 0x400000000 [ 0.000000] x86/PAT: Configuration [0-7]: WB WC UC- UC WB WP UC- WT [ 0.000000] last_pfn = 0xbffda max_arch_pfn = 0x400000000 [ 0.000000] found SMP MP-table at [mem 0x000f54d0-0x000f54df] [ 0.000000] RAMDISK: [mem 0xbcc64000-0xbffcffff] [ 0.000000] ACPI: Early table checksum verification disabled [ 0.000000] ACPI: RSDP 0x00000000000F52F0 000014 (v00 BOCHS ) [ 0.000000] ACPI: RSDT 0x00000000BFFE2464 000034 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACP 0x00000000BFFE2300 000074 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: DSDT 0x00000000BFFE0040 0022C0 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: FACS 0x00000000BFFE0000 000040 [ 0.000000] ACPI: APIC 0x00000000BFFE2374 000090 (v03 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: HPET 0x00000000BFFE2404 000038 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: WAET 0x00000000BFFE243C 000028 (v01 BOCHS BXPC 00000001 BXPC 00000001) [ 0.000000] ACPI: Reserving FACP table memory at [mem 0xbffe2300-0xbffe2373] [ 0.000000] ACPI: Reserving DSDT table memory at [mem 0xbffe0040-0xbffe22ff] [ 0.000000] ACPI: Reserving FACS table memory at [mem 0xbffe0000-0xbffe003f] [ 0.000000] ACPI: Reserving APIC table memory at [mem 0xbffe2374-0xbffe2403] [ 0.000000] ACPI: Reserving HPET table memory at [mem 0xbffe2404-0xbffe243b] [ 0.000000] ACPI: Reserving WAET table memory at [mem 0xbffe243c-0xbffe2463] [ 0.000000] No NUMA configuration found [ 0.000000] Faking a node at [mem 0x0000000000000000-0x0000000146dfffff] [ 0.000000] NODE_DATA(0) allocated [mem 0x1465a3000-0x1465cdfff] [ 0.000000] Reserving 256MB of memory at 2752MB for crashkernel (System RAM: 4205MB) [ 0.000000] Zone ranges: [ 0.000000] DMA [mem 0x0000000000001000-0x0000000000ffffff] [ 0.000000] DMA32 [mem 0x0000000001000000-0x00000000ffffffff] [ 0.000000] Normal [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Device empty [ 0.000000] Movable zone start for each node [ 0.000000] Early memory node ranges [ 0.000000] node 0: [mem 0x0000000000001000-0x000000000009efff] [ 0.000000] node 0: [mem 0x0000000000100000-0x00000000bffd9fff] [ 0.000000] node 0: [mem 0x0000000100000000-0x0000000146dfffff] [ 0.000000] Zeroed struct page in unavailable ranges: 4744 pages [ 0.000000] Initmem setup node 0 [mem 0x0000000000001000-0x0000000146dfffff] [ 0.000000] ACPI: PM-Timer IO Port: 0x608 [ 0.000000] ACPI: LAPIC_NMI (acpi_id[0xff] dfl dfl lint[0x1]) [ 0.000000] IOAPIC[0]: apic_id 0, version 17, address 0xfec00000, GSI 0-23 [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 5 global_irq 5 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 10 global_irq 10 high level) [ 0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 11 global_irq 11 high level) [ 0.000000] Using ACPI (MADT) for SMP configuration information [ 0.000000] ACPI: HPET id: 0x8086a201 base: 0xfed00000 [ 0.000000] TSC deadline timer available [ 0.000000] smpboot: Allowing 4 CPUs, 0 hotplug CPUs [ 0.000000] kvm-guest: KVM setup pv remote TLB flush [ 0.000000] kvm-guest: setup PV sched yield [ 0.000000] PM: Registered nosave memory: [mem 0x00000000-0x00000fff] [ 0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff] [ 0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000effff] [ 0.000000] PM: Registered nosave memory: [mem 0x000f0000-0x000fffff] [ 0.000000] PM: Registered nosave memory: [mem 0xbffda000-0xbfffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xc0000000-0xfeffbfff] [ 0.000000] PM: Registered nosave memory: [mem 0xfeffc000-0xfeffffff] [ 0.000000] PM: Registered nosave memory: [mem 0xff000000-0xfffbffff] [ 0.000000] PM: Registered nosave memory: [mem 0xfffc0000-0xffffffff] [ 0.000000] [mem 0xc0000000-0xfeffbfff] available for PCI devices [ 0.000000] Booting paravirtualized kernel on KVM [ 0.000000] clocksource: refined-jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1910969940391419 ns [ 0.000000] setup_percpu: NR_CPUS:8192 nr_cpumask_bits:4 nr_cpu_ids:4 nr_node_ids:1 [ 0.000000] percpu: Embedded 63 pages/cpu s221184 r8192 d28672 u524288 [ 0.000000] kvm-guest: PV spinlocks enabled [ 0.000000] PV qspinlock hash table entries: 256 (order: 0, 4096 bytes, linear) [ 0.000000] Built 1 zonelists, mobility grouping on. Total pages: 1059618 [ 0.000000] Policy zone: Normal [ 0.000000] Kernel command line: rd.shell root=nbd:192.168.200.253:rocky8.10:ext4:ro:-p,-b4096 ro crashkernel=256M panic=1 nomodeset ipmtu=9000 ip=dhcp rd.neednet=1 init_on_free=off mitigations=off console=ttyS1,115200 audit=0 [ 0.000000] Specific versions of hardware are certified with Red Hat Enterprise Linux 8. Please see the list of hardware certified with Red Hat Enterprise Linux 8 at https://catalog.redhat.com. [ 0.000000] audit: disabled (until reboot) [ 0.000000] software IO TLB: area num 4. [ 0.000000] Memory: 2829700K/4306400K available (18435K kernel code, 11221K rwdata, 7248K rodata, 2908K init, 18040K bss, 524580K reserved, 0K cma-reserved) [ 0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1 [ 0.000000] kmemleak: Kernel memory leak detector disabled [ 0.000000] ftrace: allocating 41240 entries in 162 pages [ 0.000000] ftrace: allocated 162 pages with 3 groups [ 0.000000] rcu: Hierarchical RCU implementation. [ 0.000000] rcu: RCU event tracing is enabled. [ 0.000000] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=4. [ 0.000000] rcu: RCU callback double-/use-after-free debug enabled. [ 0.000000] Rude variant of Tasks RCU enabled. [ 0.000000] Tracing variant of Tasks RCU enabled. [ 0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies. [ 0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4 [ 0.000000] NR_IRQS: 524544, nr_irqs: 456, preallocated irqs: 16 [ 0.000000] random: get_random_bytes called from start_kernel+0x622/0x9a8 with crng_init=0 [ 0.001000] Console: colour *CGA 80x25 [ 0.001000] printk: console [ttyS1] enabled [ 0.001000] ACPI: Core revision 20220331 [ 0.001000] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns [ 0.001012] APIC: Switch to symmetric I/O mode setup [ 0.002377] x2apic enabled [ 0.003007] Switched APIC routing to physical x2apic. [ 0.004009] kvm-guest: setup PV IPIs [ 0.007000] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1 [ 0.007000] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 0.007019] Calibrating delay loop (skipped) preset value.. 4799.99 BogoMIPS (lpj=2399998) [ 0.008013] pid_max: default: 32768 minimum: 301 [ 0.009135] LSM: Security Framework initializing [ 0.010043] Yama: becoming mindful. [ 0.011027] SELinux: Initializing. [ 0.012048] *** VALIDATE selinux *** [ 0.020168] Dentry cache hash table entries: 1048576 (order: 11, 8388608 bytes, vmalloc) [ 0.024590] Inode-cache hash table entries: 524288 (order: 10, 4194304 bytes, vmalloc) [ 0.025147] Mount-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.026102] Mountpoint-cache hash table entries: 16384 (order: 5, 131072 bytes, vmalloc) [ 0.028095] *** VALIDATE tmpfs *** [ 0.029408] *** VALIDATE proc *** [ 0.030200] *** VALIDATE cgroup *** [ 0.031007] *** VALIDATE cgroup2 *** [ 0.033159] x86/cpu: User Mode Instruction Prevention (UMIP) activated [ 0.034138] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0 [ 0.035005] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0 [ 0.036026] Spectre V2 : User space: Vulnerable [ 0.037007] Speculative Store Bypass: Vulnerable [ 0.040518] debug: unmapping init [mem 0xffffffff98a59000-0xffffffff98a60fff] [ 0.042144] smpboot: CPU0: Intel(R) Xeon(R) CPU E5-2695 v2 @ 2.40GHz (family: 0x6, model: 0x3e, stepping: 0x4) [ 0.043591] Performance Events: IvyBridge events, full-width counters, Intel PMU driver. [ 0.044021] ... version: 2 [ 0.045009] ... bit width: 48 [ 0.046008] ... generic registers: 4 [ 0.047018] ... value mask: 0000ffffffffffff [ 0.048015] ... max period: 00007fffffffffff [ 0.049013] ... fixed-purpose events: 3 [ 0.050008] ... event mask: 000000070000000f [ 0.051276] rcu: Hierarchical SRCU implementation. [ 0.053534] smp: Bringing up secondary CPUs ... [ 0.054491] x86: Booting SMP configuration: [ 0.055020] .... node #0, CPUs: #1 #2 #3 [ 0.060610] smp: Brought up 1 node, 4 CPUs [ 0.062026] smpboot: Max logical packages: 1 [ 0.063010] smpboot: Total of 4 processors activated (19199.98 BogoMIPS) [ 0.261392] node 0 deferred pages initialised in 195ms [ 0.266141] devtmpfs: initialized [ 0.267841] x86/mm: Memory block size: 128MB [ 0.269518] gcov: version magic: 0x41383552 [ 0.273035] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275000 ns [ 0.277124] futex hash table entries: 1024 (order: 4, 65536 bytes, vmalloc) [ 0.280475] pinctrl core: initialized pinctrl subsystem [ 0.282242] [ 0.282903] ************************************************************* [ 0.285019] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.288019] ** ** [ 0.290014] ** IOMMU DebugFS SUPPORT HAS BEEN ENABLED IN THIS KERNEL ** [ 0.293251] ** ** [ 0.296019] ** This means that this kernel is built to expose internal ** [ 0.298015] ** IOMMU data structures, which may compromise security on ** [ 0.301020] ** your system. ** [ 0.304019] ** ** [ 0.306017] ** If you see this message and you are not debugging the ** [ 0.309086] ** kernel, report this immediately to your vendor! ** [ 0.312024] ** ** [ 0.314013] ** NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE NOTICE ** [ 0.316018] ************************************************************* [ 0.319777] NET: Registered protocol family 16 [ 0.321503] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations [ 0.325087] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations [ 0.328084] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations [ 0.332157] cpuidle: using governor menu [ 0.333684] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5 [ 0.336574] PCI: Using configuration type 1 for base access [ 0.339136] core: PMU erratum BJ122, BV98, HSD29 worked around, HT is on [ 0.349228] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages [ 0.352042] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages [ 0.355063] cryptd: max_cpu_qlen set to 1000 [ 0.358308] ACPI: Added _OSI(Module Device) [ 0.360246] ACPI: Added _OSI(Processor Device) [ 0.362013] ACPI: Added _OSI(3.0 _SCP Extensions) [ 0.363014] ACPI: Added _OSI(Processor Aggregator Device) [ 0.367949] ACPI: 1 ACPI AML tables successfully acquired and loaded [ 0.373427] ACPI: Interpreter enabled [ 0.374053] ACPI: PM: (supports S0 S3 S4 S5) [ 0.376012] ACPI: Using IOAPIC for interrupt routing [ 0.377129] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug [ 0.380453] ACPI: Enabled 2 GPEs in block 00 to 0F [ 0.390771] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff]) [ 0.393034] acpi PNP0A03:00: _OSC: OS supports [ASPM ClockPM Segments MSI HPX-Type3] [ 0.395015] acpi PNP0A03:00: _OSC: not requesting OS control; OS requires [ExtendedConfig ASPM ClockPM MSI] [ 0.397070] acpi PNP0A03:00: fail to add MMCONFIG information, can't access extended PCI configuration space under this bridge. [ 0.401378] acpiphp: Slot [2] registered [ 0.403116] acpiphp: Slot [5] registered [ 0.404120] acpiphp: Slot [6] registered [ 0.405110] acpiphp: Slot [3] registered [ 0.407095] acpiphp: Slot [4] registered [ 0.408079] acpiphp: Slot [7] registered [ 0.409076] acpiphp: Slot [8] registered [ 0.410085] acpiphp: Slot [9] registered [ 0.411081] acpiphp: Slot [10] registered [ 0.413131] acpiphp: Slot [11] registered [ 0.414078] acpiphp: Slot [12] registered [ 0.415137] acpiphp: Slot [13] registered [ 0.417217] acpiphp: Slot [14] registered [ 0.418352] acpiphp: Slot [15] registered [ 0.420117] acpiphp: Slot [16] registered [ 0.422118] acpiphp: Slot [17] registered [ 0.424158] acpiphp: Slot [18] registered [ 0.426605] acpiphp: Slot [19] registered [ 0.429357] acpiphp: Slot [20] registered [ 0.431171] acpiphp: Slot [21] registered [ 0.434172] acpiphp: Slot [22] registered [ 0.435130] acpiphp: Slot [23] registered [ 0.437287] acpiphp: Slot [24] registered [ 0.440159] acpiphp: Slot [25] registered [ 0.442111] acpiphp: Slot [26] registered [ 0.443133] acpiphp: Slot [27] registered [ 0.445099] acpiphp: Slot [28] registered [ 0.447102] acpiphp: Slot [29] registered [ 0.448079] acpiphp: Slot [30] registered [ 0.449110] acpiphp: Slot [31] registered [ 0.451051] PCI host bridge to bus 0000:00 [ 0.452015] pci_bus 0000:00: root bus resource [io 0x0000-0x0cf7 window] [ 0.455025] pci_bus 0000:00: root bus resource [io 0x0d00-0xffff window] [ 0.457018] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff window] [ 0.459020] pci_bus 0000:00: root bus resource [mem 0xc0000000-0xfebfffff window] [ 0.462025] pci_bus 0000:00: root bus resource [mem 0xe0000000000-0xe007fffffff window] [ 0.464021] pci_bus 0000:00: root bus resource [bus 00-ff] [ 0.466266] pci 0000:00:00.0: [8086:1237] type 00 class 0x060000 [ 0.469194] pci 0000:00:01.0: [8086:7000] type 00 class 0x060100 [ 0.473183] pci 0000:00:01.1: [8086:7010] type 00 class 0x010180 [ 0.483663] pci 0000:00:01.1: reg 0x20: [io 0xc120-0xc12f] [ 0.489063] pci 0000:00:01.1: legacy IDE quirk: reg 0x10: [io 0x01f0-0x01f7] [ 0.491033] pci 0000:00:01.1: legacy IDE quirk: reg 0x14: [io 0x03f6] [ 0.494032] pci 0000:00:01.1: legacy IDE quirk: reg 0x18: [io 0x0170-0x0177] [ 0.497028] pci 0000:00:01.1: legacy IDE quirk: reg 0x1c: [io 0x0376] [ 0.501758] pci 0000:00:01.3: [8086:7113] type 00 class 0x068000 [ 0.504824] pci 0000:00:01.3: quirk: [io 0x0600-0x063f] claimed by PIIX4 ACPI [ 0.508060] pci 0000:00:01.3: quirk: [io 0x0700-0x070f] claimed by PIIX4 SMB [ 0.512566] pci 0000:00:02.0: [1af4:1000] type 00 class 0x020000 [ 0.517013] pci 0000:00:02.0: reg 0x10: [io 0xc100-0xc11f] [ 0.528017] pci 0000:00:02.0: reg 0x20: [mem 0xe0000000000-0xe0000003fff 64bit pref] [ 0.533013] pci 0000:00:02.0: reg 0x30: [mem 0xfeb80000-0xfebbffff pref] [ 0.538142] pci 0000:00:05.0: [1af4:1001] type 00 class 0x010000 [ 0.552025] pci 0000:00:05.0: reg 0x10: [io 0xc000-0xc07f] [ 0.559015] pci 0000:00:05.0: reg 0x14: [mem 0xfebc0000-0xfebc0fff] [ 0.573016] pci 0000:00:05.0: reg 0x20: [mem 0xe0000004000-0xe0000007fff 64bit pref] [ 0.581543] pci 0000:00:06.0: [1af4:1001] type 00 class 0x010000 [ 0.591013] pci 0000:00:06.0: reg 0x10: [io 0xc080-0xc0ff] [ 0.602016] pci 0000:00:06.0: reg 0x14: [mem 0xfebc1000-0xfebc1fff] [ 0.622000] pci 0000:00:06.0: reg 0x20: [mem 0xe0000008000-0xe000000bfff 64bit pref] [ 0.634180] ACPI: PCI: Interrupt link LNKA configured for IRQ 10 [ 0.636358] ACPI: PCI: Interrupt link LNKB configured for IRQ 10 [ 0.639357] ACPI: PCI: Interrupt link LNKC configured for IRQ 11 [ 0.641338] ACPI: PCI: Interrupt link LNKD configured for IRQ 11 [ 0.643221] ACPI: PCI: Interrupt link LNKS configured for IRQ 9 [ 0.651025] iommu: Default domain type: Passthrough [ 0.653624] SCSI subsystem initialized [ 0.655513] ACPI: bus type USB registered [ 0.657145] usbcore: registered new interface driver usbfs [ 0.660230] usbcore: registered new interface driver hub [ 0.663116] usbcore: registered new device driver usb [ 0.665218] pps_core: LinuxPPS API ver. 1 registered [ 0.667017] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti [ 0.671084] PTP clock support registered [ 0.673228] EDAC MC: Ver: 3.0.0 [ 0.676198] PCI: Using ACPI for IRQ routing [ 0.677704] NetLabel: Initializing [ 0.679269] NetLabel: domain hash size = 128 [ 0.681011] NetLabel: protocols = UNLABELED CIPSOv4 CALIPSO [ 0.683094] NetLabel: unlabeled traffic allowed by default [ 0.686050] vgaarb: loaded [ 0.687278] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0 [ 0.689017] hpet0: 3 comparators, 64-bit 100.000000 MHz counter [ 0.695096] clocksource: Switched to clocksource kvm-clock [ 0.815293] VFS: Disk quotas dquot_6.6.0 [ 0.817158] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes) [ 0.819856] *** VALIDATE ramfs *** [ 0.821288] *** VALIDATE hugetlbfs *** [ 0.823604] pnp: PnP ACPI init [ 0.826234] pnp: PnP ACPI: found 6 devices [ 0.844078] clocksource: acpi_pm: mask: 0xffffff max_cycles: 0xffffff, max_idle_ns: 2085701024 ns [ 0.847662] pci_bus 0000:00: resource 4 [io 0x0000-0x0cf7 window] [ 0.850572] pci_bus 0000:00: resource 5 [io 0x0d00-0xffff window] [ 0.854285] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff window] [ 0.858585] pci_bus 0000:00: resource 7 [mem 0xc0000000-0xfebfffff window] [ 0.862018] pci_bus 0000:00: resource 8 [mem 0xe0000000000-0xe007fffffff window] [ 0.866196] NET: Registered protocol family 2 [ 0.869574] IP idents hash table entries: 131072 (order: 8, 1048576 bytes, vmalloc) [ 0.876122] tcp_listen_portaddr_hash hash table entries: 4096 (order: 5, 163840 bytes, vmalloc) [ 0.880511] TCP established hash table entries: 65536 (order: 7, 524288 bytes, vmalloc) [ 0.887673] TCP bind hash table entries: 65536 (order: 9, 2097152 bytes, vmalloc) [ 0.891814] TCP: Hash tables configured (established 65536 bind 65536) [ 0.894734] MPTCP token hash table entries: 8192 (order: 6, 393216 bytes, vmalloc) [ 0.897518] UDP hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.900279] UDP-Lite hash table entries: 4096 (order: 6, 393216 bytes, vmalloc) [ 0.903183] NET: Registered protocol family 1 [ 0.905849] RPC: Registered named UNIX socket transport module. [ 0.907666] RPC: Registered udp transport module. [ 0.909711] RPC: Registered tcp transport module. [ 0.912112] RPC: Registered tcp NFSv4.1 backchannel transport module. [ 0.915124] NET: Registered protocol family 44 [ 0.917156] pci 0000:00:00.0: Limiting direct PCI/PCI transfers [ 0.919496] pci 0000:00:01.0: PIIX3: Enabling Passive Release [ 0.921624] pci 0000:00:01.0: Activating ISA DMA hang workarounds [ 0.924217] PCI: CLS 0 bytes, default 64 [ 0.925955] Unpacking initramfs... [ 2.456686] debug: unmapping init [mem 0xffff9b233cc64000-0xffff9b233ffcffff] [ 2.463223] PCI-DMA: Using software bounce buffering for IO (SWIOTLB) [ 2.465072] software IO TLB: mapped [mem 0x00000000a8000000-0x00000000ac000000] (64MB) [ 2.468502] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x229835b7123, max_idle_ns: 440795242976 ns [ 2.949283] Initialise system trusted keyrings [ 2.950835] Key type blacklist registered [ 2.952463] workingset: timestamp_bits=36 max_order=20 bucket_order=0 [ 2.961318] zbud: loaded [ 2.965100] *** VALIDATE nfs *** [ 2.966314] *** VALIDATE nfs4 *** [ 2.971147] pstore: using deflate compression [ 2.975887] Platform Keyring initialized [ 3.107270] NET: Registered protocol family 38 [ 3.109633] Key type asymmetric registered [ 3.114947] Asymmetric key parser 'x509' registered [ 3.116821] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) [ 3.120841] io scheduler mq-deadline registered [ 3.123050] io scheduler kyber registered [ 3.125095] io scheduler bfq registered [ 3.127528] atomic64_test: passed for x86-64 platform with CX8 and with SSE [ 3.131445] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4 [ 3.135252] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input0 [ 3.138716] ACPI: Power Button [PWRF] [ 3.146264] ACPI: \_SB_.LNKB: Enabled at IRQ 10 [ 3.153621] ACPI: \_SB_.LNKA: Enabled at IRQ 11 [ 3.164774] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled [ 3.193364] 00:03: ttyS1 at I/O 0x2f8 (irq = 3, base_baud = 115200) is a 16550A [ 3.223553] 00:04: ttyS0 at I/O 0x3f8 (irq = 4, base_baud = 115200) is a 16550A [ 3.238055] Non-volatile memory driver v1.3 [ 3.240456] Linux agpgart interface v0.103 [ 3.282931] virtio_blk virtio1: [vda] 149960 512-byte logical blocks (76.8 MB/73.2 MiB) [ 3.287963] vda: detected capacity change from 0 to 76779520 [ 3.306202] virtio_blk virtio2: [vdb] 2097152 512-byte logical blocks (1.07 GB/1.00 GiB) [ 3.310450] vdb: detected capacity change from 0 to 1073741824 [ 3.322704] libphy: Fixed MDIO Bus: probed [ 3.332614] usbcore: registered new interface driver usbserial_generic [ 3.336378] usbserial: USB Serial support registered for generic [ 3.339379] i8042: PNP: PS/2 Controller [PNP0303:KBD,PNP0f13:MOU] at 0x60,0x64 irq 1,12 [ 3.345159] serio: i8042 KBD port at 0x60,0x64 irq 1 [ 3.347410] serio: i8042 AUX port at 0x60,0x64 irq 12 [ 3.350561] mousedev: PS/2 mouse device common for all mice [ 3.354203] rtc_cmos 00:05: RTC can wake from S4 [ 3.357242] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input1 [ 3.363333] rtc_cmos 00:05: registered as rtc0 [ 3.365439] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input4 [ 3.368149] rtc_cmos 00:05: alarms up to one day, y3k, 242 bytes nvram, hpet irqs [ 3.373225] input: VirtualPS/2 VMware VMMouse as /devices/platform/i8042/serio1/input/input3 [ 3.381493] intel_pstate: CPU model not supported [ 3.385264] hid: raw HID events driver (C) Jiri Kosina [ 3.387823] usbcore: registered new interface driver usbhid [ 3.390249] usbhid: USB HID core driver [ 3.392195] drop_monitor: Initializing network drop monitor service [ 3.394786] Initializing XFRM netlink socket [ 3.397205] NET: Registered protocol family 10 [ 3.400782] Segment Routing with IPv6 [ 3.403188] NET: Registered protocol family 17 [ 3.406373] mpls_gso: MPLS GSO support [ 3.411323] RAS: Correctable Errors collector initialized. [ 3.413928] AVX version of gcm_enc/dec engaged. [ 3.416043] AES CTR mode by8 optimization enabled [ 3.506374] sched_clock: Marking stable (3506255980, 0)->(4377562897, -871306917) [ 3.512451] registered taskstats version 1 [ 3.515983] Loading compiled-in X.509 certificates [ 3.518507] zswap: loaded using pool lzo/zbud [ 3.548043] Key type big_key registered [ 3.561762] Key type encrypted registered [ 3.563552] ima: No TPM chip found, activating TPM-bypass! [ 3.566174] ima: Allocated hash algorithm: sha1 [ 3.568089] ima: No architecture policies found [ 3.569984] evm: Initialising EVM extended attributes: [ 3.572230] evm: security.selinux [ 3.573740] evm: security.ima [ 3.575072] evm: security.capability [ 3.576626] evm: HMAC attrs: 0x1 [ 3.579870] rtc_cmos 00:05: setting system clock to 2026-09-14 09:20:45 UTC (1789377645) [ 3.587391] debug: unmapping init [mem 0xffffffff99a03000-0xffffffff99bfffff] [ 3.590835] debug: unmapping init [mem 0xffffffff98782000-0xffffffff98a58fff] [ 3.600070] Write protecting the kernel read-only data: 28672k [ 3.604316] debug: unmapping init [mem 0xffffffff96e03000-0xffffffff96ffffff] [ 3.608142] debug: unmapping init [mem 0xffffffff97714000-0xffffffff977fffff] [ 3.643744] systemd[1]: systemd 239 (239-82.el8_10.5) running in system mode. (+PAM +AUDIT +SELINUX +IMA -APPARMOR +SMACK +SYSVINIT +UTMP +LIBCRYPTSETUP +GCRYPT +GNUTLS +ACL +XZ +LZ4 +SECCOMP +BLKID +ELFUTILS +KMOD +IDN2 -IDN +PCRE2 default-hierarchy=legacy) [ 3.653263] systemd[1]: Detected virtualization kvm. [ 3.655593] systemd[1]: Detected architecture x86-64. [ 3.657516] systemd[1]: Running in initial RAM disk. Welcome to Rocky Linux 8.10 (Green Obsidian) dracut-049-233.git20240115.el8 (Initramfs)! [ 3.690664] systemd[1]: No hostname configured. [ 3.693326] systemd[1]: Set hostname to . [ 3.696378] random: systemd: uninitialized urandom read (16 bytes read) [ 3.699769] systemd[1]: Initializing machine ID from random generator. [ 3.865251] random: systemd: uninitialized urandom read (16 bytes read) [ 3.868531] systemd[1]: Reached target Timers. [ OK ] Reached target Timers. [ 3.873084] random: systemd: uninitialized urandom read (16 bytes read) [ 3.875965] systemd[1]: Reached target Slices. [ OK ] Reached target Slices. [ 3.880860] systemd[1]: Listening on Journal Socket (/dev/log). [ OK ] Listening on Journal Socket (/dev/log). [ OK ] Listening on udev Kernel Socket. [ OK ] Started Dispatch Password Requests to Console Directory Watch. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Reached target Local File Systems. [ OK ] Reached target Paths. [ OK ] Listening on Journal Socket. [ OK ] Started Memstrack Anylazing Service. Starting Setup Virtual Console... Starting Journal Service... Starting Apply Kernel Variables... [ OK ] Listening on udev Control Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Swap. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Reached target Initrd Root Device. Starting Create Volatile Files and Directories... [ OK ] Started Setup Virtual Console. [ OK ] Started Apply Kernel Variables. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Started Create Volatile Files and Directories. Starting Create Static Device Nodes in /dev... Starting dracut cmdline hook... [ OK ] Started Journal Service. [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started dracut cmdline hook. Starting dracut pre-udev hook... [ 4.689351] device-mapper: uevent: version 1.0.3 [ 4.691443] 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... [ 5.189430] random: fast init done Mounting Kernel Configuration File System... [ OK ] Mounted Kernel Configuration File System. [ OK ] Started udev Coldplug all Devices. [ OK ] Reached target System Initialization. [ OK ] Reached target Basic System. [ OK ] Started Hardware RNG Entropy Gatherer Daemon. Starting dracut initqueue hook... [ 5.525144] virtio_net virtio0 ens2: renamed from eth0 [ 5.600918] scsi host0: ata_piix [ 5.610171] scsi host1: ata_piix [ 5.612089] ata1: PATA max MWDMA2 cmd 0x1f0 ctl 0x3f6 bmdma 0xc120 irq 14 [ 5.614680] ata2: PATA max MWDMA2 cmd 0x170 ctl 0x376 bmdma 0xc128 irq 15 [ 9.359524] dracut-initqueue[580]: RTNETLINK answers: File exists [ 10.113784] random: crng init done [ 10.115432] 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). [ OK ] Reached target Remote File Systems. [ 10.784401] EXT4-fs (nbd0): mounted filesystem with ordered data mode. Opts: (null) [ OK ] Mounted /sysroot. [ OK ] Reached target Initrd Root File System. Starting Reload Configuration from the Real Root... [ OK ] Started Reload Configuration from the Real Root. [ OK ] Reached target Initrd File Systems. [ OK ] Reached target Initrd Default Target. Starting dracut pre-pivot and cleanup hook... [ OK ] Started dracut pre-pivot and cleanup hook. Starting Cleaning Up and Shutting Down Daemons... [ OK ] Stopped target Timers. [ OK ] Stopped dracut pre-pivot and cleanup hook. [ OK ] Stopped target Initrd Default Target. [ OK ] Stopped target Initrd Root Device. [ 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 Hardware RNG Entropy Gatherer Daemon. [ OK ] Stopped target Basic System. [ OK ] Stopped target Slices. [ OK ] Stopped target Paths. [ OK ] Stopped target Sockets. [ OK ] Stopped target System Initialization. [ OK ] Stopped Apply Kernel Variables. [ OK ] Stopped udev Coldplug all Devices. [ OK ] Stopped dracut pre-trigger hook. Stopping udev Kernel Device Manager... [ OK ] Stopped target Local Encrypted Volumes. [ OK ] Stopped Dispatch Password Requests to Console Directory Watch. [ OK ] Stopped Create Volatile Files and Directories. [ OK ] Stopped target Local File Systems. [ OK ] Stopped target Swap. [ 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... [ 12.297268] printk: systemd: 25 output lines suppressed due to ratelimiting [ 12.617909] SELinux: Disabled at runtime. [ 12.684265] 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) [ 12.692855] systemd[1]: Detected virtualization kvm. [ 12.695053] systemd[1]: Detected architecture x86-64. Welcome to Rocky Linux 8.10 (Green Obsidian)! [ 13.221133] systemd[1]: initrd-switch-root.service: Succeeded. [ 13.224421] systemd[1]: Stopped Switch Root. [ OK ] Stopped Switch Root. [ 13.229556] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart. [ 13.235284] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1. [ 13.238852] systemd[1]: Stopped Journal Service. [ OK ] Stopped Journal Service. [ 13.246359] systemd[1]: Starting Journal Service... Starting Journal Service... [ 13.251436] systemd[1]: Reached target rpc_pipefs.target. [ OK ] Reached target rpc_pipefs.target. [ OK ] Listening on initctl Compatibility Named Pipe. [ OK ] Listening on udev Kernel Socket. [ OK ] Listening on udev Control Socket. [ OK ] Started Dispatch Password Requests to Console Directory Watch. Activating swap /dev/disk/by-label/SWAP... [ OK ] Created slice system-sshd\x2dkeygen.slice. [ OK ] Created slice User and Session Slice. Mounting Kernel Debug File System... Mounting Huge Pages File System... [ 13.311211] Adding 1048572k swap on /dev/vdb. Priority:-2 extents:1 across:1048572k FS Starting udev Coldplug all Devices... [ OK ] Started Forward Password Requests to Wall Directory Watch. [ OK ] Reached target Paths. [ OK ] Reached target Local Encrypted Volumes. [ OK ] Listening on RPCbind Server Activation Socket. [ OK ] Reached target RPC Port Mapper. Starting Apply Kernel Variables... Starting Remount Root and Kernel File Systems... [ OK ] Created slice system-getty.slice. [ OK ] Stopped target Switch Root. [ OK ] Stopped target Initrd File Systems. [ OK ] Stopped target Initrd Root File System. [ OK ] Listening on Process Core Dump Socket. Starting Create list of required st…ce nodes for the current kernel... [ OK ] Reached target Slices. 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-serial\x2dgetty.slice. [ OK ] Started Journal Service. [ OK ] Activated swap /dev/disk/by-label/SWAP. [ OK ] Mounted Kernel Debug File System. [ OK ] Mounted Huge Pages File System. [ OK ] Started Apply Kernel Variables. [FAILED] Failed to start Remount Root and Kernel File Systems. See 'systemctl status systemd-remount-fs.service' for details. [ OK ] Started Create list of required sta…vice nodes for the current kernel. [ OK ] Mounted POSIX Message Queue File System. Starting Create Static Device Nodes in /dev... Starting Configure read-only root support... [ OK ] Reached target Swap. Starting Flush Journal to Persistent Storage... [ OK ] Started Create Static Device Nodes in /dev. [ OK ] Started Flush Journal to Persistent Storage. 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. [ 13.817259] squashfs: version 4.0 (2009/01/31) Phillip Lougher [ OK ] Mounted /home/green/git/lustre-release. [ OK ] Started udev Kernel Device Manager. [ 14.145838] piix4_smbus 0000:00:01.3: SMBus Host Controller at 0x700, revision 0 [ 14.147308] input: PC Speaker as /devices/platform/pcspkr/input/input5 [ 14.473278] RAPL PMU: API unit is 2^-32 Joules, 0 fixed counters, 10737418240 ms ovfl timer [ 14.481847] EDAC sbridge: Ver: 1.1.2 [ 15.907336] Key type dns_resolver registered [ 16.226900] NFS: Registering the id_resolver key type [ 16.232715] Key type id_resolver registered [ 16.234015] Key type id_legacy registered [ OK ] Started Configure read-only root support. [ OK ] Reached target Local File Systems. Starting Rebuild Dynamic Linker Cache... Starting Mark the need to relabel after reboot... Starting Create Volatile Files and Directories... Starting Load/Save Random Seed... [ OK ] Started Mark the need to relabel after reboot. [ OK ] Started Load/Save Random Seed. [ OK ] Started Create Volatile Files and Directories. Starting 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 ] Listening on D-Bus System Message Bus Socket. [ OK ] Reached target Sockets. [ OK ] Reached target Basic System. [ OK ] Started irqbalance daemon. Starting Restore /run/initramfs on shutdown... [ OK ] Started Hardware RNG Entropy Gatherer Daemon. [ OK ] Started D-Bus System Message Bus. Starting Network Manager... [ OK ] Started daily update of the root trust anchor for DNSSEC. [ OK ] Reached target sshd-keygen.target. [ OK ] Started dnf makecache --timer. Starting Login Service... [ OK ] Started Daily Cleanup of Temporary Directories. [ OK ] Reached target Timers. [ OK ] Started Restore /run/initramfs on shutdown. [ OK ] Started Network Manager. [ OK ] Reached target Network. Starting GSSAPI Proxy Daemon... Starting Dynamic System Tuning Daemon... Starting OpenSSH server daemon... Starting Network Manager Wait Online... [ 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... Starting Hostname Service... [ OK ] Started Permit User Sessions. [ OK ] Started Command Scheduler. [ OK ] Started Serial Getty on ttyS0. [ OK ] Started Serial Getty on ttyS1. [ OK ] Started Getty on tty1. [ OK ] Reached target Login Prompts. [ OK ] Started Hostname Service. Starting Network Manager Script Dispatcher Service... [ OK ] Started Network Manager Script Dispatcher Service. [ OK ] Started Network Manager Wait Online. [ OK ] Reached target Network is Online. Starting System Logging Service... Starting Crash recovery kernel arming... Starting Notify NFS peers of a restart... [ OK ] Started Notify NFS peers of a restart. [ OK ] Started System Logging Service. Starting Authorization Manager... [ OK ] Started Dynamic System Tuning Daemon. [ OK ] Reached target Multi-User System. [ OK ] Reached target Graphical Interface. Starting Update UTMP about System Runlevel Changes... Rocky Linux 8.10 (Green Obsidian) Kernel 4.18.0rh8.10-debug on an x86_64 oleg326-client login: [ 91.744633] libcfs: loading out-of-tree module taints kernel. [ 91.866520] Key type ._llcrypt registered [ 91.868036] Key type .llcrypt registered [ 92.358485] libcfs: HW NUMA nodes: 1, HW CPU cores: 4, npartitions: 2 [ 92.395678] alg: No test for adler32 (adler32-zlib) [ 93.751500] Lustre: Lustre: Build Version: 2.17.58_39_gb3cb314 [ 94.545560] LNet: Added LNI 192.168.203.26@tcp [8/256/0/180] [ 96.431237] Key type lgssc registered [ 98.248528] Lustre: Echo OBD driver; http://www.lustre.org/ [ 281.122019] hrtimer: interrupt took 18616379 ns [ 295.125665] Lustre: Mounted lustre-client - version 2.17.58_39_gb3cb314 [ 295.328209] LustreError: 6209:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [ 295.356565] LustreError: 6209:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 0 [ 297.759750] LustreError: 6261:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [ 297.766763] LustreError: 6261:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 1 [ 300.710097] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 317.854608] Lustre: DEBUG MARKER: oleg326-client.virtnet: executing check_logdir /tmp/testlogs/ [ 321.001894] Lustre: lustre-OST0000-osc-ffff9b2390b78800: disconnect after 23s idle [ 323.638430] Lustre: DEBUG MARKER: oleg326-client.virtnet: executing yml_node [ 329.055294] Lustre: DEBUG MARKER: Client: 2.17.58.39 [ 331.807926] Lustre: DEBUG MARKER: MDS: 2.17.58.39 [ 334.375416] Lustre: DEBUG MARKER: OSS: 2.17.58.39 [ 336.077885] Lustre: DEBUG MARKER: -----============= acceptance-small: sanity ============----- Mon Sep 14 05:26:16 EDT 2026 [ 356.907395] Lustre: DEBUG MARKER: - need MDS1_VERSION <= 2.16.61-1-g89cf292a8c2 (34683431 <= 34618625) for LU-18938, skip 360 [ 358.439830] Lustre: DEBUG MARKER: - need MDS1_VERSION < v2_14_55-100-g8a84c7f9c7 (34683431 < 34486116) for LU-14927, skip 0f [ 360.103733] Lustre: DEBUG MARKER: - need OST1_VERSION < v2_17_50-410-gbd8e7b9555 (34683431 < 34681754) for LU-12550, skip 216 [ 361.416110] Lustre: DEBUG MARKER: excepting tests: 56oc 42a 42c 42b 118c 118d 407 119i 216 817 411a [ 362.625456] Lustre: DEBUG MARKER: skipping tests SLOW=no: 27m 60i 64b 68 71 135 136 230d 300o 842 51c 51e 834 [ 364.028226] Lustre: DEBUG MARKER: === sanity: start setup 05:26:44 (1789378004) === [ 364.377122] LustreError: 8253:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [ 364.389622] LustreError: 8253:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 2 previous similar messages [ 364.398868] LustreError: 8253:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 1 [ 364.403657] LustreError: 8253:0:(namei.c:956:ll_intent_lock()) Skipped 2 previous similar messages [ 372.130241] Lustre: DEBUG MARKER: oleg326-client.virtnet: executing check_config_client /mnt/lustre [ 393.856704] Lustre: DEBUG MARKER: Using TIMEOUT=20 [ 408.708867] Lustre: DEBUG MARKER: === sanity: finish setup 05:27:28 (1789378048) === [ 408.821067] LustreError: 8253:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [ 408.832966] LustreError: 8253:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 3 previous similar messages [ 408.852144] LustreError: 8253:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 1 [ 408.868238] LustreError: 8253:0:(namei.c:956:ll_intent_lock()) Skipped 3 previous similar messages [ 408.886191] LustreError: 8253:0:(dcache.c:176:ll_intent_release()) intent ffffae0bc1a0f8d0 released [ 409.027223] LustreError: 11283:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [ 409.139504] LustreError: 11286:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [ 409.160580] LustreError: 11286:0:(namei.c:1721:ll_create_it()) VFS Op:name=f8253, dir=[0x200000402:0x1:0x0](ffff9b239191b248), intent=open|creat [ 409.168619] LustreError: 11286:0:(namei.c:1744:ll_create_it()) inode ffff9b2391970908 need_sync_to_mds [0x200000402:0x2:0x0] [ 409.218343] LustreError: 11287:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [ 411.030333] Lustre: DEBUG MARKER: == sanity test 0a: touch; rm ============================= 05:27:31 (1789378051) [ 411.248024] LustreError: 11442:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [ 411.305698] LustreError: 11442:0:(namei.c:1721:ll_create_it()) VFS Op:name=f0a.sanity, dir=[0x200000007:0x1:0x0](ffff9b23919180c8), intent=open|creat [ 411.337635] LustreError: 11442:0:(namei.c:1744:ll_create_it()) inode ffff9b2391979988 need_sync_to_mds [0x200000402:0x3:0x0] [ 411.356457] LustreError: 11442:0:(dcache.c:176:ll_intent_release()) intent ffff9b2383fa6480 released [ 411.367697] LustreError: 11442:0:(dcache.c:176:ll_intent_release()) Skipped 6 previous similar messages [ 419.816082] Lustre: DEBUG MARKER: == sanity test 0b: chmod 0755 /mnt/lustre ======================================================================================= 05:27:40 (1789378060) [ 419.870066] LustreError: 12012:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [ 419.896591] LustreError: 12012:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 60 previous similar messages [ 419.900779] LustreError: 12012:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 1 [ 419.913772] LustreError: 12012:0:(namei.c:956:ll_intent_lock()) Skipped 44 previous similar messages [ 428.934097] Lustre: DEBUG MARKER: == sanity test 0c: check import proc ===================== 05:27:48 (1789378068) [ 433.648166] Lustre: lustre-OST0001-osc-ffff9b2390b78800: disconnect after 24s idle [ 433.661342] Lustre: Skipped 1 previous similar message [ 436.898096] Lustre: DEBUG MARKER: == sanity test 0d: check export proc ===================== 05:27:56 (1789378076) [ 437.239442] LustreError: 13184:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [ 437.247979] LustreError: 13184:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 2 previous similar messages [ 437.253942] LustreError: 13184:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 1 [ 437.259827] LustreError: 13184:0:(namei.c:956:ll_intent_lock()) Skipped 1 previous similar message [ 437.265335] LustreError: 13184:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [ 437.314106] LustreError: 13184:0:(namei.c:1721:ll_create_it()) VFS Op:name=f0d.sanity.import, dir=[0x200000007:0x1:0x0](ffff9b23919180c8), intent=open|creat [ 437.326150] LustreError: 13184:0:(namei.c:1744:ll_create_it()) inode ffff9b239191ba88 need_sync_to_mds [0x200000402:0x4:0x0] [ 437.332992] LustreError: 13184:0:(dcache.c:176:ll_intent_release()) intent ffff9b2390de1b40 released [ 437.338234] LustreError: 13184:0:(dcache.c:176:ll_intent_release()) Skipped 3 previous similar messages [ 438.753912] Lustre: lustre-OST0000-osc-ffff9b2390b78800: disconnect after 24s idle [ 441.019197] LustreError: 13230:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [ 441.049898] LustreError: 13230:0:(namei.c:1721:ll_create_it()) VFS Op:name=f0d.sanity.export, dir=[0x200000007:0x1:0x0](ffff9b23919180c8), intent=open|creat [ 441.080284] LustreError: 13230:0:(namei.c:1744:ll_create_it()) inode ffff9b239191cb08 need_sync_to_mds [0x200000402:0x5:0x0] [ 441.085719] LustreError: 13230:0:(dcache.c:176:ll_intent_release()) intent ffff9b2383fa67e0 released [ 441.783417] LustreError: 13239:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [ 449.115475] Lustre: DEBUG MARKER: == sanity test 0e: Enable DNE MDT balancing for mkdir in the ROOT ========================================================== 05:28:08 (1789378088) [ 449.307334] LustreError: 13839:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [ 449.598092] LustreError: 13847:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [ 449.681229] LustreError: 13847:0:(dcache.c:176:ll_intent_release()) intent ffff9b2383fa6660 released [ 449.694747] LustreError: 13847:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [ 449.702833] LustreError: 13847:0:(file.c:977:ll_kernel_to_mds_open_flags()) Skipped 2 previous similar messages [ 455.613613] Lustre: DEBUG MARKER: == sanity test 1: mkdir; remkdir; rmdir ================== 05:28:16 (1789378096) [ 455.748403] LustreError: 14432:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [ 455.764560] LustreError: 14432:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 50 previous similar messages [ 455.808310] LustreError: 14432:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 0 [ 455.825917] LustreError: 14432:0:(namei.c:956:ll_intent_lock()) Skipped 38 previous similar messages [ 455.841055] LustreError: 14432:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [ 455.853180] LustreError: 14432:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 1 previous similar message [ 456.046893] LustreError: 14443:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [ 456.053253] LustreError: 14443:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 1 previous similar message [ 461.819930] Lustre: DEBUG MARKER: == sanity test 2: mkdir; touch; rmdir; check file ======== 05:28:22 (1789378102) [ 462.011512] LustreError: 15026:0:(dcache.c:176:ll_intent_release()) intent ffffae0bc1a17930 released [ 462.021510] LustreError: 15026:0:(dcache.c:176:ll_intent_release()) Skipped 11 previous similar messages [ 462.048012] LustreError: 15026:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [ 462.062919] LustreError: 15026:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 2 previous similar messages [ 462.183283] LustreError: 15033:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [ 462.191538] LustreError: 15033:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 2 previous similar messages [ 462.267282] LustreError: 15033:0:(namei.c:1721:ll_create_it()) VFS Op:name=f2.sanity, dir=[0x200000402:0x8:0x0](ffff9b2391979988), intent=open|creat [ 462.277092] LustreError: 15033:0:(namei.c:1744:ll_create_it()) inode ffff9b23919d2a08 need_sync_to_mds [0x240000402:0x4:0x0] [ 462.391207] LustreError: 15035:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [ 468.676821] Lustre: DEBUG MARKER: == sanity test 3: mkdir; touch; rmdir; check dir ========= 05:28:29 (1789378109) [ 468.928762] LustreError: 15617:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [ 469.239123] LustreError: 15624:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [ 469.245905] LustreError: 15624:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 1 previous similar message [ 476.482892] Lustre: DEBUG MARKER: == sanity test 4: mkdir; touch dir/file; rmdir; checkdir (expect error) ========================================================== 05:28:36 (1789378116) [ 477.077550] LustreError: 16210:0:(namei.c:1721:ll_create_it()) VFS Op:name=f4.sanity, dir=[0x240000402:0x7:0x0](ffff9b23919d5b88), intent=open|creat [ 477.097286] LustreError: 16210:0:(namei.c:1721:ll_create_it()) Skipped 1 previous similar message [ 477.107416] LustreError: 16210:0:(namei.c:1744:ll_create_it()) inode ffff9b239197a1c8 need_sync_to_mds [0x200000402:0x9:0x0] [ 477.114355] LustreError: 16210:0:(namei.c:1744:ll_create_it()) Skipped 1 previous similar message [ 477.280302] LustreError: 16212:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [ 477.294507] LustreError: 16212:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 1 previous similar message [ 484.591378] Lustre: DEBUG MARKER: == sanity test 5: mkdir .../d5 .../d5/d2; chmod .../d5/d2 ========================================================== 05:28:44 (1789378124) [ 484.838615] LustreError: 16792:0:(dcache.c:176:ll_intent_release()) intent ffffae0bc1d0f930 released [ 484.845324] LustreError: 16792:0:(dcache.c:176:ll_intent_release()) Skipped 16 previous similar messages [ 484.859936] LustreError: 16792:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [ 484.874370] LustreError: 16792:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 1 previous similar message [ 491.179502] Lustre: DEBUG MARKER: == sanity test 6a: touch f6a; chmod f6a; runas -u 500 -g 500 chmod f6a (should return error) ============================================================ 05:28:51 (1789378131) [ 491.518656] LustreError: 17385:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [ 491.529303] LustreError: 17385:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 165 previous similar messages [ 491.536318] LustreError: 17385:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 1 [ 491.543073] LustreError: 17385:0:(namei.c:956:ll_intent_lock()) Skipped 127 previous similar messages [ 491.551178] LustreError: 17385:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [ 491.560092] LustreError: 17385:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 2 previous similar messages [ 500.937336] Lustre: DEBUG MARKER: == sanity test 6c: touch f6c; chown f6c; runas -u 500 -g 500 chown f6c (should return error) ============================================================ 05:29:00 (1789378140) [ 501.265942] LustreError: 17966:0:(namei.c:1721:ll_create_it()) VFS Op:name=f6c.sanity, dir=[0x200000007:0x1:0x0](ffff9b23919180c8), intent=open|creat [ 501.281284] LustreError: 17966:0:(namei.c:1721:ll_create_it()) Skipped 1 previous similar message [ 501.306172] LustreError: 17966:0:(namei.c:1744:ll_create_it()) inode ffff9b2391918908 need_sync_to_mds [0x200000402:0xb:0x0] [ 501.327104] LustreError: 17966:0:(namei.c:1744:ll_create_it()) Skipped 1 previous similar message [ 510.575834] Lustre: DEBUG MARKER: == sanity test 6e: touch+chgrp ; runas -u 500 -g 500 chgrp (should return error) ========================================================== 05:29:10 (1789378150) [ 517.467679] Lustre: DEBUG MARKER: == sanity test 6g: verify new dir in sgid dir inherits group ========================================================== 05:29:17 (1789378157) [ 517.971497] LustreError: 19135:0:(dcache.c:176:ll_intent_release()) intent ffffae0bc1def930 released [ 517.979487] LustreError: 19135:0:(dcache.c:176:ll_intent_release()) Skipped 15 previous similar messages [ 517.991503] LustreError: 19135:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [ 518.002232] LustreError: 19135:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 1 previous similar message [ 518.474120] LustreError: 19147:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [ 518.484738] LustreError: 19147:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 2 previous similar messages [ 526.013298] Lustre: DEBUG MARKER: == sanity test 6h: runas -u 500 -g 500 chown RUNAS_ID.0 .../ (should return error) ========================================================== 05:29:26 (1789378166) [ 526.255762] LustreError: 19731:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [ 526.264437] LustreError: 19731:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 2 previous similar messages [ 532.334575] Lustre: DEBUG MARKER: == sanity test 6i: touch+chmod+chgrp ; chgrp read-only file should succeed ========================================================== 05:29:32 (1789378172) [ 539.886548] Lustre: DEBUG MARKER: == sanity test 7a: mkdir .../d7; mcreate .../d7/f; chmod .../d7/f ============================================================== 05:29:40 (1789378180) [ 549.424530] Lustre: DEBUG MARKER: == sanity test 7b: mkdir .../d7; mcreate d7/f2; echo foo > d7/f2 =============================================================== 05:29:48 (1789378188) [ 550.106180] LustreError: 21489:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [ 550.123726] LustreError: 21489:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 7 previous similar messages [ 561.329201] Lustre: DEBUG MARKER: == sanity test 8: mkdir .../d8; touch .../d8/f; chmod .../d8/f ================================================================= 05:29:59 (1789378199) [ 561.818262] LustreError: 22077:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [ 561.837788] LustreError: 22077:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 213 previous similar messages [ 561.860191] LustreError: 22077:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 1 [ 561.876697] LustreError: 22077:0:(namei.c:956:ll_intent_lock()) Skipped 177 previous similar messages [ 562.037393] LustreError: 22078:0:(namei.c:1721:ll_create_it()) VFS Op:name=f8.sanity, dir=[0x200000402:0x12:0x0](ffff9b239197ec08), intent=open|creat [ 562.044609] LustreError: 22078:0:(namei.c:1721:ll_create_it()) Skipped 3 previous similar messages [ 562.049864] LustreError: 22078:0:(namei.c:1744:ll_create_it()) inode ffff9b23919faa08 need_sync_to_mds [0x240000402:0x11:0x0] [ 562.056553] LustreError: 22078:0:(namei.c:1744:ll_create_it()) Skipped 3 previous similar messages [ 570.747617] Lustre: DEBUG MARKER: == sanity test 9: mkdir .../d9 .../d9/d2 .../d9/d2/d3 ========================================================================== 05:30:10 (1789378210) [ 571.604765] LustreError: 22673:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [ 571.615405] LustreError: 22673:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 1 previous similar message [ 580.513742] Lustre: DEBUG MARKER: == sanity test 10: mkdir .../d10 .../d10/d2; touch .../d10/d2/f ================================================================ 05:30:20 (1789378220) [ 589.563688] Lustre: DEBUG MARKER: == sanity test 11: mkdir .../d11 d11/d2; chmod .../d11/d2 ====================================================================== 05:30:29 (1789378229) [ 589.833897] LustreError: 23856:0:(dcache.c:176:ll_intent_release()) intent ffffae0bc1d0f930 released [ 589.842844] LustreError: 23856:0:(dcache.c:176:ll_intent_release()) Skipped 51 previous similar messages [ 599.514862] Lustre: DEBUG MARKER: == sanity test 12: touch .../d12/f; chmod .../d12/f .../d12/f ================================================================== 05:30:39 (1789378239) [ 599.888093] LustreError: 24461:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [ 599.905090] LustreError: 24461:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 5 previous similar messages [ 608.112429] Lustre: DEBUG MARKER: == sanity test 13: creat .../d13/f; dd .../d13/f; > .../d13/f ================================================================== 05:30:48 (1789378248) [ 608.684493] LustreError: 24896:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [ 618.919317] Lustre: DEBUG MARKER: == sanity test 14: touch .../d14/f; rm .../d14/f; rm .../d14/f ================================================================= 05:30:58 (1789378258) [ 619.467986] LustreError: 25636:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [ 619.493755] LustreError: 25636:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 10 previous similar messages [ 629.547763] Lustre: DEBUG MARKER: == sanity test 15: touch .../d15/f; mv .../d15/f .../d15/f2 ==================================================================== 05:31:09 (1789378269) [ 630.075151] LustreError: 26225:0:(namei.c:1721:ll_create_it()) VFS Op:name=f15.sanity, dir=[0x240000402:0x1c:0x0](ffff9b2391a15348), intent=open|creat [ 630.083241] LustreError: 26225:0:(namei.c:1721:ll_create_it()) Skipped 4 previous similar messages [ 630.088615] LustreError: 26225:0:(namei.c:1744:ll_create_it()) inode ffff9b2391a163c8 need_sync_to_mds [0x240000402:0x1d:0x0] [ 630.095816] LustreError: 26225:0:(namei.c:1744:ll_create_it()) Skipped 4 previous similar messages [ 636.822228] Lustre: DEBUG MARKER: == sanity test 16: touch .../d16/f; rm -rf .../d16/f ===== 05:31:17 (1789378277) [ 643.634368] Lustre: DEBUG MARKER: == sanity test 17a: symlinks: create, remove (real) ====== 05:31:24 (1789378284) [ 644.111909] LustreError: 27402:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [ 644.120134] LustreError: 27402:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 3 previous similar messages [ 652.064231] Lustre: DEBUG MARKER: == sanity test 17b: symlinks: create, remove (dangling) == 05:31:31 (1789378291) [ 662.162560] Lustre: DEBUG MARKER: == sanity test 17c: symlinks: open dangling (should return error) ========================================================== 05:31:41 (1789378301) [ 673.861684] Lustre: DEBUG MARKER: == sanity test 17d: symlinks: create dangling ============ 05:31:53 (1789378313) [ 683.764986] Lustre: DEBUG MARKER: == sanity test 17e: symlinks: create recursive symlink (should return error) ========================================================== 05:32:03 (1789378323) [ 695.344643] Lustre: DEBUG MARKER: == sanity test 17f: symlinks: long and very long symlink name ========================================================== 05:32:15 (1789378335) [ 695.710553] LustreError: 30349:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [ 695.718600] LustreError: 30349:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 415 previous similar messages [ 695.724726] LustreError: 30349:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 1 [ 695.732875] LustreError: 30349:0:(namei.c:956:ll_intent_lock()) Skipped 344 previous similar messages [ 704.250886] Lustre: DEBUG MARKER: == sanity test 17g: symlinks: really long symlink name and inode boundaries ========================================================== 05:32:23 (1789378343) [ 716.136678] Lustre: DEBUG MARKER: == sanity test 17h: create objects: lov_free_memmd() doesn't lbug ========================================================== 05:32:36 (1789378356) [ 716.914191] LustreError: 31584:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [ 716.985494] LustreError: 31585:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [ 717.003221] LustreError: 31585:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 2 previous similar messages [ 718.052601] LustreError: 31594:0:(dcache.c:176:ll_intent_release()) intent ffff9b2385f90b40 released [ 718.077662] LustreError: 31594:0:(dcache.c:176:ll_intent_release()) Skipped 113 previous similar messages [ 726.998564] Lustre: DEBUG MARKER: == sanity test 17i: don't panic on short symlink (should return error) ========================================================== 05:32:46 (1789378366) [ 727.805093] LustreError: 32211:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [ 729.808298] LustreError: 32221:0:(symlink.c:84:ll_readlink_internal()) lustre: inode [0x240000402:0x31:0x0]: symlink length 33 not expected 35 [ 742.020203] Lustre: DEBUG MARKER: == sanity test 17k: symlinks: rsync with xattrs enabled == 05:33:01 (1789378381) [ 742.973178] LustreError: 32823:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [ 742.996300] LustreError: 32823:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 12 previous similar messages [ 743.780096] LustreError: 32825:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [ 754.789383] Lustre: DEBUG MARKER: == sanity test 17l: Ensure lgetxattr's returned xattr size is consistent ========================================================== 05:33:15 (1789378395) [ 755.139879] LustreError: 33417:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [ 755.149430] LustreError: 33417:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 32 previous similar messages [ 762.372648] Lustre: DEBUG MARKER: == sanity test 17m: run e2fsck against MDT which contains short/long symlink ========================================================== 05:33:22 (1789378402) [ 842.247260] LustreError: 36109:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [ 848.399174] Lustre: lustre-MDT0001-mdc-ffff9b2390b78800: Connection to lustre-MDT0001 (at 192.168.203.126@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 861.015721] LustreError: 2402:0:(client.c:3449:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9b2390da4700 x1876298549081472/t4294967449(4294967449) o101->lustre-MDT0001-mdc-ffff9b2390b78800@192.168.203.126@tcp:12/10 lens 608/608 e 0 to 0 dl 1789378518 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'lfs.0' uid:0 gid:0 projid:0 [ 864.546304] Lustre: lustre-MDT0001-mdc-ffff9b2390b78800: Connection restored to 192.168.203.126@tcp (at 192.168.203.126@tcp) [ 898.238473] Lustre: DEBUG MARKER: == sanity test 17n: run e2fsck against master/slave MDT which contains remote dir ========================================================== 05:35:38 (1789378538) [ 899.614938] LustreError: 36986:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [ 899.634316] LustreError: 36986:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 3 previous similar messages [ 899.846209] LustreError: 36987:0:(namei.c:1721:ll_create_it()) VFS Op:name=f0, dir=[0x240000402:0x339:0x0](ffff9b238347db88), intent=open|creat [ 899.851182] LustreError: 36987:0:(namei.c:1721:ll_create_it()) Skipped 7 previous similar messages [ 899.855717] LustreError: 36987:0:(namei.c:1744:ll_create_it()) inode ffff9b2383478908 need_sync_to_mds [0x200000402:0x327:0x0] [ 899.860345] LustreError: 36987:0:(namei.c:1744:ll_create_it()) Skipped 7 previous similar messages [ 907.766706] Lustre: lustre-MDT0000-mdc-ffff9b2390b78800: Connection to lustre-MDT0000 (at 192.168.203.126@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 923.103363] Lustre: 2406:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789378549/real 1789378549] req@ffff9b2387b73800 x1876298550586880/t0(0) o400->MGC192.168.203.126@tcp@192.168.203.126@tcp:26/25 lens 224/224 e 0 to 1 dl 1789378565 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 923.130884] LustreError: MGC192.168.203.126@tcp: Connection to MGS (at 192.168.203.126@tcp) was lost; in progress operations using this service will fail [ 923.150952] Lustre: Evicted from MGS (at 192.168.203.126@tcp) after server handle changed from 0xc50e9934a47e44a6 to 0xc50e9934a4813add [ 923.173334] Lustre: MGC192.168.203.126@tcp: Connection restored to 192.168.203.126@tcp (at 192.168.203.126@tcp) [ 923.210454] LustreError: 2402:0:(client.c:3449:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9b23891bb800 x1876298548934912/t4294967323(4294967323) o101->lustre-MDT0000-mdc-ffff9b2390b78800@192.168.203.126@tcp:12/10 lens 576/608 e 0 to 0 dl 1789378581 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'grep.0' uid:0 gid:0 projid:0 [ 928.249600] Lustre: lustre-MDT0001-mdc-ffff9b2390b78800: Connection to lustre-MDT0001 (at 192.168.203.126@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 940.258893] LustreError: 2402:0:(client.c:3449:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9b2390da4700 x1876298549081472/t4294967449(4294967449) o101->lustre-MDT0001-mdc-ffff9b2390b78800@192.168.203.126@tcp:12/10 lens 608/608 e 0 to 0 dl 1789378598 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'lfs.0' uid:0 gid:0 projid:0 [ 943.903707] Lustre: lustre-MDT0001-mdc-ffff9b2390b78800: Connection restored to 192.168.203.126@tcp (at 192.168.203.126@tcp) [ 943.918471] Lustre: Skipped 1 previous similar message [ 955.895502] Lustre: lustre-MDT0000-mdc-ffff9b2390b78800: Connection to lustre-MDT0000 (at 192.168.203.126@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 971.231813] Lustre: 2404:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789378597/real 1789378597] req@ffff9b2387ae0a80 x1876298550658432/t0(0) o400->MGC192.168.203.126@tcp@192.168.203.126@tcp:26/25 lens 224/224 e 0 to 1 dl 1789378613 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 971.254725] LustreError: MGC192.168.203.126@tcp: Connection to MGS (at 192.168.203.126@tcp) was lost; in progress operations using this service will fail [ 971.343402] LustreError: 2402:0:(client.c:3449:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9b23891bb800 x1876298548934912/t4294967323(4294967323) o101->lustre-MDT0000-mdc-ffff9b2390b78800@192.168.203.126@tcp:12/10 lens 576/608 e 0 to 0 dl 1789378629 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'grep.0' uid:0 gid:0 projid:0 [ 971.390324] LustreError: 2402:0:(client.c:3449:ptlrpc_replay_interpret()) Skipped 1 previous similar message [ 971.415512] Lustre: Evicted from MGS (at 192.168.203.126@tcp) after server handle changed from 0xc50e9934a4813add to 0xc50e9934a48161aa [ 971.523296] Lustre: MGC192.168.203.126@tcp: Connection restored to 192.168.203.126@tcp (at 192.168.203.126@tcp) [ 979.210793] LustreError: 37743:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [ 979.227362] LustreError: 37743:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 19924 previous similar messages [ 979.243441] LustreError: 37743:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 1 [ 979.255557] LustreError: 37743:0:(namei.c:956:ll_intent_lock()) Skipped 14029 previous similar messages [ 981.505544] LustreError: 2404:0:(dcache.c:176:ll_intent_release()) intent ffff9b238822f590 released [ 981.512265] LustreError: 2404:0:(dcache.c:176:ll_intent_release()) Skipped 7907 previous similar messages [ 986.638470] Lustre: lustre-MDT0001-mdc-ffff9b2390b78800: Connection to lustre-MDT0001 (at 192.168.203.126@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 999.648637] LustreError: 2402:0:(client.c:3449:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9b2390da4700 x1876298549081472/t4294967449(4294967449) o101->lustre-MDT0001-mdc-ffff9b2390b78800@192.168.203.126@tcp:12/10 lens 608/608 e 0 to 0 dl 1789378657 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'lfs.0' uid:0 gid:0 projid:0 [ 1003.827861] Lustre: lustre-MDT0001-mdc-ffff9b2390b78800: Connection restored to 192.168.203.126@tcp (at 192.168.203.126@tcp) [ 1003.840414] Lustre: Skipped 1 previous similar message [ 1009.052190] LustreError: 37997:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [ 1009.074372] LustreError: 37997:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 104 previous similar messages [ 1009.680335] LustreError: 37998:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [ 1011.655866] LustreError: 38000:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [ 1011.667342] LustreError: 38000:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 1551 previous similar messages [ 1035.771035] Lustre: lustre-MDT0000-mdc-ffff9b2390b78800: Connection to lustre-MDT0000 (at 192.168.203.126@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1051.103228] Lustre: 2403:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789378677/real 1789378677] req@ffff9b2387b80a80 x1876298550825728/t0(0) o400->MGC192.168.203.126@tcp@192.168.203.126@tcp:26/25 lens 224/224 e 0 to 1 dl 1789378693 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1051.151120] LustreError: MGC192.168.203.126@tcp: Connection to MGS (at 192.168.203.126@tcp) was lost; in progress operations using this service will fail [ 1060.105287] Lustre: lustre-MDT0000-mdc-ffff9b2390b78800: Connection restored to 192.168.203.126@tcp (at 192.168.203.126@tcp) [ 1061.173360] Lustre: Evicted from MGS (at 192.168.203.126@tcp) after server handle changed from 0xc50e9934a48161aa to 0xc50e9934a481a44d [ 1066.488887] Lustre: lustre-MDT0001-mdc-ffff9b2390b78800: Connection to lustre-MDT0001 (at 192.168.203.126@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1078.696630] LustreError: 2402:0:(client.c:3449:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9b2390da4700 x1876298549081472/t4294967449(4294967449) o101->lustre-MDT0001-mdc-ffff9b2390b78800@192.168.203.126@tcp:12/10 lens 608/608 e 0 to 0 dl 1789378736 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'lfs.0' uid:0 gid:0 projid:0 [ 1078.734677] LustreError: 2402:0:(client.c:3449:ptlrpc_replay_interpret()) Skipped 1 previous similar message [ 1082.106499] Lustre: lustre-MDT0001-mdc-ffff9b2390b78800: Connection restored to 192.168.203.126@tcp (at 192.168.203.126@tcp) [ 1082.127326] Lustre: Skipped 1 previous similar message [ 1104.370532] LustreError: MGC192.168.203.126@tcp: Connection to MGS (at 192.168.203.126@tcp) was lost; in progress operations using this service will fail [ 1104.399677] Lustre: Evicted from MGS (at 192.168.203.126@tcp) after server handle changed from 0xc50e9934a481a44d to 0xc50e9934a481c96f [ 1109.482507] Lustre: lustre-MDT0001-mdc-ffff9b2390b78800: Connection to lustre-MDT0001 (at 192.168.203.126@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 1109.497983] Lustre: Skipped 1 previous similar message [ 1121.962829] LustreError: 2402:0:(client.c:3449:ptlrpc_replay_interpret()) @@@ status 301, old was 0 req@ffff9b2390da4700 x1876298549081472/t4294967449(4294967449) o101->lustre-MDT0001-mdc-ffff9b2390b78800@192.168.203.126@tcp:12/10 lens 608/608 e 0 to 0 dl 1789378779 ref 2 fl Interpret:RPQU/604/0 rc 301/301 job:'lfs.0' uid:0 gid:0 projid:0 [ 1121.977023] LustreError: 2402:0:(client.c:3449:ptlrpc_replay_interpret()) Skipped 1 previous similar message [ 1125.633329] Lustre: lustre-MDT0001-mdc-ffff9b2390b78800: Connection restored to 192.168.203.126@tcp (at 192.168.203.126@tcp) [ 1125.645620] Lustre: Skipped 2 previous similar messages [ 1133.828579] Lustre: DEBUG MARKER: == sanity test 17o: stat file with incompat LMA feature == 05:39:34 (1789378774) [ 1154.527394] Lustre: 2403:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789378780/real 1789378780] req@ffff9b23891bb100 x1876298550909440/t0(0) o400->MGC192.168.203.126@tcp@192.168.203.126@tcp:26/25 lens 224/224 e 0 to 1 dl 1789378796 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 1154.547324] LustreError: MGC192.168.203.126@tcp: Connection to MGS (at 192.168.203.126@tcp) was lost; in progress operations using this service will fail [ 1165.810441] Lustre: Evicted from MGS (at 192.168.203.126@tcp) after server handle changed from 0xc50e9934a481c96f to 0xc50e9934a481cfea [ 1180.306423] Lustre: DEBUG MARKER: oleg326-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [ 1181.597183] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [ 1191.810294] Lustre: DEBUG MARKER: == sanity test 17p: symlink overwrite directory error message ========================================================== 05:40:32 (1789378832) [ 1191.945617] LustreError: 41011:0:(namei.c:1721:ll_create_it()) VFS Op:name=f17p.sanity, dir=[0x200000007:0x1:0x0](ffff9b23919180c8), intent=open|creat [ 1191.966985] LustreError: 41011:0:(namei.c:1721:ll_create_it()) Skipped 200 previous similar messages [ 1191.985731] LustreError: 41011:0:(namei.c:1744:ll_create_it()) inode ffff9b238346b248 need_sync_to_mds [0x200000402:0x3a6:0x0] [ 1191.998511] LustreError: 41011:0:(namei.c:1744:ll_create_it()) Skipped 200 previous similar messages [ 1198.614843] Lustre: DEBUG MARKER: == sanity test 17q: set large xattr on fast symlink ====== 05:40:39 (1789378839) [ 1199.964468] sysctl (41653): drop_caches: 3 [ 1210.283231] Lustre: DEBUG MARKER: == sanity test 18: touch .../f ; ls ... ======================================================================================== 05:40:50 (1789378850) [ 1216.296170] Lustre: DEBUG MARKER: == sanity test 19a: touch .../f19 ; ls -l ... ; rm .../f19 ===================================================================== 05:40:56 (1789378856) [ 1224.291684] Lustre: DEBUG MARKER: == sanity test 19b: ls -l .../f19 (should return error) ======================================================================== 05:41:05 (1789378865) [ 1230.172933] Lustre: DEBUG MARKER: == sanity test 19c: runas -u 500 -g 500 touch .../f19 (should return error) ============================================================ 05:41:11 (1789378871) [ 1236.653994] Lustre: DEBUG MARKER: == sanity test 19d: cat .../f19 (should return error) ======================================================================== 05:41:17 (1789378877) [ 1242.890267] Lustre: DEBUG MARKER: == sanity test 20: touch .../f ; ls -l ... =============== 05:41:23 (1789378883) [ 1250.173178] Lustre: DEBUG MARKER: == sanity test 21: write to dangling link ================ 05:41:30 (1789378890) [ 1250.795628] LustreError: 45747:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [ 1250.801468] LustreError: 45747:0:(file.c:977:ll_kernel_to_mds_open_flags()) Skipped 9 previous similar messages [ 1257.751179] Lustre: DEBUG MARKER: == sanity test 22: unpack tar archive as non-root user === 05:41:38 (1789378898) [ 1258.594839] LustreError: 46338:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [ 1258.602030] LustreError: 46338:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 70 previous similar messages [ 1265.697562] Lustre: DEBUG MARKER: == sanity test 23a: O_CREAT|O_EXCL in subdir ============= 05:41:45 (1789378905) [ 1274.828720] Lustre: DEBUG MARKER: == sanity test 23b: O_APPEND check ======================= 05:41:54 (1789378914) [ 1285.016767] Lustre: DEBUG MARKER: == sanity test 23c: O_APPEND size checks for tiny writes ========================================================== 05:42:04 (1789378924) [ 1304.771297] Lustre: DEBUG MARKER: == sanity test 23d: file offset is correct after appending writes ========================================================== 05:42:24 (1789378944) [ 1313.004147] Lustre: DEBUG MARKER: == sanity test 23e: tiny write updates the size seen by cached statx ========================================================== 05:42:33 (1789378953) [ 1321.695432] Lustre: DEBUG MARKER: == sanity test 24a: rename file to non-existent target === 05:42:41 (1789378961) [ 1332.861506] Lustre: DEBUG MARKER: == sanity test 24b: rename file to existing target ======= 05:42:51 (1789378971) [ 1344.167965] Lustre: DEBUG MARKER: == sanity test 24c: rename directory to non-existent target ========================================================== 05:43:04 (1789378984) [ 1355.411993] Lustre: DEBUG MARKER: == sanity test 24d: rename directory to existing target == 05:43:15 (1789378995) [ 1364.411060] Lustre: DEBUG MARKER: == sanity test 24e: touch .../R5a/f; rename .../R5a/f .../R5b/g ================================================================ 05:43:24 (1789379004) [ 1373.386313] Lustre: DEBUG MARKER: == sanity test 24f: touch .../R6a/f R6b/g; mv .../R6a/f .../R6b/g ============================================================== 05:43:33 (1789379013) [ 1382.995433] Lustre: DEBUG MARKER: == sanity test 24g: mkdir .../R7a/d; .../R7b/d; mv .../R7a/d .../R7b/e ================================================================ 05:43:43 (1789379023) [ 1393.378519] Lustre: DEBUG MARKER: == sanity test 24h: mkdir .../R8a/d; .../R8a/e; .../R8b/d; .../R8b/e; rename .../R8a/d .../R8b/e ========================================================== 05:43:52 (1789379032) [ 1404.677958] Lustre: DEBUG MARKER: == sanity test 24i: rename file to dir error: touch f ; mkdir a ; rename f a ========================================================== 05:44:04 (1789379044) [ 1413.793147] Lustre: DEBUG MARKER: == sanity test 24j: source does not exist ====================================================================================== 05:44:14 (1789379054) [ 1421.800786] Lustre: DEBUG MARKER: == sanity test 24k: touch .../R11a/f; mv .../R11a/f .../R11a/d ================================================================= 05:44:22 (1789379062) [ 1429.378729] Lustre: DEBUG MARKER: == sanity test 24l: Renaming a file to itself ================================================================================== 05:44:30 (1789379070) [ 1437.024092] Lustre: DEBUG MARKER: == sanity test 24m: Renaming a file to a hard link to itself =================================================================== 05:44:36 (1789379076) [ 1444.771604] Lustre: DEBUG MARKER: == sanity test 24n: Statting the old file after renaming (Posix rename 2) ========================================================== 05:44:45 (1789379085) [ 1451.816485] Lustre: DEBUG MARKER: == sanity test 24o: rename of files during htree split === 05:44:52 (1789379092) [ 1491.211475] LustreError: 58163:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [ 1491.220308] LustreError: 58163:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 5532 previous similar messages [ 1491.260931] LustreError: 58163:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x240000402:0x416:0x0] suppgids 0 -1: rc 0 [ 1491.273619] LustreError: 58163:0:(namei.c:956:ll_intent_lock()) Skipped 3129 previous similar messages [ 1493.510703] LustreError: 58163:0:(dcache.c:176:ll_intent_release()) intent ffffae0bc1d8fdb8 released [ 1493.520676] LustreError: 58163:0:(dcache.c:176:ll_intent_release()) Skipped 2329 previous similar messages [ 1524.845379] LustreError: 58163:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [ 1524.862160] LustreError: 58163:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 1043 previous similar messages [ 2091.225780] LustreError: 58163:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [ 2091.235766] LustreError: 58163:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 45696 previous similar messages [ 2091.268116] LustreError: 58163:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x240000402:0x235e:0x0] suppgids 0 -1: rc 0 [ 2091.294972] LustreError: 58163:0:(namei.c:956:ll_intent_lock()) Skipped 22458 previous similar messages [ 2093.510926] LustreError: 58163:0:(dcache.c:176:ll_intent_release()) intent ffffae0bc1d8fdb8 released [ 2093.523892] LustreError: 58163:0:(dcache.c:176:ll_intent_release()) Skipped 22458 previous similar messages [ 2159.153877] LustreError: 58163:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [ 2159.169439] LustreError: 58163:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 8007 previous similar messages [ 2268.763970] Lustre: DEBUG MARKER: == sanity test 24p: mkdir .../R12a; .../R12b; rename .../R12a .../R12b ========================================================== 05:58:28 (1789379908) [ 2279.668475] Lustre: DEBUG MARKER: == sanity test 24q: mkdir .../R13a; .../R13b; open R13b rename R13a R13b ============================================================= 05:58:39 (1789379919) [ 2280.763617] LustreError: 59486:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [ 2280.770662] LustreError: 59486:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 154 previous similar messages [ 2294.611082] Lustre: DEBUG MARKER: == sanity test 24r: mkdir .../R14a/b; rename .../R14a .../R14a/b =============================================================== 05:58:53 (1789379933) [ 2295.365779] LustreError: 60092:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [ 2295.388453] LustreError: 60092:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 8 previous similar messages [ 2307.220228] Lustre: DEBUG MARKER: == sanity test 24s: mkdir .../R15a/b/c; rename .../R15a .../R15a/b/c =========================================================== 05:59:07 (1789379947) [ 2319.331136] Lustre: DEBUG MARKER: == sanity test 24t: mkdir .../R16a/b/c; rename .../R16a/b/c .../R16a =========================================================== 05:59:19 (1789379959) [ 2330.642934] Lustre: DEBUG MARKER: == sanity test 24u: create stripe file =================== 05:59:30 (1789379970) [ 2331.005552] LustreError: 61888:0:(namei.c:1721:ll_create_it()) VFS Op:name=f24u.sanity, dir=[0x200000007:0x1:0x0](ffff9b23919180c8), intent=open|creat [ 2331.029222] LustreError: 61888:0:(namei.c:1721:ll_create_it()) Skipped 26 previous similar messages [ 2331.046678] LustreError: 61888:0:(namei.c:1744:ll_create_it()) inode ffff9b239926c2c8 need_sync_to_mds [0x200000402:0x3e0:0x0] [ 2331.071474] LustreError: 61888:0:(namei.c:1744:ll_create_it()) Skipped 26 previous similar messages [ 2343.485743] Lustre: DEBUG MARKER: == sanity test 24v: list large directory (test hash collision, b=17560) ========================================================== 05:59:43 (1789379983) [ 2691.227522] LustreError: 62615:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [ 2691.237182] LustreError: 62615:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 91765 previous similar messages [ 2691.268234] LustreError: 62615:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 1 [ 2691.273541] LustreError: 62615:0:(namei.c:956:ll_intent_lock()) Skipped 46464 previous similar messages [ 2759.164722] LustreError: 62615:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [ 2759.177422] LustreError: 62615:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 49921 previous similar messages [ 3122.458923] LustreError: 62814:0:(dcache.c:176:ll_intent_release()) intent ffffae0bc1effb20 released [ 3122.476606] LustreError: 62814:0:(dcache.c:176:ll_intent_release()) Skipped 5913 previous similar messages [ 3122.516688] LustreError: 62814:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [ 3122.523200] LustreError: 62814:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 4 previous similar messages [ 3143.915376] LustreError: 62827:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [ 3143.937816] LustreError: 62827:0:(file.c:977:ll_kernel_to_mds_open_flags()) Skipped 6 previous similar messages [ 3291.247795] LustreError: 63387:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [ 3291.260109] LustreError: 63387:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 151218 previous similar messages [ 3291.289593] LustreError: 63387:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 1 [ 3291.312295] LustreError: 63387:0:(namei.c:956:ll_intent_lock()) Skipped 80898 previous similar messages [ 3722.460256] LustreError: 63387:0:(dcache.c:176:ll_intent_release()) intent ffffae0bc1c3fe00 released [ 3722.465324] LustreError: 63387:0:(dcache.c:176:ll_intent_release()) Skipped 48197 previous similar messages [ 3891.252427] LustreError: 63387:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [ 3891.272657] LustreError: 63387:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 156045 previous similar messages [ 3891.292444] LustreError: 63387:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 1 [ 3891.306954] LustreError: 63387:0:(namei.c:956:ll_intent_lock()) Skipped 104030 previous similar messages [ 4312.947482] LustreError: 63620:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [ 4312.958652] LustreError: 63620:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 3 previous similar messages [ 4319.749602] Lustre: DEBUG MARKER: == sanity test 24w: Reading a file larger than 4Gb ======= 06:32:39 (1789381959) [ 4319.919736] LustreError: 63902:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [ 4319.938594] LustreError: 63902:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 3 previous similar messages [ 4320.064046] LustreError: 63902:0:(namei.c:1721:ll_create_it()) VFS Op:name=f24w.sanity, dir=[0x200000007:0x1:0x0](ffff9b23919180c8), intent=open|creat [ 4320.090480] LustreError: 63902:0:(namei.c:1744:ll_create_it()) inode ffff9b23ba67ec08 need_sync_to_mds [0x200000402:0xc97a:0x0] [ 4320.325605] LustreError: 63914:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [ 4327.501316] Lustre: DEBUG MARKER: == sanity test 24x: cross MDT rename/link ================ 06:32:48 (1789381968) [ 4327.815356] LustreError: 64506:0:(dcache.c:176:ll_intent_release()) intent ffffae0bc1d57930 released [ 4327.819477] LustreError: 64506:0:(dcache.c:176:ll_intent_release()) Skipped 51805 previous similar messages [ 4327.836650] LustreError: 64506:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [ 4327.860235] LustreError: 64506:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 51091 previous similar messages [ 4328.432685] LustreError: 64517:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [ 4328.445526] LustreError: 64517:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 2 previous similar messages [ 4328.500521] LustreError: 64517:0:(namei.c:1721:ll_create_it()) VFS Op:name=src_file, dir=[0x200000402:0xc97d:0x0](ffff9b23ba681148), intent=open|creat [ 4328.520249] LustreError: 64517:0:(namei.c:1721:ll_create_it()) Skipped 1 previous similar message [ 4328.529390] LustreError: 64517:0:(namei.c:1744:ll_create_it()) inode ffff9b23ba68e3c8 need_sync_to_mds [0x200000402:0xc97f:0x0] [ 4328.539254] LustreError: 64517:0:(namei.c:1744:ll_create_it()) Skipped 1 previous similar message [ 4337.573365] Lustre: DEBUG MARKER: == sanity test 24y: rename/link on the same dir should succeed ========================================================== 06:32:57 (1789381977) [ 4345.369880] Lustre: DEBUG MARKER: == sanity test 24z: cross-MDT rename is done as cp ======= 06:33:05 (1789381985) [ 4345.622337] LustreError: 65734:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [ 4345.633257] LustreError: 65734:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 4 previous similar messages [ 4345.696284] LustreError: 65734:0:(namei.c:1721:ll_create_it()) VFS Op:name=f24z.sanity.0, dir=[0x200000402:0xc985:0x0](ffff9b23ba635b88), intent=open|creat [ 4345.714904] LustreError: 65734:0:(namei.c:1721:ll_create_it()) Skipped 4 previous similar messages [ 4345.724219] LustreError: 65734:0:(namei.c:1744:ll_create_it()) inode ffff9b23ba683248 need_sync_to_mds [0x200000402:0xc986:0x0] [ 4345.735752] LustreError: 65734:0:(namei.c:1744:ll_create_it()) Skipped 4 previous similar messages [ 4347.450434] LustreError: 65803:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [ 4355.411126] Lustre: DEBUG MARKER: == sanity test 24A: readdir() returns correct number of entries. ========================================================== 06:33:15 (1789381995) [ 4452.700644] Lustre: DEBUG MARKER: == sanity test 24B: readdir for striped dir return correct number of entries ========================================================== 06:34:53 (1789382093) [ 4452.928356] LustreError: 67550:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [ 4452.953326] LustreError: 67550:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 5010 previous similar messages [ 4453.331927] LustreError: 67559:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [ 4453.353230] LustreError: 67559:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 6 previous similar messages [ 4453.431837] LustreError: 67559:0:(namei.c:1721:ll_create_it()) VFS Op:name=a, dir=[0x200000402:0xd3b6:0x0](ffff9b23b3d8aa08), intent=open|creat [ 4453.457677] LustreError: 67559:0:(namei.c:1721:ll_create_it()) Skipped 2 previous similar messages [ 4453.466092] LustreError: 67559:0:(namei.c:1744:ll_create_it()) inode ffff9b23ba3900c8 need_sync_to_mds [0x200000402:0xd3b7:0x0] [ 4453.476559] LustreError: 67559:0:(namei.c:1744:ll_create_it()) Skipped 2 previous similar messages [ 4461.021326] Lustre: DEBUG MARKER: == sanity test 24C: check .. in striped dir ============== 06:35:01 (1789382101) [ 4468.557771] Lustre: DEBUG MARKER: == sanity test 24E: cross MDT rename/link ================ 06:35:08 (1789382108) [ 4469.987135] Lustre: DEBUG MARKER: SKIP: sanity test_24E needs >= 4 MDTs [ 4472.167883] Lustre: DEBUG MARKER: == sanity test 24F: hash order vs readdir (LU-11330) ===== 06:35:12 (1789382112) [ 4491.263711] LustreError: 69288:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [ 4491.286374] LustreError: 69288:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 149636 previous similar messages [ 4491.317554] LustreError: 69288:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x240002b11:0x53:0x0] suppgids 0 -1: rc 0 [ 4491.337749] LustreError: 69288:0:(namei.c:956:ll_intent_lock()) Skipped 96410 previous similar messages [ 4517.426179] LustreError: 69626:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [ 4517.431344] LustreError: 69626:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 129 previous similar messages [ 4517.497567] LustreError: 69626:0:(namei.c:1721:ll_create_it()) VFS Op:name=a, dir=[0x200000402:0xd47a:0x0](ffff9b23ba6763c8), intent=open|creat [ 4517.515947] LustreError: 69626:0:(namei.c:1721:ll_create_it()) Skipped 96 previous similar messages [ 4517.530615] LustreError: 69626:0:(namei.c:1744:ll_create_it()) inode ffff9b23ba674b08 need_sync_to_mds [0x200000402:0xd47b:0x0] [ 4517.545317] LustreError: 69626:0:(namei.c:1744:ll_create_it()) Skipped 96 previous similar messages [ 4526.414802] Lustre: DEBUG MARKER: == sanity test 24G: migrate symlink in rename ============ 06:36:06 (1789382166) [ 4533.335370] Lustre: DEBUG MARKER: == sanity test 24H: repeat FLD_QUERY rpc ================= 06:36:13 (1789382173) [ 4542.621962] Lustre: DEBUG MARKER: == sanity test 24I: large striped mkdir with limit check ========================================================== 06:36:23 (1789382183) [ 4543.431351] LustreError: 71417:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [ 4552.269621] Lustre: DEBUG MARKER: == sanity test 25a: create file in symlinked directory ========================================================================= 06:36:32 (1789382192) [ 4560.583877] Lustre: DEBUG MARKER: == sanity test 25b: lookup file in symlinked directory ========================================================================= 06:36:40 (1789382200) [ 4567.374368] Lustre: DEBUG MARKER: == sanity test 26a: multiple component symlink ================================================================================= 06:36:47 (1789382207) [ 4573.749653] Lustre: DEBUG MARKER: == sanity test 26b: multiple component symlink at end of lookup ================================================================ 06:36:54 (1789382214) [ 4580.237177] Lustre: DEBUG MARKER: == sanity test 26c: chain of symlinks ==================== 06:37:00 (1789382220) [ 4586.939789] Lustre: DEBUG MARKER: == sanity test 26d: create multiple component recursive symlink ========================================================== 06:37:07 (1789382227) [ 4593.955959] Lustre: DEBUG MARKER: == sanity test 26e: unlink multiple component recursive symlink ========================================================== 06:37:14 (1789382234) [ 4600.769688] Lustre: DEBUG MARKER: == sanity test 26f: rm -r of a directory which has recursive symlink ========================================================== 06:37:21 (1789382241) [ 4610.781269] Lustre: DEBUG MARKER: == sanity test 27a: one stripe file ====================== 06:37:31 (1789382251) [ 4610.947882] LustreError: 76706:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [ 4610.957712] LustreError: 76706:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 231 previous similar messages [ 4611.109132] LustreError: 76710:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [ 4617.528922] Lustre: DEBUG MARKER: == sanity test 27b: create and write to two stripe file == 06:37:38 (1789382258) [ 4625.181917] Lustre: DEBUG MARKER: == sanity test 27ca: one stripe on specified OST ========= 06:37:45 (1789382265) [ 4632.185507] Lustre: DEBUG MARKER: == sanity test 27cb: two stripes on specified OSTs ======= 06:37:52 (1789382272) [ 4638.759712] Lustre: DEBUG MARKER: == sanity test 27cc: two stripes on the same OST ========= 06:37:59 (1789382279) [ 4646.594276] Lustre: DEBUG MARKER: == sanity test 27cd: four stripes on two OSTs ============ 06:38:07 (1789382287) [ 4646.970046] LustreError: 79665:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [ 4646.975477] LustreError: 79665:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 56 previous similar messages [ 4647.026357] LustreError: 79665:0:(namei.c:1721:ll_create_it()) VFS Op:name=f27cd.sanity, dir=[0x240000402:0xf610:0x0](ffff9b2391bfe3c8), intent=open|creat [ 4647.040542] LustreError: 79665:0:(namei.c:1721:ll_create_it()) Skipped 15 previous similar messages [ 4647.051078] LustreError: 79665:0:(namei.c:1744:ll_create_it()) inode ffff9b2391bfd348 need_sync_to_mds [0x240000402:0xf611:0x0] [ 4647.062849] LustreError: 79665:0:(namei.c:1744:ll_create_it()) Skipped 15 previous similar messages [ 4655.234793] Lustre: DEBUG MARKER: == sanity test 27ce: more stripes than OSTs with -o ====== 06:38:15 (1789382295) [ 4663.288435] Lustre: DEBUG MARKER: == sanity test 27cf: 'setstripe -o' on inactive OSTs should return error ========================================================== 06:38:23 (1789382303) [ 4676.841329] Lustre: DEBUG MARKER: == sanity test 27cg: 1000 shouldn't cause too many credits ========================================================== 06:38:37 (1789382317) [ 4693.045674] Lustre: DEBUG MARKER: == sanity test 27d: create file with default settings ==== 06:38:53 (1789382333) [ 4693.862378] LustreError: 82190:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [ 4693.887765] LustreError: 82190:0:(file.c:977:ll_kernel_to_mds_open_flags()) Skipped 1 previous similar message [ 4702.028982] Lustre: DEBUG MARKER: == sanity test 27e: setstripe existing file (should return error) ========================================================== 06:39:02 (1789382342) [ 4709.665617] Lustre: DEBUG MARKER: == sanity test 27f: setstripe with bad stripe size (should return error) ========================================================== 06:39:10 (1789382350) [ 4717.199968] Lustre: DEBUG MARKER: == sanity test 27g: /home/green/git/lustre-release/lustre/utils/lfs getstripe with no objects ========================================================== 06:39:17 (1789382357) [ 4724.913884] Lustre: DEBUG MARKER: == sanity test 27ga: /home/green/git/lustre-release/lustre/utils/lfs getstripe with missing file (should return error) ========================================================== 06:39:25 (1789382365) [ 4733.046531] Lustre: DEBUG MARKER: == sanity test 27i: /home/green/git/lustre-release/lustre/utils/lfs getstripe with some objects ========================================================== 06:39:33 (1789382373) [ 4740.631318] Lustre: DEBUG MARKER: == sanity test 27j: setstripe with bad stripe offset (should return error) ========================================================== 06:39:40 (1789382380) [ 4747.890390] Lustre: DEBUG MARKER: == sanity test 27k: limit i_blksize for broken user apps ========================================================== 06:39:48 (1789382388) [ 4748.672480] LustreError: 86308:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [ 4755.580410] Lustre: DEBUG MARKER: == sanity test 27l: check setstripe permissions (should return error) ========================================================== 06:39:55 (1789382395) [ 4762.814170] Lustre: DEBUG MARKER: SKIP: sanity test_27m skipping SLOW test 27m [ 4764.844967] Lustre: DEBUG MARKER: == sanity test 27n: create file with some full OSTs ====== 06:40:05 (1789382405) [ 4806.549377] Lustre: DEBUG MARKER: == sanity test 27o: create file with all full OSTs (should error) ========================================================== 06:40:47 (1789382447) [ 4819.733512] LustreError: 89136:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [ 4851.465270] Lustre: DEBUG MARKER: == sanity test 27oo: don't let few threads to reserve too many objects ========================================================== 06:41:32 (1789382492) [ 4878.832536] Lustre: lustre-OST0000-osc-ffff9b2390b78800: Connection to lustre-OST0000 (at 192.168.203.126@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 4878.839861] Lustre: Skipped 1 previous similar message [ 4901.542635] Lustre: lustre-OST0000-osc-ffff9b2390b78800: Connection restored to 192.168.203.126@tcp (at 192.168.203.126@tcp) [ 4901.552201] Lustre: Skipped 2 previous similar messages [ 4914.008349] Lustre: DEBUG MARKER: == sanity test 27p: append to a truncated file with some full OSTs ========================================================== 06:42:34 (1789382554) [ 4929.988781] LustreError: 91765:0:(dcache.c:176:ll_intent_release()) intent ffffae0bc20df8d0 released [ 4930.000256] LustreError: 91765:0:(dcache.c:176:ll_intent_release()) Skipped 16021 previous similar messages [ 4930.143449] LustreError: 91774:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [ 4930.152415] LustreError: 91774:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 31 previous similar messages [ 4930.471474] LustreError: 91779:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [ 4930.487195] LustreError: 91779:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 485 previous similar messages [ 4932.603849] LustreError: 91816:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [ 4932.609912] LustreError: 91816:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 114 previous similar messages [ 4934.550493] LustreError: 91841:0:(namei.c:1721:ll_create_it()) VFS Op:name=f211, dir=[0x240000402:0xf62c:0x0](ffff9b2391ab63c8), intent=open|creat [ 4934.560662] LustreError: 91841:0:(namei.c:1721:ll_create_it()) Skipped 74 previous similar messages [ 4934.574268] LustreError: 91841:0:(namei.c:1744:ll_create_it()) inode ffff9b23ba681988 need_sync_to_mds [0x240000402:0xf62d:0x0] [ 4934.587595] LustreError: 91841:0:(namei.c:1744:ll_create_it()) Skipped 71 previous similar messages [ 4948.299704] LustreError: 91140:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [ 4948.314019] LustreError: 91140:0:(file.c:977:ll_kernel_to_mds_open_flags()) Skipped 1 previous similar message [ 4963.427401] Lustre: DEBUG MARKER: == sanity test 27q: append to truncated file with all OSTs full (should error) ========================================================== 06:43:23 (1789382603) [ 5010.291221] Lustre: DEBUG MARKER: == sanity test 27r: stripe file with some full OSTs (shouldn't LBUG) =========================================================== 06:44:10 (1789382650) [ 5047.761570] Lustre: DEBUG MARKER: == sanity test 27s: lsm_xfersize overflow (should error) (bug 10725) ========================================================== 06:44:48 (1789382688) [ 5054.748445] Lustre: DEBUG MARKER: == sanity test 27t: check that utils parse path correctly ========================================================== 06:44:55 (1789382695) [ 5062.073596] Lustre: DEBUG MARKER: == sanity test 27u: skip object creation on OSC w/o objects ========================================================== 06:45:02 (1789382702) [ 5093.899710] LustreError: 96110:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [ 5093.917594] LustreError: 96110:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 8631 previous similar messages [ 5093.928212] LustreError: 96110:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 1 [ 5093.937359] LustreError: 96110:0:(namei.c:956:ll_intent_lock()) Skipped 5197 previous similar messages [ 5119.636877] Lustre: DEBUG MARKER: == sanity test 27v: skip object creation on slow OST ===== 06:46:00 (1789382760) [ 5177.400535] Lustre: DEBUG MARKER: == sanity test 27w: check /home/green/git/lustre-release/lustre/utils/lfs setstripe -S and getstrip -d options ========================================================== 06:46:57 (1789382817) [ 5185.862844] Lustre: DEBUG MARKER: == sanity test 27wa: check /home/green/git/lustre-release/lustre/utils/lfs setstripe -c -i options ========================================================== 06:47:06 (1789382826) [ 5194.308510] Lustre: DEBUG MARKER: == sanity test 27x: create files while OST0 is degraded == 06:47:14 (1789382834) [ 5221.035540] Lustre: DEBUG MARKER: == sanity test 27y: create files while OST0 is degraded and the rest inactive ========================================================== 06:47:40 (1789382860) [ 5270.875441] Lustre: DEBUG MARKER: == sanity test 27z: check SEQ/OID on the MDT and OST filesystems ========================================================== 06:48:31 (1789382911) [ 5279.382965] Lustre: DEBUG MARKER: check file /mnt/lustre/d27z.sanity/f27z.sanity-1 [ 5281.285906] Lustre: DEBUG MARKER: FID seq 0x240000402, oid 0xf85a ver 0x0 [ 5282.751250] Lustre: DEBUG MARKER: LOV seq 0x240000402, oid 0xf85a, count: 1 [ 5284.688809] Lustre: DEBUG MARKER: want: stripe:0 ost:0 oid:260/0x104 seq:0x280000400 [ 5287.912381] Lustre: DEBUG MARKER: check file /mnt/lustre/d27z.sanity/f27z.sanity-2 [ 5289.684788] Lustre: DEBUG MARKER: FID seq 0x200000402, oid 0xd798 ver 0x0 [ 5291.093781] Lustre: DEBUG MARKER: LOV seq 0x200000402, oid 0xd798, count: 2 [ 5292.774074] Lustre: DEBUG MARKER: want: stripe:0 ost:1 oid:1444/0x5a4 seq:0x2c0000401 [ 5295.452159] Lustre: DEBUG MARKER: want: stripe:1 ost:0 oid:856/0x358 seq:0x280000401 [ 5302.934376] Lustre: DEBUG MARKER: == sanity test 27A: check filesystem-wide default LOV EA values ========================================================== 06:49:03 (1789382943) [ 5310.583980] Lustre: DEBUG MARKER: == sanity test 27B: call setstripe on open unlinked file/rename victim ========================================================== 06:49:10 (1789382950) [ 5318.162146] Lustre: DEBUG MARKER: == sanity test 27Ca: check full striping across all OSTs ========================================================== 06:49:18 (1789382958) [ 5325.847912] Lustre: DEBUG MARKER: == sanity test 27Cb: more stripes than OSTs with -C ====== 06:49:26 (1789382966) [ 5332.811710] Lustre: DEBUG MARKER: == sanity test 27Cc: fewer stripes than OSTs does not set overstriping ========================================================== 06:49:33 (1789382973) [ 5341.098611] Lustre: DEBUG MARKER: == sanity test 27Cd: test maximum stripe count =========== 06:49:41 (1789382981) [ 5382.548988] Lustre: DEBUG MARKER: == sanity test 27Ce: test pool with overstriping ========= 06:50:22 (1789383022) [ 5410.590491] Lustre: DEBUG MARKER: == sanity test 27Cf: test default inheritance with overstriping ========================================================== 06:50:51 (1789383051) [ 5411.260119] LustreError: 108470:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [ 5411.265340] LustreError: 108470:0:(file.c:977:ll_kernel_to_mds_open_flags()) Skipped 6 previous similar messages [ 5418.449381] Lustre: DEBUG MARKER: == sanity test 27Cg: test setstripe with wrong OST idx === 06:50:58 (1789383058) [ 5424.980663] Lustre: DEBUG MARKER: == sanity test 27Ci: add an overstriping component ======= 06:51:05 (1789383065) [ 5434.094267] Lustre: DEBUG MARKER: == sanity test 27Cj: overstriping with -C for max values in multiple of targets ========================================================== 06:51:14 (1789383074) [ 5442.255938] Lustre: DEBUG MARKER: == sanity test 27D: validate llapi_layout API ============ 06:51:22 (1789383082) [ 5452.321837] LustreError: 110939:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [ 5452.331240] LustreError: 110939:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 1447 previous similar messages [ 5452.390645] LustreError: 110939:0:(namei.c:1721:ll_create_it()) VFS Op:name=t0, dir=[0x240000402:0xf8a5:0x0](ffff9b2391c74b08), intent=open|creat [ 5452.419688] LustreError: 110939:0:(namei.c:1721:ll_create_it()) Skipped 1333 previous similar messages [ 5452.454784] LustreError: 110939:0:(namei.c:1744:ll_create_it()) inode ffff9b2391cc3248 need_sync_to_mds [0x200000402:0xd7ee:0x0] [ 5452.465052] LustreError: 110939:0:(namei.c:1744:ll_create_it()) Skipped 1331 previous similar messages [ 5474.265740] Lustre: DEBUG MARKER: == sanity test 27E: check that default extended attribute size properly increases ========================================================== 06:51:54 (1789383114) [ 5482.475832] Lustre: DEBUG MARKER: == sanity test 27F: Client resend delayed layout creation with non-zero size ========================================================== 06:52:02 (1789383122) [ 5488.119295] Lustre: lustre-OST0000-osc-ffff9b2390b78800: Connection to lustre-OST0000 (at 192.168.203.126@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 5508.802856] Lustre: lustre-OST0000-osc-ffff9b2390b78800: Connection restored to 192.168.203.126@tcp (at 192.168.203.126@tcp) [ 5509.475260] Lustre: 2403:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789383135/real 1789383135] req@ffff9b23883d9880 x1876298632608768/t0(0) o400->lustre-OST0001-osc-ffff9b2390b78800@192.168.203.126@tcp:28/4 lens 224/224 e 0 to 1 dl 1789383151 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5514.719807] Lustre: 2404:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789383140/real 1789383140] req@ffff9b23883da300 x1876298632609280/t0(0) o400->lustre-OST0001-osc-ffff9b2390b78800@192.168.203.126@tcp:28/4 lens 224/224 e 0 to 1 dl 1789383156 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [ 5530.970616] Lustre: DEBUG MARKER: == sanity test 27G: Clear OST pool from stripe =========== 06:52:51 (1789383171) [ 5531.481499] LustreError: 113416:0:(dcache.c:176:ll_intent_release()) intent ffffae0bc1d8f930 released [ 5531.490325] LustreError: 113416:0:(dcache.c:176:ll_intent_release()) Skipped 1798 previous similar messages [ 5531.502232] LustreError: 113416:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [ 5531.511981] LustreError: 113416:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 41 previous similar messages [ 5540.167094] LustreError: 113492:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [ 5540.185096] LustreError: 113492:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 59 previous similar messages [ 5558.401462] Lustre: DEBUG MARKER: == sanity test 27H: Set specific OSTs stripe ============= 06:53:18 (1789383198) [ 5560.709633] Lustre: DEBUG MARKER: SKIP: sanity test_27H needs >= 3 OSTs [ 5562.949046] Lustre: DEBUG MARKER: == sanity test 27I: check that root dir striping does not break parent dir one ========================================================== 06:53:23 (1789383203) [ 5589.013469] Lustre: DEBUG MARKER: == sanity test 27Ia: check that root dir pool is dropped with conflict parent dir settings ========================================================== 06:53:49 (1789383229) [ 5617.511527] Lustre: DEBUG MARKER: == sanity test 27J: basic ops on file with foreign LOV === 06:54:18 (1789383258) [ 5626.492807] Lustre: DEBUG MARKER: == sanity test 27K: basic ops on dir with foreign LMV ==== 06:54:26 (1789383266) [ 5635.609751] Lustre: DEBUG MARKER: == sanity test 27Ke: test enable_foreign_dir and enable_foreign_dir_gid ========================================================== 06:54:35 (1789383275) [ 5664.466828] Lustre: DEBUG MARKER: == sanity test 27L: lfs pool_list gives correct pool name ========================================================== 06:55:04 (1789383304) [ 5683.872985] Lustre: DEBUG MARKER: == sanity test 27M: test O_APPEND striping =============== 06:55:24 (1789383324) [ 5693.913925] LustreError: 119590:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [ 5693.924731] LustreError: 119590:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 4821 previous similar messages [ 5693.948252] LustreError: 119590:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 1 [ 5693.962409] LustreError: 119590:0:(namei.c:956:ll_intent_lock()) Skipped 2970 previous similar messages [ 5744.540161] Lustre: DEBUG MARKER: == sanity test 27N: lctl pool_list on separate MGS gives correct pool name ========================================================== 06:56:25 (1789383385) [ 5746.518723] Lustre: DEBUG MARKER: SKIP: sanity test_27N needs separate MGS/MDT [ 5748.511721] Lustre: DEBUG MARKER: == sanity test 27O: basic ops on foreign file of symlink type ========================================================== 06:56:28 (1789383388) [ 5757.884321] Lustre: DEBUG MARKER: == sanity test 27P: basic ops on foreign dir of foreign_symlink type ========================================================== 06:56:38 (1789383398) [ 5768.108497] Lustre: DEBUG MARKER: == sanity test 27Q: llapi_file_get_stripe() works on symlinks ========================================================== 06:56:48 (1789383408) [ 5776.275066] Lustre: DEBUG MARKER: == sanity test 27R: test max_stripecount limitation when stripe count is set to -1 ========================================================== 06:56:56 (1789383416) [ 5787.390777] Lustre: DEBUG MARKER: == sanity test 27T: no eio on close on partial write due to enosp ========================================================== 06:57:07 (1789383427) [ 5796.844697] Lustre: *** cfs_fail_loc=411, val=1*** [ 5804.886542] Lustre: DEBUG MARKER: == sanity test 27U: append pool and stripe count work with composite default layout ========================================================== 06:57:24 (1789383444) [ 5868.368597] Lustre: DEBUG MARKER: == sanity test 27V: creating widely striped file races with deactivating OST ========================================================== 06:58:28 (1789383508) [ 5869.567745] Lustre: DEBUG MARKER: SKIP: sanity test_27V needs >= 4 OSTs [ 5871.515406] Lustre: DEBUG MARKER: == sanity test 27W: test enable_setstripe_gid ============ 06:58:32 (1789383512) [ 5878.696638] Lustre: DEBUG MARKER: == sanity test 27X: lfs migrate honors --overstripe-count option ========================================================== 06:58:39 (1789383519) [ 5879.072142] LustreError: 126149:0:(llite_lib.c:4170:ll_prep_md_op_data()) debug: Setting bias to MDS_CREATE_VOLATILE: . :VOLATILE:0000:4085B9B8:fd=03 [ 5879.098363] LustreError: 126149:0:(lmv_obd.c:1943:lmv_locate_tgt()) debug: handling volatile file... [ 5879.105365] LustreError: 126149:0:(mdc_lib.c:326:mdc_open_pack()) debug: create_volatile changes to mds_open_volatile [ 5888.071947] Lustre: DEBUG MARKER: == sanity test 28: create/mknod/mkdir with bad file types ====================================================================== 06:58:47 (1789383527) [ 5898.103247] Lustre: DEBUG MARKER: == sanity test 29: IT_GETATTR regression ====================================================================================== 06:58:58 (1789383538) [ 5902.189972] Lustre: DEBUG MARKER: first d29 [ 5904.308457] Lustre: DEBUG MARKER: second d29 [ 5906.481479] Lustre: DEBUG MARKER: done [ 5916.340966] Lustre: DEBUG MARKER: == sanity test 30a: execute binary from Lustre (execve) ======================================================================== 06:59:15 (1789383555) [ 5928.377729] Lustre: DEBUG MARKER: == sanity test 30b: execute binary from Lustre as non-root ===================================================================== 06:59:27 (1789383567) [ 5937.059519] Lustre: DEBUG MARKER: == sanity test 30c: execute binary from Lustre without read perms ============================================================== 06:59:36 (1789383576) [ 5947.707224] Lustre: DEBUG MARKER: == sanity test 30d: execute binary from Lustre while clear locks ========================================================== 06:59:47 (1789383587) [ 5948.568850] LustreError: 130120:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [ 5948.579343] LustreError: 130120:0:(file.c:977:ll_kernel_to_mds_open_flags()) Skipped 31 previous similar messages [ 6052.882846] LustreError: 130166:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [ 6052.892307] LustreError: 130166:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 307 previous similar messages [ 6053.002345] LustreError: 130166:0:(namei.c:1721:ll_create_it()) VFS Op:name=f30d.sanity, dir=[0x200000007:0x1:0x0](ffff9b23919180c8), intent=open|creat [ 6053.014182] LustreError: 130166:0:(namei.c:1721:ll_create_it()) Skipped 216 previous similar messages [ 6053.021373] LustreError: 130166:0:(namei.c:1744:ll_create_it()) inode ffff9b2391d25348 need_sync_to_mds [0x200000402:0xd888:0x0] [ 6053.029115] LustreError: 130166:0:(namei.c:1744:ll_create_it()) Skipped 216 previous similar messages [ 6137.337062] LustreError: 130193:0:(dcache.c:176:ll_intent_release()) intent ffffae0bc1cc7b20 released [ 6137.342282] LustreError: 130193:0:(dcache.c:176:ll_intent_release()) Skipped 744 previous similar messages [ 6163.944537] Lustre: lustre-OST0001-osc-ffff9b2390b78800: disconnect after 21s idle [ 6165.598177] Lustre: DEBUG MARKER: == sanity test 31a: open-unlink file ============================================================================================ 07:03:26 (1789383806) [ 6171.981120] Lustre: DEBUG MARKER: == sanity test 31b: unlink file with multiple links while open ================================================================= 07:03:32 (1789383812) [ 6179.953506] Lustre: DEBUG MARKER: == sanity test 31c: open-unlink file with multiple links ======================================================================= 07:03:40 (1789383820) [ 6187.495765] Lustre: DEBUG MARKER: == sanity test 31d: remove of open directory =================================================================================== 07:03:47 (1789383827) [ 6187.727590] LustreError: 132523:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [ 6187.742850] LustreError: 132523:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 54 previous similar messages [ 6187.925804] LustreError: 132523:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [ 6187.946278] LustreError: 132523:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 75 previous similar messages [ 6194.658089] Lustre: lustre-OST0001-osc-ffff9b2390b78800: disconnect after 24s idle [ 6195.214602] Lustre: DEBUG MARKER: == sanity test 31e: remove of open non-empty directory ========================================================================= 07:03:55 (1789383835) [ 6202.056242] Lustre: DEBUG MARKER: == sanity test 31f: remove of open directory with open-unlink file ============================================================= 07:04:02 (1789383842) [ 6217.034968] Lustre: DEBUG MARKER: == sanity test 31g: cross directory link================== 07:04:17 (1789383857) [ 6224.590527] Lustre: DEBUG MARKER: == sanity test 31h: cross directory link under child========================================================================= 07:04:25 (1789383865) [ 6231.599294] Lustre: DEBUG MARKER: == sanity test 31i: cross directory link under parent========================================================================= 07:04:32 (1789383872) [ 6237.602481] Lustre: DEBUG MARKER: == sanity test 31j: link for directory =================== 07:04:38 (1789383878) [ 6243.434698] Lustre: DEBUG MARKER: == sanity test 31k: link to file: the same, non-existing, dir ========================================================== 07:04:44 (1789383884) [ 6249.743728] Lustre: DEBUG MARKER: == sanity test 31l: link to file: target dir has trailing slash ========================================================== 07:04:50 (1789383890) [ 6256.501980] Lustre: DEBUG MARKER: == sanity test 31m: link to file: the same, non-existing, dir ========================================================== 07:04:56 (1789383896) [ 6263.566162] Lustre: DEBUG MARKER: == sanity test 31n: check link count of unlinked file ==== 07:05:04 (1789383904) [ 6271.066452] Lustre: DEBUG MARKER: == sanity test 31o: duplicate hard links with same filename ========================================================== 07:05:11 (1789383911) [ 6293.923127] LustreError: 140080:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [ 6293.934332] LustreError: 140080:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 5403 previous similar messages [ 6293.953088] LustreError: 140080:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x240002b10:0x41:0x0] suppgids 0 -1: rc 0 [ 6293.966088] LustreError: 140080:0:(namei.c:956:ll_intent_lock()) Skipped 3717 previous similar messages [ 6356.330980] Lustre: DEBUG MARKER: == sanity test 31p: remove of open striped directory ===== 07:06:37 (1789383997) [ 6363.612030] Lustre: DEBUG MARKER: == sanity test 31q: create striped directory on specific MDTs ========================================================== 07:06:44 (1789384004) [ 6365.022405] Lustre: DEBUG MARKER: SKIP: sanity test_31q needs >= 3 MDTs [ 6366.876036] Lustre: DEBUG MARKER: == sanity test 31r: open-rename(replace) race ============ 07:06:47 (1789384007) [ 6374.748206] Lustre: DEBUG MARKER: == sanity test 32a: stat d32a/ext2-mountpoint/.. =============================================================================== 07:06:55 (1789384015) [ 6375.187849] loop: module loaded [ 6375.209163] loop0: detected capacity change from 0 to 8192000 [ 6375.232400] EXT4-fs (loop0): mounting ext2 file system using the ext4 subsystem [ 6375.315134] EXT4-fs (loop0): mounted filesystem with ordered data mode. Opts: (null) [ 6382.240316] Lustre: DEBUG MARKER: == sanity test 32b: open d32b/ext2-mountpoint/.. =============================================================================== 07:07:02 (1789384022) [ 6382.863092] loop0: detected capacity change from 0 to 8192000 [ 6382.874103] EXT4-fs (loop0): mounting ext2 file system using the ext4 subsystem [ 6382.891514] EXT4-fs (loop0): mounted filesystem with ordered data mode. Opts: (null) [ 6390.125305] Lustre: DEBUG MARKER: == sanity test 32c: stat d32c/ext2-mountpoint/../d2/test_dir =================================================================== 07:07:10 (1789384030) [ 6390.526685] loop0: detected capacity change from 0 to 8192000 [ 6390.547928] EXT4-fs (loop0): mounting ext2 file system using the ext4 subsystem [ 6390.556505] EXT4-fs (loop0): mounted filesystem with ordered data mode. Opts: (null) [ 6398.546251] Lustre: DEBUG MARKER: == sanity test 32d: open d32d/ext2-mountpoint/../d2/test_dir ========================================================== 07:07:18 (1789384038) [ 6399.175884] loop0: detected capacity change from 0 to 8192000 [ 6399.208475] EXT4-fs (loop0): mounting ext2 file system using the ext4 subsystem [ 6399.236606] EXT4-fs (loop0): mounted filesystem with ordered data mode. Opts: (null) [ 6408.566949] Lustre: DEBUG MARKER: == sanity test 32e: stat d32e/symlink->tmp/symlink->lustre-subdir ========================================================== 07:07:28 (1789384048) [ 6416.442681] Lustre: DEBUG MARKER: == sanity test 32f: open d32f/symlink->tmp/symlink->lustre-subdir ========================================================== 07:07:36 (1789384056) [ 6424.904745] Lustre: DEBUG MARKER: == sanity test 32g: stat d32g/symlink->tmp/symlink->lustre-subdir/2 ========================================================== 07:07:45 (1789384065) [ 6433.656838] Lustre: DEBUG MARKER: == sanity test 32h: open d32h/symlink->tmp/symlink->lustre-subdir/2 ========================================================== 07:07:53 (1789384073) [ 6441.446821] Lustre: DEBUG MARKER: == sanity test 32i: stat d32i/ext2-mountpoint/../test_file ===================================================================== 07:08:02 (1789384082) [ 6441.913088] loop0: detected capacity change from 0 to 8192000 [ 6441.938134] EXT4-fs (loop0): mounting ext2 file system using the ext4 subsystem [ 6441.952927] EXT4-fs (loop0): mounted filesystem with ordered data mode. Opts: (null) [ 6449.025644] Lustre: DEBUG MARKER: == sanity test 32j: open d32j/ext2-mountpoint/../test_file ===================================================================== 07:08:09 (1789384089) [ 6449.802952] loop0: detected capacity change from 0 to 8192000 [ 6449.822783] EXT4-fs (loop0): mounting ext2 file system using the ext4 subsystem [ 6449.840476] EXT4-fs (loop0): mounted filesystem with ordered data mode. Opts: (null) [ 6457.057468] Lustre: DEBUG MARKER: == sanity test 32k: stat d32k/ext2-mountpoint/../d2/test_file ================================================================== 07:08:17 (1789384097) [ 6457.483933] loop0: detected capacity change from 0 to 8192000 [ 6457.514743] EXT4-fs (loop0): mounting ext2 file system using the ext4 subsystem [ 6457.561532] EXT4-fs (loop0): mounted filesystem with ordered data mode. Opts: (null) [ 6464.784988] Lustre: DEBUG MARKER: == sanity test 32l: open d32l/ext2-mountpoint/../d2/test_file ================================================================== 07:08:25 (1789384105) [ 6465.509226] loop0: detected capacity change from 0 to 8192000 [ 6465.538173] EXT4-fs (loop0): mounting ext2 file system using the ext4 subsystem [ 6465.554975] EXT4-fs (loop0): mounted filesystem with ordered data mode. Opts: (null) [ 6473.635641] Lustre: DEBUG MARKER: == sanity test 32m: stat d32m/symlink->tmp/symlink->lustre-root ================================================================ 07:08:34 (1789384114) [ 6481.077497] Lustre: DEBUG MARKER: == sanity test 32n: open d32n/symlink->tmp/symlink->lustre-root ================================================================ 07:08:41 (1789384121) [ 6490.487913] Lustre: DEBUG MARKER: == sanity test 32o: stat d32o/symlink->tmp/symlink->lustre-root/ ========================================================== 07:08:50 (1789384130) [ 6498.758992] Lustre: DEBUG MARKER: == sanity test 32p: open d32p/symlink->tmp/symlink->lustre-root/ ========================================================== 07:08:58 (1789384138) [ 6500.325988] Lustre: DEBUG MARKER: 32p_1 [ 6502.221238] Lustre: DEBUG MARKER: 32p_2 [ 6503.725657] Lustre: DEBUG MARKER: 32p_3 [ 6505.064812] Lustre: DEBUG MARKER: 32p_4 [ 6506.998825] Lustre: DEBUG MARKER: 32p_5 [ 6508.552791] Lustre: DEBUG MARKER: 32p_6 [ 6510.577772] Lustre: DEBUG MARKER: 32p_7 [ 6512.496518] Lustre: DEBUG MARKER: 32p_8 [ 6513.943236] Lustre: DEBUG MARKER: 32p_9 [ 6515.796331] Lustre: DEBUG MARKER: 32p_10 [ 6523.120548] Lustre: DEBUG MARKER: == sanity test 32q: stat follows mountpoints in Lustre (should return error) ========================================================== 07:09:23 (1789384163) [ 6523.905323] loop0: detected capacity change from 0 to 8192000 [ 6523.930862] EXT4-fs (loop0): mounting ext2 file system using the ext4 subsystem [ 6523.967648] EXT4-fs (loop0): mounted filesystem with ordered data mode. Opts: (null) [ 6530.988411] Lustre: DEBUG MARKER: == sanity test 32r: opendir follows mountpoints in Lustre (should return error) ========================================================== 07:09:31 (1789384171) [ 6531.691198] loop0: detected capacity change from 0 to 8192000 [ 6531.727560] EXT4-fs (loop0): mounting ext2 file system using the ext4 subsystem [ 6531.752526] EXT4-fs (loop0): mounted filesystem with ordered data mode. Opts: (null) [ 6537.687867] Lustre: DEBUG MARKER: == sanity test 33aa: write file with mode 444 (should return error) ========================================================== 07:09:38 (1789384178) [ 6539.548674] Lustre: DEBUG MARKER: 33_1 [ 6541.444435] Lustre: DEBUG MARKER: 33_2 [ 6548.009461] Lustre: DEBUG MARKER: == sanity test 33a: test open file(mode=0444) with O_RDWR (should return error) ========================================================== 07:09:47 (1789384187) [ 6557.296192] Lustre: DEBUG MARKER: == sanity test 33b: test open file with malformed flags (No panic) ========================================================== 07:09:57 (1789384197) [ 6564.301460] Lustre: DEBUG MARKER: == sanity test 33c: test write_bytes stats =============== 07:10:04 (1789384204) [ 6573.096190] Lustre: DEBUG MARKER: == sanity test 33d: openfile with 444 modes and malformed flags under remote dir ========================================================== 07:10:13 (1789384213) [ 6580.228882] Lustre: DEBUG MARKER: == sanity test 33e: mkdir and striped directory should have same mode ========================================================== 07:10:20 (1789384220) [ 6590.350208] Lustre: DEBUG MARKER: == sanity test 33f: nonroot user can create, access, and remove a striped directory ========================================================== 07:10:30 (1789384230) [ 6601.902464] Lustre: DEBUG MARKER: == sanity test 33g: nonroot user create already existing root created file ========================================================== 07:10:42 (1789384242) [ 6609.443778] Lustre: DEBUG MARKER: == sanity test 33h: temp file is located on the same MDT as target (crush) ========================================================== 07:10:49 (1789384249) [ 6610.709725] LustreError: 162112:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [ 6610.716613] LustreError: 162112:0:(file.c:977:ll_kernel_to_mds_open_flags()) Skipped 3 previous similar messages [ 6652.975643] LustreError: 163230:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [ 6652.990313] LustreError: 163230:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 1561 previous similar messages [ 6653.151417] LustreError: 163231:0:(namei.c:1721:ll_create_it()) VFS Op:name=.f33h.sanity.111168, dir=[0x240000402:0xfafa:0x0](ffff9b23990380c8), intent=open|creat [ 6653.163984] LustreError: 163231:0:(namei.c:1721:ll_create_it()) Skipped 1411 previous similar messages [ 6653.174891] LustreError: 163231:0:(namei.c:1744:ll_create_it()) inode ffff9b2383443248 need_sync_to_mds [0x200000402:0xdca4:0x0] [ 6653.183402] LustreError: 163231:0:(namei.c:1744:ll_create_it()) Skipped 1411 previous similar messages [ 6737.384154] LustreError: 165001:0:(dcache.c:176:ll_intent_release()) intent ffff9b239fd9e9c0 released [ 6737.399917] LustreError: 165001:0:(dcache.c:176:ll_intent_release()) Skipped 4733 previous similar messages [ 6750.074757] Lustre: DEBUG MARKER: == sanity test 33hh: temp file is located on the same MDT as target (crush2) ========================================================== 07:13:10 (1789384390) [ 6787.956918] LustreError: 166599:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [ 6787.971851] LustreError: 166599:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 2234 previous similar messages [ 6875.615771] Lustre: lustre-OST0001-osc-ffff9b2390b78800: disconnect after 24s idle [ 6895.019862] Lustre: DEBUG MARKER: == sanity test 33i: striped directory can be accessed when one MDT is down ========================================================== 07:15:35 (1789384535) [ 6895.241291] LustreError: 169338:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [ 6895.258441] LustreError: 169338:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 33186 previous similar messages [ 6895.269518] LustreError: 169338:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 1 [ 6895.283283] LustreError: 169338:0:(namei.c:956:ll_intent_lock()) Skipped 25680 previous similar messages [ 6895.312215] LustreError: 169338:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [ 6895.331652] LustreError: 169338:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 101 previous similar messages [ 6934.891766] Lustre: setting import lustre-MDT0001_UUID INACTIVE by administrator request [ 6934.911796] LustreError: 169542:0:(file.c:251:ll_close_inode_openhandle()) lustre-clilmv-ffff9b2390b78800: inode [0x240000402:0xfc1e:0x0] mdc close failed: rc = -108 [ 6935.412591] LustreError: 169542:0:(file.c:251:ll_close_inode_openhandle()) lustre-clilmv-ffff9b2390b78800: inode [0x240000402:0xfc14:0x0] mdc close failed: rc = -108 [ 6935.420657] LustreError: 169542:0:(file.c:251:ll_close_inode_openhandle()) Skipped 174 previous similar messages [ 6935.709947] LustreError: 169545:0:(mdc_request.c:1507:mdc_read_page()) lustre-MDT0001-mdc-ffff9b2390b78800: [0x240002b11:0xb7:0x0] lock enqueue fails: rc = -108 [ 6935.722853] Lustre: dir [0x200000402:0xe439:0x0] stripe 1 readdir failed: -108, directory is partially accessed! [ 6936.216110] LustreError: 169549:0:(mdc_request.c:1507:mdc_read_page()) lustre-MDT0001-mdc-ffff9b2390b78800: [0x240002b11:0xb7:0x0] lock enqueue fails: rc = -108 [ 6936.230060] LustreError: 169549:0:(mdc_request.c:1507:mdc_read_page()) Skipped 85 previous similar messages [ 6936.245870] Lustre: dir [0x200000402:0xe439:0x0] stripe 1 readdir failed: -108, directory is partially accessed! [ 6936.262272] Lustre: Skipped 85 previous similar messages [ 6937.381605] LustreError: 169549:0:(mdc_request.c:1507:mdc_read_page()) lustre-MDT0001-mdc-ffff9b2390b78800: [0x240002b11:0xb7:0x0] lock enqueue fails: rc = -108 [ 6937.412515] LustreError: 169549:0:(mdc_request.c:1507:mdc_read_page()) Skipped 13 previous similar messages [ 6937.430628] Lustre: dir [0x200000402:0xe439:0x0] stripe 1 readdir failed: -108, directory is partially accessed! [ 6937.444319] Lustre: Skipped 13 previous similar messages [ 6943.577505] Lustre: lustre-MDT0001-mdc-ffff9b2390b78800: Connection to lustre-MDT0001 (at 192.168.203.126@tcp) was lost; in progress operations using this service will wait for recovery to complete [ 6943.589062] Lustre: Skipped 1 previous similar message [ 6943.615404] LustreError: lustre-MDT0001-mdc-ffff9b2390b78800: This client was evicted by lustre-MDT0001; in progress operations using this service will fail. [ 6943.643033] Lustre: lustre-MDT0001-mdc-ffff9b2390b78800: Connection restored to 192.168.203.126@tcp (at 192.168.203.126@tcp) [ 6943.655694] Lustre: Skipped 1 previous similar message [ 6945.100625] Lustre: DEBUG MARKER: == sanity test 33j: lfs setdirstripe -D -i x,y,x should fail ========================================================== 07:16:25 (1789384585) [ 6952.271264] Lustre: DEBUG MARKER: == sanity test 34a: truncate file that has not been opened ===================================================================== 07:16:32 (1789384592) [ 6958.904182] Lustre: DEBUG MARKER: == sanity test 34b: O_RDONLY opening file doesn't create objects =============================================================== 07:16:39 (1789384599) [ 6966.194166] Lustre: DEBUG MARKER: == sanity test 34c: O_RDWR opening file-with-size works ======================================================================== 07:16:46 (1789384606) [ 6973.283935] Lustre: DEBUG MARKER: == sanity test 34d: write to sparse file ======================================================================================= 07:16:53 (1789384613) [ 6980.214587] Lustre: DEBUG MARKER: == sanity test 34e: create objects, some with size and some without ============================================================ 07:17:00 (1789384620) [ 6986.886958] Lustre: DEBUG MARKER: == sanity test 34f: read from a file with no objects until EOF ================================================================= 07:17:07 (1789384627) [ 6995.512232] Lustre: DEBUG MARKER: == sanity test 34g: truncate long file ========================================================================================= 07:17:15 (1789384635) [ 7003.467599] Lustre: DEBUG MARKER: == sanity test 34h: ftruncate file under grouplock should not block ========================================================== 07:17:23 (1789384643) [ 7013.489225] Lustre: DEBUG MARKER: == sanity test 35a: exec file with mode 444 (should return and not leak) ========================================================== 07:17:33 (1789384653) [ 7020.638098] Lustre: DEBUG MARKER: == sanity test 36a: MDS utime check (mknod, utime) ======= 07:17:40 (1789384660) [ 7028.569902] Lustre: DEBUG MARKER: == sanity test 36b: OST utime check (open, utime) ======== 07:17:48 (1789384668) [ 7035.134824] Lustre: DEBUG MARKER: == sanity test 36c: non-root MDS utime check (mknod, utime) ========================================================== 07:17:55 (1789384675) [ 7041.827512] Lustre: DEBUG MARKER: == sanity test 36d: non-root OST utime check (open, utime) ========================================================== 07:18:02 (1789384682) [ 7047.737843] Lustre: DEBUG MARKER: == sanity test 36e: utime on non-owned file (should return error) ========================================================== 07:18:08 (1789384688) [ 7054.019841] Lustre: DEBUG MARKER: == sanity test 36f: utime on file racing with OST BRW write ==================================================================== 07:18:14 (1789384694) [ 7061.815689] Lustre: DEBUG MARKER: == sanity test 36g: FMD cache expiry =============================================================================== 07:18:22 (1789384702) [ 7087.583610] Lustre: lustre-OST0000-osc-ffff9b2390b78800: disconnect after 24s idle [ 7113.829423] Lustre: DEBUG MARKER: == sanity test 36h: utime on file racing with OST BRW write ==================================================================== 07:19:14 (1789384754) [ 7121.758687] Lustre: DEBUG MARKER: == sanity test 36i: change mtime on striped directory ==== 07:19:21 (1789384761) [ 7130.303830] Lustre: DEBUG MARKER: == sanity test 38: open a regular file with O_DIRECTORY should return -ENOTDIR ============================================================= 07:19:30 (1789384770) [ 7136.382280] Lustre: DEBUG MARKER: == sanity test 39a: mtime changed on create ============== 07:19:37 (1789384777) [ 7145.429112] Lustre: DEBUG MARKER: == sanity test 39b: mtime change on open, link, unlink, rename ========================================================== 07:19:46 (1789384786) [ 7154.611885] Lustre: DEBUG MARKER: == sanity test 39c: mtime change on rename =============== 07:19:55 (1789384795) [ 7164.555455] Lustre: DEBUG MARKER: == sanity test 39d: create, utime, stat ================== 07:20:05 (1789384805) [ 7171.174558] Lustre: DEBUG MARKER: == sanity test 39e: create, stat, utime, stat ============ 07:20:11 (1789384811) [ 7177.619707] Lustre: DEBUG MARKER: == sanity test 39f: create, stat, sleep, utime, stat ===== 07:20:18 (1789384818) [ 7186.727234] Lustre: DEBUG MARKER: == sanity test 39g: write, chmod, stat =================== 07:20:26 (1789384826) [ 7195.717460] Lustre: DEBUG MARKER: == sanity test 39h: write, utime within one second, stat ========================================================== 07:20:36 (1789384836) [ 7204.639991] Lustre: DEBUG MARKER: == sanity test 39i: write, rename, stat ================== 07:20:44 (1789384844) [ 7213.769256] Lustre: DEBUG MARKER: == sanity test 39j: write, rename, close, stat =========== 07:20:54 (1789384854) [ 7230.943530] Lustre: lustre-OST0000-osc-ffff9b2390b78800: disconnect after 24s idle [ 7247.161894] Lustre: DEBUG MARKER: == sanity test 39k: write, utime, close, stat ============ 07:21:27 (1789384887) [ 7250.404257] LustreError: 188189:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [ 7250.420465] LustreError: 188189:0:(file.c:977:ll_kernel_to_mds_open_flags()) Skipped 3015 previous similar messages [ 7256.553258] Lustre: lustre-OST0001-osc-ffff9b2390b78800: disconnect after 20s idle [ 7257.358703] Lustre: DEBUG MARKER: == sanity test 39l: directory atime update =============== 07:21:37 (1789384897) [ 7258.820908] LustreError: 188826:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [ 7258.833143] LustreError: 188826:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 5385 previous similar messages [ 7275.658981] Lustre: DEBUG MARKER: == sanity test 39m: test atime and mtime before 1970 ===== 07:21:55 (1789384915) [ 7275.751239] LustreError: 189442:0:(namei.c:1721:ll_create_it()) VFS Op:name=f39m.sanity, dir=[0x200000007:0x1:0x0](ffff9b23919180c8), intent=open|creat [ 7275.760324] LustreError: 189442:0:(namei.c:1721:ll_create_it()) Skipped 3471 previous similar messages [ 7275.775583] LustreError: 189442:0:(namei.c:1744:ll_create_it()) inode ffff9b23b3f7cb08 need_sync_to_mds [0x200000402:0xe65c:0x0] [ 7275.790967] LustreError: 189442:0:(namei.c:1744:ll_create_it()) Skipped 3471 previous similar messages [ 7282.143639] Lustre: lustre-OST0000-osc-ffff9b2390b78800: disconnect after 21s idle [ 7285.518555] Lustre: DEBUG MARKER: == sanity test 39n: check that O_NOATIME is honored ====== 07:22:05 (1789384925) [ 7302.644862] Lustre: lustre-OST0001-osc-ffff9b2390b78800: disconnect after 24s idle [ 7308.072605] Lustre: DEBUG MARKER: == sanity test 39o: directory cached attributes updated after create ========================================================== 07:22:28 (1789384948) [ 7316.799373] Lustre: DEBUG MARKER: == sanity test 39p: remote directory cached attributes updated after create ================================================================== 07:22:37 (1789384957) [ 7326.202070] Lustre: DEBUG MARKER: == sanity test 39r: lazy atime update on OST ============= 07:22:46 (1789384966) [ 7338.417939] LustreError: 191925:0:(dcache.c:176:ll_intent_release()) intent ffff9b239e7e4f00 released [ 7338.429353] LustreError: 191925:0:(dcache.c:176:ll_intent_release()) Skipped 4913 previous similar messages [ 7351.019742] Lustre: DEBUG MARKER: == sanity test 39q: close won't zero out atime =========== 07:23:11 (1789384991) [ 7357.715418] Lustre: DEBUG MARKER: == sanity test 39s: relatime is supported ================ 07:23:18 (1789384998) [ 7363.671682] Lustre: Unmounted lustre-client [ 7364.483492] Lustre: Mounted lustre-client - version 2.17.58_39_gb3cb314 [ 7372.695764] Lustre: Unmounted lustre-client [ 7373.118148] Lustre: Mounted lustre-client - version 2.17.58_39_gb3cb314 [ 7380.781635] Lustre: DEBUG MARKER: == sanity test 39u: stat race ============================ 07:23:41 (1789385021) [ 7383.413060] Lustre: *** cfs_fail_loc=1434, val=5173*** [ 7383.417196] LustreError: 193884:0:(file.c:6423:ll_getattr_dentry()) cfs_race id 1435 sleeping [ 7384.402505] LustreError: 193887:0:(file.c:1766:ll_merge_attr_nolock()) cfs_race id 1435 sleeping [ 7388.640612] LustreError: 193884:0:(file.c:6423:ll_getattr_dentry()) cfs_fail_race id 1435 awake: rc=0 [ 7389.663173] LustreError: 193887:0:(file.c:1766:ll_merge_attr_nolock()) cfs_fail_race id 1435 awake: rc=0 [ 7389.669080] LustreError: 193887:0:(file.c:1771:ll_merge_attr_nolock()) cfs_fail_timeout id 1435 sleeping for 1000ms [ 7390.711206] LustreError: 193887:0:(file.c:1771:ll_merge_attr_nolock()) cfs_fail_timeout id 1435 awake [ 7390.720068] LustreError: 193887:0:(file.c:6423:ll_getattr_dentry()) cfs_race id 1435 sleeping [ 7395.807296] LustreError: 193887:0:(file.c:6423:ll_getattr_dentry()) cfs_fail_race id 1435 awake: rc=0 [ 7402.601745] Lustre: DEBUG MARKER: == sanity test 40: failed open(O_TRUNC) doesn't truncate ======================================================================= 07:24:03 (1789385043) [ 7408.795057] Lustre: DEBUG MARKER: == sanity test 41: test small file write + fstat =============================================================================== 07:24:09 (1789385049) [ 7417.673583] Lustre: DEBUG MARKER: SKIP: sanity test_42a skipping ALWAYS excluded test 42a [ 7419.700883] Lustre: DEBUG MARKER: SKIP: sanity test_42b skipping ALWAYS excluded test 42b [ 7421.763996] Lustre: DEBUG MARKER: SKIP: sanity test_42c skipping ALWAYS excluded test 42c [ 7423.871597] Lustre: DEBUG MARKER: == sanity test 42d: test complete truncate of file with cached dirty data ========================================================== 07:24:24 (1789385064) [ 7433.414239] Lustre: DEBUG MARKER: == sanity test 42e: verify sub-RPC writes are not done synchronously ========================================================== 07:24:33 (1789385073) [ 7465.719904] LustreError: 197142:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [ 7465.735205] LustreError: 197142:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 2082 previous similar messages [ 7495.251599] LustreError: 197281:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [ 7495.260720] LustreError: 197281:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 19642 previous similar messages [ 7495.271786] LustreError: 197281:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 1 [ 7495.280605] LustreError: 197281:0:(namei.c:956:ll_intent_lock()) Skipped 12769 previous similar messages [ 7689.928828] Lustre: DEBUG MARKER: == sanity test 43A: execution of file opened for write should return -ETXTBSY ========================================================== 07:28:50 (1789385330) [ 7690.241491] LustreError: 199371:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [ 7690.258558] LustreError: 199371:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 28 previous similar messages [ 7697.894447] Lustre: DEBUG MARKER: == sanity test 43a: open(RDWR) of file being executed should return -ETXTBSY ========================================================== 07:28:58 (1789385338) [ 7706.968666] Lustre: DEBUG MARKER: == sanity test 43b: truncate of file being executed should return -ETXTBSY ========================================================== 07:29:07 (1789385347) [ 7715.337865] Lustre: DEBUG MARKER: == sanity test 43c: md5sum of copy into lustre =========== 07:29:15 (1789385355) [ 7723.522944] Lustre: DEBUG MARKER: == sanity test 44A: zero length read from a sparse stripe ========================================================== 07:29:23 (1789385363) [ 7731.228849] Lustre: DEBUG MARKER: == sanity test 44a: test sparse pwrite ========================================================================================= 07:29:31 (1789385371) [ 7744.838457] Lustre: DEBUG MARKER: == sanity test 44b: write one byte at offset 0xfffffffe000 ========================================================== 07:29:45 (1789385385) [ 7751.860255] Lustre: DEBUG MARKER: == sanity test 44c: write 1 byte at max_object_bytes - 1 offset ========================================================== 07:29:52 (1789385392) [ 7759.589109] Lustre: DEBUG MARKER: == sanity test 44d: if write at position fails (EFBIG), so should do append ========================================================== 07:29:59 (1789385399) [ 7767.543651] Lustre: DEBUG MARKER: == sanity test 44e: write and read maximal stripes ======= 07:30:07 (1789385407) [ 7795.204023] Lustre: DEBUG MARKER: == sanity test 44f: Check fiemap for sparse files ======== 07:30:35 (1789385435) [ 7873.716199] LustreError: 2402:0:(osc_request.c:1024:osc_init_grant()) lustre-OST0000-osc-ffff9b238520e800: granted 8437760 but already consumed 10559488 [ 7952.641650] LustreError: 206491:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [ 7952.654430] LustreError: 206491:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 2223 previous similar messages [ 7952.720746] LustreError: 206491:0:(namei.c:1721:ll_create_it()) VFS Op:name=f44f.sanity-1, dir=[0x200000007:0x1:0x0](ffff9b23b3f9ec08), intent=open|creat [ 7952.742891] LustreError: 206491:0:(namei.c:1721:ll_create_it()) Skipped 1945 previous similar messages [ 7952.754635] LustreError: 206491:0:(namei.c:1744:ll_create_it()) inode ffff9b2391b25348 need_sync_to_mds [0x200002b12:0x491:0x0] [ 7952.776849] LustreError: 206491:0:(namei.c:1744:ll_create_it()) Skipped 1945 previous similar messages [ 7952.807432] LustreError: 206491:0:(dcache.c:176:ll_intent_release()) intent ffff9b239208e360 released [ 7952.818058] LustreError: 206491:0:(dcache.c:176:ll_intent_release()) Skipped 2741 previous similar messages [ 8039.687971] LustreError: 2402:0:(osc_request.c:1024:osc_init_grant()) lustre-OST0001-osc-ffff9b238520e800: granted 8437760 but already consumed 10559488 [ 8109.897893] LustreError: 206491:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [ 8109.913665] LustreError: 206491:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 9008 previous similar messages [ 8109.975691] LustreError: 206515:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 0 [ 8109.984091] LustreError: 206515:0:(namei.c:956:ll_intent_lock()) Skipped 4961 previous similar messages [ 8190.936813] LustreError: 2402:0:(osc_request.c:1024:osc_init_grant()) lustre-OST0000-osc-ffff9b238520e800: granted 8437760 but already consumed 10559488 [ 8268.372706] LustreError: 2402:0:(osc_request.c:1024:osc_init_grant()) lustre-OST0000-osc-ffff9b238520e800: granted 8437760 but already consumed 10559488 [ 8340.665255] LustreError: 2402:0:(osc_request.c:1024:osc_init_grant()) lustre-OST0001-osc-ffff9b238520e800: granted 8437760 but already consumed 10559488 [ 8425.551584] LustreError: 2402:0:(osc_request.c:1024:osc_init_grant()) lustre-OST0001-osc-ffff9b238520e800: granted 8437760 but already consumed 10559488 [ 8504.315291] LustreError: 2402:0:(osc_request.c:1024:osc_init_grant()) lustre-OST0000-osc-ffff9b238520e800: granted 8437760 but already consumed 10559488 [ 8589.853293] LustreError: 2402:0:(osc_request.c:1024:osc_init_grant()) lustre-OST0000-osc-ffff9b238520e800: granted 8437760 but already consumed 10559488 [ 8596.154215] LustreError: 207014:0:(dcache.c:176:ll_intent_release()) intent ffffae0bc0dd3b20 released [ 8596.159337] LustreError: 207014:0:(dcache.c:176:ll_intent_release()) Skipped 3 previous similar messages [ 8598.379226] Lustre: DEBUG MARKER: == sanity test 44g: test overflow in lov_stripe_size ===== 07:43:58 (1789386238) [ 8598.436667] LustreError: 207156:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [ 8598.447772] LustreError: 207156:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 3 previous similar messages [ 8598.513203] LustreError: 207156:0:(namei.c:1721:ll_create_it()) VFS Op:name=f44g.sanity, dir=[0x200000007:0x1:0x0](ffff9b23b3f9ec08), intent=open|creat [ 8598.519852] LustreError: 207156:0:(namei.c:1721:ll_create_it()) Skipped 3 previous similar messages [ 8598.530283] LustreError: 207156:0:(namei.c:1744:ll_create_it()) inode ffff9b23937c21c8 need_sync_to_mds [0x200002b12:0x495:0x0] [ 8598.535447] LustreError: 207156:0:(namei.c:1744:ll_create_it()) Skipped 3 previous similar messages [ 8606.883709] Lustre: DEBUG MARKER: == sanity test 45: osc io page accounting ================ 07:44:07 (1789386247) [ 8607.610688] LustreError: 207610:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [ 8607.626852] LustreError: 207610:0:(file.c:977:ll_kernel_to_mds_open_flags()) Skipped 519 previous similar messages [ 8616.041896] Lustre: DEBUG MARKER: == sanity test 46: dirtying a previously written page ========================================================================== 07:44:16 (1789386256) [ 8625.217899] Lustre: DEBUG MARKER: == sanity test 48a: Access renamed working dir (should return errors)=========================================================== 07:44:25 (1789386265) [ 8625.465689] LustreError: 208996:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [ 8625.471608] LustreError: 208996:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 3 previous similar messages [ 8626.731290] LustreError: 209016:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [ 8626.738469] LustreError: 209016:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 1002 previous similar messages [ 8637.011870] Lustre: DEBUG MARKER: == sanity test 48b: Access removed working dir (should return errors)=========================================================== 07:44:36 (1789386276) [ 8647.413970] Lustre: DEBUG MARKER: == sanity test 48c: Access removed working subdir (should return errors) ========================================================== 07:44:47 (1789386287) [ 8655.754379] Lustre: DEBUG MARKER: == sanity test 48d: Access removed parent subdir (should return errors) ========================================================== 07:44:56 (1789386296) [ 8664.573575] Lustre: DEBUG MARKER: == sanity test 48e: Access to recreated parent subdir (should return errors) ========================================================== 07:45:04 (1789386304) [ 8673.839792] Lustre: DEBUG MARKER: == sanity test 48f: non-zero nlink dir unlink won't LBUG() ========================================================== 07:45:13 (1789386313) [ 8675.846698] Lustre: DEBUG MARKER: SKIP: sanity test_48f needs different host for mdt1 mdt2 [ 8677.911833] Lustre: DEBUG MARKER: == sanity test 49a: Change max_pages_per_rpc won't break osc extent ========================================================== 07:45:18 (1789386318) [ 9200.816961] LustreError: 193273:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [ 9200.831818] LustreError: 193273:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 503 previous similar messages [ 9250.982667] LustreError: 212321:0:(namei.c:956:ll_intent_lock()) intent lock 1024 on i1 [0x200002b12:0x4ad:0x0] suppgids 0 0: rc 0 [ 9250.987396] LustreError: 212321:0:(namei.c:956:ll_intent_lock()) Skipped 431 previous similar messages [ 9431.137932] LustreError: 213371:0:(dcache.c:176:ll_intent_release()) intent ffffae0bc32afb20 released [ 9431.148448] LustreError: 213371:0:(dcache.c:176:ll_intent_release()) Skipped 222 previous similar messages [ 9464.391919] Lustre: DEBUG MARKER: == sanity test 49b: verify max_mb_per_rpc_read/write after setting max_pages_per_rpc ========================================================== 07:58:24 (1789387104) [ 9471.538686] Lustre: DEBUG MARKER: == sanity test 49c: verify max_mb_per_rpc_read/write ===== 07:58:32 (1789387112) [ 9479.407962] Lustre: DEBUG MARKER: == sanity test 50: special situations: /proc symlinks ========================================================================= 07:58:39 (1789387119) [ 9479.624737] LustreError: 215156:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [ 9479.647406] LustreError: 215156:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 11 previous similar messages [ 9479.873832] LustreError: 215161:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [ 9479.888461] LustreError: 215161:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 74 previous similar messages [ 9487.765246] Lustre: DEBUG MARKER: == sanity test 51a: special situations: split htree with empty entry ============================================================ 07:58:47 (1789387127) [ 9488.250229] LustreError: 215747:0:(namei.c:1721:ll_create_it()) VFS Op:name=foo, dir=[0x240002b13:0x3ca:0x0](ffff9b2391b221c8), intent=open|creat [ 9488.271070] LustreError: 215747:0:(namei.c:1721:ll_create_it()) Skipped 8 previous similar messages [ 9488.283951] LustreError: 215747:0:(namei.c:1744:ll_create_it()) inode ffff9b239911aa08 need_sync_to_mds [0x240002b13:0x3cb:0x0] [ 9488.299348] LustreError: 215747:0:(namei.c:1744:ll_create_it()) Skipped 8 previous similar messages [ 9493.986687] LustreError: 215943:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [ 9494.000467] LustreError: 215943:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 6 previous similar messages [ 9503.554418] Lustre: DEBUG MARKER: == sanity test 51b: exceed 64k subdirectory nlink limit on create, verify unlink ========================================================== 07:59:03 (1789387143) [ 9504.071196] LustreError: 216528:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [ 9504.077545] LustreError: 216528:0:(file.c:977:ll_kernel_to_mds_open_flags()) Skipped 1 previous similar message [ 9800.818546] LustreError: 216768:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [ 9800.827747] LustreError: 216768:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 94313 previous similar messages [ 9850.985890] LustreError: 216768:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 1 [ 9851.000364] LustreError: 216768:0:(namei.c:956:ll_intent_lock()) Skipped 54992 previous similar messages [10031.160327] LustreError: 216997:0:(dcache.c:176:ll_intent_release()) intent ffffae0bc1f07b20 released [10031.177363] LustreError: 216997:0:(dcache.c:176:ll_intent_release()) Skipped 17368 previous similar messages [10400.818160] LustreError: 216997:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [10400.823382] LustreError: 216997:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 153861 previous similar messages [10450.988877] LustreError: 216997:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x240002b13:0x496:0x0] suppgids 0 -1: rc 0 [10450.998314] LustreError: 216997:0:(namei.c:956:ll_intent_lock()) Skipped 108351 previous similar messages [10631.163181] LustreError: 217434:0:(dcache.c:176:ll_intent_release()) intent ffffae0bc146fe08 released [10631.170070] LustreError: 217434:0:(dcache.c:176:ll_intent_release()) Skipped 132614 previous similar messages [10976.724908] LustreError: 217650:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [10976.740810] LustreError: 217650:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 1 previous similar message [10992.929760] Lustre: DEBUG MARKER: SKIP: sanity test_51c skipping SLOW test 51c [10995.245759] Lustre: DEBUG MARKER: == sanity test 51d: check LOV round-robin OST object distribution ========================================================== 08:23:55 (1789388635) [10996.671884] Lustre: DEBUG MARKER: SKIP: sanity test_51d needs >= 3 OSTs [10998.356291] Lustre: DEBUG MARKER: SKIP: sanity test_51e skipping SLOW test 51e [11000.301618] Lustre: DEBUG MARKER: == sanity test 51f: check many open files limit ========== 08:24:00 (1789388640) [11000.824967] LustreError: 219204:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [11000.837919] LustreError: 219204:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 174606 previous similar messages [11000.846523] LustreError: 219204:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [11000.852787] LustreError: 219204:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 65840 previous similar messages [11001.007679] LustreError: 219206:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [11001.016590] LustreError: 219206:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 7 previous similar messages [11001.100533] LustreError: 219206:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [11004.478646] LustreError: 219328:0:(namei.c:1721:ll_create_it()) VFS Op:name=f0, dir=[0x240002b13:0x104fb:0x0](ffff9b23c1d83a88), intent=open|creat [11004.495273] LustreError: 219328:0:(namei.c:1744:ll_create_it()) inode ffff9b23c1d83248 need_sync_to_mds [0x200002b12:0x4b0:0x0] [11050.992927] LustreError: 219328:0:(namei.c:956:ll_intent_lock()) intent lock 3 on i1 [0x240002b10:0x54:0x0] suppgids 0 -1: rc 0 [11051.004542] LustreError: 219328:0:(namei.c:956:ll_intent_lock()) Skipped 102894 previous similar messages [11076.012638] LustreError: 219328:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [11076.022653] LustreError: 219328:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 10040 previous similar messages [11079.484081] LustreError: 219328:0:(namei.c:1721:ll_create_it()) VFS Op:name=f10532, dir=[0x240002b13:0x104fb:0x0](ffff9b23c1d83a88), intent=open|creat [11079.494517] LustreError: 219328:0:(namei.c:1721:ll_create_it()) Skipped 10531 previous similar messages [11079.501890] LustreError: 219328:0:(namei.c:1744:ll_create_it()) inode ffff9b2386c0cb08 need_sync_to_mds [0x240002b13:0x1198e:0x0] [11079.508190] LustreError: 219328:0:(namei.c:1744:ll_create_it()) Skipped 10531 previous similar messages [11301.315832] LustreError: 219540:0:(dcache.c:176:ll_intent_release()) intent ffffae0bc0da3e00 released [11301.321419] LustreError: 219540:0:(dcache.c:176:ll_intent_release()) Skipped 24426 previous similar messages [11312.308694] Lustre: DEBUG MARKER: == sanity test 52a: append-only flag test (should return errors) ========================================================== 08:29:12 (1789388952) [11312.540612] LustreError: 220212:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [11312.702308] LustreError: 220217:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [11312.715877] LustreError: 220217:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 6593 previous similar messages [11312.767414] LustreError: 220217:0:(namei.c:1721:ll_create_it()) VFS Op:name=foo, dir=[0x200002b12:0x252d:0x0](ffff9b23b6ab4b08), intent=open|creat [11312.783315] LustreError: 220217:0:(namei.c:1721:ll_create_it()) Skipped 6101 previous similar messages [11312.789062] LustreError: 220217:0:(namei.c:1744:ll_create_it()) inode ffff9b23b6aacb08 need_sync_to_mds [0x200002b12:0x252e:0x0] [11312.804703] LustreError: 220217:0:(namei.c:1744:ll_create_it()) Skipped 6101 previous similar messages [11313.019880] LustreError: 220218:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [11313.231426] LustreError: 220062:0:(file.c:251:ll_close_inode_openhandle()) lustre-clilmv-ffff9b238520e800: inode [0x200002b12:0x252e:0x0] mdc close failed: rc = -1 [11313.242169] LustreError: 220062:0:(file.c:251:ll_close_inode_openhandle()) Skipped 77 previous similar messages [11313.513438] LustreError: 220226:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [11320.811182] Lustre: DEBUG MARKER: == sanity test 52b: immutable flag test (should return errors) ================================================================= 08:29:21 (1789388961) [11321.286647] LustreError: 220815:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [11321.291874] LustreError: 220815:0:(file.c:977:ll_kernel_to_mds_open_flags()) Skipped 6 previous similar messages [11329.028674] Lustre: DEBUG MARKER: == sanity test 53: verify that MDS and OSTs agree on pre-creation ============================================================== 08:29:29 (1789388969) [11344.483800] Lustre: DEBUG MARKER: == sanity test 54a: unix domain socket test ============== 08:29:44 (1789388984) [11352.141095] Lustre: DEBUG MARKER: == sanity test 54b: char device works in lustre ================================================================================ 08:29:52 (1789388992) [11359.157570] Lustre: DEBUG MARKER: == sanity test 54c: block device works in lustre =============================================================================== 08:29:59 (1789388999) [11359.432298] LustreError: 223327:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [11359.446193] LustreError: 223327:0:(file.c:977:ll_kernel_to_mds_open_flags()) Skipped 4 previous similar messages [11359.500937] loop3: detected capacity change from 0 to 4198400 [11360.470995] EXT4-fs (loop3): mounting ext2 file system using the ext4 subsystem [11360.878742] EXT4-fs (loop3): mounted filesystem without journal. Opts: (null) [11368.140892] Lustre: DEBUG MARKER: == sanity test 54d: fifo device works in lustre ================================================================================ 08:30:08 (1789389008) [11375.211614] Lustre: DEBUG MARKER: == sanity test 54e: console/tty device works in lustre ================================================================================ 08:30:15 (1789389015) aaaaaa [11383.345565] Lustre: DEBUG MARKER: == sanity test 55a: OBD device life cycle unit tests ===== 08:30:23 (1789389023) [11383.673322] Lustre: OBD: obd_test_device_init [11383.673332] Lustre: OBD: obd_name: obd_name, obd_num: 7, obd_uuid: obd_uuid [11383.675787] Lustre: OBD: class_name2dev(): 7, PASS [11383.682595] Lustre: OBD: class_name2obd(): 7, PASS [11383.687189] Lustre: OBD: class_uuid2obd(): 7, PASS [11383.727476] Lustre: OBD: obd_test_device_fini [11390.615352] Lustre: DEBUG MARKER: == sanity test 55b: Load and unload max OBD devices ====== 08:30:30 (1789389030) [12180.749457] Lustre: DEBUG MARKER: == sanity test 55c: obd_mod_rpcs_test ==================== 08:43:41 (1789389821) [12181.120217] [12181.120217] === Starting test case 1: kthread flags === [12181.134062] Test 1: Current flags: 0x208840 [12181.146334] Test 1: set_child_tid: 0000000000000000 [12181.156633] Lustre: mock_obd: Force grant RPC slot (2 current) to proc with flag: 208840. [12181.173097] Test 1: Return value (slot): 3 [12181.178016] Test 1: RPCs in flight: 2 [12181.179381] === Finished test case 1 === [12181.193289] [12181.193289] === Starting test case 2: non mem_alloc flags === [12181.199058] Test 2: Current flags: 0x208040 [12181.202519] Test 2: set_child_tid: 0000000000000000 [12181.212325] Test 2: Return value (slot): 1 [12181.223541] Test 2: RPCs in flight: 1 [12181.228914] === Finished test case 2 === [12181.515354] Task Module: Unloading module [12189.114709] Lustre: DEBUG MARKER: == sanity test 56a: check /home/green/git/lustre-release/lustre/utils/lfs getstripe ========================================================== 08:43:49 (1789389829) [12189.183769] LustreError: 226992:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [12189.198737] LustreError: 226992:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 83552 previous similar messages [12189.260933] LustreError: 226992:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 0 [12189.273580] LustreError: 226992:0:(namei.c:956:ll_intent_lock()) Skipped 37265 previous similar messages [12189.304744] LustreError: 226992:0:(dcache.c:176:ll_intent_release()) intent ffffae0bc0d17930 released [12189.309010] LustreError: 226992:0:(dcache.c:176:ll_intent_release()) Skipped 34 previous similar messages [12189.392235] LustreError: 227005:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [12189.408325] LustreError: 227005:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 7 previous similar messages [12189.744903] LustreError: 227012:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [12189.759366] LustreError: 227012:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 5 previous similar messages [12189.982558] LustreError: 227014:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [12189.993872] LustreError: 227014:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 9 previous similar messages [12190.048503] LustreError: 227014:0:(namei.c:1721:ll_create_it()) VFS Op:name=file1, dir=[0x240002b13:0x12579:0x0](ffff9b23b6aaf448), intent=open|creat [12190.056631] LustreError: 227014:0:(namei.c:1721:ll_create_it()) Skipped 2 previous similar messages [12190.061876] LustreError: 227014:0:(namei.c:1744:ll_create_it()) inode ffff9b23b6a39988 need_sync_to_mds [0x240002b13:0x1257a:0x0] [12190.068291] LustreError: 227014:0:(namei.c:1744:ll_create_it()) Skipped 2 previous similar messages [12190.518753] LustreError: 227020:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [12191.764440] LustreError: 227059:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [12191.783964] LustreError: 227059:0:(file.c:977:ll_kernel_to_mds_open_flags()) Skipped 17 previous similar messages [12199.449414] Lustre: DEBUG MARKER: == sanity test 56b: check /home/green/git/lustre-release/lustre/utils/lfs getdirstripe ========================================================== 08:43:59 (1789389839) [12200.621924] LustreError: 227682:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [12200.631489] LustreError: 227682:0:(file.c:977:ll_kernel_to_mds_open_flags()) Skipped 6 previous similar messages [12208.668589] Lustre: DEBUG MARKER: == sanity test 56bb: check /home/green/git/lustre-release/lustre/utils/lfs getdirstripe layout is YAML ========================================================== 08:44:08 (1789389848) [12209.543568] LustreError: 228265:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [12209.553837] LustreError: 228265:0:(file.c:977:ll_kernel_to_mds_open_flags()) Skipped 2 previous similar messages [12210.230196] LustreError: 228275:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [12210.238088] LustreError: 228275:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 5 previous similar messages [12217.486562] Lustre: DEBUG MARKER: == sanity test 56bc: check '/home/green/git/lustre-release/lustre/utils/lfs getdirstripe --yaml' params are valid ========================================================== 08:44:17 (1789389857) [12218.721744] LustreError: 228861:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [12218.730420] LustreError: 228861:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 33 previous similar messages [12219.168644] LustreError: 228888:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [12219.193755] LustreError: 228888:0:(file.c:977:ll_kernel_to_mds_open_flags()) Skipped 6 previous similar messages [12226.413629] Lustre: DEBUG MARKER: == sanity test 56bd: check '/home/green/git/lustre-release/lustre/utils/lfs getdirstripe' output contains header only when needed ========================================================== 08:44:26 (1789389866) [12233.444880] Lustre: DEBUG MARKER: == sanity test 56c: check 'lfs df' showing device status ========================================================== 08:44:33 (1789389873) [12265.439653] Lustre: DEBUG MARKER: == sanity test 56ca: 'lfs df -v' correctly reports 'R' flag when OST set as Readonly ========================================================== 08:45:05 (1789389905) [12299.031568] Lustre: DEBUG MARKER: == sanity test 56d: 'lfs df -v' prints only configured devices ========================================================== 08:45:39 (1789389939) [12308.234784] Lustre: DEBUG MARKER: == sanity test 56e: 'lfs df' Handle non LustreFS [12317.916689] Lustre: DEBUG MARKER: == sanity test 56g: check lfs find -name ================= 08:45:57 (1789389957) [12318.742258] LustreError: 232696:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [12318.776910] LustreError: 232696:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 3 previous similar messages [12319.695676] LustreError: 232711:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [12321.704725] LustreError: 232747:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [12321.711578] LustreError: 232747:0:(file.c:977:ll_kernel_to_mds_open_flags()) Skipped 1 previous similar message [12331.104683] Lustre: DEBUG MARKER: == sanity test 56h: check lfs find ! -name =============== 08:46:11 (1789389971) [12340.777889] Lustre: DEBUG MARKER: == sanity test 56i: check 'lfs find -ost UUID' skips directories ========================================================== 08:46:20 (1789389980) [12349.517745] Lustre: DEBUG MARKER: == sanity test 56ib: check 'lfs find -ost INDEX_RANGE' command ========================================================== 08:46:29 (1789389989) [12360.916871] Lustre: DEBUG MARKER: == sanity test 56j: check lfs find -type d =============== 08:46:39 (1789389999) [12362.189591] LustreError: 235153:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [12362.203145] LustreError: 235153:0:(file.c:977:ll_kernel_to_mds_open_flags()) Skipped 29 previous similar messages [12370.103661] Lustre: DEBUG MARKER: == sanity test 56k: check lfs find -type f =============== 08:46:50 (1789390010) [12377.115433] Lustre: DEBUG MARKER: == sanity test 56l: check lfs find -type b =============== 08:46:57 (1789390017) [12384.742253] Lustre: DEBUG MARKER: == sanity test 56m: check lfs find -type c =============== 08:47:05 (1789390025) [12392.962854] Lustre: DEBUG MARKER: == sanity test 56n: check lfs find -type l =============== 08:47:13 (1789390033) [12400.881334] Lustre: DEBUG MARKER: == sanity test 56o: check lfs find -mtime for old files == 08:47:21 (1789390041) [12401.311622] LustreError: 238072:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [12401.323165] LustreError: 238072:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 23 previous similar messages [12401.819845] LustreError: 238086:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [12401.827257] LustreError: 238086:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 49 previous similar messages [12412.683838] Lustre: DEBUG MARKER: == sanity test 56ob: check lfs find -atime -mtime -ctime with units ========================================================== 08:47:32 (1789390052) [12425.720463] Lustre: DEBUG MARKER: SKIP: sanity test_56oc skipping excluded test 56oc [12427.315756] Lustre: DEBUG MARKER: == sanity test 56od: check lfs find -btime with units ==== 08:47:47 (1789390067) [12438.513421] LustreError: 239621:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [12438.532437] LustreError: 239621:0:(file.c:977:ll_kernel_to_mds_open_flags()) Skipped 39 previous similar messages [12447.712834] Lustre: DEBUG MARKER: == sanity test 56oe: check lfs find with time range ====== 08:48:08 (1789390088) [12572.594782] LustreError: 240322:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [12572.610626] LustreError: 240322:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 48 previous similar messages [12582.940360] Lustre: DEBUG MARKER: == sanity test 56p: check lfs find -uid and ! -uid ======= 08:50:23 (1789390223) [12583.123973] LustreError: 240947:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [12583.140973] LustreError: 240947:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 15 previous similar messages [12592.453189] Lustre: DEBUG MARKER: == sanity test 56q: check lfs find -gid and ! -gid ======= 08:50:32 (1789390232) [12594.815653] LustreError: 241646:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [12594.826101] LustreError: 241646:0:(file.c:977:ll_kernel_to_mds_open_flags()) Skipped 38 previous similar messages [12601.826334] Lustre: DEBUG MARKER: == sanity test 56r: check lfs find -size works =========== 08:50:42 (1789390242) [12614.670779] Lustre: DEBUG MARKER: == sanity test 56ra: check lfs find -size -lazy works for data on OSTs ========================================================== 08:50:54 (1789390254) [12629.962300] Lustre: DEBUG MARKER: == sanity test 56rb: check lfs find --size --ost/--mdt works ========================================================== 08:51:10 (1789390270) [12636.973455] Lustre: DEBUG MARKER: == sanity test 56rc: check lfs find --mdt-count/--mdt-hash works ========================================================== 08:51:17 (1789390277) [12647.774959] Lustre: DEBUG MARKER: == sanity test 56rd: check lfs find --printf special files ========================================================== 08:51:28 (1789390288) [12654.897639] Lustre: DEBUG MARKER: == sanity test 56re: check lfs find -printf width format specifiers are consistant with regular find ========================================================== 08:51:35 (1789390295) [12665.115768] Lustre: DEBUG MARKER: == sanity test 56rf: check lfs find -printf width format specifiers for lustre specific formats ========================================================== 08:51:45 (1789390305) [12684.194229] Lustre: DEBUG MARKER: == sanity test 56s: check lfs find -stripe-count works === 08:52:04 (1789390324) [12693.862089] Lustre: DEBUG MARKER: == sanity test 56t: check lfs find -stripe-size works ==== 08:52:14 (1789390334) [12707.278411] Lustre: DEBUG MARKER: == sanity test 56u: check lfs find -stripe-index works === 08:52:27 (1789390347) [12717.223040] Lustre: DEBUG MARKER: == sanity test 56v: check 'lfs find -m match with lfs getstripe -m' ========================================================== 08:52:37 (1789390357) [12726.039668] Lustre: DEBUG MARKER: == sanity test 56wa: check 'lfs migrate -c stripe_count' works ========================================================== 08:52:46 (1789390366) [12742.144508] LustreError: 250398:0:(llite_lib.c:4170:ll_prep_md_op_data()) debug: Setting bias to MDS_CREATE_VOLATILE: . :VOLATILE:0000:4D446290:fd=03 [12742.157294] LustreError: 250398:0:(lmv_obd.c:1943:lmv_locate_tgt()) debug: handling volatile file... [12742.166854] LustreError: 250398:0:(mdc_lib.c:326:mdc_open_pack()) debug: create_volatile changes to mds_open_volatile [12743.554478] LustreError: 250406:0:(llite_lib.c:4170:ll_prep_md_op_data()) debug: Setting bias to MDS_CREATE_VOLATILE: . :VOLATILE:0000:2E98802B:fd=03 [12743.561331] LustreError: 250406:0:(lmv_obd.c:1943:lmv_locate_tgt()) debug: handling volatile file... [12743.565795] LustreError: 250406:0:(mdc_lib.c:326:mdc_open_pack()) debug: create_volatile changes to mds_open_volatile [12745.294588] LustreError: 250410:0:(llite_lib.c:4170:ll_prep_md_op_data()) debug: Setting bias to MDS_CREATE_VOLATILE: . :VOLATILE:0000:386FC56F:fd=03 [12745.306118] LustreError: 250410:0:(lmv_obd.c:1943:lmv_locate_tgt()) debug: handling volatile file... [12745.315556] LustreError: 250410:0:(mdc_lib.c:326:mdc_open_pack()) debug: create_volatile changes to mds_open_volatile [12747.368746] LustreError: 250410:0:(llite_lib.c:4170:ll_prep_md_op_data()) debug: Setting bias to MDS_CREATE_VOLATILE: . :VOLATILE:0000:6CD68D3A:fd=03 [12747.381297] LustreError: 250410:0:(llite_lib.c:4170:ll_prep_md_op_data()) Skipped 1 previous similar message [12747.388628] LustreError: 250410:0:(lmv_obd.c:1943:lmv_locate_tgt()) debug: handling volatile file... [12747.397629] LustreError: 250410:0:(lmv_obd.c:1943:lmv_locate_tgt()) Skipped 1 previous similar message [12747.410907] LustreError: 250410:0:(mdc_lib.c:326:mdc_open_pack()) debug: create_volatile changes to mds_open_volatile [12747.416688] LustreError: 250410:0:(mdc_lib.c:326:mdc_open_pack()) Skipped 1 previous similar message [12752.352463] LustreError: 250410:0:(llite_lib.c:4170:ll_prep_md_op_data()) debug: Setting bias to MDS_CREATE_VOLATILE: . :VOLATILE:0000:4C301D40:fd=03 [12752.369744] LustreError: 250410:0:(llite_lib.c:4170:ll_prep_md_op_data()) Skipped 4 previous similar messages [12752.382870] LustreError: 250410:0:(lmv_obd.c:1943:lmv_locate_tgt()) debug: handling volatile file... [12752.391583] LustreError: 250410:0:(lmv_obd.c:1943:lmv_locate_tgt()) Skipped 4 previous similar messages [12752.400564] LustreError: 250410:0:(mdc_lib.c:326:mdc_open_pack()) debug: create_volatile changes to mds_open_volatile [12752.405886] LustreError: 250410:0:(mdc_lib.c:326:mdc_open_pack()) Skipped 4 previous similar messages [12761.106307] LustreError: 250410:0:(llite_lib.c:4170:ll_prep_md_op_data()) debug: Setting bias to MDS_CREATE_VOLATILE: . :VOLATILE:0000:E25B752:fd=03 [12761.115417] LustreError: 250410:0:(llite_lib.c:4170:ll_prep_md_op_data()) Skipped 8 previous similar messages [12761.121328] LustreError: 250410:0:(lmv_obd.c:1943:lmv_locate_tgt()) debug: handling volatile file... [12761.125782] LustreError: 250410:0:(lmv_obd.c:1943:lmv_locate_tgt()) Skipped 8 previous similar messages [12761.131592] LustreError: 250410:0:(mdc_lib.c:326:mdc_open_pack()) debug: create_volatile changes to mds_open_volatile [12761.137295] LustreError: 250410:0:(mdc_lib.c:326:mdc_open_pack()) Skipped 8 previous similar messages [12777.695799] LustreError: 250410:0:(llite_lib.c:4170:ll_prep_md_op_data()) debug: Setting bias to MDS_CREATE_VOLATILE: . :VOLATILE:0000:503B8BB:fd=03 [12777.705560] LustreError: 250410:0:(llite_lib.c:4170:ll_prep_md_op_data()) Skipped 15 previous similar messages [12777.711275] LustreError: 250410:0:(lmv_obd.c:1943:lmv_locate_tgt()) debug: handling volatile file... [12777.716580] LustreError: 250410:0:(lmv_obd.c:1943:lmv_locate_tgt()) Skipped 15 previous similar messages [12777.720829] LustreError: 250410:0:(mdc_lib.c:326:mdc_open_pack()) debug: create_volatile changes to mds_open_volatile [12777.726433] LustreError: 250410:0:(mdc_lib.c:326:mdc_open_pack()) Skipped 15 previous similar messages [12789.452889] LustreError: 250410:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [12789.470735] LustreError: 250410:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 10649 previous similar messages [12789.638106] LustreError: 250410:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 1 [12789.644858] LustreError: 250410:0:(namei.c:956:ll_intent_lock()) Skipped 6229 previous similar messages [12789.665744] LustreError: 250410:0:(dcache.c:176:ll_intent_release()) intent ffff9b23b70d7c60 released [12789.671438] LustreError: 250410:0:(dcache.c:176:ll_intent_release()) Skipped 1240 previous similar messages [12790.491292] LustreError: 250410:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [12790.498216] LustreError: 250410:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 525 previous similar messages [12790.560981] LustreError: 250410:0:(namei.c:1721:ll_create_it()) VFS Op:name=. :VOLATILE:0000:55FAA99E:fd=03, dir=[0x200002b12:0x2636:0x0](ffff9b23993663c8), intent=open|creat [12790.581027] LustreError: 250410:0:(namei.c:1721:ll_create_it()) Skipped 276 previous similar messages [12790.597050] LustreError: 250410:0:(namei.c:1744:ll_create_it()) inode ffff9b2384b1a1c8 need_sync_to_mds [0x200002b12:0x267d:0x0] [12790.605385] LustreError: 250410:0:(namei.c:1744:ll_create_it()) Skipped 276 previous similar messages [12810.217723] LustreError: 250410:0:(llite_lib.c:4170:ll_prep_md_op_data()) debug: Setting bias to MDS_CREATE_VOLATILE: . :VOLATILE:0000:59F966C3:fd=03 [12810.244282] LustreError: 250410:0:(llite_lib.c:4170:ll_prep_md_op_data()) Skipped 30 previous similar messages [12810.253052] LustreError: 250410:0:(lmv_obd.c:1943:lmv_locate_tgt()) debug: handling volatile file... [12810.262372] LustreError: 250410:0:(lmv_obd.c:1943:lmv_locate_tgt()) Skipped 30 previous similar messages [12810.273958] LustreError: 250410:0:(mdc_lib.c:326:mdc_open_pack()) debug: create_volatile changes to mds_open_volatile [12810.287955] LustreError: 250410:0:(mdc_lib.c:326:mdc_open_pack()) Skipped 30 previous similar messages [12874.414453] LustreError: 250410:0:(llite_lib.c:4170:ll_prep_md_op_data()) debug: Setting bias to MDS_CREATE_VOLATILE: . :VOLATILE:0000:703270DD:fd=03 [12874.429147] LustreError: 250410:0:(llite_lib.c:4170:ll_prep_md_op_data()) Skipped 57 previous similar messages [12874.436768] LustreError: 250410:0:(lmv_obd.c:1943:lmv_locate_tgt()) debug: handling volatile file... [12874.443967] LustreError: 250410:0:(lmv_obd.c:1943:lmv_locate_tgt()) Skipped 57 previous similar messages [12874.448912] LustreError: 250410:0:(mdc_lib.c:326:mdc_open_pack()) debug: create_volatile changes to mds_open_volatile [12874.454389] LustreError: 250410:0:(mdc_lib.c:326:mdc_open_pack()) Skipped 57 previous similar messages [12970.600077] LustreError: 250461:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [12970.605182] LustreError: 250461:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 407 previous similar messages [12984.125271] Lustre: DEBUG MARKER: == sanity test 56wb: check 'lfs migrate' pool support ==== 08:57:04 (1789390624) [12984.550438] LustreError: 251058:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [12984.563102] LustreError: 251058:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 66 previous similar messages [13011.069210] Lustre: DEBUG MARKER: == sanity test 56wc: check unrecognized options for lfs migrate are passed through ========================================================== 08:57:31 (1789390651) [13013.548520] LustreError: 251824:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [13013.553851] LustreError: 251824:0:(file.c:977:ll_kernel_to_mds_open_flags()) Skipped 394 previous similar messages [13013.569195] LustreError: 251824:0:(llite_lib.c:4170:ll_prep_md_op_data()) debug: Setting bias to MDS_CREATE_VOLATILE: . :VOLATILE:0001:4D880DDE:fd=03 [13013.578636] LustreError: 251824:0:(llite_lib.c:4170:ll_prep_md_op_data()) Skipped 94 previous similar messages [13013.585697] LustreError: 251824:0:(lmv_obd.c:1943:lmv_locate_tgt()) debug: handling volatile file... [13013.592513] LustreError: 251824:0:(lmv_obd.c:1943:lmv_locate_tgt()) Skipped 94 previous similar messages [13013.598501] LustreError: 251824:0:(mdc_lib.c:326:mdc_open_pack()) debug: create_volatile changes to mds_open_volatile [13013.605465] LustreError: 251824:0:(mdc_lib.c:326:mdc_open_pack()) Skipped 94 previous similar messages [13046.725931] Lustre: DEBUG MARKER: == sanity test 56wd: check lfs_migrate --rsync and --no-rsync work ========================================================== 08:58:07 (1789390687) [13055.208849] Lustre: DEBUG MARKER: == sanity test 56we: check lfs migrate --non-direct|-D support ========================================================== 08:58:15 (1789390695) [13064.223401] Lustre: DEBUG MARKER: == sanity test 56x: lfs migration support ================ 08:58:24 (1789390704) [13072.242495] Lustre: DEBUG MARKER: == sanity test 56xB: lfs migrate with -0, --null, --files-from arguments ========================================================== 08:58:32 (1789390712) [13084.716476] Lustre: DEBUG MARKER: == sanity test 56xC: lfs migration can accept FID list file ========================================================== 08:58:45 (1789390725) [13095.685725] Lustre: DEBUG MARKER: == sanity test 56xD: lfs_migration can accept FIDs ======= 08:58:56 (1789390736) [13105.901917] Lustre: DEBUG MARKER: == sanity test 56xa: lfs migration --block support ======= 08:59:06 (1789390746) [13114.940855] Lustre: DEBUG MARKER: == sanity test 56xab: lfs migration --block on changing file ========================================================== 08:59:15 (1789390755) [13126.441904] Lustre: DEBUG MARKER: == sanity test 56xb: lfs migration hard link support ===== 08:59:26 (1789390766) [13346.349483] LustreError: 263841:0:(llite_lib.c:4170:ll_prep_md_op_data()) debug: Setting bias to MDS_CREATE_VOLATILE: . :VOLATILE:0001:3662ADF5:fd=03 [13346.356167] LustreError: 263841:0:(llite_lib.c:4170:ll_prep_md_op_data()) Skipped 55 previous similar messages [13346.360616] LustreError: 263841:0:(lmv_obd.c:1943:lmv_locate_tgt()) debug: handling volatile file... [13346.365386] LustreError: 263841:0:(lmv_obd.c:1943:lmv_locate_tgt()) Skipped 55 previous similar messages [13346.370898] LustreError: 263841:0:(mdc_lib.c:326:mdc_open_pack()) debug: create_volatile changes to mds_open_volatile [13346.376076] LustreError: 263841:0:(mdc_lib.c:326:mdc_open_pack()) Skipped 55 previous similar messages [13389.455047] LustreError: 266404:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [13389.471425] LustreError: 266404:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 26869 previous similar messages [13389.660711] LustreError: 266404:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x240002b11:0x117:0x0] suppgids 0 -1: rc 0 [13389.679241] LustreError: 266404:0:(namei.c:956:ll_intent_lock()) Skipped 21411 previous similar messages [13389.694629] LustreError: 266404:0:(dcache.c:176:ll_intent_release()) intent ffffae0bc8c77df8 released [13389.701020] LustreError: 266404:0:(dcache.c:176:ll_intent_release()) Skipped 5606 previous similar messages [13403.835678] Lustre: DEBUG MARKER: == sanity test 56xc: lfs migration autostripe ============ 09:04:04 (1789391044) [13404.184550] LustreError: 266992:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [13404.197154] LustreError: 266992:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 500 previous similar messages [13404.251454] LustreError: 266992:0:(namei.c:1721:ll_create_it()) VFS Op:name=20mb, dir=[0x200002b12:0x2774:0x0](ffff9b23864321c8), intent=open|creat [13404.258188] LustreError: 266992:0:(namei.c:1721:ll_create_it()) Skipped 287 previous similar messages [13404.263184] LustreError: 266992:0:(namei.c:1744:ll_create_it()) inode ffff9b23c1d99148 need_sync_to_mds [0x200002b12:0x2775:0x0] [13404.269541] LustreError: 266992:0:(namei.c:1744:ll_create_it()) Skipped 287 previous similar messages [13412.439641] Lustre: DEBUG MARKER: == sanity test 56xd: check lfs migrate --yaml and --copy support ========================================================== 09:04:12 (1789391052) [13429.383233] Lustre: DEBUG MARKER: == sanity test 56xe: migrate a composite layout file ===== 09:04:29 (1789391069) [13446.464526] Lustre: DEBUG MARKER: == sanity test 56xf: FID is not lost during migration of a composite layout file ========================================================== 09:04:46 (1789391086) [13456.698650] Lustre: DEBUG MARKER: == sanity test 56xg: lfs migrate pool support ============ 09:04:57 (1789391097) [13527.979786] Lustre: DEBUG MARKER: == sanity test 56xh: lfs migrate bandwidth limitation support ========================================================== 09:06:08 (1789391168) [13568.282289] Lustre: DEBUG MARKER: == sanity test 56xi: lfs migrate stats support =========== 09:06:48 (1789391208) [13582.252837] Lustre: DEBUG MARKER: == sanity test 56xj: lfs migrate -b should not cause starvation of threads on OSS ========================================================== 09:07:02 (1789391222) [13615.351568] LustreError: 273591:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [13615.359570] LustreError: 273591:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 939 previous similar messages [13624.821924] Lustre: DEBUG MARKER: == sanity test 56xk: lfs mirror resync bandwidth limitation support ========================================================== 09:07:45 (1789391265) [13625.633395] LustreError: 273752:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [13625.645403] LustreError: 273752:0:(file.c:977:ll_kernel_to_mds_open_flags()) Skipped 170 previous similar messages [13639.164180] Lustre: DEBUG MARKER: == sanity test 56xl: lfs mirror resync stats support ===== 09:07:59 (1789391279) [13649.278184] Lustre: DEBUG MARKER: == sanity test 56y: lfs find -L raid0|released =========== 09:08:09 (1789391289) [13649.538416] LustreError: 274939:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [13649.544683] LustreError: 274939:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 27 previous similar messages [13657.154705] Lustre: DEBUG MARKER: == sanity test 56z: lfs find should continue after an error ========================================================== 09:08:17 (1789391297) [13667.604968] Lustre: DEBUG MARKER: == sanity test 56Aa: lfs find --size under striped dir === 09:08:28 (1789391308) [13712.940397] Lustre: DEBUG MARKER: == sanity test 56ab: lfs find --blocks =================== 09:09:13 (1789391353) [13723.946216] Lustre: DEBUG MARKER: == sanity test 56aca: check lfs find -perm with octal representation ========================================================== 09:09:24 (1789391364) [13767.835872] Lustre: DEBUG MARKER: == sanity test 56acb: check lfs find -perm with symbolic representation ========================================================== 09:10:08 (1789391408) [13783.724935] Lustre: DEBUG MARKER: == sanity test 56acc: check parsing error for lfs find -perm ========================================================== 09:10:24 (1789391424) [13789.786873] Lustre: DEBUG MARKER: == sanity test 56Ba: test lfs find --component-end, -start, -count, and -flags ========================================================== 09:10:30 (1789391430) [13804.700781] Lustre: DEBUG MARKER: == sanity test 56Ca: check lfs find --mirror-count|-N and --mirror-state ========================================================== 09:10:45 (1789391445) [13815.780530] Lustre: DEBUG MARKER: == sanity test 56Da: test lfs find with long paths ======= 09:10:56 (1789391456) [13833.426227] Lustre: DEBUG MARKER: == sanity test 56Db: test 'lfs df -m' only shows MDT devices ========================================================== 09:11:13 (1789391473) [13840.053932] Lustre: DEBUG MARKER: == sanity test 56Dc: test 'lfs df -o' only shows OST devices ========================================================== 09:11:20 (1789391480) [13846.488792] Lustre: DEBUG MARKER: == sanity test 56Dd: test lfs find with mindepth argument ========================================================== 09:11:26 (1789391486) [13855.035440] Lustre: DEBUG MARKER: == sanity test 56Ea: test lfs find -printf option ======== 09:11:34 (1789391494) [13886.635100] Lustre: DEBUG MARKER: == sanity test 56Eaa: test lfs find -printf added functions ========================================================== 09:12:07 (1789391527) [13989.461511] LustreError: 285291:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [13989.470738] LustreError: 285291:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 46233 previous similar messages [13989.686695] LustreError: 285291:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 1 [13989.708333] LustreError: 285291:0:(namei.c:956:ll_intent_lock()) Skipped 26374 previous similar messages [13989.736094] LustreError: 285288:0:(dcache.c:176:ll_intent_release()) intent ffff9b23ab49d0c0 released [13989.741420] LustreError: 285288:0:(dcache.c:176:ll_intent_release()) Skipped 8396 previous similar messages [14004.256026] LustreError: 285288:0:(mdc_lib.c:329:mdc_open_pack()) debug: NOT!!! create_volatile changes to mds_open_volatile [14004.269730] LustreError: 285288:0:(mdc_lib.c:329:mdc_open_pack()) Skipped 6913 previous similar messages [14092.361525] Lustre: DEBUG MARKER: == sanity test 56Eab: test lfs find -ls function ========= 09:15:32 (1789391732) [14092.596997] LustreError: 286428:0:(namei.c:1721:ll_create_it()) VFS Op:name=f56Eab.sanity, dir=[0x200000007:0x1:0x0](ffff9b23b3f9ec08), intent=open|creat [14092.612458] LustreError: 286428:0:(namei.c:1721:ll_create_it()) Skipped 1353 previous similar messages [14092.624567] LustreError: 286428:0:(namei.c:1744:ll_create_it()) inode ffff9b238664a1c8 need_sync_to_mds [0x200002b12:0x2aa6:0x0] [14092.633512] LustreError: 286428:0:(namei.c:1744:ll_create_it()) Skipped 1353 previous similar messages [14119.138458] Lustre: DEBUG MARKER: == sanity test 56Eb: check lfs getstripe on symlink ====== 09:15:59 (1789391759) [14128.557449] Lustre: DEBUG MARKER: == sanity test 56Ebb: check /home/green/git/lustre-release/lustre/utils/lfs getdirstripe for FIFO file ========================================================== 09:16:08 (1789391768) [14136.018438] Lustre: DEBUG MARKER: == sanity test 56Ec: check lfs getstripe,setstripe --hex --yaml ========================================================== 09:16:16 (1789391776) [14145.234522] Lustre: DEBUG MARKER: == sanity test 56Ed: verify new YAML format is valid and back-compatible ========================================================== 09:16:24 (1789391784) [14173.888950] Lustre: DEBUG MARKER: == sanity test 56Eda: check lfs find --links ============= 09:16:53 (1789391813) [14182.511761] Lustre: DEBUG MARKER: == sanity test 56Edb: check lfs find --links for directory striped on multiple MDTs ========================================================== 09:17:02 (1789391822) [14189.778712] Lustre: DEBUG MARKER: == sanity test 56Ef: lfs find with multiple paths ======== 09:17:10 (1789391830) [14196.605421] Lustre: DEBUG MARKER: == sanity test 56Eg: lfs find -xattr ===================== 09:17:17 (1789391837) [14204.682436] Lustre: DEBUG MARKER: == sanity test 56Eh: check lfs find --skip =============== 09:17:25 (1789391845) [14239.315178] LustreError: 294359:0:(file.c:975:ll_kernel_to_mds_open_flags()) debug flags found................... [14239.325544] LustreError: 294359:0:(file.c:975:ll_kernel_to_mds_open_flags()) Skipped 1560 previous similar messages [14239.351467] LustreError: 294359:0:(file.c:977:ll_kernel_to_mds_open_flags()) debug flags not found................... [14239.363033] LustreError: 294359:0:(file.c:977:ll_kernel_to_mds_open_flags()) Skipped 2193 previous similar messages [14253.192326] Lustre: DEBUG MARKER: == sanity test 56Ei: test lfs find --printf prints correct projid for special files ========================================================== 09:18:13 (1789391893) [14253.412769] LustreError: 295641:0:(mdc_lib.c:221:mdc_create_pack()) debug1: NOT!!! create_volatile changes to mds_open_volatile [14253.423414] LustreError: 295641:0:(mdc_lib.c:221:mdc_create_pack()) Skipped 1252 previous similar messages [14260.883730] Lustre: DEBUG MARKER: == sanity test 56Ej: lfs migration --non-block copy ====== 09:18:21 (1789391901) [14261.621182] LustreError: 296263:0:(llite_lib.c:4170:ll_prep_md_op_data()) debug: Setting bias to MDS_CREATE_VOLATILE: . :VOLATILE:0001:3989D97B:fd=03 [14261.630759] LustreError: 296263:0:(llite_lib.c:4170:ll_prep_md_op_data()) Skipped 202 previous similar messages [14261.637128] LustreError: 296263:0:(lmv_obd.c:1943:lmv_locate_tgt()) debug: handling volatile file... [14261.641493] LustreError: 296263:0:(lmv_obd.c:1943:lmv_locate_tgt()) Skipped 202 previous similar messages [14261.647558] LustreError: 296263:0:(mdc_lib.c:326:mdc_open_pack()) debug: create_volatile changes to mds_open_volatile [14261.655077] LustreError: 296263:0:(mdc_lib.c:326:mdc_open_pack()) Skipped 202 previous similar messages [14268.264587] Lustre: DEBUG MARKER: == sanity test 56Ek: Test lfs find error handling with LLAPI_FAIL_LOC ========================================================== 09:18:28 (1789391908) [14277.723545] Lustre: DEBUG MARKER: == sanity test 57a: verify MDS filesystem created with large inodes ============================================================ 09:18:38 (1789391918) [14288.287333] Lustre: DEBUG MARKER: == sanity test 57b: default LOV EAs are stored inside large inodes ============================================================= 09:18:48 (1789391928) [14306.611890] Lustre: DEBUG MARKER: == sanity test 58: verify cross-platform wire constants ======================================================================== 09:19:07 (1789391947) [14313.089886] Lustre: DEBUG MARKER: == sanity test 59: verify cancellation of llog records async =================================================================== 09:19:13 (1789391953) [14368.480735] Lustre: DEBUG MARKER: == sanity test complete, duration 14029 sec ============== 09:20:07 (1789392007) [14370.929322] Lustre: DEBUG MARKER: === sanity: start cleanup 09:20:10 (1789392010) === [14549.436761] Lustre: DEBUG MARKER: === sanity: finish cleanup 09:23:09 (1789392189) === [14552.571963] Lustre: lustre-MDT0000-mdc-ffff9b238520e800: Connection to lustre-MDT0000 (at 192.168.203.126@tcp) was lost; in progress operations using this service will wait for recovery to complete [14568.929247] Lustre: 2404:0:(client.c:2504:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1789392194/real 1789392194] req@ffff9b23aee8e680 x1876298716296064/t0(0) o400->MGC192.168.203.126@tcp@192.168.203.126@tcp:26/25 lens 224/224 e 0 to 1 dl 1789392210 ref 1 fl Rpc:XNQr/200/ffffffff rc 0/-1 job:'kworker.0' uid:0 gid:0 projid:4294967295 [14568.981580] LustreError: MGC192.168.203.126@tcp: Connection to MGS (at 192.168.203.126@tcp) was lost; in progress operations using this service will fail [14588.463786] Lustre: lustre-MDT0000-mdc-ffff9b238520e800: Connection restored to 192.168.203.126@tcp (at 192.168.203.126@tcp) [14592.500658] LustreError: 302438:0:(llite_lib.c:4173:ll_prep_md_op_data()) debug: not match filename_is_volatile or other error [NULL] [14592.511232] LustreError: 302438:0:(llite_lib.c:4173:ll_prep_md_op_data()) Skipped 46776 previous similar messages [14592.539750] LustreError: 302438:0:(namei.c:956:ll_intent_lock()) intent lock 8 on i1 [0x200000007:0x1:0x0] suppgids 0 0: rc 0 [14592.550677] LustreError: 302438:0:(namei.c:956:ll_intent_lock()) Skipped 25246 previous similar messages [14593.655488] Lustre: Evicted from MGS (at 192.168.203.126@tcp) after server handle changed from 0xc50e9934a5136342 to 0xc50e9934a58fcd5e [14593.669513] Lustre: MGC192.168.203.126@tcp: Connection restored to 192.168.203.126@tcp (at 192.168.203.126@tcp) [14597.941876] Lustre: DEBUG MARKER: oleg326-client.virtnet: executing wait_import_state_mount (FULL|IDLE) mdc.lustre-MDT0000-mdc-*.mds_server_uuid 1475 0 [14599.783810] Lustre: DEBUG MARKER: mdc.lustre-MDT0000-mdc-*.mds_server_uuid in FULL state after 0 sec [14603.698501] Lustre: Unmounted lustre-client [14662.615177] Key type lgssc unregistered [14662.937575] LNet: 303632:0:(lib-ptl.c:964:lnet_clear_lazy_portal()) Active lazy portal 0 on exit [14662.942905] LNetError: 303632:0:(acceptor.c:252:lnet_acceptor_remove_socket()) Interface ens2 not found [14662.955564] LNet: Removed LNI 192.168.203.26@tcp [14664.323282] Key type .llcrypt unregistered [14664.332944] Key type ._llcrypt unregistered