Re: notification has not yet been cleaned in server side when ble is disconnected.

[Yunhan Wang <yunhanw@google.com>]

Hi, Luiz

On Mon, Oct 16, 2017 at 7:31 AM, Luiz Augusto von Dentz
<luiz.dentz@gmail.com> wrote:
> Hi Yunhan,
>
> On Fri, Oct 13, 2017 at 2:13 AM, Yunhan Wang <yunhanw@nestlabs.com> wrote=
:
>> Hi, Luiz
>>
>> On Tue, Oct 10, 2017 at 3:07 AM, Luiz Augusto von Dentz
>> <luiz.dentz@gmail.com> wrote:
>>> Hi Yunhan,
>>>
>>> On Tue, Oct 10, 2017 at 11:48 AM, Yunhan Wang <yunhanw@nestlabs.com> wr=
ote:
>>>> Hi=EF=BC=8C Luiz
>>>>
>>>> Here there is no pair operation in our end. Our rough idea is the belo=
w.
>>>> 1. ble scan
>>>> 2. ble connect from central to peripheral.
>>>> 3. central app writes data in characteristic A offered by peripheral
>>>> 4. central app subscribes characteristic B offered by peripheral app,
>>>> which is used to receive indication data from peripheral.
>>>>
>>>> I am using 2 btvirt, one is 00:AA:01:00:00:23(peripheral), another is
>>>> 00:AA:01:01:00:24 (central)
>>>>
>>>> For previous reproduced step:
>>>> 1. Assume server has one characteristic A that is subscribed by client
>>>> and sending indication,
>>>> 2. Then ble connection is disconnected by client directly or
>>>> connection disappear without unsubscribing A.
>>>> 3. Client tries to connect to ble successfully
>>>> 4. Client fails to subscribe that characteristic A although ble
>>>> connection is ok.
>>>> 5. Another retry to make Ble connection and subscribe to A can work.
>>>>
>>>> The below logs in bluetoothd are from step 2: ble disconnect seems not
>>>> clean anything related to gatt notification.
>>>>
>>>> src/gatt-database.c:send_notification_to_device() GATT server sending =
indication
>>>> src/gatt-database.c:conf_cb() GATT server received confirmation
>>>> src/device.c:gatt_debug() Write Req - handle: 0x003f
>>>> src/gatt-database.c:send_notification_to_device() GATT server sending =
indication
>>>> src/gatt-database.c:conf_cb() GATT server received confirmation
>>>> src/service.c:change_state() 0x925b20: device 00:AA:01:00:00:23
>>>> profile gap-profile state changed: connected -> disconnecting (0)
>>>> src/service.c:change_state() 0x925b20: device 00:AA:01:00:00:23
>>>> profile gap-profile state changed: disconnecting -> disconnected (0)
>>>> src/adapter.c:dev_disconnected() Device 00:AA:01:00:00:23 disconnected=
, reason 2
>>>> src/adapter.c:adapter_remove_connection()
>>>> plugins/policy.c:disconnect_cb() reason 2
>>>> src/adapter.c:bonding_attempt_complete() hci1 bdaddr 00:AA:01:00:00:23
>>>> type 1 status 0xe
>>>> src/device.c:device_bonding_complete() bonding (nil) status 0x0e
>>>> src/device.c:device_bonding_failed() status 14
>>>> src/adapter.c:resume_discovery()
>>>> src/device.c:att_disconnected_cb()
>>>> src/device.c:att_disconnected_cb() Connection reset by peer (104)
>>>> src/service.c:change_state() 0x9103e0: device 00:AA:01:01:00:24
>>>> profile gap-profile state changed: connected -> disconnecting (0)
>>>> src/service.c:change_state() 0x9103e0: device 00:AA:01:01:00:24
>>>> profile gap-profile state changed: disconnecting -> disconnected (0)
>>>> src/gatt-client.c:btd_gatt_client_disconnected() Device disconnected.
>>>> Cleaning up.
>>>> src/device.c:att_disconnected_cb() Automatic connection disabled
>>>> attrib/gattrib.c:g_attrib_unref() 0x91d190: g_attrib_unref=3D0
>>>> src/adapter.c:dev_disconnected() Device 00:AA:01:01:00:24 disconnected=
, reason 3
>>>> src/adapter.c:adapter_remove_connection()
>>>> plugins/policy.c:disconnect_cb() reason 3
>>>> src/adapter.c:bonding_attempt_complete() hci0 bdaddr 00:AA:01:01:00:24
>>>> type 1 status 0xe
>>>> src/device.c:device_bonding_complete() bonding (nil) status 0x0e
>>>> src/device.c:device_bonding_failed() status 14
>>>> src/device.c:att_disconnected_cb()
>>>> src/device.c:att_disconnected_cb() Connection reset by peer (104)
>>>> src/gatt-client.c:btd_gatt_client_disconnected() Device disconnected.
>>>> Cleaning up.
>>>> src/device.c:att_disconnected_cb() Automatic connection disabled
>>>> attrib/gattrib.c:g_attrib_unref() 0x925000: g_attrib_unref=3D0
>>>>
>>>> The below logs in bluetoothd are from step 4: Client fails to
>>>> subscribe that characteristic A although ble connection is ok. from
>>>> the log, it seems it is cleaning gatt notification in
>>>> https://git.kernel.org/pub/scm/bluetooth/bluez.git/tree/src/gatt-datab=
ase.c#n2005
>>>
>>> Looks like we are no cleanup up the subscription no matter if paired
>>> or not which partially explain the problem here.
>>>
>>>> src/device.c:gatt_debug() start: 0x0001, end: 0x0005, uuid:
>>>> 00001800-0000-1000-8000-00805f9b34fb
>>>> src/device.c:gatt_debug() start: 0x0006, end: 0x0009, uuid:
>>>> 00001801-0000-1000-8000-00805f9b34fb
>>>> src/device.c:gatt_client_ready_cb() status: success, error: 10
>>>> src/gatt-client.c:create_services() Exporting objects for GATT
>>>> services: 00:AA:01:01:00:24
>>>> src/device.c:device_svc_resolved() /org/bluez/hci0/dev_00_AA_01_01_00_=
24 err 0
>>>> src/device.c:gatt_debug() Read Req - handle: 0x0003
>>>> src/gatt-database.c:gap_device_name_read_cb() GAP Device Name read req=
uest
>>>> profiles/gap/gas.c:read_device_name_cb() GAP Device Name: N0002
>>>> src/device.c:btd_device_device_set_name()
>>>> /org/bluez/hci1/dev_00_AA_01_00_00_23 N0002
>>>> src/device.c:gatt_debug() Write Req - handle: 0x0009
>>>> src/gatt-database.c:gatt_ccc_write_cb() CCC write called for handle: 0=
x0009
>>>> src/device.c:gatt_debug() Registered handler for "Service Changed": 1
>>>> src/device.c:gatt_debug() Read Req - handle: 0x0005
>>>> src/gatt-database.c:gap_appearance_read_cb() GAP Appearance read reque=
st
>>>> profiles/gap/gas.c:read_appearance_cb() GAP Appearance: 0x0000
>>>>
>>>> src/device.c:gatt_debug() Write Req - handle: 0x0039
>>>> src/gatt-client.c:notify_client_ref() owner :1.122201
>>>> src/device.c:gatt_debug() Write Req - handle: 0x0037
>>>> src/gatt-database.c:gatt_ccc_write_cb() CCC write called for handle: 0=
x0037
>>>> src/gatt-client.c:notify_client_unref() owner :1.122201
>>>> src/gatt-client.c:notify_client_free() owner :1.122201
>>>> src/device.c:gatt_debug() Write Req - handle: 0x0037
>>>> src/gatt-database.c:gatt_ccc_write_cb() CCC write called for handle: 0=
x0037
>>>> src/gatt-database.c:ccc_write_cb() External CCC write received with
>>>> value: 0x0000
>>>
>>> Well this is an unsubscribe value:0x0000 so by itself this is no
>>> wrong, please check with btmon if the remote is not unsubscribing
>>> before subscribing again.
>>
>> Yes,
>> the observation is that
>> in first iteration, the remote disconnect without unsubscribing,
>> in second iteration, the remote would unsubscribe this characteristic,
>> and would not subscribe it again.
>> in third iteration, the remote would subscribe the characteristic succes=
sfully.
>>
>> My expectation is that either
>> a. when disconnect, bluetoothd can automatically unsubscribing.
>
> bluetoothd should remove any subscription when a non-bonded device
> disconnects, that means either call StopNotify or close the pipe with
> the application.
>

With the server application, I have closed pipe, but the subscription
status cannot be cleared.

thanks
best wishes
yunhan

>> or
>> b. when disconnect, peripheral app can trigger one dbus api to stop
>> notification.
>>
>> Any further idea?
>>
>> thanks
>> best wishes
>> yunhan
>>>
>>>> src/gatt-database.c:pipe_hup() 0x921290 closed
>>>> src/gatt-database.c:proxy_removed_cb() Proxy removed - removing
>>>> service: /org/bluez/xxxx/xxx
>>>> src/gatt-database.c:gatt_db_service_removed() Local GATT service remov=
ed
>>>> src/gatt-database.c:send_notification_to_device() GATT server sending =
indication
>>>> src/gatt-database.c:client_disconnect_cb() Client disconnected
>>>> src/advertising.c:client_disconnect_cb() Client disconnected
>>>> src/device.c:gatt_debug() Service Changed received - start: 0x0034 end=
: 0x0039
>>>> src/gatt-database.c:conf_cb() GATT server received confirmation
>>>> src/device.c:gatt_debug() Read By Grp Type - start: 0x0034 end: 0x0039
>>>> src/device.c:gatt_debug() Primary service discovery failed. ATT ECODE:=
 0x0a
>>>> src/device.c:gatt_debug() Read By Grp Type - start: 0x0034 end: 0x0039
>>>> src/device.c:gatt_debug() Secondary service discovery failed. ATT ECOD=
E: 0x0a
>>>> src/device.c:gatt_debug() Read By Type - start: 0x0000 end: 0x0000
>>>> src/device.c:gatt_debug() service disappeared: start 0x0034 end 0x0039
>>>> src/device.c:gatt_service_removed() start: 0x0034, end: 0x0039
>>>>
>>>> Any idea?
>>>>
>>>> Thanks
>>>> Best wishes
>>>> Yunhan
>>>>
>>>> On Tue, Oct 10, 2017 at 1:19 AM, Luiz Augusto von Dentz
>>>> <luiz.dentz@gmail.com> wrote:
>>>>> Hi Yunhan,
>>>>>
>>>>> On Tue, Oct 10, 2017 at 11:02 AM, Yunhan Wang <yunhanw@nestlabs.com> =
wrote:
>>>>>> Hi, Luiz
>>>>>>
>>>>>> Please ignore the previous email.
>>>>>>
>>>>>> I am seeing a bluez gatt notification problem in gatt-database.c
>>>>>>
>>>>>> Here is scenario:
>>>>>>
>>>>>> 1. Assume server has one characteristic A that is subscribed by clie=
nt
>>>>>> and sending notification,
>>>>>> 2. Then ble connection is disconnected by client directly or
>>>>>> connection disappear without unsubscribing A.
>>>>>> 3. Client tries to connect to ble successfully
>>>>>> 4. Client fails to subscribe that characteristic A although ble
>>>>>> connection is ok.
>>>>>> 5. Another retry to make Ble connection and subscribe to A can work.
>>>>>>
>>>>>> It seems ble disconnect at step 2 only disconnect ble connection and
>>>>>> does not cleanup notify_io and stop
>>>>>> notification in step 3 at code,
>>>>>> https://git.kernel.org/pub/scm/bluetooth/bluez.git/tree/src/gatt-dat=
abase.c
>>>>>>
>>>>>> It seems retry in step 4 would trigger ccc_write_cb and release
>>>>>> notify_io and stop notification so that step 5 would succeed.
>>>>>> partial log from step 4:
>>>>>> ccc_write_cb() External CCC write received with value: 0x0000
>>>>>> pipe_hup() 0x921290 closed
>>>>>>
>>>>>> Any idea?
>>>>>
>>>>> Do you have the full logs, this might be a bug since perhaps we
>>>>> cleanup the notification itself though if the device is paired the
>>>>> subscription should be persisted.
>>>>>
>>>>> --
>>>>> Luiz Augusto von Dentz
>>>
>>>
>>>
>>> --
>>> Luiz Augusto von Dentz
>
>
>
> --
> Luiz Augusto von Dentz