Hi,
after upgrading to kernel 5.1.1 (and also 5.1.2) my bluetooth speakers
are unable to auto-reconnect. I can connect them without problems, but
once I turn them off and on again an unending sequence of connections
and disconnections begins:
---- manual connection ok ---------
[bluetooth]# connect E0:D1:E6:07:62:E1
Attempting to connect to E0:D1:E6:07:62:E1
[CHG] Device E0:D1:E6:07:62:E1 Connected: yes
Connection successful
[CHG] Device E0:D1:E6:07:62:E1 ServicesResolved: yes
---- turned off speakers and on again ----
[CHG] Device E0:D1:E6:07:62:E1 ServicesResolved: no
[CHG] Device E0:D1:E6:07:62:E1 Connected: no
[CHG] Device E0:D1:E6:07:62:E1 Connected: yes
[CHG] Device E0:D1:E6:07:62:E1 Connected: no
[CHG] Device E0:D1:E6:07:62:E1 Connected: yes
[CHG] Device E0:D1:E6:07:62:E1 Connected: no
[CHG] Device E0:D1:E6:07:62:E1 Connected: yes
[CHG] Device E0:D1:E6:07:62:E1 Connected: no
[CHG] Device E0:D1:E6:07:62:E1 Connected: yes
[CHG] Device E0:D1:E6:07:62:E1 Connected: no
I've tested this with a number of kernels:
linux-lts 4.19.43: doesn't work
linux 5.0.13: works
linux 5.1: works
linux 5.1.1: doesn't work
linux 5.1.2: doesn't work
All the above tests were done against bluez 5.50. I've also tested
bluez git master against linux 5.1.2 to no avail.
During failed attempts to auto-reconnect, the debug log shows:
May 17 02:25:27 carlos bluetoothd[8178]:
src/adapter.c:connected_callback() hci0 device E0:D1:E6:07:62:E1
connected eir_len 5
May 17 02:25:27 carlos bluetoothd[8178]:
src/adapter.c:dev_disconnected() Device E0:D1:E6:07:62:E1
disconnected, reason 3
May 17 02:25:27 carlos bluetoothd[8178]:
src/adapter.c:adapter_remove_connection()
May 17 02:25:27 carlos bluetoothd[8178]:
plugins/policy.c:disconnect_cb() reason 3
May 17 02:25:27 carlos bluetoothd[8178]:
src/adapter.c:bonding_attempt_complete() hci0 bdaddr E0:D1:E6:07:62:E1
type 0 status 0xe
May 17 02:25:27 carlos bluetoothd[8178]:
src/device.c:device_bonding_complete() bonding (nil) status 0x0e
May 17 02:25:27 carlos bluetoothd[8178]:
src/device.c:device_bonding_failed() status 14
Some other info that may be relevant:
> uname -a
Linux carlos 5.1.1-arch1-1-ARCH #1 SMP PREEMPT Sat May 11 13:02:48 UTC
2019 x86_64 GNU/Linux
> yay -Qi pulseaudio
Version : 12.2-2
If you need something else to track down this issue, please let me
know. I've also reported this to pulseaudio tracker:
https://gitlab.freedesktop.org/pulseaudio/pulseaudio/issues/674.
Best regards
--
Carlos
I'm seeing the exact same behavior, but on a mouse (bt 3.x mouse; I
also have another which seems to be BLE and it still connects fine).
Reverting to 5.0 always works.
Em sex, 17 de mai de 2019 às 03:03, Carlos Pita
<[email protected]> escreveu:
>
> Hi,
>
> after upgrading to kernel 5.1.1 (and also 5.1.2) my bluetooth speakers
> are unable to auto-reconnect. I can connect them without problems, but
> once I turn them off and on again an unending sequence of connections
> and disconnections begins:
>
> ---- manual connection ok ---------
> [bluetooth]# connect E0:D1:E6:07:62:E1
> Attempting to connect to E0:D1:E6:07:62:E1
> [CHG] Device E0:D1:E6:07:62:E1 Connected: yes
> Connection successful
> [CHG] Device E0:D1:E6:07:62:E1 ServicesResolved: yes
> ---- turned off speakers and on again ----
> [CHG] Device E0:D1:E6:07:62:E1 ServicesResolved: no
> [CHG] Device E0:D1:E6:07:62:E1 Connected: no
> [CHG] Device E0:D1:E6:07:62:E1 Connected: yes
> [CHG] Device E0:D1:E6:07:62:E1 Connected: no
> [CHG] Device E0:D1:E6:07:62:E1 Connected: yes
> [CHG] Device E0:D1:E6:07:62:E1 Connected: no
> [CHG] Device E0:D1:E6:07:62:E1 Connected: yes
> [CHG] Device E0:D1:E6:07:62:E1 Connected: no
> [CHG] Device E0:D1:E6:07:62:E1 Connected: yes
> [CHG] Device E0:D1:E6:07:62:E1 Connected: no
>
> I've tested this with a number of kernels:
>
> linux-lts 4.19.43: doesn't work
> linux 5.0.13: works
> linux 5.1: works
> linux 5.1.1: doesn't work
> linux 5.1.2: doesn't work
>
> All the above tests were done against bluez 5.50. I've also tested
> bluez git master against linux 5.1.2 to no avail.
>
> During failed attempts to auto-reconnect, the debug log shows:
>
> May 17 02:25:27 carlos bluetoothd[8178]:
> src/adapter.c:connected_callback() hci0 device E0:D1:E6:07:62:E1
> connected eir_len 5
> May 17 02:25:27 carlos bluetoothd[8178]:
> src/adapter.c:dev_disconnected() Device E0:D1:E6:07:62:E1
> disconnected, reason 3
> May 17 02:25:27 carlos bluetoothd[8178]:
> src/adapter.c:adapter_remove_connection()
> May 17 02:25:27 carlos bluetoothd[8178]:
> plugins/policy.c:disconnect_cb() reason 3
> May 17 02:25:27 carlos bluetoothd[8178]:
> src/adapter.c:bonding_attempt_complete() hci0 bdaddr E0:D1:E6:07:62:E1
> type 0 status 0xe
> May 17 02:25:27 carlos bluetoothd[8178]:
> src/device.c:device_bonding_complete() bonding (nil) status 0x0e
> May 17 02:25:27 carlos bluetoothd[8178]:
> src/device.c:device_bonding_failed() status 14
>
> Some other info that may be relevant:
>
> > uname -a
> Linux carlos 5.1.1-arch1-1-ARCH #1 SMP PREEMPT Sat May 11 13:02:48 UTC
> 2019 x86_64 GNU/Linux
>
> > yay -Qi pulseaudio
> Version : 12.2-2
>
> If you need something else to track down this issue, please let me
> know. I've also reported this to pulseaudio tracker:
> https://gitlab.freedesktop.org/pulseaudio/pulseaudio/issues/674.
>
> Best regards
> --
> Carlos
Hi,
On Sat, May 18, 2019 at 12:44 AM Alexandre Pereira Nunes
<[email protected]> wrote:
>
> I'm seeing the exact same behavior, but on a mouse (bt 3.x mouse; I
> also have another which seems to be BLE and it still connects fine).
> Reverting to 5.0 always works.
>
>
> Em sex, 17 de mai de 2019 às 03:03, Carlos Pita
> <[email protected]> escreveu:
> >
> > Hi,
> >
> > after upgrading to kernel 5.1.1 (and also 5.1.2) my bluetooth speakers
> > are unable to auto-reconnect. I can connect them without problems, but
> > once I turn them off and on again an unending sequence of connections
> > and disconnections begins:
> >
> > ---- manual connection ok ---------
> > [bluetooth]# connect E0:D1:E6:07:62:E1
> > Attempting to connect to E0:D1:E6:07:62:E1
> > [CHG] Device E0:D1:E6:07:62:E1 Connected: yes
> > Connection successful
> > [CHG] Device E0:D1:E6:07:62:E1 ServicesResolved: yes
> > ---- turned off speakers and on again ----
> > [CHG] Device E0:D1:E6:07:62:E1 ServicesResolved: no
> > [CHG] Device E0:D1:E6:07:62:E1 Connected: no
> > [CHG] Device E0:D1:E6:07:62:E1 Connected: yes
> > [CHG] Device E0:D1:E6:07:62:E1 Connected: no
> > [CHG] Device E0:D1:E6:07:62:E1 Connected: yes
> > [CHG] Device E0:D1:E6:07:62:E1 Connected: no
> > [CHG] Device E0:D1:E6:07:62:E1 Connected: yes
> > [CHG] Device E0:D1:E6:07:62:E1 Connected: no
> > [CHG] Device E0:D1:E6:07:62:E1 Connected: yes
> > [CHG] Device E0:D1:E6:07:62:E1 Connected: no
> >
> > I've tested this with a number of kernels:
> >
> > linux-lts 4.19.43: doesn't work
> > linux 5.0.13: works
> > linux 5.1: works
> > linux 5.1.1: doesn't work
> > linux 5.1.2: doesn't work
> >
> > All the above tests were done against bluez 5.50. I've also tested
> > bluez git master against linux 5.1.2 to no avail.
> >
> > During failed attempts to auto-reconnect, the debug log shows:
> >
> > May 17 02:25:27 carlos bluetoothd[8178]:
> > src/adapter.c:connected_callback() hci0 device E0:D1:E6:07:62:E1
> > connected eir_len 5
> > May 17 02:25:27 carlos bluetoothd[8178]:
> > src/adapter.c:dev_disconnected() Device E0:D1:E6:07:62:E1
> > disconnected, reason 3
> > May 17 02:25:27 carlos bluetoothd[8178]:
> > src/adapter.c:adapter_remove_connection()
> > May 17 02:25:27 carlos bluetoothd[8178]:
> > plugins/policy.c:disconnect_cb() reason 3
> > May 17 02:25:27 carlos bluetoothd[8178]:
> > src/adapter.c:bonding_attempt_complete() hci0 bdaddr E0:D1:E6:07:62:E1
> > type 0 status 0xe
> > May 17 02:25:27 carlos bluetoothd[8178]:
> > src/device.c:device_bonding_complete() bonding (nil) status 0x0e
> > May 17 02:25:27 carlos bluetoothd[8178]:
> > src/device.c:device_bonding_failed() status 14
> >
> > Some other info that may be relevant:
> >
> > > uname -a
> > Linux carlos 5.1.1-arch1-1-ARCH #1 SMP PREEMPT Sat May 11 13:02:48 UTC
> > 2019 x86_64 GNU/Linux
> >
> > > yay -Qi pulseaudio
> > Version : 12.2-2
> >
> > If you need something else to track down this issue, please let me
> > know. I've also reported this to pulseaudio tracker:
> > https://gitlab.freedesktop.org/pulseaudio/pulseaudio/issues/674.
Please use btmon to collect the HCI trace and attach it to the problem.
--
Luiz Augusto von Dentz
Hi Luiz,
I've attached the output for a single auto-reconnect/disconnect sequence.
Notice this was using the 4.19.44 kernel, which is the LTS one in Arch
Linux. As I've pointed out above, the problem seems like a regression,
since it's happening both in older and latest kernels, but not
in-between them.
Best regards
--
Carlos
I've attached two btmon sessions: one captured from the text mode and
another with -w param.
Both on 5.1.2 kernel.
Em sáb, 18 de mai de 2019 às 05:53, Carlos Pita
<[email protected]> escreveu:
>
> Hi Luiz,
>
> I've attached the output for a single auto-reconnect/disconnect sequence.
>
> Notice this was using the 4.19.44 kernel, which is the LTS one in Arch
> Linux. As I've pointed out above, the problem seems like a regression,
> since it's happening both in older and latest kernels, but not
> in-between them.
>
> Best regards
> --
> Carlos
Hi Alexandre,
On Sat, May 18, 2019 at 7:13 PM Alexandre Pereira Nunes
<[email protected]> wrote:
>
> I've attached two btmon sessions: one captured from the text mode and
> another with -w param.
>
> Both on 5.1.2 kernel.
The problem seems to be here:
< ACL Data TX: Handle 512 flags 0x00 dlen 16 #87 [hci0] 9.952984
L2CAP: Connection Response (0x03) ident 1 len 8
Destination CID: 0
Source CID: 65
Result: Connection refused - security block (0x0003)
Status: No further information available (0x0000)
Ruling out encryption since HID don't require it:
https://git.kernel.org/pub/scm/bluetooth/bluez.git/tree/profiles/input/server.c#n294
Are you seeing any of the following logs on the journal:
https://git.kernel.org/pub/scm/bluetooth/bluez.git/tree/profiles/input/server.c#n181
> Em sáb, 18 de mai de 2019 às 05:53, Carlos Pita
> <[email protected]> escreveu:
> >
> > Hi Luiz,
> >
> > I've attached the output for a single auto-reconnect/disconnect sequence.
> >
> > Notice this was using the 4.19.44 kernel, which is the LTS one in Arch
> > Linux. As I've pointed out above, the problem seems like a regression,
> > since it's happening both in older and latest kernels, but not
> > in-between them.
> >
> > Best regards
> > --
> > Carlos
--
Luiz Augusto von Dentz
Hi,
The HCI log below seems to indicate an issue with the mouse:
On Sat, May 18, 2019, Alexandre Pereira Nunes wrote:
> > HCI Event: Connect Complete (0x03) plen 11 #6 [hci0] 5.703492
> Status: Success (0x00)
> Handle: 512
> Address: 20:14:12:09:18:BD (OUI 20-14-12)
> Link type: ACL (0x01)
> Encryption: Disabled (0x00)
> < HCI Command: Read Remote Supported.. (0x01|0x001b) plen 2 #7 [hci0] 5.703737
> Handle: 512
> > HCI Event: Command Status (0x0f) plen 4 #8 [hci0] 5.704439
> Read Remote Supported Features (0x01|0x001b) ncmd 1
> Status: Success (0x00)
> > HCI Event: Link Supervision Timeout Changed (0x38) plen 4 #9 [hci0] 5.707467
> Handle: 512
> Timeout: 2000.000 msec (0x0c80)
> > HCI Event: Read Remote Supported Features (0x0b) plen 11 #10 [hci0] 5.714448
> Status: Success (0x00)
> Handle: 512
> Features: 0xfc 0x02 0x04 0x38 0x18 0x18 0x19 0x83
> Encryption
> Slot offset
> Timing accuracy
> Role switch
> Hold mode
> Sniff mode
> Power control requests
> Power control
> Enhanced inquiry scan
> Interlaced inquiry scan
> Interlaced page scan
> AFH capable slave
> AFH classification slave
> AFH capable master
> AFH classification master
> Extended Inquiry Response
> Secure Simple Pairing
> Encapsulated PDU
> Link Supervision Timeout Changed Event
> Inquiry TX Power Level
> Extended features
> < HCI Command: Read Remote Extended.. (0x01|0x001c) plen 3 #11 [hci0] 5.714535
> Handle: 512
> Page: 1
> > HCI Event: Command Status (0x0f) plen 4 #12 [hci0] 5.715445
> Read Remote Extended Features (0x01|0x001c) ncmd 1
> Status: Success (0x00)
> > HCI Event: Read Remote Extended Features (0x23) plen 13 #13 [hci0] 5.728475
> Status: Success (0x00)
> Handle: 512
> Page: 1/0
> Features: 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00
> < HCI Command: Remote Name Request (0x01|0x0019) plen 10 #14 [hci0] 5.728565
> Address: 20:14:12:09:18:BD (OUI 20-14-12)
> Page scan repetition mode: R2 (0x02)
> Page scan mode: Mandatory (0x00)
> Clock offset: 0x0000
> < ACL Data TX: Handle 512 flags 0x00 dlen 10 #15 [hci0] 5.728582
> L2CAP: Information Request (0x0a) ident 1 len 2
> Type: Extended features supported (0x0002)
> > HCI Event: Command Status (0x0f) plen 4 #16 [hci0] 5.729447
> Remote Name Request (0x01|0x0019) ncmd 1
> Status: Success (0x00)
> > HCI Event: Number of Completed Packets (0x13) plen 5 #17 [hci0] 5.740495
> Num handles: 1
> Handle: 512
> Count: 1
> > ACL Data RX: Handle 512 flags 0x02 dlen 16 #18 [hci0] 5.746576
> L2CAP: Information Response (0x0b) ident 1 len 8
> Type: Extended features supported (0x0002)
> Result: Success (0x0000)
> Features: 0x00000000
> > HCI Event: Remote Name Req Complete (0x07) plen 255 #19 [hci0] 5.781389
> Status: Success (0x00)
> Address: 20:14:12:09:18:BD (OUI 20-14-12)
> Name: Bluetooth Mouse
> @ MGMT Event: Device Connected (0x000b) plen 35 {0x0001} [hci0] 5.781439
> BR/EDR Address: 20:14:12:09:18:BD (OUI 20-14-12)
> Flags: 0x00000000
> Data length: 22
> Name (complete): Bluetooth Mouse
> Class: 0x002580
> Major class: Peripheral (mouse, joystick, keyboards)
> Minor class: 0x20
> Limited Discoverable Mode
> > HCI Event: Role Change (0x12) plen 8 #20 [hci0] 6.058251
> Status: Success (0x00)
> Address: 20:14:12:09:18:BD (OUI 20-14-12)
> Role: Master (0x00)
> > ACL Data RX: Handle 512 flags 0x02 dlen 12 #21 [hci0] 6.088229
> L2CAP: Connection Request (0x02) ident 1 len 4
> PSM: 17 (0x0011)
> Source CID: 65
> < ACL Data TX: Handle 512 flags 0x00 dlen 16 #22 [hci0] 6.088298
> L2CAP: Connection Response (0x03) ident 1 len 8
> Destination CID: 0
> Source CID: 65
> Result: Connection refused - security block (0x0003)
> Status: No further information available (0x0000)
From the above it looks like the mouse is initiating an L2CAP Connection
Request to a non-SDP PSM (17 in this case), which is prohibited by the
spec whenever both sides support Secure Simple Pairing (SSP), and the
kernel is correctly responding with a security block error. So to me the
above looks like misbehavior by the mouse. Could you also post the same
log using a kernel that's working for you?
Johan
Slight clarification to my earlier mail:
On 18 May 2019, at 20.05, Johan Hedberg <[email protected]> wrote:
> From the above it looks like the mouse is initiating an L2CAP Connection
> Request to a non-SDP PSM (17 in this case), which is prohibited by the
> spec whenever both sides support Secure Simple Pairing (SSP)
.. *before encryption is enabled*. As can be seen from the log the connection starts unencrypted and does not get encrypted by the time of the L2CAP Connection Request.
Johan
Hi Luiz,
On 18 May 2019, at 19.30, Luiz Augusto von Dentz <[email protected]> wrote:
> The problem seems to be here:
>
> < ACL Data TX: Handle 512 flags 0x00 dlen 16 #87 [hci0] 9.952984
> L2CAP: Connection Response (0x03) ident 1 len 8
> Destination CID: 0
> Source CID: 65
> Result: Connection refused - security block (0x0003)
> Status: No further information available (0x0000)
>
> Ruling out encryption since HID don't require it:
When both devices support SSP, encryption is required for any non-SDP PSM. The kernel enforces this regardless of what kind of options were set for the socket.
Johan
Hi Johan,
+Marcel
On Sat, May 18, 2019 at 9:08 PM Johan Hedberg <[email protected]> wrote:
>
> Hi Luiz,
>
> On 18 May 2019, at 19.30, Luiz Augusto von Dentz <[email protected]> wrote:
> > The problem seems to be here:
> >
> > < ACL Data TX: Handle 512 flags 0x00 dlen 16 #87 [hci0] 9.952984
> > L2CAP: Connection Response (0x03) ident 1 len 8
> > Destination CID: 0
> > Source CID: 65
> > Result: Connection refused - security block (0x0003)
> > Status: No further information available (0x0000)
> >
> > Ruling out encryption since HID don't require it:
>
> When both devices support SSP, encryption is required for any non-SDP PSM. The kernel enforces this regardless of what kind of options were set for the socket.
Perhaps it could be this one:
https://git.kernel.org/pub/scm/linux/kernel/git/bluetooth/bluetooth-next.git/commit/net/bluetooth/hci_conn.c?id=d5bb334a8e171b262e48f378bd2096c0ea458265
It looks like the test you mentioned it is just above the check for
enc_key_size, though people mentioned it has been working so could it
be that SSP is not enabled after all?
--
Luiz Augusto von Dentz