Bonding problem with cheap BLE sensor and nRF DK52

[daubsi]

I am developing a CSCS client on my nRF52 DK and have two sensors at hand to test my implementation. Softdevice S132, SDK 17.0.2

My code is based on $SDKROOT\examples\ble_central_and_peripheral\experimental\ble_app_hrs_rscs_relay  with SDK 17.0.2

Though it has been heavily extended for some extra functionality, the basic service discovery and bonding is still the same as in the example, i.e.

Basically like this:

case BLE_CSCS_C_EVT_DISCOVERY_COMPLETE:
        {
            if (m_conn_handle_cscs_c == BLE_CONN_HANDLE_INVALID)
            {
                ret_code_t err_code;

                m_conn_handle_cscs_c = p_cscs_c_evt->conn_handle;
                NRF_LOG_INFO("Cycling Speed and Cadence service discovered on conn_handle 0x%x",
                             m_conn_handle_cscs_c);

                filter_settings_change();                
                err_code = ble_cscs_c_handles_assign(p_cscs_c,
                                                    m_conn_handle_cscs_c,
                                                    &p_cscs_c_evt->params.cscs_db);
                APP_ERROR_CHECK(err_code);
                
                // Initiate bonding.
                err_code = pm_conn_secure(m_conn_handle_cscs_c, false);
                
                if (err_code != NRF_ERROR_BUSY)
                {
                    APP_ERROR_CHECK(err_code);
                }
                
                // Cycling Speed Cadence Service discovered. Enable notifications.
                err_code = ble_cscs_c_csc_notif_enable(p_cscs_c);
                                
                APP_ERROR_CHECK(err_code);
            }
        } break; // BLE_C

The strange thing I now encounter through development is this:

Using the nRF Connect desktop app with an nRF52480 it works wonderful and stable. Connections are immediately recognized and bonded.

The same goes for a CSCS sensor from a known brand. Also here the connection works very well. However this sensor is fixed to my bike so I bought a cheesy cheap CSCS sensor on Ebay to have it on my desk. With this sensor I am constantly encountering problems during the pm_conn_secure.

Basically it goes on over and over again like this:

[00:00:45.429,992] <info> peer_manager_handler: Peer data updated in flash: peer_id: 0, data_id: Peer rank, action: Update, no change
[00:00:45.430,786] <warning> peer_manager_gcm: The local database has changed, so some subscriptions to notifications and indications could not be restored for conn_handle 0
[00:00:45.431,701] <warning> peer_manager_handler: Local DB could not be applied: conn_handle: 0, peer_id: 0
[00:00:45.432,312] <info> app: Central connected
[00:00:45.432,617] <info> app: Attempt to find peripheral services on conn_handle 0x0
[00:00:45.439,147] <info> peer_manager_handler: Connection security failed: role: Central, conn_handle: 0x0, procedure: Encryption, error: 4102
[00:00:45.439,941] <warning> peer_manager_handler: Disconnecting conn_handle 0.
[00:00:45.440,368] <info> app: Establishing a secure link by Peer Manager failed! Please press Button 2 + RESET on the DK to delete bonding data
[00:00:45.450,073] <error> nrf_ble_gq: SD GATT procedure (2) failed on connection handle 0 with error: 0x00000008.
[00:00:45.450,683] <info> app: DB Discovery instance 0x20002E30 available on conn handle: 0
[00:00:45.451,232] <info> app: Found 0 services on conn_handle: 0
[00:00:45.755,432] <info> peer_manager_handler: Peer data updated in flash: peer_id: 0, data_id: Peer rank, action: Update, no change
[00:00:45.756,164] <warning> peer_manager_gcm: The local database has changed, so some subscriptions to notifications and indications could not be restored for conn_handle 0
[00:00:45.757,141] <warning> peer_manager_handler: Local DB could not be applied: conn_handle: 0, peer_id: 0
[00:00:45.757,751] <info> app: Central connected
[00:00:45.757,995] <info> app: Attempt to find peripheral services on conn_handle 0x0
[00:00:45.764,587] <info> peer_manager_handler: Connection security failed: role: Central, conn_handle: 0x0, procedure: Encryption, error: 4102
[00:00:45.765,319] <warning> peer_manager_handler: Disconnecting conn_handle 0.
[00:00:45.765,808] <info> app: Establishing a secure link by Peer Manager failed! Please press Button 2 + RESET on the DK to delete bonding data
[00:00:45.775,451] <error> nrf_ble_gq: SD GATT procedure (2) failed on connection handle 0 with error: 0x00000008.
[00:00:45.776,123] <info> app: DB Discovery instance 0x20002E30 available on conn handle: 0
[00:00:45.776,611] <info> app: Found 0 services on conn_handle: 0
[00:00:46.081,054] <info> peer_manager_handler: Peer data updated in flash: peer_id: 0, data_id: Peer rank, action: Update, no change
[00:00:46.081,848] <warning> peer_manager_gcm: The local database has changed, so some subscriptions to notifications and indications could not be restored for conn_handle 0
[00:00:46.082,763] <warning> peer_manager_handler: Local DB could not be applied: conn_handle: 0, peer_id: 0
[00:00:46.083,374] <info> app: Central connected
[00:00:46.083,679] <info> app: Attempt to find peripheral services on conn_handle 0x0
[00:00:46.095,642] <info> peer_manager_handler: Connection security failed: role: Central, conn_handle: 0x0, procedure: Encryption, error: 4102
[00:00:46.096,435] <warning> peer_manager_handler: Disconnecting conn_handle 0.
[00:00:46.096,862] <info> app: Establishing a secure link by Peer Manager failed! Please press Button 2 + RESET on the DK to delete bonding data
[00:00:46.108,398] <error> nrf_ble_gq: SD GATT procedure (2) failed on connection handle 0 with error: 0x00000008.

Either error code 4102 or 4352:

Macros
#define PM_CONN_SEC_ERROR_PIN_OR_KEY_MISSING (PM_CONN_SEC_ERROR_BASE + 0x06)
Encryption failed because the peripheral has lost the LTK for this bond. See also BLE_HCI_STATUS_CODE_PIN_OR_KEY_MISSING and Table 3.7 ("Pairing Failed Reason Codes") in the Bluetooth Core Specification 4.2, section 3.H.3.5.5 (Bluetooth Core Specification).

#define PM_CONN_SEC_ERROR_DISCONNECT (PM_CONN_SEC_ERROR_BASE + 0x100)
Pairing or encryption did not finish before the link disconnected for an unrelated reason.

The only option then is to erase the peer data which I implemented when button 2 is pressed during reset. It then works for some time until it starts to freak out again

Yesterday it was so strange, that my nrf52DK even crashed during that time and I was searching for the error I seemed to have introduced in my code for 30min until I tried with nRF Connect as a client peripheral and saw it immediately worked perfectly (so it was again a new error when communicating with that sensor - though this shouldn't affect MY DK nevertheless....).

BTW: The cheap sensor seems to be build around a nRF chip as well, as it also offers the nRF DFU services ;-)

The question is: How can I cope with this erraneous situation without constantly flushing my peer/link/key database?

I see there are some posts in devzone for this topic, but none of this was helpful to solve my problem:

https://devzone.nordicsemi.com/f/nordic-q-a/63038/nrf52-bonding-error-4352-while-trying-to-bond-with-a-cots-medical-device-wearable

https://devzone.nordicsemi.com/f/nordic-q-a/52284/about-error-code-4352

https://devzone.nordicsemi.com/f/nordic-q-a/49894/peermanager-error-error-4352

https://devzone.nordicsemi.com/f/nordic-q-a/42384/connection-security-failed-role-central-in-ble_app_rscs_c

I am aware that it's probably a **** sensor firmware which causes this trouble but I wonder how I can cope with this? Can I somehow _force_  to rebond with a new key or something?

I think there was another thread that I cannot find anymore where another dev described a problem very related to mine. The problems with the peering started once he flashed a new version on the DK, as if that corrupted somethign... Will try to dig it out again...

[Simonr]

Hi

This sounds very strange. I'm not able to see that error 4352 is triggered anywhere in your log, but error 4102 is indeed a faulty or missing pin/key. This means that encryption has failed because the peripheral has lost the LTK for this bond. This issue should be fixed by deleting bond information on the central as well. You could, for example make your central device delete its bonding information whenever it runs into this error and start scanning again.

Alternatively, try contacting the manufacturers of the sensor you got (if possible), and ask if this is something they're aware of and have a firmware update available for.

Best regards,

Simon

[daubsi]

Dear Simonr,

my bad - I should have actually included the relevant log lines with error 4352 as well. Anyway, they exist and it seems it's either 4352, 4102 or a combination thereof. 

Yes, deleting the bonding information is what I just did for the last couple of weeks, but it's kinda cumbersome and I was wondering if there isn't a better way to handle this? The vendor is from the Asia reagion. I can ofc get in touch with him but I have little hope they can actually help me here... as people say "Buy cheap, buy twice" :-/

Just to understand this correctly: The error occurs because.... the DK still knows the key and tries to encrypt the channel but the peripheral says "I don't know what you're talking about" and shuts down the connection? So the question would be WHY the peripheral loses the key. I've put fresh batteries in and all that, so it shouldn't be a power supply thing.

[Simonr]

daubsi said:

Just to understand this correctly: The error occurs because.... the DK still knows the key and tries to encrypt the channel but the peripheral says "I don't know what you're talking about" and shuts down the connection?

 That's correct, the peripheral has lost the LTK for some reason, this could be that it has its own "delete bonding" that is called for some reason where it shouldn't, or that this key is stored somewhere it is prone to being deleted. I'm sorry, but for this specific issue, there is nothing you can do in the central except deleting bond information on the central side as well and pair/bond again.

Best regards,

Simon

[daubsi]

Thank you! I wasn't sure about "I'm sorry, but for this specific issue, there is nothing you can do in the central except deleting bond information on the central side as well and pair/bond again." but now that you confirm that's the only option I'll go for this one! Have a great day!

[daubsi]

Simon, I was just trying to do the peer removal as suggested, but when I now call delete_bonds() inside of pm_evt_handler() (which basically just calls pm_peers_delete()), I get an error 

[00:00:00.905,151] <info> peer_manager_handler: Connection security failed: role: Central, conn_handle: 0x0, procedure: Encryption, error: 4102
[00:00:00.905,944] <warning> peer_manager_handler: Disconnecting conn_handle 0.
[00:00:00.906,372] <info> app: Establishing a secure link by Peer Manager failed! Trying to remove bonds and rescan
[00:00:00.907,043] <info> app: Erase bonds!
[00:00:00.910,034] <error> peer_manager_handler: Peer deleted successfully: peer_id: 0
[00:00:00.910,461] <info> peer_manager_handler: All peers deleted.
[00:00:00.910,888] <error> app: ERROR 8 [NRF_ERROR_INVALID_STATE] at D:\nRF5_SDK_17.0.2_d674dde\xxxx\main.c:439
PC at: 0x00031D51

Line 439 is the last APP_ERROR_CHECK in:

static void adv_scan_start(void)
{
    ret_code_t err_code;

    //check if there are no flash operations in progress
    if (!nrf_fstorage_is_busy(NULL))
    {
        // Start scanning for peripherals and initiate connection to devices which
        // advertise Heart Rate or Cycling speed and cadence UUIDs.
        scan_start();

        // Turn on the LED to signal scanning.
        bsp_board_led_on(CENTRAL_SCANNING_LED);

        // Start advertising.
        err_code = ble_advertising_start(&m_advertising, BLE_ADV_MODE_FAST);
        APP_ERROR_CHECK(err_code);
    }
}

(i.e. checking the return value from ble_advertising_start()). What's the proper way of doing the peer delete and restarting the whole scan process, please?

BR
Markus

static void pm_evt_handler(pm_evt_t const * p_evt)
{
pm_handler_on_pm_evt(p_evt);
pm_handler_disconnect_on_sec_failure(p_evt);
pm_handler_flash_clean(p_evt);

switch (p_evt->evt_id)
{
case PM_EVT_PEERS_DELETE_SUCCEEDED:
adv_scan_start();
break;
case PM_EVT_CONN_SEC_FAILED:
//NRF_LOG_INFO("Establishing a secure link by Peer Manager failed! Please press Button 2 + RESET on the DK to delete bonding data");
NRF_LOG_INFO("Establishing a secure link by Peer Manager failed! Trying to remove bonds and rescan");
delete_bonds();
break;
default:
break;
}
}