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]

Bootloader has that set to default size of 12288

application has

#define FDS_VIRTUAL_PAGES 3

#define FDS_VIRTUAL_PAGE_SIZE 1024

[Edvin]

Ok. Then you need to start investigating the other things that I have mentioned:

Edvin said:

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?

Edvin said:

You can also make your application to tell you how many peers that are stored in the beginning of your application, to verify that it is in fact the nRF that has lost the bonding data. What does it say?

And also, what does the log from your application say? Please copy paste the log from before you DFU, i.e. when you don't have to pair again and when you do have to pair again. Do they look the same?

Does this only happen on Android? Did you try with iOS?

BR,

Edvin

[Randy Lee]

Edvin said:

And also, what does the log from your application say?

Attached is the log from nRFconnect on Android.  This has a complicated connection scheme so I have not attempted this on iOS to see if there is a difference in it.

1. Once the device is paired and bonded through our application, close the application and then connect back up with nRFconnect (this bypasses all the oddities of our application
2. Then put the device into DFU mode via struct command 0x0000000007 in nRF Connect (line 53). This causes the device to change to bootloader mode.  In this mode, we aren't using the whitelists and such...
3. run DFU
4. Allow reconnect of nRFconnect when done (line 985- ~994)
5. Android asks pairing again (starting at line 995 or so)...

I'll be looking at the embedded side to answer some questions a bit later (this is going to take awhile to do here so you'll have to bear with me please)

Thank you for your help so far in this.

Log 6.txt

[Edvin]

Hello,

Edvin said:

And also, what does the log from your application say? Please copy paste the log from before you DFU, i.e. when you don't have to pair again and when you do have to pair again. Do they look the same?

I was actually thinking of the log from the nRF chip, if you have any.

I see from the log 6.txt that it receives a pairing request. The address of the nRF chip is the same before and after the DFU (I 13:14:35.703 Connected to DF:A0:E4:ED:42:5C), so that should not be the issue. Perhaps the the nRF doesn't have the bonding data after the DFU process.

Please check that delete_bonds() is not called after the DFU. Try setting a breakpoint or add some logging in the delete_bonds() function to see whether this is triggered.

Also, you can add this before you start advertising:

static void check_bonds(void)
{
    ret_code_t err_code;
    uint32_t peer_count;
    pm_peer_id_t peer_id = PM_PEER_ID_INVALID;
    pm_peer_data_bonding_t peer_data;
    
    peer_count = pm_peer_count();
    NRF_LOG_INFO("peer_count: %d", peer_count);
    
    peer_id = pm_next_peer_id_get(PM_PEER_ID_INVALID);
    if (peer_id != PM_PEER_ID_INVALID)
    {
        while (peer_id != PM_PEER_ID_INVALID)
        {
            NRF_LOG_INFO("peer id %d is valid", peer_id);
            err_code = pm_peer_data_bonding_load(peer_id, &peer_data);
            APP_ERROR_CHECK(err_code);
            NRF_LOG_INFO("peer address: %02x:%02x:%02x:%02x:%02x:%02x", peer_data.peer_ble_id.id_addr_info.addr[5],
                                                                        peer_data.peer_ble_id.id_addr_info.addr[4],
                                                                        peer_data.peer_ble_id.id_addr_info.addr[3],
                                                                        peer_data.peer_ble_id.id_addr_info.addr[2],
                                                                        peer_data.peer_ble_id.id_addr_info.addr[1],
                                                                        peer_data.peer_ble_id.id_addr_info.addr[0]);
            
            peer_id = pm_next_peer_id_get(peer_id);
        }
    }
    else 
    {
        NRF_LOG_INFO("no valid peers");
    }
}

It will print the address of all the peers that are bonded with the nRF. Add it right before you start advertising.

BR,
Edvin

[Randy Lee]

One of my other engineers managed to grab the following logs (before I had time to get your suggested code in them) which might shed some light on things.  On the Baby Logs, you can ignore the RFID: lines as those are the application itself and have nothing to do with BLE..

Fullscreen baby logs.txt Download

00> [1655195676.403] Play Sound 102
00> [1655195677.904] Play Sound 102
00> [1655195679.404] BLE: Entering promiscuous mode
00> [1655195679.404] Whitelist: Applied whitelist with addr_cnt=0 irk_cnt=0
00> <debug> nrf_ble_gatt: Requesting to update ATT MTU to 247 bytes on connection 0x0.
00> [1655195696.006] BLE: 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> [1655195697.196] 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> <info> peer_manager_handler: Connection secured: role: Peripheral, conn_handle: 0, procedure: Encryption
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> [1655195706.684] Whitelist: Setting whitelist from current connection ...
00> [1655195706.686] Whitelist: File found. Writing data into it
00> [1655195706.686] Whitelist: Write succeeded.
00> [1655195706.687] Whitelist: Setting whitelist from current connection done
00> [1655195706.687] BLE: Whitelist for connected peer set successfully
00> [1655195706.687] BLE: Exiting promiscuous mode
00> [1655195708.928] Vbat: 100% (2.44V)
00> [1655195720.389] Reboot into bootloader in 1 sec...
00> [1655195721.013] POR Vbat: (2.44V)
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> [1655195721.263] Whitelist: File found
00> [1655195721.263] Whitelist: File read successfully
00> [1655195721.263] Whitelist: Whitelist file found. peer_id=1
00> [1655195721.265] Whitelist: File found. Writing data into it
00> [1655195721.265] Whitelist: Write succeeded.
00> [1655195721.270] Baby service: Version=0.8.4.6, Family=91, ProgramChecksum=D6DBF55D
00> [1655195721.273] Whitelist: File found
00> [1655195721.273] Whitelist: File read successfully
00> [1655195721.273] BLE: Whitelist contains a peer. Start advertising.
00> [1655195721.273] Whitelist: Applied whitelist with addr_cnt=1 irk_cnt=1
00> [1634809200.285] POR
00> <debug> nrf_ble_gatt: Requesting to update ATT MTU to 247 bytes on connection 0x0.
00> [1634809200.287] BLE: Peer connected
00> [1634809200.289] temperature: 26.0C
00> [1634809200.289] Vbat: 100% (2.43V)
00> [1634809200.307] LOG: 242,9,0x00,0x00
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> [1634809200.434] RFID: tagPWD 804C27B1 timeout
00> [1634809200.434] RFID: tag 6 data = 0x00000000
00> <debug> nrf_ble_gatt: ATT MTU updated to 247 bytes on connection 0x0 (response).
00> [1634809200.477] 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> [1634809200.521] RFID: tagPWD 804C27B1 timeout
00> [1634809200.521] RFID: tag 6 data = 0x00000000
00> [1634809200.531] Switched from event 0 to event 11
00> [1634809200.551] LOG: 11,9,0x00,0x00
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> [1634809200.716] RFID: tagPWD 804C27B1 timeout
00> [1634809200.716] RFID: tag 6 data = 0x00000000
00> [1634809200.803] RFID: tagPWD 804C27B1 timeout
00> [1634809200.803] RFID: tag 6 data = 0x00000000
00> [1634809200.940] RFID: tagPWD 804C27B1 timeout
00> [1634809200.940] RFID: tag 6 data = 0x00000000
00> [1634809201.027] RFID: tagPWD 804C27B1 timeout
00> [1634809201.027] RFID: tag 6 data = 0x00000000
00> [1634809201.165] RFID: tagPWD 804C27B1 timeout
00> [1634809201.165] RFID: tag 6 data = 0x00000000
00> [1634809201.252] RFID: tagPWD 804C27B1 timeout
00> [1634809201.252] RFID: tag 6 data = 0x00000000
00> [1634809201.389] RFID: tagPWD 804C27B1 timeout
00> [1634809201.389] RFID: tag 6 data = 0x00000000
00> [1634809201.476] RFID: tagPWD 804C27B1 timeout
00> [1634809201.476] RFID: tag 6 data = 0x00000000
00> [1634809201.613] RFID: tagPWD 804C27B1 timeout
00> [1634809201.613] RFID: tag 6 data = 0x00000000
00> [1634809201.700] RFID: tagPWD 804C27B1 timeout
00> [1634809201.700] RFID: tag 6 data = 0x00000000
00> [1634809201.837] RFID: tagPWD 804C27B1 timeout
00> [1634809201.837] RFID: tag 6 data = 0x00000000
00> [1634809201.924] RFID: tagPWD 804C27B1 timeout
00> [1634809201.924] RFID: tag 6 data = 0x00000000
00> [1634809202.061] RFID: tagPWD 804C27B1 timeout
00> [1634809202.061] RFID: tag 6 data = 0x00000000
00> [1634809202.148] RFID: tagPWD 804C27B1 timeout
00> [1634809202.148] RFID: tag 6 data = 0x00000000
00> [1634809202.286] RFID: tagPWD 804C27B1 timeout
00> [1634809202.286] RFID: tag 6 data = 0x00000000
00> [1634809202.373] RFID: tagPWD 804C27B1 timeout
00> [1634809202.373] RFID: tag 6 data = 0x00000000
00> [1634809202.510] RFID: tagPWD 804C27B1 timeout
00> [1634809202.510] RFID: tag 6 data = 0x00000000
00> [1634809202.597] RFID: tagPWD 804C27B1 timeout
00> [1634809202.597] RFID: tag 6 data = 0x00000000
00> [1634809202.734] RFID: tagPWD 804C27B1 timeout
00> [1634809202.734] RFID: tag 6 data = 0x00000000
00> [1634809202.821] RFID: tagPWD 804C27B1 timeout
00> [1634809202.821] RFID: tag 6 data = 0x00000000
00> [1634809202.958] RFID: tagPWD 804C27B1 timeout
00> [1634809202.958] RFID: tag 6 data = 0x00000000
00> [1634809203.045] RFID: tagPWD 804C27B1 timeout
00> [1634809203.045] RFID: tag 6 data = 0x00000000
00> [1634809203.182] RFID: tagPWD 804C27B1 timeout
00> [1634809203.182] RFID: tag 6 data = 0x00000000
00> [1634809203.269] RFID: tagPWD 804C27B1 timeout
00> [1634809203.269] RFID: tag 6 data = 0x00000000
00> [1634809203.406] RFID: tagPWD 804C27B1 timeout
00> [1634809203.406] RFID: tag 6 data = 0x00000000
00> [1634809203.493] RFID: tagPWD 804C27B1 timeout
00> [1634809203.493] RFID: tag 6 data = 0x00000000
00> [1634809203.630] RFID: tagPWD 804C27B1 timeout
00> [1634809203.630] RFID: tag 6 data = 0x00000000
00> [1634809203.717] RFID: tagPWD 804C27B1 timeout
00> [1634809203.717] RFID: tag 6 data = 0x00000000
00> [1634809203.854] RFID: tagPWD 804C27B1 timeout
00> [1634809203.854] RFID: tag 6 data = 0x00000000
00> [1634809203.941] RFID: tagPWD 804C27B1 timeout
00> [1634809203.941] RFID: tag 6 data = 0x00000000
00> [1634809204.078] RFID: tagPWD 804C27B1 timeout
00> [1634809204.078] RFID: tag 6 data = 0x00000000
00> [1634809204.165] RFID: tagPWD 804C27B1 timeout
00> [1634809204.165] RFID: tag 6 data = 0x00000000
00> [1634809204.186] BLE: Allow repairing: 0
00> [1634809204.187] Whitelist: File found
00> [1634809204.187] Whitelist: File read successfully
00> [1634809204.187] Whitelist: check Whitelist file found. peer_id=1
00> [1634809204.302] RFID: tagPWD 804C27B1 timeout
00> [1634809204.302] RFID: tag 6 data = 0x00000000
00> [1634809204.389] RFID: tagPWD 804C27B1 timeout
00> [1634809204.389] RFID: tag 6 data = 0x00000000
00> [1634809204.526] RFID: tagPWD 804C27B1 timeout
00> [1634809204.526] RFID: tag 6 data = 0x00000000
00> [1634809204.613] RFID: tagPWD 804C27B1 timeout
00> [1634809204.613] RFID: tag 6 data = 0x00000000
00> [1634809204.750] RFID: tagPWD 804C27B1 timeout
00> [1634809204.750] RFID: tag 6 data = 0x00000000
00> [1634809204.837] RFID: tagPWD 804C27B1 timeout
00> [1634809204.837] RFID: tag 6 data = 0x00000000
00> [1634809204.975] RFID: tagPWD 804C27B1 timeout
00> [1634809204.975] RFID: tag 6 data = 0x00000000
00> [1634809205.062] RFID: tagPWD 804C27B1 timeout
00> [1634809205.062] RFID: tag 6 data = 0x00000000
00> [1634809205.199] RFID: tagPWD 804C27B1 timeout
00> [1634809205.199] RFID: tag 6 data = 0x00000000
00> [1634809205.287] RFID: tagPWD 804C27B1 timeout
00> [1634809205.287] RFID: tag 6 data = 0x00000000
00> [1634809205.424] RFID: tagPWD 804C27B1 timeout
00> [1634809205.424] RFID: tag 6 data = 0x00000000
00> [1634809205.511] RFID: tagPWD 804C27B1 timeout
00> [1634809205.511] RFID: tag 6 data = 0x00000000
00> [1634809205.648] RFID: tagPWD 804C27B1 timeout
00> [1634809205.648] RFID: tag 6 data = 0x00000000
00> [1634809205.736] RFID: tagPWD 804C27B1 timeout
00> [1634809205.736] RFID: tag 6 data = 0x00000000
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> [1634809205.873] RFID: tagPWD 804C27B1 timeout
00> [1634809205.873] RFID: tag 6 data = 0x00000000
00> [1634809205.960] RFID: tagPWD 804C27B1 timeout
00> [1634809205.960] RFID: tag 6 data = 0x00000000
00> <info> peer_manager_handler: Connection secured: role: Peripheral, conn_handle: 0, procedure: Bonding
00> [1634809206.097] RFID: tagPWD 804C27B1 timeout
00> [1634809206.097] RFID: tag 6 data = 0x00000000
00> [1634809206.185] RFID: tagPWD 804C27B1 timeout
00> [1634809206.185] RFID: tag 6 data = 0x00000000
00> [1634809206.322] RFID: tagPWD 804C27B1 timeout
00> [1634809206.322] RFID: tag 6 data = 0x00000000
00> [1634809206.409] RFID: tagPWD 804C27B1 timeout
00> [1634809206.409] RFID: tag 6 data = 0x00000000
00> [1634809206.546] RFID: tagPWD 804C27B1 timeout
00> [1634809206.546] RFID: tag 6 data = 0x00000000
00> [1634809206.633] RFID: tagPWD 804C27B1 timeout
00> [1634809206.633] RFID: tag 6 data = 0x00000000
00> [1634809206.771] RFID: tagPWD 804C27B1 timeout
00> [1634809206.771] RFID: tag 6 data = 0x00000000
00> [1634809206.859] RFID: tagPWD 804C27B1 timeout
00> [1634809206.859] RFID: tag 6 data = 0x00000000
00> [1634809206.996] RFID: tagPWD 804C27B1 timeout
00> [1634809206.996] RFID: tag 6 data = 0x00000000
00> [1634809207.083] RFID: tagPWD 804C27B1 timeout
00> [1634809207.083] RFID: tag 6 data = 0x00000000
00> [1634809207.220] RFID: tagPWD 804C27B1 timeout
00> [1634809207.220] RFID: tag 6 data = 0x00000000
00> [1634809207.307] RFID: tagPWD 804C27B1 timeout
00> [1634809207.307] RFID: tag 6 data = 0x00000000
00> [1634809207.444] RFID: tagPWD 804C27B1 timeout
00> [1634809207.444] RFID: tag 6 data = 0x00000000
00> [1634809207.531] RFID: tagPWD 804C27B1 timeout
00> [1634809207.531] RFID: tag 6 data = 0x00000000
00> [1634809207.668] RFID: tagPWD 804C27B1 timeout
00> [1634809207.668] RFID: tag 6 data = 0x00000000
00> [1634809207.755] RFID: tagPWD 804C27B1 timeout
00> [1634809207.755] RFID: tag 6 data = 0x00000000
00> [1634809207.892] RFID: tagPWD 804C27B1 timeout
00> [1634809207.892] RFID: tag 6 data = 0x00000000
00> [1634809207.979] RFID: tagPWD 804C27B1 timeout
00> [1634809207.979] RFID: tag 6 data = 0x00000000
00> [1634809208.116] RFID: tagPWD 804C27B1 timeout
00> [1634809208.116] RFID: tag 6 data = 0x00000000
00> [1634809208.203] RFID: tagPWD 804C27B1 timeout
00> [1634809208.203] RFID: tag 6 data = 0x00000000
00> [1634809208.340] RFID: tagPWD 804C27B1 timeout
00> [1634809208.340] RFID: tag 6 data = 0x00000000
00> [1634809208.427] RFID: tagPWD 804C27B1 timeout
00> [1634809208.427] RFID: tag 6 data = 0x00000000
00> [1634809208.565] RFID: tagPWD 804C27B1 timeout
00> [1634809208.565] RFID: tag 6 data = 0x00000000
00> [1634809208.652] RFID: tagPWD 804C27B1 timeout
00> [1634809208.652] RFID: tag 6 data = 0x00000000
00> [1634809208.789] RFID: tagPWD 804C27B1 timeout
00> [1634809208.789] RFID: tag 6 data = 0x00000000
00> [1634809208.876] RFID: tagPWD 804C27B1 timeout
00> [1634809208.876] RFID: tag 6 data = 0x00000000
00> [1634809209.013] RFID: tagPWD 804C27B1 timeout
00> [1634809209.013] RFID: tag 6 data = 0x00000000
00> [1634809209.100] RFID: tagPWD 804C27B1 timeout
00> [1634809209.100] RFID: tag 6 data = 0x00000000
00> [1634809209.237] RFID: tagPWD 804C27B1 timeout
00> [1634809209.237] RFID: tag 6 data = 0x00000000
00> [1634809209.324] RFID: tagPWD 804C27B1 timeout
00> [1634809209.324] RFID: tag 6 data = 0x00000000
00> [1634809209.461] RFID: tagPWD 804C27B1 timeout
00> [1634809209.461] RFID: tag 6 data = 0x00000000
00> [1634809209.548] RFID: tagPWD 804C27B1 timeout
00> [1634809209.548] RFID: tag 6 data = 0x00000000
00> [1634809209.686] RFID: tagPWD 804C27B1 timeout
00> [1634809209.686] RFID: tag 6 data = 0x00000000
00> [1634809209.775] RFID: tagPWD 804C27B1 timeout
00> [1634809209.775] RFID: tag 6 data = 0x00000000
00> [1634809209.912] RFID: tagPWD 804C27B1 timeout
00> [1634809209.912] RFID: tag 6 data = 0x00000000
00> [1634809209.999] RFID: tagPWD 804C27B1 timeout
00> [1634809209.999] RFID: tag 6 data = 0x00000000
00> [1634809210.136] RFID: tagPWD 804C27B1 timeout
00> [1634809210.136] RFID: tag 6 data = 0x00000000
00> [1634809210.223] RFID: tagPWD 804C27B1 timeout
00> [1634809210.223] RFID: tag 6 data = 0x00000000
00> [1634809210.360] RFID: tagPWD 804C27B1 timeout
00> [1634809210.360] RFID: tag 6 data = 0x00000000
00> [1634809210.448] RFID: tagPWD 804C27B1 timeout
00> [1634809210.448] RFID: tag 6 data = 0x00000000
00> [1634809210.585] RFID: tagPWD 804C27B1 timeout
00> [1634809210.585] RFID: tag 6 data = 0x00000000
00> [1634809210.672] RFID: tagPWD 804C27B1 timeout
00> [1634809210.672] RFID: tag 6 data = 0x00000000
00> [1634809210.810] RFID: tagPWD 804C27B1 timeout
00> [1634809210.810] RFID: tag 6 data = 0x00000000
00> [1634809210.898] RFID: tagPWD 804C27B1 timeout
00> [1634809210.898] RFID: tag 6 data = 0x00000000
00> [1634809211.035] RFID: tagPWD 804C27B1 timeout
00> [1634809211.035] RFID: tag 6 data = 0x00000000
00> [1634809211.123] RFID: tagPWD 804C27B1 timeout
00> [1634809211.123] RFID: tag 6 data = 0x00000000
00> [1634809211.260] RFID: tagPWD 804C27B1 timeout
00> [1634809211.260] RFID: tag 6 data = 0x00000000
00> [1634809211.347] RFID: tagPWD 804C27B1 timeout
00> [1634809211.347] RFID: tag 6 data = 0x00000000
00> [1634809211.484] RFID: tagPWD 804C27B1 timeout
00> [1634809211.484] RFID: tag 6 data = 0x00000000
00> [1634809211.571] RFID: tagPWD 804C27B1 timeout
00> [1634809211.571] RFID: tag 6 data = 0x00000000
00> [1634809211.709] RFID: tagPWD 804C27B1 timeout
00> [1634809211.709] RFID: tag 6 data = 0x00000000
00> [1634809211.796] RFID: tagPWD 804C27B1 timeout
00> [1634809211.796] RFID: tag 6 data = 0x00000000
00> [1634809211.933] RFID: tagPWD 804C27B1 timeout
00> [1634809211.933] RFID: tag 6 data = 0x00000000
00> [1634809212.020] RFID: tagPWD 804C27B1 timeout
00> [1634809212.020] RFID: tag 6 data = 0x00000000
00> [1634809212.158] RFID: tagPWD 804C27B1 timeout
00> [1634809212.158] RFID: tag 6 data = 0x00000000
00> [1634809212.245] RFID: tagPWD 804C27B1 timeout
00> [1634809212.245] RFID: tag 6 data = 0x00000000
00> [1634809212.382] RFID: tagPWD 804C27B1 timeout
00> [1634809212.382] RFID: tag 6 data = 0x00000000
00> [1634809212.469] RFID: tagPWD 804C27B1 timeout
00> [1634809212.469] RFID: tag 6 data = 0x00000000
00> [1634809212.606] RFID: tagPWD 804C27B1 timeout
00> [1634809212.606] RFID: tag 6 data = 0x00000000
00> [1634809212.693] RFID: tagPWD 804C27B1 timeout
00> [1634809212.693] RFID: tag 6 data = 0x00000000
00> [1634809212.830] RFID: tagPWD 804C27B1 timeout
00> [1634809212.830] RFID: tag 6 data = 0x00000000
00> [1634809212.917] RFID: tagPWD 804C27B1 timeout
00> [1634809212.917] RFID: tag 6 data = 0x00000000
00> [1634809213.054] RFID: tagPWD 804C27B1 timeout
00> [1634809213.054] RFID: tag 6 data = 0x00000000
00> [1634809213.141] RFID: tagPWD 804C27B1 timeout
00> [1634809213.141] RFID: tag 6 data = 0x00000000
00> [1634809213.278] RFID: tagPWD 804C27B1 timeout
00> [1634809213.278] RFID: tag 6 data = 0x00000000
00> [1634809213.365] RFID: tagPWD 804C27B1 timeout
00> [1634809213.365] RFID: tag 6 data = 0x00000000
00> [1634809213.502] RFID: tagPWD 804C27B1 timeout
00> [1634809213.502] RFID: tag 6 data = 0x00000000
00> [1634809213.589] RFID: tagPWD 804C27B1 timeout
00> [1634809213.589] RFID: tag 6 data = 0x00000000
00> [1634809213.643] Whitelist: Applied whitelist with addr_cnt=1 irk_cnt=1
00> [1634809213.646] BLE: Peer disconnected
00> [1634809213.726] RFID: tagPWD 804C27B1 timeout
00> [1634809213.726] RFID: tag 6 data = 0x00000000
00> [1634809213.813] RFID: tagPWD 804C27B1 timeout
00> [1634809213.813] RFID: tag 6 data = 0x00000000
00> [1634809213.950] RFID: tagPWD 804C27B1 timeout
00> [1634809213.950] RFID: tag 6 data = 0x00000000
00> [1634809214.037] RFID: tagPWD 804C27B1 timeout
00> [1634809214.037] RFID: tag 6 data = 0x00000000
00> [1634809214.174] RFID: tagPWD 804C27B1 timeout
00> [1634809214.174] RFID: tag 6 data = 0x00000000
00> [1634809214.261] RFID: tagPWD 804C27B1 timeout
00> [1634809214.261] RFID: tag 6 data = 0x00000000
00> [1634809214.400] RFID: tagPWD 804C27B1 timeout
00> [1634809214.400] RFID: tag 6 data = 0x00000000
00> [1634809214.487] RFID: tagPWD 804C27B1 timeout
00> [1634809214.487] RFID: tag 6 data = 0x00000000
00> [1634809214.624] RFID: tagPWD 804C27B1 timeout
00> [1634809214.624] RFID: tag 6 data = 0x00000000
00> [1634809214.711] RFID: tagPWD 804C27B1 timeout
00> [1634809214.711] RFID: tag 6 data = 0x00000000
00> [1634809214.848] RFID: tagPWD 804C27B1 timeout
00> [1634809214.848] RFID: tag 6 data = 0x00000000
00> [1634809214.935] RFID: tagPWD 804C27B1 timeout
00> [1634809214.935] RFID: tag 6 data = 0x00000000
00> [1634809215.073] RFID: tagPWD 804C27B1 timeout
00> [1634809215.073] RFID: tag 6 data = 0x00000000
00> [1634809215.160] RFID: tagPWD 804C27B1 timeout
00> [1634809215.160] RFID: tag 6 data = 0x00000000
00> [1634809215.297] RFID: tagPWD 804C27B1 timeout
00> [1634809215.297] RFID: tag 6 data = 0x00000000
00> [1634809215.384] RFID: tagPWD 804C27B1 timeout
00> [1634809215.384] RFID: tag 6 data = 0x00000000
00> [1634809215.521] RFID: tagPWD 804C27B1 timeout
00> [1634809215.521] RFID: tag 6 data = 0x00000000
00> [1634809215.608] RFID: tagPWD 804C27B1 timeout
00> [1634809215.608] RFID: tag 6 data = 0x00000000
00> [1634809215.745] RFID: tagPWD 804C27B1 timeout
00> [1634809215.745] RFID: tag 6 data = 0x00000000
00> [1634809215.832] RFID: tagPWD 804C27B1 timeout
00> [1634809215.832] RFID: tag 6 data = 0x00000000
00> [1634809215.969] RFID: tagPWD 804C27B1 timeout
00> [1634809215.969] RFID: tag 6 data = 0x00000000
00> [1634809216.056] RFID: tagPWD 804C27B1 timeout
00> [1634809216.056] RFID: tag 6 data = 0x00000000
00> [1634809216.193] RFID: tagPWD 804C27B1 timeout
00> [1634809216.193] RFID: tag 6 data = 0x00000000
00> [1634809216.280] RFID: tagPWD 804C27B1 timeout
00> [1634809216.280] RFID: tag 6 data = 0x00000000
00> [1634809216.417] RFID: tagPWD 804C27B1 timeout
00> [1634809216.417] RFID: tag 6 data = 0x00000000
00> [1634809216.504] RFID: tagPWD 804C27B1 timeout
00> [1634809216.504] RFID: tag 6 data = 0x00000000
00> [1634809216.641] RFID: tagPWD 804C27B1 timeout
00> [1634809216.641] RFID: tag 6 data = 0x00000000
00> [1634809216.728] RFID: tagPWD 804C27B1 timeout
00> [1634809216.728] RFID: tag 6 data = 0x00000000
00> [1634809216.865] RFID: tagPWD 804C27B1 timeout
00> [1634809216.865] RFID: tag 6 data = 0x00000000
00> [1634809216.952] RFID: tagPWD 804C27B1 timeout
00> [1634809216.952] RFID: tag 6 data = 0x00000000
00> [1634809217.089] RFID: tagPWD 804C27B1 timeout
00> [1634809217.089] RFID: tag 6 data = 0x00000000
00> [1634809217.177] RFID: tagPWD 804C27B1 timeout
00> [1634809217.177] RFID: tag 6 data = 0x00000000
00> [1634809217.314] RFID: tagPWD 804C27B1 timeout
00> [1634809217.314] RFID: tag 6 data = 0x00000000
00> [1634809217.402] RFID: tagPWD 804C27B1 timeout
00> [1634809217.402] RFID: tag 6 data = 0x00000000
00> [1634809217.539] RFID: tagPWD 804C27B1 timeout
00> [1634809217.539] RFID: tag 6 data = 0x00000000
00> [1634809217.626] RFID: tagPWD 804C27B1 timeout
00> [1634809217.626] RFID: tag 6 data = 0x00000000
00> [1634809217.763] RFID: tagPWD 804C27B1 timeout
00> [1634809217.763] RFID: tag 6 data = 0x00000000
00> [1634809217.851] RFID: tagPWD 804C27B1 timeout
00> [1634809217.851] RFID: tag 6 data = 0x00000000
00> [1634809217.988] RFID: tagPWD 804C27B1 timeout
00> [1634809217.988] RFID: tag 6 data = 0x00000000
00> [1634809218.075] RFID: tagPWD 804C27B1 timeout
00> [1634809218.075] RFID: tag 6 data = 0x00000000
00> [1634809218.213] RFID: tagPWD 804C27B1 timeout
00> [1634809218.213] RFID: tag 6 data = 0x00000000
00> [1634809218.301] RFID: tagPWD 804C27B1 timeout
00> [1634809218.301] RFID: tag 6 data = 0x00000000
00> [1634809218.439] RFID: tagPWD 804C27B1 timeout
00> [1634809218.439] RFID: tag 6 data = 0x00000000
00> [1634809218.526] RFID: tagPWD 804C27B1 timeout
00> [1634809218.526] RFID: tag 6 data = 0x00000000
00> [1634809218.663] RFID: tagPWD 804C27B1 timeout
00> [1634809218.663] RFID: tag 6 data = 0x00000000
00> [1634809218.752] RFID: tagPWD 804C27B1 timeout
00> [1634809218.752] RFID: tag 6 data = 0x00000000
00> [1634809218.889] RFID: tagPWD 804C27B1 timeout
00> [1634809218.889] RFID: tag 6 data = 0x00000000
00> [1634809218.976] RFID: tagPWD 804C27B1 timeout
00> [1634809218.976] RFID: tag 6 data = 0x00000000
00> [1634809219.114] RFID: tagPWD 804C27B1 timeout
00> [1634809219.114] RFID: tag 6 data = 0x00000000
00> [1634809219.201] RFID: tagPWD 804C27B1 timeout
00> [1634809219.201] RFID: tag 6 data = 0x00000000
00> [1634809219.338] RFID: tagPWD 804C27B1 timeout
00> [1634809219.338] RFID: tag 6 data = 0x00000000
00> [1634809219.425] RFID: tagPWD 804C27B1 timeout
00> [1634809219.425] RFID: tag 6 data = 0x00000000
00> [1634809219.562] RFID: tagPWD 804C27B1 timeout
00> [1634809219.562] RFID: tag 6 data = 0x00000000
00> [1634809219.650] RFID: tagPWD 804C27B1 timeout
00> [1634809219.650] RFID: tag 6 data = 0x00000000
00> [1634809219.788] RFID: tagPWD 804C27B1 timeout
00> [1634809219.788] RFID: tag 6 data = 0x00000000
00> [1634809219.875] RFID: tagPWD 804C27B1 timeout
00> [1634809219.875] RFID: tag 6 data = 0x00000000
00> [1634809220.012] RFID: tagPWD 804C27B1 timeout
00> [1634809220.012] RFID: tag 6 data = 0x00000000
00> [1634809220.099] RFID: tagPWD 804C27B1 timeout
00> [1634809220.099] RFID: tag 6 data = 0x00000000
00> [1634809220.236] RFID: tagPWD 804C27B1 timeout
00> [1634809220.236] RFID: tag 6 data = 0x00000000
00> [1634809220.323] RFID: tagPWD 804C27B1 timeout
00> [1634809220.323] RFID: tag 6 data = 0x00000000
00> [1634809220.461] RFID: tagPWD 804C27B1 timeout
00> [1634809220.461] RFID: tag 6 data = 0x00000000
00> [1634809220.548] RFID: tagPWD 804C27B1 timeout
00> [1634809220.548] RFID: tag 6 data = 0x00000000
00> [1634809220.685] RFID: tagPWD 804C27B1 timeout
00> [1634809220.685] RFID: tag 6 data = 0x00000000
00> [1634809220.772] RFID: tagPWD 804C27B1 timeout
00> [1634809220.772] RFID: tag 6 data = 0x00000000
00> [1634809220.909] RFID: tagPWD 804C27B1 timeout
00> [1634809220.909] RFID: tag 6 data = 0x00000000
00> [1634809220.996] RFID: tagPWD 804C27B1 timeout
00> [1634809220.996] RFID: tag 6 data = 0x00000000
00> [1634809221.133] RFID: tagPWD 804C27B1 timeout
00> [1634809221.133] RFID: tag 6 data = 0x00000000
00> [1634809221.220] RFID: tagPWD 804C27B1 timeout
00> [1634809221.220] RFID: tag 6 data = 0x00000000
00> [1634809221.357] RFID: tagPWD 804C27B1 timeout
00> [1634809221.357] RFID: tag 6 data = 0x00000000
00> [1634809221.445] RFID: tagPWD 804C27B1 timeout
00> [1634809221.445] RFID: tag 6 data = 0x00000000
00> [1634809221.582] RFID: tagPWD 804C27B1 timeout
00> [1634809221.582] RFID: tag 6 data = 0x00000000
00> [1634809221.669] RFID: tagPWD 804C27B1 timeout
00> [1634809221.669] RFID: tag 6 data = 0x00000000
00> [1634809221.806] RFID: tagPWD 804C27B1 timeout
00> [1634809221.806] RFID: tag 6 data = 0x00000000
00> [1634809221.893] RFID: tagPWD 804C27B1 timeout
00> [1634809221.893] RFID: tag 6 data = 0x00000000
00> [1634809222.030] RFID: tagPWD 804C27B1 timeout
00> [1634809222.030] RFID: tag 6 data = 0x00000000
00> [1634809222.117] RFID: tagPWD 804C27B1 timeout
00> [1634809222.117] RFID: tag 6 data = 0x00000000
00> [1634809222.254] RFID: tagPWD 804C27B1 timeout
00> [1634809222.254] RFID: tag 6 data = 0x00000000
00> [1634809222.341] RFID: tagPWD 804C27B1 timeout
00> [1634809222.341] RFID: tag 6 data = 0x00000000
00> [1634809222.478] RFID: tagPWD 804C27B1 timeout
00> [1634809222.478] RFID: tag 6 data = 0x00000000
00> [1634809222.565] RFID: tagPWD 804C27B1 timeout
00> [1634809222.565] RFID: tag 6 data = 0x00000000
00> [1634809222.702] RFID: tagPWD 804C27B1 timeout
00> [1634809222.702] RFID: tag 6 data = 0x00000000
00> [1634809222.789] RFID: tagPWD 804C27B1 timeout
00> [1634809222.789] RFID: tag 6 data = 0x00000000
00> [1634809222.927] RFID: tagPWD 804C27B1 timeout
00> [1634809222.927] RFID: tag 6 data = 0x00000000
00> [1634809223.014] RFID: tagPWD 804C27B1 timeout
00> [1634809223.014] RFID: tag 6 data = 0x00000000
00> [1634809223.151] RFID: tagPWD 804C27B1 timeout
00> [1634809223.151] RFID: tag 6 data = 0x00000000
00> [1634809223.238] RFID: tagPWD 804C27B1 timeout
00> [1634809223.238] RFID: tag 6 data = 0x00000000
00> [1634809223.376] RFID: tagPWD 804C27B1 timeout
00> [1634809223.376] RFID: tag 6 data = 0x00000000
00> [1634809223.463] RFID: tagPWD 804C27B1 timeout
00> [1634809223.463] RFID: tag 6 data = 0x00000000
(Connection lost)

Android logs.txt

[Edvin]

So in this log (baby_logs.txt), is this from after the DFU, or is it the first time you turn it on (before ever bonding with the phone)?

If that is the case, then it doesn't have any devices in the whitelist, and I would assume that it doesn't have any devices in the peer manager either, since the whitelist typically uses the peer manager to load the addresses for the whitelist.

If that is not the case, then can you please describe to me what I am looking at in the baby_logs.txt log?

[Randy Lee]

Sorry, I forgot to say what we did exactly here... This is using Android 11 as the initiator

1. Set DFU mode
   • Set promiscuous mode on device (put it into a reception state where it is ready for bonding)
   • Connect 
   • Pair
   • Join (this is our special thing that tells it to whitelist the thing that bonded)
   • Send BOOTLOADER command (line 38)
   • Disconnect
2. DFU (this wouldn't be in the logs because the bootloader doesn't have that kind of instrumentation)
   
   • Connect with nRFconnect
   • Do DFU
   • Disconnect
3. Restore bonding
   • Connect with nRFconnect (line 53)
   • Pair
   • Disconnect

Search the document for POR; That the Power On Reset points so those are the points where the application running is regaining control from the bootloader.

Special note: the lines tagged with e.g. [1634809205.873] are part of the logging from the application itself.  Things tagged e.g. <debug> are Nordic code logs... you can ignore most of the lines from the application I think.

Note that the whitelist is still populated coming back so I have problems thinking that the bonding information is gone too...

Line 245: This is in response to PM_EVT_CONN_SEC_CONFIG_REQ on a pm event

I'll be able to focus back on this next week and get your code implanted and a log back to you on it.

[Edvin]

Are you reproducing this on a DK or custom HW? If custom, can you try to reproduce it on a DK? And does it only happen on a certain Android version (10) or on any android version? And have you tried iOS? Is there some way for me to replicate this issue on a DK with a phone? Preferably iOS, but I can try to get hold of an Android if I need to. 

From the logs, you are saying that on line 52, when it says "applied whitelist with addr_cnt=1 irk_cnt=1", it will still go through the pairing process? Is there anything in the logs saying when you need to pair or not?

BR,
Edvin

[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