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

Hi, Luiz

On Mon, Oct 16, 2017 at 7:31 AM, Luiz Augusto von Dentz
[off-list ref] wrote:

Hi Yunhan,

On Fri, Oct 13, 2017 at 2:13 AM, Yunhan Wang [off-list ref] wrote=

:

quoted

Hi, Luiz

On Tue, Oct 10, 2017 at 3:07 AM, Luiz Augusto von Dentz
[off-list ref] wrote:

quoted

Hi Yunhan,

On Tue, Oct 10, 2017 at 11:48 AM, Yunhan Wang [off-list ref] wr=

ote:

quoted

quoted

quoted

Hi=EF=BC=8C Luiz

Here there is no pair operation in our end. Our rough idea is the belo=

w.

quoted

quoted

quoted

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

quoted

quoted

quoted

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

quoted

quoted

quoted

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

quoted

quoted

quoted

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

quoted

quoted

quoted

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

quoted

quoted

Looks like we are no cleanup up the subscription no matter if paired
or not which partially explain the problem here.

quoted

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

quoted

quoted

quoted

src/device.c:gatt_debug() Read Req - handle: 0x0003
src/gatt-database.c:gap_device_name_read_cb() GAP Device Name read req=

uest

quoted

quoted

quoted

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

quoted

quoted

quoted

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

quoted

quoted

quoted

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

quoted

quoted

quoted

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

quoted

quoted

quoted

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.

quoted

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

quoted

or
b. when disconnect, peripheral app can trigger one dbus api to stop
notification.

Any further idea?

thanks
best wishes
yunhan

quoted

quoted

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

quoted

quoted

quoted

src/gatt-database.c:send_notification_to_device() GATT server sending =

indication

quoted

quoted

quoted

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

quoted

quoted

quoted

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

quoted

quoted

quoted

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

quoted

quoted

quoted

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
[off-list ref] wrote:

quoted

Hi Yunhan,

On Tue, Oct 10, 2017 at 11:02 AM, Yunhan Wang [off-list ref] =

wrote:

quoted

quoted

quoted

quoted

quoted

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

quoted

quoted

quoted

quoted

quoted

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

quoted

quoted

quoted

quoted

quoted

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