New association request on second Central connection

[Armando]

Hi,

I'm encountering a strange problem with the nRF52832 when it works as Central with two bonded Peripherals connection.

In particular I'm able to secure the connection with the first Peripherals by calling the pm_handler_secure_on_connection() function as soon as the BLE_GAP_EVT_CONNECTED event is sent by the softdevice.

When I establish the connection with the second one Peripheral (a smartphone) I receive a new association request on the smartphone display, please consider that the device was previously bonded.

If I accept the new pairing with the device (by pressing “OK” on the smartphone display, I use the Just Works method) a new bonding occurs and the connection is secured, after a disconnection I have to pair again.

I use the scan with policy WHITELIST and I call the  sd_ble_gap_connect() function when the NRF_BLE_SCAN_EVT_WHITELIST_ADV_REPORT occurs.

Any idea about the problem?

[Armando]

Hi,

I've noticed that the function sm_sec_is_sufficient(), into the Security Manger, ruturns with false  and the link_secure(p_event->conn_handle, null_params, force_repairing, true) is called with the  parameter force_repairing == true. I think that this couse the new pairing with the smartphone.

I have put some log messages into the sm_sec_is_sufficient(uint16_t conn_handle, pm_conn_sec_status_t * p_sec_status_req) function and I found the following value:

conn_handle                      == 1

p_sec_status_req->connected      == 0
p_sec_status_req->encrypted      == 0
p_sec_status_req->mitm_protected == 1
p_sec_status_req->bonded         == 1
p_sec_status_req->lesc           == 1
p_sec_status_req->reserved       == 0

sec_status->connected      == 1
sec_status->encrypted      == 1
sec_status->mitm_protected == 0
sec_status->bonded         == 1
sec_status->lesc           == 0
sec_status->reserved       == 7

unmet_reqs = 20;

Seems that the security status of my connection is insufficient, but my question is why the connection with the same smartphone works when it is the only Peripheral connected with my Central device?

[Edvin]

Edvin said:

Can you try to disconnect from the phone, instead of resetting the nRF52, please?

 The reason I asked you to check this is because it may be that your peripheral isn't storing the bonding information properly if you just cut the power. Please try to disconnect from the phone's bluetooth settings page, so that the nRF has the chance to store the bonding data. Does it have the same behavior then?

[Armando]

Hi,

I'm sorry if I haven't explained well the situation, please see the following image.

I never reset my "CENTRAL Device" (nRF52) in order to disconnect the Smartphone (that works as Peripheral). In order to disconnect the smartphone I close the App or turn-off the Bluetooth interface of the phone.

 I turn-off the "Peripheral Device 1" in order to disconnect it from my "CENTRAL Device".

[Edvin]

Just adding your log for readability:

00> [00:01:13.167,236] <info> app: CENTRAL: Trying to Connect with, peripheral with service ID: 0.
00>
00> [00:01:13.167,236] <info> app: CENTRAL EVT: 16.
00>
00> [00:01:13.167,236] <debug> peer_manager_handler: Connected, securing connection. conn_handle: 0
00>
00> [00:01:13.167,236] <debug> peer_manager_handler: Event PM_EVT_CONN_SEC_PARAMS_REQ
00>
00> [00:01:13.167,236] <debug> peer_manager_handler: Security parameter request
00>
00> [00:01:13.167,236] <info> app: PM_EVT_CONN_SEC_PARAMS_REQ
00>
00>
00>
00> [00:01:13.167,236] <debug> peer_manager_handler: Event PM_EVT_CONN_SEC_START
00>
00> [00:01:13.167,236] <debug> peer_manager_handler: Connection secu: Bonding
00>
00>
00> [00:01:13.167,236] <info> app: CENTRAL: Connected, handle: 0.
00>
00> [00:01:13.167,236] <debug> nrf_ble_gq: Purging request queue with id: 0
00>
00> [00:01:13.167,236] <debug> nrf_ble_gq: Registering connection handle: 0x0000
00>
00> [00:01:13.167,236] <debug> ble_db_disc: Starting discovery of service with UUID 0xE128 on connection handle 0x0.
00>
00> [00:01:13.167,236] <debug> nrf_ble_gq: Adding item to the request queue
00>
00> [00:01:13.167,236] <debug> nrf_ble_gq: GATTC Primary Services Discovery Request
00>
00> [00:01:13.167,236] <debug> nrf_ble_gq: SD GATT procedure (2) suc[00:01:13.167,236]
00>
00> [00:01:13.167,236] <info> app: CENTRAL EVT: 29.
00>
00> [00:01:13.167,236] <debug> nrf_ble_gq: Processing the request queue...
00>
00> [00:01:13.167,236] <debug> ble_db_disc: Found service UUID 0xE128.
00>
00> [00:01:13.167,236] <debug> nrf_ble_gq: Adding item to the request queue
00>
00> [00:01:13.167,236] <debug> nrf_ble_gq: GATTC Characteristic Discovery Request
00>
00> [00:01:13.167,236] <debug> nrf_ble_gq: SD GATT procedure (3) succeeded on connection handle: 0.
00>
00> [00:01:13.167,236] <info> app: CENTRAL EVT: 48.
00>
00> [00:01:13.167,236] <info> app: CENTRAL EVT: 18.
00>
00> [00:01:13.167,236] <info> app: BLE_GAP_EVT_CONN_PARAM_UPDATE
00>
00> [00:01:13.167,236] <debug> nrf_ble_gq: Processing the request queue...
00>
00> [00:01:13.167,236] <debug> nrf_ble_gq: Adding item to the request queue
00>
00> [00:01:13.167,236] <debug> nrf_ble_gq: GATTC Characteristic Discovery Request
00>
00> [00:01:13.167,236] <debug> nrf_ble_gq: SD GATT procedure (3) succeeded on connection handle: 0.
00>
00> [00:01:13.167,236] <info> app: CENTRAL EVT: 50.
00>
00> [00:01:13.167,236] <debug> nrf_ble_gq: Processing the request queue...
00>
00> [00:01:13.167,236] <debug> nrf_ble_gq: Adding item to the request queue
00>
00> [00:01:13.167,236] <debug> nrf_ble_gq: GATTC Characteristic Descriptor Request
00>
00> [00:01:13.167,236] <debug> nrf_ble_gq: SD GATT procedure (4) succeeded on connection handle: 0.
00>
00> [00:01:13.167,236] <info> app: CENTRAL EVT: 50.
00>
00> [00:01:13.167,236] <debug> peer_manager_handler: Event PM_EVT_CONN_SEC_PARAMS_REQ
00>
00> [00:01:13.167,236] <debug> peer_manager_handler: Security parameter request
00>
00> [00:01:13.167,236] <debug> nrf_ble_gq: Processing the request queue...
00>
00> [00:01:13.167,236] <debug> ble_db_disc: Discovery of service with UUID 0xE128 completed with success on connection handle 0x0.
00>
00> [00:01:13.167,236] <debug> ble_db_disc: Starting discovery of service with UUID 0x180D on connection handle 0x0.
00>
00> [00:01:13.167,236] <debug> nrf_ble_gq: Adding item to the request queue
00>
00> [00:01:13.167,236] <debug> nrf_ble_gq: GATTC Primary Services Discovery Request
00>
00> ceeded on connection handle: 0.
00>
00> [00:01:13.167,236] <debug> nrf_ble_gq: Processing the request queue...
00>
00> [00:01:13.167,236] <debug> nrf_ble_gq: Adding item to the request queue
00>
00> [00:01:13.167,236] <debug> nrf_ble_gq: GATTC Write Request
00>
00> [00:01:13.167,236] <debug> nrf_ble_gq: SD GATT procedure (1) succeeded on connection handle: 0.
00>
00> [00:01:13.916,381] <info> app: BLE_GAP_EVT_CONN_PARAM_UPDATE
00>
00> [00:01:14.318,786] <debug> peer_manager_handler: Event PM_EVT_CONN_SEC_SUCCEEDED
00>
00> [00:01:14.318,786] <info> peer_manager_handler: Connection secured: role: Central, conn_handle: 0, procedure: Bonding
00>
00> [00:01:14.318,908] <info> app: PM_EVT_CONN_SEC_SUCCEEDED
00>
00> [00:01:14.392,456] <debug> peer_manager_handler: Event PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
00>
00> [00:01:14.392,456] <info> peer_manager_handler: Peer data updated in flash: peer_id: 0, data_id: Bonding data, action: Update
00>
00> [00:01:14.392,883] <info> app: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
00>
00> [00:01:14.395,263] <debug> peer_manager_handler: Event PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
00>
00> [00:01:14.395,263] <info> peer_manager_handler: Peer data updated in flash: peer_id: 0, data_id: Peer rank, action: Update
00>
00> [00:01:14.395,507] <info> app: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
00>
00>
00>
00> [00:01:14.400,939] <debug> peer_manager_handler: Event PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
00>
00>
00> [00:01:14.401,184] <info> app: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
00>
00>
00>
00> [00:01:14.863,952] <debug> nrf_ble_gq: Processing the request queue...
00>
00> [00:01:14.864,013] <debug> ble_hrs_c: Received HVX on link 0x0, not associated to this instance. Ignore.
00>
00> [00:01:14.864,013] <info> app: CENTRAL EVT: 57.
00>
00> [00:01:15.629,028] <info> app: CENTRAL EVT: 31.
00>
00> [00:01:15.629,028] <info> app: BLE_GAP_EVT_CONN_PARAM_UPDATE_REQUEST
00>
00>
00>
00> [00:01:15.681,396] <info> app: CENTRAL EVT: 18.
00>
00> [00:01:15.681,396] <info> app: BLE_GAP_EVT_CONN_PARAM_UPDATE
00>
00>
00>
00> [00:01:18.289,184] <info> app: CENTRAL EVT: 17.
00>
00> [00:01:18.289,184] <info> app: CENTRAL: Disconnected, handle: 0, reason: 0x16
00>
00>

[Edvin]

Thank you for the figure. You were right, it turned out I was confused about your central-peripheral setup.

I have some questions:

Assuming you are bonding the central (trying to at least) with both of the peripherals, and the issue is that the connection between peripheral 2 and central device is not stored properly.

1: Does this happen with peripheral 1 as well if you disconnect that?

2: Does peripheral 1 have to be connected in order for this behavior to occur? Or can we remove peripheral 1 from the equation? 

3: Have you tried with another Android or iPhone?

4: Can you provide a sniffer trace of the connection between peripheral 2 and the central device? Both the first time they connect, and the following connection where you have to pair again? The nRF Sniffer would be sufficient. Please attach the .pcapng file from the sniffer traces here.

BR,

Edvin