inconsistent lock state in sco_sock_timeout

13 views
Skip to first unread message

syzbot

unread,
Aug 8, 2020, 6:36:36 PM8/8/20
to syzkaller...@googlegroups.com
Hello,

syzbot found the following issue on:

HEAD commit: 14b58326 Linux 4.14.193
git tree: linux-4.14.y
console output: https://syzkaller.appspot.com/x/log.txt?x=118ea5e6900000
kernel config: https://syzkaller.appspot.com/x/.config?x=68ef0287ccbc3b42
dashboard link: https://syzkaller.appspot.com/bug?extid=0aaddce8deb6b82ba8f4
compiler: gcc (GCC) 10.1.0-syz 20200507

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

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

================================
WARNING: inconsistent lock state
4.14.193-syzkaller #0 Not tainted
--------------------------------
inconsistent {SOFTIRQ-ON-W} -> {IN-SOFTIRQ-W} usage.
swapper/1/0 [HC0[0]:SC1[1]:HE1:SE0] takes:
(slock-AF_BLUETOOTH-BTPROTO_SCO){+.?.}, at: [<ffffffff85bb51ba>] spin_lock include/linux/spinlock.h:317 [inline]
(slock-AF_BLUETOOTH-BTPROTO_SCO){+.?.}, at: [<ffffffff85bb51ba>] sco_sock_timeout+0x1a/0x150 net/bluetooth/sco.c:82
{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]
sco_conn_del+0xb0/0x1e0 net/bluetooth/sco.c:175
sco_disconn_cfm net/bluetooth/sco.c:1134 [inline]
sco_disconn_cfm+0x50/0x60 net/bluetooth/sco.c:1127
hci_disconn_cfm include/net/bluetooth/hci_core.h:1226 [inline]
hci_conn_hash_flush+0x114/0x220 net/bluetooth/hci_conn.c:1376
hci_dev_do_close+0x542/0xc50 net/bluetooth/hci_core.c:1620
hci_unregister_dev+0x170/0x7a0 net/bluetooth/hci_core.c:3191
vhci_release+0x70/0xe0 drivers/bluetooth/hci_vhci.c:354
__fput+0x25f/0x7a0 fs/file_table.c:210
task_work_run+0x11f/0x190 kernel/task_work.c:113
exit_task_work include/linux/task_work.h:22 [inline]
do_exit+0xa08/0x27f0 kernel/exit.c:865
do_group_exit+0x100/0x2e0 kernel/exit.c:962
get_signal+0x38d/0x1ca0 kernel/signal.c:2423
do_signal+0x7c/0x1550 arch/x86/kernel/signal.c:814
exit_to_usermode_loop+0x160/0x200 arch/x86/entry/common.c:160
prepare_exit_to_usermode arch/x86/entry/common.c:199 [inline]
syscall_return_slowpath arch/x86/entry/common.c:270 [inline]
do_syscall_64+0x4a3/0x640 arch/x86/entry/common.c:297
entry_SYSCALL_64_after_hwframe+0x46/0xbb
irq event stamp: 37331864
hardirqs last enabled at (37331864): [<ffffffff86545f44>] __raw_spin_unlock_irq include/linux/spinlock_api_smp.h:168 [inline]
hardirqs last enabled at (37331864): [<ffffffff86545f44>] _raw_spin_unlock_irq+0x24/0x80 kernel/locking/spinlock.c:200
hardirqs last disabled at (37331863): [<ffffffff86545bd5>] __raw_spin_lock_irq include/linux/spinlock_api_smp.h:126 [inline]
hardirqs last disabled at (37331863): [<ffffffff86545bd5>] _raw_spin_lock_irq+0x35/0x80 kernel/locking/spinlock.c:168
softirqs last enabled at (37331856): [<ffffffff8137728d>] irq_enter+0xbd/0xd0 kernel/softirq.c:350
softirqs last disabled at (37331857): [<ffffffff81377433>] invoke_softirq kernel/softirq.c:368 [inline]
softirqs last disabled at (37331857): [<ffffffff81377433>] irq_exit+0x193/0x240 kernel/softirq.c:409

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

CPU0
----
lock(slock-AF_BLUETOOTH-BTPROTO_SCO);
<Interrupt>
lock(slock-AF_BLUETOOTH-BTPROTO_SCO);

*** DEADLOCK ***

1 lock held by swapper/1/0:
#0: (((&sk->sk_timer))#2){+.-.}, at: [<ffffffff814ea3d8>] lockdep_copy_map include/linux/lockdep.h:174 [inline]
#0: (((&sk->sk_timer))#2){+.-.}, at: [<ffffffff814ea3d8>] call_timer_fn+0xb8/0x650 kernel/time/timer.c:1270

stack backtrace:
CPU: 1 PID: 0 Comm: swapper/1 Not tainted 4.14.193-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+0xb4d/0x1050 kernel/locking/lockdep.c:3194
mark_irqflags kernel/locking/lockdep.c:3072 [inline]
__lock_acquire+0xc81/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]
sco_sock_timeout+0x1a/0x150 net/bluetooth/sco.c:82
call_timer_fn+0x14a/0x650 kernel/time/timer.c:1280
expire_timers+0x232/0x4d0 kernel/time/timer.c:1319
__run_timers kernel/time/timer.c:1644 [inline]
run_timer_softirq+0x1d5/0x5a0 kernel/time/timer.c:1657
__do_softirq+0x254/0xa1d kernel/softirq.c:288
invoke_softirq kernel/softirq.c:368 [inline]
irq_exit+0x193/0x240 kernel/softirq.c:409
exiting_irq arch/x86/include/asm/apic.h:648 [inline]
smp_apic_timer_interrupt+0x141/0x5e0 arch/x86/kernel/apic/apic.c:1102
apic_timer_interrupt+0x93/0xa0 arch/x86/entry/entry_64.S:793
</IRQ>
RIP: 0010:native_safe_halt+0xe/0x10 arch/x86/include/asm/irqflags.h:61
RSP: 0018:ffff8880a98d7ea8 EFLAGS: 00000286 ORIG_RAX: ffffffffffffff10
RAX: 1ffffffff0fa2d24 RBX: dffffc0000000000 RCX: 0000000000000000
RDX: dffffc0000000000 RSI: 0000000000000001 RDI: ffff8880a98c4bc4
RBP: ffffffff87d16910 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000000 R12: ffffed1015318868
R13: ffff8880a98c4340 R14: 0000000000000000 R15: 0000000000000000
arch_safe_halt arch/x86/include/asm/paravirt.h:94 [inline]
default_idle+0x47/0x370 arch/x86/kernel/process.c:558
cpuidle_idle_call kernel/sched/idle.c:156 [inline]
do_idle+0x250/0x3c0 kernel/sched/idle.c:246
cpu_startup_entry+0x14/0x20 kernel/sched/idle.c:351
start_secondary+0x488/0x5f0 arch/x86/kernel/smpboot.c:272
secondary_startup_64+0xa5/0xb0 arch/x86/kernel/head_64.S:240
netlink: 24 bytes leftover after parsing attributes in process `syz-executor.2'.
netlink: 24 bytes leftover after parsing attributes in process `syz-executor.1'.
netlink: 36 bytes leftover after parsing attributes in process `syz-executor.1'.
netlink: 24 bytes leftover after parsing attributes in process `syz-executor.1'.
netlink: 36 bytes leftover after parsing attributes in process `syz-executor.1'.
netlink: 24 bytes leftover after parsing attributes in process `syz-executor.1'.
netlink: 24 bytes leftover after parsing attributes in process `syz-executor.1'.


---
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

unread,
Aug 17, 2020, 7:02:24 AM8/17/20
to syzkaller...@googlegroups.com
syzbot has found a reproducer for the following issue on:

HEAD commit: 14b58326 Linux 4.14.193
git tree: linux-4.14.y
console output: https://syzkaller.appspot.com/x/log.txt?x=1030f79a900000
syz repro: https://syzkaller.appspot.com/x/repro.syz?x=1316c25e900000
C reproducer: https://syzkaller.appspot.com/x/repro.c?x=17ea847a900000

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

================================
WARNING: inconsistent lock state
4.14.193-syzkaller #0 Not tainted
--------------------------------
inconsistent {SOFTIRQ-ON-W} -> {IN-SOFTIRQ-W} usage.
swapper/0/0 [HC0[0]:SC1[1]:HE1:SE0] takes:
irq event stamp: 1503614
hardirqs last enabled at (1503614): [<ffffffff86545f44>] __raw_spin_unlock_irq include/linux/spinlock_api_smp.h:168 [inline]
hardirqs last enabled at (1503614): [<ffffffff86545f44>] _raw_spin_unlock_irq+0x24/0x80 kernel/locking/spinlock.c:200
hardirqs last disabled at (1503613): [<ffffffff86545bd5>] __raw_spin_lock_irq include/linux/spinlock_api_smp.h:126 [inline]
hardirqs last disabled at (1503613): [<ffffffff86545bd5>] _raw_spin_lock_irq+0x35/0x80 kernel/locking/spinlock.c:168
softirqs last enabled at (1503606): [<ffffffff8137728d>] irq_enter+0xbd/0xd0 kernel/softirq.c:350
softirqs last disabled at (1503607): [<ffffffff81377433>] invoke_softirq kernel/softirq.c:368 [inline]
softirqs last disabled at (1503607): [<ffffffff81377433>] irq_exit+0x193/0x240 kernel/softirq.c:409

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

CPU0
----
lock(slock-AF_BLUETOOTH-BTPROTO_SCO);
<Interrupt>
lock(slock-AF_BLUETOOTH-BTPROTO_SCO);

*** DEADLOCK ***

1 lock held by swapper/0/0:
#0: (((&sk->sk_timer))){+.-.}, at: [<ffffffff814ea3d8>] lockdep_copy_map include/linux/lockdep.h:174 [inline]
#0: (((&sk->sk_timer))){+.-.}, at: [<ffffffff814ea3d8>] call_timer_fn+0xb8/0x650 kernel/time/timer.c:1270

stack backtrace:
CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.14.193-syzkaller #0
RSP: 0018:ffffffff87c07e78 EFLAGS: 00000286 ORIG_RAX: ffffffffffffff10
RAX: 1ffffffff0fa2d24 RBX: dffffc0000000000 RCX: 0000000000000000
RDX: dffffc0000000000 RSI: 0000000000000001 RDI: ffffffff87c76b44
RBP: ffffffff87d16910 R08: 0000000000000000 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000000 R12: fffffbfff0f8ec58
R13: ffffffff87c762c0 R14: 0000000000000000 R15: 0000000000000000
arch_safe_halt arch/x86/include/asm/paravirt.h:94 [inline]
default_idle+0x47/0x370 arch/x86/kernel/process.c:558
cpuidle_idle_call kernel/sched/idle.c:156 [inline]
do_idle+0x250/0x3c0 kernel/sched/idle.c:246
cpu_startup_entry+0x14/0x20 kernel/sched/idle.c:351
start_kernel+0x750/0x770 init/main.c:708
secondary_startup_64+0xa5/0xb0 arch/x86/kernel/head_64.S:240

syzbot

unread,
Aug 17, 2020, 2:32:27 PM8/17/20
to syzkaller...@googlegroups.com
Hello,

syzbot found the following issue on:

HEAD commit: c14d30dc Linux 4.19.139
git tree: linux-4.19.y
console output: https://syzkaller.appspot.com/x/log.txt?x=150e876a900000
kernel config: https://syzkaller.appspot.com/x/.config?x=93b261233af4719e
dashboard link: https://syzkaller.appspot.com/bug?extid=3257b5a27d60dc9d951d
compiler: gcc (GCC) 10.1.0-syz 20200507
syz repro: https://syzkaller.appspot.com/x/repro.syz?x=10b29c36900000

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

device hsr_slave_0 entered promiscuous mode
device hsr_slave_1 entered promiscuous mode
IPv6: ADDRCONF(NETDEV_UP): hsr_slave_0: link is not ready
IPv6: ADDRCONF(NETDEV_UP): hsr_slave_1: link is not ready
================================
WARNING: inconsistent lock state
4.19.139-syzkaller #0 Not tainted
--------------------------------
inconsistent {SOFTIRQ-ON-W} -> {IN-SOFTIRQ-W} usage.
syz-executor.0/31378 [HC0[0]:SC1[1]:HE1:SE0] takes:
000000004334ec15 (slock-AF_BLUETOOTH-BTPROTO_SCO){+.?.}, at: spin_lock include/linux/spinlock.h:329 [inline]
000000004334ec15 (slock-AF_BLUETOOTH-BTPROTO_SCO){+.?.}, at: sco_sock_timeout+0x22/0x190 net/bluetooth/sco.c:82
{SOFTIRQ-ON-W} state was registered at:
__raw_spin_lock include/linux/spinlock_api_smp.h:142 [inline]
_raw_spin_lock+0x2a/0x40 kernel/locking/spinlock.c:144
spin_lock include/linux/spinlock.h:329 [inline]
sco_conn_del+0xb0/0x220 net/bluetooth/sco.c:175
sco_disconn_cfm net/bluetooth/sco.c:1133 [inline]
sco_disconn_cfm+0x62/0x80 net/bluetooth/sco.c:1126
hci_disconn_cfm include/net/bluetooth/hci_core.h:1261 [inline]
hci_conn_hash_flush+0x114/0x220 net/bluetooth/hci_conn.c:1495
hci_dev_do_close+0x624/0xe70 net/bluetooth/hci_core.c:1666
hci_unregister_dev+0x17c/0x7f0 net/bluetooth/hci_core.c:3271
vhci_release+0x70/0xe0 drivers/bluetooth/hci_vhci.c:354
__fput+0x2ce/0x890 fs/file_table.c:278
task_work_run+0x148/0x1c0 kernel/task_work.c:113
exit_task_work include/linux/task_work.h:22 [inline]
do_exit+0xbb2/0x2b70 kernel/exit.c:887
do_group_exit+0x125/0x310 kernel/exit.c:990
get_signal+0x3f2/0x1f70 kernel/signal.c:2588
do_signal+0x8f/0x1670 arch/x86/kernel/signal.c:821
exit_to_usermode_loop+0x204/0x2a0 arch/x86/entry/common.c:163
prepare_exit_to_usermode arch/x86/entry/common.c:198 [inline]
syscall_return_slowpath arch/x86/entry/common.c:271 [inline]
do_syscall_64+0x538/0x620 arch/x86/entry/common.c:296
entry_SYSCALL_64_after_hwframe+0x49/0xbe
irq event stamp: 62748
hardirqs last enabled at (62748): [<ffffffff873d6274>] __raw_spin_unlock_irq include/linux/spinlock_api_smp.h:168 [inline]
hardirqs last enabled at (62748): [<ffffffff873d6274>] _raw_spin_unlock_irq+0x24/0x80 kernel/locking/spinlock.c:192
hardirqs last disabled at (62747): [<ffffffff873d5f05>] __raw_spin_lock_irq include/linux/spinlock_api_smp.h:126 [inline]
hardirqs last disabled at (62747): [<ffffffff873d5f05>] _raw_spin_lock_irq+0x35/0x80 kernel/locking/spinlock.c:160
softirqs last enabled at (62688): [<ffffffff8564ba23>] spin_unlock_bh include/linux/spinlock.h:374 [inline]
softirqs last enabled at (62688): [<ffffffff8564ba23>] net_to_rxe drivers/infiniband/sw/rxe/rxe_net.c:63 [inline]
softirqs last enabled at (62688): [<ffffffff8564ba23>] rxe_notify+0x503/0x670 drivers/infiniband/sw/rxe/rxe_net.c:652
softirqs last disabled at (62741): [<ffffffff813f36f5>] invoke_softirq kernel/softirq.c:372 [inline]
softirqs last disabled at (62741): [<ffffffff813f36f5>] irq_exit+0x215/0x260 kernel/softirq.c:412

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

CPU0
----
lock(slock-AF_BLUETOOTH-BTPROTO_SCO);
<Interrupt>
lock(slock-AF_BLUETOOTH-BTPROTO_SCO);

*** DEADLOCK ***

2 locks held by syz-executor.0/31378:
#0: 00000000a2b59d99 (rtnl_mutex){+.+.}, at: rtnl_lock net/core/rtnetlink.c:77 [inline]
#0: 00000000a2b59d99 (rtnl_mutex){+.+.}, at: rtnetlink_rcv_msg+0x3fe/0xb80 net/core/rtnetlink.c:4775
#1: 00000000dea5aeea ((&sk->sk_timer)){+.-.}, at: lockdep_copy_map include/linux/lockdep.h:168 [inline]
#1: 00000000dea5aeea ((&sk->sk_timer)){+.-.}, at: call_timer_fn+0xc9/0x700 kernel/time/timer.c:1328

stack backtrace:
CPU: 0 PID: 31378 Comm: syz-executor.0 Not tainted 4.19.139-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+0x1fc/0x2fe lib/dump_stack.c:118
print_usage_bug.cold+0x42e/0x570 kernel/locking/lockdep.c:2544
valid_state kernel/locking/lockdep.c:2557 [inline]
mark_lock_irq kernel/locking/lockdep.c:2751 [inline]
mark_lock+0xc70/0x1160 kernel/locking/lockdep.c:3131
mark_irqflags kernel/locking/lockdep.c:3009 [inline]
__lock_acquire+0xdc4/0x3ff0 kernel/locking/lockdep.c:3372
lock_acquire+0x170/0x3c0 kernel/locking/lockdep.c:3907
__raw_spin_lock include/linux/spinlock_api_smp.h:142 [inline]
_raw_spin_lock+0x2a/0x40 kernel/locking/spinlock.c:144
spin_lock include/linux/spinlock.h:329 [inline]
sco_sock_timeout+0x22/0x190 net/bluetooth/sco.c:82
call_timer_fn+0x177/0x700 kernel/time/timer.c:1338
expire_timers+0x243/0x4e0 kernel/time/timer.c:1375
__run_timers kernel/time/timer.c:1703 [inline]
run_timer_softirq+0x21c/0x670 kernel/time/timer.c:1716
__do_softirq+0x26c/0x9a0 kernel/softirq.c:292
invoke_softirq kernel/softirq.c:372 [inline]
irq_exit+0x215/0x260 kernel/softirq.c:412
exiting_irq arch/x86/include/asm/apic.h:544 [inline]
smp_apic_timer_interrupt+0x136/0x550 arch/x86/kernel/apic/apic.c:1094
apic_timer_interrupt+0xf/0x20 arch/x86/entry/entry_64.S:894
</IRQ>
RIP: 0010:__kernel_text_address+0x4/0x30 kernel/extable.c:107
Code: 32 21 2f 00 0f b6 c0 eb cf 48 c7 c7 c4 41 ae 89 e8 11 85 5a 00 e9 64 ff ff ff 66 90 66 2e 0f 1f 84 00 00 00 00 00 53 48 89 fb <e8> 07 ff ff ff 85 c0 75 17 48 81 fb 00 50 a2 8a 72 0c 31 c0 48 81
RSP: 0018:ffff888076106718 EFLAGS: 00000246 ORIG_RAX: ffffffffffffff13
RAX: dffffc0000000000 RBX: ffffffff81cc8be5 RCX: 0000000000000000
RDX: 1ffff1100ec20cf3 RSI: ffff8880761065f8 RDI: ffffffff81cc8be5
RBP: ffff888076106798 R08: 0000000000000001 R09: 0000000000000001
R10: 0000000000066061 R11: 0000000000000001 R12: ffff8880761067e8
R13: 0000000000000000 R14: ffff8880aa00a840 R15: 00000000000000a0
unwind_get_return_address arch/x86/kernel/unwind_orc.c:297 [inline]
unwind_get_return_address+0x51/0x90 arch/x86/kernel/unwind_orc.c:292
__save_stack_trace+0xaf/0x190 arch/x86/kernel/stacktrace.c:45
save_stack mm/kasan/kasan.c:448 [inline]
set_track mm/kasan/kasan.c:460 [inline]
kasan_kmalloc+0xeb/0x160 mm/kasan/kasan.c:553
slab_post_alloc_hook mm/slab.h:445 [inline]
slab_alloc mm/slab.c:3397 [inline]
kmem_cache_alloc+0x110/0x370 mm/slab.c:3557
kmem_cache_zalloc include/linux/slab.h:699 [inline]
__kernfs_new_node+0xd2/0x680 fs/kernfs/dir.c:633
kernfs_new_node+0x92/0x120 fs/kernfs/dir.c:693
__kernfs_create_file+0x51/0x33f fs/kernfs/file.c:992
sysfs_add_file_mode_ns+0x226/0x540 fs/sysfs/file.c:306
create_files fs/sysfs/group.c:63 [inline]
internal_create_group+0x355/0xb20 fs/sysfs/group.c:147
sysfs_create_group fs/sysfs/group.c:173 [inline]
sysfs_create_groups fs/sysfs/group.c:200 [inline]
sysfs_create_groups+0x98/0x13e fs/sysfs/group.c:190
device_add_groups drivers/base/core.c:1286 [inline]
device_add_attrs drivers/base/core.c:1434 [inline]
device_add+0x803/0x1610 drivers/base/core.c:2123
netdev_register_kobject+0x17d/0x3b0 net/core/net-sysfs.c:1765
register_netdevice+0xb46/0x10f0 net/core/dev.c:8716
veth_newlink+0x4dd/0x930 drivers/net/veth.c:1170
rtnl_newlink+0x1027/0x15b0 net/core/rtnetlink.c:3141
rtnetlink_rcv_msg+0x453/0xb80 net/core/rtnetlink.c:4778
netlink_rcv_skb+0x160/0x440 net/netlink/af_netlink.c:2455
netlink_unicast_kernel net/netlink/af_netlink.c:1318 [inline]
netlink_unicast+0x4d5/0x690 net/netlink/af_netlink.c:1344
netlink_sendmsg+0x6bb/0xc40 net/netlink/af_netlink.c:1909
sock_sendmsg_nosec net/socket.c:622 [inline]
sock_sendmsg+0xc3/0x120 net/socket.c:632
__sys_sendto+0x21a/0x320 net/socket.c:1787
__do_sys_sendto net/socket.c:1799 [inline]
__se_sys_sendto net/socket.c:1795 [inline]
__x64_sys_sendto+0xdd/0x1b0 net/socket.c:1795
do_syscall_64+0xf9/0x620 arch/x86/entry/common.c:293
entry_SYSCALL_64_after_hwframe+0x49/0xbe
RIP: 0033:0x416d07
Code: 2c 00 00 00 0f 05 48 3d 01 f0 ff ff 0f 83 81 19 00 00 c3 48 83 ec 08 e8 87 fa ff ff 48 89 04 24 49 89 ca b8 2c 00 00 00 0f 05 <48> 8b 3c 24 48 89 c2 e8 cd fa ff ff 48 89 d0 48 83 c4 08 48 3d 01
RSP: 002b:00007ffec3b89550 EFLAGS: 00000293 ORIG_RAX: 000000000000002c
RAX: ffffffffffffffda RBX: 00000000016a3700 RCX: 0000000000416d07
RDX: 000000000000006c RSI: 00000000016a3750 RDI: 0000000000000003
RBP: 0000000000000000 R08: 00007ffec3b89560 R09: 000000000000000c
R10: 0000000000000000 R11: 0000000000000293 R12: 0000000000000000
R13: 0000000000000000 R14: 00000000016a3750 R15: 0000000000000003
Bluetooth: hci2: command 0x040f tx timeout
IPv6: ADDRCONF(NETDEV_UP): bridge0: link is not ready
8021q: adding VLAN 0 to HW filter on device bond0
IPv6: ADDRCONF(NETDEV_UP): veth0: link is not ready
IPv6: ADDRCONF(NETDEV_UP): veth1: link is not ready
IPv6: ADDRCONF(NETDEV_CHANGE): veth1: link becomes ready
IPv6: ADDRCONF(NETDEV_CHANGE): veth0: link becomes ready
IPv6: ADDRCONF(NETDEV_UP): team0: link is not ready
8021q: adding VLAN 0 to HW filter on device team0
IPv6: ADDRCONF(NETDEV_UP): veth0_to_bridge: link is not ready
IPv6: ADDRCONF(NETDEV_UP): veth1_to_bridge: link is not ready
IPv6: ADDRCONF(NETDEV_CHANGE): veth0_to_bridge: link becomes ready
IPv6: ADDRCONF(NETDEV_CHANGE): bridge_slave_0: link becomes ready
bridge0: port 1(bridge_slave_0) entered blocking state
bridge0: port 1(bridge_slave_0) entered forwarding state
IPv6: ADDRCONF(NETDEV_CHANGE): veth1_to_bridge: link becomes ready
IPv6: ADDRCONF(NETDEV_CHANGE): bridge_slave_1: link becomes ready
bridge0: port 2(bridge_slave_1) entered blocking state
bridge0: port 2(bridge_slave_1) entered forwarding state
IPv6: ADDRCONF(NETDEV_CHANGE): bridge0: link becomes ready
IPv6: ADDRCONF(NETDEV_UP): veth0_to_bond: link is not ready
IPv6: ADDRCONF(NETDEV_CHANGE): veth0_to_bond: link becomes ready
IPv6: ADDRCONF(NETDEV_UP): veth1_to_bond: link is not ready
IPv6: ADDRCONF(NETDEV_CHANGE): veth1_to_bond: link becomes ready
IPv6: ADDRCONF(NETDEV_UP): veth0_to_team: link is not ready
IPv6: ADDRCONF(NETDEV_UP): veth1_to_team: link is not ready
IPv6: ADDRCONF(NETDEV_CHANGE): veth0_to_team: link becomes ready
IPv6: ADDRCONF(NETDEV_CHANGE): team_slave_0: link becomes ready
IPv6: ADDRCONF(NETDEV_CHANGE): veth1_to_team: link becomes ready
IPv6: ADDRCONF(NETDEV_CHANGE): team_slave_1: link becomes ready
IPv6: ADDRCONF(NETDEV_CHANGE): team0: link becomes ready
IPv6: ADDRCONF(NETDEV_UP): veth0_to_hsr: link is not ready
IPv6: ADDRCONF(NETDEV_CHANGE): veth0_to_hsr: link becomes ready
IPv6: ADDRCONF(NETDEV_CHANGE): hsr_slave_0: link becomes ready
IPv6: ADDRCONF(NETDEV_UP): veth1_to_hsr: link is not ready
IPv6: ADDRCONF(NETDEV_CHANGE): veth1_to_hsr: link becomes ready
IPv6: ADDRCONF(NETDEV_CHANGE): hsr_slave_1: link becomes ready
IPv6: ADDRCONF(NETDEV_UP): hsr0: link is not ready
IPv6: ADDRCONF(NETDEV_CHANGE): hsr0: link becomes ready
IPv6: ADDRCONF(NETDEV_UP): vxcan0: link is not ready
IPv6: ADDRCONF(NETDEV_UP): vxcan1: link is not ready
IPv6: ADDRCONF(NETDEV_CHANGE): vxcan1: link becomes ready
IPv6: ADDRCONF(NETDEV_CHANGE): vxcan0: link becomes ready
8021q: adding VLAN 0 to HW filter on device batadv0
IPv6: ADDRCONF(NETDEV_UP): veth0_virt_wifi: link is not ready
IPv6: ADDRCONF(NETDEV_UP): veth1_virt_wifi: link is not ready
IPv6: ADDRCONF(NETDEV_CHANGE): veth1_virt_wifi: link becomes ready
IPv6: ADDRCONF(NETDEV_CHANGE): veth0_virt_wifi: link becomes ready
IPv6: ADDRCONF(NETDEV_UP): veth0_vlan: link is not ready
IPv6: ADDRCONF(NETDEV_UP): vlan0: link is not ready
IPv6: ADDRCONF(NETDEV_UP): vlan1: link is not ready
IPv6: ADDRCONF(NETDEV_UP): veth1_vlan: link is not ready
IPv6: ADDRCONF(NETDEV_CHANGE): veth1_vlan: link becomes ready
IPv6: ADDRCONF(NETDEV_CHANGE): veth0_vlan: link becomes ready
IPv6: ADDRCONF(NETDEV_CHANGE): vlan0: link becomes ready
IPv6: ADDRCONF(NETDEV_CHANGE): vlan1: link becomes ready
device veth0_vlan entered promiscuous mode
device veth1_vlan entered promiscuous mode
IPv6: ADDRCONF(NETDEV_UP): macvlan0: link is not ready
IPv6: ADDRCONF(NETDEV_UP): macvlan1: link is not ready
IPv6: ADDRCONF(NETDEV_UP): veth0_macvtap: link is not ready
IPv6: ADDRCONF(NETDEV_UP): veth1_macvtap: link is not ready
IPv6: ADDRCONF(NETDEV_CHANGE): macvlan0: link becomes ready
IPv6: ADDRCONF(NETDEV_CHANGE): macvlan1: link becomes ready
IPv6: ADDRCONF(NETDEV_CHANGE): veth1_macvtap: link becomes ready
IPv6: ADDRCONF(NETDEV_CHANGE): veth0_macvtap: link becomes ready
device veth0_macvtap entered promiscuous mode
IPv6: ADDRCONF(NETDEV_UP): macvtap0: link is not ready
device veth1_macvtap entered promiscuous mode
IPv6: ADDRCONF(NETDEV_UP): macsec0: link is not ready
IPv6: ADDRCONF(NETDEV_UP): veth0_to_batadv: link is not ready
IPv6: ADDRCONF(NETDEV_UP): veth1_to_batadv: link is not ready
batman_adv: The newly added mac address (aa:aa:aa:aa:aa:3d) already exists on: batadv_slave_0
batman_adv: It is strongly recommended to keep mac addresses unique to avoid problems!
batman_adv: The newly added mac address (aa:aa:aa:aa:aa:3d) already exists on: batadv_slave_0
batman_adv: It is strongly recommended to keep mac addresses unique to avoid problems!
batman_adv: The newly added mac address (aa:aa:aa:aa:aa:3d) already exists on: batadv_slave_0
batman_adv: It is strongly recommended to keep mac addresses unique to avoid problems!
batman_adv: The newly added mac address (aa:aa:aa:aa:aa:3d) already exists on: batadv_slave_0
batman_adv: It is strongly recommended to keep mac addresses unique to avoid problems!
batman_adv: The newly added mac address (aa:aa:aa:aa:aa:3d) already exists on: batadv_slave_0
batman_adv: It is strongly recommended to keep mac addresses unique to avoid problems!
IPv6: ADDRCONF(NETDEV_UP): batadv_slave_0: link is not ready
batman_adv: batadv0: Interface activated: batadv_slave_0
IPv6: ADDRCONF(NETDEV_CHANGE): macvtap0: link becomes ready
IPv6: ADDRCONF(NETDEV_CHANGE): macsec0: link becomes ready
IPv6: ADDRCONF(NETDEV_CHANGE): batadv_slave_0: link becomes ready
IPv6: ADDRCONF(NETDEV_CHANGE): veth0_to_batadv: link becomes ready
batman_adv: The newly added mac address (aa:aa:aa:aa:aa:3e) already exists on: batadv_slave_1
batman_adv: It is strongly recommended to keep mac addresses unique to avoid problems!
batman_adv: The newly added mac address (aa:aa:aa:aa:aa:3e) already exists on: batadv_slave_1
batman_adv: It is strongly recommended to keep mac addresses unique to avoid problems!
batman_adv: The newly added mac address (aa:aa:aa:aa:aa:3e) already exists on: batadv_slave_1
batman_adv: It is strongly recommended to keep mac addresses unique to avoid problems!
batman_adv: The newly added mac address (aa:aa:aa:aa:aa:3e) already exists on: batadv_slave_1
batman_adv: It is strongly recommended to keep mac addresses unique to avoid problems!
batman_adv: The newly added mac address (aa:aa:aa:aa:aa:3e) already exists on: batadv_slave_1
batman_adv: It is strongly recommended to keep mac addresses unique to avoid problems!
IPv6: ADDRCONF(NETDEV_UP): batadv_slave_1: link is not ready
batman_adv: batadv0: Interface activated: batadv_slave_1
IPv6: ADDRCONF(NETDEV_CHANGE): batadv_slave_1: link becomes ready
IPv6: ADDRCONF(NETDEV_CHANGE): veth1_to_batadv: link becomes ready
Bluetooth: hci2: command 0x0419 tx timeout
Bluetooth: hci2: command 0x0405 tx timeout


---
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

syzbot

unread,
Sep 5, 2020, 9:00:17 PM9/5/20
to syzkaller...@googlegroups.com
syzbot has found a reproducer for the following issue on:

HEAD commit: c37da90e Linux 4.19.143
git tree: linux-4.19.y
console output: https://syzkaller.appspot.com/x/log.txt?x=13bad4f9900000
kernel config: https://syzkaller.appspot.com/x/.config?x=d162ec57805c4e4d
dashboard link: https://syzkaller.appspot.com/bug?extid=3257b5a27d60dc9d951d
compiler: gcc (GCC) 10.1.0-syz 20200507
syz repro: https://syzkaller.appspot.com/x/repro.syz?x=10ce96ed900000
C reproducer: https://syzkaller.appspot.com/x/repro.c?x=14e21bcd900000

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

================================
WARNING: inconsistent lock state
4.19.143-syzkaller #0 Not tainted
--------------------------------
inconsistent {SOFTIRQ-ON-W} -> {IN-SOFTIRQ-W} usage.
swapper/0/0 [HC0[0]:SC1[1]:HE1:SE0] takes:
0000000010c63708 (slock-AF_BLUETOOTH-BTPROTO_SCO){+.?.}, at: spin_lock include/linux/spinlock.h:329 [inline]
0000000010c63708 (slock-AF_BLUETOOTH-BTPROTO_SCO){+.?.}, at: sco_sock_timeout+0x22/0x190 net/bluetooth/sco.c:82
{SOFTIRQ-ON-W} state was registered at:
__raw_spin_lock include/linux/spinlock_api_smp.h:142 [inline]
_raw_spin_lock+0x2a/0x40 kernel/locking/spinlock.c:144
spin_lock include/linux/spinlock.h:329 [inline]
sco_conn_del+0xb0/0x220 net/bluetooth/sco.c:175
sco_disconn_cfm net/bluetooth/sco.c:1133 [inline]
sco_disconn_cfm+0x62/0x80 net/bluetooth/sco.c:1126
hci_disconn_cfm include/net/bluetooth/hci_core.h:1261 [inline]
hci_conn_hash_flush+0x114/0x220 net/bluetooth/hci_conn.c:1495
hci_dev_do_close+0x624/0xe70 net/bluetooth/hci_core.c:1666
hci_unregister_dev+0x17c/0x7f0 net/bluetooth/hci_core.c:3271
vhci_release+0x70/0xe0 drivers/bluetooth/hci_vhci.c:354
__fput+0x2ce/0x890 fs/file_table.c:278
task_work_run+0x148/0x1c0 kernel/task_work.c:113
exit_task_work include/linux/task_work.h:22 [inline]
do_exit+0xbb2/0x2b70 kernel/exit.c:887
do_group_exit+0x125/0x310 kernel/exit.c:990
get_signal+0x3f2/0x1f70 kernel/signal.c:2588
do_signal+0x8f/0x1670 arch/x86/kernel/signal.c:821
exit_to_usermode_loop+0x204/0x2a0 arch/x86/entry/common.c:163
prepare_exit_to_usermode arch/x86/entry/common.c:198 [inline]
syscall_return_slowpath arch/x86/entry/common.c:271 [inline]
do_syscall_64+0x538/0x620 arch/x86/entry/common.c:296
entry_SYSCALL_64_after_hwframe+0x49/0xbe
irq event stamp: 1514506
hardirqs last enabled at (1514506): [<ffffffff873d9df4>] __raw_spin_unlock_irq include/linux/spinlock_api_smp.h:168 [inline]
hardirqs last enabled at (1514506): [<ffffffff873d9df4>] _raw_spin_unlock_irq+0x24/0x80 kernel/locking/spinlock.c:192
hardirqs last disabled at (1514505): [<ffffffff873d9a85>] __raw_spin_lock_irq include/linux/spinlock_api_smp.h:126 [inline]
hardirqs last disabled at (1514505): [<ffffffff873d9a85>] _raw_spin_lock_irq+0x35/0x80 kernel/locking/spinlock.c:160
softirqs last enabled at (1514502): [<ffffffff813f34cd>] irq_enter+0xbd/0xd0 kernel/softirq.c:354
softirqs last disabled at (1514503): [<ffffffff813f36f5>] invoke_softirq kernel/softirq.c:372 [inline]
softirqs last disabled at (1514503): [<ffffffff813f36f5>] irq_exit+0x215/0x260 kernel/softirq.c:412

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

CPU0
----
lock(slock-AF_BLUETOOTH-BTPROTO_SCO);
<Interrupt>
lock(slock-AF_BLUETOOTH-BTPROTO_SCO);

*** DEADLOCK ***

1 lock held by swapper/0/0:
#0: 00000000b5acbc09 ((&sk->sk_timer)){+.-.}, at: lockdep_copy_map include/linux/lockdep.h:168 [inline]
#0: 00000000b5acbc09 ((&sk->sk_timer)){+.-.}, at: call_timer_fn+0xc9/0x700 kernel/time/timer.c:1328

stack backtrace:
CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.19.143-syzkaller #0
RIP: 0010:native_safe_halt+0xe/0x10 arch/x86/include/asm/irqflags.h:61
Code: 48 89 df e8 74 45 62 fa e9 2e ff ff ff 48 89 df e8 67 45 62 fa eb 82 90 90 90 90 90 e9 07 00 00 00 0f 00 2d f4 5b 4a 00 fb f4 <c3> 90 e9 07 00 00 00 0f 00 2d e4 5b 4a 00 f4 c3 90 90 41 56 41 55
RSP: 0018:ffffffff88c07d40 EFLAGS: 00000286 ORIG_RAX: ffffffffffffff13
RAX: 1ffffffff11a4b6c RBX: dffffc0000000000 RCX: 0000000000000000
RDX: dffffc0000000000 RSI: 0000000000000001 RDI: ffffffff88c7a784
RBP: 0000000000000000 R08: 0000000000000001 R09: 0000000000000000
R10: 0000000000000000 R11: 0000000000000000 R12: ffffffff88d25b50
R13: 1ffffffff1180fb2 R14: 0000000000000000 R15: 0000000000000000
arch_safe_halt arch/x86/include/asm/paravirt.h:94 [inline]
default_idle+0x49/0x310 arch/x86/kernel/process.c:557
cpuidle_idle_call kernel/sched/idle.c:153 [inline]
do_idle+0x2ec/0x4b0 kernel/sched/idle.c:263
cpu_startup_entry+0xc5/0xe0 kernel/sched/idle.c:369
start_kernel+0x8d6/0x911 init/main.c:736
secondary_startup_64+0xa4/0xb0 arch/x86/kernel/head_64.S:243

syzbot

unread,
Oct 12, 2021, 9:04:11 AM10/12/21
to syzkaller...@googlegroups.com
syzbot suspects this issue was fixed by commit:

commit 48669c81a65628ef234cbdd91b9395952c7c27fe
Author: Desmond Cheong Zhi Xi <desmond...@gmail.com>
Date: Tue Aug 10 04:14:05 2021 +0000

Bluetooth: schedule SCO timeouts with delayed_work

bisection log: https://syzkaller.appspot.com/x/bisect.txt?x=15ae6ebf300000
start commit: 3207316b3bee Linux 4.19.164
git tree: linux-4.19.y
kernel config: https://syzkaller.appspot.com/x/.config?x=ce6a43827932e236
dashboard link: https://syzkaller.appspot.com/bug?extid=3257b5a27d60dc9d951d
syz repro: https://syzkaller.appspot.com/x/repro.syz?x=176c0e57500000
C reproducer: https://syzkaller.appspot.com/x/repro.c?x=1537cfb7500000

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

#syz fix: Bluetooth: schedule SCO timeouts with delayed_work

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