LESC_ENC_MITM unexplained delay after BLE_GAP_EVT_LESC_DHKEY_REQUEST

[habibfarahani]

Hi,

In my current project based on SDK 15.3 and sd140, I am using nrf52840 in both peripheral and central devices.  I need to be able to maintain 10 concurrent connections and transfer multi KB sensory data over encrypted NUS.  So far the connection and transfer works great for all 10 connections.

The biggest hurdle that I am trying to tackle is some unexplained delay (I am sure someone who reads this can explain) after BLE_GAP_EVT_LESC_DHKEY_REQUEST is received by the Peripheral, depending on the number of connections on the Central side, a significant delay can be injected before the Peripheral receives BLE_GAP_EVT_CONN_SEC_UPDATE (~900 ms per connection).  I do see that the Peripheral immediately responds with sd_ble_gap_lesc_dhkey_reply(...) but then after that there is a period of inactivity (900ms * connections).

Ultimately the secure connection succeeds and the pair start their data exchange.  However, this delay causes the Peripheral to consume its precious battery, which will become worse as more devices attach.   The sequence of events received in the Peripheral side is exactly as depicted in

nRF52 Series > SoftDevices > S140 SoftDevice > S140 SoftDevice v6.1.0 API > API Reference > Generic Access Profile (GAP) > Message Sequence Charts > Peripheral Security Procedures > Peripheral LESC Pairing  (Bonding: Passkey Entry, Peripheral Displays)

Any feedback would be greatly appreciated.

Cheers,

[Einar Thorsrud]

Hi,

The crypto operations involves quite a bit of processing, which is why it takes a long time. To see this in more detail, the request is handled like this using the peer manager:

1. In nrf_ble_lesc.c, the BLE event handler of the peer manager, nrf_ble_lesc_on_ble_evt(), calls on_dhkey_request() for any BLE_GAP_EVT_LESC_DHKEY_REQUEST events. This flags that this event for this connection handle, but does not process it as that is time consuming and this happens in an interrupt.
2. The main loop of the app calls nrf_ble_lesc_request_handler(), and this is doen in order to make this happen outside an interrupt (so with lowest priority). This checks for any pending requests and processes them in the compute_and_give_dhkey() function.

There is no way around this, other than making sure you are using the CC310 crypto backend (which is default in the SDK examples for the nRF52840) or using legacy pairing instead of LESC, if the reduction in security is acceptable.

[habibfarahani]

Hi Einar,

Thanks for your reply and I agree with all your points.  Security and encryption are very important in this project.  CC310 hw crypto block is one of the main feature sets that enticed me to select nRF52840.  I have enabled CC310 backend similar to multi role example.  Both Central and Peripheral devices are configured the same, using libnrf_cc310_0.9.12a in addition to nRF_Crypto cc310_backend modules and nrf_crypto modules (just like multirole example).  

compute_and_give_dhkey() does not seem to take long at all ( a few millisecond) But it seems that once that function is done the system is waiting for something else.  This something else seems to add ~900 ms per active connection.  Logs below show the progression and time stamps in both Peripheral and Central sides.

On the Central side:

<info> app: BLE_GAP_EVT_SEC_PARAMS_REQUEST
<debug> app: BLE_GAP_EVT_AUTH_KEY_REQUEST
<info> app: BLE_GAP_EVT_AUTH_KEY_REQUEST
<debug> nrf_ble_lesc: BLE_GAP_EVT_LESC_DHKEY_REQUEST
<info> nrf_ble_lesc: ENTER  compute_and_give_dhkey on conn_handle: 6 ts: 978610
<info> nrf_ble_lesc: Calling sd_ble_gap_lesc_dhkey_reply on conn_handle: 6
<info> nrf_ble_lesc: EXIT  compute_and_give_dhkey on conn_handle: 6 ts: 978629
<info> app: BLE_GAP_EVT_AUTH_STATUS [6::983394]

In Peripheral Side:

<info> app: ble event ahndler: BLE_GAP_EVT_LESC_DHKEY_REQUEST TS:7387
<info> nrf_ble_lesc: ENTER  compute_and_give_dhkey on conn_handle: 0 ts: 7395
<info> nrf_ble_lesc: Calling sd_ble_gap_lesc_dhkey_reply on conn_handle: 0
<info> nrf_ble_lesc: EXIT  compute_and_give_dhkey on conn_handle: 0 ts: 7429
<info> app: BLE_GAP_EVT_CONN_SEC_UPDATE TS:12278
<info> peer_manager_handler: Event PM_EVT_CONN_SEC_SUCCEEDED

As shown in the two logs above in central side the routine entered compute and give dhkey() at 978610 (connection 6)  and left about 19 ms later  (ENTER and EXIT are the logs I added and the time stamps were acquired from freeRTOS) Then all was quite until BLE_GAP_EVT_AUTH_STATUS was received at 983394ms  (about 4.765 seconds later)

Similarly in Peripheral side BLE_GAP_EVT_LESC_DHKEY_REQUEST was received at 7387, and dhkey computation took very little time to calculate until BLE_GAP_EVT_CONN_SEC_UPDATE was received at 12278 (about 4.849 seconds later)

As I mentioned this latency increases as the number of connections increase and I cannot find the correlation between # connections and key generation.  I am confident that something in my config is not set properly and that is why this behavior is manifesting itself as such.

Cheers

[Einar Thorsrud]

Hi,

I see. Then we need to look in a different direction. What are the BLE connection parameters? Is there much other BLE traffic between the central and allready paired peripherals when the central pairs with a new one?

[habibfarahani]

Hi Einar,

Sure, I will provide the parameters below.  But to answer your question: under normal conditions yes, there will a stream of data via NUS (with all three characteristics set to SEC_LESC_MITM) as soon as the connection is established.  At first I thought may be this is the cause of the incremental latency, so I disabled all the handshake and now each device connects, exchange their keys, and remain connected with no traffic.  I did not see any difference in the latency in terms of BLE traffic.  As shown in log above after "EXIT" there are no events during that 4.7 seconds.  If I have communication going, I do see NUS Read and Write events during this period.  Interestingly enough, I do get scan events during this time period.

Below are connection and security settings on the peripheral side:

#define APP_ADV_INTERVAL                        100//300                               /**< The advertising interval (in units of 0.625 ms. This value corresponds to 187.5 ms). */
#define APP_ADV_DURATION                        18000                                  /**< The advertising duration (180 seconds) in units of 10 milliseconds. */
#define FIRST_CONN_PARAMS_UPDATE_DELAY          APP_TIMER_TICKS(5000)                  /**< Time from initiating event (connect or start of notification) to first time sd_ble_gap_conn_param_update is called (5 seconds). */
#define NEXT_CONN_PARAMS_UPDATE_DELAY           APP_TIMER_TICKS(30000)                 /**< Time between each call to sd_ble_gap_conn_param_update after the first call (30 seconds). */
#define MAX_CONN_PARAMS_UPDATE_COUNT            3                                      /**< Number of attempts before giving up the connection parameter negotiation. */

#define NETODSE_MAIN_TIMER_INTERVAL             100//1000                                    /**< Heart rate measurement interval (ms). or it could be timer ticks using: APP_TIMER_TICKS(1000)*/

#define MIN_CONN_INTERVAL                   MSEC_TO_UNITS(7.5, UNIT_1_25_MS)        /**< Minimum acceptable connection interval (0.4 seconds). */
#define MAX_CONN_INTERVAL                   MSEC_TO_UNITS(400, UNIT_1_25_MS)        /**< Maximum acceptable connection interval (0.65 second). */
#define SLAVE_LATENCY                       0                                       /**< Slave latency. */
#define CONN_SUP_TIMEOUT                    MSEC_TO_UNITS(4000, UNIT_10_MS)         /**< Connection supervisory time-out (4 seconds). */


#define SEC_PARAM_BOND                      0                                       /**< Perform bonding. */
#define SEC_PARAM_KEY_DISTRO                0
#define SEC_PARAM_MITM                      1                                       /**< Man In The Middle protection not required. */
#define SEC_PARAM_LESC                      1                                       /**< LE Secure Connections not enabled. */
#define SEC_PARAM_KEYPRESS                  0                                       /**< Keypress notifications not enabled. */
#define SEC_PARAM_IO_CAPABILITIES           BLE_GAP_IO_CAPS_DISPLAY_ONLY
#define SEC_PARAM_OOB                       0                                       /**< Out Of Band data not available. */
#define SEC_PARAM_MIN_KEY_SIZE              7                                       /**< Minimum encryption key size. */
#define SEC_PARAM_MAX_KEY_SIZE              16                                      /**< Maximum encryption key size. */




static void gap_params_init(void)
{
    ret_code_t              err_code;
    ble_gap_conn_params_t   gap_conn_params;
    ble_gap_conn_sec_mode_t sec_mode;
    uint8_t                 mac[BLE_GAP_ADDR_LEN];
    uint8_t                 name[9];


    BLE_GAP_CONN_SEC_MODE_SET_OPEN(&sec_mode);
 

    memset(&gap_conn_params, 0, sizeof(gap_conn_params));

    gap_conn_params.min_conn_interval = MIN_CONN_INTERVAL;
    gap_conn_params.max_conn_interval = MAX_CONN_INTERVAL;
    gap_conn_params.slave_latency     = SLAVE_LATENCY;
    gap_conn_params.conn_sup_timeout  = CONN_SUP_TIMEOUT;

    err_code = sd_ble_gap_ppcp_set(&gap_conn_params);
    APP_ERROR_CHECK(err_code);

}


static void advertising_init(void)
{

    // Cosntruct GAP buffer using the parameters received from Happy Gecko

    static uint8_t  netdoseGAPData[MAX_MFR_GAP_SIZE];
    uint8_t len = 0;

    memcpy(&netdoseGAPData[len], &pDevice->m_rng, sizeof(uint16_t));      // Since customer ID is not being used overwrite it with rng(FOR NOW)
    len += sizeof(uint16_t);
    memcpy(&netdoseGAPData[len], &pDevice->m_boardId, sizeof(uint16_t));      // Since customer ID is not being used overwrite it with rng(FOR NOW)
    len += sizeof(uint16_t);

    static ble_advdata_manuf_data_t manuf_specific_data =      /**< Advertising data structure for Thermo Fisher Netdose dosimeter. */
    {

        .company_identifier = MANUFACTURER_ID,                 /**< ------- Bluetooth.org vendor ID */
        .data               =
            {
                .size   = sizeof(uint16_t)+sizeof(uint16_t),
                .p_data = &netdoseGAPData[0]
            }
    };


    // Populate the init structure for the SDK
    ble_advertising_init_t init;
      
    memset(&init, 0, sizeof(init));
      

    init.advdata.name_type               =  BLE_ADVDATA_NO_NAME;//BLE_ADVDATA_FULL_NAME;
    init.advdata.include_appearance      = false;//true;
    init.advdata.flags                   = 0;//BLE_GAP_ADV_FLAGS_LE_ONLY_GENERAL_DISC_MODE;

    init.config.ble_adv_fast_enabled  = true;
    init.config.ble_adv_fast_interval = APP_ADV_INTERVAL;
    init.config.ble_adv_fast_timeout  = APP_ADV_DURATION;

    init.evt_handler = on_adv_evt;
    //init.error_handler = ble_advertising_error_handler;


    init.advdata.p_manuf_specific_data = &manuf_specific_data;
    ret_code_t err_code = ble_advertising_init(&m_advertising, &init);
    APP_ERROR_CHECK(err_code);

    ble_advertising_conn_cfg_tag_set(&m_advertising, APP_BLE_CONN_CFG_TAG);


}

static void peer_manager_init(void)
{
    ble_gap_sec_params_t sec_param;
    ret_code_t           err_code;

    err_code = pm_init();
    APP_ERROR_CHECK(err_code);

    memset(&sec_param, 0, sizeof(ble_gap_sec_params_t));

    // Security parameters to be used for all security procedures.
    sec_param.bond           = SEC_PARAM_BOND;
    sec_param.mitm           = SEC_PARAM_MITM;
    sec_param.lesc           = SEC_PARAM_LESC;
    sec_param.keypress       = SEC_PARAM_KEYPRESS;
    sec_param.io_caps        = SEC_PARAM_IO_CAPABILITIES;
    sec_param.oob            = SEC_PARAM_OOB;
    sec_param.min_key_size   = SEC_PARAM_MIN_KEY_SIZE;
    sec_param.max_key_size   = SEC_PARAM_MAX_KEY_SIZE;
    sec_param.kdist_own.enc  = SEC_PARAM_KEY_DISTRO;
    sec_param.kdist_own.id   = SEC_PARAM_KEY_DISTRO;
    sec_param.kdist_peer.enc = SEC_PARAM_KEY_DISTRO;
    sec_param.kdist_peer.id  = SEC_PARAM_KEY_DISTRO;

    err_code = pm_sec_params_set(&sec_param);
    APP_ERROR_CHECK(err_code);

    err_code = pm_register(pm_evt_handler);
    APP_ERROR_CHECK(err_code);
}

In Central side:

#define SCAN_INTERVAL           300//0x00A0            /**< Determines scan interval in units of 0.625 millisecond. */
#define SCAN_WINDOW             300//0x0050            /**< Determines scan window in units of 0.625 millisecond. */
#define SCAN_DURATION           0x0000                 /**< Timout when scanning. 0x0000 disables timeout. */

#define MIN_CONNECTION_INTERVAL MSEC_TO_UNITS(7.5/*0x06*/, UNIT_1_25_MS)         /**< Determines minimum connection interval in millisecond. */
#define MAX_CONNECTION_INTERVAL MSEC_TO_UNITS(400/*0x18*/, UNIT_1_25_MS)         /**< Determines maximum connection interval in millisecond. */
#define SLAVE_LATENCY           0                                       /**< Determines slave latency in counts of connection events. */
#define SUPERVISION_TIMEOUT     MSEC_TO_UNITS(4000, UNIT_10_MS)         /**< Determines supervision time-out in units of 10 millisecond. */




/**@brief Connection parameters requested for connection. */
static ble_gap_conn_params_t const m_connection_param =
{
    (uint16_t)MIN_CONNECTION_INTERVAL,  // Minimum connection
    (uint16_t)MIN_CONNECTION_INTERVAL,  // Maximum connection
    (uint16_t)SLAVE_LATENCY,            // Slave latency
    (uint16_t)SUPERVISION_TIMEOUT       // Supervision time-out
};





static ble_gap_scan_params_t m_scan_param =               /**< Scan parameters requested for scanning and connection. */
{
    .active             = 1,
    .interval           = SCAN_INTERVAL,
    .window             = SCAN_WINDOW,
    .timeout            = SCAN_DURATION,
    .scan_phys          = BLE_GAP_PHY_1MBPS,
    .filter_policy      = BLE_GAP_SCAN_FP_ACCEPT_ALL,

};

static void scan_init(void)
{
    ret_code_t          err_code;
    nrf_ble_scan_init_t init_scan;

    memset(&init_scan, 0, sizeof(init_scan));

    init_scan.connect_if_match = true;
    init_scan.conn_cfg_tag     = APP_BLE_CONN_CFG_TAG;
    init_scan.p_scan_param     = &m_scan_param;

    err_code = nrf_ble_scan_init(&m_scan, &init_scan, scan_evt_handler);
    APP_ERROR_CHECK(err_code);

}

Thanks again for all the help.

Best,

Habib

[habibfarahani]

By the way, comparing this with the flow graph in the link specified in the original post, the latency seems to occue while the pair are trying to "Encrypted with LTK" phase.

One more data point that might help.  After I started sniffing the BLE traffic (using nRF52 sniffer) I realized that after pairing public key exchange hundreds of paring random (opcode 0x04) and paring confirm (opcode 0x03) is exchanged between Master and Slave (as noted in wireshark).  When I change the central device to my nrf connect iOs App, not only do I not see the latency, but I also do not see the random pairing.

[Einar Thorsrud]

Hi,

There are several interesting points here. Unfortunately I did not get a chance to look properly at it today, but I will look more into it tomorrow and get back to you.

[Einar Thorsrud]

Hi Habib,

I do not have an explanation for the many pairing random and pairing confirmed commands in the sniffer trace. Can you upload the trace? If you have code that can reproduce this on a set of DKs, then that would also be good.