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:

Fullscreen

1

2

3

4

5

6

7

8

9

10

11

12

13

14

15

16

17

18

19

20

21

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)

{

XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX

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:

Fullscreen

1

2

3

4

5

6

7

8

9

10

11

12

13

14

15

16

17

18

19

20

21

[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

XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX

[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

The INVALID_STATE error when you start advertising points to the device thinking it still is in a connection or already is advertising. Please make sure that you disconnect before deleting the peers.

Best regards,

Simon

[daubsi]

Hi Simon, 

this is exactly still the problem I am still facing:

This is my current pm_evt_handler

Fullscreen

1

2

3

4

5

6

7

8

9

10

11

12

13

14

15

16

17

18

19

20

21

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:

need_peer_delete = false;

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");

need_peer_delete = true;

//delete_bonds();

break;

case PM_EVT_CONN_SEC_CONFIG_REQ:

{

// Allow pairing request from an already bonded peer.

XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX

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:
            need_peer_delete = false;
            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");
            need_peer_delete = true;
            //delete_bonds();
            break;
        case PM_EVT_CONN_SEC_CONFIG_REQ:
          {
            // Allow pairing request from an already bonded peer.
            pm_conn_sec_config_t conn_sec_config = {.allow_repairing = true};            
            pm_conn_sec_config_reply(p_evt->conn_handle, &conn_sec_config);
          }break;
        default:
            break;
    }
}

As you can say I asked pm to disconnect

Then I tried in

Fullscreen

1

2

3

4

5

6

7

8

9

10

11

12

13

14

15

16

17

18

19

20

21

static void on_ble_central_evt(ble_evt_t const * p_ble_evt)

{

...

...

case BLE_GAP_EVT_DISCONNECTED:

{

if (p_gap_evt->conn_handle == m_conn_handle_hrs_c)

{

...

}

if (p_gap_evt->conn_handle == m_conn_handle_cscs_c)

{

...

}

// This one triggers by PM

if ((p_gap_evt->params.disconnected.reason == BLE_HCI_LOCAL_HOST_TERMINATED_CONNECTION) && need_peer_delete)

{

NRF_LOG_INFO("Disconnected due to sec failure. Deleting peers.");

XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX

static void on_ble_central_evt(ble_evt_t const * p_ble_evt)
{
...
...
case BLE_GAP_EVT_DISCONNECTED:
        {
            
            if (p_gap_evt->conn_handle == m_conn_handle_hrs_c)
            {
                ...
            }
            
            if (p_gap_evt->conn_handle == m_conn_handle_cscs_c)
            {
                ...
            }

            // This one triggers by PM
            if ((p_gap_evt->params.disconnected.reason == BLE_HCI_LOCAL_HOST_TERMINATED_CONNECTION) && need_peer_delete)
            {
                    NRF_LOG_INFO("Disconnected due to sec failure. Deleting peers.");
                    delete_bonds();
                    need_peer_delete = false;
            }
            ...
            

Because that looked like the proper place?

It also DOES delete the bonds but crashes again with an INVALID_STATE.

If this is still not the proper place, kindly give me a very brief best-practice example how to do it. My code is based on ble_app_hrs_rscs_relay.

Thanks

[Simonr]

Hi

If you check out our other examples, we generally call the delete_bonds(); function at the start of the advertising_start() functions in most of our ble_peripheral examples. Keep in mind that you need to disconnect from the peer before you call advertising_start(). How does the "need_peer_delete" function you have created look?

Best regards,

Simon

[daubsi]

Hi Simon,

yes, I saw the way you do it in the advertising_start() but the thing is that this has already started in the ble_app_hrs_rscs_relay? I am scanning for the peripherals in the "backend" (the true BLE peripherals like the HRS) and offering the services in the "frontend" (e.g. to a smartphone). When there is now a problem while connecting in the backend to one of the sensors I might be able to disconnect there but not from a potentially already connected frontend device - though - in my tests not even that was the case, that there was already a connection.

So ofc I COULD just delete the peer information every time when I power on the device/restart the app but I would rather prefer a more clean variant, where it is only done when it is really needed? Like: trying to connect to backend service. Oops, bonding problem, disconnect, delete peer data, rescan/reconnect. I understand this would be the process I implmented. Nevertheless it faults with "INVALID_STATE"

need_peer_delete is just a boolean var that I set to true in (see above)

Fullscreen

1

2

3

4

5

6

7

8

9

10

...

...

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");

need_peer_delete = true;

//delete_bonds();

break;

...

XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX

...
...
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");
            need_peer_delete = true;
            //delete_bonds();
            break;
            
...

and that I am checking for in the BLE event handler too, to be sure it is exactly that event which gets triggered.

Fullscreen

1

2

3

...

if ((p_gap_evt->params.disconnected.reason == BLE_HCI_LOCAL_HOST_TERMINATED_CONNECTION) && need_peer_delete)

...

XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX

...
if ((p_gap_evt->params.disconnected.reason == BLE_HCI_LOCAL_HOST_TERMINATED_CONNECTION) && need_peer_delete)
...            

(meaning, the PM actually really disconnects and throws an event with "BLE_HCI_LOCAL_HOST_TERMINATED_CONNECTION" reason.

I suspected I would be able to call the delete_bonds() there safely... ("delete_bonds()" is just the same function you too have in your examples)

Is it possible what I try to achieve?

[Simonr]

Hi

I discussed this with a colleague, and they spotted something important that I missed when looking at your pm_evt_handler();. 

Fullscreen

1

2

3

4

case PM_EVT_PEERS_DELETE_SUCCEEDED:

need_peer_delete = false;

adv_scan_start();

break;

XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX

        case PM_EVT_PEERS_DELETE_SUCCEEDED:
            need_peer_delete = false;
            adv_scan_start();
            break;

The problem seems to be that when you get the PEERS_DELETE_SUCCEEDED event, you start the scan right away, however this event doesn't mean that the connection is already in the DISCONNECTED state. It will take a connection interval of time, or a "manual" disconnection for the SoftDevice to get the acknowledgement of this, so you should move the adv_scan_start(); function to your DISCONNECTED event instead.

Best regards,

Simon