inconsistent lock state in xprt_destroy

9 views
Skip to first unread message

syzbot

unread,
Apr 26, 2022, 6:06:28 PM4/26/22
to syzkaller...@googlegroups.com
Hello,

syzbot found the following issue on:

HEAD commit: 15a1c6b6f516 Linux 4.14.276
git tree: linux-4.14.y
console output: https://syzkaller.appspot.com/x/log.txt?x=11a45b8af00000
kernel config: https://syzkaller.appspot.com/x/.config?x=3ec12c117082c76f
dashboard link: https://syzkaller.appspot.com/bug?extid=d4d7ee170da887c2d831
compiler: gcc version 10.2.1 20210110 (Debian 10.2.1-6)
syz repro: https://syzkaller.appspot.com/x/repro.syz?x=14f1a4e4f00000
C reproducer: https://syzkaller.appspot.com/x/repro.c?x=14474e26f00000

IMPORTANT: if you fix the issue, please add the following tag to the commit:
Reported-by: syzbot+d4d7ee...@syzkaller.appspotmail.com

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.276-syzkaller #0 Not tainted
--------------------------------
inconsistent {IN-SOFTIRQ-W} -> {SOFTIRQ-ON-W} usage.
kworker/1:3/7694 [HC0[0]:SC0[0]:HE1:SE1] takes:
(&(&xprt->transport_lock)->rlock){+.?.}, at: [<ffffffff8672c398>] spin_lock include/linux/spinlock.h:317 [inline]
(&(&xprt->transport_lock)->rlock){+.?.}, at: [<ffffffff8672c398>] 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: 38035
hardirqs last enabled at (38035): [<ffffffff817ed1ca>] kfree+0x14a/0x250 mm/slab.c:3816
hardirqs last disabled at (38034): [<ffffffff817ed0ef>] kfree+0x6f/0x250 mm/slab.c:3809
softirqs last enabled at (38016): [<ffffffff8674f71d>] spin_unlock_bh include/linux/spinlock.h:362 [inline]
softirqs last enabled at (38016): [<ffffffff8674f71d>] rpc_wake_up_first_on_wq+0x18d/0x480 net/sunrpc/sched.c:559
softirqs last disabled at (38014): [<ffffffff8674f5b9>] spin_lock_bh include/linux/spinlock.h:322 [inline]
softirqs last disabled at (38014): [<ffffffff8674f5b9>] 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/1:3/7694:
#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: 1 PID: 7694 Comm: kworker/1:3 Not tainted 4.14.276-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


---
This report is generated by a bot. It may contain errors.
See https://goo.gl/tpsmEJ for more information about syzbot.
syzbot engineers can be reached at syzk...@googlegroups.com.

syzbot will keep track of this issue. See:
https://goo.gl/tpsmEJ#status for how to communicate with syzbot.
syzbot can test patches for this issue, for details see:
https://goo.gl/tpsmEJ#testing-patches
Reply all
Reply to author
Forward
0 new messages