Long time to disconnect

[nordev]

Hi, 

Our NRF52840 (running 14.2) often takes a very long time to disconnect, from when a disconnection is initiated by the phone. It can take 30s, sometimes even more, for the disconnect to happen. Sometimes the disconnect happens immediately like it should, but I would say that it is more common for the disconnect to take a long time than for the disconnect to be normal. 

I installed the NRF Sniffer and have done a capture, but I am not really sure what to make of the result. 

The below was a bad disconnect. Here, the highlighted line was about when the disconnect was initiated on the phone (image 1). Then I got "Empty PDU" for a long time. The empty PDU continues for a long time, with only one "encrypted packet decrypted incorrectly" in between, then in the second image, the highlighted line shows when the disconnect actually happens. There is ~13 sec in between the initiation and the actual disconnect.

By contrast, this was one of the times that I got a normal disconnection. 

The above was done with our custom app. The issue also happens when using the NRF Connect App for iOS. For reference, below is the capture when the disconnect was initiated by the NRF app:

I pressed the disconnect button around the time of this highlighted line: 

There is no command of any kind here though; the closest command is this one (but I don't know if they're even related, this is just the first command I found when scrolling up):

The disconnect comes what looks like 23 seconds later: 

My questions:

(MAIN QUESTION) How can I find out why it is taking a long time to disconnect? Note that it happens with different phones, but we have only been able to test with iPhones so far.

AUXILLIARY QUESTIONS: 

1. What are control opcodes and why do they only show up in the test using the NRF app, but not our custom app? Should we do something to enable these opcodes? 

2. What is empty PDU? 

3. What is "bad MIC"?

4. Where do I learn about how to interpret the captured packets? I read this but it doesn't really explain what I should be looking for.

Thanks!

[nordev]

I have another clue: 

The "long disconnect" only happens when we try to disconnect within 30s of starting a new connection. 

If the device has been connected for more than 30s, it will disconnect immediately when the disconnect is initiated.

If the device has been connected for less than 30s when the disconnect is initiated, it will disconnect 31 seconds after the initial connection, no matter whether the disconnect was initiated 10s, 15s, 20s, etc after the initial connection. 

Again, the below is the only thing in my code that seems to use a 30s delay: 

#define NEXT_CONN_PARAMS_UPDATE_DELAY    APP_TIMER_TICKS(30000)                     /**< Time between each call to sd_ble_gap_conn_param_update after the first call (30 seconds). */

But changing this parameter does not seem to affect the long disconnect. 

So, why might this be happening?

[nordev]

Hi Joakim, are you still looking at this ticket? If not, should someone else be assigned to this ticket, perhaps? 

Thank you!

[Karl Ylvisaker]

Hello again nordev,

I will be taking over this ticket, as Joakim has been pulled away to other tasks for the time being.

From your initial ticket and answers I am thinking that it is your call to disconnect is not being handled properly. Looking at the screenshot from the traces you sent, it seems that the disconnection is working as intended when it is sent, but that the termination packet is not being sent during the 'long disconnect' intervals.
I therefore think we should look to the sd_ble_gap_disconnect calls that you have earlier mentioned does not get triggered when stepping through the code. I am confident that this is an error in the application layer / code.

I know from your other ticket that you have a lot of other tasks going immediately after a connection. I suspect that your call to disconnect takes a long time to trigger because of a priority mismatch.

If you are attempting to trigger the disconnect using a button press, what priority are you using for your bsp handler? And, what is the priority of your other interrupt based functions?

Looking forward to resolving this issue together!

Best regards,
Karl

[nordev]

Hi Karl, thank you so much!!!

I am calling the disconnect via the disconnect button inside the NRF Connect app for iOS (v2.4.8), or within our custom iOS app, not via the bsp. The long disconnect only happens on iOS. When I try using NRF Connect for android (v4.24.2), it always disconnects immediately, even when I try to disconnect immediately, like 1s after connecting. 

My interrupt priorities are as follows:

#define SPI_DEFAULT_CONFIG_IRQ_PRIORITY 6
#define UART_DEFAULT_CONFIG_IRQ_PRIORITY 3
#define APP_TIMER_CONFIG_IRQ_PRIORITY 7

The disconnect on iOS happens, without fail, exactly 30s after the initial connection. EX: if I start the connection at t=0, no matter if I press "disconnect" on the phone at t=7, t=12, t=20, etc., the disconnect will always trigger on the BT device at exactly t=30s. I would think if it were an interrupt priority problem, this time period would vary. 

I know when the disconnect happens because inside ble_evt_handler, case BLE_GAP_EVT_DISCONNECTED: I put logs and I toggle an LED. 

One last piece of possibly useful info:

nordev said:

on very very rare occasions, I also see a random disconnect with reason 0x08, /**< Connection Timeout. */

Do you know what timeout this would be? I am just wondering if it is related because the fact that it takes a different amount of time each time to disconnect suggests that maybe we are waiting for some kind of timeout, and we just happen to start at a different place in the timeout each time. 

(and by "different amount of time to connect," i mean different amount of time from when the disconnect button was pressed, which is consistent with the 30s finding above).

[Karl Ylvisaker]

nordev said:

thank you so much!!!

No problem at all, nordev!

nordev said:

I am calling the disconnect via the disconnect button inside the NRF Connect app for iOS (v2.4.8), or within our custom iOS app, not via the bsp. The long disconnect only happens on iOS. When I try using NRF Connect for android (v4.24.2), it always disconnects immediately, even when I try to disconnect immediately, like 1s after connecting. 

My apologies, I got this wrong when reading through the case history - I thought the problem was that the disconnect procedure did not start on the peripheral device.

nordev said:

My interrupt priorities are as follows:

Thank you for providing these.

nordev said:

The disconnect on iOS happens, without fail, exactly 30s after the initial connection. EX: if I start the connection at t=0, no matter if I press "disconnect" on the phone at t=7, t=12, t=20, etc., the disconnect will always trigger on the BT device at exactly t=30s. I would think if it were an interrupt priority problem, this time period would vary. 

What connection parameters are you using for your connection? And, is your peripheral device programmed to terminate the link if the connection parameters does not follow its preferences?

It would be great if you could produce a sniffer trace of a disconnect using an android, and another one when using an iOS device. This way, we should be able to rule out a couple of possibilities right off the bat. The sniffer trace will tell us whether the problem lies with the iOS's link termination packet or not.
I think that currently, the case might be that the iOS device is demanding parameters that does not align with the configuration of the peripheral, and when these are not met, the peripheral triggers the disconnect after 30 s. However, I find it very strange that your attempt to trigger the disconnect is not working either.

Make sure to select your peripheral device from the device drop down menu (shown in the included image) in Wireshark before starting the first connection, so that the sniffer will follow into the connection and be able to decrypt the packets being sent between the central and peripheral.

You could do multiple connections and reconnections in the same trace, to highlight the issue.

Looking forward to resolving this issue together!

Best regards,
Karl