Hi Luiz,
On Wed, Nov 16, 2016 at 1:45 PM, Petri Gynther <pgynther@xxxxxxxxxx> wrote:
> Hi Luiz,
>
> On Fri, Nov 11, 2016 at 1:07 AM, Luiz Augusto von Dentz
> <luiz.dentz@xxxxxxxxx> wrote:
>>
>> Hi Petri,
>>
>> On Fri, Nov 11, 2016 at 4:42 AM, Petri Gynther <pgynther@xxxxxxxxxx>
>> wrote:
>> > Hi Luiz,
>> >
>> > On Thu, Nov 10, 2016 at 6:17 AM, Luiz Augusto von Dentz
>> > <luiz.dentz@xxxxxxxxx> wrote:
>> >> Hi Petri,
>> >>
>> >> On Wed, Nov 9, 2016 at 9:39 PM, Petri Gynther <pgynther@xxxxxxxxxx>
>> >> wrote:
>> >>> Hi linux-bluetooth:
>> >>>
>> >>> I'm seeing the following issue with BlueZ 5.43 and Linux 4.4.30.
>> >>>
>> >>> When a previously bonded HoG remote control reconnects to BlueZ 5.43
>> >>> host, BlueZ goes ahead and re-discovers the primary services of the
>> >>> bonded remote again and again on every reconnect.
>> >>>
>> >>> Why is this necessary? Shouldn't this information be cached on the
>> >>> initial pairing/bonding, and a reconnect can get this information from
>> >>> the relevant persistent file, rather than wasting BLE airtime and
>> >>> delaying the reconnect?
>> >>>
>> >>
>> >> IF, and only if, the cache is restored properly then yes it will work
>> >> as you said, but bt_hog is not yet using the gatt_db so it might
>> >> rediscover the handles anyway, this happens only once though.
>> >>
>> >>>
>> >>>
>> >>> In the above log, I see that MTU exchange takes place:
>> >>> 15,148467,14484676000,-;bluez: bluetoothd[1985]:
>> >>> src/device.c:gatt_debug() MTU exchange complete, with MTU: 23
>> >>>
>> >>> Looking at the relevant code in src/shared/gatt-client.c, function
>> >>> exchange_mtu_cb():
>> >>>
>> >>> util_debug(client->debug_callback, client->debug_data,
>> >>> "MTU exchange complete, with
>> >>> MTU: %u",
>> >>> bt_att_get_mtu(client->att));
>> >>>
>> >>> discover:
>> >>> client->discovery_req = bt_gatt_discover_all_primary_services(
>> >>> client->att,
>> >>> NULL,
>> >>>
>> >>> discover_primary_cb,
>> >>>
>> >>> discovery_op_ref(op),
>> >>>
>> >>> discovery_op_unref);
>> >>>
>> >>>
>> >>> The call to bt_gatt_discover_all_primary_services() is unconditional,
>> >>> whether the device was previously bonded or not.
>> >>
>> >> This does range validation in case service changed is not properly
>> >> implemented this will attempt to figure out if there are any changes
>> >> in the database, but note that it will stop in here:
>> >>
>> >> attr = gatt_db_insert_service(client->db, start, &uuid, true,
>> >> end - start + 1);
>> >> if (!attr) {
>> >>
>> >> So if the database already contain all the services it will no do more
>> >> than one Read By Group Type.
>> Looking into btmon details after the line marked ====:
>> > 15,18491,832722000,-;bluez: bluetoothd[2346]:
>> > profiles/scanparam/scan.c:refresh_ccc_written_cb() Scan Refresh:
>> > notification enabled
>> >
>> > We can see that BlueZ issues a bunch of ATT: Read By Group Type
>> > Requests to re-discover all primary services (0x2800):
>>
>>
>> This is what I said, we will issue Read By Group Type to validate the
>> cached data since service changed is not mandatory and way too many
>> devices don't implement it correctly.
>>
>> > 15,18491,832722000,-;bluez: bluetoothd[2346]:
>> > profiles/scanparam/scan.c:refresh_ccc_written_cb() Scan Refresh:
>> > notification enabled
>> > 15,18492,832723000,-;btmon: < ACL Data TX: Handle 128 flags 0x00 dlen
>> > 11 [hci0] 17:26:51.730522
>> > 15,18493,832725000,-;btmon: ATT: Read By Type Request (0x08) len 6
>> > 15,18494,832725000,-;btmon: Handle range: 0x002f-0x0037
>> > 15,18495,832725000,-;btmon: Attribute type: Characteristic
>> > (0x2803)
>> > 15,18496,832725000,-;btmon: > HCI Event: Number of Completed Packets
>> > (0x13) plen 5 [hci0] 17:26:51.731128
>> > 15,18497,832726000,-;btmon: Num handles: 1
>> > 15,18498,832726000,-;btmon: Handle: 128
>> > 15,18499,832726000,-;btmon: Count: 1
>> > 15,18500,832733000,-;btmon: > HCI Event: Number of Completed Packets
>> > (0x13) plen 5 [hci0] 17:26:51.739362
>> > 15,18501,832733000,-;btmon: Num handles: 1
>> > 15,18502,832733000,-;btmon: Handle: 128
>> > 15,18503,832733000,-;btmon: Count: 1
>> > 15,18504,832752000,-;btmon: > ACL Data RX: Handle 128 flags 0x02 dlen
>> > 27 [hci0] 17:26:51.759357
>> > 15,18505,832753000,-;btmon: ATT: Read By Type Response (0x09) len
>> > 22
>> > 15,18506,832753000,-;btmon: Attribute data length: 7
>> > 15,18507,832753000,-;btmon: Attribute data list: 3 entries
>> > 15,18508,832753000,-;btmon: Handle: 0x0030
>> > 15,18509,832753000,-;btmon: Value: 1e3100f1ff
>> > 15,18510,832753000,-;btmon: Handle: 0x0033
>> > 15,18511,832753000,-;btmon: Value: 0a3400f2ff
>> > 15,18512,832753000,-;btmon: Handle: 0x0035
>> > 15,18513,832753000,-;btmon: Value: 123600f4ff
>> > 15,18514,832754000,-;btmon: < ACL Data TX: Handle 128 flags 0x00 dlen
>> > 11 [hci0] 17:26:51.760043
>> > 15,18515,832754000,-;btmon: ATT: Read By Group Type Request (0x10)
>> > len 6
>> > 15,18516,832754000,-;btmon: Handle range: 0x0001-0xffff
>> > 15,18517,832754000,-;btmon: Attribute group type: Primary
>> > Service (0x2800)
>> > 15,18518,832762000,-;btmon: > HCI Event: Number of Completed Packets
>> > (0x13) plen 5 [hci0] 17:26:51.769346
>> > 15,18519,832762000,-;btmon: Num handles: 1
>> > 15,18520,832762000,-;btmon: Handle: 128
>> > 15,18521,832762000,-;btmon: Count: 1
>> > 15,18522,832782000,-;btmon: > ACL Data RX: Handle 128 flags 0x02 dlen
>> > 24 [hci0] 17:26:51.789303
>> > 15,18523,832782000,-;btmon: ATT: Read By Group Type Response
>> > (0x11) len 19
>> > 15,18524,832782000,-;btmon: Attribute data length: 6
>> > 15,18525,832782000,-;btmon: Attribute group list: 3 entries
>> > 15,18526,832784000,-;btmon: Handle range: 0x0001-0x000b
>> > 15,18527,832784000,-;btmon: UUID: Generic Access Profile
>> > (0x1800)
>> > 15,18528,832784000,-;btmon: Handle range: 0x000c-0x000f
>> > 15,18529,832784000,-;btmon: UUID: Generic Attribute Profile
>> > (0x1801)
>> > 15,18530,832784000,-;btmon: Handle range: 0x0010-0x0022
>> > 15,18531,832784000,-;btmon: UUID: Device Information (0x180a)
>> > 15,18532,832784000,-;btmon: < ACL Data TX: Handle 128 flags 0x00 dlen
>> > 11 [hci0] 17:26:51.790028
>> > 15,18533,832784000,-;btmon: ATT: Read By Type Request (0x08) len 6
>> > 15,18534,832784000,-;btmon: Handle range: 0x0036-0x0037
>> > 15,18535,832784000,-;btmon: Attribute type: Characteristic
>> > (0x2803)
>> > 15,18536,832792000,-;btmon: > HCI Event: Number of Completed Packets
>> > (0x13) plen 5 [hci0] 17:26:51.799354
>> > 15,18537,832792000,-;btmon: Num handles: 1
>> > 15,18538,832792000,-;btmon: Handle: 128
>> > 15,18539,832792000,-;btmon: Count: 1
>> > 15,18540,832809000,-;btmon: > ACL Data RX: Handle 128 flags 0x02 dlen
>> > 9 [hci0] 17:26:51.808179
>> > 15,18541,832809000,-;btmon: ATT: Error Response (0x01) len 4
>> > 15,18542,832809000,-;btmon: Read By Type Request (0x08)
>> > 15,18543,832809000,-;btmon: Handle: 0x0036
>> > 15,18544,832809000,-;btmon: Error: Attribute Not Found (0x0a)
>> > 15,18546,832811000,-;btmon: < ACL Data TX: Handle 128 flags 0x00 dlen
>> > 11 [hci0] 17:26:51.810774
>> > 15,18547,832812000,-;btmon: ATT: Read By Group Type Request (0x10)
>> > len 6
>> > 15,18548,832812000,-;btmon: Handle range: 0x0023-0xffff
>> > 15,18549,832812000,-;btmon: Attribute group type: Primary
>> > Service (0x2800)
>> > 15,18553,833321000,-;btmon: > HCI Event: Number of Completed Packets
>> > (0x13) plen 5 [hci0] 17:26:52.328191
>> > 15,18554,833321000,-;btmon: Num handles: 1
>> > 15,18555,833321000,-;btmon: Handle: 128
>> > 15,18556,833321000,-;btmon: Count: 1
>> > 15,18558,833334000,-;btmon: > HCI Event: Vendor (0xff) plen 5
>> > [hci0] 17:26:52.339515
>> > 15,18559,833334000,-;btmon: 05 80 00 09 00
>> > .....
>> > 15,18560,833362000,-;btmon: > ACL Data RX: Handle 128 flags 0x02 dlen
>> > 24 [hci0] 17:26:52.369478
>> > 15,18561,833363000,-;btmon: ATT: Read By Group Type Response
>> > (0x11) len 19
>> > 15,18562,833363000,-;btmon: Attribute data length: 6
>> > 15,18563,833363000,-;btmon: Attribute group list: 3 entries
>> > 15,18564,833364000,-;btmon: Handle range: 0x0023-0x0028
>> > 15,18565,833364000,-;btmon: UUID: Battery Service (0x180f)
>> > 15,18566,833364000,-;btmon: Handle range: 0x0029-0x002e
>> > 15,18567,833364000,-;btmon: UUID: Scan Parameters (0x1813)
>> > 15,18568,833364000,-;btmon: Handle range: 0x002f-0x0037
>> > 15,18569,833364000,-;btmon: UUID: Unknown (0xfff0)
>> > 15,18570,833364000,-;btmon: < ACL Data TX: Handle 128 flags 0x00 dlen
>> > 9 [hci0] 17:26:52.370138
>>
>> I have to check but these command bellow seems to be unrelated to the
>> discover.
>>
>> > 15,18571,833364000,-;btmon: ATT: Find Information Request (0x04)
>> > len 4
>> > 15,18572,833364000,-;btmon: Handle range: 0x0036-0x0037
>> > 15,18574,833371000,-;btmon: > HCI Event: Number of Completed Packets
>> > (0x13) plen 5 [hci0] 17:26:52.378203
>> > 15,18575,833371000,-;btmon: Num handles: 1
>> > 15,18576,833371000,-;btmon: Handle: 128
>> > 15,18577,833371000,-;btmon: Count: 1
>> > 15,18578,833391000,-;btmon: > ACL Data RX: Handle 128 flags 0x02 dlen
>> > 14 [hci0] 17:26:52.398166
>> > 15,18579,833391000,-;btmon: ATT: Find Information Response (0x05)
>> > len 9
>> > 15,18580,833392000,-;btmon: Format: UUID-16 (0x01)
>> > 15,18582,833394000,-;btmon: Handle: 0x0036
>> > 15,18583,833394000,-;btmon: UUID: Unknown (0xfff4)
>> > 15,18584,833394000,-;btmon: Handle: 0x0037
>> > 15,18585,833394000,-;btmon: UUID: Client Characteristic
>> > Configuration (0x2902)
>> > 15,18586,833394000,-;btmon: < ACL Data TX: Handle 128 flags 0x00 dlen
>> > 10 [hci0] 17:26:52.400735
>> > 15,18587,833394000,-;btmon: ATT: Write Request (0x12) len 5
>> > 15,18588,833394000,-;btmon: Handle: 0x0034
>> > 15,18589,833394000,-;btmon: Data: 030000
>> > 15,18591,833912000,-;btmon: > HCI Event: Number of Completed Packets
>> > (0x13) plen 5 [hci0] 17:26:52.919397
>> > 15,18592,833912000,-;btmon: Num handles: 1
>> > 15,18593,833912000,-;btmon: Handle: 128
>> > 15,18594,833912000,-;btmon: Count: 1
>> > 15,18595,833931000,-;btmon: > ACL Data RX: Handle 128 flags 0x02 dlen
>> > 5 [hci0] 17:26:52.938157
>> > 15,18596,833931000,-;btmon: ATT: Write Response (0x13) len 0
>> > 15,18597,833932000,-;btmon: < ACL Data TX: Handle 128 flags 0x00 dlen
>> > 11 [hci0] 17:26:52.939032
>>
>>
>> Were we just continue with the primary discovery.
>>
>> > 15,18598,833932000,-;btmon: ATT: Read By Group Type Request (0x10)
>> > len 6
>> > 15,18599,833932000,-;btmon: Handle range: 0x0038-0xffff
>> > 15,18600,833932000,-;btmon: Attribute group type: Primary
>> > Service (0x2800)
>> > 15,18601,833944000,-;btmon: > HCI Event: Number of Completed Packets
>> > (0x13) plen 5 [hci0] 17:26:52.951628
>> > 15,18602,833944000,-;btmon: Num handles: 1
>> > 15,18603,833944000,-;btmon: Handle: 128
>> > 15,18604,833944000,-;btmon: Count: 1
>> > 15,18605,833959000,-;btmon: > ACL Data RX: Handle 128 flags 0x02 dlen
>> > 12 [hci0] 17:26:52.966479
>> > 15,18606,833959000,-;btmon: ATT: Read By Group Type Response
>> > (0x11) len 7
>> > 15,18607,833960000,-;btmon: Attribute data length: 6
>> > 15,18608,833960000,-;btmon: Attribute group list: 1 entry
>> > 15,18609,833960000,-;btmon: Handle range: 0x0038-0x005c
>> > 15,18610,833960000,-;btmon: UUID: Human Interface Device
>> > (0x1812)
>> > 15,18611,833960000,-;btmon: < ACL Data TX: Handle 128 flags 0x00 dlen
>> > 9 [hci0] 17:26:52.967113
>> > 15,18612,833960000,-;btmon: ATT: Write Request (0x12) len 4
>> > 15,18613,833960000,-;btmon: Handle: 0x0037
>> > 15,18614,833960000,-;btmon: Data: 0100
>> > 15,18615,833971000,-;btmon: > HCI Event: Number of Completed Packets
>> > (0x13) plen 5 [hci0] 17:26:52.976999
>> > 15,18616,833971000,-;btmon: Num handles: 1
>> > 15,18617,833972000,-;btmon: Handle: 128
>> > 15,18618,833972000,-;btmon: Count: 1
>> > 15,18619,833979000,-;btmon: > ACL Data RX: Handle 128 flags 0x02 dlen
>> > 5 [hci0] 17:26:52.986355
>> > 15,18620,833980000,-;btmon: ATT: Write Response (0x13) len 0
>> > 15,18621,833980000,-;btmon: < ACL Data TX: Handle 128 flags 0x00 dlen
>> > 11 [hci0] 17:26:52.986894
>> > 15,18622,833980000,-;btmon: ATT: Read By Group Type Request (0x10)
>> > len 6
>> > 15,18623,833980000,-;btmon: Handle range: 0x005d-0xffff
>> > 15,18624,833980000,-;btmon: Attribute group type: Primary
>> > Service (0x2800)
>> > 15,18625,833990000,-;btmon: > HCI Event: Number of Completed Packets
>> > (0x13) plen 5 [hci0] 17:26:52.996610
>> > 15,18626,833990000,-;btmon: Num handles: 1
>> > 15,18627,833991000,-;btmon: Handle: 128
>> > 15,18628,833991000,-;btmon: Count: 1
>> > 15,18629,834013000,-;btmon: > ACL Data RX: Handle 128 flags 0x02 dlen
>> > 26 [hci0] 17:26:53.019401
>> > 15,18630,834013000,-;btmon: ATT: Read By Group Type Response
>> > (0x11) len 21
>> > 15,18631,834013000,-;btmon: Attribute data length: 20
>> > 15,18632,834013000,-;btmon: Attribute group list: 1 entry
>> > 15,18633,834013000,-;btmon: Handle range: 0x005d-0x0070
>> > 15,18634,834013000,-;btmon: UUID: Vendor specific
>> > (f000fef0-0451-4000-b000-000000000000)
>> > 15,18635,834013000,-;btmon: < ACL Data TX: Handle 128 flags 0x00 dlen
>> > 11 [hci0] 17:26:53.020026
>> > 15,18636,834013000,-;btmon: ATT: Read By Group Type Request (0x10)
>> > len 6
>> > 15,18637,834013000,-;btmon: Handle range: 0x0071-0xffff
>> > 15,18638,834013000,-;btmon: Attribute group type: Primary
>> > Service (0x2800)
>> > 15,18639,834022000,-;btmon: > HCI Event: Number of Completed Packets
>> > (0x13) plen 5 [hci0] 17:26:53.029922
>> > 15,18640,834022000,-;btmon: Num handles: 1
>> > 15,18641,834022000,-;btmon: Handle: 128
>> > 15,18642,834023000,-;btmon: Count: 1
>> > 15,18643,834042000,-;btmon: > ACL Data RX: Handle 128 flags 0x02 dlen
>> > 26 [hci0] 17:26:53.049348
>> > 15,18644,834042000,-;btmon: ATT: Read By Group Type Response
>> > (0x11) len 21
>> > 15,18645,834042000,-;btmon: Attribute data length: 20
>> > 15,18646,834042000,-;btmon: Attribute group list: 1 entry
>> > 15,18647,834042000,-;btmon: Handle range: 0x0071-0xffff
>> > 15,18648,834042000,-;btmon: UUID: Vendor specific
>>
>> So there is nothing new in the behavior, it does recheck the if the
>> services are in place but it doesn't check if anything about
>> characteristics and descriptors, also in the meantime you can issue
>> command as we see above, so it doesn't introduce extra delays so I
>> wonder why this is bothering you?
>
>
> I'm just interested in optimizing the HoG reconnect, so that only the
> absolutely necessary reads/writes are done over the air.
>
> So, since I know that the primary services on my HoG device won't change, is
> there a way to avoid this re-discovery of primary services on every
> reconnect?
>
This primary services re-discovery on every reconnect is actually now
causing a problem for us.
Basically, this is what happens:
1. HoG remote control reconnects to BlueZ host for firmware update check.
2. BlueZ starts re-discovering the services of the remote, but doesn't
yet complete it.
3. The remote disconnects after being connected for 2 seconds (no
firmware update was available, so quickly disconnect to save battery).
4. BlueZ declares the HoG remote "bad" since it couldn't complete step
(2). And then, BlueZ ends up removing the HoG remote services from its
GATT database completely.
5. On the next reconnect attempt, the remote does not work. Re-pairing
is required.
Obviously, this is bad for user experience. Therefore, I'm asking:
1. Is there a way to avoid services re-discovery on every reconnect?
2. If the remote control is successfully bonded previously, and BlueZ
experiences a problem during reconnect (services re-discovery), can we
avoid destroying the bonding and GATT info on BlueZ side? A failed
reconnect should not be a reason to remove a bonded device.
>>
>>
>> --
>> Luiz Augusto von Dentz
>
>
--
To unsubscribe from this list: send the line "unsubscribe linux-bluetooth" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at http://vger.kernel.org/majordomo-info.html
