• State Verified Answer
  • Replies 2 replies
  • Subscribers 89 subscribers
  • Views 750 views
  • Users 0 members are here
Attachments (0)
Nordic Case Info
  • Case ID: 264530
Options
Beware that this post is related to an SDK in maintenance mode
More Info: Consider nRF Connect SDK for new designs
This post is older than 2 years and might not be relevant anymore
More Info: Consider searching for newer posts

PM_EVT_STORAGE_FULL when flash is empty

Federico

I have an nRF 52832 running the SDK 15.2. I have a few general questions because I'm seeing behavior I don't understand and doesn't seem to be right.

If I erase all the flash memory, from Segger running "Target, Erase All" and then run the project with the debugger, I would expect the peer manager memory to be empty. When the first devices connects and bonds, I get this log:

[00:01:15.951,721] <debug> nrf_ble_gatt: Requesting to update ATT MTU to 247 bytes on connection 0x1.
[00:01:15.951,751] <debug> nrf_ble_gatt: Updating data length to 251 on connection 0x1.
[00:01:15.951,934] <info> app: Connected.
[00:01:15.951,995] <info> app: Restarted advertising.
[00:01:16.291,687] <debug> nrf_ble_gatt: Data length updated to 251 on connection 0x1.
[00:01:16.291,717] <debug> nrf_ble_gatt: max_rx_octets: 251
[00:01:16.291,717] <debug> nrf_ble_gatt: max_tx_octets: 251
[00:01:16.291,717] <debug> nrf_ble_gatt: max_rx_time: 2120
[00:01:16.291,748] <debug> nrf_ble_gatt: max_tx_time: 2120
[00:01:16.291,778] <debug> nrf_ble_gatt: Data length updated to 251 on connection 0x1.
[00:01:16.291,778] <debug> nrf_ble_gatt: max_rx_octets: 251
[00:01:16.291,778] <debug> nrf_ble_gatt: max_tx_octets: 251
[00:01:16.291,809] <debug> nrf_ble_gatt: max_rx_time: 2120
[00:01:16.291,809] <debug> nrf_ble_gatt: max_tx_time: 2120
[00:01:16.291,839] <info> app: Data length updated to 251 bytes.
[00:01:16.351,654] <debug> nrf_ble_gatt: Peer on connection 0x1 requested a data length of 251 bytes.
[00:01:16.351,654] <debug> nrf_ble_gatt: Updating data length to 0 on connection 0x1.
[00:01:16.351,715] <debug> nrf_ble_gatt: Peer on connection 0x1 requested a data length of 251 bytes.
[00:01:16.351,715] <debug> nrf_ble_gatt: Updating data length to 251 on connection 0x1.
[00:01:16.411,590] <debug> nrf_ble_gatt: Data length updated to 251 on connection 0x1.
[00:01:16.411,590] <debug> nrf_ble_gatt: max_rx_octets: 251
[00:01:16.411,590] <debug> nrf_ble_gatt: max_tx_octets: 251
[00:01:16.411,621] <debug> nrf_ble_gatt: max_rx_time: 2120
[00:01:16.411,621] <debug> nrf_ble_gatt: max_tx_time: 2120
[00:01:16.411,651] <debug> nrf_ble_gatt: Data length updated to 251 on connection 0x1.
[00:01:16.411,651] <debug> nrf_ble_gatt: max_rx_octets: 251
[00:01:16.411,682] <debug> nrf_ble_gatt: max_tx_octets: 251
[00:01:16.411,682] <debug> nrf_ble_gatt: max_rx_time: 2120
[00:01:16.411,712] <debug> nrf_ble_gatt: max_tx_time: 2120
[00:01:16.411,712] <info> app: Data length updated to 251 bytes.
[00:01:16.651,367] <debug> nrf_ble_gatt: Peer on connection 0x1 requested an ATT MTU of 527 bytes.
[00:01:16.651,367] <debug> nrf_ble_gatt: Updating ATT MTU to 0 bytes (desired: 0) on connection 0x1.
[00:01:16.651,519] <error> nrf_ble_gatt: sd_ble_gatts_exchange_mtu_reply() returned NRF_ERROR_INVALID_PARAM.
[00:01:16.651,550] <debug> nrf_ble_gatt: Peer on connection 0x1 requested an ATT MTU of 527 bytes.
[00:01:16.651,550] <debug> nrf_ble_gatt: Updating ATT MTU to 247 bytes (desired: 247) on connection 0x1.
[00:01:16.711,364] <debug> nrf_ble_gatt: ATT MTU updated to 23 bytes on connection 0x1 (response).
[00:01:16.711,395] <debug> nrf_ble_gatt: ATT MTU updated to 247 bytes on connection 0x1 (response).
[00:01:16.711,395] <info> app: ATT MTU exchange completed on connection 1. MTU set to 247 bytes.
[00:01:16.771,789] <info> app: BLE_GAP_EVT_SEC_PARAMS_REQUEST
[00:01:16.892,333] <debug> nrf_ble_lesc: BLE_GAP_EVT_LESC_DHKEY_REQUEST
[00:01:16.892,395] <info> app: BLE_GAP_EVT_LESC_DHKEY_REQUEST
[00:01:16.929,534] <info> nrf_ble_lesc: Calling sd_ble_gap_lesc_dhkey_reply on conn_handle: 1
[00:01:17.731,842] <info> app: BLE_GAP_EVT_CONN_SEC_UPDATE
[00:01:17.731,872] <info> app: Security mode: 2
[00:01:18.091,827] <info> peer_manager_handler: Connection secured: role: Peripheral, conn_handle: 1, procedure: Bonding
[00:01:18.092,224] <info> peer_manager_handler: Connection secured: role: Peripheral, conn_handle: 1, procedure: Bonding
[00:01:18.092,254] <info> peer_manager_handler: Attempting to clean flash.
[00:01:18.092,498] <error> peer_manager_handler: There are no peers to delete.
[00:01:18.092,529] <info> app: BLE_GAP_EVT_AUTH_STATUS: status=0x0 bond=0x1 lv4: 0 kdist_own:0x3 kdist_peer:0x2
[00:01:41.493,377] <info> app: Disconnected.
[00:01:41.493,408] <info> app: Restarted advertising.

There are several things that look weird to me:

  1. Some peer_manager_handler messages are logged twice
  2. Even though the memory is empty, the peer_manager_handler says "Attempting to clean flash". Obviosuly, it gets the error "There are no peers to delete".

I've found related posts with similar issues, but none of them seem to be the same. There was a bug fixed in SDK 16 i believe for a corner case when the bonding data is deleted by some module other than the peer manager, which is not the case here, I'm coming from an empty memory (link).

If I keep bonding new devices, I get the same error of "Attempting to clean flash." many times, but this time it is able to earse the memory. Note that it will also delete the latest bond; in the following log, the second device bonding caused the peer manager to delete 2 peers, probably because it got the PM_EVT_STORAGE_FULL event twice, effectively wiping all peers. 

[00:03:30.566,772] <info> app: Connected.
[00:03:30.566,802] <info> app: Restarted advertising.
[00:03:30.786,254] <debug> nrf_ble_gatt: Data length updated to 27 on connection 0x2.
[00:03:30.786,254] <debug> nrf_ble_gatt: max_rx_octets: 27
[00:03:30.786,285] <debug> nrf_ble_gatt: max_tx_octets: 27
[00:03:30.786,285] <debug> nrf_ble_gatt: max_rx_time: 328
[00:03:30.786,315] <debug> nrf_ble_gatt: max_tx_time: 328
[00:03:30.786,315] <debug> nrf_ble_gatt: Data length updated to 27 on connection 0x2.
[00:03:30.786,346] <debug> nrf_ble_gatt: max_rx_octets: 27
[00:03:30.786,346] <debug> nrf_ble_gatt: max_tx_octets: 27
[00:03:30.786,376] <debug> nrf_ble_gatt: max_rx_time: 328
[00:03:30.786,376] <debug> nrf_ble_gatt: max_tx_time: 328
[00:03:30.786,407] <info> app: Data length updated to 27 bytes.
[00:03:30.965,942] <debug> nrf_ble_gatt: Peer on connection 0x2 requested an ATT MTU of 527 bytes.
[00:03:30.965,972] <debug> nrf_ble_gatt: Updating ATT MTU to 0 bytes (desired: 0) on connection 0x2.
[00:03:30.966,125] <error> nrf_ble_gatt: sd_ble_gatts_exchange_mtu_reply() returned NRF_ERROR_INVALID_PARAM.
[00:03:30.966,156] <debug> nrf_ble_gatt: Peer on connection 0x2 requested an ATT MTU of 527 bytes.
[00:03:30.966,156] <debug> nrf_ble_gatt: Updating ATT MTU to 247 bytes (desired: 247) on connection 0x2.
[00:03:31.025,970] <debug> nrf_ble_gatt: ATT MTU updated to 23 bytes on connection 0x2 (response).
[00:03:31.025,970] <debug> nrf_ble_gatt: ATT MTU updated to 247 bytes on connection 0x2 (response).
[00:03:31.026,000] <info> app: ATT MTU exchange completed on connection 2. MTU set to 247 bytes.
[00:03:31.026,947] <info> app: BLE_GAP_EVT_SEC_PARAMS_REQUEST
[00:03:31.147,827] <debug> nrf_ble_lesc: BLE_GAP_EVT_LESC_DHKEY_REQUEST
[00:03:31.147,888] <info> app: BLE_GAP_EVT_LESC_DHKEY_REQUEST
[00:03:31.185,089] <info> nrf_ble_lesc: Calling sd_ble_gap_lesc_dhkey_reply on conn_handle: 2
[00:03:31.926,422] <info> app: BLE_GAP_EVT_CONN_SEC_UPDATE
[00:03:31.926,452] <info> app: Security mode: 2
[00:03:32.107,208] <info> peer_manager_handler: Connection secured: role: Peripheral, conn_handle: 2, procedure: Bonding
[00:03:32.107,299] <info> peer_manager_handler: Connection secured: role: Peripheral, conn_handle: 2, procedure: Bonding
[00:03:32.107,299] <info> peer_manager_handler: Attempting to clean flash.
[00:03:32.107,360] <info> app: BLE_GAP_EVT_AUTH_STATUS: status=0x0 bond=0x1 lv4: 0 kdist_own:0x3 kdist_peer:0x2
[00:03:32.288,757] <info> peer_manager_handler: Attempting to clean flash.
[00:03:32.289,031] <info> peer_manager_handler: Deleting lowest ranked peer (peer_id: 0)
[00:03:32.289,123] <info> peer_manager_handler: Attempting to clean flash.
[00:03:32.289,398] <info> peer_manager_handler: Deleting lowest ranked peer (peer_id: 1)
[00:03:32.297,485] <error> peer_manager_handler: Peer deleted successfully: peer_id: 0
[00:03:32.297,515] <error> peer_manager_handler: Peer deleted successfully: peer_id: 0
[00:03:32.297,882] <error> peer_manager_handler: Peer deleted successfully: peer_id: 0
[00:03:32.297,882] <error> peer_manager_handler: Peer deleted successfully: peer_id: 0
[00:03:32.300,048] <error> peer_manager_handler: Peer deleted successfully: peer_id: 1
[00:03:32.300,048] <error> peer_manager_handler: Peer deleted successfully: peer_id: 1
[00:03:32.300,384] <error> peer_manager_handler: Peer deleted successfully: peer_id: 1
[00:03:32.300,384] <error> peer_manager_handler: Peer deleted successfully: peer_id: 1
[00:03:32.406,127] <warning> peer_manager_gcm: CAR char value couldn't be stored (error: NRF_ERROR_INVALID_PARAM). Reattempt will happen on the next connection.
[00:03:36.726,623] <info> app: Disconnected.
[00:03:36.726,654] <info> app: Restarted advertising.

If I unpair de nRF from the external device (i.e. Windows PC or Android phone) and pair again, this seems to override the stored pairing and, sometimes, fix the issue. After the re-pairing everything works as expected.

An extra question: I tried pairing as many devices as I could, to test when the memory would fill up. I got that after 3 devices, the fourth one would override the 'lowest ranked peer'. This seems odd, since the memory page is like 4k and nothing else is storing data (that I know of, at least not our application). The bonding that is around 80 bytes from what I could see, so it doesn't make much sense. Maybe it's part of the same bug.

Thanks!

Parents
  • 0

    This was weird yes, maybe try with one of the BLE examples that support bonding as-is for comparison?

    What have you set FDS_VIRTUAL_PAGES, FDS_VIRTUAL_PAGE_SIZE and FDS_VIRTUAL_PAGES_RESERVED too?

    Do you have any bootloader here?

    Maybe try 'nrfjprog --erasell' from command line instead of Segger running "Target, Erase All". 

  • +1 in reply to Kenneth

    Hi Kenneth, thanks for the advice. I think I figured it out. There was a mistake on our app that was calling pm_handler_on_pm_evt from two different listeners. This explains the duplicate logging. After I fixed that, I was no longer able to get the "Attempting to clean flash" error or to fill the memory with just 3 devices (I was able to bond with 5 devices with no problem, which is all I have right now at home). So it looks like this was the issue.

    If this something like this happens again, meaning that not all of it was explained by this mistake, I'll update the post. Sorry for the inconvenience and thank you for your time.

Reply
  • +1 in reply to Kenneth

    Hi Kenneth, thanks for the advice. I think I figured it out. There was a mistake on our app that was calling pm_handler_on_pm_evt from two different listeners. This explains the duplicate logging. After I fixed that, I was no longer able to get the "Attempting to clean flash" error or to fill the memory with just 3 devices (I was able to bond with 5 devices with no problem, which is all I have right now at home). So it looks like this was the issue.

    If this something like this happens again, meaning that not all of it was explained by this mistake, I'll update the post. Sorry for the inconvenience and thank you for your time.

Children
No Data
Related