Android asking for pairing after DFU

[Randy Lee]

Using SDK 15.3 on the embedded side and Android 10 I think it is on the mobile side.

We've implemented whitelists and hanging onto the bonding information on the embedded side.  The idea is that once the mobile side is talking to us we only want to talk to that particular device until we explicitly change to another one.

This works fine across power cycles on both sides.  Once paired and bonded and everything, the mobile side and embedded side exist in married bliss.

Now, pull up nRF connect and run a DFU on the embedded side. Once the embedded side comes back (and it is keeping all the bonding information and whitelists and all that across this as far as I can tell), Android wants to pair again...

I just don't understand why this is.  We've got the bonding information both sides as far as I know. Why does the Android side really want to pair again?  Am I missing something on the embedded side?

[Edvin]

Hello,

So it is after the update is complete, and you try to connect to it again like it was before (in the married bliss) that it wants to pair again, is that correct? 

Do you see whether the peripheral device has changed anything? Or did you try to debug the applciation? Is the bonding data still present on the peripheral? Does the peripheral use the same Bluetooth LE address as before the DFU update took place?

Best regards,

Edvin

[Randy Lee]

yes, after the DFU has completed. Everything should be the same as before the update as all that information is being saved as far as I know...  Power cycles of either side of that prior to DFU does not cause this repairing request so I'm pretty sure it's being saved.

Android itself is popping a "you want to pair?" message.

[Randy Lee]

iOS: my engineers are reporting that iOS does not have this problem..  

They did run into a services cache problem on that platform, but that's another problem (see https://developer.apple.com/forums/thread/76339)

[Edvin]

As it is mentioned in that ticket, you need to enable the SERVICE_CHANGED in sdk_config.h of your application. Ironically, adding it later wouldn't help, but if you add it in your initial application, that should solve that. So for the phones that have already cached the services, First forget the device from the iPhone's bluetooth menu, then turn off bluetooth from the phone's settings (Settings menu, not the "drag up from bottom menu"). Wait for about 15 seconds, and turn bluetooth back on. Then it should be forgotten. Then, if you have the service changed service enabled, then the peer manager will use this to tell the phone to do a new service discovery if it has new services.

Now, regarding our issue:

I need you to check the number of peers in the peer manager (using the snippets in my answer from 13th of june. 

Does this also happen if you use the "normal" bootloader and e.g. the ble_app_buttonless_dfu example to perform the update? Did you test this? If you test this with ble_app_buttonless_dfu, there is a setting in sdk_config.h called NRF_DFU_BLE_BUTTONLESS_SUPPORTS_BONDS. Leave this set to 0, because this does a couple of things. Then try to open ble_dfu_unbonded.c, and set:

    add_char_params.cccd_write_access = SEC_JUST_WORKS;
    add_char_params.write_access      = SEC_JUST_WORKS;
    add_char_params.read_access       = SEC_OPEN;

in ble_dfu_buttonless_char_add(). That should trigger the pairing/bonding in the app, and then you can perform a DFU and try to connect again. Does that trigger the issue where you need to bond again?

NB: This example already have the NRF_SDH_BLE_SERVICE_CHANGED set to 1.

Best regards,

Edvin

[Randy Lee]

Our app uses the Nordic buttonless bootloader as the base for the bootloader portion and is called by the application to get it started..

The version we're running has those parameters set:

    add_char_params.cccd_write_access = SEC_OPEN;
    add_char_params.write_access      = SEC_OPEN;
    add_char_params.read_access       = SEC_OPEN;

since we can't get there but by a bonded thing that is explicitly whitelisted.

I'm still attempting to get the number of peers seen.  For some interesting reason that particular piece of code is being an issue in situ.  It gives me an output using SES directly but not if I'm using RTT viewer. Curiously all the stuff around it gives me output so I'm having some experiments done to figure out just why that it... I hope to have some usable data early next week.

[Randy Lee]

so we got that code to work... I've annotated the output from that code with "bounds: " so as to note it specifically from the other things that are logging... You'll find it towards the back.  This output here is right after the thing is booting after a DFU:

00> [1634810895.013] POR Vbat: (2.41V)
00> <debug> nrf_sdh_freertos: Creating a SoftDevice task.
00> <debug> ble_scan: Adding filter on RWStudentID name
00> <debug> nrf_sdh_freertos: Enter softdevice_task.
00> [1634810895.253] FDS: File found
00> [1634810895.253] FDS: File read successfully
00> [1634810895.253] Whitelist: Whitelist file found. peer_id=0
00> [1634810895.255] FDS: File found. Writing data into it
00> [1634810895.255] FDS: Write succeeded.
00> [1634810895.260] Baby service: Version=0.8.4.9, Family=91, ProgramChecksum=87778671
00> [1634810895.263] BLE: bounds: peer_count: 2
00> [1634810895.263] BLE: bounds: peer id 0 is valid
00> [1634810895.263] BLE: bounds: peer address: f0:5c:77:f5:2f:63
00> [1634810895.263] BLE: bounds: peer id 1 is valid
00> [1634810895.263] BLE: bounds: peer address: 94:be:46:11:e2:5b
00> [1634810895.265] FDS: File found
00> [1634810895.265] FDS: File read successfully
00> [1634810895.265] BLE: Whitelist contains a peer. Start advertising.
00> [1634810895.265] Whitelist: Applied whitelist with addr_cnt=1 irk_cnt=1

The first one (peer ID 0) is the current MAC address of the device talking to it.. I don't know what the second one is, but it's possible it's the same device as Android phones can apparently change MAC addresses from time to time (this one is a Pixel 4 running Android 11

[Edvin]

Randy Lee said:

I don't know what the second one is, but it's possible it's the same device as Android phones can apparently change MAC addresses from time to time

Yes they do, but they shouldn't take up more than one peer. There are mechanisms to recognize peers that have changed addresses using an IRK (Identity resolving key).

When you connect to the bonded device after the DFU is performed, do you get the event (on the nRF) PM_EVT_BONDED_PEER_CONNECTED?

BR,

Edvin

[Randy Lee]

Yes, I get that... interestingly enough a couple of times...

00> [1634809769.258] Baby service: Version=0.8.4.10, Family=91, ProgramChecksum=05107740
00> [1634809769.261] BLE: bounds: peer_count: 1
00> [1634809769.261] BLE: bounds: peer id 0 is valid
00> [1634809769.261] BLE: bounds: peer address: f0:5c:77:f5:2f:63
00> [1634809769.262] FDS: File found
00> [1634809769.262] FDS: File read successfully
00> [1634809769.262] BLE: Whitelist contains a peer. Start advertising.
00> [1634809769.262] Whitelist: Applied whitelist with addr_cnt=1 irk_cnt=1
00> [1634809200.272] SIM Restart
00> [1634809200.274] temperature: 26.0C
00> [1634809200.275] Vbat: 100% (2.52V)
00> [1634809200.290] LOG: 242,9,0x00,0x00
00> [1634809200.345] Motion set: a=-0.158072, A[xyz]=0.005859,-0.115234,-0.833984
00> [1634809200.516] Switched from event 0 to event 11
00> [1634809200.536] LOG: 11,9,0x00,0x00
00> [1634809201.766] BLE: Unhandled PeerManager event 5 (PM_EVT_CONN_SEC_PARAMS_REQ?)
00> [1634809201.766] BLE: Unhandled PeerManager event 8 (PM_EVT_PEER_DATA_UPDATE_SUCCEEDED)
00> [1634809201.766] BLE: Bonded Peer Connected (PM_EVT_PEER_DATA_UPDATE_SUCCEEDED)
00> [1634809201.767] BLE: Unhandled PeerManager event 14 (PM_EVT_LOCAL_DB_CACHE_APPLIED)
00> <debug> nrf_ble_gatt: Requesting to update ATT MTU to 247 bytes on connection 0x0.
00> [1634809201.768] BLE: Peer connected (PM_EVT_BONDED_PEER_CONNECTED)
00> <debug> nrf_ble_gatt: Peer on connection 0x0 requested a data length of 27 bytes.
00> <debug> nrf_ble_gatt: Updating data length to 27 on connection 0x0.
00> <debug> nrf_ble_gatt: ATT MTU updated to 247 bytes on connection 0x0 (response).
00> [1634809201.951] BLE: Data len is set to 0xF4(244)
00> <debug> nrf_ble_gatt: Data length updated to 251 on connection 0x0.
00> <debug> nrf_ble_gatt: max_rx_octets: 27
00> <debug> nrf_ble_gatt: max_tx_octets: 251
00> <debug> nrf_ble_gatt: max_rx_time: 328
00> <debug> nrf_ble_gatt: max_tx_time: 2120
00> <debug> nrf_ble_gatt: Peer on connection 0x0 requested a data length of 251 bytes.
00> <debug> nrf_ble_gatt: Updating data length to 27 on connection 0x0.
00> <debug> nrf_ble_gatt: Data length updated to 251 on connection 0x0.
00> <debug> nrf_ble_gatt: max_rx_octets: 251
00> <debug> nrf_ble_gatt: max_tx_octets: 251
00> <debug> nrf_ble_gatt: max_rx_time: 2120
00> <debug> nrf_ble_gatt: max_tx_time: 2120
00> <debug> nrf_ble_gatt: Peer on connection 0x0 requested a data length of 251 bytes.
00> <debug> nrf_ble_gatt: Updating data length to 27 on connection 0x0.
00> <debug> nrf_ble_gatt: Data length updated to 251 on connection 0x0.
00> <debug> nrf_ble_gatt: max_rx_octets: 251
00> <debug> nrf_ble_gatt: max_tx_octets: 251
00> <debug> nrf_ble_gatt: max_rx_time: 2120
00> <debug> nrf_ble_gatt: max_tx_time: 2120
00> [1634809204.405] BLE: Unhandled PeerManager event 1 (PM_EVT_CONN_SEC_START)
00> [1634809204.409] BLE: Unhandled PeerManager event 5 (PM_EVT_CONN_SEC_PARAMS_REQ)
00> [1634809204.410] FDS: File found
00> [1634809204.410] FDS: File read successfully
00> [1634809204.410] Whitelist: check Whitelist file found. peer_id=0
00> [1634809204.410] BLE: Allow repairing: 1
00> <info> peer_manager_handler: Connection secured: role: Peripheral, conn_handle: 0, procedure: Bonding
00> [1634809206.511] BLE: Unhandled PeerManager event 8 (PM_EVT_PEER_DATA_UPDATE_SUCCEEDED)
00> [1634809206.511] BLE: Unhandled PeerManager event 2 (PM_EVT_CONN_SEC_SUCCEEDED)
00> [1634809206.515] BLE: Unhandled PeerManager event 8 (PM_EVT_PEER_DATA_UPDATE_SUCCEEDED)
00> [1634809206.519] BLE: Unhandled PeerManager event 8 (PM_EVT_PEER_DATA_UPDATE_SUCCEEDED)
00> <debug> nrf_ble_gatt: Peer on connection 0x0 requested a data length of 251 bytes.
00> <debug> nrf_ble_gatt: Updating data length to 27 on connection 0x0.
00> <debug> nrf_ble_gatt: Data length updated to 251 on connection 0x0.
00> <debug> nrf_ble_gatt: max_rx_octets: 251
00> <debug> nrf_ble_gatt: max_tx_octets: 251
00> <debug> nrf_ble_gatt: max_rx_time: 2120
00> <debug> nrf_ble_gatt: max_tx_time: 2120
00> [1634809207.347] BLE: Unhandled PeerManager event 8
00> [1634809211.634] Play Sound 13, 0xD
00> [1634809216.951] Whitelist: Applied whitelist with addr_cnt=1 irk_cnt=1
00> [1634809216.952] BLE: Peer disconnected

[Edvin]

I assume that since the log says "Allow repairing: 1", that the phone requests to pair again, as if it has lost the bonding information. Exactly why the phone decides to do that, I am not sure.

1: Did you test this with different android phones? If not, can you please do? 

2: Is there some way for me to reproduce this? Did you try to reproduce it using the ble_app_buttonless_dfu example? If so, can you zip that modified ble_app_buttonless_dfu example so that I can try to reproduce the issue, preferably without doing too many changes to the rest of the SDK?

I am sorry for the long response time. We are a bit understaffed during the summer holidays. Sorry for the inconvenience.

Best regards,

Edvin

[Randy Lee]

The "Allow repairing" thing is a code note to myself meaning, in this case, that we've got something in the whitelist and to allow that MAC address to talk to me.  The app is very locked down here using whitelists to not allow anyone to connect to it unless it's gone through some serious upper level handshakes.  This notation just says that, yes, the whitelists survived the update.  Those whitelists use fds so that are hasn't been wiped (this was a previous bug that we had in the code)

1) Yes, we're using a couple of different ones. One team tends to use a Pixel and most of the other teams tend to use a Lenovo tablet.  Different versions of Android.

2) The bootstrap here is effectively the buttonless dfu using SDK15.3 (with a couple of mods backporting some SDK17 fixes). 5707.bootloader.zip

[Randy Lee]

Oh, and, I understand the time thing in the summer.... Thank you for being able to keep following this thing...

[Edvin]

Hello,

Ok. I am back (and will stay for a while this time).

Can you please try to capture a sniffer trace of the connection being entered. Preferably one after a DFU, and one with a normal connection (where the bonding is not requested). Please note that in order for the sniffer to be able to follow into a bonded connection, you probably need to erase the bonds, connect -> bond -> disconnect -> reconnect for the sniffer to be able to capture the LTK. If you are using OOB (6-digit passkey), you need to enter this manually in the sniffer.

To capture a sniffer trace, you can use the nRF Sniffer for Bluetooth LE.

And again, if there is some way for me to reproduce this, please zip a project application that can reproduce the issue. You say that it is a slightly modified ble_app_buttonless_dfu application, but please zip the one that is used for reproducing the issue. I also see that you are mixing a few different SDK versions. Can you please try to stick to one, and see if it is still reproducible, just to make sure that it is not the backport that is causing something to behave weirdly?

Best regards,

Edvin