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,

From older post

Allen said:

Could the issue be passing the bond information back to the application from the bootloader when the DFU is complete? 

No. bonding information only goes from application to bootloader when starting the DFU, but not from the bootloader to application. It is not touched.

Allen said:

After more testing, it appears the reset issue reported is related to a bond mismatch between the host and device. There seems to be several failure modes:

I do not get a full understanding from the logs, but I think I may have read them too quickly before. It could be that bonding information is deleted during the DFU update. You could verify the FDS page configuration in the application and the reserved appdata in the bootloader. This does not fit what we see with the GATT write, though.

Some questions, which it would be good to get answered:

• Have you looked into uploading a project that can reproduce this on a DK?
• Do you have service changed enabled in both the bootloader and application?
• You mention tha tyou deleted bonding information in Windows, and then you did not see any issues. What was that issue?
• What happens if you delete bonding information on the Android device?
• Do you only see this issue when doing DFU from SDK 14 to SDK 17? What if you DFU in the same SDK 17 or SDK 14 application again (you need to change the version number in the .zip, though)? Same issue?

[Allen]

Which FDS configuration is of concern? Here are the option from sdk_config.h. No appdata reserved.

#define FDS_ENABLED 1

#define FDS_VIRTUAL_PAGES 5

#define FDS_VIRTUAL_PAGE_SIZE 1024

#define FDS_VIRTUAL_PAGES_RESERVED 0

#define FDS_BACKEND 2

#define FDS_OP_QUEUE_SIZE 4

#define FDS_CRC_CHECK_ON_READ 0

#define FDS_CRC_CHECK_ON_WRITE 0

#define FDS_MAX_USERS 4

The original logs had service changed enabled for both the application and the bootloader. Later I disabled the service changed notification in the application. There was no change in the bond behavior either way.

I will test going from SDK17 S113 7.0.1 to SDK17 S113 7.2.0

I believe deleting the bonds on Android would work. However that is not a viable solution for our product. Right now we would rather ship with this defect provided it recovers on the next boot.

[Einar Thorsrud]

Hi,

Allen said:

The original logs had service changed enabled for both the application and the bootloader. Later I disabled the service changed notification in the application. There was no change in the bond behavior either way.

You should always have service changed enabled both in the bootloader and application. If you don't use it, then you should remove it in both. (If not, you can end up in a situation where the phone will not do service discovery because it waits for the service changed indication, as it discovered the service changed characteristic before, when device was in the bootloader). I do not think this is related to the issue at hand, though.

Allen said:

I believe deleting the bonds on Android would work. However that is not a viable solution for our product. Right now we would rather ship with this defect provided it recovers on the next boot.

I agree that is not a viable solution for most products. However, this suggests that the bonding information is lost or corrupted, so it is relevant information.

Allen said:

Which FDS configuration is of concern? Here are the option from sdk_config.h. No appdata reserved.

I assume this is from the application's sdk_config.h. Here you reserve 5 pages. Is that the case for both the old and new firmware?

App data flash pages are reserved differently in different SDK versions. IN the SDK 14 bootloader, this is  DFU_APP_DATA_RESERVED, which you typically set as a project vide define or by modifying nrf_dfu_types.h. In SDK 17 this is the NRF_DFU_APP_DATA_AREA_SIZE. In both cases these must be configured to match the number of FDS pages.

If this is not the problem, then I would very much like to see your application and bootloader projects, both old and new to compare and see if anything sticks out.

[Allen]

Einar,

I believe you hit on the issue. I remember increasing the number of FDS pages from 4 to 5. There was a problem which was resolved with this changed. I need to go back and evaluate this again.

Will keep you posted.

[Allen]

Application sdk_config.h
#define FDS_VIRTUAL_PAGES 4

Bootloader sdk_config.h

#define NRF_DFU_APP_DATA_AREA_SIZE 12288

This is the current configuration. I believe they match. 1024 page size * 4 num pages * 3 = 12288?

Not sure why it is x3

[Einar Thorsrud]

Hi,

Then this cold be the problem. NRF_DFU_APP_DATA_AREA_SIZE is in bytes, and each flash page is 1024 words = 4096 bytes (this is where the 4 comes from in your calculation, and 3 is the number of pages). Your value of 12288 matches 3 FDS pages, not 4.

[Allen]

dfu_data_types.h has this code which confused me. The constant 3 should actually be number of pages or something to make it clearer.

#ifndef NRF_DFU_APP_DATA_AREA_SIZE
#define NRF_DFU_APP_DATA_AREA_SIZE (CODE_PAGE_SIZE * 3)
#endif

--------------------------------------------------------------------------------------------------

Changing the number of FDS_VIRTUAL_PAGES pages to 3, to match the bootloader NRF_DFU_APP_DATA_AREA_SIZE 12288, did resolve the problem!

Thank you for the help!