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:
- Some peer_manager_handler messages are logged twice
- 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!
