unexpected SMP command errors with controller ATS2851

unexpected SMP command errors with controller ATS2851

[Raul Cheleguini]

Hi everyone,

I'm trying to understand and narrow down a pairing problem with this
controller that I'm trying to make it work in Linux.

When pairing, the negotiation does not complete and the system logs
the following messages:

Bluetooth: hci0: unexpected SMP command 0x08 from dd:5e:b9:fe:49:3f
Bluetooth: hci0: unexpected SMP command 0x09 from dd:5e:b9:fe:49:3f
Bluetooth: hci0: Opcode 0x200d failed: -110
Bluetooth: hci0: request failed to create LE connection: err -110

(dd:5e:b9:fe:49:3f is my bluetooth mouse)

After some debug I found the condition that refuses the SMP commands and
drops them:

net/bluetooth/smp.c in smp_sig_channel()

if (smp && !test_and_clear_bit(code, &smp->allow_cmd))
    goto drop;

The interesting part is that if I disable this condition with comments,
the pairing process manages to complete and my bluetooth mouse starts to work
(even with some errors in logs):

Bluetooth: hci0: Opcode 0x200d failed: -110
Bluetooth: hci0: request failed to create LE connection: err -110
hid: raw HID events driver (C) Jiri Kosina
input: Logi M650 L Mouse as /devices/virtual/misc/uhid/0005:046D:B02A.0001/
input/input6
hid-generic 0005:046D:B02A.0001: input,hidraw0: BLUETOOTH HID v0.09 Mouse
[Logi M650 L] on f4:4e:fc:c0:de:5e
Bluetooth: hci0: Opcode 0x200d failed: -110
Bluetooth: hci0: request failed to create LE connection: err -110

Logs from bluetoothd receiving the mouse data events:

bluetoothd[576]: src/shared/att.c:can_read_data() (chan 0x55f8ad8db380)
ATT PDU received: 0x1b
bluetoothd[576]: src/shared/att.c:can_read_data() (chan 0x55f8ad8db380)
ATT PDU received: 0x1b
bluetoothd[576]: src/shared/att.c:can_read_data() (chan 0x55f8ad8db380)
ATT PDU received: 0x1b

I kindly ask guidance on what could be done in these cases or any hints
how to further debug this issue.

For context, the controller works in other systems using generic drivers.

Regards,
Raul.

Re: unexpected SMP command errors with controller ATS2851

[Christopher Snowhill]

Would some pcapng logs be useful? It appears this device flags some commands as supported, while indicating their entire feature sets are not supported in the local supported features bitfields. Or that's as near as I can guess.

First is captured from a generic driver that works, the latter is captured from Linux 6.2.9. Included in the working capture is the beginning of an exchange with my Sony headphones. The latter stops logging after the first failed command.

https://f.losno.co/bluetooth_ats2851.pcapng.zst
https://f.losno.co/bluetooth_ats2851_broken.pcapng.zst

Re: unexpected SMP command errors with controller ATS2851

[Raul Cheleguini]

On Fri, Mar 31, 2023 at 2:50 AM Christopher Snowhill <chris@kode54.net> wrote:
>
> Would some pcapng logs be useful? It appears this device flags some commands as supported, while indicating their entire feature sets are not supported in the local supported features bitfields. Or that's as near as I can guess.
>
> First is captured from a generic driver that works, the latter is captured from Linux 6.2.9. Included in the working capture is the beginning of an exchange with my Sony headphones. The latter stops logging after the first failed command.
>
> https://f.losno.co/bluetooth_ats2851.pcapng.zst
> https://f.losno.co/bluetooth_ats2851_broken.pcapng.zst

Hi Christopher,

Thank you for sharing the pcap files. Based on your comments from another
thread regarding this adapter, I suggest that you apply the following patches:

[PATCH] Bluetooth: Improve support for Actions Semi ATS2851 based devices
https://marc.info/?l=linux-bluetooth&m=167846197021176&w=2

[PATCH] Bluetooth: Add new quirk for broken set random RPA timeout for ATS...
https://marc.info/?l=linux-bluetooth&m=167957918920723&w=2

[PATCH] Bluetooth: Add new quirk for broken extended create connection for...
https://marc.info/?l=linux-bluetooth&m=167957998621276&w=2

You would end up in the situation mentioned in this thread, and you could
resume your tests from there. I haven't had the time to experiment with SMP yet,
so any assistance would be greatly appreciated.

Re: unexpected SMP command errors with controller ATS2851

[Christopher Snowhill]

On Thu, Apr 13, 2023, at 6:54 AM, Raul Cheleguini wrote:
> On Fri, Mar 31, 2023 at 2:50 AM Christopher Snowhill <chris@kode54.net> wrote:
>>
>> Would some pcapng logs be useful? It appears this device flags some commands as supported, while indicating their entire feature sets are not supported in the local supported features bitfields. Or that's as near as I can guess.
>>
>> First is captured from a generic driver that works, the latter is captured from Linux 6.2.9. Included in the working capture is the beginning of an exchange with my Sony headphones. The latter stops logging after the first failed command.
>>
>> https://f.losno.co/bluetooth_ats2851.pcapng.zst
>> https://f.losno.co/bluetooth_ats2851_broken.pcapng.zst
>
> Hi Christopher,
>
> Thank you for sharing the pcap files. Based on your comments from another
> thread regarding this adapter, I suggest that you apply the following patches:
>
> [PATCH] Bluetooth: Improve support for Actions Semi ATS2851 based devices
> https://marc.info/?l=linux-bluetooth&m=167846197021176&w=2
>
> [PATCH] Bluetooth: Add new quirk for broken set random RPA timeout for ATS...
> https://marc.info/?l=linux-bluetooth&m=167957918920723&w=2
>
> [PATCH] Bluetooth: Add new quirk for broken extended create connection for...
> https://marc.info/?l=linux-bluetooth&m=167957998621276&w=2
>
> You would end up in the situation mentioned in this thread, and you could
> resume your tests from there. I haven't had the time to experiment with SMP yet,
> so any assistance would be greatly appreciated.

The above PCAP files from Linux were logged with those three patches already applied. It did not help my situation. And any further feedback on this device will not be coming from me, as I already returned it and bought a supported Realtek device instead.

Re: unexpected SMP command errors with controller ATS2851

[Raul Cheleguini]

On Fri, Mar 24, 2023 at 12:17 AM Raul Cheleguini
<raul.cheleguini@gmail.com> wrote:
>
> Hi everyone,
>
> I'm trying to understand and narrow down a pairing problem with this
> controller that I'm trying to make it work in Linux.
>
> When pairing, the negotiation does not complete and the system logs
> the following messages:
>
> Bluetooth: hci0: unexpected SMP command 0x08 from dd:5e:b9:fe:49:3f
> Bluetooth: hci0: unexpected SMP command 0x09 from dd:5e:b9:fe:49:3f
> Bluetooth: hci0: Opcode 0x200d failed: -110
> Bluetooth: hci0: request failed to create LE connection: err -110
>
> (dd:5e:b9:fe:49:3f is my bluetooth mouse)
>
> After some debug I found the condition that refuses the SMP commands and
> drops them:
>
> net/bluetooth/smp.c in smp_sig_channel()
>
> if (smp && !test_and_clear_bit(code, &smp->allow_cmd))
>     goto drop;
>
> The interesting part is that if I disable this condition with comments,
> the pairing process manages to complete and my bluetooth mouse starts to work
> (even with some errors in logs):
>
> Bluetooth: hci0: Opcode 0x200d failed: -110
> Bluetooth: hci0: request failed to create LE connection: err -110
> hid: raw HID events driver (C) Jiri Kosina
> input: Logi M650 L Mouse as /devices/virtual/misc/uhid/0005:046D:B02A.0001/
> input/input6
> hid-generic 0005:046D:B02A.0001: input,hidraw0: BLUETOOTH HID v0.09 Mouse
> [Logi M650 L] on f4:4e:fc:c0:de:5e
> Bluetooth: hci0: Opcode 0x200d failed: -110
> Bluetooth: hci0: request failed to create LE connection: err -110
>
> Logs from bluetoothd receiving the mouse data events:
>
> bluetoothd[576]: src/shared/att.c:can_read_data() (chan 0x55f8ad8db380)
> ATT PDU received: 0x1b
> bluetoothd[576]: src/shared/att.c:can_read_data() (chan 0x55f8ad8db380)
> ATT PDU received: 0x1b
> bluetoothd[576]: src/shared/att.c:can_read_data() (chan 0x55f8ad8db380)
> ATT PDU received: 0x1b
>
> I kindly ask guidance on what could be done in these cases or any hints
> how to further debug this issue.
>
> For context, the controller works in other systems using generic drivers.
>
> Regards,
> Raul.

For the benefit of any novice who may face similar situation in future:

The error "unexpected SMP command 0x08" indicates that command 0x08
(SMP_CMD_IDENT_INFO) arrives before it has been allowed. That is part smp
implementation, it allows commands and responds to them in the expected
context, otherwise it drops them.

In this particular situation, we enter a condition in hci_encrypt_change_evt()
[1] that results in an unrelated HCI command being sent during the time we
should be preparing to receive command 0x08. The command 0x08 arrives before
it has been allowed and this confusion eventually leads to a disconnect event.

According to my raw notes, 0x08 is allowed in smp_allow_key_dist(), as
a result of a callback chain for this type of connection/adapter:

hci_encrypt_cfm > security_cfm_cb >
l2cap_security_cfm > smp_resume_cb > smp_distribute_keys > smp_allow_key_dist

Regards,
Raul.

[1]
https://elixir.bootlin.com/linux/v6.3/source/net/bluetooth/hci_event.c#L3670