[TW#18502] BLE register service change notify odd behaviour

[jedi7]

Hi,
I have quite problem to find right time when I can write to BLE server (Scale).
When I start after open/connect event, then I collide with bta_gattc_register_service_change_notify
which also trying to write to the device and it ends with GATT_BUSY.

But when I start after ESP_GAP_BLE_UPDATE_CONN_PARAMS_EVT
Then I miss 5s on start, where is scale sending data about temporary weight.

Also the function bta_gattc_register_service_change_notify try to write before ESP_GATTC_OPEN_EVT
which does not make too much sense.

This is log when I start after ESP_GATTC_OPEN_EVT (you can see 5s delay)

I (15667) [BLE]: : Connect to the remote device.
I (15677) [BLE]: : stop scan successfully
I (16157) dbg: bta_gattc_conn_cback enter
I (16157) dbg: bta_gattc_register_service_change_notify enter
I (16157) dbg: need timer1 // position markers, which say if timer will be used
I (16167) dbg: need timer2
I (16167) dbg: bta_gattc_register_service_change_notify exit 1
I (16177) dbg: start timer
I (16177) dbg: bta_gattc_conn_cback exit
I (16187) [BLE]: : ESP_GATTC_CONNECT_EVT conn_id 0, if 1
I (16187) [BLE]: : ESP_GATTC_OPEN_EVT, status=0
I (17177) dbg: bta_gattc_wait4_service_change_ccc_cback enter
I (17177) dbg: bta_gattc_register_service_change_notify enter
I (17177) dbg: will write conn=1
I (17187) dbg: write status 132 // 0x84 GATT_BUSY
I (17187) dbg: need timer5
I (17187) dbg: bta_gattc_register_service_change_notify exit 5
I (17197) dbg: bta_gattc_wait4_service_change_ccc_cback exit
I (17397) dbg: bta_gattc_wait4_service_change_ccc_cback enter
I (17397) dbg: bta_gattc_register_service_change_notify enter
I (17397) dbg: will write conn=1
I (17407) dbg: write status 132 // 0x84 GATT_BUSY
I (17407) dbg: need timer5
I (17407) dbg: bta_gattc_register_service_change_notify exit 5
I (17417) dbg: bta_gattc_wait4_service_change_ccc_cback exit
I (17617) dbg: bta_gattc_wait4_service_change_ccc_cback enter
I (17617) dbg: bta_gattc_register_service_change_notify enter
I (17617) dbg: will write conn=1
I (17627) dbg: write status 0
I (17627) dbg: bta_gattc_register_service_change_notify exit 0
I (17637) dbg: bta_gattc_wait4_service_change_ccc_cback exit
E (17647) BT: No pending command
I (21177) [BLE]: : ESP_GAP_BLE_UPDATE_CONN_PARAMS_EVT status = 0, min_int = 40, max_int = 40,conn_int = 40,latency = 0, timeout = 600
I (21277) [BLE]: : ESP_GATTC_CFG_MTU_EVT, Status 0, MTU 23, conn_id 0
I (21277) [BLE]: : direct register notify, handle=0x2e
I (21287) [BLE]: : ESP_GATTC_REG_FOR_NOTIFY_EVT
I (21377) [BLE]: : WRITE DESCR: status 0
scale cmd=0, auto=1
send_hello

Then question is, what is proper order of evetns/ commands? Because gattc client example does not count with service change registration and initial writing to device.
Thanks

[Weijian-Espressif]

@jedi7 you can refer to gatt_client demo and gatt_server demo in our ESP-IDF.
Run the gatt_client demo, the client demo will automatically connect to the gatt_server demo.
The client demo will enable gatt_server's notify after connection. Then two devices will exchange
data.

[jedi7]

@Weijian-Espressif yeah I started from gatt_client demo. But I think it does not work properly.

If I understand the flow. Then after connect the 1s timer is started for registering service change notification. And also after connect is registered notification. After this, data are started writing.

Then there can (and it is, in my prog) be collision when timer expires, and client wants write data and also try register service change notification.

I tried to disable registering of the service change registration and everything started working properly.

Then is please possible add an configuration option to disable this automatic service change registration? Because if I want it, then I register it in my program.

Thanks :)

[Weijian-Espressif]

@jedi7 Thanks for your advice. our example is just a demo, you can write directly when get ESP_GATTC_SEARCH_CMPL_EVT.

[jedi7]

@Weijian-Espressif Maybe I explain it wrongly. When you look at the log in first comment, I will hit the GATT_BUSY when I ignore the service change registration and start sequentially writing to client.
In other words. When I write after ESP_GATTC_WRITE_DESCR_EVT and then ESP_GATTC_WRITE_CHAR_EVT. Then I hit the GATT_BUSY (not always, depends on the service change timer expiration) and communication is going to hell.

When I comment out (in esp-idf) the service change registration, then everything works like charm.

I can create pull request, but I will need esp architect, which will say if I should disable the code by #ifdef or by parameter.

[jedi7]

I'm using master branch,commit 363c096

[Weijian-Espressif]

@jedi7 You can set connection params before connection in gatt cilent , the API is esp_ble_gap_set_prefer_conn_params(), gatt server do not need to update connection params.
gatt client steps:

1. stop scan and set prefer_conn_params
2. open
3. esp_ble_gattc_search_service when get ESP_GATTC_CONNECT_EVT
4. write char when get ESP_GATTC_SEARCH_CMPL_EVT

[jedi7]

@Weijian-Espressif It little confuses me. How setting these parameters helps with avoid calling function bta_gattc_register_service_change_notify() in callback bta_gattc_conn_cback() ?

I'm looking into file ./esp-idf/components/bt/bluedroid/bta/gatt/bta_gattc_act.c
Line: 1626
exactly this Line 2314 GATTC_Write collides with my GATTC_Write.

I'm doing this sequention:
`ESP_GATTC_SEARCH_CMPL_EVT // But I can avoid searching, because I already know the handlers.
esp_ble_gattc_register_for_notify
ESP_GATTC_REG_FOR_NOTIFY_EVT:
esp_ble_gattc_write_char_descr
ESP_GATTC_WRITE_DESCR_EVT:

loop:
write user data to server (scale) - esp_ble_gattc_write_char
ESP_GATTC_WRITE_CHAR_EVT: mark I can write to server
ESP_GATTC_NOTIFY_EVT: - read data from server (scale)`

[Weijian-Espressif]

@jedi7 I write char directly when get ESP_GATTC_CONNECT_EVT, it works properly. bta_gattc_register_service_change_notify do not affect your writing! I work at IDF release/3.0.

I (574) GATTC_DEMO: REG_EVT
I (584) GATTC_DEMO: scan start success
I (614) GATTC_DEMO: 30 ae a4 80 59 22
I (614) GATTC_DEMO: searched Adv Data Len 28, Scan Response Len 28
I (614) GATTC_DEMO: searched Device Name Len 14
I (614) GATTC_DEMO: ESP_GATTS_DEMO
I (624) GATTC_DEMO:

I (624) GATTC_DEMO: searched device ESP_GATTS_DEMO

I (634) GATTC_DEMO: connect to the remote device.
I (644) GATTC_DEMO: stop scan successfully
bta_gattc_register_service_change_notify
I (774) GATTC_DEMO: ESP_GATTC_CONNECT_EVT conn_id 0, if 1
I (774) GATTC_DEMO: REMOTE BDA:
I (774) GATTC_DEMO: 30 ae a4 80 59 22
I (774) GATTC_DEMO: open success
I (1444) GATTC_DEMO: write char success
bta_gattc_register_service_change_notify
bta_gattc_register_service_change_notify

gatt server log:
I (463) GATTS_DEMO: REGISTER_APP_EVT, status 0, app_id 0

I (463) GATTS_DEMO: CREATE_SERVICE_EVT, status 0, service_handle 40

I (473) GATTS_DEMO: SERVICE_START_EVT, status 0, service_handle 40

I (473) GATTS_DEMO: ADD_CHAR_EVT, status 0, attr_handle 42, service_handle 40

I (483) GATTS_DEMO: the gatts demo char length = 3

I (483) GATTS_DEMO: prf_char[0] =11

I (493) GATTS_DEMO: prf_char[1] =22

I (493) GATTS_DEMO: prf_char[2] =33

I (503) GATTS_DEMO: ADD_DESCR_EVT, status 0, attr_handle 43, service_handle 40

I (503) GATTS_DEMO: REGISTER_APP_EVT, status 0, app_id 1

I (513) GATTS_DEMO: CREATE_SERVICE_EVT, status 0, service_handle 44

I (523) GATTS_DEMO: SERVICE_START_EVT, status 0, service_handle 44

I (523) GATTS_DEMO: ADD_CHAR_EVT, status 0, attr_handle 46, service_handle 44

I (533) GATTS_DEMO: ADD_DESCR_EVT, status 0, attr_handle 47, service_handle 44

I (38973) GATTS_DEMO: ESP_GATTS_CONNECT_EVT, conn_id 0, remote 30:ae:a4:00:46:d2:
I (38973) GATTS_DEMO: CONNECT_EVT, conn_id 0, remote 30:ae:a4:00:46:d2:
I (39633) GATTS_DEMO: GATT_WRITE_EVT, conn_id 0, trans_id 1, handle 42
I (39663) GATTS_DEMO: GATT_WRITE_EVT, conn_id 0, trans_id 2, handle 42
I (39693) GATTS_DEMO: ESP_GATTS_EXEC_WRITE_EVT
I (39693) GATTS_DEMO: ff 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
I (39693) GATTS_DEMO: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
I (39703) GATTS_DEMO: 00 00 00

here is my test demo, please refer to.
test_code.zip

[jedi7]

@Weijian-Espressif Thanks for your effort. I looked into your test code (it looks like reduced the example one) And there is only one write to server.

My problem occurs after cca 1s and not always, depends when the "ccc_timer" timer expire and "bta_gattc_register_service_change_notify" is called.
I can try to modify the example to do more work, but I do not have devices to test it. (I have only one now)

[jedi7]

There is another example, when the collision happen:

I (33257) [BLE]: : Is known device
scale is probably awaked
I (33257) [BLE]: : Connect to the remote device.
I (33267) [BLE]: : stop scan successfully
E (33547) BT: bta_gattc_act bta_gattc_register_service_change_notify
I (33547) [BLE]: : EVT 40, gattc if 1
I (33547) [BLE]: : ESP_GATTC_CONNECT_EVT conn_id 0, if 1
I (33557) [BLE]: : REMOTE BDA:
I (33557) [BLE]: : c8 fd 19 94 27 9a
I (33557) [BLE]: : EVT 2, gattc if 1
I (33567) [BLE]: : ESP_GATTC_OPEN_EVT, status=0
E (34547) BT: bta_gattc_act bta_gattc_register_service_change_notify
E (34747) BT: bta_gattc_act bta_gattc_register_service_change_notify
I (34937) [BLE]: : EVT 18, gattc if 1
I (34937) [BLE]: : ESP_GATTC_CFG_MTU_EVT, Status 0, MTU 23, conn_id 0
I (34937) [BLE]: : register notify, handle=0x2e
I (34947) [BLE]: : EVT 38, gattc if 1
I (34947) [BLE]: : ESP_GATTC_REG_FOR_NOTIFY_EVT
E (34957) BT: bta_gattc_act bta_gattc_register_service_change_notify
E (34967) BT: gatt_api GATT_Write called conn=1
E (34967) BT: gatt_api GATT_Write called conn=1
E (34977) BT: GATTC_Write GATT_BUSY conn_id = 1
E (34977) BT: No pending command
E (35047) BT: No pending command
I (38597) [BLE]: : update connetion params status = 0, min_int = 40, max_int = 40,conn_int = 40,latency = 0, timeout = 600
Scale Watchdog - disconnecting scale
E (63567) BT: bta_gattc_conn_cback() - cif=1 connected=0 conn_id=1 reason=0x0016
I (63567) [BLE]: : EVT 41, gattc if 1
I (63567) [BLE]: : ESP_GATTC_DISCONNECT_EVT reason=22

here you can see the ccc timer started on
E (33547) BT: bta_gattc_act bta_gattc_register_service_change_notify
expires here E (34957) BT: bta_gattc_act bta_gattc_register_service_change_notify
and collide with my write after
I (34947) [BLE]: : ESP_GATTC_REG_FOR_NOTIFY_EVT
which leads to
E (34977) BT: GATTC_Write GATT_BUSY conn_id = 1

[jedi7]

I also fixed formatting in first comment, so it is now better readable (sorry for that)

[Weijian-Espressif]

My test is ok, Can you delete the connection parameter update in gatt server and try? Or can you provide your test code?

[jedi7]

@Weijian-Espressif that is the problem, the server is proprietary scale, I cannot make changes into server. Just on client. I can provide the client code for communicating with the scale. But without the scale you are not able to test it.

Anyway, I think, the problem is visible directly in the code. Where I have my chain of writing and reading to server and this chain is interrupted by the ccc timer with bta_gattc_act bta_gattc_register_service_change_notify.
And the scale (or BLE) is not able to handle two writes / commands at once.

I compared the release 3.0 and master and there only minor changes, then with proper test we will be able to create the scenario.

I will try to modify the example files, and send it to you.

[jedi7]

jedi_gatt_test.zip

Please try this test client with an gatt server with enabled service change.
I also added piece of my code which I really use.
Thanks

[Weijian-Espressif]

@jedi7 It is normal to register service change notification after connection. In fact it will only be written once. The result of my test is that it has little impact on application layer read and write.
If your application is time-sensitive, you can increase the timeout or delete the function. If you delete this function, you maybe can not receive the service change event.

[jedi7]

@Weijian-Espressif Yes it is, but i prefer to have it registered in my flow, not in paralel which leads to collision on write and GATT_BUSY. The test which I sent run ok? No GATT_BUSY collisions?
As I wrote, I cannot change the server, it is scale. And when user steps on scale, then it starts sending his weight to me. There is no much time.

I can prepare PR with turning off the automatic service change registration and keep it on user if he want it or not.

[Weijian-Espressif]

@jedi7 Scale requires higher time. Now the best solution is to switch off the bta_gattc_register_service_change_notify.