disconnecting while operations are in progress never gives BLE_GAP_EVT_DISCONNECTED event

[Paul Bradford]

2020-01-24-092119EST-ProductStoppedGettingEventsFromNordicDK.txtImprivataTestNordicEventsNotReceived.zipCalls_to_pc_ble_driver.cpp0285.2020-02-24-TestProgramUploadedToNordicSupport.zipFeb25TestProgramUploadedToNordicSupport.zipImprivata_bgTestApp.zipbgSDKTestAppMay4.zip2020-05-05-035347-NordicDK_USB840M_200505_ClockInternal_2in1.hex.txt.txtbgSDKTestAppMay6.zipI’m developing an application based on pc-ble-driver to talk to an nRF52840-based dongle (from Fanstel).

I’m having trouble disconnecting cleanly when a connection has operations in progress.  For example, I call ‘sd_ble_gattc_write’, which returns NRF_SUCCESS, but I don’t receive event BLE_GATTC_EVT_WRITE_RSP (after waiting 60 seconds), so I decide to disconnect. When this happens, sd_ble_gap_disconnect returns NRF_SUCCESS, but I do not receive BLE_GAP_EVT_DISCONNECTED even after waiting 30 seconds. The connection supervision timeout is 4 seconds.  What could cause the disconnect to not generate any BLE_GAP_EVT_DISCONNECTED event?

What I’m trying to accomplish here: if a connection is not responsive, I want to end that connection, without disturbing other connections I have open.

Thanks,

Paul Bradford

[Paul Bradford]

I have created a test program that reproduces this problem: failure to receive events after a write or read request.  I have posted test program ImprivataTestNordicEventsNotReceived.zip and the main source file NordicTest-pc-ble-driver.cpp.   My intention is that you use the test program binaries, as described in the README.txt n the zip file. I included the source just so you can see what I'm doing, but I didn't include all headers to make it buildable.

[Jørgen Holmefjord]

Thanks for providing the example and detailed instructions. I have managed to run the test, and I have observed a few errors:

2020-02-05 17:18:11.814: sd_ble_gattc_read failed during characteristic_metadata_discovery_start error 0x0008 NRF_ERROR_INVALID_STATE, conn_handle = 0
2020-02-05 17:20:07.410: current GATTC read/write timed out
2020-02-05 17:20:07.410: sd_ble_gattc_read to keep connection alive got BLE_GATTC_EVT_TIMEOUT (which is allowable), so we must disconnect
2020-02-05 17:20:07.439: ERROR: sd_ble_gap_disconnect failed handle 0 error 0x3002 BLE_ERROR_INVALID_CONN_HANDLE
2020-02-05 17:20:43.446: current GATTC read/write timed out
2020-02-05 17:20:43.446: sd_ble_gattc_read to keep connection alive got BLE_GATTC_EVT_TIMEOUT (which is allowable), so we must disconnect
2020-02-05 17:20:43.507: ERROR: sd_ble_gap_disconnect failed handle 0 error 0x3002 BLE_ERROR_INVALID_CONN_HANDLE
2020-02-05 17:22:03.067: current GATTC read/write timed out
2020-02-05 17:22:03.067: sd_ble_gattc_write for characteristic notification got BLE_GATTC_EVT_TIMEOUT (which is allowable), so we must disconnect
2020-02-05 17:22:06.154: sd_ble_gattc_read failed during characteristic_metadata_discovery_start error 0x0008 NRF_ERROR_INVALID_STATE, conn_handle = 0
2020-02-05 17:22:39.167: current GATTC read/write timed out
2020-02-05 17:22:39.167: sd_ble_gattc_read to keep connection alive got BLE_GATTC_EVT_TIMEOUT (which is allowable), so we must disconnect
2020-02-05 17:22:39.254: ERROR: sd_ble_gap_disconnect failed handle 0 error 0x3002 BLE_ERROR_INVALID_CONN_HANDLE

I'm not sure if any of these are related to the issues you are seeing? How long does it normally take before the issue occurs with a single connection?

[Paul Bradford]

The updated test program has some very encouraging results, but with one remaining mystery.   The important recent change (as requested), after a read/write request, it checks for BLE_GAP_EVT_DISCONNECTED in addition to BLE_GATTC_EVT_TIMEOUT and BLE_GATTC_EVT_READ_RSP/BLE_GATTC_EVT_WRITE_RSP. With this change, the GATTC_READ/WRITE problem is not reproducible. That’s great! That implies that since this support case was created (at which time I was checking only for BLE_GATTC_EVT_READ_RSP/BLE_GATTC_EVT_WRITE_RSP) that each failure was caused by receiving events BLE_GATTC_EVT_TIMEOUT or BLE_GAP_EVT_DISCONNECTED but not checking for them.   However, the one remaining mystery is that log I uploaded (2020-01-24-092119EST-ProductStoppedGettingEventsFromNordicDK) shows a SD_BLE_GATTC_READ and then none of those events afterward

 

The test program does often reproduce the problem "ERROR: never got BLE_GAP_EVT_CONNECTED or BLE_GAP_TIMEOUT_SRC_CONN after waiting 65000 milliseconds." For this issue, I want to make sure that after sd_ble_gap_connect returns NRF_SUCCESS, I should definitely get either BLE_GAP_EVT_CONNECTED  or BLE_GAP_EVT_TIMEOUT(with source BLE_GAP_TIMEOUT_SRC_CONN) – that there is no other event that I’m not checking that could signal the end of this operation.

[Paul Bradford]

Looks like the GATTC_WRITE problem is not gone after all. After about a day without the GATTC_WRITE error, I am seeing it multiple times over a short period of time "ERROR: never got BLE_GATTC_EVT_WRITE_RSP or BLE_GATTC_EVT_TIMEOUT or BLE_GAP_EVT_DISCONNECTED after waiting 65000 milliseconds." After that the test program tries to disconnect and fails "ERROR: never got BLE_GAP_EVT_DISCONNECTED after waiting 65000 milliseconds." I have the logging level set so I would see any disconnect event, and there was none.

[Jørgen Holmefjord]

Ok, that's too bad. Are you able to provide the logs for the run with the failing run on the latest application? I'm still not able to reproduce this.

I will try to look more into the missing CONNECTED event issue tomorrow, as this is simpler to reproduce.

[Paul Bradford]

I will work today on reproducing this with the Nordic DK with firmware logging enabled.

For the connection timeout issue, one thing that is very suspicious is that I have tracing to show if I ever receive BLE_GAP_EVT_TIMEOUT, and I don't think I've ever seen this, I would expect that over many hours of testing with thousands of connection attempts, I would see BLE_GAP_EVT_TIMEOUT fairly often, since connections don't always succeed.

[LeoChen]

Fanstel dongle doesn't mount 32K crystal.

The clock setting is internal RC.

Not sure if it makes any difference.

Attached the firmware that Paul is using.

USB840_Connect200120_3in1.hex

[Paul Bradford]

This problem occurs with the nRF52840 dev-dongle, the nRF52840 development kit, as well as the Fanstel dongle. It's not Fanstel-specific.

[Jørgen Holmefjord]

It does, in fact, look like there stops coming events from the softdevice when the CONNECT issue occurs. I have added some debug logs in the serialization library and softdevice handler library and I see that the sd_ble_gap_connect function is being called. After this, I do not see the event handler in the SDH library being called. I can't see any errors or obvious reasons for this. When debugging after the error occurs, the chip seems to be in sleep/WFE.

I will check with the softdevice team tomorrow if they can help with further debugging.

Paul, did you manage to capture debug logs for the GATTC_READ/WRITE issue? Sounds like it could be caused by the same issue from your previous log file.

[Paul Bradford]

I have not reproduced the GATC_READ/WRITE issue since I last setup the Development Kit with debug firmware.   It's been about four days. I'll let it keep running. I did reproduce it (with my product, not my test program) in January, with debug firmware on the DK, and that's the log file 2020-01-24-092119EST-ProductStoppedGettingEventsFromNordicDK. See my update from Jan. 28. That log showed that I issued a GATTC_READ and got no event in response. If I reproduce this with my test program, I don't expect the logs to show anything different from the January log file. I'm not sure what you mean by "it could be caused by the same issue".   If you mean that the CONNECT issue might be the same as the GATTC_READ/WRITE issue, I agree it's possible.

What is the "SDH library"?

[Jørgen Holmefjord]

You can read about the SoftDevice Handler library in the SDK documentation. This is used by most examples in the SDK, to handle the interaction with the softdevice.

I have involved our SDK team, and they are currently investigating this issue. I will get back to you as soon as I receive more feedback from them.

[Jørgen Holmefjord]

Our developers are having some problems with reproducing this on their side. This is a bit strange since I'm able to reproduce within a few minutes every time I run the test with my test-phone. I will be working with them further on Monday to assure they have all the details on how the issue can be reproduced. Have a nice weekend!