inconsistent lock state in rxrpc_put_client_connection_id

Status: fixed on 2020/03/30 09:03
Reported-by: syzbot+25ccd810e06085667dcd@syzkaller.appspotmail.com
Fix commit: 963485d436cc rxrpc: Fix call RCU cleanup using non-bh-safe locks
First crash: 2382d, last: 2365d
Fix bisection: fixed by (bisect log) :
commit 43cac315bec132e962e04c31fe888caac257ec0a
Author: David Howells <dhowells@redhat.com>
Date: Thu Feb 6 13:57:40 2020 +0000

  rxrpc: Fix call RCU cleanup using non-bh-safe locks

  
▶ ▼ Similar bugs (2)
Kernel Title Rank 🛈 Repro Cause bisect Fix bisect Count Last Reported Patched Status
upstream inconsistent lock state in rxrpc_put_client_connection_id afs net 4 syz, C done 473 2383d 2389d 15/29 fixed on 2020/02/18 14:31
linux-4.14 inconsistent lock state in rxrpc_put_client_connection_id 4 8 2271d 2369d 0/1 auto-closed as invalid on 2020/09/29 08:26

Sample crash report:
audit: type=1400 audit(1582553796.125:36): avc:  denied  { map } for  pid=8293 comm="syz-executor950" path="/root/syz-executor950892875" dev="sda1" ino=16483 scontext=unconfined_u:system_r:insmod_t:s0-s0:c0.c1023 tcontext=unconfined_u:object_r:user_home_t:s0 tclass=file permissive=1
IPVS: ftp: loaded support on port[0] = 21
================================
WARNING: inconsistent lock state
4.19.106-syzkaller #0 Not tainted
--------------------------------
inconsistent {SOFTIRQ-ON-W} -> {IN-SOFTIRQ-W} usage.
swapper/0/0 [HC0[0]:SC1[1]:HE1:SE0] takes:
000000006ecf415e (rxrpc_conn_id_lock){+.?.}, at: spin_lock include/linux/spinlock.h:329 [inline]
000000006ecf415e (rxrpc_conn_id_lock){+.?.}, at: rxrpc_put_client_connection_id.part.0+0x19/0x70 net/rxrpc/conn_client.c:143
{SOFTIRQ-ON-W} state was registered at:
  lock_acquire+0x16f/0x3f0 kernel/locking/lockdep.c:3903
  __raw_spin_lock include/linux/spinlock_api_smp.h:142 [inline]
  _raw_spin_lock+0x2f/0x40 kernel/locking/spinlock.c:144
  spin_lock include/linux/spinlock.h:329 [inline]
  rxrpc_get_client_connection_id net/rxrpc/conn_client.c:114 [inline]
  rxrpc_alloc_client_connection net/rxrpc/conn_client.c:198 [inline]
  rxrpc_get_client_conn net/rxrpc/conn_client.c:345 [inline]
  rxrpc_connect_call+0x948/0x4920 net/rxrpc/conn_client.c:702
  rxrpc_new_client_call+0x8e7/0x1880 net/rxrpc/call_object.c:291
  rxrpc_new_client_call_for_sendmsg net/rxrpc/sendmsg.c:596 [inline]
  rxrpc_do_sendmsg+0xfc3/0x1ca3 net/rxrpc/sendmsg.c:652
  rxrpc_sendmsg+0x4a0/0x5b0 net/rxrpc/af_rxrpc.c:593
  sock_sendmsg_nosec net/socket.c:622 [inline]
  sock_sendmsg+0xd7/0x130 net/socket.c:632
  ___sys_sendmsg+0x3e2/0x920 net/socket.c:2115
  __sys_sendmmsg+0x1bf/0x4e0 net/socket.c:2210
  __do_sys_sendmmsg net/socket.c:2239 [inline]
  __se_sys_sendmmsg net/socket.c:2236 [inline]
  __x64_sys_sendmmsg+0x9d/0x100 net/socket.c:2236
  do_syscall_64+0xfd/0x620 arch/x86/entry/common.c:293
  entry_SYSCALL_64_after_hwframe+0x49/0xbe
irq event stamp: 180920
hardirqs last  enabled at (180920): [<ffffffff8754cb6b>] __raw_spin_unlock_irqrestore include/linux/spinlock_api_smp.h:160 [inline]
hardirqs last  enabled at (180920): [<ffffffff8754cb6b>] _raw_spin_unlock_irqrestore+0x6b/0xe0 kernel/locking/spinlock.c:184
hardirqs last disabled at (180919): [<ffffffff8754cdff>] __raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:108 [inline]
hardirqs last disabled at (180919): [<ffffffff8754cdff>] _raw_spin_lock_irqsave+0x6f/0xcd kernel/locking/spinlock.c:152
softirqs last  enabled at (180814): [<ffffffff813fdc1c>] _local_bh_enable+0x1c/0x30 kernel/softirq.c:162
softirqs last disabled at (180815): [<ffffffff814007a0>] invoke_softirq kernel/softirq.c:372 [inline]
softirqs last disabled at (180815): [<ffffffff814007a0>] irq_exit+0x180/0x1d0 kernel/softirq.c:412

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

       CPU0
       ----
  lock(rxrpc_conn_id_lock);
  <Interrupt>
    lock(rxrpc_conn_id_lock);

 *** DEADLOCK ***

1 lock held by swapper/0/0:
 #0: 00000000a7255a0b (rcu_callback){....}, at: __rcu_reclaim kernel/rcu/rcu.h:226 [inline]
 #0: 00000000a7255a0b (rcu_callback){....}, at: rcu_do_batch kernel/rcu/tree.c:2584 [inline]
 #0: 00000000a7255a0b (rcu_callback){....}, at: invoke_rcu_callbacks kernel/rcu/tree.c:2897 [inline]
 #0: 00000000a7255a0b (rcu_callback){....}, at: __rcu_process_callbacks kernel/rcu/tree.c:2864 [inline]
 #0: 00000000a7255a0b (rcu_callback){....}, at: rcu_process_callbacks+0xc79/0x1a30 kernel/rcu/tree.c:2881

stack backtrace:
CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.19.106-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
Call Trace:
 <IRQ>
 __dump_stack lib/dump_stack.c:77 [inline]
 dump_stack+0x197/0x210 lib/dump_stack.c:118
 print_usage_bug.cold+0x330/0x42a kernel/locking/lockdep.c:2540
 valid_state kernel/locking/lockdep.c:2553 [inline]
 mark_lock_irq kernel/locking/lockdep.c:2747 [inline]
 mark_lock+0xd1b/0x1370 kernel/locking/lockdep.c:3127
 mark_irqflags kernel/locking/lockdep.c:3005 [inline]
 __lock_acquire+0xc62/0x49c0 kernel/locking/lockdep.c:3368
 lock_acquire+0x16f/0x3f0 kernel/locking/lockdep.c:3903
 __raw_spin_lock include/linux/spinlock_api_smp.h:142 [inline]
 _raw_spin_lock+0x2f/0x40 kernel/locking/spinlock.c:144
 spin_lock include/linux/spinlock.h:329 [inline]
 rxrpc_put_client_connection_id.part.0+0x19/0x70 net/rxrpc/conn_client.c:143
 rxrpc_put_client_connection_id include/linux/spinlock.h:370 [inline]
 rxrpc_put_one_client_conn net/rxrpc/conn_client.c:956 [inline]
 rxrpc_put_client_conn+0x6c6/0xc20 net/rxrpc/conn_client.c:1002
 rxrpc_put_connection net/rxrpc/ar-internal.h:951 [inline]
 rxrpc_rcu_destroy_call+0xbd/0x200 net/rxrpc/call_object.c:657
 __rcu_reclaim kernel/rcu/rcu.h:236 [inline]
 rcu_do_batch kernel/rcu/tree.c:2584 [inline]
 invoke_rcu_callbacks kernel/rcu/tree.c:2897 [inline]
 __rcu_process_callbacks kernel/rcu/tree.c:2864 [inline]
 rcu_process_callbacks+0xba0/0x1a30 kernel/rcu/tree.c:2881
 __do_softirq+0x25c/0x921 kernel/softirq.c:292
 invoke_softirq kernel/softirq.c:372 [inline]
 irq_exit+0x180/0x1d0 kernel/softirq.c:412
 exiting_irq arch/x86/include/asm/apic.h:544 [inline]
 smp_apic_timer_interrupt+0x13b/0x550 arch/x86/kernel/apic/apic.c:1094
 apic_timer_interrupt+0xf/0x20 arch/x86/entry/entry_64.S:893
 </IRQ>
RIP: 0010:native_safe_halt+0xe/0x10 arch/x86/include/asm/irqflags.h:61
Code: ff ff 48 89 df e8 22 c7 4d fa eb 82 e9 07 00 00 00 0f 00 2d 44 30 53 00 f4 c3 66 90 e9 07 00 00 00 0f 00 2d 34 30 53 00 fb f4 <c3> 90 55 48 89 e5 41 57 41 56 41 55 41 54 53 e8 6e 9b 04 fa e8 09
RSP: 0018:ffffffff88e07cb0 EFLAGS: 00000282 ORIG_RAX: ffffffffffffff13
RAX: 1ffffffff11e4ab4 RBX: ffffffff88e79ec0 RCX: 0000000000000000
RDX: dffffc0000000000 RSI: 0000000000000001 RDI: ffffffff88e7a73c
RBP: ffffffff88e07ce0 R08: ffffffff88e79ec0 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000000
R13: ffffffff88f25590 R14: 0000000000000000 R15: ffffffff88e79ec0
 arch_cpu_idle+0xa/0x10 arch/x86/kernel/process.c:556
 default_idle_call+0x36/0x90 kernel/sched/idle.c:93
 cpuidle_idle_call kernel/sched/idle.c:153 [inline]
 do_idle+0x30c/0x4d0 kernel/sched/idle.c:263
 cpu_startup_entry+0xc8/0xe0 kernel/sched/idle.c:369
 rest_init+0x219/0x222 init/main.c:441
 start_kernel+0x7ec/0x825 init/main.c:737
 x86_64_start_reservations+0x29/0x2b arch/x86/kernel/head64.c:490
 x86_64_start_kernel+0x77/0x7b arch/x86/kernel/head64.c:471
 secondary_startup_64+0xa4/0xb0 arch/x86/kernel/head_64.S:243

Crashes (89):
Time Kernel Commit Syzkaller Config Log Report Syz repro C repro VM info Assets (help?) Manager Title
2020/02/24 14:19 linux-4.19.y f25804f38984 1253d6f0 .config console log report syz C ci2-linux-4-19
2020/02/28 15:29 linux-4.19.y f25804f38984 c88c7b75 .config console log report ci2-linux-4-19
2020/02/27 21:32 linux-4.19.y f25804f38984 c88c7b75 .config console log report ci2-linux-4-19
2020/02/27 19:21 linux-4.19.y f25804f38984 40bcfdd5 .config console log report ci2-linux-4-19
2020/02/27 09:34 linux-4.19.y f25804f38984 40bcfdd5 .config console log report ci2-linux-4-19
2020/02/27 04:06 linux-4.19.y f25804f38984 251aabb7 .config console log report ci2-linux-4-19
2020/02/27 01:48 linux-4.19.y f25804f38984 251aabb7 .config console log report ci2-linux-4-19
2020/02/26 15:08 linux-4.19.y f25804f38984 251aabb7 .config console log report ci2-linux-4-19
2020/02/26 02:09 linux-4.19.y f25804f38984 4f588111 .config console log report ci2-linux-4-19
2020/02/25 15:19 linux-4.19.y f25804f38984 4c886d6a .config console log report ci2-linux-4-19
2020/02/25 14:04 linux-4.19.y f25804f38984 4c886d6a .config console log report ci2-linux-4-19
2020/02/25 09:43 linux-4.19.y f25804f38984 59b57593 .config console log report ci2-linux-4-19
2020/02/24 23:33 linux-4.19.y f25804f38984 59b57593 .config console log report ci2-linux-4-19
2020/02/24 21:50 linux-4.19.y f25804f38984 59b57593 .config console log report ci2-linux-4-19
2020/02/24 11:41 linux-4.19.y f25804f38984 1253d6f0 .config console log report ci2-linux-4-19
2020/02/24 10:32 linux-4.19.y f25804f38984 1253d6f0 .config console log report ci2-linux-4-19
2020/02/24 08:55 linux-4.19.y f25804f38984 d801cb02 .config console log report ci2-linux-4-19
2020/02/23 22:02 linux-4.19.y 4fccc2503536 d801cb02 .config console log report ci2-linux-4-19
2020/02/23 00:50 linux-4.19.y 4fccc2503536 2c36e7a7 .config console log report ci2-linux-4-19
2020/02/22 21:32 linux-4.19.y 4fccc2503536 2c36e7a7 .config console log report ci2-linux-4-19
2020/02/22 13:27 linux-4.19.y 4fccc2503536 2c36e7a7 .config console log report ci2-linux-4-19
2020/02/22 12:21 linux-4.19.y 4fccc2503536 2c36e7a7 .config console log report ci2-linux-4-19
2020/02/22 06:17 linux-4.19.y 4fccc2503536 2ffa6679 .config console log report ci2-linux-4-19
2020/02/21 18:26 linux-4.19.y 4fccc2503536 2ffa6679 .config console log report ci2-linux-4-19
2020/02/21 05:03 linux-4.19.y 4fccc2503536 bd2a74a3 .config console log report ci2-linux-4-19
2020/02/21 04:01 linux-4.19.y 4fccc2503536 bd2a74a3 .config console log report ci2-linux-4-19
2020/02/21 01:19 linux-4.19.y 4fccc2503536 81230308 .config console log report ci2-linux-4-19
2020/02/21 00:07 linux-4.19.y 4fccc2503536 81230308 .config console log report ci2-linux-4-19
2020/02/20 14:13 linux-4.19.y 4fccc2503536 81230308 .config console log report ci2-linux-4-19
2020/02/20 13:03 linux-4.19.y 4fccc2503536 81230308 .config console log report ci2-linux-4-19
2020/02/20 06:21 linux-4.19.y 4fccc2503536 b690a6e3 .config console log report ci2-linux-4-19
2020/02/20 01:04 linux-4.19.y 4fccc2503536 b690a6e3 .config console log report ci2-linux-4-19
2020/02/19 19:51 linux-4.19.y 4fccc2503536 47fae6e9 .config console log report ci2-linux-4-19
2020/02/19 14:27 linux-4.19.y 9b15f7fae677 47fae6e9 .config console log report ci2-linux-4-19
2020/02/19 14:27 linux-4.19.y 9b15f7fae677 47fae6e9 .config console log report ci2-linux-4-19
2020/02/19 14:17 linux-4.19.y 9b15f7fae677 47fae6e9 .config console log report ci2-linux-4-19
2020/02/19 13:18 linux-4.19.y 9b15f7fae677 47fae6e9 .config console log report ci2-linux-4-19
2020/02/19 02:23 linux-4.19.y 9b15f7fae677 135c18aa .config console log report ci2-linux-4-19
2020/02/19 02:22 linux-4.19.y 9b15f7fae677 135c18aa .config console log report ci2-linux-4-19
2020/02/19 02:22 linux-4.19.y 9b15f7fae677 135c18aa .config console log report ci2-linux-4-19
2020/02/19 02:21 linux-4.19.y 9b15f7fae677 135c18aa .config console log report ci2-linux-4-19
2020/02/19 02:17 linux-4.19.y 9b15f7fae677 135c18aa .config console log report ci2-linux-4-19
2020/02/19 02:17 linux-4.19.y 9b15f7fae677 135c18aa .config console log report ci2-linux-4-19
2020/02/18 12:23 linux-4.19.y 9b15f7fae677 1ce142dc .config console log report ci2-linux-4-19
2020/02/18 12:23 linux-4.19.y 9b15f7fae677 1ce142dc .config console log report ci2-linux-4-19
2020/02/17 22:29 linux-4.19.y 9b15f7fae677 72bfa6f2 .config console log report ci2-linux-4-19
2020/02/17 13:30 linux-4.19.y 9b15f7fae677 72bfa6f2 .config console log report ci2-linux-4-19
2020/02/12 18:39 linux-4.19.y 357668399cf7 84f4fc8a .config console log report ci2-linux-4-19
2020/02/12 12:14 linux-4.19.y 357668399cf7 a75b198c .config console log report ci2-linux-4-19
2020/02/12 08:00 linux-4.19.y 357668399cf7 a75b198c .config console log report ci2-linux-4-19
2020/02/12 05:44 linux-4.19.y 357668399cf7 a75b198c .config console log report ci2-linux-4-19
2020/02/11 19:03 linux-4.19.y 357668399cf7 4d1ab643 .config console log report ci2-linux-4-19
2020/02/11 18:01 linux-4.19.y 357668399cf7 4d1ab643 .config console log report ci2-linux-4-19
2020/02/11 16:52 linux-4.19.y 357668399cf7 084454ae .config console log report ci2-linux-4-19
* Struck through repros no longer work on HEAD.