syzbot


inconsistent lock state in _synchronize_rcu_expedited

Status: auto-closed as invalid on 2019/02/24 16:29
First crash: 2374d, last: 2277d

Sample crash report:
=================================
[ INFO: inconsistent lock state ]
IPVS: stopping master sync thread 25198 ...
4.9.111-g03c70fe #58 Not tainted
---------------------------------
inconsistent {SOFTIRQ-ON-W} -> {IN-SOFTIRQ-W} usage.
ksoftirqd/0/3 [HC0[0]:SC1[1]:HE1:SE0] takes:
IPVS: stopping master sync thread 25201 ...
 (&(&rnp->exp_lock)->rlock){+.?...}, at: [<ffffffff812829ab>] spin_lock include/linux/spinlock.h:302 [inline]
 (&(&rnp->exp_lock)->rlock){+.?...}, at: [<ffffffff812829ab>] exp_funnel_lock kernel/rcu/tree_exp.h:271 [inline]
 (&(&rnp->exp_lock)->rlock){+.?...}, at: [<ffffffff812829ab>] _synchronize_rcu_expedited+0x1fb/0x840 kernel/rcu/tree_exp.h:569
IPVS: stopping master sync thread 25205 ...
{SOFTIRQ-ON-W} state was registered at:
  mark_irqflags kernel/locking/lockdep.c:2941 [inline]
  __lock_acquire+0xdd0/0x4070 kernel/locking/lockdep.c:3302
  lock_acquire+0x130/0x3e0 kernel/locking/lockdep.c:3756
  __raw_spin_lock include/linux/spinlock_api_smp.h:144 [inline]
  _raw_spin_lock+0x36/0x50 kernel/locking/spinlock.c:151
  spin_lock include/linux/spinlock.h:302 [inline]
  rcu_exp_wait_wake+0x2d2/0x5e0 kernel/rcu/tree_exp.h:504
  rcu_exp_sel_wait_wake kernel/rcu/tree_exp.h:535 [inline]
  _synchronize_rcu_expedited+0x73c/0x840 kernel/rcu/tree_exp.h:575
  synchronize_rcu_expedited kernel/rcu/tree_exp.h:687 [inline]
  synchronize_rcu.part.62+0xd3/0x110 kernel/rcu/tree_plugin.h:682
  synchronize_rcu+0x27/0x90 kernel/rcu/tree_plugin.h:685
  rcu_test_sync_prims+0x9/0x30 kernel/rcu/update.c:829
  rcu_scheduler_starting+0x51/0x80 kernel/rcu/tree.c:4016
  rest_init+0xf/0x189 init/main.c:388
  start_kernel+0x67e/0x6b2 init/main.c:664
  x86_64_start_reservations+0x29/0x2b arch/x86/kernel/head64.c:196
  x86_64_start_kernel+0x13f/0x162 arch/x86/kernel/head64.c:177
irq event stamp: 9983290
hardirqs last  enabled at (9983290): [<ffffffff8114989a>] __local_bh_enable_ip+0x6a/0xd0 kernel/softirq.c:186
hardirqs last disabled at (9983289): [<ffffffff81149862>] __local_bh_enable_ip+0x32/0xd0 kernel/softirq.c:163
softirqs last  enabled at (9982906): [<ffffffff839ffb1c>] __do_softirq+0x46c/0x937 kernel/softirq.c:310
softirqs last disabled at (9982911): [<ffffffff8114afce>] run_ksoftirqd+0x2e/0x60 kernel/softirq.c:676

other info that might help us debug this:
 Possible unsafe locking scenario:

       CPU0
       ----
  lock(&(&rnp->exp_lock)->rlock);
  <Interrupt>
    lock(&(&rnp->exp_lock)->rlock);

 *** DEADLOCK ***

1 lock held by ksoftirqd/0/3:
 #0:  (rcu_callback){......}, at: [<ffffffff8128784e>] __rcu_reclaim kernel/rcu/rcu.h:108 [inline]
 #0:  (rcu_callback){......}, at: [<ffffffff8128784e>] rcu_do_batch kernel/rcu/tree.c:2789 [inline]
 #0:  (rcu_callback){......}, at: [<ffffffff8128784e>] invoke_rcu_callbacks kernel/rcu/tree.c:3053 [inline]
 #0:  (rcu_callback){......}, at: [<ffffffff8128784e>] __rcu_process_callbacks kernel/rcu/tree.c:3020 [inline]
 #0:  (rcu_callback){......}, at: [<ffffffff8128784e>] rcu_process_callbacks+0x98e/0x12b0 kernel/rcu/tree.c:3037

stack backtrace:
CPU: 0 PID: 3 Comm: ksoftirqd/0 Not tainted 4.9.111-g03c70fe #58
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
 ffff8801d99ef498 ffffffff81eb2729 ffff8801d99b3000 ffffffff85595210
 ffff8801d99b38f0 ffff8801d99b3910 0000000000000000 ffff8801d99ef508
 ffffffff81427762 0000000000000001 0000000000000001 ffff880100000000
Call Trace:
 [<ffffffff81eb2729>] __dump_stack lib/dump_stack.c:15 [inline]
 [<ffffffff81eb2729>] dump_stack+0xc1/0x128 lib/dump_stack.c:51
 [<ffffffff81427762>] print_usage_bug.cold.56+0x327/0x421 kernel/locking/lockdep.c:2387
 [<ffffffff81234f86>] valid_state kernel/locking/lockdep.c:2400 [inline]
 [<ffffffff81234f86>] mark_lock_irq kernel/locking/lockdep.c:2602 [inline]
 [<ffffffff81234f86>] mark_lock+0xcc6/0x1280 kernel/locking/lockdep.c:3065
 [<ffffffff81236eb0>] mark_irqflags kernel/locking/lockdep.c:2923 [inline]
 [<ffffffff81236eb0>] __lock_acquire+0xd40/0x4070 kernel/locking/lockdep.c:3302
 [<ffffffff8123ac50>] lock_acquire+0x130/0x3e0 kernel/locking/lockdep.c:3756
 [<ffffffff839f8086>] __raw_spin_lock include/linux/spinlock_api_smp.h:144 [inline]
 [<ffffffff839f8086>] _raw_spin_lock+0x36/0x50 kernel/locking/spinlock.c:151
 [<ffffffff812829ab>] spin_lock include/linux/spinlock.h:302 [inline]
 [<ffffffff812829ab>] exp_funnel_lock kernel/rcu/tree_exp.h:271 [inline]
 [<ffffffff812829ab>] _synchronize_rcu_expedited+0x1fb/0x840 kernel/rcu/tree_exp.h:569
 [<ffffffff81284043>] synchronize_rcu_expedited kernel/rcu/tree_exp.h:687 [inline]
 [<ffffffff81284043>] synchronize_rcu.part.62+0xd3/0x110 kernel/rcu/tree_plugin.h:682
 [<ffffffff812840a7>] synchronize_rcu+0x27/0x90 kernel/rcu/tree_plugin.h:685
 [<ffffffff836bbeda>] __l2tp_session_unhash+0x38a/0x520 net/l2tp/l2tp_core.c:1796
 [<ffffffff836bc267>] l2tp_tunnel_closeall+0x1f7/0x350 net/l2tp/l2tp_core.c:1364
 [<ffffffff836bcb22>] l2tp_tunnel_destruct+0x2f2/0x590 net/l2tp/l2tp_core.c:1324
 [<ffffffff83020095>] __sk_destruct+0x55/0x590 net/core/sock.c:1428
 [<ffffffff8128776e>] __rcu_reclaim kernel/rcu/rcu.h:118 [inline]
 [<ffffffff8128776e>] rcu_do_batch kernel/rcu/tree.c:2789 [inline]
 [<ffffffff8128776e>] invoke_rcu_callbacks kernel/rcu/tree.c:3053 [inline]
 [<ffffffff8128776e>] __rcu_process_callbacks kernel/rcu/tree.c:3020 [inline]
 [<ffffffff8128776e>] rcu_process_callbacks+0x8ae/0x12b0 kernel/rcu/tree.c:3037
 [<ffffffff839ff8bb>] __do_softirq+0x20b/0x937 kernel/softirq.c:284
 [<ffffffff8114afce>] run_ksoftirqd+0x2e/0x60 kernel/softirq.c:676
 [<ffffffff811a8239>] smpboot_thread_fn+0x5c9/0x900 kernel/smpboot.c:163
 [<ffffffff8119d05d>] kthread+0x26d/0x300 kernel/kthread.c:211
 [<ffffffff839f8e9c>] ret_from_fork+0x5c/0x70 arch/x86/entry/entry_64.S:373
BUG: sleeping function called from invalid context at kernel/rcu/tree_exp.h:281
in_atomic(): 1, irqs_disabled(): 0, pid: 3, name: ksoftirqd/0
INFO: lockdep is turned off.
Preemption disabled at:[  461.900632] [<ffffffff839ff78b>] __do_softirq+0xdb/0x937 kernel/softirq.c:261
CPU: 0 PID: 3 Comm: ksoftirqd/0 Not tainted 4.9.111-g03c70fe #58
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
 ffff8801d99ef738 ffffffff81eb2729 ffffffff839ff78b 0000000000000000
 0000000000000100 ffff8801d99b3000 ffff8801d99b3000 ffff8801d99ef770
 ffffffff81424390 ffff8801d99b3000 ffffffff83c6d460 0000000000000119
Call Trace:
 [<ffffffff81eb2729>] __dump_stack lib/dump_stack.c:15 [inline]
 [<ffffffff81eb2729>] dump_stack+0xc1/0x128 lib/dump_stack.c:51
 [<ffffffff81424390>] ___might_sleep.cold.123+0x1bc/0x1f5 kernel/sched/core.c:7992
 [<ffffffff811bb635>] __might_sleep+0x95/0x1a0 kernel/sched/core.c:7949
 [<ffffffff81282db0>] exp_funnel_lock kernel/rcu/tree_exp.h:279 [inline]
 [<ffffffff81282db0>] _synchronize_rcu_expedited+0x600/0x840 kernel/rcu/tree_exp.h:569
 [<ffffffff81284043>] synchronize_rcu_expedited kernel/rcu/tree_exp.h:687 [inline]
 [<ffffffff81284043>] synchronize_rcu.part.62+0xd3/0x110 kernel/rcu/tree_plugin.h:682
 [<ffffffff812840a7>] synchronize_rcu+0x27/0x90 kernel/rcu/tree_plugin.h:685
 [<ffffffff836bbeda>] __l2tp_session_unhash+0x38a/0x520 net/l2tp/l2tp_core.c:1796
 [<ffffffff836bc267>] l2tp_tunnel_closeall+0x1f7/0x350 net/l2tp/l2tp_core.c:1364
 [<ffffffff836bcb22>] l2tp_tunnel_destruct+0x2f2/0x590 net/l2tp/l2tp_core.c:1324
 [<ffffffff83020095>] __sk_destruct+0x55/0x590 net/core/sock.c:1428
 [<ffffffff8128776e>] __rcu_reclaim kernel/rcu/rcu.h:118 [inline]
 [<ffffffff8128776e>] rcu_do_batch kernel/rcu/tree.c:2789 [inline]
 [<ffffffff8128776e>] invoke_rcu_callbacks kernel/rcu/tree.c:3053 [inline]
 [<ffffffff8128776e>] __rcu_process_callbacks kernel/rcu/tree.c:3020 [inline]
 [<ffffffff8128776e>] rcu_process_callbacks+0x8ae/0x12b0 kernel/rcu/tree.c:3037
 [<ffffffff839ff8bb>] __do_softirq+0x20b/0x937 kernel/softirq.c:284
 [<ffffffff8114afce>] run_ksoftirqd+0x2e/0x60 kernel/softirq.c:676
 [<ffffffff811a8239>] smpboot_thread_fn+0x5c9/0x900 kernel/smpboot.c:163
 [<ffffffff8119d05d>] kthread+0x26d/0x300 kernel/kthread.c:211
 [<ffffffff839f8e9c>] ret_from_fork+0x5c/0x70 arch/x86/entry/entry_64.S:373
BUG: scheduling while atomic: ksoftirqd/0/3/0x00000101
INFO: lockdep is turned off.
Modules linked in:
Preemption disabled at:[  462.237803] [<ffffffff839ff78b>] __do_softirq+0xdb/0x937 kernel/softirq.c:261

Crashes (3):
Time Kernel Commit Syzkaller Config Log Report Syz repro C repro VM info Assets (help?) Manager Title
2018/07/08 21:15 https://android.googlesource.com/kernel/common android-4.9 03c70feafdb2 f25e5770 .config console log report ci-android-49-kasan-gce
2018/05/23 06:40 https://android.googlesource.com/kernel/common android-4.9 d054505522c4 f48c20b8 .config console log report ci-android-49-kasan-gce
2018/08/28 16:20 https://android.googlesource.com/kernel/common android-4.9 09eb2ba5ed0c 7ef1de9e .config console log report ci-android-49-kasan-gce-386
* Struck through repros no longer work on HEAD.