inconsistent lock state in rxrpc_put_client_conn

13 views
Skip to first unread message

syzbot

unread,
Feb 11, 2020, 10:22:12 AM2/11/20
to syzkaller...@googlegroups.com
Hello,

syzbot found the following crash on:

HEAD commit: 35766839 Linux 4.19.103
git tree: linux-4.19.y
console output: https://syzkaller.appspot.com/x/log.txt?x=14b31395e00000
kernel config: https://syzkaller.appspot.com/x/.config?x=84f14e7b6cbc7d27
dashboard link: https://syzkaller.appspot.com/bug?extid=19114525476fe0be9e7b
compiler: gcc (GCC) 9.0.0 20181231 (experimental)

Unfortunately, I don't have any reproducer for this crash yet.

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

================================
WARNING: inconsistent lock state
4.19.103-syzkaller #0 Not tainted
--------------------------------
inconsistent {SOFTIRQ-ON-W} -> {IN-SOFTIRQ-W} usage.
syz-fuzzer/8087 [HC0[0]:SC1[1]:HE1:SE0] takes:
00000000e62d9ee6 (&(&local->client_conns_lock)->rlock){+.?.}, at: spin_lock include/linux/spinlock.h:329 [inline]
00000000e62d9ee6 (&(&local->client_conns_lock)->rlock){+.?.}, at: rxrpc_put_one_client_conn net/rxrpc/conn_client.c:949 [inline]
00000000e62d9ee6 (&(&local->client_conns_lock)->rlock){+.?.}, at: rxrpc_put_client_conn+0x683/0xc20 net/rxrpc/conn_client.c:1002
{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_conn net/rxrpc/conn_client.c:309 [inline]
rxrpc_connect_call+0x351/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: 181734
hardirqs last enabled at (181734): [<ffffffff87553a3b>] __raw_spin_unlock_irqrestore include/linux/spinlock_api_smp.h:160 [inline]
hardirqs last enabled at (181734): [<ffffffff87553a3b>] _raw_spin_unlock_irqrestore+0x6b/0xe0 kernel/locking/spinlock.c:184
hardirqs last disabled at (181733): [<ffffffff87553ccf>] __raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:108 [inline]
hardirqs last disabled at (181733): [<ffffffff87553ccf>] _raw_spin_lock_irqsave+0x6f/0xcd kernel/locking/spinlock.c:152
softirqs last enabled at (181364): [<ffffffff87800633>] __do_softirq+0x633/0x921 kernel/softirq.c:318
softirqs last disabled at (181575): [<ffffffff81405860>] invoke_softirq kernel/softirq.c:372 [inline]
softirqs last disabled at (181575): [<ffffffff81405860>] irq_exit+0x180/0x1d0 kernel/softirq.c:412

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

CPU0
----
lock(&(&local->client_conns_lock)->rlock);
<Interrupt>
lock(&(&local->client_conns_lock)->rlock);

*** DEADLOCK ***

2 locks held by syz-fuzzer/8087:
#0: 00000000ae937205 (&mm->mmap_sem){++++}, at: __do_page_fault+0x3c9/0xe90 arch/x86/mm/fault.c:1319
#1: 00000000dbcf7e29 (rcu_callback){....}, at: __rcu_reclaim kernel/rcu/rcu.h:226 [inline]
#1: 00000000dbcf7e29 (rcu_callback){....}, at: rcu_do_batch kernel/rcu/tree.c:2584 [inline]
#1: 00000000dbcf7e29 (rcu_callback){....}, at: invoke_rcu_callbacks kernel/rcu/tree.c:2897 [inline]
#1: 00000000dbcf7e29 (rcu_callback){....}, at: __rcu_process_callbacks kernel/rcu/tree.c:2864 [inline]
#1: 00000000dbcf7e29 (rcu_callback){....}, at: rcu_process_callbacks+0xc79/0x1a30 kernel/rcu/tree.c:2881

stack backtrace:
CPU: 0 PID: 8087 Comm: syz-fuzzer Not tainted 4.19.103-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_one_client_conn net/rxrpc/conn_client.c:949 [inline]
rxrpc_put_client_conn+0x683/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:___might_sleep+0x1f4/0x2b0 kernel/sched/core.c:6157
Code: 84 d2 74 05 e8 dd 74 59 00 41 f6 46 24 02 0f 85 b3 fe ff ff e9 ea fe ff ff be ff ff ff ff 48 c7 c7 a0 34 f9 88 e8 ac 3b 08 00 <85> c0 0f 84 2f fe ff ff 48 c7 c2 60 35 aa 87 be 0d 18 00 00 48 c7
RSP: 0000:ffff88807bc4f8e8 EFLAGS: 00000296 ORIG_RAX: ffffffffffffff13
RAX: 0000000000000000 RBX: 0000000000000000 RCX: ffff888088bcac80
RDX: dffffc0000000000 RSI: ffffffff88f934a0 RDI: 0000000000000282
RBP: ffff88807bc4f910 R08: ffff888088bca400 R09: 0000000000000001
R10: ffff888088bcaca8 R11: ffffffff8a799420 R12: ffffffff87b17260
R13: 00000000000010f6 R14: 0000000000000000 R15: 0000000000000001
__might_sleep+0x95/0x190 kernel/sched/core.c:6145
prepare_alloc_pages mm/page_alloc.c:4342 [inline]
__alloc_pages_nodemask+0x4ec/0x750 mm/page_alloc.c:4391
alloc_pages_vma+0xdd/0x590 mm/mempolicy.c:2161
alloc_zeroed_user_highpage_movable include/linux/highmem.h:184 [inline]
wp_page_copy+0xc75/0x16a0 mm/memory.c:2508
do_wp_page+0x57d/0x10b0 mm/memory.c:2799
handle_pte_fault mm/memory.c:4057 [inline]
__handle_mm_fault+0x2305/0x3f80 mm/memory.c:4165
handle_mm_fault+0x1b5/0x690 mm/memory.c:4202
__do_page_fault+0x62a/0xe90 arch/x86/mm/fault.c:1390
do_page_fault+0x71/0x57d arch/x86/mm/fault.c:1465
page_fault+0x1e/0x30 arch/x86/entry/entry_64.S:1204
RIP: 0033:0x40ad42
Code: 00 83 e1 0f bf 01 00 00 00 d3 e7 66 39 fa 73 8b 4d 85 d2 74 32 48 c1 e8 38 3c 04 73 03 83 c0 04 41 84 02 4d 89 c1 49 83 e0 07 <43> 88 04 02 4c 89 d0 4b 8d 4c 8a 08 8b 54 24 58 89 11 48 ff 03 49
RSP: 002b:000000c4288f5b78 EFLAGS: 00010246
RAX: 000000000000001b RBX: 000000c4299d5830 RCX: 000000000000000a
RDX: 0000000000000000 RSI: 0000000000866760 RDI: 0000000000000400
RBP: 000000c4288f5bb0 R08: 0000000000000000 R09: 0000000000000000
R10: 000000c429a3e300 R11: 0000000000000004 R12: 0000000000000000
R13: 0000000000000018 R14: 0000000000000057 R15: 0000000000000100
loop3: p1 p2 p3 p4
loop3: p1 size 11290111 extends beyond EOD, truncated
loop3: p2 size 1073741824 extends beyond EOD, truncated
loop3: p3 size 1912633224 extends beyond EOD, truncated
loop3: p4 size 3657465856 extends beyond EOD, truncated
loop3: p1 p2 p3 p4
loop3: p1 size 11290111 extends beyond EOD, truncated
loop3: p2 size 1073741824 extends beyond EOD, truncated
loop3: p3 size 1912633224 extends beyond EOD, truncated
loop3: p4 size 3657465856 extends beyond EOD, truncated
loop3: p1 p2 p3 p4
loop3: p1 size 11290111 extends beyond EOD, truncated
loop3: p2 size 1073741824 extends beyond EOD, truncated
loop3: p3 size 1912633224 extends beyond EOD, truncated
loop3: p4 size 3657465856 extends beyond EOD, truncated
loop3: p1 p2 p3 p4
loop3: p1 size 11290111 extends beyond EOD, truncated
loop3: p2 size 1073741824 extends beyond EOD, truncated
loop3: p3 size 1912633224 extends beyond EOD, truncated
loop3: p4 size 3657465856 extends beyond EOD, truncated
audit: type=1804 audit(1581434511.459:88): pid=10018 uid=0 auid=4294967295 ses=4294967295 subj=unconfined_u:system_r:insmod_t:s0-s0:c0.c1023 op=invalid_pcr cause=open_writers comm="syz-executor.5" name="/root/syzkaller-testdir298014258/syzkaller.h37ArO/72/file0" dev="sda1" ino=16717 res=1
hid-generic 0000:0000:0000.0001: ignoring exceeding usage max
hid-generic 0000:0000:0000.0001: hidraw0: <UNKNOWN> HID v0.00 Device [syz1 ] on s�z1
audit: type=1804 audit(1581434511.609:89): pid=10018 uid=0 auid=4294967295 ses=4294967295 subj=unconfined_u:system_r:insmod_t:s0-s0:c0.c1023 op=invalid_pcr cause=open_writers comm="syz-executor.5" name="/root/syzkaller-testdir298014258/syzkaller.h37ArO/72/file0" dev="sda1" ino=16717 res=1
hid-generic 0000:0000:0000.0002: ignoring exceeding usage max
hid-generic 0000:0000:0000.0002: hidraw0: <UNKNOWN> HID v0.00 Device [syz1 ] on s�z1
hid-generic 0000:0000:0000.0003: ignoring exceeding usage max
audit: type=1804 audit(1581434511.869:90): pid=10066 uid=0 auid=4294967295 ses=4294967295 subj=unconfined_u:system_r:insmod_t:s0-s0:c0.c1023 op=invalid_pcr cause=open_writers comm="syz-executor.5" name="/root/syzkaller-testdir298014258/syzkaller.h37ArO/73/file0" dev="sda1" ino=16742 res=1
hid-generic 0000:0000:0000.0003: hidraw0: <UNKNOWN> HID v0.00 Device [syz1 ] on s�z1
hid-generic 0000:0000:0000.0004: ignoring exceeding usage max
hid-generic 0000:0000:0000.0004: hidraw0: <UNKNOWN> HID v0.00 Device [syz1 ] on s�z1
hid-generic 0000:0000:0000.0005: ignoring exceeding usage max
hid-generic 0000:0000:0000.0005: hidraw0: <UNKNOWN> HID v0.00 Device [syz1 ] on s�z1
audit: type=1804 audit(1581434514.919:91): pid=10118 uid=0 auid=4294967295 ses=4294967295 subj=unconfined_u:system_r:insmod_t:s0-s0:c0.c1023 op=invalid_pcr cause=open_writers comm="syz-executor.5" name="/root/syzkaller-testdir298014258/syzkaller.h37ArO/74/file0" dev="sda1" ino=16752 res=1


---
This bug 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 bug report. See:
https://goo.gl/tpsmEJ#status for how to communicate with syzbot.

syzbot

unread,
Feb 11, 2020, 5:14:14 PM2/11/20
to syzkaller...@googlegroups.com
syzbot has found a reproducer for the following crash on:

HEAD commit: 35766839 Linux 4.19.103
git tree: linux-4.19.y
console output: https://syzkaller.appspot.com/x/log.txt?x=17504065e00000
kernel config: https://syzkaller.appspot.com/x/.config?x=84f14e7b6cbc7d27
dashboard link: https://syzkaller.appspot.com/bug?extid=19114525476fe0be9e7b
compiler: gcc (GCC) 9.0.0 20181231 (experimental)
syz repro: https://syzkaller.appspot.com/x/repro.syz?x=1363aa31e00000
C reproducer: https://syzkaller.appspot.com/x/repro.c?x=140b634ee00000

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

audit: type=1400 audit(1581459062.954:36): avc: denied { map } for pid=8321 comm="syz-executor451" path="/root/syz-executor451532386" dev="sda1" ino=16484 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.103-syzkaller #0 Not tainted
--------------------------------
inconsistent {SOFTIRQ-ON-W} -> {IN-SOFTIRQ-W} usage.
swapper/1/0 [HC0[0]:SC1[1]:HE1:SE0] takes:
000000008093ceed (&(&local->client_conns_lock)->rlock){+.?.}, at: spin_lock include/linux/spinlock.h:329 [inline]
000000008093ceed (&(&local->client_conns_lock)->rlock){+.?.}, at: rxrpc_put_one_client_conn net/rxrpc/conn_client.c:949 [inline]
000000008093ceed (&(&local->client_conns_lock)->rlock){+.?.}, at: rxrpc_put_client_conn+0x683/0xc20 net/rxrpc/conn_client.c:1002
{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_conn net/rxrpc/conn_client.c:309 [inline]
rxrpc_connect_call+0x351/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: 157726
hardirqs last enabled at (157726): [<ffffffff87553a3b>] __raw_spin_unlock_irqrestore include/linux/spinlock_api_smp.h:160 [inline]
hardirqs last enabled at (157726): [<ffffffff87553a3b>] _raw_spin_unlock_irqrestore+0x6b/0xe0 kernel/locking/spinlock.c:184
hardirqs last disabled at (157725): [<ffffffff87553ccf>] __raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:108 [inline]
hardirqs last disabled at (157725): [<ffffffff87553ccf>] _raw_spin_lock_irqsave+0x6f/0xcd kernel/locking/spinlock.c:152
softirqs last enabled at (157610): [<ffffffff81402cdc>] _local_bh_enable+0x1c/0x30 kernel/softirq.c:162
softirqs last disabled at (157611): [<ffffffff81405860>] invoke_softirq kernel/softirq.c:372 [inline]
softirqs last disabled at (157611): [<ffffffff81405860>] irq_exit+0x180/0x1d0 kernel/softirq.c:412

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

CPU0
----
lock(&(&local->client_conns_lock)->rlock);
<Interrupt>
lock(&(&local->client_conns_lock)->rlock);

*** DEADLOCK ***

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

stack backtrace:
CPU: 1 PID: 0 Comm: swapper/1 Not tainted 4.19.103-syzkaller #0
RIP: 0010:native_safe_halt+0xe/0x10 arch/x86/include/asm/irqflags.h:61
Code: ff ff 48 89 df e8 42 aa 4d fa eb 82 e9 07 00 00 00 0f 00 2d 74 c2 52 00 f4 c3 66 90 e9 07 00 00 00 0f 00 2d 64 c2 52 00 fb f4 <c3> 90 55 48 89 e5 41 57 41 56 41 55 41 54 53 e8 6e 7e 04 fa e8 19
RSP: 0018:ffff8880aa3b7d08 EFLAGS: 00000286 ORIG_RAX: ffffffffffffff13
RAX: 1ffffffff11e4aec RBX: ffff8880aa3a43c0 RCX: 0000000000000000
RDX: dffffc0000000000 RSI: 0000000000000001 RDI: ffff8880aa3a4c3c
RBP: ffff8880aa3b7d38 R08: ffff8880aa3a43c0 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000000 R12: 0000000000000001
R13: ffffffff88f25750 R14: 0000000000000000 R15: ffff8880aa3a43c0
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

syzbot

unread,
Feb 14, 2020, 5:06:12 PM2/14/20
to syzkaller...@googlegroups.com
Hello,

syzbot found the following crash on:

HEAD commit: 98db2bf2 Linux 4.14.171
git tree: linux-4.14.y
console output: https://syzkaller.appspot.com/x/log.txt?x=16895c09e00000
kernel config: https://syzkaller.appspot.com/x/.config?x=9dc3f6f9d0ff3b98
dashboard link: https://syzkaller.appspot.com/bug?extid=6eafa608d39089492895
compiler: gcc (GCC) 9.0.0 20181231 (experimental)

Unfortunately, I don't have any reproducer for this crash yet.

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

================================
WARNING: inconsistent lock state
4.14.171-syzkaller #0 Not tainted
--------------------------------
inconsistent {SOFTIRQ-ON-W} -> {IN-SOFTIRQ-W} usage.
ksoftirqd/1/17 [HC0[0]:SC1[1]:HE1:SE0] takes:
(&(&local->client_conns_lock)->rlock){+.?.}, at: [<ffffffff85de67d8>] spin_lock include/linux/spinlock.h:317 [inline]
(&(&local->client_conns_lock)->rlock){+.?.}, at: [<ffffffff85de67d8>] rxrpc_put_one_client_conn net/rxrpc/conn_client.c:905 [inline]
(&(&local->client_conns_lock)->rlock){+.?.}, at: [<ffffffff85de67d8>] rxrpc_put_client_conn+0x538/0xaa0 net/rxrpc/conn_client.c:957
{SOFTIRQ-ON-W} state was registered at:
mark_irqflags kernel/locking/lockdep.c:3086 [inline]
__lock_acquire+0xc33/0x4620 kernel/locking/lockdep.c:3444
lock_acquire+0x16f/0x430 kernel/locking/lockdep.c:3994
__raw_spin_lock include/linux/spinlock_api_smp.h:142 [inline]
_raw_spin_lock+0x2f/0x40 kernel/locking/spinlock.c:152
spin_lock include/linux/spinlock.h:317 [inline]
rxrpc_get_client_conn net/rxrpc/conn_client.c:306 [inline]
rxrpc_connect_call+0x2f5/0x41a0 net/rxrpc/conn_client.c:692
rxrpc_new_client_call+0x8f7/0x1420 net/rxrpc/call_object.c:276
rxrpc_new_client_call_for_sendmsg net/rxrpc/sendmsg.c:525 [inline]
rxrpc_do_sendmsg+0x92a/0x1109 net/rxrpc/sendmsg.c:577
rxrpc_sendmsg+0x4d1/0x610 net/rxrpc/af_rxrpc.c:543
sock_sendmsg_nosec net/socket.c:646 [inline]
sock_sendmsg+0xce/0x110 net/socket.c:656
___sys_sendmsg+0x349/0x840 net/socket.c:2062
__sys_sendmmsg+0x152/0x3a0 net/socket.c:2152
SYSC_sendmmsg net/socket.c:2183 [inline]
SyS_sendmmsg+0x35/0x60 net/socket.c:2178
do_syscall_64+0x1e8/0x640 arch/x86/entry/common.c:292
entry_SYSCALL_64_after_hwframe+0x42/0xb7
irq event stamp: 2093464
hardirqs last enabled at (2093464): [<ffffffff866945cb>] __raw_spin_unlock_irqrestore include/linux/spinlock_api_smp.h:160 [inline]
hardirqs last enabled at (2093464): [<ffffffff866945cb>] _raw_spin_unlock_irqrestore+0x6b/0xe0 kernel/locking/spinlock.c:192
hardirqs last disabled at (2093463): [<ffffffff8669485f>] __raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:108 [inline]
hardirqs last disabled at (2093463): [<ffffffff8669485f>] _raw_spin_lock_irqsave+0x6f/0xcd kernel/locking/spinlock.c:160
softirqs last enabled at (2093412): [<ffffffff86a00645>] __do_softirq+0x645/0x9a0 kernel/softirq.c:314
softirqs last disabled at (2093417): [<ffffffff813902ec>] run_ksoftirqd kernel/softirq.c:670 [inline]
softirqs last disabled at (2093417): [<ffffffff813902ec>] run_ksoftirqd+0x8c/0x1b0 kernel/softirq.c:662

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

CPU0
----
lock(&(&local->client_conns_lock)->rlock);
<Interrupt>
lock(&(&local->client_conns_lock)->rlock);

*** DEADLOCK ***

1 lock held by ksoftirqd/1/17:
#0: (rcu_callback){....}, at: [<ffffffff814e5703>] __rcu_reclaim kernel/rcu/rcu.h:185 [inline]
#0: (rcu_callback){....}, at: [<ffffffff814e5703>] rcu_do_batch kernel/rcu/tree.c:2699 [inline]
#0: (rcu_callback){....}, at: [<ffffffff814e5703>] invoke_rcu_callbacks kernel/rcu/tree.c:2962 [inline]
#0: (rcu_callback){....}, at: [<ffffffff814e5703>] __rcu_process_callbacks kernel/rcu/tree.c:2929 [inline]
#0: (rcu_callback){....}, at: [<ffffffff814e5703>] rcu_process_callbacks+0x893/0x12b0 kernel/rcu/tree.c:2946

stack backtrace:
CPU: 1 PID: 17 Comm: ksoftirqd/1 Not tainted 4.14.171-syzkaller #0
Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
Call Trace:
__dump_stack lib/dump_stack.c:17 [inline]
dump_stack+0x142/0x197 lib/dump_stack.c:58
print_usage_bug.cold+0x330/0x42a kernel/locking/lockdep.c:2585
valid_state kernel/locking/lockdep.c:2598 [inline]
mark_lock_irq kernel/locking/lockdep.c:2792 [inline]
mark_lock+0xdbd/0x1240 kernel/locking/lockdep.c:3190
mark_irqflags kernel/locking/lockdep.c:3068 [inline]
__lock_acquire+0xb57/0x4620 kernel/locking/lockdep.c:3444
lock_acquire+0x16f/0x430 kernel/locking/lockdep.c:3994
__raw_spin_lock include/linux/spinlock_api_smp.h:142 [inline]
_raw_spin_lock+0x2f/0x40 kernel/locking/spinlock.c:152
spin_lock include/linux/spinlock.h:317 [inline]
rxrpc_put_one_client_conn net/rxrpc/conn_client.c:905 [inline]
rxrpc_put_client_conn+0x538/0xaa0 net/rxrpc/conn_client.c:957
rxrpc_put_connection net/rxrpc/ar-internal.h:862 [inline]
rxrpc_rcu_destroy_call+0x88/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+0x7b8/0x12b0 kernel/rcu/tree.c:2946
__do_softirq+0x244/0x9a0 kernel/softirq.c:288
run_ksoftirqd kernel/softirq.c:670 [inline]
run_ksoftirqd+0x8c/0x1b0 kernel/softirq.c:662
smpboot_thread_fn+0x5f4/0x960 kernel/smpboot.c:164
kthread+0x319/0x430 kernel/kthread.c:232
ret_from_fork+0x24/0x30 arch/x86/entry/entry_64.S:404

syzbot

unread,
Feb 14, 2020, 5:42:15 PM2/14/20
to syzkaller...@googlegroups.com
syzbot has found a reproducer for the following crash on:

HEAD commit: 98db2bf2 Linux 4.14.171
git tree: linux-4.14.y
console output: https://syzkaller.appspot.com/x/log.txt?x=169f0ae6e00000
kernel config: https://syzkaller.appspot.com/x/.config?x=9dc3f6f9d0ff3b98
dashboard link: https://syzkaller.appspot.com/bug?extid=6eafa608d39089492895
compiler: gcc (GCC) 9.0.0 20181231 (experimental)
syz repro: https://syzkaller.appspot.com/x/repro.syz?x=16c95c09e00000
C reproducer: https://syzkaller.appspot.com/x/repro.c?x=111532a1e00000

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

audit: type=1400 audit(1581719953.878:36): avc: denied { map } for pid=7338 comm="syz-executor590" path="/root/syz-executor590385341" dev="sda1" ino=16484 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.14.171-syzkaller #0 Not tainted
--------------------------------
inconsistent {SOFTIRQ-ON-W} -> {IN-SOFTIRQ-W} usage.
swapper/0/0 [HC0[0]:SC1[1]:HE1:SE0] takes:
(&(&local->client_conns_lock)->rlock){+.?.}, at: [<ffffffff85de67d8>] spin_lock include/linux/spinlock.h:317 [inline]
(&(&local->client_conns_lock)->rlock){+.?.}, at: [<ffffffff85de67d8>] rxrpc_put_one_client_conn net/rxrpc/conn_client.c:905 [inline]
(&(&local->client_conns_lock)->rlock){+.?.}, at: [<ffffffff85de67d8>] rxrpc_put_client_conn+0x538/0xaa0 net/rxrpc/conn_client.c:957
{SOFTIRQ-ON-W} state was registered at:
mark_irqflags kernel/locking/lockdep.c:3086 [inline]
__lock_acquire+0xc33/0x4620 kernel/locking/lockdep.c:3444
lock_acquire+0x16f/0x430 kernel/locking/lockdep.c:3994
__raw_spin_lock include/linux/spinlock_api_smp.h:142 [inline]
_raw_spin_lock+0x2f/0x40 kernel/locking/spinlock.c:152
spin_lock include/linux/spinlock.h:317 [inline]
rxrpc_get_client_conn net/rxrpc/conn_client.c:306 [inline]
rxrpc_connect_call+0x2f5/0x41a0 net/rxrpc/conn_client.c:692
rxrpc_new_client_call+0x8f7/0x1420 net/rxrpc/call_object.c:276
rxrpc_new_client_call_for_sendmsg net/rxrpc/sendmsg.c:525 [inline]
rxrpc_do_sendmsg+0x92a/0x1109 net/rxrpc/sendmsg.c:577
rxrpc_sendmsg+0x4d1/0x610 net/rxrpc/af_rxrpc.c:543
sock_sendmsg_nosec net/socket.c:646 [inline]
sock_sendmsg+0xce/0x110 net/socket.c:656
___sys_sendmsg+0x349/0x840 net/socket.c:2062
__sys_sendmmsg+0x152/0x3a0 net/socket.c:2152
SYSC_sendmmsg net/socket.c:2183 [inline]
SyS_sendmmsg+0x35/0x60 net/socket.c:2178
do_syscall_64+0x1e8/0x640 arch/x86/entry/common.c:292
entry_SYSCALL_64_after_hwframe+0x42/0xb7
irq event stamp: 272930
hardirqs last enabled at (272930): [<ffffffff866945cb>] __raw_spin_unlock_irqrestore include/linux/spinlock_api_smp.h:160 [inline]
hardirqs last enabled at (272930): [<ffffffff866945cb>] _raw_spin_unlock_irqrestore+0x6b/0xe0 kernel/locking/spinlock.c:192
hardirqs last disabled at (272929): [<ffffffff8669485f>] __raw_spin_lock_irqsave include/linux/spinlock_api_smp.h:108 [inline]
hardirqs last disabled at (272929): [<ffffffff8669485f>] _raw_spin_lock_irqsave+0x6f/0xcd kernel/locking/spinlock.c:160
softirqs last enabled at (272894): [<ffffffff8138e3bc>] _local_bh_enable+0x1c/0x30 kernel/softirq.c:159
softirqs last disabled at (272895): [<ffffffff81390670>] invoke_softirq kernel/softirq.c:368 [inline]
softirqs last disabled at (272895): [<ffffffff81390670>] irq_exit+0x160/0x1b0 kernel/softirq.c:409

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

CPU0
----
lock(&(&local->client_conns_lock)->rlock);
<Interrupt>
lock(&(&local->client_conns_lock)->rlock);

*** DEADLOCK ***

1 lock held by swapper/0/0:
#0: (rcu_callback){....}, at: [<ffffffff814e5703>] __rcu_reclaim kernel/rcu/rcu.h:185 [inline]
#0: (rcu_callback){....}, at: [<ffffffff814e5703>] rcu_do_batch kernel/rcu/tree.c:2699 [inline]
#0: (rcu_callback){....}, at: [<ffffffff814e5703>] invoke_rcu_callbacks kernel/rcu/tree.c:2962 [inline]
#0: (rcu_callback){....}, at: [<ffffffff814e5703>] __rcu_process_callbacks kernel/rcu/tree.c:2929 [inline]
#0: (rcu_callback){....}, at: [<ffffffff814e5703>] rcu_process_callbacks+0x893/0x12b0 kernel/rcu/tree.c:2946

stack backtrace:
CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.14.171-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+0x142/0x197 lib/dump_stack.c:58
print_usage_bug.cold+0x330/0x42a kernel/locking/lockdep.c:2585
valid_state kernel/locking/lockdep.c:2598 [inline]
mark_lock_irq kernel/locking/lockdep.c:2792 [inline]
mark_lock+0xdbd/0x1240 kernel/locking/lockdep.c:3190
mark_irqflags kernel/locking/lockdep.c:3068 [inline]
__lock_acquire+0xb57/0x4620 kernel/locking/lockdep.c:3444
lock_acquire+0x16f/0x430 kernel/locking/lockdep.c:3994
__raw_spin_lock include/linux/spinlock_api_smp.h:142 [inline]
_raw_spin_lock+0x2f/0x40 kernel/locking/spinlock.c:152
spin_lock include/linux/spinlock.h:317 [inline]
rxrpc_put_one_client_conn net/rxrpc/conn_client.c:905 [inline]
rxrpc_put_client_conn+0x538/0xaa0 net/rxrpc/conn_client.c:957
rxrpc_put_connection net/rxrpc/ar-internal.h:862 [inline]
rxrpc_rcu_destroy_call+0x88/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+0x7b8/0x12b0 kernel/rcu/tree.c:2946
__do_softirq+0x244/0x9a0 kernel/softirq.c:288
invoke_softirq kernel/softirq.c:368 [inline]
irq_exit+0x160/0x1b0 kernel/softirq.c:409
exiting_irq arch/x86/include/asm/apic.h:648 [inline]
smp_apic_timer_interrupt+0x146/0x5e0 arch/x86/kernel/apic/apic.c:1102
apic_timer_interrupt+0x96/0xa0 arch/x86/entry/entry_64.S:792
</IRQ>
RIP: 0010:native_safe_halt+0xe/0x10 arch/x86/include/asm/irqflags.h:61
RSP: 0018:ffffffff87e07de8 EFLAGS: 00000282 ORIG_RAX: ffffffffffffff10
RAX: 1ffffffff0fe2ce4 RBX: ffffffff87e76240 RCX: 0000000000000000
RDX: dffffc0000000000 RSI: 0000000000000001 RDI: ffffffff87e76abc
RBP: ffffffff87e07e10 R08: 1ffffffff1164201 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000000 R12: ffffffff87f16710
R13: 0000000000000000 R14: 0000000000000000 R15: ffffffff87e76240
arch_cpu_idle+0xa/0x10 arch/x86/kernel/process.c:557
default_idle_call+0x36/0x90 kernel/sched/idle.c:98
cpuidle_idle_call kernel/sched/idle.c:156 [inline]
do_idle+0x262/0x3d0 kernel/sched/idle.c:246
cpu_startup_entry+0x1b/0x20 kernel/sched/idle.c:351
rest_init+0x1d9/0x1e2 init/main.c:434
start_kernel+0x65f/0x67d init/main.c:708

syzbot

unread,
Mar 29, 2020, 5:34:04 PM3/29/20
to syzkaller...@googlegroups.com
syzbot suspects this bug was fixed by commit:

commit 43cac315bec132e962e04c31fe888caac257ec0a
Author: David Howells <dhow...@redhat.com>
Date: Thu Feb 6 13:57:40 2020 +0000

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

bisection log: https://syzkaller.appspot.com/x/bisect.txt?x=15e52e83e00000
start commit: f25804f3 Linux 4.19.106
git tree: linux-4.19.y
kernel config: https://syzkaller.appspot.com/x/.config?x=a5f029a69ae922fd
dashboard link: https://syzkaller.appspot.com/bug?extid=19114525476fe0be9e7b
syz repro: https://syzkaller.appspot.com/x/repro.syz?x=16fe3bd9e00000
C reproducer: https://syzkaller.appspot.com/x/repro.c?x=177ffbe9e00000

If the result looks correct, please mark the bug fixed by replying with:

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

For information about bisection process see: https://goo.gl/tpsmEJ#bisection
Reply all
Reply to author
Forward
0 new messages