* notification has not yet been cleaned in server side when ble is disconnected. @ 2017-10-10 7:57 Yunhan Wang 2017-10-10 8:02 ` Yunhan Wang 0 siblings, 1 reply; 7+ messages in thread From: Yunhan Wang @ 2017-10-10 7:57 UTC (permalink / raw) To: Luiz Augusto von Dentz, linux-bluetooth Hi, Luiz 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 client 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. 5. Another retry to make Ble connection and subscribe to A can work. It seems ble disconnect 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-database.c It seems retry in step 5 would ccc_write_cb() External CCC write received with value: 0x0000 pipe_hup() 0x921290 closed gatt_ccc_write_cb() CCC write called for handle: 0x0037 ^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: notification has not yet been cleaned in server side when ble is disconnected. 2017-10-10 7:57 notification has not yet been cleaned in server side when ble is disconnected Yunhan Wang @ 2017-10-10 8:02 ` Yunhan Wang 2017-10-10 8:19 ` Luiz Augusto von Dentz 0 siblings, 1 reply; 7+ messages in thread From: Yunhan Wang @ 2017-10-10 8:02 UTC (permalink / raw) To: Luiz Augusto von Dentz, linux-bluetooth 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 client 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-database.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? Thanks Best wishes Yunhan ^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: notification has not yet been cleaned in server side when ble is disconnected. 2017-10-10 8:02 ` Yunhan Wang @ 2017-10-10 8:19 ` Luiz Augusto von Dentz 2017-10-10 8:48 ` Yunhan Wang 0 siblings, 1 reply; 7+ messages in thread From: Luiz Augusto von Dentz @ 2017-10-10 8:19 UTC (permalink / raw) To: Yunhan Wang; +Cc: linux-bluetooth@vger.kernel.org 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 client > 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-database.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 ^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: notification has not yet been cleaned in server side when ble is disconnected. 2017-10-10 8:19 ` Luiz Augusto von Dentz @ 2017-10-10 8:48 ` Yunhan Wang 2017-10-10 10:07 ` Luiz Augusto von Dentz 0 siblings, 1 reply; 7+ messages in thread From: Yunhan Wang @ 2017-10-10 8:48 UTC (permalink / raw) To: Luiz Augusto von Dentz; +Cc: linux-bluetooth@vger.kernel.org Hi=EF=BC=8C Luiz Here there is no pair operation in our end. Our rough idea is the below. 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 indic= ation 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 indic= ation 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, rea= son 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, rea= son 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-database.c= #n2005 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 er= r 0 src/device.c:gatt_debug() Read Req - handle: 0x0003 src/gatt-database.c:gap_device_name_read_cb() GAP Device Name read request 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: 0x0009 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 request 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: 0x0037 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: 0x0037 src/gatt-database.c:ccc_write_cb() External CCC write received with value: 0x0000 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 removed src/gatt-database.c:send_notification_to_device() GATT server sending indic= ation 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: 0x0= 039 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 ECODE: 0x= 0a 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> wrot= e: >> 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 client >> 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-databas= e.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 ^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: notification has not yet been cleaned in server side when ble is disconnected. 2017-10-10 8:48 ` Yunhan Wang @ 2017-10-10 10:07 ` Luiz Augusto von Dentz 2017-10-10 15:56 ` Yunhan Wang [not found] ` <CALvjcs-gHUG2byLTCXma9qiRiDAfXpSPcmSePifCUZeDpeLdzA@mail.gmail.com> 0 siblings, 2 replies; 7+ messages in thread From: Luiz Augusto von Dentz @ 2017-10-10 10:07 UTC (permalink / raw) To: Yunhan Wang; +Cc: linux-bluetooth@vger.kernel.org Hi Yunhan, On Tue, Oct 10, 2017 at 11:48 AM, Yunhan Wang <yunhanw@nestlabs.com> wrote: > Hi=EF=BC=8C Luiz > > Here there is no pair operation in our end. Our rough idea is the below. > 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 ind= ication > 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 ind= ication > 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, r= eason 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, r= eason 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-database= .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 reques= t > 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: 0x00= 09 > 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 request > 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: 0x00= 37 > 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: 0x00= 37 > 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. > 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 removed > src/gatt-database.c:send_notification_to_device() GATT server sending ind= ication > 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: 0= x0039 > 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: 0x= 0a > src/device.c:gatt_debug() Read By Grp Type - start: 0x0034 end: 0x0039 > src/device.c:gatt_debug() Secondary service discovery failed. ATT ECODE: = 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> wro= te: >>> 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 client >>> 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-databa= se.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 --=20 Luiz Augusto von Dentz ^ permalink raw reply [flat|nested] 7+ messages in thread
* Re: notification has not yet been cleaned in server side when ble is disconnected. 2017-10-10 10:07 ` Luiz Augusto von Dentz @ 2017-10-10 15:56 ` Yunhan Wang [not found] ` <CALvjcs-gHUG2byLTCXma9qiRiDAfXpSPcmSePifCUZeDpeLdzA@mail.gmail.com> 1 sibling, 0 replies; 7+ messages in thread From: Yunhan Wang @ 2017-10-10 15:56 UTC (permalink / raw) To: Luiz Augusto von Dentz; +Cc: linux-bluetooth@vger.kernel.org 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> wrot= e: >> Hi=EF=BC=8C Luiz >> >> Here there is no pair operation in our end. Our rough idea is the below. >> 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 in= dication >> 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 in= dication >> 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-databas= e.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 reque= st >> 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: 0x0= 009 >> 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 request >> 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: 0x0= 037 >> 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: 0x0= 037 >> 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, normally the remote needs to unsubscribe the characterstic gracefully, then everything would be fine, yes, i have done that in my end. However, if something wrong happens in the remote or someone moves the remote device far away from the peripheral, the client would be disconnected abnormally without unsubscribing, and the peripheral would fail to process the later ble connection if this connection is subscribing the same characteristic. I think we need cleanup functionality inside bluez when disconnect happens, in addition it seems there is no grace way to cleanup characteristic from application using any bluez dbus API. 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 removed >> src/gatt-database.c:send_notification_to_device() GATT server sending in= dication >> 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: 0= x0a >> src/device.c:gatt_debug() Read By Grp Type - start: 0x0034 end: 0x0039 >> src/device.c:gatt_debug() Secondary service discovery failed. ATT ECODE:= 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> wr= ote: >>>> 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 client >>>> 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-datab= ase.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 ^ permalink raw reply [flat|nested] 7+ messages in thread
[parent not found: <CALvjcs-gHUG2byLTCXma9qiRiDAfXpSPcmSePifCUZeDpeLdzA@mail.gmail.com>]
[parent not found: <CABBYNZJySnOPJETdST18KqW1QLAMeHuhyynuoqGjhpoS_fCHYA@mail.gmail.com>]
* Re: notification has not yet been cleaned in server side when ble is disconnected. [not found] ` <CABBYNZJySnOPJETdST18KqW1QLAMeHuhyynuoqGjhpoS_fCHYA@mail.gmail.com> @ 2017-10-21 0:28 ` Yunhan Wang 0 siblings, 0 replies; 7+ messages in thread From: Yunhan Wang @ 2017-10-21 0:28 UTC (permalink / raw) To: Luiz Augusto von Dentz; +Cc: linux-bluetooth@vger.kernel.org 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 ^ permalink raw reply [flat|nested] 7+ messages in thread
end of thread, other threads:[~2017-10-21 0:28 UTC | newest]
Thread overview: 7+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2017-10-10 7:57 notification has not yet been cleaned in server side when ble is disconnected Yunhan Wang
2017-10-10 8:02 ` Yunhan Wang
2017-10-10 8:19 ` Luiz Augusto von Dentz
2017-10-10 8:48 ` Yunhan Wang
2017-10-10 10:07 ` Luiz Augusto von Dentz
2017-10-10 15:56 ` Yunhan Wang
[not found] ` <CALvjcs-gHUG2byLTCXma9qiRiDAfXpSPcmSePifCUZeDpeLdzA@mail.gmail.com>
[not found] ` <CABBYNZJySnOPJETdST18KqW1QLAMeHuhyynuoqGjhpoS_fCHYA@mail.gmail.com>
2017-10-21 0:28 ` Yunhan Wang
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox; as well as URLs for NNTP newsgroup(s).