rfcomm - bug - sleeping in atomic context

rfcomm - bug - sleeping in atomic context

[Alban Browaeys]

To me rfcomm_connect_ind calls bt_accept_enqueue under bh_lock_sock
(spinlock) while bt_accept_enqueue might sleep (lock_sock_nessted)

I got this bug once. The bug did not escalate and the effects seems
limited to this connection but the box recovered (I did suspend/resume
in the meantime).

>From the look of it this issue predates the switch to git.

[ 6157.449801] BUG: sleeping function called from invalid context at net/core/sock.c:2761
[ 6157.449809] in_atomic(): 1, irqs_disabled(): 0, pid: 5073, name: krfcommd
[ 6157.449814] 2 locks held by krfcommd/5073:
[ 6157.449816]  #0:  (rfcomm_mutex){....}, at: [<00000000daacba7f>] rfcomm_run+0x6d8/0x5300 [rfcomm]
[ 6157.449837]  #1:  (slock-AF_BLUETOOTH-BTPROTO_RFCOMM){....}, at: [<00000000fbe9fa39>] rfcomm_connect_ind+0x32a/0x970 [rfcomm]
[ 6157.449853] CPU: 2 PID: 5073 Comm: krfcommd Not tainted 4.15.0-rc3prahal+intel+ #202
[ 6157.449856] Hardware name: LENOVO 20CDCTO1WW/20CDCTO1WW, BIOS GQET53WW (1.33 ) 09/15/2017
[ 6157.449859] Call Trace:
[ 6157.449866]  dump_stack+0xa6/0x125
[ 6157.449872]  ? _atomic_dec_and_lock+0x13b/0x13b
[ 6157.449881]  ? lockdep_print_held_locks+0xbb/0x120
[ 6157.449889]  ___might_sleep+0x29e/0x330
[ 6157.449893]  ? cpumask_next+0x16/0x20
[ 6157.449897]  ? rq_clock+0xf0/0xf0
[ 6157.449907]  ? is_module_address+0x11/0x20
[ 6157.449913]  lock_sock_nested+0x32/0x100
[ 6157.449948]  bt_accept_enqueue+0x81/0x2b0 [bluetooth]
[ 6157.449957]  ? rfcomm_sock_alloc.constprop.4+0x306/0x400 [rfcomm]
[ 6157.449984]  ? bt_sock_reclassify_lock+0x2a0/0x2a0 [bluetooth]
[ 6157.449990]  ? rfcomm_sock_getsockopt+0x8b0/0x8b0 [rfcomm]
[ 6157.450000]  ? rfcomm_sock_init+0x35b/0x470 [rfcomm]
[ 6157.450010]  rfcomm_connect_ind+0x6cb/0x970 [rfcomm]
[ 6157.450017]  ? lock_release+0x10b0/0x10b0
[ 6157.450024]  ? rfcomm_sock_create+0x140/0x140 [rfcomm]
[ 6157.450032]  ? rfcomm_session_add+0x241/0x3b0 [rfcomm]
[ 6157.450038]  ? do_raw_spin_trylock+0x180/0x180
[ 6157.450044]  ? wait_woken+0x116/0x260
[ 6157.450059]  rfcomm_run+0x3bfc/0x5300 [rfcomm]
[ 6157.450076]  ? rfcomm_check_accept+0x1e0/0x1e0 [rfcomm]
[ 6157.450080]  ? _raw_spin_unlock_irq+0x24/0x40
[ 6157.450085]  ? finish_task_switch+0x1d8/0x700
[ 6157.450088]  ? finish_task_switch+0x1af/0x700
[ 6157.450096]  ? preempt_notifier_dec+0x20/0x20
[ 6157.450108]  ? __schedule+0x7d4/0x1e10
[ 6157.450118]  ? __sched_text_start+0x8/0x8
[ 6157.450123]  ? __lock_acquire.isra.33+0x35a/0x1c70
[ 6157.450132]  ? tsc_resume+0x10/0x10
[ 6157.450137]  ? lockdep_rcu_suspicious+0x150/0x150
[ 6157.450140]  ? _raw_spin_unlock+0x24/0x30
[ 6157.450150]  ? __init_waitqueue_head+0x130/0x130
[ 6157.450155]  ? sched_clock_cpu+0x18/0x170
[ 6157.450158]  ? find_held_lock+0x39/0x1c0
[ 6157.450171]  ? schedule+0xe7/0x380
[ 6157.450174]  ? lock_downgrade+0x690/0x690
[ 6157.450178]  ? __schedule+0x1e10/0x1e10
[ 6157.450184]  ? do_wait_intr_irq+0x330/0x330
[ 6157.450194]  ? do_raw_spin_trylock+0x180/0x180
[ 6157.450208]  ? rfcomm_check_accept+0x1e0/0x1e0 [rfcomm]
[ 6157.450213]  kthread+0x312/0x3d0
[ 6157.450217]  ? kthread_create_worker_on_cpu+0xc0/0xc0
[ 6157.450225]  ret_from_fork+0x1f/0x30
[ 6171.628395] Bluetooth: hci0: last event is not cmd complete (0x0f)
[ 6187.745374] Bluetooth: hci0: last event is not cmd complete (0x0f)
[ 6203.744416] Bluetooth: hci0: last event is not cmd complete (0x0f)
[ 6219.743384] Bluetooth: hci0: last event is not cmd complete (0x0f)




this decode as:

BUG: sleeping function called from invalid context at net/core/sock.c:2761
in_atomic(): 1, irqs_disabled(): 0, pid: 5073, name: krfcommd
2 locks held by krfcommd/5073:
#0: (rfcomm_mutex){....}, at: rfcomm_run (/home/prahal/Projects/Admin/Linux/linux/net/bluetooth/rfcomm/core.c:1983 /home/prahal/Projects/Admin/Linux/linux/net/bluetooth/rfcomm/core.c:2087) rfcomm
#1: (slock-AF_BLUETOOTH-BTPROTO_RFCOMM){....}, at: rfcomm_connect_ind (/home/prahal/Projects/Admin/Linux/linux/include/net/sock.h:835 /home/prahal/Projects/Admin/Linux/linux/net/bluetooth/rfcomm/sock.c:974) rfcomm
CPU: 2 PID: 5073 Comm: krfcommd Not tainted 4.15.0-rc3prahal+intel+ #202
Hardware name: LENOVO 20CDCTO1WW/20CDCTO1WW, BIOS GQET53WW (1.33 ) 09/15/2017
Call Trace:
dump_stack (/home/prahal/Projects/Admin/Linux/linux/lib/dump_stack.c:55) 
? _atomic_dec_and_lock (/home/prahal/Projects/Admin/Linux/linux/lib/dump_stack.c:29) 
? lockdep_print_held_locks (/home/prahal/Projects/Admin/Linux/linux/kernel/locking/lockdep.c:591 (discriminator 3)) 
___might_sleep (/home/prahal/Projects/Admin/Linux/linux/kernel/sched/core.c:6061) 
? cpumask_next (/home/prahal/Projects/Admin/Linux/linux/lib/cpumask.c:22) 
? rq_clock (/home/prahal/Projects/Admin/Linux/linux/kernel/sched/core.c:6018) 
? is_module_address (/home/prahal/Projects/Admin/Linux/linux/arch/x86/include/asm/preempt.h:81 /home/prahal/Projects/Admin/Linux/linux/kernel/module.c:4273) 
lock_sock_nested (/home/prahal/Projects/Admin/Linux/linux/net/core/sock.c:2761) 
bt_accept_enqueue (/home/prahal/Projects/Admin/Linux/linux/include/linux/list.h:93 /home/prahal/Projects/Admin/Linux/linux/net/bluetooth/af_bluetooth.c:163) bluetooth
? rfcomm_sock_alloc.constprop.4 (/home/prahal/Projects/Admin/Linux/linux/net/bluetooth/rfcomm/sock.c:308 /home/prahal/Projects/Admin/Linux/linux/net/bluetooth/rfcomm/sock.c:310) rfcomm
? bt_sock_reclassify_lock (/home/prahal/Projects/Admin/Linux/linux/net/bluetooth/af_bluetooth.c:158) bluetooth
? rfcomm_sock_getsockopt (/home/prahal/Projects/Admin/Linux/linux/net/bluetooth/rfcomm/sock.c:273) rfcomm
? rfcomm_sock_init (/home/prahal/Projects/Admin/Linux/linux/net/bluetooth/rfcomm/sock.c:255) rfcomm
rfcomm_connect_ind (/home/prahal/Projects/Admin/Linux/linux/net/bluetooth/rfcomm/sock.c:994) rfcomm
? lock_release (/home/prahal/Projects/Admin/Linux/linux/kernel/locking/lockdep.c:3993) 
? rfcomm_sock_create (/home/prahal/Projects/Admin/Linux/linux/net/bluetooth/rfcomm/sock.c:957) rfcomm
? rfcomm_session_add (/home/prahal/Projects/Admin/Linux/linux/include/linux/list.h:60 /home/prahal/Projects/Admin/Linux/linux/include/linux/list.h:79 /home/prahal/Projects/Admin/Linux/linux/net/bluetooth/rfcomm/core.c:670) rfcomm
? do_raw_spin_trylock (/home/prahal/Projects/Admin/Linux/linux/kernel/locking/spinlock_debug.c:133) 
? wait_woken (/home/prahal/Projects/Admin/Linux/linux/kernel/sched/wait.c:419) 
rfcomm_run (/home/prahal/Projects/Admin/Linux/linux/net/bluetooth/rfcomm/core.c:1430 /home/prahal/Projects/Admin/Linux/linux/net/bluetooth/rfcomm/core.c:1622 /home/prahal/Projects/Admin/Linux/linux/net/bluetooth/rfcomm/core.c:1755 /home/prahal/Projects/Admin/Linux/linux/net/bluetooth/rfcomm/core.c:1907 /home/prahal/Projects/Admin/Linux/linux/net/bluetooth/rfcomm/core.c:2000 /home/prahal/Projects/Admin/Linux/linux/net/bluetooth/rfcomm/core.c:2087) rfcomm
? rfcomm_check_accept (/home/prahal/Projects/Admin/Linux/linux/net/bluetooth/rfcomm/core.c:2075) rfcomm
? _raw_spin_unlock_irq (/home/prahal/Projects/Admin/Linux/linux/arch/x86/include/asm/paravirt.h:787 /home/prahal/Projects/Admin/Linux/linux/include/linux/spinlock_api_smp.h:168 /home/prahal/Projects/Admin/Linux/linux/kernel/locking/spinlock.c:199) 
? finish_task_switch (/home/prahal/Projects/Admin/Linux/linux/arch/x86/include/asm/current.h:15 /home/prahal/Projects/Admin/Linux/linux/kernel/sched/core.c:2669) 
? finish_task_switch (/home/prahal/Projects/Admin/Linux/linux/kernel/sched/sched.h:1360 /home/prahal/Projects/Admin/Linux/linux/kernel/sched/core.c:2666) 
? preempt_notifier_dec (/home/prahal/Projects/Admin/Linux/linux/kernel/sched/core.c:2619) 
? __schedule (/home/prahal/Projects/Admin/Linux/linux/kernel/sched/core.c:2802 /home/prahal/Projects/Admin/Linux/linux/kernel/sched/core.c:3375) 
? __sched_text_start (/home/prahal/Projects/Admin/Linux/linux/kernel/sched/core.c:3288) 
? __lock_acquire.isra.33 (/home/prahal/Projects/Admin/Linux/linux/kernel/locking/lockdep.c:3453) 
? tsc_resume (/home/prahal/Projects/Admin/Linux/linux/arch/x86/kernel/tsc.c:193) 
? lockdep_rcu_suspicious (/home/prahal/Projects/Admin/Linux/linux/kernel/locking/lockdep.c:3353) 
? _raw_spin_unlock (/home/prahal/Projects/Admin/Linux/linux/arch/x86/include/asm/preempt.h:81 /home/prahal/Projects/Admin/Linux/linux/include/linux/spinlock_api_smp.h:152 /home/prahal/Projects/Admin/Linux/linux/kernel/locking/spinlock.c:183) 
? __init_waitqueue_head (/home/prahal/Projects/Admin/Linux/linux/kernel/sched/wait.c:435) 
? sched_clock_cpu (/home/prahal/Projects/Admin/Linux/linux/kernel/sched/clock.c:363) 
? find_held_lock (/home/prahal/Projects/Admin/Linux/linux/kernel/locking/lockdep.c:3612) 
? schedule (/home/prahal/Projects/Admin/Linux/linux/arch/x86/include/asm/current.h:15 (discriminator 1) /home/prahal/Projects/Admin/Linux/linux/include/linux/sched.h:1620 (discriminator 1) /home/prahal/Projects/Admin/Linux/linux/kernel/sched/core.c:3436 (discriminator 1)) 
? lock_downgrade (/home/prahal/Projects/Admin/Linux/linux/kernel/locking/lockdep.c:4013) 
? __schedule (/home/prahal/Projects/Admin/Linux/linux/kernel/sched/core.c:3428) 
? do_wait_intr_irq (/home/prahal/Projects/Admin/Linux/linux/kernel/sched/wait.c:75) 
? do_raw_spin_trylock (/home/prahal/Projects/Admin/Linux/linux/kernel/locking/spinlock_debug.c:133) 
? rfcomm_check_accept (/home/prahal/Projects/Admin/Linux/linux/net/bluetooth/rfcomm/core.c:2075) rfcomm
kthread (/home/prahal/Projects/Admin/Linux/linux/kernel/kthread.c:238) 
? kthread_create_worker_on_cpu (/home/prahal/Projects/Admin/Linux/linux/kernel/kthread.c:198) 
ret_from_fork (/home/prahal/Projects/Admin/Linux/linux/arch/x86/entry/entry_64.S:447)