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?

[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!

[Jørgen Holmefjord]

The developer has managed to reproduce the issue, but have not found any root cause of the issue yet. I will be out of the office for the rest of the week, but my colleague will follow up on this thread if there are any updates.

[Paul Bradford]

Update on the two problems in this case:

1. I’ve found the cause of the error “never got BLE_GAP_EVT_CONNECTED or BLE_GAP_EVT_TIMEOUT(BLE_GAP_TIMEOUT_SRC_CONN)”.   ble_gap_scan_params_t.timeout  in the call to sd_ble_gap_connect was set to zero, meaning never timeout.   When setting this to a non-zero value, I do get BLE_GAP_EVT_TIMEOUT(BLE_GAP_TIMEOUT_SRC_CONN).   I had just used the same ble_gap_scan_params_t values from passive scanning, where I really did not want to timeout.
2. I have not seen the GATTC_READ or GATTC_WRITE problem in my test program in 13 days (Feb 27). However, I am seeing it in my product, so I need to investigate the differences between the two.  When I started this support case GATTC_READ was waiting only for event BLE_GATTC_EVT_READ_RSP and GATTC_WRITE was waiting only for event BLE_GATTC_EVT_WRITE_RSP/BLE_GATTC_EVT_WRITE_CMD_TX_COMPLETE. Since then I’ve added checks for events BLE_GAP_EVT_DISCONNECTED and BLE_GATTC_EVT_TIMEOUT.  These changes seemed to almost entirely eliminate this problem from the test program. I have two unexplained facts: a) after making those changes, I did see this problem once, on Feb. 27, with the test program;  b) the logging from debug firmware (attachment 2020-01-24-092119EST-ProductStoppedGettingEventsFromNordicDK.txt) that shows a call to SD_BLE_GATTC_READ with no response event afterwards (BLE_GATTC_EVT_READ_RSP   or BLE_GATTC_EVT_TIMEOUT or BLE_GAP_EVT_DISCONNECTED).  

 

Until I can reproduce this second problem again in a test program, I don’t expect that Nordic can investigate further.   

[Jørgen Holmefjord]

Thanks for the update! Let me know if you are able to reproduce the second issue again and what we need to do to reproduce/investigate it.

[Paul Bradford]

My product intermittently fails to receive an event after a GATTC read/write, but so far my test program does not fail. I'm making the test program incorporate more of the product code, while still being a self-contained test. Still working on it.