Received-SPF: pass (google.com: domain of linux-bluetooth-owner@vger.kernel.org designates 2620:137:e000::1:20 as permitted sender) client-ip=2620:137:e000::1:20;
MIME-Version: 1.0
References: <CACk7upyDgd8kCY+8j+RMJz35GXrF=bwRzDNH76Oh8q4nB8i0KQ@mail.gmail.com>
In-Reply-To: <CACk7upyDgd8kCY+8j+RMJz35GXrF=bwRzDNH76Oh8q4nB8i0KQ@mail.gmail.com>
From:   Raul Cheleguini <raul.cheleguini@gmail.com>
Date:   Thu, 27 Apr 2023 15:49:29 -0300
Message-ID: <CACk7upyDxpy45wEWXi_EU_r7F8WeD2bObSHRRo82HGTrYGXNHQ@mail.gmail.com>
Subject: Re: unexpected SMP command errors with controller ATS2851
To:     linux-bluetooth@vger.kernel.org
Cc:     marcel@holtmann.org, johan.hedberg@gmail.com, luiz.dentz@gmail.com
Content-Type: text/plain; charset="UTF-8"
Content-Transfer-Encoding: quoted-printable
Precedence: bulk

On Fri, Mar 24, 2023 at 12:17=E2=80=AFAM 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.000=
1/
> 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_ev=
t()
[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 befor=
e
it has been allowed and this confusion eventually leads to a disconnect eve=
nt.

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_di=
st

Regards,
Raul.

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