2021-06-14 13:35:33

by Lukasz Majczak

[permalink] [raw]
Subject: PROBLEM: Crash after Bluetooth: SMP: Convert BT_ERR/BT_DBG to bt_dev_err/bt_dev_dbg

Hi,

I was testing v5.13-rc5 and I have noticed it sometimes crashes giving
the following logs:

[ 13.886255] Bluetooth: rfcomm_init() RFCOMM ver 1.11
[ 14.654758] BUG: kernel NULL pointer dereference, address: 0000000000000000
[ 14.662562] #PF: supervisor read access in kernel mode
[ 14.668319] #PF: error_code(0x0000) - not-present page
[ 14.674080] PGD 0 P4D 0
[ 14.676923] Oops: 0000 [#1] PREEMPT SMP NOPTI
[ 14.681802] CPU: 0 PID: 2647 Comm: kworker/u17:2 Tainted: G U
5.13.0-rc5 #2
[ 14.691052] Hardware name: Google Delbin/Delbin, BIOS
Google_Delbin.13672.156.3 05/14/2021
[ 14.700289] Workqueue: hci0 hci_rx_work [bluetooth]
[ 14.705776] RIP: 0010:smp_new_conn_cb+0xd/0xb0 [bluetooth]
[ 14.711920] Code: 47 c5 6b c0 48 89 d9 31 c0 e8 aa 31 00 00 48 8b
3b be 13 00 00 00 5b 5d e9 8d b4 fc ff 55 48 89 e5 41 56 53 49 89 fe
48 8b 07 <48> 8b 00 48 8b 90 c0 05 00 00 48 83 c2 48 48 c7 c7 53 c58
[ 14.732905] RSP: 0018:ffffba9fc2a5bc88 EFLAGS: 00010246
[ 14.738755] RAX: 0000000000000000 RBX: 0000000000000002 RCX: ffff9f373f23ad00
[ 14.746748] RDX: 0000000000000000 RSI: ffffffff88df7c90 RDI: ffff9f3760e51c00
[ 14.754718] RBP: ffffba9fc2a5bc98 R08: 0000000000000000 R09: fefefefefefefeff
[ 14.762678] R10: 0000000000000018 R11: ffffffffc06a93d3 R12: ffff9f37344fe000
[ 14.770657] R13: ffff9f3760e51f28 R14: ffff9f3760e51c00 R15: ffff9f3757aab540
[ 14.778625] FS: 0000000000000000(0000) GS:ffff9f3878000000(0000)
knlGS:0000000000000000
[ 14.787672] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 14.794099] CR2: 0000000000000000 CR3: 000000012e6dc003 CR4: 0000000000770ef0
[ 14.802070] PKRU: 55555554
[ 14.805087] Call Trace:
[ 14.807815] l2cap_connect_cfm+0x15b/0x3b1 [bluetooth]
[ 14.813574] hci_le_meta_evt+0x8c2/0xb76 [bluetooth]
[ 14.819136] ? newidle_balance+0x200/0x36f
[ 14.823724] hci_event_packet+0x6f1/0x844 [bluetooth]
[ 14.829383] hci_rx_work+0x121/0x338 [bluetooth]
[ 14.834557] process_one_work+0x1b9/0x368
[ 14.839038] worker_thread+0x213/0x372
[ 14.843222] ? _raw_spin_unlock_irqrestore+0x12/0x2c
[ 14.848782] kthread+0x150/0x15f
[ 14.852384] ? pr_cont_work+0x58/0x58
[ 14.856477] ? kthread_blkcg+0x31/0x31
[ 14.860663] ret_from_fork+0x1f/0x30
[ 14.864655] Modules linked in: rfcomm cmac algif_hash
algif_skcipher af_alg vhost_vsock vhost vhost_iotlb
vmw_vsock_virtio_transport_common vsock uinput mei_hdcp xt_cgroup
btusb cdc_ether usbnet btrtl s1
[ 14.864691] iwlwifi cfg80211 joydev
[ 14.968673] gsmi: Log Shutdown Reason 0x03
[ 14.973278] CR2: 0000000000000000
[ 14.976991] ---[ end trace 9e1b3a2966a93e69 ]---
[ 14.984499] RIP: 0010:smp_new_conn_cb+0xd/0xb0 [bluetooth]
[ 14.990648] Code: 47 c5 6b c0 48 89 d9 31 c0 e8 aa 31 00 00 48 8b
3b be 13 00 00 00 5b 5d e9 8d b4 fc ff 55 48 89 e5 41 56 53 49 89 fe
48 8b 07 <48> 8b 00 48 8b 90 c0 05 00 00 48 83 c2 48 48 c7 c7 53 c58
[ 15.011645] RSP: 0018:ffffba9fc2a5bc88 EFLAGS: 00010246
[ 15.017481] RAX: 0000000000000000 RBX: 0000000000000002 RCX: ffff9f373f23ad00
[ 15.025449] RDX: 0000000000000000 RSI: ffffffff88df7c90 RDI: ffff9f3760e51c00
[ 15.033418] RBP: ffffba9fc2a5bc98 R08: 0000000000000000 R09: fefefefefefefeff
[ 15.041387] R10: 0000000000000018 R11: ffffffffc06a93d3 R12: ffff9f37344fe000
[ 15.049361] R13: ffff9f3760e51f28 R14: ffff9f3760e51c00 R15: ffff9f3757aab540
[ 15.057336] FS: 0000000000000000(0000) GS:ffff9f3878000000(0000)
knlGS:0000000000000000
[ 15.066380] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 15.072797] CR2: 0000000000000000 CR3: 000000012e6dc003 CR4: 0000000000770ef0
[ 15.080768] PKRU: 55555554
[ 15.083775] Kernel panic - not syncing: Fatal exception
[ 15.089661] Kernel Offset: 0x6a00000 from 0xffffffff81000000
(relocation range: 0xffffffff80000000-0xffffffffbfffffff)
[ 15.102110] gsmi: Log Shutdown Reason 0x02
[ 15.108941] ACPI MEMORY or I/O RESET_REG.

After short debug it pointed to the commit:

commit 2e1614f7d61e407f1a8e7935a2903a6fa3cb0b11
Author: Luiz Augusto von Dentz <[email protected]>
Date: Mon Mar 15 14:39:29 2021 -0700

Bluetooth: SMP: Convert BT_ERR/BT_DBG to bt_dev_err/bt_dev_dbg

In my case it looks like "conn" appears to be NULL,
at the following call (function: smp_new_conn_cb, net/bluetooth/smp.c)
bt_dev_dbg(pchan->conn->hcon->hdev, "created chan %p", chan);

Best regards,
Lukasz


2021-06-14 17:33:07

by Luiz Augusto von Dentz

[permalink] [raw]
Subject: Re: PROBLEM: Crash after Bluetooth: SMP: Convert BT_ERR/BT_DBG to bt_dev_err/bt_dev_dbg

Hi Lukasz,

On Mon, Jun 14, 2021 at 6:32 AM Lukasz Majczak <[email protected]> wrote:
>
> Hi,
>
> I was testing v5.13-rc5 and I have noticed it sometimes crashes giving
> the following logs:
>
> [ 13.886255] Bluetooth: rfcomm_init() RFCOMM ver 1.11
> [ 14.654758] BUG: kernel NULL pointer dereference, address: 0000000000000000
> [ 14.662562] #PF: supervisor read access in kernel mode
> [ 14.668319] #PF: error_code(0x0000) - not-present page
> [ 14.674080] PGD 0 P4D 0
> [ 14.676923] Oops: 0000 [#1] PREEMPT SMP NOPTI
> [ 14.681802] CPU: 0 PID: 2647 Comm: kworker/u17:2 Tainted: G U
> 5.13.0-rc5 #2
> [ 14.691052] Hardware name: Google Delbin/Delbin, BIOS
> Google_Delbin.13672.156.3 05/14/2021
> [ 14.700289] Workqueue: hci0 hci_rx_work [bluetooth]
> [ 14.705776] RIP: 0010:smp_new_conn_cb+0xd/0xb0 [bluetooth]
> [ 14.711920] Code: 47 c5 6b c0 48 89 d9 31 c0 e8 aa 31 00 00 48 8b
> 3b be 13 00 00 00 5b 5d e9 8d b4 fc ff 55 48 89 e5 41 56 53 49 89 fe
> 48 8b 07 <48> 8b 00 48 8b 90 c0 05 00 00 48 83 c2 48 48 c7 c7 53 c58
> [ 14.732905] RSP: 0018:ffffba9fc2a5bc88 EFLAGS: 00010246
> [ 14.738755] RAX: 0000000000000000 RBX: 0000000000000002 RCX: ffff9f373f23ad00
> [ 14.746748] RDX: 0000000000000000 RSI: ffffffff88df7c90 RDI: ffff9f3760e51c00
> [ 14.754718] RBP: ffffba9fc2a5bc98 R08: 0000000000000000 R09: fefefefefefefeff
> [ 14.762678] R10: 0000000000000018 R11: ffffffffc06a93d3 R12: ffff9f37344fe000
> [ 14.770657] R13: ffff9f3760e51f28 R14: ffff9f3760e51c00 R15: ffff9f3757aab540
> [ 14.778625] FS: 0000000000000000(0000) GS:ffff9f3878000000(0000)
> knlGS:0000000000000000
> [ 14.787672] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [ 14.794099] CR2: 0000000000000000 CR3: 000000012e6dc003 CR4: 0000000000770ef0
> [ 14.802070] PKRU: 55555554
> [ 14.805087] Call Trace:
> [ 14.807815] l2cap_connect_cfm+0x15b/0x3b1 [bluetooth]
> [ 14.813574] hci_le_meta_evt+0x8c2/0xb76 [bluetooth]
> [ 14.819136] ? newidle_balance+0x200/0x36f
> [ 14.823724] hci_event_packet+0x6f1/0x844 [bluetooth]
> [ 14.829383] hci_rx_work+0x121/0x338 [bluetooth]
> [ 14.834557] process_one_work+0x1b9/0x368
> [ 14.839038] worker_thread+0x213/0x372
> [ 14.843222] ? _raw_spin_unlock_irqrestore+0x12/0x2c
> [ 14.848782] kthread+0x150/0x15f
> [ 14.852384] ? pr_cont_work+0x58/0x58
> [ 14.856477] ? kthread_blkcg+0x31/0x31
> [ 14.860663] ret_from_fork+0x1f/0x30
> [ 14.864655] Modules linked in: rfcomm cmac algif_hash
> algif_skcipher af_alg vhost_vsock vhost vhost_iotlb
> vmw_vsock_virtio_transport_common vsock uinput mei_hdcp xt_cgroup
> btusb cdc_ether usbnet btrtl s1
> [ 14.864691] iwlwifi cfg80211 joydev
> [ 14.968673] gsmi: Log Shutdown Reason 0x03
> [ 14.973278] CR2: 0000000000000000
> [ 14.976991] ---[ end trace 9e1b3a2966a93e69 ]---
> [ 14.984499] RIP: 0010:smp_new_conn_cb+0xd/0xb0 [bluetooth]
> [ 14.990648] Code: 47 c5 6b c0 48 89 d9 31 c0 e8 aa 31 00 00 48 8b
> 3b be 13 00 00 00 5b 5d e9 8d b4 fc ff 55 48 89 e5 41 56 53 49 89 fe
> 48 8b 07 <48> 8b 00 48 8b 90 c0 05 00 00 48 83 c2 48 48 c7 c7 53 c58
> [ 15.011645] RSP: 0018:ffffba9fc2a5bc88 EFLAGS: 00010246
> [ 15.017481] RAX: 0000000000000000 RBX: 0000000000000002 RCX: ffff9f373f23ad00
> [ 15.025449] RDX: 0000000000000000 RSI: ffffffff88df7c90 RDI: ffff9f3760e51c00
> [ 15.033418] RBP: ffffba9fc2a5bc98 R08: 0000000000000000 R09: fefefefefefefeff
> [ 15.041387] R10: 0000000000000018 R11: ffffffffc06a93d3 R12: ffff9f37344fe000
> [ 15.049361] R13: ffff9f3760e51f28 R14: ffff9f3760e51c00 R15: ffff9f3757aab540
> [ 15.057336] FS: 0000000000000000(0000) GS:ffff9f3878000000(0000)
> knlGS:0000000000000000
> [ 15.066380] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [ 15.072797] CR2: 0000000000000000 CR3: 000000012e6dc003 CR4: 0000000000770ef0
> [ 15.080768] PKRU: 55555554
> [ 15.083775] Kernel panic - not syncing: Fatal exception
> [ 15.089661] Kernel Offset: 0x6a00000 from 0xffffffff81000000
> (relocation range: 0xffffffff80000000-0xffffffffbfffffff)
> [ 15.102110] gsmi: Log Shutdown Reason 0x02
> [ 15.108941] ACPI MEMORY or I/O RESET_REG.
>
> After short debug it pointed to the commit:
>
> commit 2e1614f7d61e407f1a8e7935a2903a6fa3cb0b11
> Author: Luiz Augusto von Dentz <[email protected]>
> Date: Mon Mar 15 14:39:29 2021 -0700
>
> Bluetooth: SMP: Convert BT_ERR/BT_DBG to bt_dev_err/bt_dev_dbg
>
> In my case it looks like "conn" appears to be NULL,
> at the following call (function: smp_new_conn_cb, net/bluetooth/smp.c)
> bt_dev_dbg(pchan->conn->hcon->hdev, "created chan %p", chan);

Just sent a patch for it, looks like our CI doesn't enable debug logs
so we were not able to test it properly.

--
Luiz Augusto von Dentz