BLE Central - getting HVX notification before service discovery completes and handles are saved

[PriyeshN]

Hi Nordic team,

My dev environment is as follows:

nrf52840 + s140 +SD6.0.0 + SDK15.0.0 + SES + nrf52840-DK

nrf52840 is configured as BLE central with bonding enabled

Following is the RTT log when I reboot nrf52840 and connect to peripheral:

<info> app: Enter pairing mode in Lock and enter key as 123456
<info> app: Found Onity device with MAC as DC:A6:32:A9:77:D5
<info> app: Enter pairing mode in Lock and enter key as 123456
<info> app: Connecting to target DC:A6:32:A9:77:D5
<debug> nrf_ble_gatt: Requesting to update ATT MTU to 247 bytes on connection 0x0.
<debug> nrf_ble_gatt: Updating data length to 251 on connection 0x0.
<info> app: Connected to a previously bonded device.
<info> app: Connected to target
<debug> ble_db_disc: Starting discovery of service with UUID 0x9B5F on connection handle 0x0.
<info> app: Connection secured: role: 2, conn_handle: 0x0, procedure: 0.
<debug> nrf_ble_gatt: ATT MTU updated to 247 bytes on connection 0x0 (response).
<info> app: GATT ATT MTU on connection 0x0 changed to 247.
<debug> ble_db_disc: Starting discovery of service with UUID 0x9B5F on connection handle 0x0.
<debug> nrf_ble_gatt: Data length updated to 251 on connection 0x0.
<debug> nrf_ble_gatt: max_rx_octets: 251
<debug> nrf_ble_gatt: max_tx_octets: 251
<debug> nrf_ble_gatt: max_rx_time: 2120
<debug> nrf_ble_gatt: max_tx_time: 2120
<info> app: Data length for connection 0x0 updated to 251.
<debug> nrf_ble_gatt: Peer on connection 0x0 requested an ATT MTU of 517 bytes.
<debug> nrf_ble_gatt: Updating ATT MTU to 247 bytes (desired: 247) on connection 0x0.
<info> app: GATT ATT MTU on connection 0x0 changed to 247.
<debug> ble_db_disc: Found service UUID 0x9B5F.
<debug> app: BLE_GATTC_EVT_HVX
<debug> app: on_hvx
<debug> ble_db_disc: Discovery of service with UUID 0x9B5F completed with success on connection handle 0x0.
<debug> ble_db_disc: Starting discovery of service with UUID 0x9B5F on connection handle 0x0.
<debug> ble_db_disc: Found service UUID 0x9B5F.
<debug> ble_db_disc: Discovery of service with UUID 0x9B5F completed with success on connection handle 0x0.
<info> app: Discovery complete.
<info> app: Connected to device with Onity Event Service.
<debug> app: Notification enabled
<info> app: Discovery complete.
<info> app: Connected to device with Onity Message Service.
<debug> app: BLE_GATTC_EVT_WRITE_RSP
<info> app: Disconnected.
<info> app: Disconnected.
<info> app: Disconnected, reason 0x13.

If you see on line #24 and #25, we see that I'm getting the notification even before the discovery is complete, handles assigned and notification is set. I'm aware that in case of bonded devices, the notification set/clear is saved and need not be enabled everytime. But, here we are getting the notification even before handles are assigned and thus, the checks under "on_hvx()" fails and I cannot see data.

Below is the RTT log for 2nd time connection without any reboot:

<info> app: Found Onity device with MAC as DC:A6:32:A9:77:D5
<info> app: Enter pairing mode in Lock and enter key as 123456
<info> app: Connecting to target DC:A6:32:A9:77:D5
<debug> nrf_ble_gatt: Requesting to update ATT MTU to 247 bytes on connection 0x0.
<debug> nrf_ble_gatt: Updating data length to 251 on connection 0x0.
<info> app: Connected to a previously bonded device.
<info> app: Connected to target
<debug> ble_db_disc: Starting discovery of service with UUID 0x9B5F on connection handle 0x0.
<info> app: Connection secured: role: 2, conn_handle: 0x0, procedure: 0.
<debug> nrf_ble_gatt: ATT MTU updated to 247 bytes on connection 0x0 (response).
<info> app: GATT ATT MTU on connection 0x0 changed to 247.
<debug> ble_db_disc: Starting discovery of service with UUID 0x9B5F on connection handle 0x0.
<debug> nrf_ble_gatt: Data length updated to 251 on connection 0x0.
<debug> nrf_ble_gatt: max_rx_octets: 251
<debug> nrf_ble_gatt: max_tx_octets: 251
<debug> nrf_ble_gatt: max_rx_time: 2120
<debug> nrf_ble_gatt: max_tx_time: 2120
<info> app: Data length for connection 0x0 updated to 251.
<debug> nrf_ble_gatt: Peer on connection 0x0 requested an ATT MTU of 517 bytes.
<debug> nrf_ble_gatt: Updating ATT MTU to 247 bytes (desired: 247) on connection 0x0.
<info> app: GATT ATT MTU on connection 0x0 changed to 247.
<debug> ble_db_disc: Found service UUID 0x9B5F.
<debug> app: BLE_GATTC_EVT_HVX
<debug> app: on_hvx
<debug> app:  01 06 00 00 00 00 00 00|........
<debug> app:  00 00 00 2B 11 5A 83 80|...+.Z..
<debug> app: Client sending data.
<debug> ble_db_disc: Discovery of service with UUID 0x9B5F completed with success on connection handle 0x0.
<debug> ble_db_disc: Starting discovery of service with UUID 0x9B5F on connection handle 0x0.
<debug> ble_db_disc: Found service UUID 0x9B5F.
<debug> ble_db_disc: Discovery of service with UUID 0x9B5F completed with success on connection handle 0x0.
<info> app: Discovery complete.
<info> app: Connected to device with Onity Event Service.
<debug> app: Notification enabled
<info> app: Discovery complete.
<info> app: Connected to device with Onity Message Service.
<debug> app: BLE_GATTC_EVT_WRITE_RSP
<info> app: Disconnected.
<info> app: Disconnected.
<info> app: Disconnected, reason 0x13.

on line #25 and #26, we see the data getting logged this time. looks like the handles existed before hand from the 1st connection.

can someone please explain this behavior? Is it the intended way? How can I get it correct from the 1st connection instance.

Thanks

[Kenneth]

This is kind of the way it is intended to work, since in a bonded relationship it is (as you already write) CCCD that are enabled once the link is secured/encrypted. The peer can then send notification before service discovery is complete. My suggested workarounds:

1. Executing service discovery before bonding/securing the link may help.

2. The application can buffer any notifications received and analyze them when service discovery is complete.

3. The application can cache the handles, e.g. in RAM between connections.

Best regards,
Kenneth

[PriyeshN]

Hi Kenneth,

Thanks for this valuable information.

I did quickly try your 1st option, but it too gave the same result.

Can you help me with any example pseudo code on how can I buffer notifications or handles? Handles I think will be lost on a reboot and I may face the same issue for the 1st event after reboot.

Buffering the notifications seems to be a long term solution, but I'm not aware as to what all I need to buffer to be able to successfully retrieve the data later. Any pseudo-code will be of great help.

Thanks

Priyesh

[Kenneth]

Can you just double check that sd_ble_gatts_hvx() is called on the peripheral, and that there is no error code from sd_ble_gatts_hvx() on the peripheral?

Kenneth

[PriyeshN]

Sorry Kenneth, but peripheral code is not in our scope and control. And definitely that's not Nordic stack. The only information what I have it that peripheral is running on Bluez stack. 

Any other way you can suggest, please

Regards,

Priyesh

[Kenneth]

Okey, in that case I need an on-air sniffer log, I want to see when the notifications is sent from the peripheral relative to the other procedures. You can for instance use nRF Sniffer to create an on-air log.

Kenneth

[PriyeshN]

Sure Kenneth. Do give me some time to get the logs and share with you. I don't have sniffer with me as of now, I'll get one from one of my peers and will capture logs.

Thanks

[PriyeshN]

Hi Kenneth,

Sorry for delayed response. I finally got nRF Dongle with me.

Attached are the on-air logs.

1.pcapng - This is a big logs which has most of the good data transfers. When I say good, I meant, I received HVX and was able to read/write characteristics. Some data did get missed, but I cannot pin-point it

2_missing_hvx.pcapng - This file created just after reboot of peripheral and central. This has only one data (peripheral to master) which I could not read as HVX did not come. This file is laser focused for data we need. I see lot of "MIC error". Is it the cause of issue? What it is?

I was expecting this data on my central 

Tx --> 0x01 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x00 0x2B 0x1F 0x65 0xE3 0x00 

I hope the log files help us in analyzing the issue and resolving it.

Thanks & regards,

Priyesh

5556.pcapng

2_missing_hvx.pcapng

[Kenneth]

Bad MIC means that the link is encrypted, and that the sniffer is not able to decrypt the data.

Are you able to sniff the communication while bonding/pairing? If it's "just work" bonding without passkey, then the sniffer should typically be able to sniff the the reconnections also as long as you don't restart the sniffer. The LTK key may also be distributed during during bonding, in which case you can read it out and use it for later reconnections. If you have the LTK key it may be entered later in wireshark as described here:
https://infocenter.nordicsemi.com/topic/ug_sniffer_ble/UG/sniffer_ble/action_bonded.html
https://infocenter.nordicsemi.com/topic/ug_sniffer_ble/UG/sniffer_ble/sniffer_usage.html

Kenneth