2014-06-15 07:13:24

by Jet Chen

[permalink] [raw]
Subject: [random] BUG: spinlock trylock failure on UP on CPU#0, swapper/1

Hi Greg,

0day kernel testing robot got the below dmesg and the first bad commit is

git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git master
commit 0fb7a01af5b0cbe5bf365891fc4d186f2caa23f7
Author: Greg Price <[email protected]>
AuthorDate: Thu Dec 5 19:32:19 2013 -0500
Commit: Theodore Ts'o <[email protected]>
CommitDate: Wed Mar 19 22:18:51 2014 -0400

random: simplify accounting code
With this we handle "reserved" in just one place. As a bonus the
code becomes less nested, and the "wakeup_write" flag variable
becomes unnecessary. The variable "flags" was already unused.
This code behaves identically to the previous version except in
two pathological cases that don't occur. If the argument "nbytes"
is already less than "min", then we didn't previously enforce
"min". If r->limit is false while "reserved" is nonzero, then we
previously applied "reserved" in checking whether we had enough
bits, even though we don't apply it to actually limit how many we
take. The callers of account() never exercise either of these cases.
Before the previous commit, it was possible for "nbytes" to be less
than "min" if userspace chose a pathological configuration, but no
longer.
Cc: Jiri Kosina <[email protected]>
Cc: "H. Peter Anvin" <[email protected]>
Signed-off-by: Greg Price <[email protected]>
Signed-off-by: "Theodore Ts'o" <[email protected]>

+-------------------------------------------+------------+------------+
| | 8c2aa3390e | 0fb7a01af5 |
+-------------------------------------------+------------+------------+
| boot_successes | 66 | 2 |
| boot_failures | 0 | 20 |
| BUG:spinlock_trylock_failure_on_UP_on_CPU | 0 | 20 |
| backtrace:prandom_reseed | 0 | 11 |
| backtrace:kernel_init_freeable | 0 | 11 |
+-------------------------------------------+------------+------------+

[ 374.075477] raid6test: test_disks(62, 63): faila= 62(P) failb= 63(Q) OK
[ 374.192518] raid6test: [ 374.312137] raid6test: complete (2429 tests, 0 failures)
[ 374.434548] BUG: spinlock trylock failure on UP on CPU#0, swapper/1
[ 374.444114] lock: lock.13830+0x0/0x50, .magic: dead4ead, .owner: swapper/1, .owner_cpu: 0
[ 374.444114] CPU: 0 PID: 1 Comm: swapper Not tainted 3.14.0-rc2-00009-g0fb7a01 #1
[ 374.444114] Hardware name: Bochs Bochs, BIOS Bochs 01/01/2011
[ 374.444114] 0000000000000000 ffff88001386fc28 ffffffff81ec8af8 ffff88001386fc48
[ 374.444114] ffffffff81ec26d9 0000000000000000 ffffffff827db7a0 ffff88001386fc68
[ 374.444114] ffffffff81ec2704 ffffffff827db7a0 ffffffff823b74f3 ffff88001386fc80
[ 374.444114] Call Trace:
[ 374.444114] [<ffffffff81ec8af8>] dump_stack+0x19/0x1b
[ 374.444114] [<ffffffff81ec26d9>] spin_dump+0x85/0x8a
[ 374.444114] [<ffffffff81ec2704>] spin_bug+0x26/0x28
[ 374.444114] [<ffffffff810ae690>] do_raw_spin_trylock+0x37/0x3c
[ 374.444114] [<ffffffff81ed707b>] _raw_spin_lock_irqsave+0x4b/0x7a
[ 374.444114] [<ffffffff814f5f69>] ? __prandom_reseed+0x1a/0xad
[ 374.444114] [<ffffffff814f5f69>] __prandom_reseed+0x1a/0xad
[ 374.444114] [<ffffffff814f6183>] prandom_reseed_late+0xe/0x10
[ 374.444114] [<ffffffff8162f31c>] credit_entropy_bits+0x116/0x21e
[ 374.444114] [<ffffffff8162f8d9>] _xfer_secondary_pool+0x86/0x8f
[ 374.444114] [<ffffffff810abe66>] ? __lock_acquire.isra.20+0x4cf/0x5cd
[ 374.444114] [<ffffffff8162f963>] xfer_secondary_pool+0x5d/0x5f
[ 374.444114] [<ffffffff8162fa0a>] extract_entropy+0xa5/0x16b
[ 374.444114] [<ffffffff816301cc>] get_random_bytes+0x1b/0x1d
[ 374.444114] [<ffffffff814f5f8f>] __prandom_reseed+0x40/0xad
[ 374.444114] [<ffffffff810e7b32>] ? put_page+0x20/0x22
[ 374.444114] [<ffffffff8295f922>] ? radix_tree_init+0xce/0xce
[ 374.444114] [<ffffffff8295f92e>] prandom_reseed+0xc/0x49
[ 374.444114] [<ffffffff8295f922>] ? radix_tree_init+0xce/0xce
[ 374.444114] [<ffffffff8293ae11>] do_one_initcall+0x7d/0x108
[ 374.444114] [<ffffffff81098f9c>] ? parse_args+0x180/0x246
[ 374.444114] [<ffffffff8293af92>] kernel_init_freeable+0xf6/0x187
[ 374.444114] [<ffffffff8293a70e>] ? do_early_param+0x8a/0x8a
[ 374.444114] [<ffffffff81ebe658>] ? rest_init+0xbc/0xbc
[ 374.444114] [<ffffffff81ebe661>] kernel_init+0x9/0xd0
[ 374.444114] [<ffffffff81ed850a>] ret_from_fork+0x7a/0xb0
[ 374.444114] [<ffffffff81ebe658>] ? rest_init+0xbc/0xbc

Elapsed time: 380
qemu-system-x86_64 -cpu kvm64 -enable-kvm -kernel /kernel/x86_64-randconfig-hsxa1-06150953/0fb7a01af5b0cbe5bf365891fc4d186f2caa23f7/vmlinuz-3.14.0-rc2-00009-g0fb7a01 -append 'hung_task_panic=1 earlyprintk=ttyS0,115200 debug apic=debug sysrq_always_enabled rcupdate.rcu_cpu_stall_timeout=100 panic=10 softlockup_panic=1 nmi_watchdog=panic prompt_ramdisk=0 console=ttyS0,115200 console=tty0 vga=normal root=/dev/ram0 rw link=/kbuild-tests/run-queue/kvm/x86_64-randconfig-hsxa1-06150953/linux-devel:devel-hourly-2014061509:0fb7a01af5b0cbe5bf365891fc4d186f2caa23f7:bisect-linux3/.vmlinuz-0fb7a01af5b0cbe5bf365891fc4d186f2caa23f7-20140615135429-17-ivb41 branch=linux-devel/devel-hourly-2014061509 BOOT_IMAGE=/kernel/x86_64-randconfig-hsxa1-06150953/0fb7a01af5b0cbe5bf365891fc4d186f2caa23f7/vmlinuz-3.14.0-rc2-00009-g0fb7a01 drbd.minor_count=8' -initrd /kernel-tests/initrd/yocto-minimal-x86_64.cgz -m 320 -smp 2 -net nic,vlan=1,model=e1000 -net user,vlan=1 -boot order=nc -no-reboot -watchdog i6300esb

-rtc base=localtime -pidfile /dev/shm/kboot/pid-yocto-ivb41-47 -serial file:/dev/shm/kboot/serial-yocto-ivb41-47 -daemonize -display none -monitor null

git bisect start v3.15 v3.14 --
git bisect bad 674366e90e5a2430e3ddef40ce51512d681944e4 # 10:49 0- 3 Merge tag 'pci-v3.15-fixes-1' of git://git.kernel.org/pub/scm/linux/kernel/git/helgaas/pci
git bisect bad 9f800363bb0ea459e15bef0928a72c88d374e489 # 11:28 2- 14 Merge tag 'fixes-non-critical-3.15' of git://git.kernel.org/pub/scm/linux/kernel/git/arm/arm-soc
git bisect good 1aabc5990d205cdb0789a1c26143c53601e9bb07 # 11:38 21+ 0 x86: Fix dumpstack_64 to keep state of "used" variable in loop
git bisect good d0cb5f71c5cde8e1ef6d03983641366800ceabdb # 11:51 21+ 0 Merge tag 'vfio-v3.15-rc1' of git://github.com/awilliam/linux-vfio
git bisect good d15fee814d8d30bbb4859ef8fef7a1f96327635b # 12:07 21+ 0 Merge branch 'for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/mszeredi/fuse
git bisect bad d1d9cfc330e2622f4b4e0b82d3b41a34619614d4 # 12:16 1- 8 Merge tag 'random_for_linus' of git://git.kernel.org/pub/scm/linux/kernel/git/tytso/random
git bisect good 24e7ea3bea94fe05eae5019f5f12bcdc98fc5157 # 12:27 21+ 0 Merge tag 'ext4_for_linus' of git://git.kernel.org/pub/scm/linux/kernel/git/tytso/ext4
git bisect good d15e03104eb9a4f8e244ab6ed3ca5a107e46db13 # 12:40 21+ 0 Merge tag 'xfs-for-linus-3.15-rc1' of git://oss.sgi.com/xfs/xfs
git bisect good cda540ace6a194850e23c79955cc2e46fd91c19a # 13:15 21+ 0 mm: get_user_pages(write,force) refuse to COW in shared areas
git bisect good 8c2aa3390ebb59cba4495a56557b70ad0575eef5 # 13:34 21+ 0 random: tighten bound on random_read_wakeup_thresh
git bisect bad 46884442fc5bb81a896f7245bd850fde9b435509 # 13:44 0- 2 random: use the architectural HWRNG for the SHA's IV in extract_buf()
git bisect bad 7d1b08c40c4f02c119476b29eca9bbc8d98d2a83 # 13:52 2- 9 random: entropy_bytes is actually bits
git bisect bad 0fb7a01af5b0cbe5bf365891fc4d186f2caa23f7 # 14:01 0- 5 random: simplify accounting code
# first bad commit: [0fb7a01af5b0cbe5bf365891fc4d186f2caa23f7] random: simplify accounting code
git bisect good 8c2aa3390ebb59cba4495a56557b70ad0575eef5 # 14:11 66+ 0 random: tighten bound on random_read_wakeup_thresh
git bisect bad 1d08ab37636d6a169c67e879cba37675cd82e6ac # 14:11 0- 11 0day head guard for 'devel-hourly-2014061509'
git bisect bad abf04af74a9f27a65172a43b43ccabcbc2bbdc39 # 14:27 3- 2 Merge tag 'scsi-for-linus' of git://git.kernel.org/pub/scm/linux/kernel/git/jejb/scsi
git bisect bad f9801c532e045c1ab89801d0597353c5e2a55671 # 14:41 5- 8 Add linux-next specific files for 20140613


This script may reproduce the error.

-----------------------------------------------------------------------------
#!/bin/bash

kernel=$1
initrd=yocto-minimal-x86_64.cgz

wget --no-clobber https://github.com/fengguang/reproduce-kernel-bug/blob/master/initrd/$initrd

kvm=(
qemu-system-x86_64 -cpu kvm64 -enable-kvm
-kernel $kernel
-initrd $initrd
-smp 2
-m 256M
-net nic,vlan=0,macaddr=00:00:00:00:00:00,model=virtio
-net user,vlan=0
-net nic,vlan=1,model=e1000
-net user,vlan=1
-boot order=nc
-no-reboot
-watchdog i6300esb
-serial stdio
-display none
-monitor null
)

append=(
debug
sched_debug
apic=debug
ignore_loglevel
sysrq_always_enabled
panic=10
prompt_ramdisk=0
earlyprintk=ttyS0,115200
console=ttyS0,115200
console=tty0
vga=normal
root=/dev/ram0
rw
)

"${kvm[@]}" --append "${append[*]}"
-----------------------------------------------------------------------------

Thanks,
Jet


Attachments:
dmesg-yocto-ivb41-47:20140615140105:x86_64-randconfig-hsxa1-06150953:3.14.0-rc2-00009-g0fb7a01:1 (239.26 kB)
x86_64-randconfig-hsxa1-06150953-1d08ab37636d6a169c67e879cba37675cd82e6ac-BUG:-spinlock-trylock-failure-on-UP-on-CPU---16957.log (67.11 kB)
config-3.14.0-rc2-00009-g0fb7a01 (84.46 kB)
Attached Message Part (86.00 B)
Download all attachments

2014-06-16 01:44:22

by Theodore Ts'o

[permalink] [raw]
Subject: Re: [random] BUG: spinlock trylock failure on UP on CPU#0, swapper/1

On Sun, Jun 15, 2014 at 03:12:54PM +0800, Jet Chen wrote:
> Hi Greg,
>
> 0day kernel testing robot got the below dmesg and the first bad commit is
>
> git://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git master
> commit 0fb7a01af5b0cbe5bf365891fc4d186f2caa23f7
> Author: Greg Price <[email protected]>
> AuthorDate: Thu Dec 5 19:32:19 2013 -0500
>
> random: simplify accounting code

I believe I've found the problem, thanks for the report!

There was an earlier warning when this was in the random.git tree, but
I analyzed the bug report incorrectly and thought it was due to a bug
in lib/random32.c that would only show up in testing. My bad for not
seeing the problem earlier.

The patch will be chained to this reply and sent to LKML.

- Ted

2014-06-16 01:47:51

by Theodore Ts'o

[permalink] [raw]
Subject: [PATCH] random: fix nasty entropy accounting bug

Commit 0fb7a01af5b0 "random: simplify accounting code", introduced in
v3.15, has a very nasty accounting problem when the entropy pool has
has fewer bytes of entropy than the number of requested reserved
bytes. In that case, "have_bytes - reserved" goes negative, and since
size_t is unsigned, the expression:

ibytes = min_t(size_t, ibytes, have_bytes - reserved);

... does not do the right thing. This is rather bad, because it
defeats the catastrophic reseeding feature in the
xfer_secondary_pool() path.

It also can cause the "BUG: spinlock trylock failure on UP" for some
kernel configurations when prandom_reseed() calls get_random_bytes()
in the early init, since when the entropy count gets corrupted,
credit_entropy_bits() erroneously believes that the nonblocking pool
has been fully initialized (when in fact it is not), and so it calls
prandom_reseed(true) recursively leading to the spinlock BUG.

The logic is *not* the same it was originally, but in the cases where
it matters, the behavior is the same, and the resulting code is
hopefully easier to read and understand.

Fixes: 0fb7a01af5b0 "random: simplify accounting code"
Signed-off-by: Theodore Ts'o <[email protected]>
Cc: Greg Price <[email protected]>
Cc: [email protected] #v3.15
---
drivers/char/random.c | 17 +++++++++--------
1 file changed, 9 insertions(+), 8 deletions(-)

diff --git a/drivers/char/random.c b/drivers/char/random.c
index 102c50d..2b6e4cd 100644
--- a/drivers/char/random.c
+++ b/drivers/char/random.c
@@ -979,7 +979,6 @@ static void push_to_pool(struct work_struct *work)
static size_t account(struct entropy_store *r, size_t nbytes, int min,
int reserved)
{
- int have_bytes;
int entropy_count, orig;
size_t ibytes;

@@ -988,17 +987,19 @@ static size_t account(struct entropy_store *r, size_t nbytes, int min,
/* Can we pull enough? */
retry:
entropy_count = orig = ACCESS_ONCE(r->entropy_count);
- have_bytes = entropy_count >> (ENTROPY_SHIFT + 3);
ibytes = nbytes;
/* If limited, never pull more than available */
- if (r->limit)
- ibytes = min_t(size_t, ibytes, have_bytes - reserved);
+ if (r->limit) {
+ int have_bytes = entropy_count >> (ENTROPY_SHIFT + 3);
+
+ if ((have_bytes -= reserved) < 0)
+ have_bytes = 0;
+ ibytes = min_t(size_t, ibytes, have_bytes);
+ }
if (ibytes < min)
ibytes = 0;
- if (have_bytes >= ibytes + reserved)
- entropy_count -= ibytes << (ENTROPY_SHIFT + 3);
- else
- entropy_count = reserved << (ENTROPY_SHIFT + 3);
+ if ((entropy_count -= ibytes << (ENTROPY_SHIFT + 3)) < 0)
+ entropy_count = 0;

if (cmpxchg(&r->entropy_count, orig, entropy_count) != orig)
goto retry;
--
2.0.0