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 Edvin,

I perform the following steps during my tests:

1) turn-on my board (with nRF52832 - Central)

2) clear the bonding information (by calling the pm_peers_delete() function)

3) perform a scan with filter policy BLE_GAP_SCAN_FP_ACCEPT_ALL

4) connect and pair with bonding the two devices (not already bonded with my board) that contains particular UUID into the advertising packet. The first one device is a smartphone and the second one is a PCA10040 board with the ble_app_hrs example of the SDK 16.0. 

5) disconnect the devices after bonding

6) start a new scan with filter policy  BLE_GAP_SCAN_FP_WHITELIST

The first connection with the PCA10040 board is established without new association but the second one, with the Android smartphone, requires a new association.

Thank you for your attention.

[Armando]

Hi Edvin,

in order to disconnect the devices I turn-off the nRF52832 on the PCA10040 and turn-off the Bluetooth interface of the smartphone. I think that it is not necessary to close all the connections before to change the filter policy of the scan an start the scan again with the BLE_GAP_SCAN_FP_WHITELIST ( point 6) of my test).

Of course the first pairing (point 4) of my test ) requires the click on the Android pop-up. As soon as I press "OK" on the smartphone display I see the following log messages:

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>

After the disconnection I connect the PCA10040 board and than the previusly bonded smartphone (the same of the above trave).

The problem is that I see a new pair request on the smartphone display after the new connection.

If I click "Ok" again on the smartphone display I see the same log above posted, if I click "No" I see the pairing error. 

[Edvin]

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

For the future: When you want to attach logs or snippets, please use the insert->code function.

[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

[Armando]

Hi Edvin,

the problem occurs with the Periperal 1 connected. 

The problem now occurs with a specific smartphone.

I have disabled the PEER RANKS module by putting the #define PM_PEER_RANKS_ENABLED 0 and now the problem seems solved.

I have tried to set again the #define PM_PEER_RANKS_ENABLED 1 in order to acquire the sniffer trace but the problem doesn't occurs now.

I will send you the sniffer trace if the problem occurs again. Can you help me to understand the aim of the PEER RANK module?

[Edvin]

The peer rank is used to keep track of what peers that are used and in what order they were stored. Later this is used to know what peer to delete if your peer manager is full, but you want to store bonding information for a new device. It shouldn't really cause trouble like this. Perhaps the issue was just that one of your device used old bonding data, while the new one had deleted the bonding data.That would cause the bonding information to be invalid for the connection, and you need to perform the pairing again.

BR,

Edvin

[Armando]

Hi Edvin,

I used the pm_peers_delete() to delete the bonding information on the Central Device and Peripheral 1 and the nRF Connect App to delete the donding information on the Peripheral 2 before every test.

[Edvin]

Then the problem was probably that the bonding data was deleted, so the phone had to pair again, if you did this on every startup.