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 attached a new test program Imprivata_bgTestApp.zip. There is a file called README with instructions, and a description of the problem.   I suggest you try this on a Dell 64-bit Windows 10 laptop that has not had Nordic dev tools installed on it. Usually the problem occurs with in an hour or two.

This test program reproduces the problem on two 64-bit Windows 10 laptops and does not reproduce this on one 64-bit Windows 10 laptop. I don't know what difference between these laptops causes two to fail and one to succeed. All have the same driver usbser.sys 10.0.18362.1 winbuild 160101.0800. Problem has occurred when plugged into USB 2.0 and USB 3.0 ports.

Failing laptops: both Dell, one Windows 10 version 1903 build 18362.657, another Windows 10 version 1909 build 18363.752 (the latest public Windows 10 build)

Laptop that does not reproduce the problem: Lenovo ThinkPad, Windows 10 version 1903 build 18362.657 (exactly the same as one failing laptop). This one has had Nordic tools like nRF Connect installed. One consequence is that when I plugged in an nRF52840 it would show in Device Manager as 'nRF Connect USB CDC ACM (COMx)'. To make it like my other laptops that do not have Nordic tools, I uninstalled the driver so that the nRF52840 would show up as 'USB Serial Device (COMx)'

[Jørgen Holmefjord]

I have had the new application running on my PC with 5 parallel devices for 8 hours yesterday and 4 hours today. So far, I have not been able to reproduce the issue. I do have another PC that does not have Nordic tools installed, but this is not a Dell PC. I will try to setup the test on that one next. It's a bit harder to find equipment for testing this with the limited factors where you have managed to reproduce the issue, due most of us working from home-office due to the Corona situation. Is it still a requirement to have heavy Bluetooth activity around the device in order to reproduce the issue? This could also be a problem to facilitate during home-office.

[Paul Bradford]

I have been reproducing the problem with the new test program at home, where there are few BLE devices. I've also been running a single copy of the program and still reproducing it.

[Paul Bradford]

Hi Jorgen,

I just wanted to confirm that the test program is actually tracking phones. These are the instructions from the README file with the test program:

You can type command 's' (and Enter) at any time to have the test program show progress.
The first line of progress shows the total number of advertisements received through scanning, and how many of those have 128-bit UUIDs.
The second line shows the status of the one UUID we are trying to track (the Android peripheral running Imprivata ID).
Example output if the test program currently has a connection to the test peripheral:
 2020-03-28 14:33:56.614: (WARNING) phone is being tracked: UUID: 1f1413aa-a819-4da2-ae94-c3564c8da7ec; total #adverts = 657

Example output if the test program currently does NOT have a connection to the test peripheral:
 2020-03-28 14:33:56.614: (WARNING) phone is NOT being tracked: total #adverts =

If you can't reproduce this problem with the test program, what help can you give me on diagnosing the problem on my test machines?   Can you create a diagnostic version of the S140 SoftDevice that will generate more logging information when I run it on the Nordic DK and view logging with J-LINK RTT Viewer?

Let me summarize what I'm seeing.

Since this doesn't reproduce on all machines, there is some machine-dependent factor in whether this is reproducible. But I can't imagine a machine-dependent factor that would explain the behavior I'm seeing. At the time the problem occurs, all events from the Nordic chip cease. The serial-port-reader (in pc-ble-driver) still reads "responses" from commands, but never gets another event.
1. The first operation to fail is a write - no event.
2. Then I do a disconnect - get a response but no event.
3. Then I do a connect - get a response but no event.

In mid-January, you had me use connectivity firmware with logging enabled. On January 28, I uploaded logging that showed that I send a read request and never get any event in response.    To me, this indicates the problem is in the SoftDevice layer, since the Connectivity layer never got the event. We need some kind of logging that shows what is happening in the SoftDevice - why does it stop emitting all events?

-Paul

[Jørgen Holmefjord]

Hi Paul,

Today, I managed to reproduce this once on a second computer. That was with the nRF52840 Dongle and the stock connectivity FW (no logging enabled). I'm now testing on the same machine with a nRF52840 DK with logging enabled in the connectivity FW, but so far, I have not been able to reproduce the issue with this setup. 

I can't rule out Softdevice issue entirely, but I would have expected this to be reported by more customers and applications if the problem originated there. Hopefully, we will be able to reproduce it with the logging setup soon to get more details on the root cause. The SDK developers are also trying to reproduce the issue on their end.

Best regards,
Jørgen

[Paul Bradford]

Hi Jørgen,

Have you been able to reproduce the problem again?  Can you tell me the model PC on which you did reproduce it?

-Paul

[Jørgen Holmefjord]

Today I have reproduced it 3 times on the same PC, but only with the precompiled HEX file. Last week I ran it for multiple days on the same PC with logging enabled, without being able to reproduce.

This was on a ASUS ET2221 All-in-One PC, which is the only I have available without Nordic tools installed.

[Paul Bradford]

What is the next step now?

We can't make any progress on using the nRF52840 until this is fixed, or you find some way for us to avoid the problem.

If you are trying to reproduce it with the connectivity firmware logging enabled, I already posted that on January 24, and it didn't show any useful information.

[Jørgen Holmefjord]

Hi Paul,

The point of reproducing it with logging enabled is not just to get similar logs to what you posted on January 24, but to add more logging to the application in order to find where the issue occurs.

I can now consistently reproduce this issue on the same computer, with two different phones, with UART logging enabled. This means that I should be able to add more logging next week, and hopefully get some more details on why this is happening. It's a bit strange that I'm not able to reproduce with RTT logging enabled, but UART will have to do for now. Unfortunately, our SDK developers are still not able to reproduce it on their end, so, for now, we only have my setup to debug with.

Have a nice weekend.

Best regards,
Jørgen

[Jørgen Holmefjord]

Hi,

I ran the application many times over the last few days and from studying the logs it seems that this issue occurs right after the application/connectivity FW starts receiving notifications from the connected phone. It could be a coincidence, but I see the same pattern in all the log-files I have checked. Is there any way you could disable the notifications in the phone application, in order to verify if that is what's causing the issue?

Another customer have reported similar issues with pc-ble-driver, but he was only able to reproduce this with sd_api_v3, not with 6 like you are using. However, it has some other similarities with this issue (I was not able to reproduce his issue when running J-Link RTT Viewer, same as here).

Best regards,
Jørgen

[Paul Bradford]

I agree it seems that the problem is related to receiving notifications. In my reply on January 22 I wrote "The failure to receive events always occurs after I have received notifications for a characteristic."

I've done an experiment that is much simpler than altering the phone app. The notifications from the phone app are triggered by the Windows app writing to a particular characteristic on the phone. I modified the Windows app so that it (optionally) does not write to that characteristic. With that option enabled, the Windows app runs for many hours without failing (about 18 hours so far). By contrast when I start it without that option (and thus with notifications received), it fails in less than an hour each time.

[Jørgen Holmefjord]

Hi Paul,

Today we managed to track down what may be a potential race condition in the connectivity firmware. When the scheduler queue gets close to full (above 75%), the processing of events from the softdevice is suspended in order to leave room for serial events from USB, etc. This happens in ser_conn_handlers.c:191. When the queue is processed and free space is below 50%, the processing of softdevice events will continue (main.c:376). What happens when this issue occurs seems to be that the suspend function is called twice in a row, with a call to resume right after the second suspend:

[00:03:16.456,695] <info> app: nrf_sdh_suspend
[00:03:16.692,565] <info> app: nrf_sdh_suspend
[00:03:16.692,596] <info> app: nrf_sdh_resume

The solution we now are testing is to incorporate the resume section into a critical region:

CRITICAL_REGION_ENTER();
if (nrf_sdh_is_suspended())
{
    // Resume pulling new events if queue utilization drops below 50%.
    if (app_sched_queue_space_get() > (SER_CONN_SCHED_QUEUE_SIZE >> 1))
    {
        nrf_sdh_resume();
    }
}
CRITICAL_REGION_EXIT();

The critical region will prevent the application from processing other application events during this region.

I have had this workaround running with a clean connectivity FW for 3 hours without hitting the issue now (typically issue happens within 5-15 minutes on my setup).

Best regards,
Jørgen