Bug 216580 - Jabra Elite 75t (ear buds):Unable to connect and use (`hci0: Opcode 0x 401 failed: -16`)
Summary: Jabra Elite 75t (ear buds):Unable to connect and use (`hci0: Opcode 0x 401 fa...
Status: NEW
Alias: None
Product: Drivers
Classification: Unclassified
Component: Bluetooth (show other bugs)
Hardware: All Linux
: P1 normal
Assignee: linux-bluetooth@vger.kernel.org
URL:
Keywords:
Depends on:
Blocks:
 
Reported: 2022-10-13 15:36 UTC by Paul Menzel
Modified: 2022-10-21 19:40 UTC (History)
2 users (show)

See Also:
Kernel Version: 6.0-rc7
Subsystem:
Regression: No
Bisected commit-id:


Attachments
`journalctl -o short-precise -u bluetooth -b` (877.41 KB, text/plain)
2022-10-13 15:39 UTC, Paul Menzel
Details
sudo btmon -w /dev/shm/20221013-trace.log (483.68 KB, text/plain)
2022-10-13 15:40 UTC, Paul Menzel
Details
`sudo btmon -w /dev/shm/20221021-linux-6.1-rc1+-ge35184f32151-with-patch.log` (15.91 KB, application/octet-stream)
2022-10-21 13:58 UTC, Paul Menzel
Details

Description Paul Menzel 2022-10-13 15:36:32 UTC
This is a Dell Latitude E7250 with Debian sid/unstable with Linux 6.0-rc7 and *bluez* 5.65-1.

    Bus 001 Device 003: ID 8087:0a2a Intel Corp. Bluetooth wireless interface

The Jabra ear buds show up several times in the gnome-control-center’s Bluetooth section (Every three(?) seconds one more popped up until three or four were shown.)

Pairing and connecting worked, but then it was disconnected, and the properties said, the device type is unknown, that means it wasn’t detected as audio output. Linux logged the line below, no idea, if it is related:

    Bluetooth: hci0: Opcode 0x 401 failed: -16

```
[10968.635501] calling  bnep_init+0x0/0xc2 [bnep] @ 8069
[10968.635510] Bluetooth: BNEP (Ethernet Emulation) ver 1.3
[10968.635512] Bluetooth: BNEP filters: protocol multicast
[10968.635517] Bluetooth: BNEP socket layer initialized
[10968.635518] initcall bnep_init+0x0/0xc2 [bnep] returned 0 after 8 usecs
[10968.639206] Bluetooth: MGMT ver 1.22
[10968.656529] calling  af_alg_init+0x0/0x1000 [af_alg] @ 8072
[10968.656536] NET: Registered PF_ALG protocol family
[10968.656537] initcall af_alg_init+0x0/0x1000 [af_alg] returned 0 after 1 usecs
[10968.670311] calling  algif_skcipher_init+0x0/0x1000 [algif_skcipher] @ 8075
[10968.670319] initcall algif_skcipher_init+0x0/0x1000 [algif_skcipher] returned 0 after 0 usecs
[10968.694495] calling  algif_hash_init+0x0/0x1000 [algif_hash] @ 8080
[10968.694502] initcall algif_hash_init+0x0/0x1000 [algif_hash] returned 0 after 0 usecs
[10968.703175] calling  crypto_cmac_module_init+0x0/0x1000 [cmac] @ 8084
[10968.703181] initcall crypto_cmac_module_init+0x0/0x1000 [cmac] returned 0 after 1 usecs
[10969.100553] calling  rfcomm_init+0x0/0xdd [rfcomm] @ 8087
[10969.100629] Bluetooth: RFCOMM TTY layer initialized
[10969.100634] Bluetooth: RFCOMM socket layer initialized
[10969.100643] Bluetooth: RFCOMM ver 1.11
[10969.100646] initcall rfcomm_init+0x0/0xdd [rfcomm] returned 0 after 81 usecs
[10998.096380] calling  prng_mod_init+0x0/0x1000 [ansi_cprng] @ 8139
[10998.096539] initcall prng_mod_init+0x0/0x1000 [ansi_cprng] returned 0 after 149 usecs
[10998.102550] calling  drbg_init+0x0/0xef2 [drbg] @ 8139
[10998.103349] initcall drbg_init+0x0/0xef2 [drbg] returned 0 after 791 usecs
[10998.115790] calling  sha512_generic_mod_init+0x0/0x1000 [sha512_generic] @ 8168
[10998.115976] initcall sha512_generic_mod_init+0x0/0x1000 [sha512_generic] returned 0 after 175 usecs
[10998.117796] calling  sha512_ssse3_mod_init+0x0/0x1000 [sha512_ssse3] @ 8168
[10998.118010] initcall sha512_ssse3_mod_init+0x0/0x1000 [sha512_ssse3] returned 0 after 205 usecs
[10998.124309] calling  jent_mod_init+0x0/0x1000 [jitterentropy_rng] @ 8179
[10998.133261] initcall jent_mod_init+0x0/0x1000 [jitterentropy_rng] returned 0 after 8942 usecs
[11016.243648] Bluetooth: hci0: Opcode 0x 401 failed: -16
```

bluetoothd messages in the journal:

```
Okt 13 14:08:19.628200 ersatz systemd[1]: Starting Bluetooth service...
Okt 13 14:08:19.717447 ersatz bluetoothd[8067]: Bluetooth daemon 5.65
Okt 13 14:08:19.731566 ersatz systemd[1]: Started Bluetooth service.
Okt 13 14:08:19.740475 ersatz bluetoothd[8067]: Starting SDP server
Okt 13 14:08:19.778720 ersatz bluetoothd[8067]: Bluetooth management interface 1.22 initialized
Okt 13 14:08:19.846270 ersatz bluetoothd[8067]: profiles/sap/server.c:sap_server_register() Sap driver initialization failed.
Okt 13 14:08:19.846286 ersatz bluetoothd[8067]: sap-server: Operation not permitted (1)
Okt 13 14:08:20.245498 ersatz bluetoothd[8067]: Endpoint registered: sender=:1.56 path=/MediaEndpoint/A2DPSource/ldac
Okt 13 14:08:20.245524 ersatz bluetoothd[8067]: Endpoint registered: sender=:1.56 path=/MediaEndpoint/A2DPSink/aptx_hd
Okt 13 14:08:20.245533 ersatz bluetoothd[8067]: Endpoint registered: sender=:1.56 path=/MediaEndpoint/A2DPSource/aptx_hd
Okt 13 14:08:20.245540 ersatz bluetoothd[8067]: Endpoint registered: sender=:1.56 path=/MediaEndpoint/A2DPSink/aptx
Okt 13 14:08:20.245546 ersatz bluetoothd[8067]: Endpoint registered: sender=:1.56 path=/MediaEndpoint/A2DPSource/aptx
Okt 13 14:08:20.245554 ersatz bluetoothd[8067]: Endpoint registered: sender=:1.56 path=/MediaEndpoint/A2DPSink/sbc
Okt 13 14:08:20.245562 ersatz bluetoothd[8067]: Endpoint registered: sender=:1.56 path=/MediaEndpoint/A2DPSource/sbc
Okt 13 14:08:20.245568 ersatz bluetoothd[8067]: Endpoint registered: sender=:1.56 path=/MediaEndpoint/A2DPSink/sbc_xq
Okt 13 14:08:20.245574 ersatz bluetoothd[8067]: Endpoint registered: sender=:1.56 path=/MediaEndpoint/A2DPSource/sbc_xq
Okt 13 14:08:20.245580 ersatz bluetoothd[8067]: Endpoint registered: sender=:1.56 path=/MediaEndpoint/A2DPSource/aptx_ll_1
Okt 13 14:08:20.245587 ersatz bluetoothd[8067]: Endpoint registered: sender=:1.56 path=/MediaEndpoint/A2DPSource/aptx_ll_0
Okt 13 14:08:20.245593 ersatz bluetoothd[8067]: Endpoint registered: sender=:1.56 path=/MediaEndpoint/A2DPSource/aptx_ll_duplex_1
Okt 13 14:08:20.245603 ersatz bluetoothd[8067]: Endpoint registered: sender=:1.56 path=/MediaEndpoint/A2DPSource/aptx_ll_duplex_0
Okt 13 14:08:20.245616 ersatz bluetoothd[8067]: Endpoint registered: sender=:1.56 path=/MediaEndpoint/A2DPSource/faststream
Okt 13 14:08:20.245628 ersatz bluetoothd[8067]: Endpoint registered: sender=:1.56 path=/MediaEndpoint/A2DPSource/faststream_duplex
Okt 13 14:08:20.245639 ersatz bluetoothd[8067]: Endpoint registered: sender=:1.56 path=/MediaEndpoint/A2DPSink/opus_05
Okt 13 14:08:20.245651 ersatz bluetoothd[8067]: Endpoint registered: sender=:1.56 path=/MediaEndpoint/A2DPSource/opus_05
Okt 13 14:08:20.245661 ersatz bluetoothd[8067]: Endpoint registered: sender=:1.56 path=/MediaEndpoint/A2DPSource/opus_05_51
Okt 13 14:08:20.245668 ersatz bluetoothd[8067]: Endpoint registered: sender=:1.56 path=/MediaEndpoint/A2DPSource/opus_05_71
Okt 13 14:08:20.245674 ersatz bluetoothd[8067]: Endpoint registered: sender=:1.56 path=/MediaEndpoint/A2DPSink/opus_05_duplex
Okt 13 14:08:20.245680 ersatz bluetoothd[8067]: Endpoint registered: sender=:1.56 path=/MediaEndpoint/A2DPSource/opus_05_duplex
Okt 13 14:08:20.245687 ersatz bluetoothd[8067]: Endpoint registered: sender=:1.56 path=/MediaEndpoint/A2DPSource/opus_05_pro
Okt 13 14:08:22.515725 ersatz bluetoothd[8067]: Failed to set mode: Failed (0x03)
Okt 13 14:08:26.044861 ersatz bluetoothd[8067]: Failed to set mode: Failed (0x03)
Okt 13 14:08:57.914640 ersatz bluetoothd[8067]: Device is already marked as connected
Okt 13 14:08:59.218535 ersatz bluetoothd[8067]: Device is already marked as connected
Okt 13 14:10:02.335876 ersatz bluetoothd[8067]: src/profile.c:ext_connect() Hands-Free Voice gateway failed connect to 50:C2:ED:6B:24:98: Connection refused (111)
Okt 13 14:10:02.471755 ersatz bluetoothd[8067]: profiles/audio/avdtp.c:avdtp_connect_cb() connect to 50:C2:ED:6B:24:98: Connection refused (111)
Okt 13 14:10:05.127901 ersatz bluetoothd[8067]: profiles/audio/avdtp.c:avdtp_connect_cb() connect to 50:C2:ED:6B:24:98: Connection refused (111)
Okt 13 14:10:11.327826 ersatz bluetoothd[8067]: src/profile.c:ext_connect() Hands-Free Voice gateway failed connect to 50:C2:ED:6B:24:98: Connection refused (111)
Okt 13 14:10:11.463810 ersatz bluetoothd[8067]: profiles/audio/avdtp.c:avdtp_connect_cb() connect to 50:C2:ED:6B:24:98: Connection refused (111)
Okt 13 14:10:14.107766 ersatz bluetoothd[8067]: profiles/audio/avdtp.c:avdtp_connect_cb() connect to 50:C2:ED:6B:24:98: Connection refused (111)
Okt 13 14:17:56.098494 ersatz bluetoothd[8067]: Device is already marked as connected
Okt 13 14:17:56.475325 ersatz bluetoothd[8067]: Failed to set mode: Busy (0x0a)
Okt 13 14:17:56.936575 ersatz bluetoothd[8067]: Device is already marked as connected
Okt 13 14:18:18.286239 ersatz bluetoothd[8067]: src/profile.c:record_cb() Unable to get Hands-Free Voice gateway SDP record: Host is down
Okt 13 14:31:41.074910 ersatz bluetoothd[8067]: Wrong size of start discovery return parameters
Okt 13 14:31:46.754174 ersatz bluetoothd[8067]: Terminating
Okt 13 14:31:46.754333 ersatz systemd[1]: Stopping Bluetooth service...
```

After removing `btusb` module, and starting `btmon` and inserting `btusb` also, and after a restart, the Jabra device did not show up anymore.

(Connecting the laptop to the Nokia N9 still worked.)
Comment 1 Paul Menzel 2022-10-13 15:39:39 UTC
Created attachment 302992 [details]
`journalctl -o short-precise -u bluetooth -b`
Comment 2 Paul Menzel 2022-10-13 15:40:57 UTC
Created attachment 302993 [details]
sudo btmon -w /dev/shm/20221013-trace.log
Comment 3 Luiz Von Dentz 2022-10-13 19:44:44 UTC
This looks suspicious:

< HCI Command: Microsoft SW RF Kill (0x3f|0x003f) plen 0                                                                #844 [hci0] 226.575196
> HCI Event: Command Complete (0x0e) plen 4                                    
>                                         #845 [hci0] 226.576116
      Microsoft SW RF Kill (0x3f|0x003f) ncmd 1
        Status: Success (0x00)

Which comes from:

https://git.kernel.org/pub/scm/linux/kernel/git/bluetooth/bluetooth-next.git/tree/drivers/bluetooth/btintel.c#n2600

The problem is that after sending RFKILL we need to reset again in order for the firmware to become operation again as explained bellow:

https://git.kernel.org/pub/scm/linux/kernel/git/bluetooth/bluetooth-next.git/tree/drivers/bluetooth/btintel.c#n2361
Comment 4 Luiz Von Dentz 2022-10-13 21:04:01 UTC
Perhaps something like the following makes more sense since what the command was meant for is to synchronize the RFKILL of state of the host with the controller:

diff --git a/drivers/bluetooth/btintel.c b/drivers/bluetooth/btintel.c
index a657e9a3e96a..f8be70f7924e 100644
--- a/drivers/bluetooth/btintel.c
+++ b/drivers/bluetooth/btintel.c
@@ -2597,7 +2597,7 @@ static int btintel_shutdown_combined(struct hci_dev *hdev)
         * goes off. As a workaround, sends HCI_Intel_SW_RFKILL to put the
         * device in the RFKILL ON state which turns off the BT LED immediately.
         */
-       if (btintel_test_flag(hdev, INTEL_BROKEN_SHUTDOWN_LED)) {
+       if (hci_dev_test_flag(hdev, HCI_RFKILLED)) {
                skb = __hci_cmd_sync(hdev, 0xfc3f, 0, NULL, HCI_INIT_TIMEOUT);
                if (IS_ERR(skb)) {
                        ret = PTR_ERR(skb);
Comment 5 Paul Menzel 2022-10-21 13:58:11 UTC
Created attachment 303066 [details]
`sudo btmon -w /dev/shm/20221021-linux-6.1-rc1+-ge35184f32151-with-patch.log`

I tested this on a different system, Dell XPS 13 9360, with the Qualcomm Atheros Communications QCA1x4 Bluetooth 4.0 (0cf3:e300), and Debian sid/unstable with KDE Plasma 5.25/5.26 and *bluez* 5.65-1+b1. Please find the `btmon` output attached.
Comment 6 Luiz Von Dentz 2022-10-21 19:40:12 UTC
(In reply to Paul Menzel from comment #5)
> Created attachment 303066 [details]
> `sudo btmon -w /dev/shm/20221021-linux-6.1-rc1+-ge35184f32151-with-patch.log`
> 
> I tested this on a different system, Dell XPS 13 9360, with the Qualcomm
> Atheros Communications QCA1x4 Bluetooth 4.0 (0cf3:e300), and Debian
> sid/unstable with KDE Plasma 5.25/5.26 and *bluez* 5.65-1+b1. Please find
> the `btmon` output attached.

Well the patch above is intel specific and it probably does make any difference for a Qualcomm controller and it doesn't seem there is any attempt to connect to anything in this logs.

Note You need to log in before you can comment on or make changes to this bug.