2016-03-09 16:42:17

by François Beaufort

[permalink] [raw]
Subject: Feature Request: Clean the cache upon device disconnection

As we've discovered recently
(https://github.com/thegecko/web-bluetooth-dfu/issues/12#issuecomment-194348474),
it looks like BlueZ trunk doesn't clean/update its cache upon device
disconnection.

Is this on purpose?
If not, can it be fixed?


2016-03-10 12:50:34

by François Beaufort

[permalink] [raw]
Subject: Re: Feature Request: Clean the cache upon device disconnection

Here are the dbus logs: http://pastebin.com/raw/aX9LyDbU
Fingers crossed!

On Thu, Mar 10, 2016 at 12:44 PM, Luiz Augusto von Dentz
<[email protected]> wrote:
> Hi François,
>
> On Thu, Mar 10, 2016 at 1:41 PM, François Beaufort
> <[email protected]> wrote:
>> Are there more logs I can provide to help diagnose this issue?
>
> D-Bus perhaps would help, but you will probably have to enable
> eavesdrop so you can actually see the responses:
>
> https://wiki.ubuntu.com/DebuggingDBus
>
>> On Thu, Mar 10, 2016 at 12:26 PM, Luiz Augusto von Dentz
>> <[email protected]> wrote:
>>> Hi François,
>>>
>>> On Thu, Mar 10, 2016 at 1:01 PM, François Beaufort
>>> <[email protected]> wrote:
>>>> On Thu, Mar 10, 2016 at 11:54 AM, Luiz Augusto von Dentz
>>>> <[email protected]> wrote:
>>>>> Hi François,
>>>>>
>>>>> On Thu, Mar 10, 2016 at 12:15 PM, François Beaufort
>>>>> <[email protected]> wrote:
>>>>>> Here are failing bluetoothd and hcidump logs with BlueZ at commit
>>>>>> c8a81f43921cf417e270f3b6e0b0118cbc27a58d
>>>>>
>>>>> git log c8a81f43921cf417e270f3b6e0b0118cbc27a58d
>>>>> fatal: bad object c8a81f43921cf417e270f3b6e0b0118cbc27a58d
>>>>>
>>>>> Seems like it is not a valid object, is this based on upstream?
>>>>
>>>> It is: http://git.kernel.org/cgit/bluetooth/bluez.git/commit/?id=c8a81f43921cf417e270f3b6e0b0118cbc27a58d
>>>
>>> Sorry forgot to update since yesterday.
>>>
>>>>>
>>>>>> http://pastebin.com/raw/i416k6aw
>>>>>
>>>>> I can see the old services being removed and the new one being added:
>>>>>
>>>>> old services:
>>>>> bluetoothd[8323]: src/gatt-client.c:unregister_service() Removing GATT
>>>>> service: /org/bluez/hci0/dev_F1_6F_DE_EC_F1_D6/service0012
>>>>> bluetoothd[8323]: src/gatt-client.c:unregister_service() Removing GATT
>>>>> service: /org/bluez/hci0/dev_F1_6F_DE_EC_F1_D6/service0016
>>>>> bluetoothd[8323]: src/gatt-client.c:unregister_service() Removing GATT
>>>>> service: /org/bluez/hci0/dev_F1_6F_DE_EC_F1_D6/service0019
>>>>>
>>>>> new service:
>>>>>
>>>>> bluetoothd[8323]: src/gatt-client.c:service_create() Exported GATT
>>>>> service: /org/bluez/hci0/dev_F1_6F_DE_EC_F1_D6/service000c
>>>>> bluetoothd[8323]: src/gatt-client.c:characteristic_create() Exported
>>>>> GATT characteristic:
>>>>> /org/bluez/hci0/dev_F1_6F_DE_EC_F1_D6/service000c/char000d
>>>>> bluetoothd[8323]: src/gatt-client.c:characteristic_create() Exported
>>>>> GATT characteristic:
>>>>> /org/bluez/hci0/dev_F1_6F_DE_EC_F1_D6/service000c/char000f
>>>>> bluetoothd[8323]: src/gatt-client.c:descriptor_create() Exported GATT
>>>>> characteristic descriptor:
>>>>> /org/bluez/hci0/dev_F1_6F_DE_EC_F1_D6/service000c/char000f/desc0011
>>>>> bluetoothd[8323]: src/gatt-client.c:characteristic_create() Exported
>>>>> GATT characteristic:
>>>>> /org/bluez/hci0/dev_F1_6F_DE_EC_F1_D6/service000c/char0012
>>>>>
>>>>>
>>>>>> http://pastebin.com/raw/5dC9dFiP
>>>>>
>>>>> So it fails here:
>>>>>
>>>>> 2016-03-10 11:11:49.083776 < ACL data: handle 32 flags 0x00 dlen 9
>>>>> ATT: Write req (0x12)
>>>>> handle 0x000b value 0x02 0x00
>>>>> 2016-03-10 11:11:49.118038 > ACL data: handle 32 flags 0x02 dlen 5
>>>>> ATT: Write resp (0x13)
>>>>>
>>>>> It is trying to write to handle 0x000b which is not in the range of
>>>>> the new services, in fact is probably the service changed
>>>>> characteristic CCC:
>>>>>
>>>>> bluetoothd[8323]: src/device.c:gatt_debug() start: 0x0008, end:
>>>>> 0x000b, uuid: 00001801-0000-1000-8000-00805f9b34fb
>>>>>
>>>>> That is GATT service:
>>>>>
>>>>> #define GATT_UUID "00001801-0000-1000-8000-00805f9b34fb"
>>>>>
>>>>> So there is nothing in the logs related to the application, it is
>>>>> perhaps something in the above layers, perhaps it could not be
>>>>> detecting the service removal properly. I did a quick test here with
>>>>> zephyr as peripheral and changing services do actually appear in
>>>>> bluetoothctl.
>>>>
>>>> Do you have a nRF51 Dev Kit you could use to replicate locally this issue?
>>>
>>> No, but there is nothing we couldn't do with zephyr or BlueZ I
>>> suppose. But as I mentioned above it doesn't look like is something
>>> that even reached HCI so I suppose there is something else wrong,
>>> perhaps you are trying to access objects that don't exist anymore.
>>>
>>> --
>>> Luiz Augusto von Dentz
>
>
>
> --
> Luiz Augusto von Dentz

2016-03-10 11:44:35

by Luiz Augusto von Dentz

[permalink] [raw]
Subject: Re: Feature Request: Clean the cache upon device disconnection

Hi François,

On Thu, Mar 10, 2016 at 1:41 PM, François Beaufort
<[email protected]> wrote:
> Are there more logs I can provide to help diagnose this issue?

D-Bus perhaps would help, but you will probably have to enable
eavesdrop so you can actually see the responses:

https://wiki.ubuntu.com/DebuggingDBus

> On Thu, Mar 10, 2016 at 12:26 PM, Luiz Augusto von Dentz
> <[email protected]> wrote:
>> Hi François,
>>
>> On Thu, Mar 10, 2016 at 1:01 PM, François Beaufort
>> <[email protected]> wrote:
>>> On Thu, Mar 10, 2016 at 11:54 AM, Luiz Augusto von Dentz
>>> <[email protected]> wrote:
>>>> Hi François,
>>>>
>>>> On Thu, Mar 10, 2016 at 12:15 PM, François Beaufort
>>>> <[email protected]> wrote:
>>>>> Here are failing bluetoothd and hcidump logs with BlueZ at commit
>>>>> c8a81f43921cf417e270f3b6e0b0118cbc27a58d
>>>>
>>>> git log c8a81f43921cf417e270f3b6e0b0118cbc27a58d
>>>> fatal: bad object c8a81f43921cf417e270f3b6e0b0118cbc27a58d
>>>>
>>>> Seems like it is not a valid object, is this based on upstream?
>>>
>>> It is: http://git.kernel.org/cgit/bluetooth/bluez.git/commit/?id=c8a81f43921cf417e270f3b6e0b0118cbc27a58d
>>
>> Sorry forgot to update since yesterday.
>>
>>>>
>>>>> http://pastebin.com/raw/i416k6aw
>>>>
>>>> I can see the old services being removed and the new one being added:
>>>>
>>>> old services:
>>>> bluetoothd[8323]: src/gatt-client.c:unregister_service() Removing GATT
>>>> service: /org/bluez/hci0/dev_F1_6F_DE_EC_F1_D6/service0012
>>>> bluetoothd[8323]: src/gatt-client.c:unregister_service() Removing GATT
>>>> service: /org/bluez/hci0/dev_F1_6F_DE_EC_F1_D6/service0016
>>>> bluetoothd[8323]: src/gatt-client.c:unregister_service() Removing GATT
>>>> service: /org/bluez/hci0/dev_F1_6F_DE_EC_F1_D6/service0019
>>>>
>>>> new service:
>>>>
>>>> bluetoothd[8323]: src/gatt-client.c:service_create() Exported GATT
>>>> service: /org/bluez/hci0/dev_F1_6F_DE_EC_F1_D6/service000c
>>>> bluetoothd[8323]: src/gatt-client.c:characteristic_create() Exported
>>>> GATT characteristic:
>>>> /org/bluez/hci0/dev_F1_6F_DE_EC_F1_D6/service000c/char000d
>>>> bluetoothd[8323]: src/gatt-client.c:characteristic_create() Exported
>>>> GATT characteristic:
>>>> /org/bluez/hci0/dev_F1_6F_DE_EC_F1_D6/service000c/char000f
>>>> bluetoothd[8323]: src/gatt-client.c:descriptor_create() Exported GATT
>>>> characteristic descriptor:
>>>> /org/bluez/hci0/dev_F1_6F_DE_EC_F1_D6/service000c/char000f/desc0011
>>>> bluetoothd[8323]: src/gatt-client.c:characteristic_create() Exported
>>>> GATT characteristic:
>>>> /org/bluez/hci0/dev_F1_6F_DE_EC_F1_D6/service000c/char0012
>>>>
>>>>
>>>>> http://pastebin.com/raw/5dC9dFiP
>>>>
>>>> So it fails here:
>>>>
>>>> 2016-03-10 11:11:49.083776 < ACL data: handle 32 flags 0x00 dlen 9
>>>> ATT: Write req (0x12)
>>>> handle 0x000b value 0x02 0x00
>>>> 2016-03-10 11:11:49.118038 > ACL data: handle 32 flags 0x02 dlen 5
>>>> ATT: Write resp (0x13)
>>>>
>>>> It is trying to write to handle 0x000b which is not in the range of
>>>> the new services, in fact is probably the service changed
>>>> characteristic CCC:
>>>>
>>>> bluetoothd[8323]: src/device.c:gatt_debug() start: 0x0008, end:
>>>> 0x000b, uuid: 00001801-0000-1000-8000-00805f9b34fb
>>>>
>>>> That is GATT service:
>>>>
>>>> #define GATT_UUID "00001801-0000-1000-8000-00805f9b34fb"
>>>>
>>>> So there is nothing in the logs related to the application, it is
>>>> perhaps something in the above layers, perhaps it could not be
>>>> detecting the service removal properly. I did a quick test here with
>>>> zephyr as peripheral and changing services do actually appear in
>>>> bluetoothctl.
>>>
>>> Do you have a nRF51 Dev Kit you could use to replicate locally this issue?
>>
>> No, but there is nothing we couldn't do with zephyr or BlueZ I
>> suppose. But as I mentioned above it doesn't look like is something
>> that even reached HCI so I suppose there is something else wrong,
>> perhaps you are trying to access objects that don't exist anymore.
>>
>> --
>> Luiz Augusto von Dentz



--
Luiz Augusto von Dentz

2016-03-10 11:41:36

by François Beaufort

[permalink] [raw]
Subject: Re: Feature Request: Clean the cache upon device disconnection

Are there more logs I can provide to help diagnose this issue?

On Thu, Mar 10, 2016 at 12:26 PM, Luiz Augusto von Dentz
<[email protected]> wrote:
> Hi François,
>
> On Thu, Mar 10, 2016 at 1:01 PM, François Beaufort
> <[email protected]> wrote:
>> On Thu, Mar 10, 2016 at 11:54 AM, Luiz Augusto von Dentz
>> <[email protected]> wrote:
>>> Hi François,
>>>
>>> On Thu, Mar 10, 2016 at 12:15 PM, François Beaufort
>>> <[email protected]> wrote:
>>>> Here are failing bluetoothd and hcidump logs with BlueZ at commit
>>>> c8a81f43921cf417e270f3b6e0b0118cbc27a58d
>>>
>>> git log c8a81f43921cf417e270f3b6e0b0118cbc27a58d
>>> fatal: bad object c8a81f43921cf417e270f3b6e0b0118cbc27a58d
>>>
>>> Seems like it is not a valid object, is this based on upstream?
>>
>> It is: http://git.kernel.org/cgit/bluetooth/bluez.git/commit/?id=c8a81f43921cf417e270f3b6e0b0118cbc27a58d
>
> Sorry forgot to update since yesterday.
>
>>>
>>>> http://pastebin.com/raw/i416k6aw
>>>
>>> I can see the old services being removed and the new one being added:
>>>
>>> old services:
>>> bluetoothd[8323]: src/gatt-client.c:unregister_service() Removing GATT
>>> service: /org/bluez/hci0/dev_F1_6F_DE_EC_F1_D6/service0012
>>> bluetoothd[8323]: src/gatt-client.c:unregister_service() Removing GATT
>>> service: /org/bluez/hci0/dev_F1_6F_DE_EC_F1_D6/service0016
>>> bluetoothd[8323]: src/gatt-client.c:unregister_service() Removing GATT
>>> service: /org/bluez/hci0/dev_F1_6F_DE_EC_F1_D6/service0019
>>>
>>> new service:
>>>
>>> bluetoothd[8323]: src/gatt-client.c:service_create() Exported GATT
>>> service: /org/bluez/hci0/dev_F1_6F_DE_EC_F1_D6/service000c
>>> bluetoothd[8323]: src/gatt-client.c:characteristic_create() Exported
>>> GATT characteristic:
>>> /org/bluez/hci0/dev_F1_6F_DE_EC_F1_D6/service000c/char000d
>>> bluetoothd[8323]: src/gatt-client.c:characteristic_create() Exported
>>> GATT characteristic:
>>> /org/bluez/hci0/dev_F1_6F_DE_EC_F1_D6/service000c/char000f
>>> bluetoothd[8323]: src/gatt-client.c:descriptor_create() Exported GATT
>>> characteristic descriptor:
>>> /org/bluez/hci0/dev_F1_6F_DE_EC_F1_D6/service000c/char000f/desc0011
>>> bluetoothd[8323]: src/gatt-client.c:characteristic_create() Exported
>>> GATT characteristic:
>>> /org/bluez/hci0/dev_F1_6F_DE_EC_F1_D6/service000c/char0012
>>>
>>>
>>>> http://pastebin.com/raw/5dC9dFiP
>>>
>>> So it fails here:
>>>
>>> 2016-03-10 11:11:49.083776 < ACL data: handle 32 flags 0x00 dlen 9
>>> ATT: Write req (0x12)
>>> handle 0x000b value 0x02 0x00
>>> 2016-03-10 11:11:49.118038 > ACL data: handle 32 flags 0x02 dlen 5
>>> ATT: Write resp (0x13)
>>>
>>> It is trying to write to handle 0x000b which is not in the range of
>>> the new services, in fact is probably the service changed
>>> characteristic CCC:
>>>
>>> bluetoothd[8323]: src/device.c:gatt_debug() start: 0x0008, end:
>>> 0x000b, uuid: 00001801-0000-1000-8000-00805f9b34fb
>>>
>>> That is GATT service:
>>>
>>> #define GATT_UUID "00001801-0000-1000-8000-00805f9b34fb"
>>>
>>> So there is nothing in the logs related to the application, it is
>>> perhaps something in the above layers, perhaps it could not be
>>> detecting the service removal properly. I did a quick test here with
>>> zephyr as peripheral and changing services do actually appear in
>>> bluetoothctl.
>>
>> Do you have a nRF51 Dev Kit you could use to replicate locally this issue?
>
> No, but there is nothing we couldn't do with zephyr or BlueZ I
> suppose. But as I mentioned above it doesn't look like is something
> that even reached HCI so I suppose there is something else wrong,
> perhaps you are trying to access objects that don't exist anymore.
>
> --
> Luiz Augusto von Dentz

2016-03-10 11:26:03

by Luiz Augusto von Dentz

[permalink] [raw]
Subject: Re: Feature Request: Clean the cache upon device disconnection

Hi François,

On Thu, Mar 10, 2016 at 1:01 PM, François Beaufort
<[email protected]> wrote:
> On Thu, Mar 10, 2016 at 11:54 AM, Luiz Augusto von Dentz
> <[email protected]> wrote:
>> Hi François,
>>
>> On Thu, Mar 10, 2016 at 12:15 PM, François Beaufort
>> <[email protected]> wrote:
>>> Here are failing bluetoothd and hcidump logs with BlueZ at commit
>>> c8a81f43921cf417e270f3b6e0b0118cbc27a58d
>>
>> git log c8a81f43921cf417e270f3b6e0b0118cbc27a58d
>> fatal: bad object c8a81f43921cf417e270f3b6e0b0118cbc27a58d
>>
>> Seems like it is not a valid object, is this based on upstream?
>
> It is: http://git.kernel.org/cgit/bluetooth/bluez.git/commit/?id=c8a81f43921cf417e270f3b6e0b0118cbc27a58d

Sorry forgot to update since yesterday.

>>
>>> http://pastebin.com/raw/i416k6aw
>>
>> I can see the old services being removed and the new one being added:
>>
>> old services:
>> bluetoothd[8323]: src/gatt-client.c:unregister_service() Removing GATT
>> service: /org/bluez/hci0/dev_F1_6F_DE_EC_F1_D6/service0012
>> bluetoothd[8323]: src/gatt-client.c:unregister_service() Removing GATT
>> service: /org/bluez/hci0/dev_F1_6F_DE_EC_F1_D6/service0016
>> bluetoothd[8323]: src/gatt-client.c:unregister_service() Removing GATT
>> service: /org/bluez/hci0/dev_F1_6F_DE_EC_F1_D6/service0019
>>
>> new service:
>>
>> bluetoothd[8323]: src/gatt-client.c:service_create() Exported GATT
>> service: /org/bluez/hci0/dev_F1_6F_DE_EC_F1_D6/service000c
>> bluetoothd[8323]: src/gatt-client.c:characteristic_create() Exported
>> GATT characteristic:
>> /org/bluez/hci0/dev_F1_6F_DE_EC_F1_D6/service000c/char000d
>> bluetoothd[8323]: src/gatt-client.c:characteristic_create() Exported
>> GATT characteristic:
>> /org/bluez/hci0/dev_F1_6F_DE_EC_F1_D6/service000c/char000f
>> bluetoothd[8323]: src/gatt-client.c:descriptor_create() Exported GATT
>> characteristic descriptor:
>> /org/bluez/hci0/dev_F1_6F_DE_EC_F1_D6/service000c/char000f/desc0011
>> bluetoothd[8323]: src/gatt-client.c:characteristic_create() Exported
>> GATT characteristic:
>> /org/bluez/hci0/dev_F1_6F_DE_EC_F1_D6/service000c/char0012
>>
>>
>>> http://pastebin.com/raw/5dC9dFiP
>>
>> So it fails here:
>>
>> 2016-03-10 11:11:49.083776 < ACL data: handle 32 flags 0x00 dlen 9
>> ATT: Write req (0x12)
>> handle 0x000b value 0x02 0x00
>> 2016-03-10 11:11:49.118038 > ACL data: handle 32 flags 0x02 dlen 5
>> ATT: Write resp (0x13)
>>
>> It is trying to write to handle 0x000b which is not in the range of
>> the new services, in fact is probably the service changed
>> characteristic CCC:
>>
>> bluetoothd[8323]: src/device.c:gatt_debug() start: 0x0008, end:
>> 0x000b, uuid: 00001801-0000-1000-8000-00805f9b34fb
>>
>> That is GATT service:
>>
>> #define GATT_UUID "00001801-0000-1000-8000-00805f9b34fb"
>>
>> So there is nothing in the logs related to the application, it is
>> perhaps something in the above layers, perhaps it could not be
>> detecting the service removal properly. I did a quick test here with
>> zephyr as peripheral and changing services do actually appear in
>> bluetoothctl.
>
> Do you have a nRF51 Dev Kit you could use to replicate locally this issue?

No, but there is nothing we couldn't do with zephyr or BlueZ I
suppose. But as I mentioned above it doesn't look like is something
that even reached HCI so I suppose there is something else wrong,
perhaps you are trying to access objects that don't exist anymore.

--
Luiz Augusto von Dentz

2016-03-10 11:01:05

by François Beaufort

[permalink] [raw]
Subject: Re: Feature Request: Clean the cache upon device disconnection

On Thu, Mar 10, 2016 at 11:54 AM, Luiz Augusto von Dentz
<[email protected]> wrote:
> Hi François,
>
> On Thu, Mar 10, 2016 at 12:15 PM, François Beaufort
> <[email protected]> wrote:
>> Here are failing bluetoothd and hcidump logs with BlueZ at commit
>> c8a81f43921cf417e270f3b6e0b0118cbc27a58d
>
> git log c8a81f43921cf417e270f3b6e0b0118cbc27a58d
> fatal: bad object c8a81f43921cf417e270f3b6e0b0118cbc27a58d
>
> Seems like it is not a valid object, is this based on upstream?

It is: http://git.kernel.org/cgit/bluetooth/bluez.git/commit/?id=c8a81f43921cf417e270f3b6e0b0118cbc27a58d

>
>> http://pastebin.com/raw/i416k6aw
>
> I can see the old services being removed and the new one being added:
>
> old services:
> bluetoothd[8323]: src/gatt-client.c:unregister_service() Removing GATT
> service: /org/bluez/hci0/dev_F1_6F_DE_EC_F1_D6/service0012
> bluetoothd[8323]: src/gatt-client.c:unregister_service() Removing GATT
> service: /org/bluez/hci0/dev_F1_6F_DE_EC_F1_D6/service0016
> bluetoothd[8323]: src/gatt-client.c:unregister_service() Removing GATT
> service: /org/bluez/hci0/dev_F1_6F_DE_EC_F1_D6/service0019
>
> new service:
>
> bluetoothd[8323]: src/gatt-client.c:service_create() Exported GATT
> service: /org/bluez/hci0/dev_F1_6F_DE_EC_F1_D6/service000c
> bluetoothd[8323]: src/gatt-client.c:characteristic_create() Exported
> GATT characteristic:
> /org/bluez/hci0/dev_F1_6F_DE_EC_F1_D6/service000c/char000d
> bluetoothd[8323]: src/gatt-client.c:characteristic_create() Exported
> GATT characteristic:
> /org/bluez/hci0/dev_F1_6F_DE_EC_F1_D6/service000c/char000f
> bluetoothd[8323]: src/gatt-client.c:descriptor_create() Exported GATT
> characteristic descriptor:
> /org/bluez/hci0/dev_F1_6F_DE_EC_F1_D6/service000c/char000f/desc0011
> bluetoothd[8323]: src/gatt-client.c:characteristic_create() Exported
> GATT characteristic:
> /org/bluez/hci0/dev_F1_6F_DE_EC_F1_D6/service000c/char0012
>
>
>> http://pastebin.com/raw/5dC9dFiP
>
> So it fails here:
>
> 2016-03-10 11:11:49.083776 < ACL data: handle 32 flags 0x00 dlen 9
> ATT: Write req (0x12)
> handle 0x000b value 0x02 0x00
> 2016-03-10 11:11:49.118038 > ACL data: handle 32 flags 0x02 dlen 5
> ATT: Write resp (0x13)
>
> It is trying to write to handle 0x000b which is not in the range of
> the new services, in fact is probably the service changed
> characteristic CCC:
>
> bluetoothd[8323]: src/device.c:gatt_debug() start: 0x0008, end:
> 0x000b, uuid: 00001801-0000-1000-8000-00805f9b34fb
>
> That is GATT service:
>
> #define GATT_UUID "00001801-0000-1000-8000-00805f9b34fb"
>
> So there is nothing in the logs related to the application, it is
> perhaps something in the above layers, perhaps it could not be
> detecting the service removal properly. I did a quick test here with
> zephyr as peripheral and changing services do actually appear in
> bluetoothctl.

Do you have a nRF51 Dev Kit you could use to replicate locally this issue?

2016-03-10 10:54:04

by Luiz Augusto von Dentz

[permalink] [raw]
Subject: Re: Feature Request: Clean the cache upon device disconnection

Hi François,

On Thu, Mar 10, 2016 at 12:15 PM, François Beaufort
<[email protected]> wrote:
> Here are failing bluetoothd and hcidump logs with BlueZ at commit
> c8a81f43921cf417e270f3b6e0b0118cbc27a58d

git log c8a81f43921cf417e270f3b6e0b0118cbc27a58d
fatal: bad object c8a81f43921cf417e270f3b6e0b0118cbc27a58d

Seems like it is not a valid object, is this based on upstream?

> http://pastebin.com/raw/i416k6aw

I can see the old services being removed and the new one being added:

old services:
bluetoothd[8323]: src/gatt-client.c:unregister_service() Removing GATT
service: /org/bluez/hci0/dev_F1_6F_DE_EC_F1_D6/service0012
bluetoothd[8323]: src/gatt-client.c:unregister_service() Removing GATT
service: /org/bluez/hci0/dev_F1_6F_DE_EC_F1_D6/service0016
bluetoothd[8323]: src/gatt-client.c:unregister_service() Removing GATT
service: /org/bluez/hci0/dev_F1_6F_DE_EC_F1_D6/service0019

new service:

bluetoothd[8323]: src/gatt-client.c:service_create() Exported GATT
service: /org/bluez/hci0/dev_F1_6F_DE_EC_F1_D6/service000c
bluetoothd[8323]: src/gatt-client.c:characteristic_create() Exported
GATT characteristic:
/org/bluez/hci0/dev_F1_6F_DE_EC_F1_D6/service000c/char000d
bluetoothd[8323]: src/gatt-client.c:characteristic_create() Exported
GATT characteristic:
/org/bluez/hci0/dev_F1_6F_DE_EC_F1_D6/service000c/char000f
bluetoothd[8323]: src/gatt-client.c:descriptor_create() Exported GATT
characteristic descriptor:
/org/bluez/hci0/dev_F1_6F_DE_EC_F1_D6/service000c/char000f/desc0011
bluetoothd[8323]: src/gatt-client.c:characteristic_create() Exported
GATT characteristic:
/org/bluez/hci0/dev_F1_6F_DE_EC_F1_D6/service000c/char0012


> http://pastebin.com/raw/5dC9dFiP

So it fails here:

2016-03-10 11:11:49.083776 < ACL data: handle 32 flags 0x00 dlen 9
ATT: Write req (0x12)
handle 0x000b value 0x02 0x00
2016-03-10 11:11:49.118038 > ACL data: handle 32 flags 0x02 dlen 5
ATT: Write resp (0x13)

It is trying to write to handle 0x000b which is not in the range of
the new services, in fact is probably the service changed
characteristic CCC:

bluetoothd[8323]: src/device.c:gatt_debug() start: 0x0008, end:
0x000b, uuid: 00001801-0000-1000-8000-00805f9b34fb

That is GATT service:

#define GATT_UUID "00001801-0000-1000-8000-00805f9b34fb"

So there is nothing in the logs related to the application, it is
perhaps something in the above layers, perhaps it could not be
detecting the service removal properly. I did a quick test here with
zephyr as peripheral and changing services do actually appear in
bluetoothctl.

2016-03-10 10:15:18

by François Beaufort

[permalink] [raw]
Subject: Re: Feature Request: Clean the cache upon device disconnection

Here are failing bluetoothd and hcidump logs with BlueZ at commit
c8a81f43921cf417e270f3b6e0b0118cbc27a58d

http://pastebin.com/raw/i416k6aw
http://pastebin.com/raw/5dC9dFiP

On Thu, Mar 10, 2016 at 10:11 AM, Luiz Augusto von Dentz
<[email protected]> wrote:
> Hi François,
>
> On Wed, Mar 9, 2016 at 10:47 PM, Luiz Augusto von Dentz
> <[email protected]> wrote:
>> Hi François,
>>
>> On Wed, Mar 9, 2016 at 6:42 PM, François Beaufort
>> <[email protected]> wrote:
>>> As we've discovered recently
>>> (https://github.com/thegecko/web-bluetooth-dfu/issues/12#issuecomment-194348474),
>>> it looks like BlueZ trunk doesn't clean/update its cache upon device
>>> disconnection.
>>>
>>> Is this on purpose?
>>> If not, can it be fixed?
>>
>> I actually need more info, we do check if the cache is valid on every
>> reconnection, can someone provide the HCI trace of the issue perhaps
>> it is not using the fixes for the cache that have been merged
>> upstream.
>
> There at least 2 important fixes to the cache that where applied upstream:
>
> Author: Luiz Augusto von Dentz <[email protected]>
> Date: Mon Feb 15 14:14:31 2016 +0200
>
> core/device: Fix not clearing Attributes before storing
>
> This can leave the storage in a bad state if device start changing its
> attributes the old one are never removed as the code reloads them with
> g_key_file_load_from_file.
>
> commit e3c14b2627ed8fd6277a72761539cb54111fc205
> Author: Luiz Augusto von Dentz <[email protected]>
> Date: Mon Feb 15 13:44:27 2016 +0200
>
> core/device: Fix not reseting database if attributes cannot be loaded
>
> If one or more attributes cannot be loaded it means the database is
> probably in a bad state so just clear it so the attributes can be
> discovered again.
>
> If you don't have them it is probably not going to work since the
> device appears to be changing its database while win DFU mode.
>
>
> --
> Luiz Augusto von Dentz

2016-03-10 09:11:04

by Luiz Augusto von Dentz

[permalink] [raw]
Subject: Re: Feature Request: Clean the cache upon device disconnection

Hi François,

On Wed, Mar 9, 2016 at 10:47 PM, Luiz Augusto von Dentz
<[email protected]> wrote:
> Hi François,
>
> On Wed, Mar 9, 2016 at 6:42 PM, François Beaufort
> <[email protected]> wrote:
>> As we've discovered recently
>> (https://github.com/thegecko/web-bluetooth-dfu/issues/12#issuecomment-194348474),
>> it looks like BlueZ trunk doesn't clean/update its cache upon device
>> disconnection.
>>
>> Is this on purpose?
>> If not, can it be fixed?
>
> I actually need more info, we do check if the cache is valid on every
> reconnection, can someone provide the HCI trace of the issue perhaps
> it is not using the fixes for the cache that have been merged
> upstream.

There at least 2 important fixes to the cache that where applied upstream:

Author: Luiz Augusto von Dentz <[email protected]>
Date: Mon Feb 15 14:14:31 2016 +0200

core/device: Fix not clearing Attributes before storing

This can leave the storage in a bad state if device start changing its
attributes the old one are never removed as the code reloads them with
g_key_file_load_from_file.

commit e3c14b2627ed8fd6277a72761539cb54111fc205
Author: Luiz Augusto von Dentz <[email protected]>
Date: Mon Feb 15 13:44:27 2016 +0200

core/device: Fix not reseting database if attributes cannot be loaded

If one or more attributes cannot be loaded it means the database is
probably in a bad state so just clear it so the attributes can be
discovered again.

If you don't have them it is probably not going to work since the
device appears to be changing its database while win DFU mode.


--
Luiz Augusto von Dentz

2016-03-09 20:47:52

by Luiz Augusto von Dentz

[permalink] [raw]
Subject: Re: Feature Request: Clean the cache upon device disconnection

Hi François,

On Wed, Mar 9, 2016 at 6:42 PM, François Beaufort
<[email protected]> wrote:
> As we've discovered recently
> (https://github.com/thegecko/web-bluetooth-dfu/issues/12#issuecomment-194348474),
> it looks like BlueZ trunk doesn't clean/update its cache upon device
> disconnection.
>
> Is this on purpose?
> If not, can it be fixed?

I actually need more info, we do check if the cache is valid on every
reconnection, can someone provide the HCI trace of the issue perhaps
it is not using the fixes for the cache that have been merged
upstream.


--
Luiz Augusto von Dentz