[RFC PATCH 0/1] Bluetooth: btmtk: add USB autopm support to btmtk_usb_setup()

[RFC PATCH 0/1] Bluetooth: btmtk: add USB autopm support to btmtk_usb_setup()

[Alberto Garcia]

Hello,

I've been having problems with the btmtk bluetooth driver for a long
time. What happens is a failure during initialization and the loading
of the firmware, with errors like these:

   kernel: Bluetooth: hci0: Failed to get device id (-108)
   kernel: Bluetooth: hci0: Failed to get fw version (-108)

The device is MediaTek MT7921 (0489:e0cd), there are more details in
this bug report:

   https://bugzilla.kernel.org/show_bug.cgi?id=217475

Passing btusb.enable_autosuspend=n seems to solve the problem for me.
My computer's hard drive is encrypted so it can take a long time
before the bluetooth firmware is loaded, so I interpret that this
causes the device to autosuspend during boot and that's why
initialization fails. Does that make sense?

I saw that commit 67dba2c28fe0 fixed similar errors during shutdown by
using usb_autopm_get_interface() so I tried the same approach for the
btusb_mtk_setup() function. I confirm that this solves the problem for
me and with this patch the bluetooth adapter works reliably.

I was also suggested to try the simpler approach of using setup_on_usb
instead:

        if (IS_ENABLED(CONFIG_BT_HCIBTUSB_MTK) &&
            (id->driver_info & BTUSB_MEDIATEK)) {
-               hdev->setup = btusb_mtk_setup;
+               data->setup_on_usb = btusb_mtk_setup;
                hdev->shutdown = btusb_mtk_shutdown;
                hdev->manufacturer = 70;

However this does not solve the problem:

   kernel: usbcore: registered new interface driver btusb
   kernel: Bluetooth: hci0: HW/SW Version: 0x008a008a, Build Time: 20241106151414
   kernel: Bluetooth: hci0: Execution of wmt command timed out
   kernel: Bluetooth: hci0: Failed to send wmt patch dwnld (-110)
   kernel: Bluetooth: hci0: Failed to set up firmware (-110)

So I would like to know if a patch like the one I'm sending is a good
approach or if I should try something else.

Regards,

Berto

Alberto Garcia (1):
  Bluetooth: btmtk: add USB autopm support to btmtk_usb_setup()

 drivers/bluetooth/btmtk.c | 17 ++++++++++++++++-
 1 file changed, 16 insertions(+), 1 deletion(-)

-- 
2.47.3

[RFC PATCH 1/1] Bluetooth: btmtk: add USB autopm support to btmtk_usb_setup()

[Alberto Garcia]

btmtk_usb_setup() accesses the device without first ensuring that it
is awake, so it may fail if the device has been autosuspended, e.g.:

    Bluetooth: hci0: Failed to get device id (-108)
    Bluetooth: hci0: Failed to get fw version (-108)

Add usb_autopm_get_interface()/usb_autopm_put_interface() around the
entire setup process, mirroring what commit 67dba2c28fe0 ("Bluetooth:
btmtk: Fix failed to send func ctrl for MediaTek devices.") already
did for btmtk_usb_shutdown().

Link: https://bugzilla.kernel.org/show_bug.cgi?id=217475
Signed-off-by: Alberto Garcia <berto@igalia.com>
---
 drivers/bluetooth/btmtk.c | 17 ++++++++++++++++-
 1 file changed, 16 insertions(+), 1 deletion(-)

diff --git a/drivers/bluetooth/btmtk.c b/drivers/bluetooth/btmtk.c
index fa7533578f85..a5d15efa8712 100644
--- a/drivers/bluetooth/btmtk.c
+++ b/drivers/bluetooth/btmtk.c
@@ -1268,7 +1268,7 @@ int btmtk_usb_suspend(struct hci_dev *hdev)
 }
 EXPORT_SYMBOL_GPL(btmtk_usb_suspend);
 
-int btmtk_usb_setup(struct hci_dev *hdev)
+static int do_btmtk_usb_setup(struct hci_dev *hdev)
 {
 	struct btmtk_data *btmtk_data = hci_get_priv(hdev);
 	struct btmtk_hci_wmt_params wmt_params;
@@ -1453,6 +1453,21 @@ int btmtk_usb_setup(struct hci_dev *hdev)
 
 	return 0;
 }
+
+int btmtk_usb_setup(struct hci_dev *hdev)
+{
+	struct btmtk_data *btmtk_data = hci_get_priv(hdev);
+	int err;
+
+	err = usb_autopm_get_interface(btmtk_data->intf);
+	if (err < 0)
+		return err;
+
+	err = do_btmtk_usb_setup(hdev);
+
+	usb_autopm_put_interface(btmtk_data->intf);
+	return err;
+}
 EXPORT_SYMBOL_GPL(btmtk_usb_setup);
 
 int btmtk_usb_shutdown(struct hci_dev *hdev)
-- 
2.47.3

RE: Bluetooth: btmtk: add USB autopm support to btmtk_usb_setup()

[bluez.test.bot]

[-- Attachment #1: Type: text/plain, Size: 2833 bytes --]

This is automated email and please do not reply to this email!

Dear submitter,

Thank you for submitting the patches to the linux bluetooth mailing list.
This is a CI test results with your patch series:
PW Link:https://patchwork.kernel.org/project/bluetooth/list/?series=1071561

---Test result---

Test Summary:
CheckPatch                    PENDING   0.44 seconds
GitLint                       PENDING   0.25 seconds
SubjectPrefix                 PASS      0.11 seconds
BuildKernel                   PASS      26.35 seconds
CheckAllWarning               PASS      28.76 seconds
CheckSparse                   PASS      27.75 seconds
BuildKernel32                 PASS      25.28 seconds
TestRunnerSetup               PASS      562.72 seconds
TestRunner_l2cap-tester       PASS      27.55 seconds
TestRunner_iso-tester         FAIL      38.48 seconds
TestRunner_bnep-tester        PASS      6.23 seconds
TestRunner_mgmt-tester        FAIL      114.01 seconds
TestRunner_rfcomm-tester      PASS      9.83 seconds
TestRunner_sco-tester         FAIL      14.12 seconds
TestRunner_ioctl-tester       PASS      10.23 seconds
TestRunner_mesh-tester        FAIL      11.48 seconds
TestRunner_smp-tester         PASS      8.44 seconds
TestRunner_userchan-tester    PASS      6.52 seconds
IncrementalBuild              PENDING   0.83 seconds

Details
##############################
Test: CheckPatch - PENDING
Desc: Run checkpatch.pl script
Output:

##############################
Test: GitLint - PENDING
Desc: Run gitlint
Output:

##############################
Test: TestRunner_iso-tester - FAIL
Desc: Run iso-tester with test-runner
Output:
BUG: KASAN: slab-use-after-free in le_read_features_complete+0x7e/0x2b0
Total: 141, Passed: 141 (100.0%), Failed: 0, Not Run: 0
##############################
Test: TestRunner_mgmt-tester - FAIL
Desc: Run mgmt-tester with test-runner
Output:
Total: 494, Passed: 489 (99.0%), Failed: 1, Not Run: 4

Failed Test Cases
Read Exp Feature - Success                           Failed       0.103 seconds
##############################
Test: TestRunner_sco-tester - FAIL
Desc: Run sco-tester with test-runner
Output:
WARNING: possible circular locking dependency detected
BUG: sleeping function called from invalid context at net/core/sock.c:3782
Total: 30, Passed: 30 (100.0%), Failed: 0, Not Run: 0
##############################
Test: TestRunner_mesh-tester - FAIL
Desc: Run mesh-tester with test-runner
Output:
Total: 10, Passed: 8 (80.0%), Failed: 2, Not Run: 0

Failed Test Cases
Mesh - Send cancel - 1                               Timed out    1.908 seconds
Mesh - Send cancel - 2                               Timed out    2.006 seconds
##############################
Test: IncrementalBuild - PENDING
Desc: Incremental build with the patches in the series
Output:



---
Regards,
Linux Bluetooth

RE: Bluetooth: btmtk: add USB autopm support to btmtk_usb_setup()

[bluez.test.bot]

[-- Attachment #1: Type: text/plain, Size: 6877 bytes --]

This is automated email and please do not reply to this email!

Dear submitter,

Thank you for submitting the patches to the linux bluetooth mailing list.
This is a CI test results with your patch series:
PW Link:https://patchwork.kernel.org/project/bluetooth/list/?series=1071561

---Test result---

Test Summary:
CheckPatch                    PENDING   0.35 seconds
GitLint                       PENDING   0.27 seconds
SubjectPrefix                 PASS      0.13 seconds
BuildKernel                   PASS      26.15 seconds
CheckAllWarning               PASS      28.43 seconds
CheckSparse                   PASS      27.09 seconds
BuildKernel32                 PASS      25.51 seconds
TestRunnerSetup               PASS      567.84 seconds
TestRunner_l2cap-tester       PASS      28.15 seconds
TestRunner_iso-tester         PASS      57.33 seconds
TestRunner_bnep-tester        PASS      6.37 seconds
TestRunner_mgmt-tester        FAIL      114.44 seconds
TestRunner_rfcomm-tester      PASS      9.48 seconds
TestRunner_sco-tester         FAIL      14.43 seconds
TestRunner_ioctl-tester       PASS      10.34 seconds
TestRunner_mesh-tester        FAIL      12.52 seconds
TestRunner_smp-tester         PASS      8.74 seconds
TestRunner_userchan-tester    PASS      6.71 seconds
TestRunner_6lowpan-tester     FAIL      8.71 seconds
IncrementalBuild              PENDING   0.32 seconds

Details
##############################
Test: CheckPatch - PENDING
Desc: Run checkpatch.pl script
Output:

##############################
Test: GitLint - PENDING
Desc: Run gitlint
Output:

##############################
Test: TestRunner_mgmt-tester - FAIL
Desc: Run mgmt-tester with test-runner
Output:
Total: 494, Passed: 489 (99.0%), Failed: 1, Not Run: 4

Failed Test Cases
Read Exp Feature - Success                           Failed       0.112 seconds
##############################
Test: TestRunner_sco-tester - FAIL
Desc: Run sco-tester with test-runner
Output:
WARNING: possible circular locking dependency detected
7.0.0-rc2-ged17c54eba28 #1 Not tainted
------------------------------------------------------
kworker/u5:2/117 is trying to acquire lock:
ffff8880025fe240 (sk_lock-AF_BLUETOOTH-BTPROTO_SCO){+.+.}-{0:0}, at: sco_connect_cfm+0x358/0x8d0

but task is already holding lock:
ffff888002141c20 (&conn->lock){+.+.}-{3:3}, at: sco_connect_cfm+0x22d/0x8d0

which lock already depends on the new lock.


the existing dependency chain (in reverse order) is:

-> #1 (&conn->lock){+.+.}-{3:3}:
       lock_acquire+0xf7/0x2c0
       _raw_spin_lock+0x2a/0x40
       sco_sock_connect+0x4d7/0x1280
       __sys_connect+0x1a3/0x260
       __x64_sys_connect+0x6e/0xb0
       do_syscall_64+0xa0/0x570
       entry_SYSCALL_64_after_hwframe+0x74/0x7c

-> #0 (sk_lock-AF_BLUETOOTH-BTPROTO_SCO){+.+.}-{0:0}:
       check_prev_add+0xe9/0xc70
       __lock_acquire+0x1457/0x1df0
       lock_acquire+0xf7/0x2c0
       lock_sock_nested+0x36/0xd0
       sco_connect_cfm+0x358/0x8d0
       hci_sync_conn_complete_evt+0x3d3/0x8e0
       hci_event_packet+0x74f/0xb10
       hci_rx_work+0x398/0xd00
       process_scheduled_works+0xb16/0x1ac0
       worker_thread+0x4ff/0xba0
       kthread+0x368/0x490
       ret_from_fork+0x498/0x7e0
       ret_from_fork_asm+0x19/0x30

other info that might help us debug this:

...
BUG: sleeping function called from invalid context at net/core/sock.c:3782
in_atomic(): 1, irqs_disabled(): 0, non_block: 0, pid: 117, name: kworker/u5:2
preempt_count: 1, expected: 0
RCU nest depth: 0, expected: 0
INFO: lockdep is turned off.
CPU: 0 UID: 0 PID: 117 Comm: kworker/u5:2 Not tainted 7.0.0-rc2-ged17c54eba28 #1 PREEMPT(lazy) 
Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS 1.13.0-1ubuntu1.1 04/01/2014
Workqueue: hci0 hci_rx_work
Call Trace:
 <TASK>
 dump_stack_lvl+0x49/0x60
 __might_resched+0x2ea/0x500
 lock_sock_nested+0x47/0xd0
 ? sco_connect_cfm+0x358/0x8d0
 sco_connect_cfm+0x358/0x8d0
 ? hci_debugfs_create_conn+0x190/0x210
 ? __pfx_sco_connect_cfm+0x10/0x10
 hci_sync_conn_complete_evt+0x3d3/0x8e0
 hci_event_packet+0x74f/0xb10
 ? __pfx_hci_sync_conn_complete_evt+0x10/0x10
 ? __pfx_hci_event_packet+0x10/0x10
 ? mark_held_locks+0x49/0x80
 ? lockdep_hardirqs_on_prepare+0xd4/0x180
 ? _raw_spin_unlock_irqrestore+0x2c/0x50
 hci_rx_work+0x398/0xd00
 process_scheduled_works+0xb16/0x1ac0
 ? __pfx_process_scheduled_works+0x10/0x10
 ? lock_acquire+0xf7/0x2c0
 ? lock_is_held_type+0x9b/0x110
 ? __pfx_hci_rx_work+0x10/0x10
 worker_thread+0x4ff/0xba0
 ? _raw_spin_unlock_irqrestore+0x2c/0x50
 ? __pfx_worker_thread+0x10/0x10
 kthread+0x368/0x490
 ? _raw_spin_unlock_irq+0x23/0x40
 ? __pfx_kthread+0x10/0x10
 ret_from_fork+0x498/0x7e0
 ? __pfx_ret_from_fork+0x10/0x10
 ? __switch_to+0x9e4/0xe50
 ? __switch_to_asm+0x32/0x60
...
Total: 30, Passed: 30 (100.0%), Failed: 0, Not Run: 0
##############################
Test: TestRunner_mesh-tester - FAIL
Desc: Run mesh-tester with test-runner
Output:
Total: 10, Passed: 8 (80.0%), Failed: 2, Not Run: 0

Failed Test Cases
Mesh - Send cancel - 1                               Timed out    2.762 seconds
Mesh - Send cancel - 2                               Timed out    1.995 seconds
##############################
Test: TestRunner_6lowpan-tester - FAIL
Desc: Run 6lowpan-tester with test-runner
Output:
WARNING: possible circular locking dependency detected
7.0.0-rc2-ged17c54eba28 #1 Not tainted
------------------------------------------------------
kworker/0:1/11 is trying to acquire lock:
ffff888002760140 ((wq_completion)hci0#2){+.+.}-{0:0}, at: touch_wq_lockdep_map+0x75/0x180

but task is already holding lock:
ffffffff8b64d720 (rtnl_mutex){+.+.}-{4:4}, at: lowpan_unregister_netdev+0xd/0x30

which lock already depends on the new lock.


the existing dependency chain (in reverse order) is:

-> #4 (rtnl_mutex){+.+.}-{4:4}:
       lock_acquire+0xf7/0x2c0
       __mutex_lock+0x16b/0x1fc0
       lowpan_register_netdev+0x11/0x30
       chan_ready_cb+0x836/0xd00
       l2cap_recv_frame+0x6a06/0x8920
       l2cap_recv_acldata+0x790/0xdf0
       hci_rx_work+0x500/0xd00
       process_scheduled_works+0xb16/0x1ac0
       worker_thread+0x4ff/0xba0
       kthread+0x368/0x490
       ret_from_fork+0x498/0x7e0
       ret_from_fork_asm+0x19/0x30

-> #3 (&chan->lock#3/1){+.+.}-{4:4}:
       lock_acquire+0xf7/0x2c0
       __mutex_lock+0x16b/0x1fc0
       l2cap_chan_connect+0x74e/0x1980
       lowpan_control_write+0x523/0x660
       full_proxy_write+0x10b/0x190
       vfs_write+0x1c0/0xf60
       ksys_write+0xf1/0x1d0
       do_syscall_64+0xa0/0x570
       entry_SYSCALL_64_after_hwframe+0x74/0x7c

-> #2 (&conn->lock){+.+.}-{4:4}:
...
Total: 8, Passed: 8 (100.0%), Failed: 0, Not Run: 0
##############################
Test: IncrementalBuild - PENDING
Desc: Incremental build with the patches in the series
Output:



https://github.com/bluez/bluetooth-next/pull/31/checks

---
Regards,
Linux Bluetooth