inconsistent lock state in rxrpc_put_client_connection

inconsistent lock state in rxrpc_put_client_connection_id
Status: auto-closed as invalid on 2020/09/29 08:26
Reported-by: syzbot+9a6b527fea584738d810@syzkaller.appspotmail.com
First crash: 609d, last: 511d

similar bugs (2):
Kernel	Title	Repro	Cause bisect	Fix bisect	Count	Last	Reported	Patched	Status
upstream	inconsistent lock state in rxrpc_put_client_connection_id	C	done		473	624d	629d	16/22	fixed on 2020/02/18 14:31
linux-4.19	inconsistent lock state in rxrpc_put_client_connection_id	C		done	89	605d	622d	1/1	fixed on 2020/03/30 09:03

Sample crash report:

mmap: syz-executor.2 (8388) uses deprecated remap_file_pages() syscall. See Documentation/vm/remap_file_pages.txt.
================================
WARNING: inconsistent lock state
ieee80211 phy3: hwaddr 02:00:00:00:03:00 registered
4.14.182-syzkaller #0 Not tainted
--------------------------------
inconsistent {SOFTIRQ-ON-W} -> {IN-SOFTIRQ-W} usage.
syz-fuzzer/6328 [HC0[0]:SC1[1]:HE1:SE0] takes:
 (rxrpc_conn_id_lock){+.?.}, at: [<ffffffff85b7c7e5>] spin_lock include/linux/spinlock.h:317 [inline]
 (rxrpc_conn_id_lock){+.?.}, at: [<ffffffff85b7c7e5>] rxrpc_put_client_connection_id.part.0+0x15/0x70 net/rxrpc/conn_client.c:143
{SOFTIRQ-ON-W} state was registered at:
  lock_acquire+0x170/0x3f0 kernel/locking/lockdep.c:3998
  __raw_spin_lock include/linux/spinlock_api_smp.h:142 [inline]
  _raw_spin_lock+0x2a/0x40 kernel/locking/spinlock.c:152
  spin_lock include/linux/spinlock.h:317 [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:342 [inline]
  rxrpc_connect_call+0x7ec/0x3e50 net/rxrpc/conn_client.c:692
  rxrpc_new_client_call+0x8d3/0x1400 net/rxrpc/call_object.c:276
  rxrpc_new_client_call_for_sendmsg net/rxrpc/sendmsg.c:525 [inline]
  rxrpc_do_sendmsg+0x8a1/0x1023 net/rxrpc/sendmsg.c:577
  rxrpc_sendmsg+0x47d/0x5a0 net/rxrpc/af_rxrpc.c:543
  sock_sendmsg_nosec net/socket.c:646 [inline]
  sock_sendmsg+0xb5/0x100 net/socket.c:656
  ___sys_sendmsg+0x349/0x840 net/socket.c:2062
  __sys_sendmmsg+0x129/0x330 net/socket.c:2152
  SYSC_sendmmsg net/socket.c:2183 [inline]
  SyS_sendmmsg+0x2f/0x50 net/socket.c:2178
  do_syscall_64+0x1d5/0x640 arch/x86/entry/common.c:292
  entry_SYSCALL_64_after_hwframe+0x46/0xbb
irq event stamp: 8456560
hardirqs last  enabled at (8456560): [<ffffffff863e5d09>] __raw_spin_unlock_irqrestore include/linux/spinlock_api_smp.h:160 [inline]
hardirqs last  enabled at (8456560): [<ffffffff863e5d09>] _raw_spin_unlock_irqrestore+0x79/0xe0 kernel/locking/spinlock.c:192
hardirqs last disabled at (8456559): [<ffffffff863e5af6>] __raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:108 [inline]
hardirqs last disabled at (8456559): [<ffffffff863e5af6>] _raw_spin_lock_irqsave+0x66/0xc0 kernel/locking/spinlock.c:160
softirqs last  enabled at (8456028): [<ffffffff86600664>] __do_softirq+0x664/0x9bf kernel/softirq.c:314
softirqs last disabled at (8456539): [<ffffffff8137076b>] invoke_softirq kernel/softirq.c:368 [inline]
softirqs last disabled at (8456539): [<ffffffff8137076b>] irq_exit+0x15b/0x1a0 kernel/softirq.c:409

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 syz-fuzzer/6328:
 #0:  (rcu_callback){....}, at: [<ffffffff814c5ed1>] __rcu_reclaim kernel/rcu/rcu.h:185 [inline]
 #0:  (rcu_callback){....}, at: [<ffffffff814c5ed1>] rcu_do_batch kernel/rcu/tree.c:2699 [inline]
 #0:  (rcu_callback){....}, at: [<ffffffff814c5ed1>] invoke_rcu_callbacks kernel/rcu/tree.c:2962 [inline]
 #0:  (rcu_callback){....}, at: [<ffffffff814c5ed1>] __rcu_process_callbacks kernel/rcu/tree.c:2929 [inline]
 #0:  (rcu_callback){....}, at: [<ffffffff814c5ed1>] rcu_process_callbacks+0x861/0x1180 kernel/rcu/tree.c:2946

stack backtrace:
CPU: 1 PID: 6328 Comm: syz-fuzzer Not tainted 4.14.182-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:17 [inline]
 dump_stack+0x1b2/0x283 lib/dump_stack.c:58
 print_usage_bug.cold+0x42e/0x570 kernel/locking/lockdep.c:2589
 valid_state kernel/locking/lockdep.c:2602 [inline]
 mark_lock_irq kernel/locking/lockdep.c:2796 [inline]
 mark_lock+0xb42/0x1040 kernel/locking/lockdep.c:3194
 mark_irqflags kernel/locking/lockdep.c:3072 [inline]
 __lock_acquire+0xd2f/0x42a0 kernel/locking/lockdep.c:3448
 lock_acquire+0x170/0x3f0 kernel/locking/lockdep.c:3998
 __raw_spin_lock include/linux/spinlock_api_smp.h:142 [inline]
 _raw_spin_lock+0x2a/0x40 kernel/locking/spinlock.c:152
 spin_lock include/linux/spinlock.h:317 [inline]
 rxrpc_put_client_connection_id.part.0+0x15/0x70 net/rxrpc/conn_client.c:143
 rxrpc_put_client_connection_id include/linux/rcupdate.h:775 [inline]
 rxrpc_put_one_client_conn net/rxrpc/conn_client.c:912 [inline]
 rxrpc_put_client_conn+0x60e/0xa90 net/rxrpc/conn_client.c:957
 rxrpc_put_connection net/rxrpc/ar-internal.h:862 [inline]
 rxrpc_rcu_destroy_call+0x83/0x190 net/rxrpc/call_object.c:642
 __rcu_reclaim kernel/rcu/rcu.h:195 [inline]
 rcu_do_batch kernel/rcu/tree.c:2699 [inline]
 invoke_rcu_callbacks kernel/rcu/tree.c:2962 [inline]
 __rcu_process_callbacks kernel/rcu/tree.c:2929 [inline]
 rcu_process_callbacks+0x78d/0x1180 kernel/rcu/tree.c:2946
 __do_softirq+0x254/0x9bf kernel/softirq.c:288
 invoke_softirq kernel/softirq.c:368 [inline]
 irq_exit+0x15b/0x1a0 kernel/softirq.c:409
 exiting_irq arch/x86/include/asm/apic.h:648 [inline]
 smp_apic_timer_interrupt+0x141/0x5f0 arch/x86/kernel/apic/apic.c:1102
 apic_timer_interrupt+0x93/0xa0 arch/x86/entry/entry_64.S:793
 </IRQ>
RIP: 0033:0x40c34b
RSP: 002b:000000c002856cc8 EFLAGS: 00000246 ORIG_RAX: ffffffffffffff10
RAX: 000000c002856d48 RBX: 000000c00003ea80 RCX: 000000c0000ad680
RDX: 000000c0000ad680 RSI: 0000000000000000 RDI: 000000c01e98f8e8
RBP: 000000c002856d58 R08: 0000000000000004 R09: 0000000000203000
R10: 0000000000000008 R11: 0000000000000074 R12: 00000000000000f4
R13: 0000000000000000 R14: 0000000000ab4ae7 R15: 0000000000000000
ieee80211 phy4: Selected rate control algorithm 'minstrel_ht'
IPVS: ftp: loaded support on port[0] = 21
ieee80211 phy4: hwaddr 02:00:00:00:04:00 registered
audit: type=1804 audit(1590999941.664:25): pid=8427 uid=0 auid=0 ses=4 subj=system_u:system_r:kernel_t:s0 op="invalid_pcr" cause="ToMToU" comm="syz-executor.5" name="/root/syzkaller-testdir670630704/syzkaller.eEJgSq/16/file0/file0" dev="ramfs" ino=29923 res=1
IPVS: ftp: loaded support on port[0] = 21
IPVS: ftp: loaded support on port[0] = 21
IPVS: ftp: loaded support on port[0] = 21

Crashes (8):
Manager	Time	Kernel	Commit	Syzkaller	Config	Log	Report
ci2-linux-4-14	2020/06/01 08:25	linux-4.14.y	4f68020fef1c	a0331e89	.config	log	report
ci2-linux-4-14	2020/05/16 10:55	linux-4.14.y	ab9dfda23248	37bccd4e	.config	log	report
ci2-linux-4-14	2020/05/04 18:58	linux-4.14.y	773e2b1cd56a	58ae5e18	.config	log	report
ci2-linux-4-14	2020/03/11 04:36	linux-4.14.y	78d697fc93f9	35f53e45	.config	log	report
ci2-linux-4-14	2020/02/29 03:40	linux-4.14.y	78d697fc93f9	c88c7b75	.config	log	report
ci2-linux-4-14	2020/02/24 11:29	linux-4.14.y	98db2bf27b9e	1253d6f0	.config	log	report
ci2-linux-4-14	2020/02/24 11:29	linux-4.14.y	98db2bf27b9e	1253d6f0	.config	log	report
ci2-linux-4-14	2020/02/24 11:29	linux-4.14.y	98db2bf27b9e	1253d6f0	.config	log	report