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]

I installed 4 dongle and captures the log.

The PC tool output  "never got BLE_GATT_EVT_WRITE_RSP ...." after three hour test.

Attached the log and screenshot.

The last WRITE event on line 7866.

SD_BLE_GATTC_WRITE #7866
BLE_GAP_EVT_DISCONNECTED #7874

BLE_GAP_EVT_CONNECTED #8432
BLE_GAP_EVT_DISCONNECTED #8460

Hope this log can do some help.

Log200212.log

[Jørgen Holmefjord]

Do you always see a DISCONNECTED event after the READ/WRITE when the RSP event is not received? I too am seeing this in my tests, and in this case, I would not expect the softdevice to give any more events for this connection. I can double-check this with the softdevice team if this is the case.

I see the disconnected reason being set to 8 (BLE_HCI_CONNECTION_TIMEOUT) in my tests.

[Paul Bradford]

You're responding to Leo Chen's comment, but I'll add my observations: In my Jan. 22 comment I wrote "I never receive another event for that connection, as shown by USB capture." So after I do a write (or a read), I do not get an event to end that write (or read). In the product, I go ahead and call sd_ble_gap_disconnect, but never receive the disconnect event.   Once I get in this state, I don't receive any more events. (In the test program I don't bother to call sd_ble_gap_disconnect, I exit as soon as the error is detected).

[Jørgen Holmefjord]

Ok, in that case, I do not think I have managed to reproduce the issue properly at all. When I get the error and your program exits, I still see a lot of scan/advertising and events happening in the log (I guess for the next 65 seconds until the error is detected).

I will keep working on it and see if I can get into the state you are describing.

[LeoChen]

When I am using SamSung S7 to test.

I always got the similar result.

The READ/WRITE, then far end disconnected after couple hour testing.

The tool exit after 1 minute later.

I bough a new SamSung Note 10 to test.

I can't reproduce this problem with Note 10 so far.

I installed 6 dongle and running about 20 hours testing.

The difference is Note 10 has more powerful CPU maybe can handle more connection at the same time.

I need to find other phones to compare.

Still trying.

Paul, Would you please also upload your log to Nordic to analysis.

[Jørgen Holmefjord]

I performed my tests with a Huawei P30 Pro, so I'm not sure the CPU speed is the limiting factor. However, phone HW/SW can certainly make an impact.

Which phone model(s) did you do the test with Paul? I'm asking this to be able to reproduce the issue, not to blame the phone vendor.

Also, as Leo suggested, please upload your full debug logs from the connectivity FW.

[Paul Bradford]

I have reproduced this with a variety of phones including an iPhone 8 and a Samsung Galaxy S5. I posted my logs from the connectivity firmware quite a while ago, attachment name 2020-01-24-092119EST-ProductStoppedGettingEventsFromNordicDK

[Jørgen Holmefjord]

Sorry, I thought I had seen the log from you before but I missed it when I read through the post this time. This is strange, I'm not able to get into the state you describe. I have run two kits over the weekend, but I still receive events. I'm now testing with 3 additional dongles, no issues so far today. I will keep running the applications to try and reproduce the issue.

[Paul Bradford]

You wrote on Feb. 19 "I get the error and your program exits". Is somebody debugging to find/fix this? The test program exits when I do a read/write and get no events in response. That's the bug I need fixed. Everything that occurs after that failure to produce an event is secondary.

[Jørgen Holmefjord]

I also said that I always see a BLE_GAP_EVT_DISCONNECTED event in the log after the last GATTC_READ/WRITE, but before the expected GATTC_TIMEOUT. As I understood your next comment, you do not get any DISCONNECTED events, and the connectivity FW stops sending packets entirely? To me, this indicated that you are seeing a different behavior and that I have not managed to reproduce the same issue.