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)