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 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