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]

Another detail that I should point out is that this is a DFU upgrade of the entire chip.

from SDK14, S132 v5.0 to SDK17, S113 v7.2.0

Everything is different, including the format of the bootloader settings file.

[Einar Thorsrud]

Hi,

Changing the number of FDS pages through DFU does not work out of the box. Basically, there are two different scenarios:

1. If you add an additional FDS page, this may or may not be empty. If the page is empty, it will be initialized by FDS and used. If it is not empty, it will not be used (see line 706-711 in fds.c in SDK 17.0.2.

2. If you remove FDS pages, then you may remove data and/or swap pages (those shift around after every garbage collection so you can never know). If you remove data page(s), you risk loosing data such as bonding information. If only data pages are deleted, you "just" loose data. If the swap page is removed, fds_init() will return the FDS_ERR_NO_PAGES error.

So the only way to get a predictable and consistent behavior when updating an existing product via DFU while changing the number of FDS pages is to delete all those pages before you initialize FDS. In that case all data will be lost, but FDS will initializes the empty pages and you will be good to go.

[mrono]

I'm not the original poster (sorry Allen for this sidetrack), but this latest reply seems to have a major impact so I'd like to ask for clarification.

Einar Thorsrud said:

So the only way to get a predictable and consistent behavior when updating an existing product via DFU while changing the number of FDS pages is to delete all those pages before you initialize FDS. In that case all data will be lost, but FDS will initializes the empty pages and you will be good to go.

Einar Thorsrud said:

1. If you add an additional FDS page, this may or may not be empty. If the page is empty, it will be initialized by FDS and used. If it is not empty, it will not be used (see line 706-711 in fds.c in SDK 17.0.2.

So are you saying that even if one has always reserved the correct amount of pages in both the bootloader and application, and never reduced the number of pages, that increasing the number of pages is still not necessarily safe?

I guess the problematic scenario is a case where at some point the application size is just right to completely fill the empty flash using a dual bank update. The next  updates are still successful even if size increases, as the update switches to a single bank. But now stale code is left in the last pages that would be used if the FDS needs to grow?

Am I on the right track here? And the only solution is that the application deletes a page in flash that is not empty but supposedly unused? Is there a way for the application to know if the page is truly unused, or if it is part of the application itself (ie the flash is truly full)?

[Einar Thorsrud]

Hi,

I was not clear enough in my previous post.

mrono said:

So are you saying that even if one has always reserved the correct amount of pages in both the bootloader and application, and never reduced the number of pages, that increasing the number of pages is still not necessarily safe?

No, increasing the amount of pages is safe. But you may not be able to actually use the new page(s) for anything useful unless you make sure it is erased before FDS is initialized. That is because FDS will stay away from pages that do not have the FDS page tag but have other content. So it will simply not be used by FDS. But again: this is only if the additional flash pages are not erased (contain other than FF...).

mrono said:

I guess the problematic scenario is a case where at some point the application size is just right to completely fill the empty flash using a dual bank update. The next  updates are still successful even if size increases, as the update switches to a single bank. But now stale code is left in the last pages that would be used if the FDS needs to grow?

Am I on the right track here? And the only solution is that the application deletes a page in flash that is not empty but supposedly unused?

Yes. In this case you would have to delete the new flash page(s) before you initialize FDS. So the logic to do that should be part of the new app you are updating to (which use more FDS pages).

mrono said:

Is there a way for the application to know if the page is truly unused, or if it is part of the application itself (ie the flash is truly full)?

You will know the size of the app when you build it, but I do not think the app can automatically know that an area is truly unused (perhaps you have some code there that writes to some flash above the end address of the app etc?). But you can know, so that should be OK. As long as you have control of the memory map of your application, you should be good and have the information you need.

Another approach here is to modify the FDS implementation so that it would not care if a page is empty or not, but simply erase it if it does not have the FDS page tag but is part of the reserved pages.

[mrono]

Thank you.

Just to clarify further: Assuming a 'typical' nRF52 flash layout. Nordic's secure Bootloader, FDS, softdevice and application. No extra flash sections, no other writers to flash than bootloder and FDS. FDS never shrinks, only grows.

So assuming these conditions, is it possible that we end up in a situation where FDS can't grow? The scenario I described above occurred to me as a possibility, but I'm not even sure if the bootloader leaves stuff into bank 1 after copying it to bank 0.

Because if there is a need to increase the size of FDS then there is a need to use those pages as well. So this:

Einar Thorsrud said:

you would have to delete the new flash page(s) before you initialize FDS.

.. is a bit difficult for the application. If the pages aren't empty how does the application know it is safe to erase them?

[Einar Thorsrud]

mrono said:

If the pages aren't empty how does the application know it is safe to erase them?

Except for the bootloader when it is doing a dual bank update, the only thing that can write to the flash is the application that you (who is developing it) is responsible for. So you need to know the flash layout, and as you make the application you need to let the application "know" whatever it needs to know. That is basically it. In other words: If you never use a flash page for anything (directly or indirectly via FDS or something else), then you know it is safe to erase. And you decide what your applications "knows" as you write it.

[Allen]

This is all very interesting. Let me try to bring this down to my reality.

1. Reducing FDS_VIRTUAL_PAGES causes peer_manager initialization to fail. 

It is unclear to me the relationship between virtual pages and physical pages. It sounds like they are independent. (it is state above that it may grow) On the other hand it appears from the source code that they number of physical pages is directly related to the number of virtual pages.

2. The proposed solution is to erase the pages prior to peer manager initialization.

The peer manager is not part of our application. It is part of the SDK. How do we know what pages to erase? peer_data_storage.h defines  PDS_FIRST_RESERVED_RECORD_KEY and  PDS_LAST_RESERVED_RECORD_KEY. Do we find the ID for all keys in this range and delete them?

3. pm_init() calls pds_init() which calls fds_init(). To erase the peer manager information we would need to fds_init() first. It looks like this will be fine. Just verifying.

4. Is there a generic way to determine how FDS_VIRTUAL_PAGES was previously configured? It appears that this macro is used to calculate the number of physical pages. Is is possible to read the FDS pages and determine the end and therefore the previous value of FDS_VIRTUAL_PAGES?

5. Where are these pages located? How does the number of FDS pages affect soft device flash size, application flash size or flash available for dual boot DFU operation?

Currently our application only supports dual boot DFU mode. The remaining flash for application growth is becoming an issue.

[Einar Thorsrud]

Hi,

Allen said:

1. Reducing FDS_VIRTUAL_PAGES causes peer_manager initialization to fail. 

It is unclear to me the relationship between virtual pages and physical pages. It sounds like they are independent. (it is state above that it may grow) On the other hand it appears from the source code that they number of physical pages is directly related to the number of virtual pages.

This issue is not related to the size of the virtual pages, as they anyway need to be a multiple of the physical pages (in practice you typically configure it so that a virtual page is the same as a physical page). (Also, reducing the number of pages can cause fds initialization and thus peer manager initialization to fail. If it actually does not not depends on if the swap page was removed or not. If only data page(s) were deleted, you would "just" lose data.).

Just as a side note it is unlikely that the virtual page size is different than the virtual page size. It does not make sense for most application, as that would waste mor flash on the swap page. And the only benefit would be to support very large records.

Allen said:

2. The proposed solution is to erase the pages prior to peer manager initialization.

The peer manager is not part of our application. It is part of the SDK. How do we know what pages to erase? peer_data_storage.h defines  PDS_FIRST_RESERVED_RECORD_KEY and  PDS_LAST_RESERVED_RECORD_KEY. Do we find the ID for all keys in this range and delete them?

You know that the FDS pages are immediately below the bootloader, counting downwards as many pages as you have configured in your sdk_config.h. You cannot know at which page data is contained, regardless of if it is stored by the peer_manager or another user, as data will be shifted around during the life cycle of a device as it performs garbage collection without searching for FDS records (like FDS itself does).

If you don't need to keep the data, then you can simply delete all FDS pages blindly. If not, then you can search for the data and temporarily store them somewhere else. That would be up to you though. You would not be able to use FDS directly if it cannot be initialized, but you could use code from the FDS implementation. I do not know enough about your use case and requirements to say if this is sensible or not, though.

Allen said:

3. pm_init() calls pds_init() which calls fds_init(). To erase the peer manager information we would need to fds_init() first. It looks like this will be fine. Just verifying.

Yes. FDS is intended to support multiple "users" and it is perfectly legal to initialize it more than once (it will simply return NRF_SUCCESS and trigger the event indicating it is initialized again for any subsequent calls to fds_init()).

Allen said:

4. Is there a generic way to determine how FDS_VIRTUAL_PAGES was previously configured? It appears that this macro is used to calculate the number of physical pages. Is is possible to read the FDS pages and determine the end and therefore the previous value of FDS_VIRTUAL_PAGES?

Yes, that should be possible. During initialization FDS will tag all pages with an FDS page header. So if you don't know how many pages the previous firmware configured you can search through all pages. If the first word is 0xDEADC0DE (FDS_PAGE_TAG_MAGIC) and the second tag is either 0xF11E01FF (FDS_PAGE_TAG_SWAP) or 0xF11E01FE (FDS_PAGE_TAG_DATA), then the page is an FDS page (at least FDS will consider it as one). So if you search downwards from just below the bootloader, and count the number of times you find this pattern you will know the virtual page count.

Allen said:

5. Where are these pages located? How does the number of FDS pages affect soft device flash size, application flash size or flash available for dual boot DFU operation?

Currently our application only supports dual boot DFU mode. The remaining flash for application growth is becoming an issue.

FDS pages are always located immediately below the bootloader (or at the very end of the flash if a bootloader is not present).

[Allen]

FDS_VIRTUAL_PAGES did not have the same configuration for the boot loader and the application. This difference was the root of this issue.