Return-Path: MIME-Version: 1.0 In-Reply-To: <2DBBB005-93A7-47ED-8E88-1D6B92ACCC07@holtmann.org> References: <2045332.GytFuFKTvp@ix> <2DBBB005-93A7-47ED-8E88-1D6B92ACCC07@holtmann.org> From: =?UTF-8?Q?Fran=C3=A7ois_Beaufort?= Date: Mon, 30 Nov 2015 08:43:16 +0100 Message-ID: Subject: Re: Unknown Connection Identifier To: Marcel Holtmann Cc: Szymon Janc , linux-bluetooth@vger.kernel.org Content-Type: multipart/alternative; boundary=047d7b3a8a9298fbe00525bd32da List-ID: --047d7b3a8a9298fbe00525bd32da Content-Type: text/plain; charset=UTF-8 On Tue, Nov 24, 2015 at 12:00 PM, Marcel Holtmann wrote: > Hi Francois, > > > Thanks both of you for your input. > > > > Here are my 100% reproducible steps: > > - Restart bluetoothd to start fresh > > - Remove cached device (remove 88:0F:10:9D:EB:42) > > - Run basic scan (scan on) > > - Wait for the device to pop up in results and stop scan (scan off) > > - Try to connect to it (connect 88:0F:10:9D:EB:42) > > > > As you can read below I now have 2 "LE Connection Complete (0x01)" > events. > > > > Bluetooth monitor ver 5.35 > > = New Index: A4:17:31:78:A6:04 (BR/EDR,USB,hci0) > > [hci0] 0.624321 > > < HCI Command: LE Add Device To White List (0x08|0x0011) plen 7 > > [hci0] 11.038826 > > Address type: Public (0x00) > > Address: 88:0F:10:9D:EB:42 (OUI 88-0F-10) > >> HCI Event: Command Complete (0x0e) plen 4 > [hci0] 11.040084 > > LE Add Device To White List (0x08|0x0011) ncmd 1 > > Status: Success (0x00) > > < HCI Command: LE Set Scan Parameters (0x08|0x000b) plen 7 > > [hci0] 11.040125 > > Type: Passive (0x00) > > Interval: 60.000 msec (0x0060) > > Window: 30.000 msec (0x0030) > > Own address type: Public (0x00) > > Filter policy: Ignore not in white list (0x01) > >> HCI Event: Command Complete (0x0e) plen 4 > [hci0] 11.041085 > > LE Set Scan Parameters (0x08|0x000b) ncmd 1 > > Status: Success (0x00) > > < HCI Command: LE Set Scan Enable (0x08|0x000c) plen 2 > > [hci0] 11.041134 > > Scanning: Enabled (0x01) > > Filter duplicates: Enabled (0x01) > >> HCI Event: Command Complete (0x0e) plen 4 > [hci0] 11.042084 > > LE Set Scan Enable (0x08|0x000c) ncmd 1 > > Status: Success (0x00) > >> HCI Event: LE Meta Event (0x3e) plen 43 > [hci0] 15.668141 > > LE Advertising Report (0x02) > > Num reports: 1 > > Event type: Connectable undirected - ADV_IND (0x00) > > Address type: Public (0x00) > > Address: 88:0F:10:9D:EB:42 (OUI 88-0F-10) > > Data length: 31 > > Flags: 0x06 > > LE General Discoverable Mode > > BR/EDR Not Supported > > Company: Anhui Huami Information Technology Co., Ltd. (343) > > Data: 00f70b676930f4c909f4a5acd792a299ff02880f109deb42 > > RSSI: -59 dBm (0xc5) > > < HCI Command: LE Set Scan Enable (0x08|0x000c) plen 2 > > [hci0] 15.668289 > > Scanning: Disabled (0x00) > > Filter duplicates: Disabled (0x00) > >> HCI Event: Command Complete (0x0e) plen 4 > [hci0] 15.669062 > > LE Set Scan Enable (0x08|0x000c) ncmd 1 > > Status: Success (0x00) > > < HCI Command: LE Create Connection (0x08|0x000d) plen 25 > > [hci0] 15.669171 > > Scan interval: 60.000 msec (0x0060) > > Scan window: 30.000 msec (0x0030) > > we might should have the LE Create Connection scan with a full duty cycle > here. So it does not miss any advertising PDUs. > Is this something the Linux Bluetooth team is going to address? > > > Filter policy: White list is not used (0x00) > > Peer address type: Public (0x00) > > Peer address: 88:0F:10:9D:EB:42 (OUI 88-0F-10) > > Own address type: Public (0x00) > > Min connection interval: 50.00 msec (0x0028) > > Max connection interval: 70.00 msec (0x0038) > > Connection latency: 0x0000 > > Supervision timeout: 420 msec (0x002a) > > Min connection length: 0.000 msec (0x0000) > > Max connection length: 0.000 msec (0x0000) > >> HCI Event: Command Status (0x0f) plen 4 > [hci0] 15.670065 > > LE Create Connection (0x08|0x000d) ncmd 1 > > Status: Success (0x00) > > < HCI Command: LE Create Connection Cancel (0x08|0x000e) plen 0 > > [hci0] 17.670566 > > And I think we need to increase the timeout to something like 4-5 seconds > before we give up and try the next device that might have been found. > > For my own curiosity, how does does perform Android Bluetooth stack when creating a LE connection? Does it hardcode a 4-5 seconds timeout or does it use other heuristics? > >> HCI Event: Command Complete (0x0e) plen 4 > [hci0] 17.672048 > > LE Create Connection Cancel (0x08|0x000e) ncmd 1 > > Status: Success (0x00) > >> HCI Event: LE Meta Event (0x3e) plen 19 > [hci0] 17.674036 > > LE Connection Complete (0x01) > > Status: Unknown Connection Identifier (0x02) > > Handle: 32 > > Role: Master (0x00) > > Peer address type: Public (0x00) > > Peer address: 88:0F:10:9D:EB:42 (OUI 88-0F-10) > > Connection interval: 67.50 msec (0x0036) > > Connection latency: 0.00 msec (0x0000) > > Supervision timeout: 420 msec (0x002a) > > Master clock accuracy: 0x00 > > @ Connect Failed: 88:0F:10:9D:EB:42 (1) status 0x02 > > This one still needs to be fixed. It is a bug. The implementation is too > naive. The unknown connection identifier is actually the success case for > LE Create Connection Cancel command. And since we keep trying until the > connection timeout hits, this is not an error at this point. > > Regards > > Marcel > > --047d7b3a8a9298fbe00525bd32da Content-Type: text/html; charset=UTF-8 Content-Transfer-Encoding: quoted-printable


On Tue, Nov 24, 2015 at 12:00 PM, Marcel Holtmann <= ;marcel@holtmann.o= rg> wrote:
Hi Francois,

> Thanks both of you for your input.
>
> Here are my 100% reproducible steps:
> - Restart bluetoothd to start fresh
> - Remove cached device (remove 88:0F:10:9D:EB:42)
> - Run basic scan (scan on)
> - Wait for the device to pop up in results and stop scan (scan off) > - Try to connect to it (connect 88:0F:10:9D:EB:42)
>
> As you can read below I now have 2 "LE Connection Complete (0x01)= " events.
>
> Bluetooth monitor ver 5.35
> =3D New Index: A4:17:31:78:A6:04 (BR/EDR,USB,hci0)
>=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 [hci0] 0.624321=
> < HCI Command: LE Add Device To White List (0x08|0x0011) plen 7
>=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0[hci0] 11.038826=
>=C2=A0 =C2=A0 =C2=A0 =C2=A0 Address type: Public (0x00)
>=C2=A0 =C2=A0 =C2=A0 =C2=A0 Address: 88:0F:10:9D:EB:42 (OUI 88-0F-10) >> HCI Event: Command Complete (0x0e) plen 4=C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 = =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0[hci0] 11.040084
>=C2=A0 =C2=A0 =C2=A0 LE Add Device To White List (0x08|0x0011) ncmd 1 >=C2=A0 =C2=A0 =C2=A0 =C2=A0 Status: Success (0x00)
> < HCI Command: LE Set Scan Parameters (0x08|0x000b) plen 7
>=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0[hci0] 11.040125=
>=C2=A0 =C2=A0 =C2=A0 =C2=A0 Type: Passive (0x00)
>=C2=A0 =C2=A0 =C2=A0 =C2=A0 Interval: 60.000 msec (0x0060)
>=C2=A0 =C2=A0 =C2=A0 =C2=A0 Window: 30.000 msec (0x0030)
>=C2=A0 =C2=A0 =C2=A0 =C2=A0 Own address type: Public (0x00)
>=C2=A0 =C2=A0 =C2=A0 =C2=A0 Filter policy: Ignore not in white list (0x= 01)
>> HCI Event: Command Complete (0x0e) plen 4=C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 = =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0[hci0] 11.041085
>=C2=A0 =C2=A0 =C2=A0 LE Set Scan Parameters (0x08|0x000b) ncmd 1
>=C2=A0 =C2=A0 =C2=A0 =C2=A0 Status: Success (0x00)
> < HCI Command: LE Set Scan Enable (0x08|0x000c) plen 2
>=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0[hci0] 11.041134=
>=C2=A0 =C2=A0 =C2=A0 =C2=A0 Scanning: Enabled (0x01)
>=C2=A0 =C2=A0 =C2=A0 =C2=A0 Filter duplicates: Enabled (0x01)
>> HCI Event: Command Complete (0x0e) plen 4=C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 = =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0[hci0] 11.042084
>=C2=A0 =C2=A0 =C2=A0 LE Set Scan Enable (0x08|0x000c) ncmd 1
>=C2=A0 =C2=A0 =C2=A0 =C2=A0 Status: Success (0x00)
>> HCI Event: LE Meta Event (0x3e) plen 43=C2=A0 =C2=A0 =C2=A0 =C2=A0= =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0[hci0] 15.668141=
>=C2=A0 =C2=A0 =C2=A0 LE Advertising Report (0x02)
>=C2=A0 =C2=A0 =C2=A0 =C2=A0 Num reports: 1
>=C2=A0 =C2=A0 =C2=A0 =C2=A0 Event type: Connectable undirected - ADV_IN= D (0x00)
>=C2=A0 =C2=A0 =C2=A0 =C2=A0 Address type: Public (0x00)
>=C2=A0 =C2=A0 =C2=A0 =C2=A0 Address: 88:0F:10:9D:EB:42 (OUI 88-0F-10) >=C2=A0 =C2=A0 =C2=A0 =C2=A0 Data length: 31
>=C2=A0 =C2=A0 =C2=A0 =C2=A0 Flags: 0x06
>=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 LE General Discoverable Mode
>=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 BR/EDR Not Supported
>=C2=A0 =C2=A0 =C2=A0 =C2=A0 Company: Anhui Huami Information Technology= Co., Ltd. (343)
>=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 Data: 00f70b676930f4c909f4a5acd792a2= 99ff02880f109deb42
>=C2=A0 =C2=A0 =C2=A0 =C2=A0 RSSI: -59 dBm (0xc5)
> < HCI Command: LE Set Scan Enable (0x08|0x000c) plen 2
>=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0[hci0] 15.668289=
>=C2=A0 =C2=A0 =C2=A0 =C2=A0 Scanning: Disabled (0x00)
>=C2=A0 =C2=A0 =C2=A0 =C2=A0 Filter duplicates: Disabled (0x00)
>> HCI Event: Command Complete (0x0e) plen 4=C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 = =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0[hci0] 15.669062
>=C2=A0 =C2=A0 =C2=A0 LE Set Scan Enable (0x08|0x000c) ncmd 1
>=C2=A0 =C2=A0 =C2=A0 =C2=A0 Status: Success (0x00)
> < HCI Command: LE Create Connection (0x08|0x000d) plen 25
>=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0[hci0] 15.669171=
>=C2=A0 =C2=A0 =C2=A0 =C2=A0 Scan interval: 60.000 msec (0x0060)
>=C2=A0 =C2=A0 =C2=A0 =C2=A0 Scan window: 30.000 msec (0x0030)

we might should have the LE Create Connection scan with a full = duty cycle here. So it does not miss any advertising PDUs.
=

Is this something the Linux Bluetooth team is going to = address?
=C2=A0

>=C2=A0 =C2=A0 =C2=A0 =C2=A0 Filter policy: White list is not used (0x00= )
>=C2=A0 =C2=A0 =C2=A0 =C2=A0 Peer address type: Public (0x00)
>=C2=A0 =C2=A0 =C2=A0 =C2=A0 Peer address: 88:0F:10:9D:EB:42 (OUI 88-0F-= 10)
>=C2=A0 =C2=A0 =C2=A0 =C2=A0 Own address type: Public (0x00)
>=C2=A0 =C2=A0 =C2=A0 =C2=A0 Min connection interval: 50.00 msec (0x0028= )
>=C2=A0 =C2=A0 =C2=A0 =C2=A0 Max connection interval: 70.00 msec (0x0038= )
>=C2=A0 =C2=A0 =C2=A0 =C2=A0 Connection latency: 0x0000
>=C2=A0 =C2=A0 =C2=A0 =C2=A0 Supervision timeout: 420 msec (0x002a)
>=C2=A0 =C2=A0 =C2=A0 =C2=A0 Min connection length: 0.000 msec (0x0000)<= br> >=C2=A0 =C2=A0 =C2=A0 =C2=A0 Max connection length: 0.000 msec (0x0000)<= br> >> HCI Event: Command Status (0x0f) plen 4=C2=A0 =C2=A0 =C2=A0 =C2=A0= =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0[hci0] 15.670065=
>=C2=A0 =C2=A0 =C2=A0 LE Create Connection (0x08|0x000d) ncmd 1
>=C2=A0 =C2=A0 =C2=A0 =C2=A0 Status: Success (0x00)
> < HCI Command: LE Create Connection Cancel (0x08|0x000e) plen 0
>=C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0[hci0] 17.670566=

And I think we need to increase the timeout to something like 4-5 se= conds before we give up and try the next device that might have been found.=


For my own cur= iosity, how does does perform Android Bluetooth stack when creating a LE co= nnection?=C2=A0
Does it hardcode a 4-5 seconds timeout or does it= use other heuristics?

=C2=A0
>> HCI Event: Command Complete (0x0e) plen 4=C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 = =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0[hci0] 17.672048
>=C2=A0 =C2=A0 =C2=A0 LE Create Connection Cancel (0x08|0x000e) ncmd 1 >=C2=A0 =C2=A0 =C2=A0 =C2=A0 Status: Success (0x00)
>> HCI Event: LE Meta Event (0x3e) plen 19=C2=A0 =C2=A0 =C2=A0 =C2=A0= =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2= =A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0 =C2=A0[hci0] 17.674036=
>=C2=A0 =C2=A0 =C2=A0 LE Connection Complete (0x01)
>=C2=A0 =C2=A0 =C2=A0 =C2=A0 Status: Unknown Connection Identifier (0x02= )
>=C2=A0 =C2=A0 =C2=A0 =C2=A0 Handle: 32
>=C2=A0 =C2=A0 =C2=A0 =C2=A0 Role: Master (0x00)
>=C2=A0 =C2=A0 =C2=A0 =C2=A0 Peer address type: Public (0x00)
>=C2=A0 =C2=A0 =C2=A0 =C2=A0 Peer address: 88:0F:10:9D:EB:42 (OUI 88-0F-= 10)
>=C2=A0 =C2=A0 =C2=A0 =C2=A0 Connection interval: 67.50 msec (0x0036) >=C2=A0 =C2=A0 =C2=A0 =C2=A0 Connection latency: 0.00 msec (0x0000)
>=C2=A0 =C2=A0 =C2=A0 =C2=A0 Supervision timeout: 420 msec (0x002a)
>=C2=A0 =C2=A0 =C2=A0 =C2=A0 Master clock accuracy: 0x00
> @ Connect Failed: 88:0F:10:9D:EB:42 (1) status 0x02

This one still needs to be fixed. It is a bug. The implementation is= too naive. The unknown connection identifier is actually the success case = for LE Create Connection Cancel command. And since we keep trying until the= connection timeout hits, this is not an error at this point.

Regards

Marcel


--047d7b3a8a9298fbe00525bd32da--