Received-SPF: pass (google.com: domain of linux-bluetooth-owner@vger.kernel.org designates 23.128.96.18 as permitted sender) client-ip=23.128.96.18;
MIME-Version: 1.0
From:   Lukasz Majczak <lma@semihalf.com>
Date:   Mon, 14 Jun 2021 15:32:35 +0200
Message-ID: <CAFJ_xbpkmBv4O8EPN0DRNYEzBEFcm1dj+ae765626nd+PPbo3Q@mail.gmail.com>
Subject: PROBLEM: Crash after Bluetooth: SMP: Convert BT_ERR/BT_DBG to bt_dev_err/bt_dev_dbg
To:     luiz.dentz@gmail.com, marcel@holtmann.org, johan.hedberg@gmail.com
Cc:     upstream@semihalf.com, linux-bluetooth@vger.kernel.org,
        Alex Levin <levinale@google.com>
Content-Type: text/plain; charset="UTF-8"
Precedence: bulk

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 <luiz.von.dentz@intel.com>
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