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]

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

[nordev]

Karl Ylvisaker said:

What connection parameters are you using for your connection?

#define APP_BLE_OBSERVER_PRIO            3                                          /**< Application's BLE observer priority. You shouldn't need to modify this value. */
#define APP_BLE_CONN_CFG_TAG             1                                          /**< A tag for the SoftDevice BLE configuration. */

#define APP_ADV_INTERVAL                 244                                        /**< The advertising interval (in units of 0.625 ms. Value of 300 corresponds to 187.5 ms). */
#define APP_ADV_TIMEOUT_IN_SECONDS       0                                          /**< The advertising timeout in units of seconds. */

#define MIN_CONN_INTERVAL                MSEC_TO_UNITS(25, UNIT_1_25_MS)            /**< Minimum acceptable connection interval (0.1 seconds). */
#define MAX_CONN_INTERVAL                MSEC_TO_UNITS(1500, UNIT_1_25_MS)          /**< Maximum acceptable connection interval (0.2 second). */
#define SLAVE_LATENCY                    0                                          /**< Slave latency. */
#define CONN_SUP_TIMEOUT                 MSEC_TO_UNITS(5000, UNIT_10_MS)            /**< Connection supervisory timeout (4 seconds). */

#define FIRST_CONN_PARAMS_UPDATE_DELAY   APP_TIMER_TICKS(5000)                      /**< Time from initiating event (connect or start of notification) to first time sd_ble_gap_conn_param_update is called (5 seconds). */
#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). */
#define MAX_CONN_PARAMS_UPDATE_COUNT     2                                          /**< Number of attempts before giving up the connection parameter negotiation. */

#define SEC_PARAM_BOND                   1                                          /**< Perform bonding. */
#define SEC_PARAM_MITM                   0                                          /**< Man In The Middle protection required for Passkey */
#define SEC_PARAM_LESC                   0                                          /**< LE Secure Connections not enabled. */
#define SEC_PARAM_KEYPRESS               0                                          /**< Keypress notifications not enabled. */
#define SEC_PARAM_IO_CAPABILITIES        BLE_GAP_IO_CAPS_DISPLAY_ONLY               /**< Changed for Passkey */
#define SEC_PARAM_OOB                    0                                          /**< Out Of Band data not available. */
#define SEC_PARAM_MIN_KEY_SIZE           7                                          /**< Minimum encryption key size. */
#define SEC_PARAM_MAX_KEY_SIZE           16                                         /**< Maximum encryption key size. */

#define SECURITY_REQUEST_DELAY          APP_TIMER_TICKS(400)

Karl Ylvisaker said:

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

I am sorry, I am not sure how to tell for sure whether this is the case, but I don't think so, because I have tried changing the parameters so they no longer match apple's requirements, as such:

nordev said:

but I followed all the parameters in section 36.6 here, and the issue persisted.

and I was still able to connect. 

To be clear, if I let the iOS phone stay connected to the peripheral for longer than 30s, it will always disconnect immediately. It just seems like there is a minimum 30s waiting period before any disconnect request is processed. 

Karl Ylvisaker said:

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.

I have tried this, but I couldn't get the packets to be decrypted, even if I start watching the peripheral from the device dropdown menu prior to connection. Do you have other suggestions?

As you may (or may not) be able to see from my original post in this thread, the only thing I noticed was that after pressing disconnect, I would get "Empty PDU" for however many seconds it took until I started getting advertising packets again (signifying successful disconnection). If it was a good disconnection, I would go from getting packets ("BAD MIC") to advertising almost immediately, without a lot of "Empty PDU" in between. When I set a breakpoint in the code, the call stack for a "good" disconnection and a long disconnection look the same, except that the long disconnection just takes up to 30 seconds before it is actually triggered. 

nordev said:

I checked the call stack for when the disconnect is triggered and compared between my app and the Nordic example. It is the same exact thing in both cases (screenshot from bms app):

One last thing of note... I am not sure we have MITM and the passkey set up properly. Do you think this could contribute to the problem? I notice that on Android, the phone always requests a passkey to be entered before pairing. On iOS, using the same firmware, it never asks us for a passkey before pairing. This is the only other difference between iOS and Android, so maybe the problems are related?

[Karl Ylvisaker]

Hello again nordev,

Thank you for your patience with this. 

nordev said:

I am sorry, I am not sure how to tell for sure whether this is the case, but I don't think so, because I have tried changing the parameters so they no longer match apple's requirements, as such:

It would be implemented as part of your ble_evt_handler. If no case is implemented to disconnect on a rejected update request, or if an conn param update event is received, which does not match the peripheral's requirements. If none of these cases is implemented, your peripheral will accept whatever the central sets.

nordev said:

I have tried this, but I couldn't get the packets to be decrypted, even if I start watching the peripheral from the device dropdown menu prior to connection. Do you have other suggestions?

With the security parameters you have set there should be no issue sniffing this connection. It is really only LESC security that makes sniffing the connection hard.
The trick for sniffing non-LESC connections is that the sniffer needs to be listening when the connection and bond is being established, so that it may save a copy of the key used for the encryption.
So, if your android already is bonded with the device it will use its stored key, and the sniffer will only then get the BAD MIC packets, because it is unable to decrypt them.

Please make sure to delete bonds on the peripheral and central side, and then restart the bonding process with the sniffer actively listening. Let me know if you still are unable to see the packets' content after doing this.

nordev said:

One last thing of note... I am not sure we have MITM and the passkey set up properly. Do you think this could contribute to the problem? I notice that on Android, the phone always requests a passkey to be entered before pairing. On iOS, using the same firmware, it never asks us for a passkey before pairing. This is the only other difference between iOS and Android, so maybe the problems are related?

This would be a lot easier to debug and pinpoint with a trace. Lets pursue getting the trace up and running, and then return to this once we see what is happening in the exchange.

Best regards,
Karl

[nordev]

Hi Karl, 

Thank you again so, so much for your thorough replies. I was called away on other work for a while and am finally back on this. 

Karl Ylvisaker said:

The trick for sniffing non-LESC connections is that the sniffer needs to be listening when the connection and bond is being established, so that it may save a copy of the key used for the encryption.

I tried sniffing by letting the sniffer sniff the pairing process, as you suggested, but then I got no packets coming in on Wireshark -- I am not sure, maybe this is a Wireshark bug? If I have already paired and I am just connecting, I see a lot of ADV_INV, and then after connecting, I see a lot of "61623 805.470 Slave_0xaf9a83e0 Encrypted packet decrypted incorrectly (bad MIC) LE 1M LE LL 12 150µs 1 0 True 9382" 

I would expect if the sniffer has sniffed the encryption process, these Master / Slave packets would still be coming in, and they would have actual data. But I just get nothing. I get ADV_INV before connection, then after the connection, no packets, and when I disconnect, I get ADV_INV again. I am filtering to only look for data from a particular device.

I saw this resource as well -- What is "Just Works"? Do you have other recommendations for sniffing the connection?

[Karl Ylvisaker]

Hello again nordev,

I hop you are well! :) 

nordev said:

Thank you again so, so much for your thorough replies. I was called away on other work for a while and am finally back on this. 

No problem at all, I am happy to help!
We'll continue this whenever you have the chance, no worries.

nordev said:

I tried sniffing by letting the sniffer sniff the pairing process, as you suggested, but then I got no packets coming in on Wireshark

Are you using a newer iOS device as the central here? What device are you using as your sniffer?
I know that never iOS devices switch to 2 Mbps PHY for the pairing if possible, so if you are using a nRF51 series device as your sniffer that might be why you are not seeing any packets for the pairing process. If it does not show up at all, this might be why.
Could you make sure that you peripheral is only advertising on the 1 Mbps PHY, or that your sniffer device is compatible with 2 Mbps PHY?

nordev said:

then after connecting, I see a lot of "61623 805.470 Slave_0xaf9a83e0 Encrypted packet decrypted incorrectly (bad MIC) LE 1M LE LL 12 150µs 1 0 True 9382" 

Yes, this is to be expected - if the sniffer does not have the encryption key, it will not be able to decode the contents of the message, it will only see that a message is being exchanged. 

nordev said:

What is "Just Works"? Do you have other recommendations for sniffing the connection?

Just Works is one of the available security procedures. If we are unable to sniff the pairing procedure we might look into providing the LTK key manually to the sniffer, but let us keep trying with the sniffer first.

Best regards,
Karl