Android phone loses bonding information when trying to read characteristic

[Acutetech]

I have an issue with bonding between a PCA10040 running the sample Glucose app and an Acer tablet running Android 7 and nRF Toolbox. I have not seen the problem on a second (Asus) tablet or a Samsung phone (Android 8). I can set up a bond and interact with the peripheral, but when I try to connect a second time, the peripheral disconnects immediately and then the tablet loses its bonding after about 19s.

Here is a typical sequence (although other variants also occur):

1   Ensure the peripheral is removed from the Paired Devices list on the tablet.

2   Remove pairing from the peripheral by holding down Button 2 during power on.

3   Run the nRF Toolbox Glucose monitor app and connect to the peripheral. The peripheral prints a passkey which I enter. Toast says the device is now bonded and I see it appears in the Paired Devices list on the tablet.

4   I use nRF Toolbox to disconnect from the peripheral, then attempt to connect again. The peripheral appears in the list of "Bonded devices".

5   The peripheral reports "Glucose example started, Fast advertising, Connected, Connection secured: role: Peripheral, conn_handle: 0, procedure: Encryption,  Link secured. Role: 1. conn_handle: 0, Procedure: 0, Fast advertising, Disconnected".  The disconnect is immediate.

6   The app does not immediately notice that the peripheral has disconnected. After a while the "Disconnect" button changes to "Connect"

7   When I click on "Connect" the peripheral now appears in the "Available devices" section in the "Select device:" dialog, rather than the "Paired Devices" section. Furthermore, if I go to Settings>Bluetooth, it also appears in the "Available devices" section. In other words, the tablet has forgotten the pairing. The peripheral presumably thinks it is still paired.

8   If I try to connect in nRF Toolbox, the app makes a sound, Toast says "bonding with the device", the peripheral prints "Connected", then after a delay, Toast says "bonding failed" and the peripheral prints: "BLE_GAP_EVT_AUTH_STATUS: status=0x1 bond=0x0 lv4: 0 kdist_own:0x0 kdist_peer:0x0, Fast advertising, Disconnected".

At this stage the only way to recover is to remove the pairing from the peripheral.

When I look at the nRF logs, in the failure case errors start when nRF Toolbox tries to read the battery characteristic. Typically I see error (0x85). In some log files (but not all) I see "[Broadcast] Action received: android.bluettoth.device.action.BOND_STATE_CHANGED, bond state changed to: BOND_NONE (10)"

I see the problems when I use nRF Toolkit downloaded from Playstore and built from the Github Master branch.

Sometimes the app makes a sound, Toast says "Bonding with the device" but the dialog asking for the passkey does not appear, and the peripheral does not print a passkey.

I can predict when the loss of pairing is about to happen. I go to the Settings Bluetooth screen and see the peripheral in the list of bonded devices. After a few sections I see Toast "Error on reading characteristic 133" error, and at the same moment the peripheral moves from the "Bonded devices" list to the "Available devices" list. In the case, nRF Logger shows the app is trying to read teh battery characteristic, then about 19s later the BOND_STATE_CHANGE message is printed, then the Error (0x85). Note in this case that while the tablet thinks it is connected, the peripheral has disconnected almost immediately after it connected.

[Sigurd]

Hi,

I have not seen this issue before.

What SDK version did you test this with? 

If you have another nRF52-DK, it could be interesting to see the results of a sniffer log. See this and this page.

[Acutetech]

Hi Sigurd. As I wrote above, on the second connection nRF Connect thinks it is connected, but the peripheral connects and disconnects very quickly. After 19s the nRF Logger prints that the bonding has changed to BOND_NONE, then shows a 0x85 GATT Error.

I added code to print the disconnect reason and I see this:

<info> app: Connected
<info> peer_manager_handler: Connection secured: role: Peripheral, conn_handle: 0, procedure: Encryption
<info> app: Link secured. Role: 1. conn_handle: 0, Procedure: 0
<info> app: Fast advertising
<info> app: Disconnected, reason 61.

Error 61 (0x3D) is described in these posts:

https://devzone.nordicsemi.com/f/nordic-q-a/25583/error-0x3d-disconnected-reason-61-sdk12-3

https://devzone.nordicsemi.com/f/nordic-q-a/26287/connections-to-moto-e4-fail-with-0x3d-connection-terminated-due-to-mic-failure

The second post suggests a fix but I don't understand it. main.c contains this line - should I change it, and what to:

    cp_init.start_on_notify_cccd_handle    = BLE_GATT_HANDLE_INVALID;

There are two questions in my mind:

1  Why is the peripheral disconnecting with reason 61, and how do I avoid this?

2  Why is the tablet losing the bonding information, and how to avoid it? Is the bonding being lost because of explicit action by nRF Toolkit or the Android BLE Library, or is this being done by the BLE stack in my phone as a result of the earlier error?

FYI, I can operate the same tablet plus nRF Toolkit with a Glucose peripheral based on a CSR development board without this problem.

[Sigurd]

Acutetech said:

1  Why is the peripheral disconnecting with reason 61, and how do I avoid this?

Generally, you will get this error if you use incorrect encryption keys when you try to encrypt the link with a bonded device. As mentioned before, a sniffer log could help us identify the problem.

What SDK version is this? If you are using an old SDK version, please try to use latest version(SDK 15.2).

Acutetech said:

2  Why is the tablet losing the bonding information, and how to avoid it? Is the bonding being lost because of explicit action by nRF Toolkit or the Android BLE Library, or is this being done by the BLE stack in my phone as a result of the earlier error?

I believe that this is caused by issues in the native BLE stack on the phone. Maybe triggered by some BLE procedure it’s not handling correctly. Do you see the same issue if you use nRFConnect instead ? See this link. 

[Acutetech]

I get the same results when I use nRF Connect. The first connection gives a bond and I can access the peripheral, but the second connection gives the 61 error and the bonding is lost from the tablet.

I have programmed the PCA10040 with the "latest" code (SDK downloaded 31/10/18 with this path:)
C:\Users\charl\Development\nRF5_SDK_15.2.0_9412b96\examples\ble_peripheral\ble_app_gls I believe this uses the s132 SoftDevice.

I downloaded the sniffer package but it does not look like I have hardware that will permit me to run this at the moment.
I have PCA10059 dongles but it looks like the sniffer does not work with these. Can this be done? Or could I run the Glucose app on the dongle? Otherwise looks like I have to find some extra hardware.

[Acutetech]

I get the same result if I use LightBlue Explorer instead of nRF Connect.

Can you comment on the fix reported in one of the links above? I don't know how I can do that.

AFAIK, neither nRF Logger nor the glucose app reports on either conn param negotiation or encryption events. Can these be turned on and examined?

[Sigurd]

Acutetech said:

I have PCA10059 dongles but it looks like the sniffer does not work with these. Can this be done?

PCA10059 is currently not supported by the nRF Sniffer.

Acutetech said:

Or could I run the Glucose app on the dongle?

That is possible. To simplify things, it might be easier to use static passkey with the dongle.

Acutetech said:

Can you comment on the fix reported in one of the links above? I don't know how I can do that.

Link 1: The workaround was to delay the connection parameter update request. If the connection parameters is not within the min/max values, it will send a request after FIRST_CONN_PARAMS_UPDATE_DELAY, which is set to 5 sec in the ble_app_gls example. You could try to set it to 15 sec instead.

Link 2: Same thing here as in link 1.

Acutetech said:

AFAIK, neither nRF Logger nor the glucose app reports on either conn param negotiation or encryption events. Can these be turned on and examined?

Do you have "VERBOSE" logging on the app? On the nRF52 you could set PM_LOG_LEVEL to 4, and NRF_LOG_DEFAULT_LEVEL to 4 in sdk_config.h

You could also test with older versions of the SDK, to see if you have the samme issue here. E.g. test with SDK 12.3.

[Acutetech]

(1) I obtained a second nRF52 to act as a sniffer. However it does not decrypt encrypted packets -  see devzone.nordicsemi.com/.../nrf-sniffer-decryption-is-not-working-after-entering-passkey

(2) I extended FIRST_CONN_PARAMS_UPDATE_DELAY from 5s to 15s but it did not fix the problem. Note that is NOT the fix applied by Seth Foster (see link above) who said "start_on_notify_cccd_handle to a handle that is always set to notify after connection" - what does that mean?

(3)    I then tried the SDK12.3, which also gave problems (not identical), then started digging into the code in both versions that established a secure connection. Full details follow but the problem seems to be when both the Central and Peripheral try to initiate encryption. Looks like the Asus tablet handles that badly and ends up deleting bonding data. One hack is to stop the peripheral initiating encryption, but from comments in the source it looks like that might be needed for some Central devices. It looks like another fix is to reduce PM_HANDLER_SEC_DELAY_MS from 400ms to 100ms (but what is safe?).

Does Nordic have documentation on which device should initiate encryption, and when?

Full results for both SDKs follow in the next post, to avoid clutter.

[Acutetech]

Experiments with both SDKs and different security delays follow.

With SDK12.3  (Summary: works with a 100ms security delay but not with 400ms or 900ms. Bug fix found.)

Code in main.c sets up a delayed call to pm_conn_secure() to secure the communications. This is triggered after
BLE_GAP_EVT_CONNECTED events (connection established) and PM_EVT_BONDED_PEER_CONNECTED events ("Connected to a previously bonded device.")
The delay is set by SECURITY_REQUEST_DELAY, initially at 400ms.

On the first connection (not bonded) this is the sequence:
    BLE_GAP_EVT_CONNECTED event (connection established)
    A delayed call to sec_req_timeout_handler() and pm_conn_secure()
    This triggers the passkey activity.
    PM_EVT_CONN_SEC_SUCCEEDED event ("Link secured")
    Works OK until the Central disconnects.

On the second connection and a 100ms delay this is the sequence:
    PM_EVT_BONDED_PEER_CONNECTED event ("Connected to a previously bonded device.")
    BLE_GAP_EVT_CONNECTED event (connection established)
    One delayed call to sec_req_timeout_handler() and pm_conn_secure()
    PM_EVT_CONN_SEC_SUCCEEDED event ("Link secured")
    (Works OK: stays connected until the Central disconnects)
    
    (Same with Asus tablet)
    
On the second connection and a 400ms delay this is the sequence:
    PM_EVT_BONDED_PEER_CONNECTED event ("Connected to a previously bonded device.")
    BLE_GAP_EVT_CONNECTED event (connection established)
    One delayed call to sec_req_timeout_handler() and pm_conn_secure()
    PM_EVT_CONN_SEC_SUCCEEDED event ("Link secured")
    Disconnect, reason 61. The Acer loses bonding info after about 20s.
    
    (On the Asus tablet at 400ms I get _two_ PM_EVT_CONN_SEC_SUCCEEDED events)
        
On the second connection and a 900ms delay this is the sequence:
    PM_EVT_BONDED_PEER_CONNECTED event ("Connected to a previously bonded device.")
    BLE_GAP_EVT_CONNECTED event (connection established)
    PM_EVT_CONN_SEC_SUCCEEDED event ("Link secured") - this must be because the Central requests it.
    Only then do I make the delayed call to pm_conn_secure()
    Sometimes an immediate disconnect, reason 61. The Acer loses bonding info after about 20s.
    Other times the Acer loses bonding information after about 20s and the the peripheral disconnects, reason 19
    
    (On the Asus tablet I get PM_EVT_CONN_SEC_SUCCEEDED, then the delayed call to pm_conn_secure(), then a second PM_EVT_CONN_SEC_SUCCEEDED)  
    
Perhaps: both Central and Peripheral attempt to establish encrypted communications (note the _two_ PM_EVT_CONN_SEC_SUCCEEDED
events seen with the Asus). Perhaps there is trouble in this case.

Bug fix: I set the delay to 900ms then added code to stop the delay timer on the PM_EVT_CONN_SEC_SUCCEEDED event.
This means the peripheral relies on the central to invoke encryption.
Tested with phone and both tablets.

With SDK 15.2 (Summary: works with a 100ms or 900ms security delay but not with 400ms. Bug fix found.)

The delayed call to pm_conn_secure() is moved to pm_handler_secure_on_connection() in components/ble/peer_manager/peer_manager_handler.c
It is defined by PM_HANDLER_SEC_DELAY_MS in sdk_config.h initially as 400ms

On the first connection (not bonded) this is the sequence:
    BLE_GAP_EVT_CONNECTED event (connection established)
    A delayed call to delayed_conn_secure() and pm_conn_secure()
    This triggers the passkey activity.
    PM_EVT_CONN_SEC_SUCCEEDED event ("Link secured")
    (Works OK: stays connected until the Central disconnects)

    On the second connection and a 100ms delay this is the sequence:
    PM_EVT_BONDED_PEER_CONNECTED event ("Connected to a previously bonded device.")
    BLE_GAP_EVT_CONNECTED event (connection established)
    I make the delayed call to pm_conn_secure()
    PM_EVT_CONN_SEC_SUCCEEDED event ("Link secured")
    (Works OK: stays connected until the Central disconnects)
    
    (Same on the Asus tablet)
            
    On the second connection and a 400ms delay this is the sequence:
    PM_EVT_BONDED_PEER_CONNECTED event ("Connected to a previously bonded device.")
    BLE_GAP_EVT_CONNECTED event (connection established)
    I make the delayed call to pm_conn_secure()
    PM_EVT_CONN_SEC_SUCCEEDED event ("Link secured")
    Disconnected, reason 61. The Acer loses bonding info after about 20s.
    
    (The Asus tablet has the same sequence except it receives _two_ PM_EVT_CONN_SEC_SUCCEEDED events, and works correctly).
    
    On the second connection and a 900ms delay this is the sequence:
    PM_EVT_BONDED_PEER_CONNECTED event ("Connected to a previously bonded device.")
    BLE_GAP_EVT_CONNECTED event (connection established)
    PM_EVT_CONN_SEC_SUCCEEDED event ("Link secured") - this must be because the Central requests it.
    Only then do I make the delayed call to pm_conn_secure()
    (Works OK: stays connected until the Central disconnects)
    
    (Same on the Asus tablet)  
    
Behaviour is similar to SDK12.3 (except it works with long and short security delays but not the default.)

Bug fix: I set the delay to 900ms then added code to stop the delay timer on the PM_EVT_CONN_SEC_SUCCEEDED event
in peer_manager_handler.c. This means the peripheral relies on the central to invoke encryption.

Tested with phone and both tablets. 

[Acutetech]

Hi Sigurd - do you have any comment on the results I report above? "the problem seems to be when both the Central and Peripheral try to initiate encryption. "

Or an answer to my question "Does Nordic have documentation on which device should initiate encryption, and when?"