Date:   Wed, 8 Aug 2018 13:36:15 +0200
From:   Petr Mladek <pmladek@...e.com>
To:     Vlastimil Babka <vbabka@...e.cz>
Cc:     "David S. Miller" <davem@...emloft.net>,
        Marcel Holtmann <marcel@...tmann.org>,
        Johan Hedberg <johan.hedberg@...il.com>,
        linux-bluetooth@...r.kernel.org, netdev@...r.kernel.org,
        Mikhail Gavrilov <mikhail.v.gavrilov@...il.com>,
        linux-mm@...ck.org, Steven Rostedt <rostedt@...dmis.org>,
        Sergey Senozhatsky <sergey.senozhatsky@...il.com>,
        Peter Zijlstra <peterz@...radead.org>
Subject: lock recursion - was: Re: [4.18 rc7] BUG: sleeping function called
 from invalid context at mm/slab.h:421

On Wed 2018-08-08 11:05:00, Vlastimil Babka wrote:
> On 08/08/2018 11:01 AM, Vlastimil Babka wrote:
> > fbcon_startup() calls kzalloc(sizeof(struct fbcon_ops), GFP_KERNEL) so
> > it tells slab it can sleep. The problem must be higher in the stack,
> > CCing printk people.
> 
> Uh just noticed there was also attached dmesg which my reply converted
> to inline. The first problem there is a lockdep splat.

The lockdep splat might eventually be a valid issue (recursive lock) in the
networking code. But it seems to be unrelated to the later problems
with sleeping in fbcon_startup().

Adding networking people into CC. Please, find below the relevant part
from the dmesg. The full log can be found in the original message at
https://marc.info/?l=linux-mm&m=153370024009996&w=2

Lock recursion in bluetooth code:

[   32.050660] Bluetooth: RFCOMM TTY layer initialized
[   32.050675] Bluetooth: RFCOMM socket layer initialized
[   32.050719] Bluetooth: RFCOMM ver 1.11
[   34.413359] fuse init (API version 7.27)
[   40.562871] rfkill: input handler disabled
[   42.272301] pool (2344) used greatest stack depth: 11320 bytes left
[   42.701283] ISO 9660 Extensions: Microsoft Joliet Level 3
[   42.704062] ISO 9660 Extensions: Microsoft Joliet Level 3
[   42.710375] ISO 9660 Extensions: RRIP_1991A
[   64.930766] tracker-extract (2229) used greatest stack depth: 11176 bytes left
[  465.911281] TaskSchedulerFo (3362) used greatest stack depth: 11112 bytes left
[  491.743600] TaskSchedulerFo (3364) used greatest stack depth: 11032 bytes left
[  507.733884] nf_conntrack: default automatic helper assignment has been turned off \
for security reasons and CT-based  firewall rule not found. Use the iptables CT \
target to attach helpers instead. [  660.384586] kworker/dying (155) used greatest \
stack depth: 10888 bytes left [  699.910094] device enp2s0 entered promiscuous mode
[ 1098.658964] kworker/dying (7) used greatest stack depth: 10712 bytes left
[ 1843.488301] perf: interrupt took too long (2510 > 2500), lowering \
kernel.perf_event_max_sample_rate to 79000 [ 2819.896469] perf: interrupt took too \
long (3138 > 3137), lowering kernel.perf_event_max_sample_rate to 63000 [ \
6120.247124] perf: interrupt took too long (3923 > 3922), lowering \
kernel.perf_event_max_sample_rate to 50000

[ 6829.212232] ============================================
[ 6829.212234] WARNING: possible recursive locking detected
[ 6829.212236] 4.18.0-0.rc7.git1.1.fc29.x86_64 #1 Not tainted
[ 6829.212237] --------------------------------------------
[ 6829.212239] kworker/u17:2/28441 is trying to acquire lock:
[ 6829.212242] 000000004025b723 (sk_lock-AF_BLUETOOTH-BTPROTO_L2CAP){+.+.}, at: \
bt_accept_enqueue+0x3c/0xb0 [bluetooth] [ 6829.212260] 
               but task is already holding lock:
[ 6829.212262] 000000004cb71eef (sk_lock-AF_BLUETOOTH-BTPROTO_L2CAP){+.+.}, at: \
l2cap_sock_new_connection_cb+0x18/0xa0 [bluetooth] [ 6829.212278] 
               other info that might help us debug this:
[ 6829.212279]  Possible unsafe locking scenario:

[ 6829.212281]        CPU0
[ 6829.212282]        ----
[ 6829.212284]   lock(sk_lock-AF_BLUETOOTH-BTPROTO_L2CAP);
[ 6829.212286]   lock(sk_lock-AF_BLUETOOTH-BTPROTO_L2CAP);
[ 6829.212288] 
                *** DEADLOCK ***

[ 6829.212290]  May be due to missing lock nesting notation

[ 6829.212293] 5 locks held by kworker/u17:2/28441:
[ 6829.212294]  #0: 000000009af6a4dc ((wq_completion)"%s"hdev->name#2){+.+.}, at: \
process_one_work+0x1f3/0x650 [ 6829.212301]  #1: 000000006f7488f4 \
((work_completion)(&hdev->rx_work)){+.+.}, at: process_one_work+0x1f3/0x650 [ \
6829.212306]  #2: 000000003dba8333 (&conn->chan_lock){+.+.}, at: \
l2cap_connect+0x8f/0x5a0 [bluetooth] [ 6829.212321]  #3: 00000000aaa813b9 \
(&chan->lock/2){+.+.}, at: l2cap_connect+0xa9/0x5a0 [bluetooth] [ 6829.212335]  #4: \
000000004cb71eef (sk_lock-AF_BLUETOOTH-BTPROTO_L2CAP){+.+.}, at: \
l2cap_sock_new_connection_cb+0x18/0xa0 [bluetooth] [ 6829.212350] 
               stack backtrace:
[ 6829.212354] CPU: 6 PID: 28441 Comm: kworker/u17:2 Not tainted \
4.18.0-0.rc7.git1.1.fc29.x86_64 #1 [ 6829.212355] Hardware name: Gigabyte Technology \
Co., Ltd. Z87M-D3H/Z87M-D3H, BIOS F11 08/12/2014 [ 6829.212365] Workqueue: hci0 \
hci_rx_work [bluetooth] [ 6829.212367] Call Trace:
[ 6829.212373]  dump_stack+0x85/0xc0
[ 6829.212377]  __lock_acquire.cold.64+0x158/0x227
[ 6829.212381]  ? mark_held_locks+0x57/0x80
[ 6829.212384]  lock_acquire+0x9e/0x1b0
[ 6829.212394]  ? bt_accept_enqueue+0x3c/0xb0 [bluetooth]
[ 6829.212398]  lock_sock_nested+0x72/0xa0
[ 6829.212407]  ? bt_accept_enqueue+0x3c/0xb0 [bluetooth]
[ 6829.212417]  bt_accept_enqueue+0x3c/0xb0 [bluetooth]
[ 6829.212429]  l2cap_sock_new_connection_cb+0x5d/0xa0 [bluetooth]
[ 6829.212441]  l2cap_connect+0x110/0x5a0 [bluetooth]
[ 6829.212454]  ? l2cap_recv_frame+0x6d0/0x2cb0 [bluetooth]
[ 6829.212458]  ? __mutex_unlock_slowpath+0x4b/0x2b0
[ 6829.212470]  l2cap_recv_frame+0x6e8/0x2cb0 [bluetooth]
[ 6829.212474]  ? __mutex_unlock_slowpath+0x4b/0x2b0
[ 6829.212484]  hci_rx_work+0x1c6/0x5d0 [bluetooth]
[ 6829.212488]  process_one_work+0x27d/0x650
[ 6829.212492]  worker_thread+0x3c/0x390
[ 6829.212494]  ? process_one_work+0x650/0x650
[ 6829.212498]  kthread+0x120/0x140
[ 6829.212501]  ? kthread_create_worker_on_cpu+0x70/0x70
[ 6829.212504]  ret_from_fork+0x3a/0x50
[ 6829.285343] BUG: sleeping function called from invalid context at \
net/core/sock.c:2833 [ 6829.285349] in_atomic(): 1, irqs_disabled(): 0, pid: 1743, \
name: krfcommd [ 6829.285351] INFO: lockdep is turned off.
[ 6829.285355] CPU: 6 PID: 1743 Comm: krfcommd Not tainted \
4.18.0-0.rc7.git1.1.fc29.x86_64 #1 [ 6829.285358] Hardware name: Gigabyte Technology \
Co., Ltd. Z87M-D3H/Z87M-D3H, BIOS F11 08/12/2014 [ 6829.285360] Call Trace:
[ 6829.285368]  dump_stack+0x85/0xc0
[ 6829.285373]  ___might_sleep.cold.72+0xac/0xbc
[ 6829.285378]  lock_sock_nested+0x29/0xa0
[ 6829.285394]  bt_accept_enqueue+0x3c/0xb0 [bluetooth]
[ 6829.285401]  rfcomm_connect_ind+0x21b/0x260 [rfcomm]
[ 6829.285406]  rfcomm_run+0x1611/0x1820 [rfcomm]
[ 6829.285411]  ? do_wait_intr_irq+0xb0/0xb0
[ 6829.285416]  ? rfcomm_check_accept+0x90/0x90 [rfcomm]
[ 6829.285419]  kthread+0x120/0x140
[ 6829.285422]  ? kthread_create_worker_on_cpu+0x70/0x70
[ 6829.285426]  ret_from_fork+0x3a/0x50
[ 6829.476282] input: 04:5D:4B:5F:34:57 as /devices/virtual/input/input35
[ 7273.090391] show_signal_msg: 23 callbacks suppressed
[ 7273.090393] CFileWriterThre[29422]: segfault at 7f078bfe7240 ip 00007f079137843c \
sp 00007f078bb8dcf0 error 4 in steamclient.so[7f0790880000+14d2000] [ 7273.090404] \
Code: 89 df ff d2 8b 45 00 83 f8 02 0f 84 9e 00 00 00 83 f8 03 0f 84 55 05 00 00 83 \
f8 01 74 48 31 ed 4d 85 e4 74 11 48 85 db 74 0c <48> 8b 03 4c 89 e6 48 89 df ff 50 10 \
48 8b b4 24 e8 00 00 00 64 48  [ 7755.656023] rfkill: input handler enabled
[ 7773.439895] rfkill: input handler disabled
[ 8075.232946] BUG: sleeping function called from invalid context at \
net/core/sock.c:2833 [ 8075.232951] in_atomic(): 1, irqs_disabled(): 0, pid: 1743, \
name: krfcommd [ 8075.232952] INFO: lockdep is turned off.
[ 8075.232956] CPU: 5 PID: 1743 Comm: krfcommd Tainted: G        W         \
4.18.0-0.rc7.git1.1.fc29.x86_64 #1 [ 8075.232957] Hardware name: Gigabyte Technology \
Co., Ltd. Z87M-D3H/Z87M-D3H, BIOS F11 08/12/2014 [ 8075.232959] Call Trace:
[ 8075.232965]  dump_stack+0x85/0xc0
[ 8075.232969]  ___might_sleep.cold.72+0xac/0xbc
[ 8075.232973]  lock_sock_nested+0x29/0xa0
[ 8075.232987]  bt_accept_enqueue+0x3c/0xb0 [bluetooth]
[ 8075.232992]  rfcomm_connect_ind+0x21b/0x260 [rfcomm]
[ 8075.232997]  rfcomm_run+0x1611/0x1820 [rfcomm]
[ 8075.233001]  ? do_wait_intr_irq+0xb0/0xb0
[ 8075.233005]  ? rfcomm_check_accept+0x90/0x90 [rfcomm]
[ 8075.233008]  kthread+0x120/0x140
[ 8075.233011]  ? kthread_create_worker_on_cpu+0x70/0x70
[ 8075.233014]  ret_from_fork+0x3a/0x50
[ 8075.413187] input: 04:5D:4B:5F:34:57 as /devices/virtual/input/input36
[13538.300352] steam[4385]: segfault at 0 ip 00000000eabc32d9 sp 00000000ffdca1b0 \
error 4 in vgui2_s.so[eab26000+292000] [13538.300365] Code: 74 03 00 00 00 00 00 00 \
c7 44 24 08 02 00 00 00 c7 44 24 04 10 00 00 00 c7 04 24 44 ac 00 00 e8 1d 40 fb ff \
89 86 74 03 00 00 <8b> 00 8b 78 10 e8 3d 1a fb ff 8b 86 74 03 00 00 dd 5c 24 04 89 04 \
 [14324.004275] pool[443]: segfault at 0 ip 00007f53e2399556 sp 00007f53ceffcc40 \
error 4 in libnssutil3.so[7f53e2395000+12000] [14324.004286] Code: d8 5b 5d 41 5c c3 \
66 2e 0f 1f 84 00 00 00 00 00 0f 1f 40 00 f3 0f 1e fa 41 54 41 bc ff ff ff ff 55 53 \
48 89 fb e8 7a bc ff ff <48> 8b 3b 48 89 c5 e8 9f c1 ff ff 48 8b 43 38 48 39 c5 75 23 \
eb 2d  [14324.007764] rfkill: input handler enabled
[14348.933385] rfkill: input handler disabled
[15930.680376] DMA-API: debugging out of memory - disabling
[16087.451698] vaapi-queue:src (10166) used greatest stack depth: 10616 bytes left
[19689.192082] BUG: sleeping function called from invalid context at \
net/core/sock.c:2833 [19689.192087] in_atomic(): 1, irqs_disabled(): 0, pid: 1743, \
name: krfcommd [19689.192089] INFO: lockdep is turned off.
[19689.192093] CPU: 6 PID: 1743 Comm: krfcommd Tainted: G        W         \
4.18.0-0.rc7.git1.1.fc29.x86_64 #1 [19689.192096] Hardware name: Gigabyte Technology \
Co., Ltd. Z87M-D3H/Z87M-D3H, BIOS F11 08/12/2014 [19689.192098] Call Trace:
[19689.192106]  dump_stack+0x85/0xc0
[19689.192112]  ___might_sleep.cold.72+0xac/0xbc
[19689.192117]  lock_sock_nested+0x29/0xa0
[19689.192142]  bt_accept_enqueue+0x3c/0xb0 [bluetooth]
[19689.192150]  rfcomm_connect_ind+0x21b/0x260 [rfcomm]
[19689.192157]  rfcomm_run+0x1611/0x1820 [rfcomm]
[19689.192163]  ? do_wait_intr_irq+0xb0/0xb0
[19689.192179]  ? rfcomm_check_accept+0x90/0x90 [rfcomm]
[19689.192183]  kthread+0x120/0x140
[19689.192186]  ? kthread_create_worker_on_cpu+0x70/0x70
[19689.192190]  ret_from_fork+0x3a/0x50
[19689.377451] input: 04:5D:4B:5F:34:57 as /devices/virtual/input/input37


Best Regards,
Petr

Powered by blists - more mailing lists