Bonding sequence not finalized in first connection

[Kasper Leonhardt]

Hi

I have tried to enable bonding on a application based on the Running Speed and Cadence example (Both peripheral and central). (I could not find an example with bonding enabled)

But it seems that the bonding sequence is interrupted, and after disconnection and re-connection the bonding procedure is finalized. I have created a custom service with a single characteristic, with reading, notifying and writing enabled. All with the security setting SEC_JUST_WORKS for both reading and writing.

Central - first connection

[00:00:00.002,197] <info> app: Custom Receiver Controller started.
[00:00:00.002,441] <info> app: =======================================
[00:00:00.002,441] <info> app: Deleting bonds
[00:00:00.002,441] <info> app: Erase bonds
[00:00:00.005,859] <error> peer_manager_handler: Peer deleted successfully: peer_id: 0
[00:00:00.005,859] <info> app: pm_evt_handler: EventId=10
[00:00:00.005,859] <info> peer_manager_handler: All peers deleted.
[00:00:00.005,859] <info> app: Starting scan.
[00:00:00.005,859] <info> app: scan_evt_handler: NRF_BLE_SCAN_EVT_WHITELIST_REQUEST
[00:00:09.923,828] <info> app: scan_evt_handler: NRF_BLE_SCAN_EVT_FILTER_MATCH
[00:00:09.959,228] <info> app: scan_evt_handler: 7
[00:00:09.959,228] <info> app: Connected.
[00:00:10.470,703] <info> app: pm_evt_handler: PM_EVT_CONN_SEC_PARAMS_REQ
[00:00:10.470,703] <info> app: pm_evt_handler: PM_EVT_CONN_SEC_START
[00:00:10.470,703] <info> app: Custom Service discovered.
[00:00:10.470,703] <info> app: Device Information Service discovered.
[00:00:10.501,464] <info> app: pm_evt_handler: PM_EVT_CONN_SEC_PARAMS_REQ
[00:00:10.531,005] <info> app:
[00:00:10.531,005] <info> app: Device Information:
[00:00:10.531,005] <info> app: PnP ID:
[00:00:10.531,005] <info> app:  Vendor ID Source: 0x01
[00:00:10.531,005] <info> app:  Vendor ID:        0x0059
[00:00:10.531,005] <info> app:  Product ID:       0x0001
[00:00:10.531,005] <info> app:  Product Version:  0x0002
[00:00:10.531,005] <info> app:
[00:00:10.922,851] <info> peer_manager_handler: Connection secured: role: Central, conn_handle: 0, procedure: Bonding
[00:00:10.922,851] <info> app: pm_evt_handler: PM_EVT_CONN_SEC_SUCCEEDED
[00:00:10.925,537] <info> app: pm_evt_handler: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
[00:00:10.927,978] <info> app: pm_evt_handler: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
[00:00:10.982,910] <info> app: pm_evt_handler: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
[00:00:30.960,449] <info> app: Disconnected. conn_handle: 0x0, reason: 0x15

Central - second connection:

[00:00:30.960,449] <info> app: Starting scan.
[00:00:30.960,449] <info> app: scan_evt_handler: NRF_BLE_SCAN_EVT_WHITELIST_REQUEST
[00:00:50.873,046] <info> app: scan_evt_handler: NRF_BLE_SCAN_EVT_WHITELIST_ADV_REPORT: F6:7F:4C:04:7F:2B
[00:00:50.873,046] <info> app: scan_evt_handler: Adv data: len=26
[00:00:50.873,046] <info> app: scan_evt_handler: Adv data: manuf_id=0xBEAF
[00:00:50.902,832] <info> app: scan_evt_handler: 7
[00:00:50.902,832] <info> app: pm_evt_handler: PM_EVT_CONN_SEC_PARAMS_REQ
[00:00:50.902,832] <info> app: pm_evt_handler: PM_EVT_CONN_SEC_START
[00:00:50.902,832] <info> app: pm_evt_handler: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
[00:00:50.902,832] <info> app: pm_evt_handler: PM_EVT_BONDED_PEER_CONNECTED
[00:00:50.902,832] <info> app: pm_evt_handler: EventId=14
[00:00:50.902,832] <info> app: Connected.
[00:00:50.904,785] <info> app: pm_evt_handler: PM_EVT_CONN_SEC_PARAMS_REQ
[00:00:50.904,785] <info> app: pm_evt_handler: PM_EVT_CONN_SEC_START
[00:00:50.904,785] <info> app: pm_evt_handler: EventId=18
[00:00:51.084,472] <info> peer_manager_handler: Connection secured: role: Central, conn_handle: 0, procedure: Encryption
[00:00:51.084,472] <info> app: pm_evt_handler: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
[00:00:51.084,472] <info> app: pm_evt_handler: PM_EVT_CONN_SEC_SUCCEEDED
[00:00:51.384,521] <info> peer_manager_handler: Connection secured: role: Central, conn_handle: 0, procedure: Encryption
[00:00:51.384,521] <info> app: pm_evt_handler: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
[00:00:51.384,521] <info> app: pm_evt_handler: PM_EVT_CONN_SEC_SUCCEEDED Bonding=Yes
[00:00:51.804,443] <info> app: pm_evt_handler: PM_EVT_CONN_SEC_PARAMS_REQ
[00:00:51.804,443] <info> app: pm_evt_handler: PM_EVT_CONN_SEC_START
[00:00:51.804,443] <info> app: Notification enabled.
[00:00:51.804,443] <info> app: Custom Service discovered.
[00:00:51.804,443] <info> app: Device Information Service discovered.
[00:00:52.104,492] <info> peer_manager_handler: Connection secured: role: Central, conn_handle: 0, procedure: Encryption
[00:00:52.104,492] <info> app: pm_evt_handler: PM_EVT_PEER_DATA_UPDATE_SUCCEEDED
[00:00:52.104,492] <info> app: pm_evt_handler: PM_EVT_CONN_SEC_SUCCEEDED
[00:00:52.164,550] <info> app:
[00:00:52.164,550] <info> app: Device Information:
[00:00:52.164,550] <info> app: PnP ID:
[00:00:52.164,550] <info> app:  Vendor ID Source: 0x01
[00:00:52.164,550] <info> app:  Vendor ID:        0x0059
[00:00:52.164,550] <info> app:  Product ID:       0x0001
[00:00:52.164,550] <info> app:  Product Version:  0x0002
[00:00:52.164,550] <info> app:
[00:01:02.410,644] <info> app: AppEventBtn: 3 Pressed
[00:01:02.410,644] <info> app: Sendig config.
[00:01:02.543,945] <info> app: AppEventBtn: 3 Released
[00:01:02.543,945] <info> app: Sendig config.

I believe it should be possible to do all the bonding sequence in a single connection. Do anyone have an example, or en idea why the bonding sequence is not finalized. Is there some more debug I should create/enable?

[Vidar Berg]

Hi,

Yes there's something wrong,  you should be able to perform bonding without losing the link. Could you upload the project so I can try to  debug it here? I have not seen that disconnect reason before (0x15 == BLE_HCI_REMOTE_USER_TERMINATED_CONNECTION). All examples that include the Peer manager support bonding.

EDIT:  0x15 corresponds to BLE_HCI_REMOTE_DEV_TERMINATION_DUE_TO_POWER_OFF, and not BLE_HCI_REMOTE_USER_TERMINATED_CONNECTION which is a common status code.

[Kasper Leonhardt]

By the way. I have also posted another issue on this project. Can also be visualized with this project.

https://devzone.nordicsemi.com/f/nordic-q-a/40751/various-notification-delays

And I forgot to write that connection is established when pressing the button 3 and 4, and the two buttons are mapped to LED 3 and 4 on the central. when holding the buttons the state is notified every 200 ms. When Idle for some time the connection is terminated.

[Vidar Berg]

Hi, 

The disconnect appears to be caused your "disconnect" timer, see app.c->AppDisconnectHandler(). 

[Kasper Leonhardt]

I know. But it disconnects 10 seconds after the last BLE event. It seems never to finalize before disconnection and re-connection. 

[Vidar Berg]

Ok. I thought it was the disconnect itself that was the problem . According to the log the bond procedure is actually being completed on the first connection (this: [00:00:10.922,851] <info> peer_manager_handler: Connection secured: role: Central, conn_handle: 0, procedure: Bonding).

I guess the problem is that notification is not being enabled on the first connection then?  The central must wait for the PM_EVT_CONN_SEC_SUCCEEDED event before enabling the notification since you've changed the CCCD write access to "Just works". 

[Kasper Leonhardt]

Perfect. It solved it. Thank you.