| lists.openwall.net | lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC | |
|
Open Source and information security mailing list archives
| ||
|
Date: Sun, 19 Jul 2020 19:48:45 -0400
From: Waiman Long <longman@...hat.com>
To: kernel test robot <lkp@...el.com>
Cc: Peter Zijlstra <peterz@...radead.org>,
Ingo Molnar <mingo@...hat.com>,
Will Deacon <will.deacon@....com>,
Thomas Gleixner <tglx@...utronix.de>,
Borislav Petkov <bp@...en8.de>, Arnd Bergmann <arnd@...db.de>,
linux-kernel@...r.kernel.org, x86@...nel.org,
linux-arch@...r.kernel.org, Nicholas Piggin <npiggin@...il.com>,
Davidlohr Bueso <dave@...olabs.net>, lkp@...ts.01.org
Subject: Re: [locking/qspinlock] 45877ea393:
BUG:spinlock_already_unlocked_on_CPU
On 7/17/20 3:39 AM, kernel test robot wrote:
> Greeting,
>
> FYI, we noticed the following commit (built with gcc-9):
>
> commit: 45877ea3934b977dd4fd9fa8b4b7e9a2a8925d38 ("[PATCH v2 4/5] locking/qspinlock: Make qspinhlock store lock holder cpu number")
> url: https://github.com/0day-ci/linux/commits/Waiman-Long/x86-locking-qspinlock-Allow-lock-to-store-lock-holder-cpu-number/20200717-033319
> base: https://git.kernel.org/cgit/linux/kernel/git/tip/tip.git f9ad4a5f3f20bee022b1bdde94e5ece6dc0b0edc
>
> in testcase: trinity
> with following parameters:
>
> runtime: 300s
>
> test-description: Trinity is a linux system call fuzz tester.
> test-url: http://codemonkey.org.uk/projects/trinity/
>
>
> on test machine: qemu-system-x86_64 -enable-kvm -cpu SandyBridge -smp 2 -m 16G
>
> caused below changes (please refer to attached dmesg/kmsg for entire log/backtrace):
>
>
> +--------------------------------------+------------+------------+
> | | a104f8329b | 45877ea393 |
> +--------------------------------------+------------+------------+
> | boot_successes | 6 | 0 |
> | boot_failures | 0 | 8 |
> | BUG:spinlock_already_unlocked_on_CPU | 0 | 8 |
> +--------------------------------------+------------+------------+
>
>
> If you fix the issue, kindly add following tag
> Reported-by: kernel test robot <lkp@...el.com>
>
>
> [ 0.174207] BUG: spinlock already unlocked on CPU#0, swapper/0
> [ 0.174208] lock: logbuf_lock+0x0/0x40, .magic: dead4ead, .owner: swapper/0, .owner_cpu: 0
> [ 0.174209] CPU: 0 PID: 0 Comm: swapper Not tainted 5.8.0-rc4-00016-g45877ea3934b9 #1
> [ 0.174210] Call Trace:
> [ 0.174210] ? dump_stack+0x96/0xd0
> [ 0.174211] ? do_raw_spin_unlock+0x81/0xc0
> [ 0.174211] ? _raw_spin_unlock+0x1f/0x40
> [ 0.174212] ? vprintk_emit+0x141/0x370
> [ 0.174212] ? printk+0x58/0x6f
> [ 0.174213] ? start_kernel+0x60/0x664
> [ 0.174213] ? x86_family+0x5/0x20
> [ 0.174214] ? secondary_startup_64+0xb6/0xc0
> [ 0.174215] BUG: spinlock already unlocked on CPU#0, swapper/0
> [ 0.174216] lock: logbuf_lock+0x0/0x40, .magic: dead4ead, .owner: swapper/0, .owner_cpu: 0
> [ 0.174217] CPU: 0 PID: 0 Comm: swapper Not tainted 5.8.0-rc4-00016-g45877ea3934b9 #1
> [ 0.174217] Call Trace:
> [ 0.174218] ? dump_stack+0x96/0xd0
> [ 0.174218] ? do_raw_spin_unlock+0x81/0xc0
> [ 0.174219] ? _raw_spin_unlock+0x1f/0x40
> [ 0.174219] ? vprintk_emit+0x141/0x370
> [ 0.174220] ? printk+0x58/0x6f
> [ 0.174220] ? start_kernel+0x60/0x664
> [ 0.174221] ? x86_family+0x5/0x20
> [ 0.174222] ? secondary_startup_64+0xb6/0xc0
> [ 0.179324] Dentry cache hash table entries: 2097152 (order: 12, 16777216 bytes, linear)
> [ 0.203325] Inode-cache hash table entries: 1048576 (order: 11, 8388608 bytes, linear)
> [ 0.204873] mem auto-init: stack:off, heap alloc:off, heap free:off
> [ 0.303179] Memory: 2330956K/16776640K available (16390K kernel code, 3578K rwdata, 9300K rodata, 2508K init, 17536K bss, 1290512K reserved, 0K cma-reserved)
> [ 0.306358] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=2, Nodes=1
> [ 0.307555] Kernel/User page tables isolation: enabled
> [ 0.308477] ftrace: allocating 49199 entries in 193 pages
> [ 0.334062] ftrace: allocated 193 pages with 3 groups
> [ 0.335730] Running RCU self tests
> [ 0.336314] rcu: Preemptible hierarchical RCU implementation.
> [ 0.337275] rcu: RCU lockdep checking is enabled.
> [ 0.338117] rcu: RCU restricting CPUs from NR_CPUS=8192 to nr_cpu_ids=2.
> [ 0.339252] RCU CPU stall warnings timeout set to 100 (rcu_cpu_stall_timeout).
> [ 0.340525] Trampoline variant of Tasks RCU enabled.
> [ 0.341420] Rude variant of Tasks RCU enabled.
> [ 0.342120] rcu: RCU calculated value of scheduler-enlistment delay is 100 jiffies.
> [ 0.343410] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=2
> [ 0.350046] NR_IRQS: 524544, nr_irqs: 440, preallocated irqs: 16
> [ 0.351568] random: get_random_bytes called from start_kernel+0x47c/0x664 with crng_init=0
> [ 0.360133] Console: colour VGA+ 80x25
> [ 0.488053] printk: console [tty0] enabled
> [ 0.489397] printk: console [ttyS0] enabled
> [ 0.491484] printk: bootconsole [earlyser0] disabled
> [ 0.493957] Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo Molnar
> [ 0.496330] ... MAX_LOCKDEP_SUBCLASSES: 8
> [ 0.497667] ... MAX_LOCK_DEPTH: 48
> [ 0.498992] ... MAX_LOCKDEP_KEYS: 8192
> [ 0.500345] ... CLASSHASH_SIZE: 4096
> [ 0.501709] ... MAX_LOCKDEP_ENTRIES: 32768
> [ 0.502983] ... MAX_LOCKDEP_CHAINS: 65536
> [ 0.504225] ... CHAINHASH_SIZE: 32768
> [ 0.505597] memory used by lock dependency info: 6301 kB
> [ 0.507170] memory used for stack traces: 4224 kB
> [ 0.508622] per task-struct memory footprint: 1920 bytes
> [ 0.510320] ACPI: Core revision 20200528
> [ 0.511870] clocksource: hpet: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604467 ns
> [ 0.514831] APIC: Switch to symmetric I/O mode setup
> [ 0.516572] x2apic enabled
> [ 0.517835] Switched APIC routing to physical x2apic.
> [ 0.519267] masked ExtINT on CPU#0
> [ 0.521620] ENABLING IO-APIC IRQs
> [ 0.522862] init IO_APIC IRQs
> [ 0.523904] apic 0 pin 0 not connected
> [ 0.525142] IOAPIC[0]: Set routing entry (0-1 -> 0xef -> IRQ 1 Mode:0 Active:0 Dest:0)
> [ 0.527588] IOAPIC[0]: Set routing entry (0-2 -> 0x30 -> IRQ 0 Mode:0 Active:0 Dest:0)
> [ 0.530160] IOAPIC[0]: Set routing entry (0-3 -> 0xef -> IRQ 3 Mode:0 Active:0 Dest:0)
> [ 0.532595] IOAPIC[0]: Set routing entry (0-4 -> 0xef -> IRQ 4 Mode:0 Active:0 Dest:0)
> [ 0.535040] IOAPIC[0]: Set routing entry (0-5 -> 0xef -> IRQ 5 Mode:1 Active:0 Dest:0)
> [ 0.537473] IOAPIC[0]: Set routing entry (0-6 -> 0xef -> IRQ 6 Mode:0 Active:0 Dest:0)
> [ 0.539907] IOAPIC[0]: Set routing entry (0-7 -> 0xef -> IRQ 7 Mode:0 Active:0 Dest:0)
> [ 0.542375] IOAPIC[0]: Set routing entry (0-8 -> 0xef -> IRQ 8 Mode:0 Active:0 Dest:0)
> [ 0.544872] IOAPIC[0]: Set routing entry (0-9 -> 0xef -> IRQ 9 Mode:1 Active:0 Dest:0)
> [ 0.547321] IOAPIC[0]: Set routing entry (0-10 -> 0xef -> IRQ 10 Mode:1 Active:0 Dest:0)
> [ 0.549764] IOAPIC[0]: Set routing entry (0-11 -> 0xef -> IRQ 11 Mode:1 Active:0 Dest:0)
> [ 0.552139] IOAPIC[0]: Set routing entry (0-12 -> 0xef -> IRQ 12 Mode:0 Active:0 Dest:0)
> [ 0.554509] IOAPIC[0]: Set routing entry (0-13 -> 0xef -> IRQ 13 Mode:0 Active:0 Dest:0)
> [ 0.556877] IOAPIC[0]: Set routing entry (0-14 -> 0xef -> IRQ 14 Mode:0 Active:0 Dest:0)
> [ 0.559407] IOAPIC[0]: Set routing entry (0-15 -> 0xef -> IRQ 15 Mode:0 Active:0 Dest:0)
> [ 0.561851] apic 0 pin 16 not connected
> [ 0.563100] apic 0 pin 17 not connected
> [ 0.564382] apic 0 pin 18 not connected
> [ 0.565667] apic 0 pin 19 not connected
> [ 0.566978] apic 0 pin 20 not connected
> [ 0.568223] apic 0 pin 21 not connected
> [ 0.569546] apic 0 pin 22 not connected
> [ 0.574439] apic 0 pin 23 not connected
> [ 0.575852] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1
> [ 0.577696] clocksource: tsc-early: mask: 0xffffffffffffffff max_cycles: 0x26d349e8249, max_idle_ns: 440795288087 ns
> [ 0.580936] Calibrating delay loop (skipped) preset value.. 5387.01 BogoMIPS (lpj=2693508)
> [ 0.581945] pid_max: default: 32768 minimum: 301
> [ 0.583003] LSM: Security Framework initializing
> [ 0.583943] Yama: becoming mindful.
> [ 0.585038] Mount-cache hash table entries: 32768 (order: 6, 262144 bytes, linear)
> [ 0.586506] Mountpoint-cache hash table entries: 32768 (order: 6, 262144 bytes, linear)
> Poking KASLR using RDTSC...
> [ 0.589007] Last level iTLB entries: 4KB 0, 2MB 0, 4MB 0
> [ 0.589936] Last level dTLB entries: 4KB 0, 2MB 0, 4MB 0, 1GB 0
> [ 0.590943] Spectre V1 : Mitigation: usercopy/swapgs barriers and __user pointer sanitization
> [ 0.591952] Spectre V2 : Mitigation: Full generic retpoline
> [ 0.592937] Spectre V2 : Spectre v2 / SpectreRSB mitigation: Filling RSB on context switch
> [ 0.593941] Speculative Store Bypass: Vulnerable
> [ 0.594944] MDS: Vulnerable: Clear CPU buffers attempted, no microcode
> [ 0.597034] Freeing SMP alternatives memory: 40K
> [ 0.600063] smpboot: CPU0: Intel Xeon E312xx (Sandy Bridge) (family: 0x6, model: 0x2a, stepping: 0x1)
> [ 0.601429] Performance Events: unsupported p6 CPU model 42 no PMU driver, software events only.
> [ 0.602098] rcu: Hierarchical SRCU implementation.
> [ 0.604237] NMI watchdog: Perf NMI watchdog permanently disabled
> [ 0.605187] smp: Bringing up secondary CPUs ...
> [ 0.606363] x86: Booting SMP configuration:
>
>
> To reproduce:
>
> # build kernel
> cd linux
> cp config-5.8.0-rc4-00016-g45877ea3934b9 .config
> make HOSTCC=gcc-9 CC=gcc-9 ARCH=x86_64 olddefconfig prepare modules_prepare bzImage
>
> git clone https://github.com/intel/lkp-tests.git
> cd lkp-tests
> bin/lkp qemu -k <bzImage> job-script # job-script is attached in this email
>
>
>
> Thanks,
> lkp
>
Thanks for the test. The first locking call is earlier than I expected.
There is a simple fix for that and I will put that in the next v3 patch.
Cheers,
Longman
Powered by blists - more mailing lists