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]

This is full custom hardware; I rarely use a dev kit from anyone as they are so limiting to what I do. Reproducing it on the DK would be difficult as there is so much code there that assumes custom hardware.  Also we've seen this over 5 or 6 products all with the same basic code base.

As to Android version, We've seen it on 10 and 11 (these logs were produced with an 11 connection). Never tried it on iOS as we don't have the app we use with it on iOS and it's rather difficult to get the connection to begin with without the app.  We can try it at some point here tho as that would be something instructive I think.

Line 52 is saying that, when it comes back from POR, that there whitelist is still intact in flash storage.  That implies to me that any bonding information kept in the same basic storage place would be still intact.  I will have to verify that with your code suggestion the next time I get a chance.

Line 54 has what I assume is step 3 pairing requests and whatnot coming through. Ignore anything labeled "RFID:"  It's about 5 seconds later (line around 188) where we see the bonding completion....

The upshot is that these logs aren't as informative as they could possibly be.  I don't have an air sniffer at present to see the traffic here, which would be far more informative, and for that I apologize.

[Edvin]

I understand. 

Well, sometimes a custom log can give some insight in whats going on, but it is not always conclusive. 

For the iOS part, if you are using the standard bootloader from the nRF5 SDK (without too much modifications), you should be able to use the nRF Connect for iOS app to perform the update, and then try to connect to it afterwards, to see if it also requires to re-bond. This is just for debugging purposes, to see whether this issue is limited to Android, or on all platforms. Perhaps it can narrow down possible reasons for this behavior.

Best regards,

Edvin

[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