syzbot


inconsistent lock state in xprt_destroy

Status: upstream: reported C repro on 2022/04/26 22:06
Reported-by: syzbot+d4d7ee170da887c2d831@syzkaller.appspotmail.com
First crash: 975d, last: 848d
Fix bisection: failed (error log, bisect log)
  
Last patch testing requests (2)
Created Duration User Patch Repo Result
2023/03/07 01:32 0m retest repro linux-4.14.y error
2023/03/07 00:32 0m retest repro linux-4.14.y error
Fix bisection attempts (3)
Created Duration User Patch Repo Result
2022/10/13 02:14 0m bisect fix linux-4.14.y error job log
2022/08/31 16:20 31m bisect fix linux-4.14.y OK (0) job log log
2022/07/17 19:05 27m bisect fix linux-4.14.y OK (0) job log log

Sample crash report:
IPv6: ADDRCONF(NETDEV_CHANGE): macvtap0: link becomes ready
batman_adv: batadv0: Interface activated: batadv_slave_1
IPv6: ADDRCONF(NETDEV_CHANGE): veth1_to_batadv: link becomes ready
IPv6: ADDRCONF(NETDEV_CHANGE): bond0: link becomes ready
================================
WARNING: inconsistent lock state
4.14.280-syzkaller #0 Not tainted
--------------------------------
inconsistent {IN-SOFTIRQ-W} -> {SOFTIRQ-ON-W} usage.
kworker/0:2/3413 [HC0[0]:SC0[0]:HE1:SE1] takes:
 (&(&xprt->transport_lock)->rlock){+.?.}, at: [<ffffffff8672d498>] spin_lock include/linux/spinlock.h:317 [inline]
 (&(&xprt->transport_lock)->rlock){+.?.}, at: [<ffffffff8672d498>] xprt_destroy+0x68/0x1c0 net/sunrpc/xprt.c:1528
{IN-SOFTIRQ-W} state was registered at:
  lock_acquire+0x170/0x3f0 kernel/locking/lockdep.c:3998
  __raw_spin_lock_bh include/linux/spinlock_api_smp.h:135 [inline]
  _raw_spin_lock_bh+0x2f/0x40 kernel/locking/spinlock.c:176
  spin_lock_bh include/linux/spinlock.h:322 [inline]
  xprt_disconnect_done+0x19/0x40 net/sunrpc/xprt.c:664
  xs_sock_mark_closed net/sunrpc/xprtsock.c:811 [inline]
  xs_tcp_state_change+0x3c4/0x7e0 net/sunrpc/xprtsock.c:1637
  tcp_done+0x14f/0x210 net/ipv4/tcp.c:3427
  tcp_v4_err+0x7dd/0x1820 net/ipv4/tcp_ipv4.c:523
  icmp_socket_deliver+0x1a7/0x330 net/ipv4/icmp.c:836
  icmp_unreach+0x268/0xae0 net/ipv4/icmp.c:953
  icmp_rcv+0xb7f/0x1240 net/ipv4/icmp.c:1134
  ip_local_deliver_finish+0x3f2/0xab0 net/ipv4/ip_input.c:216
  NF_HOOK include/linux/netfilter.h:250 [inline]
  ip_local_deliver+0x167/0x460 net/ipv4/ip_input.c:257
  dst_input include/net/dst.h:476 [inline]
  ip_rcv_finish+0x6e3/0x19f0 net/ipv4/ip_input.c:396
  NF_HOOK include/linux/netfilter.h:250 [inline]
  ip_rcv+0x8a7/0xf10 net/ipv4/ip_input.c:493
  __netif_receive_skb_core+0x15ee/0x2a30 net/core/dev.c:4474
  __netif_receive_skb+0x27/0x1a0 net/core/dev.c:4512
  process_backlog+0x218/0x6f0 net/core/dev.c:5195
  napi_poll net/core/dev.c:5604 [inline]
  net_rx_action+0x466/0xfd0 net/core/dev.c:5670
  __do_softirq+0x24d/0x9ff kernel/softirq.c:288
  run_ksoftirqd+0x50/0x1a0 kernel/softirq.c:670
  smpboot_thread_fn+0x5c1/0x920 kernel/smpboot.c:164
  kthread+0x30d/0x420 kernel/kthread.c:232
  ret_from_fork+0x24/0x30 arch/x86/entry/entry_64.S:404
irq event stamp: 45695
hardirqs last  enabled at (45695): [<ffffffff817ed5da>] kfree+0x14a/0x250 mm/slab.c:3816
hardirqs last disabled at (45694): [<ffffffff817ed4ff>] kfree+0x6f/0x250 mm/slab.c:3809
softirqs last  enabled at (45676): [<ffffffff867508fd>] spin_unlock_bh include/linux/spinlock.h:362 [inline]
softirqs last  enabled at (45676): [<ffffffff867508fd>] rpc_wake_up_first_on_wq+0x18d/0x480 net/sunrpc/sched.c:559
softirqs last disabled at (45674): [<ffffffff86750799>] spin_lock_bh include/linux/spinlock.h:322 [inline]
softirqs last disabled at (45674): [<ffffffff86750799>] rpc_wake_up_first_on_wq+0x29/0x480 net/sunrpc/sched.c:551

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

       CPU0
       ----
  lock(&(&xprt->transport_lock)->rlock);
  <Interrupt>
    lock(&(&xprt->transport_lock)->rlock);

 *** DEADLOCK ***

2 locks held by kworker/0:2/3413:
 #0:  ("rpciod"){+.+.}, at: [<ffffffff81364f80>] process_one_work+0x6b0/0x14a0 kernel/workqueue.c:2088
 #1:  ((&task->u.tk_work)){+.+.}, at: [<ffffffff81364fb6>] process_one_work+0x6e6/0x14a0 kernel/workqueue.c:2092

stack backtrace:
CPU: 0 PID: 3413 Comm: kworker/0:2 Not tainted 4.14.280-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
Workqueue: rpciod rpc_async_schedule
Call Trace:
 __dump_stack lib/dump_stack.c:17 [inline]
 dump_stack+0x1b2/0x281 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+0xb4d/0x1050 kernel/locking/lockdep.c:3194
 mark_irqflags kernel/locking/lockdep.c:3090 [inline]
 __lock_acquire+0xd5c/0x3f20 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]
 xprt_destroy+0x68/0x1c0 net/sunrpc/xprt.c:1528
 xprt_destroy_kref net/sunrpc/xprt.c:1542 [inline]
 kref_put include/linux/kref.h:70 [inline]
 xprt_put+0x32/0x40 net/sunrpc/xprt.c:1566
 rpc_task_release_transport net/sunrpc/clnt.c:974 [inline]
 rpc_task_release_client+0x1cd/0x280 net/sunrpc/clnt.c:992
 rpc_release_resources_task net/sunrpc/sched.c:1030 [inline]
 rpc_release_task net/sunrpc/sched.c:1069 [inline]
 __rpc_execute+0x66b/0xc90 net/sunrpc/sched.c:832

Crashes (4):
Time Kernel Commit Syzkaller Config Log Report Syz repro C repro VM info Assets (help?) Manager Title
2022/05/24 06:36 linux-4.14.y dffb5c6ff09c e7f9308d .config console log report syz C ci2-linux-4-14 inconsistent lock state in xprt_destroy
2022/04/26 22:05 linux-4.14.y 15a1c6b6f516 1fa34c1b .config console log report syz C ci2-linux-4-14 inconsistent lock state in xprt_destroy
2022/08/01 16:20 linux-4.14.y b641242202ed fef302b1 .config console log report info ci2-linux-4-14 inconsistent lock state in xprt_destroy
2022/06/17 19:05 linux-4.14.y 84bae26850e3 8f633d84 .config console log report info ci2-linux-4-14 inconsistent lock state in xprt_destroy
* Struck through repros no longer work on HEAD.