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

[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

[nordev]

Thanks, I hope you are well, too! 

Yes, I am using a newer iOS device as the central. Although the same thing happened when using an older Android device as the central. My sniffer is a Rigado BMD Development Kit with NRF52840 on it. I am not sure how to make sure my peripheral is only advertising on 1Mbps or that my sniffer is compatible with 2Mbps. Do you have guidance on this?

Karl Ylvisaker said:

we might look into providing the LTK key manually to the sniffer,

I am sorry, what is LTK?

[Karl Ylvisaker]

nordev said:

My sniffer is a Rigado BMD Development Kit with NRF52840 on it.

Which sniffer firmware and software are you using?
As far as I know the nRF Sniffer is only compatible with the nRF52840 PCA10056 and PCA10059.
Are you able to successfully sniff any other pairing process? i.e if you flash your DK with an unmodified example from the SDK, and connect to it with your phone, are you able to sniff this connection just fine?

nordev said:

I am not sure how to make sure my peripheral is only advertising on 1Mbps or that my sniffer is compatible with 2Mbps. Do you have guidance on this?

The nRF52840 is compatible with 2 Mbps PHY, so that is fine.
Are you able to see the PHY used for the advertising of each packet in Wireshark? I.e when you see an advertising packet, are you able to tell with PHY it is being advertised on?
The advertised PHY is what will be used when connecting.

nordev said:

I am sorry, what is LTK?

Sorry, it is the long term encryption key. It is possible to provide this directly to the sniffer, if the sniffer is unable to sniff the bonding (such as when using LESC security). We should however first see if we can get the sniffer to work as expected, before moving to this approach.

Best regards,
Karl

[nordev]

Hi Karl,

This is the sniffer hex file I am using. I followed the sniffer setup steps months ago, so I don't remember exactly where I got it from. But the instructions I used were here. I am not sure that I got it from the SDK, but I am sure I got it straight from a Nordic source, and I definitely did not modify the sniffer prior to using it.  

I don't know what changed, but suddenly I seem able to sniff the connection as expected:

The problem is if I let the phone screen go dark, it turns back to "bad mic" 

But I can just delete the bonds from the phone and let the sniffer sniff the pairing process. this should be good enough for testing, I think!

Advertising PHY is LE 1M. What does that mean? Low Energy 1Mbps? 

Sample captures while disconnecting are below: 

When I press disconnect BEFORE the 30s is up, I get a lot of Empty PDU after I press disconnect on the phone.

A) Then I eventually got this (#21714, time 209.819):

B) Then I get this later (#21889, time 212.578)

I tried again keeping better track of time this time: 

 all this stuff happened ~504 (pairing)

@ 512, got this:512.641 Master_0x5065659d Control Opcode: LL_CHANNEL_MAP_IND 

 ~519 pressed disconnect. Got this (mostly empty PDU, all packets were Bad Mic from 515 onward, but they are very sparse -- maybe 3 total packets before the final disconnection)

~537 finally disconnected  Same kind of packet flow as B above, except instead of the actual opcode, I got "bad mic" this time for the last message (I assume it was the termination opcode though)

If I wait MORE than 30s to disconnect, then I get this and it disconnects immediately.

Any ideas what is happening? Is there other data you want me to collect?

[Karl Ylvisaker]

Hello again Nordev,

nordev said:

This is the sniffer hex file I am using. I followed the sniffer setup steps months ago, so I don't remember exactly where I got it from. But the instructions I used were here. I am not sure that I got it from the SDK, but I am sure I got it straight from a Nordic source, and I definitely did not modify the sniffer prior to using it.  

This seems to be our official sniffer firmware, yes. Thank you for clarifying.

nordev said:

I don't know what changed, but suddenly I seem able to sniff the connection as expected:

I am glad to hear it is working as expected now, at least.
For future reference, it would be better if you uploaded the trace instead of screenshots, so I may take a look at it myself.

nordev said:

The problem is if I let the phone screen go dark, it turns back to "bad mic" 

Are you saying that the sniffer will start reading bad mic packages if you let the screen on your phone go dark? Is this consistently happening?
It would be great if you could upload a sniffer trace of this, and indicate which packet number this behavior starts on, so I may take a closer look.
This sounds very strange to me, and I have never heard of anything like it before, but if this turns out to be correlated I suppose there have to be some other power saving setting setting in at the same time as the screen goes dark. Again, this sounds very strange to me, and I'd love to see a trace of this so I may try to understand it better.
Bad mic packets primarily happens when the sniffer is unable to decrypt the packet, so unless the devices update this (without the sniffer seeing it), I dont immediately see how this could happen. 

nordev said:

Advertising PHY is LE 1M. What does that mean? Low Energy 1Mbps? 

Correct.

nordev said:

Sample captures while disconnecting are below: 

When I press disconnect BEFORE the 30s is up, I get a lot of Empty PDU after I press disconnect on the phone.

Great detail to your explanation! It is good that you relate everything to the packet number. However, here it would be great for me to have the sniffer trace myself, so I can see more than just the packets included in the screenshot.
Could you please provide me the complete trace - use the "Insert -> File" option here on DevZone - so I may go through your detailed explanation here, but rather see it in the trace directly? This would make the debugging much easier.

nordev said:

time 209.819

Please be advised that the 'time' column is USB time (i.e when wireshark reads it from the sniffer device), and it is thus not as accurate as the delta time column, for example.

nordev said:

Any ideas what is happening? Is there other data you want me to collect?

It is unfortunately not immediately clear from the description and screenshots alone. I find it very strange that the sniffer suddenly is unable to decrypt the packets, so it would be great to have a look at the packets leading up to this.
Please provide the full trace file(s), so I may take a look for myself. 

I look forward to getting to the bottom of this weird behavior you describe in your comment!

Best regards,
Karl