Zephyr/BLE stack: Problem pairing/bonding more than one device, whilst the first device is still connected.


Declan Traill <declan.traill@...>
 

Hi Zephyr group,

 

    We have found on our Zephyr system that the first device (Android or iOS) pairs/bonds with not problems, but a second (or third etc) device fails to pair/bond most of the time.
Sometimes it works ok & both devices become paired/bonded and stay connected, but most of the time it fails and the second device is disconnected as soon as the pairing key has been entered on the device.

Here is some debug output for when the pairing/bonding of the first device works, and then when it fails for the second device:

 

WHEN IT WORKS (FOR THE FIRST DEVICE):

 

[ble_p] [INF] ble_p_connected: 1/4, 00:00:46:00:00:01 (public) is NOT bonded

passkey display 520717

[] [INF] rvmn_ui_bt_auth_pairing_complete: 00:00:46:00:00:01 (public), bonded:1

[] [ERR] rvmn_ui_bt_auth_pairing_complete: not bonded

 

 

WHEN IT DOESN’T WORK (FOR THE SECOND DEVICE):

 

ble_p] [INF] ble_p_connected: 2/4, d4:61:9d:ee:41:53 (public) is NOT bonded

passkey display 183049

[ble_p] [INF] ble_p_disconnected: 2/4, d4:61:9d:ee:41:53 (public) is NOT bonded

[ble_p] [ERR] ble_p_disconnected: 1/4, d4:61:9d:ee:41:53 (public) NOT

[ble_p] [DBG] ble_p_disconnected: d4:61:9d:ee:41:53 (public), reason 0x08: BT_HCI_ERR_CONN_TIMEOUT

 

 

 

I investigated the cause of the disconnection in the Zephyr BLE stack, and found it to be caused by trx_done  not being TRUE when the isr() function is called (in ctrl.c) whilst in STATE_RX  _radio.state:

 

The trx_done is set based on the value of NRF_RADIO->EVENTS_END.

It seems that when the second device tries to pair, we get a BLE isr() occur whilst in STATE_RX, but NRF_RADIO->EVENTS_END is not set.
Thus it appears to not have completed a Tx/Rx in the Radio?

Why is this happening, and is there some configuration/setting we can change to fix this, or is it a Zephyr BLE stack bug?

 

 

 

Here is the code:

 

 

u32_t radio_is_done(void)

{

       if (NRF_RADIO->EVENTS_END != 0) {

              /* On packet END event increment last packet end time value.

              * Note: this depends on the function being called exactly once

              * in the ISR function.

              */

              last_pdu_end_us += EVENT_TIMER->CC[2];

              return 1;

       } else {

              return 0;

       }

}

 

#else /* !CONFIG_BT_CTLR_SW_SWITCH_SINGLE_TIMER */

u32_t radio_is_done(void)

{

       return (NRF_RADIO->EVENTS_END != 0);

}

#endif /* !CONFIG_BT_CTLR_SW_SWITCH_SINGLE_TIMER */

 

 

 

static void isr(void)

{

       u8_t trx_done;

       u8_t crc_ok;

       u8_t devmatch_ok;

       u8_t devmatch_id;

       u8_t irkmatch_ok;

       u8_t irkmatch_id;

       u8_t rssi_ready;

 

       DEBUG_RADIO_ISR(1);

 

       /* Read radio status and events */

       trx_done = radio_is_done();

       if (trx_done) {

 

#if defined(CONFIG_BT_CTLR_PROFILE_ISR)

              /* sample the packet timer here, use it to calculate ISR latency

              * and generate the profiling event at the end of the ISR.

              */

              radio_tmr_sample();

#endif /* CONFIG_BT_CTLR_PROFILE_ISR */

 

              crc_ok = radio_crc_is_valid();

              devmatch_ok = radio_filter_has_match();

              devmatch_id = radio_filter_match_get();

              irkmatch_ok = radio_ar_has_match();

              irkmatch_id = radio_ar_match_get();

              rssi_ready = radio_rssi_is_ready();

       } else {

              crc_ok = devmatch_ok = irkmatch_ok = rssi_ready = 0;

              devmatch_id = irkmatch_id = 0xFF;

       }

 

       /* Clear radio status and events */

       radio_status_reset();

       radio_tmr_status_reset();

       radio_filter_status_reset();

       radio_ar_status_reset();

       radio_rssi_status_reset();

 

#if defined(CONFIG_BT_CTLR_GPIO_PA_PIN) || \

    defined(CONFIG_BT_CTLR_GPIO_LNA_PIN)

       radio_gpio_pa_lna_disable();

#endif /* CONFIG_BT_CTLR_GPIO_PA_PIN || CONFIG_BT_CTLR_GPIO_LNA_PIN */

 

       switch (_radio.state) {

       case STATE_TX:

              isr_radio_state_tx();

              break;

 

       case STATE_RX:

              isr_radio_state_rx(trx_done, crc_ok, devmatch_ok, devmatch_id,

                              irkmatch_ok, irkmatch_id, rssi_ready);

              break;

 

       case STATE_ABORT:

       case STATE_STOP:

       case STATE_CLOSE:

              isr_radio_state_close();

              break;

 

       case STATE_NONE:

              /* Ignore Duplicate Radio Disabled IRQ due to forced stop

              * using Radio Disable task.

              */

              break;

 

       default:

              LL_ASSERT(0);

              break;

       }

 

       DEBUG_RADIO_ISR(0);

}

 

 

At the start of the function isr_radio_state_rx, trx_done is tested, and if not true, _radio.state is set to STATE_CLOSE, then the connection is closed

 

static inline void isr_radio_state_rx(u8_t trx_done, u8_t crc_ok,

                                 u8_t devmatch_ok, u8_t devmatch_id,

                                 u8_t irkmatch_ok, u8_t irkmatch_id,

                                 u8_t rssi_ready)

{

       u32_t err;

       u8_t  rl_idx;

 

       if (!((trx_done) || ((SILENT_CONNECTION) &&

                          (_radio.role == ROLE_SLAVE)))) {

              _radio.state = STATE_CLOSE;

              radio_disable();

 

              return;

       }

 

 

 

static inline void isr_radio_state_close(void)

{

       u32_t dont_close = 0;

 

       switch (_radio.role) {

       case ROLE_ADV:

              dont_close = isr_close_adv();

              break;

 

       case ROLE_SCAN:

              dont_close = isr_close_scan();

              break;

 

       case ROLE_SLAVE:

       case ROLE_MASTER:

              isr_close_conn();

              break;

 

 

This is the function called from code above, resulting in the connection being closed with a BT_HCI_ERR_CONN_TIMEOUT

 

static inline void isr_close_conn(void)

{

       u16_t ticks_drift_plus;

       u16_t ticks_drift_minus;

       u16_t latency_event;

       u16_t elapsed_event;

       u8_t reason_peer;

       u16_t lazy;

       u8_t force;

 

       /* Local initiated terminate happened */

       if (_radio.conn_curr == 0) {

              return;

       }

 

       /* Master transmitted ack for the received terminate ind or

       * Slave received terminate ind.

       */

       reason_peer = _radio.conn_curr->llcp_terminate.reason_peer;

       if (reason_peer && ((_radio.role == ROLE_SLAVE) ||

                         _radio.conn_curr->master.terminate_ack)) {

              terminate_ind_rx_enqueue(_radio.conn_curr, reason_peer);

 

              connection_release(_radio.conn_curr);

              _radio.conn_curr = NULL;

 

              return;

       }

 

       ticks_drift_plus = 0;

       ticks_drift_minus = 0;

       latency_event = _radio.conn_curr->latency_event;

       elapsed_event = latency_event + 1;

 

       /* calculate drift if anchor point sync-ed */

       if (_radio.packet_counter &&

           (!SILENT_CONNECTION || (_radio.packet_counter != 0xFF))) {

              if (_radio.role == ROLE_SLAVE) {

                     u32_t start_to_address_expected_us;

                     u32_t start_to_address_actual_us;

                     u32_t window_widening_event_us;

                     u32_t preamble_to_addr_us;

 

                     /* calculate the drift in ticks */

                     start_to_address_actual_us = radio_tmr_aa_restore() -

                                              radio_tmr_ready_get();

                     window_widening_event_us =

                           _radio.conn_curr->slave.window_widening_event_us;

#if defined(CONFIG_BT_CTLR_PHY)

                     preamble_to_addr_us =

                           addr_us_get(_radio.conn_curr->phy_rx);

#else /* !CONFIG_BT_CTLR_PHY */

                     preamble_to_addr_us = addr_us_get(0);

#endif /* !CONFIG_BT_CTLR_PHY */

                     start_to_address_expected_us = RADIO_TICKER_JITTER_US +

                           (RADIO_TICKER_JITTER_US << 1) +

                           preamble_to_addr_us +

                           window_widening_event_us;

                     if (start_to_address_actual_us <=

                         start_to_address_expected_us) {

                           ticks_drift_plus = HAL_TICKER_US_TO_TICKS(

                                  window_widening_event_us);

                           ticks_drift_minus = HAL_TICKER_US_TO_TICKS(

                                  (start_to_address_expected_us -

                                  start_to_address_actual_us));

                     } else {

                           ticks_drift_plus = HAL_TICKER_US_TO_TICKS(

                                  start_to_address_actual_us);

                           ticks_drift_minus = HAL_TICKER_US_TO_TICKS(

                                  RADIO_TICKER_JITTER_US +

                                  (RADIO_TICKER_JITTER_US << 1) +

                                  preamble_to_addr_us);

                     }

 

                     /* Reset window widening, as anchor point sync-ed */

                     _radio.conn_curr->slave.window_widening_event_us = 0;

                     _radio.conn_curr->slave.window_size_event_us = 0;

 

                     /* apply latency if no more data */

                     if (_radio.conn_curr->pkt_tx_head) {

                           struct pdu_data *pdu_data_tx;

 

                           pdu_data_tx = (void *)

                                  _radio.conn_curr->pkt_tx_head->pdu_data;

                           if (pdu_data_tx->len ||

                               _radio.conn_curr->packet_tx_head_offset) {

                                  _radio.conn_curr->latency_event = 0;

                           }

                     } else if (_radio.conn_curr->slave.latency_enabled) {

                           _radio.conn_curr->latency_event =

                                  _radio.conn_curr->latency;

                     }

              } else if (reason_peer) {

                     _radio.conn_curr->master.terminate_ack = 1;

              }

 

              /* Reset connection failed to establish procedure */

              _radio.conn_curr->connect_expire = 0;

       }

 

       /* check connection failed to establish */

       else if (_radio.conn_curr->connect_expire) {

              if (_radio.conn_curr->connect_expire > elapsed_event) {

                     _radio.conn_curr->connect_expire -= elapsed_event;

              } else {

                     terminate_ind_rx_enqueue(_radio.conn_curr,

                                         BT_HCI_ERR_CONN_FAIL_TO_ESTAB);

 

                     connection_release(_radio.conn_curr);

                     _radio.conn_curr = NULL;

 

                     return;

              }

       }

 

       /* if anchor point not sync-ed, start supervision timeout, and break

       * latency if any.

       */

       else {

              /* Start supervision timeout, if not started already */

              if (!_radio.conn_curr->supervision_expire) {

                     _radio.conn_curr->supervision_expire =

                           _radio.conn_curr->supervision_reload;

              }

       }

 

       /* check supervision timeout */

       force = 0;

       if (_radio.conn_curr->supervision_expire) {

              if (_radio.conn_curr->supervision_expire > elapsed_event) {

                     _radio.conn_curr->supervision_expire -= elapsed_event;

 

                     /* break latency */

                     _radio.conn_curr->latency_event = 0;

 

                     /* Force both master and slave when close to

                     * supervision timeout.

                     */

                     if (_radio.conn_curr->supervision_expire <= 6) {

                           force = 1;

                     }

                     /* use randomness to force slave role when anchor

                     * points are being missed.

                     */

                     else if (_radio.role == ROLE_SLAVE) {

                           if (latency_event != 0) {

                                  force = 1;

                           } else {

                                  force = _radio.conn_curr->slave.force & 0x01;

 

                                  /* rotate force bits */

                                  _radio.conn_curr->slave.force >>= 1;

                                  if (force) {

                                         _radio.conn_curr->slave.force |=

                                                ((u32_t)1 << 31);

                                  }

                           }

                     }

              } else {

                     terminate_ind_rx_enqueue(_radio.conn_curr,

                                         BT_HCI_ERR_CONN_TIMEOUT);

 

                     connection_release(_radio.conn_curr);

                     _radio.conn_curr = NULL;

 

                     return;

              }

       }

 

   Thanks for any help you can provide…

 

Regards,

Declan Traill
Embedded Firmware Engineer
declan.traill@...

SETEC Pty Ltd
19 Henderson Road, Knoxfield 3180, Victoria, Australia
Phone: +61 3 9763 0962
Fax: +61 3 9763 8789
Direct: +61 3 9213 8458
setec.com.au | teambmpro.com

SETEC on Facebook     SETEC on Instagram     SETEC on LinkedIn     SETEC on YouTube
SETEC Celebrating 50 Years



Email from setec.com.au does not necessarily represent the official policy of SETEC Pty Ltd.
See Email Disclaimer 20060629 for details.


Join devel@lists.zephyrproject.org to automatically receive all group messages.