first secure connection after DFU fails. SDK17 S113

[Allen]

Hello.

After performing a secure DFU download, the first attempt to open a secure NUS connection fails with an NRF_ERROR_INVALID_PARAM error. After resetting the device, all subsequent connections are successful. I have traced this to the call to BLE_GATS_EVT_WRITE handling in gatt_cache_manager.c. gscm_local_db_cache_update() fails in pdb_write_buf_store() because the peer_id is not tagged as allocated?

Below is a log. The first part is the connection attempt right after the DFU operation. The second part is the connection after reset which is successful.

0> REBOOT (52)
0> Bluetooth Name NM04-000078
0> Board Type D045
0> Model Type ETM
0> FPGA Ver Model 4 Version 4
0> Firmware Ver 2.1.399
0> Firmware Type FIELD
0> SoftDevice Ver 7.2.0
0> BootLoader Ver 7 (INSTALLED)
0> Mfg Data Ver 4
0> Sys Config Ver 12
0> API Versions OK
0> Bluetooth Enabled
0> UART Enabled
0> 0:00:00.000 BLE terminated
0> BLE: Local BDADDR xE49C814C1039
0> 0:00:01.439 PWR: Entering normal power
0> 0:00:01.442 STIM STATE: x02
0> 0:00:01.442 ADV: Sys=FFFFFFFF Dev=0 VBat=3956 Amp={63 63 63 63} Sched=00/FF Err=00 Col=02 Prg=F Ins=0 Post=0 Stim=1 LowP=0 LowB=0 Sess=1 BLE=1 Buzz=0
0> 0:00:01.566 STIM EVENT[01]: x0E
0> 0:00:01.567 STIM STATE: x03
0> SD: 26 BLE_GAP_EVT_ADV_SET_TERMINATED
0> 0:00:02.103 Detected ID x00000244 (Patient x00000244, Reference xFFFFFFFF)
0> 0:00:02.103 update_implant_trim_data
0> 0:00:02.104 Trim not found
0> 0:00:02.106 Connected to patient device x00000244
0> 0:00:02.106 STIM EVENT[02]: x0F
0> 0:00:02.107 STIM STATE: x0E
0> 0:00:02.112 STIM EVENT[03]: x2B
0> 0:00:02.112 STIM STATE: x06
0> 0:00:02.140 ADV: Sys=FFFFFFFF Dev=0 VBat=3956 Amp={63 63 63 63} Sched=00/FF Err=00 Col=02 Prg=F Ins=1 Post=0 Stim=2 LowP=0 LowB=0 Sess=1 BLE=1 Buzz=0
0> SD: 26 BLE_GAP_EVT_ADV_SET_TERMINATED
0> SD: 10 BLE_GAP_EVT_CONNECTED
0> BLE: Remote x67F4C478945C
0> NCE: bd_addr1 xE49C814C1039
0> NCE: bd_addr2 x67F4C478945C
0> PK: device passkey F3E47DDFF77F8B74
0> BLE: GAP connected. Unauthenticated timer restarted
0> PM: PM_EVT_BONDED_PEER_CONNECTED
0> PM: PM_EVT_CONN_SEC_PARAMS_REQ
0> PM: PM_EVT_BONDED_PEER_CONNECTED evt_id=0 get_id=0
0> PM: Connected to a previously bonded device.
0> PM: PM_EVT_LOCAL_DB_CACHE_APPLY_FAILED
0> 0:00:13.263 BLE terminated
0> PMM: CONNECTED, stored 0 peers
0> PM: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
0> 0:00:13.296 ADV: Sys=FFFFFFFF Dev=0 VBat=3956 Amp={63 63 63 63} Sched=00/FF Err=00 Col=02 Prg=F Ins=1 Post=0 Stim=2 LowP=0 LowB=0 Sess=1 BLE=0 Buzz=0
0> SD: 3A SD_BLE_GATTC_EXCHANGE_MTU_REQUEST
0> SD: 24 BLE_GAP_EVT_DATA_LENGTH_UPDATE
0> SD: 26 BLE_GAP_EVT_ADV_SET_TERMINATED
0> SD: 12 BLE_GAP_EVT_CONN_PARAM_UPDATE
0> SD: 14 BLE_GAP_EVT_SEC_INFO_REQUEST
0> PM: PM_EVT_CONN_SEC_START
0> SD: 1A BLE_GAP_EVT_CONN_SEC_UPDATE
0> PM: PM_EVT_CONN_SEC_SUCCEEDED
0> PM: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
0> PM: Connection secured. Procedure: 0 Role: 1 conn_handle: 0
0> PMM: CONNECTED, stored 0 peers
0> SD: 50 BLE_GATTS_EVT_WRITE
0> B gcm_ble_evt_handler EVT_WRITE
0> pdb_write_buf_get id=0 err=0
0> sd_ble_gatts_sys_attr_get id=0 err=0
0> pdb_write_buf_store id=0 err=7
0> local_db_update_in_evt err=7
0> PM: PM_EVT_ERROR_UNEXPECTED
0> ERROR 7 [NRF_ERROR_INVALID_PARAM] at ..\components\ble\peer_manager\peer_manager_handler.c:294
0> PC at: 0x000361d5
0> ERROR 7 [NRF_ERROR_INVALID_PARAM] at ble_driver.c:1805
0> PC at: 0x00028345
0> E gcm_ble_evt_handler EVT_WRITE
0> on_write:453 resp 0
0> on_write:561 resp 0
0> SD: 12 BLE_GAP_EVT_CONN_PARAM_UPDATE
0> 0:00:14.394 ADV: Sys=FFFFFFFF Dev=0 VBat=3921 Amp={63 63 63 63} Sched=00/FF Err=00 Col=02 Prg=F Ins=1 Post=0 Stim=2 LowP=0 LowB=0 Sess=1 BLE=0 Buzz=0
0>
0> REBOOT (53)
0>
0> ERROR 7 [NRF_ERROR_INVALID_PARAM] at ble_driver.c:1805
0> PC at: 0x00028345
0> Bluetooth Name NM04-000078
0> Board Type D045
0> Model Type ETM
0> FPGA Ver Model 4 Version 4
0> Firmware Ver 2.1.399
0> Firmware Type FIELD
0> SoftDevice Ver 7.2.0
0> BootLoader Ver 7 (INSTALLED)
0> Mfg Data Ver 4
0> Sys Config Ver 12
0> API Versions OK
0> Bluetooth Enabled
0> UART Enabled
0> Stimulation Enabled
0> Acceleration Disabled (0)
0> Force Error Disabled (0)
0> Electrode Map Field 8 Contact
0> Reboot Reason Restart
0>
0> 0:00:00.000 BLE terminated
0> peer 0 rank 0 stamp 0:00:37.499
0> BLE: Local BDADDR xE49C814C1039
0> 0:00:01.436 PWR: Entering normal power
0> 0:00:01.439 STIM STATE: x02
0> 0:00:01.439 ADV: Sys=FFFFFFFF Dev=0 VBat=3961 Amp={63 63 63 63} Sched=00/FF Err=00 Col=02 Prg=F Ins=0 Post=0 Stim=1 LowP=0 LowB=0 Sess=1 BLE=1 Buzz=0
0> 0:00:01.564 STIM EVENT[01]: x0E
0> 0:00:01.564 STIM STATE: x03
0> SD: 26 BLE_GAP_EVT_ADV_SET_TERMINATED
0> 0:00:02.100 Detected ID x00000244 (Patient x00000244, Reference xFFFFFFFF)
0> 0:00:02.100 update_implant_trim_data
0> 0:00:02.101 Trim not found
0> 0:00:02.103 Connected to patient device x00000244
0> 0:00:02.103 STIM EVENT[02]: x0F
0> 0:00:02.104 STIM STATE: x0E
0> 0:00:02.109 STIM EVENT[03]: x2B
0> 0:00:02.109 STIM STATE: x06
0> 0:00:02.137 ADV: Sys=FFFFFFFF Dev=0 VBat=3961 Amp={63 63 63 63} Sched=00/FF Err=00 Col=02 Prg=F Ins=1 Post=0 Stim=2 LowP=0 LowB=0 Sess=1 BLE=1 Buzz=0
0> SD: 26 BLE_GAP_EVT_ADV_SET_TERMINATED
0> SD: 10 BLE_GAP_EVT_CONNECTED
0> BLE: Remote x67F4C478945C
0> NCE: bd_addr1 xE49C814C1039
0> NCE: bd_addr2 x67F4C478945C
0> PK: device passkey C6DB518BE8DD4913
0> BLE: GAP connected. Unauthenticated timer restarted
0> PM: PM_EVT_BONDED_PEER_CONNECTED
0> PM: PM_EVT_CONN_SEC_PARAMS_REQ
0> PM: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
0> PM: PM_EVT_BONDED_PEER_CONNECTED evt_id=0 get_id=0
0> PM: Connected to a previously bonded device.
0> PM: PM_EVT_LOCAL_DB_CACHE_APPLY_FAILED
0> 0:00:03.193 BLE terminated
0> PMM: CONNECTED, stored 1 peers
0> 0:00:03.233 ADV: Sys=FFFFFFFF Dev=0 VBat=3961 Amp={63 63 63 63} Sched=00/FF Err=00 Col=02 Prg=F Ins=1 Post=0 Stim=2 LowP=0 LowB=0 Sess=1 BLE=0 Buzz=0
0> SD: 3A SD_BLE_GATTC_EXCHANGE_MTU_REQUEST
0> SD: 50 BLE_GATTS_EVT_WRITE
0> B gcm_ble_evt_handler EVT_WRITE
0> pdb_write_buf_get id=0 err=0
0> sd_ble_gatts_sys_attr_get id=0 err=0
0> pdb_write_buf_store id=0 err=0
0> local_db_update_in_evt err=0
0> E gcm_ble_evt_handler EVT_WRITE
0> on_write:453 resp 0
0> on_write:561 resp 0
0> PM: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
0> SD: 24 BLE_GAP_EVT_DATA_LENGTH_UPDATE
0> SD: 14 BLE_GAP_EVT_SEC_INFO_REQUEST
0> PM: PM_EVT_CONN_SEC_START
0> SD: 26 BLE_GAP_EVT_ADV_SET_TERMINATED
0> SD: 1A BLE_GAP_EVT_CONN_SEC_UPDATE
0> PM: PM_EVT_CONN_SEC_SUCCEEDED
0> PM: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
0> PM: Connection secured. Procedure: 0 Role: 1 conn_handle: 0
0> PMM: CONNECTED, stored 1 peers
0> SD: 50 BLE_GATTS_EVT_WRITE
0> B gcm_ble_evt_handler EVT_WRITE
0> pdb_write_buf_get id=0 err=0
0> sd_ble_gatts_sys_attr_get id=0 err=0
0> pdb_write_buf_store id=0 err=0
0> local_db_update_in_evt err=0
0> E gcm_ble_evt_handler EVT_WRITE
0> on_write:453 resp 0
0> on_write:561 resp 0
0> PM: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
0> SD: 35 SD_BLE_GATTC_CHAR_VALUE_BY_UUID_READ
0> SD: 55 BLE_GATTS_EVT_EXCHANGE_MTU_REQUEST
0> SD: 36 SD_BLE_GATTC_READ
0> PM: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
0> SD: 23 BLE_GAP_EVT_DATA_LENGTH_UPDATE_REQUEST
0> SD: 24 BLE_GAP_EVT_DATA_LENGTH_UPDATE
0> SD: 51 BLE_GATTS_EVT_RW_AUTHORIZE_REQUEST
0> on_write:453 resp 1
0> BLE_NUS_EVT_HOST_PASSKEY_DATA
0> BLE: ble_host_passkey[16]=17 8D 53 60 01 FD 42 65 EE 8F A6 A9 54 DC 17 8F
0> NCE: bd_addr1 x67F4C478945C
0> NCE: bd_addr2 xE49C814C1039
0> PK: passkey EE8FA6A954DC178F
0> PK: ptr EE8FA6A954DC178F
0> CDB: oldest table[0].timestamp = 51
0> CDB: table[0].addr = 68EB8938A770, .timestamp = 38158
0> CDB: oldest table[1].timestamp = 4294967285
0> CDB: table[1].addr = 5A5F58810DBC, .timestamp = 23936
0> CDB: oldest table[2].timestamp = 4294967293
0> CDB: table[2].addr = 4ED340F5FCA3, .timestamp = 34401
0> CDB: table[3].addr = 4353F39350AF, .timestamp = 4564
0> 56CDFFSD: 50 BLE_GATTS_EVT_WRITE
0> B gcm_ble_evt_handler EVT_WRITE
0> E gcm_ble_evt_handler EVT_WRITE
0> on_write:453 resp 0
0> BLE_NUS_EVT_RX_DATA
0> 0:00:04.664 BLE detected
0>
0>
0> on_write:561 resp 0
0> 0:00:04.666 Sess Start
0> Session Type=Engineering
0> BLE: Connection in session. Session timer restarted
0> 0:00:04.666 STIM EVENT[04]: x09 (255)
0> 0:00:04.666 ACK: 001000
0>
0> PMM: ENTER_UNPROTECTED, active id=x0000
0> PM_PEER_DATA_ID_APPLICATION 4
0> data_id 4
0> PM: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
0> SD: 57 BLE_GATTS_EVT_HVN_TX_COMPLETE
0> SD: 50 BLE_GATTS_EVT_WRITE
0> B gcm_ble_evt_handler EVT_WRITE
0> E gcm_ble_evt_handler EVT_WRITE
0> on_write:453 resp 0
0> BLE_NUS_EVT_RX_DATA
0>
0> on_write:561 resp 0
0> 0:00:04.755 Rd Ver
0> Firmware=2.1.399 SecurityVer=2 AdvertiseVer=4 UnrestictedVer=9 RemoteVer=4 ProgrammingVer=14 EngineeringVer=12 FPGAModel=4 FPGAVer=4 ImplantVer=1 Bootloader=7 SD_FWID=x0102 SD_Ver=7.2.0 Model=ETM Type=FIELD_BLE_UART
0> 0:00:04.755 ACK: 002016
0>
0> SD: 57 BLE_GATTS_EVT_HVN_TX_COMPLETE

[Einar Thorsrud]

Hi,

I do not have an explanation for this strange behaviour. There should not be any difference between the first and second time the application runs after reset, and it is odd that the peer manager does not find the bonding information in flash the first time but it suddenly reappears after a reset. Are you able to reproduce this on a DK? Can  you share the project so that I can have a look and test on my side?

[Allen]

Yes, it is very strange.

The PM library knows about the peer. pm_peer_id_get() returns the correct peer ID for the specified connection handle. My initial assumption was that this would fail and I would need to manually add the peer using pm_peer_new().

The error isn't identified until a BLE_GATTS_EVT_WRITE event. The BLE event handler in gatt_cache_manager ultimately causes the error when updating the local DB.

I should also note that this is on Android. It assumed that the bond used for the secure DFU is preserved and used when the new firmware loads.

[Einar Thorsrud]

Hi,

Allen said:

The PM library knows about the peer. pm_peer_id_get() returns the correct peer ID for the specified connection handle.

Yes the peer manager library knows about the peer and according to the log the connection is secured (which happens using the stored bondign information) also the first time, before the error happens. 

Allen said:

The error isn't identified until a BLE_GATTS_EVT_WRITE event. The BLE event handler in gatt_cache_manager ultimately causes the error when updating the local DB.

 I see. So pdb_write_buf_store() returns NRF_ERROR_INVALID_PARAM (7) because the peer ID is not allocated, or so it seems. Is there a timing factor there? What happens if you delay the GATT write?

Allen said:

It assumed that the bond used for the secure DFU is preserved and used when the new firmware loads.

Yes, the bond is preserved provided you have configured the application and bootloader correctly (so that the bootloader is configured to stay away of the FDS pages). This does not seem to be the problem though: the link is secured, so the boning information is clearly present.

Do you have any code that can reproduce this on the DK?