Long time to disconnect

[nordev]

Hi, 

Our NRF52840 (running 14.2) often takes a very long time to disconnect, from when a disconnection is initiated by the phone. It can take 30s, sometimes even more, for the disconnect to happen. Sometimes the disconnect happens immediately like it should, but I would say that it is more common for the disconnect to take a long time than for the disconnect to be normal. 

I installed the NRF Sniffer and have done a capture, but I am not really sure what to make of the result. 

The below was a bad disconnect. Here, the highlighted line was about when the disconnect was initiated on the phone (image 1). Then I got "Empty PDU" for a long time. The empty PDU continues for a long time, with only one "encrypted packet decrypted incorrectly" in between, then in the second image, the highlighted line shows when the disconnect actually happens. There is ~13 sec in between the initiation and the actual disconnect.

By contrast, this was one of the times that I got a normal disconnection. 

The above was done with our custom app. The issue also happens when using the NRF Connect App for iOS. For reference, below is the capture when the disconnect was initiated by the NRF app:

I pressed the disconnect button around the time of this highlighted line: 

There is no command of any kind here though; the closest command is this one (but I don't know if they're even related, this is just the first command I found when scrolling up):

The disconnect comes what looks like 23 seconds later: 

My questions:

(MAIN QUESTION) How can I find out why it is taking a long time to disconnect? Note that it happens with different phones, but we have only been able to test with iPhones so far.

AUXILLIARY QUESTIONS: 

1. What are control opcodes and why do they only show up in the test using the NRF app, but not our custom app? Should we do something to enable these opcodes? 

2. What is empty PDU? 

3. What is "bad MIC"?

4. Where do I learn about how to interpret the captured packets? I read this but it doesn't really explain what I should be looking for.

Thanks!

[nordev]

UPDATE: 

I have added breakpoints everywhere I have sd_ble_gap_disconnect(), and none of the breakpoints trigger. 

The disconnect reason is always BLE_HCI_REMOTE_USER_TERMINATED_CONNECTION           0x13

I am guessing that my code doesn't handle disconnect requests from the phone properly. can you tell me what events are triggered when "disconnect" is pressed inside the NRF Connect phone app? It would be very helpful if you could describe the full call stack involved in a disconnection initiated by the central. 

I can put a sd_ble_gap_disconnect() inside the appropriate place in the call stack. Thank you.

UPDATE 2: 

The NRF Sniffer capture when connecting to / disconnecting from chip using NRF Connect App shows "Encrypted packet decrypted incorrectly" sometimes. 

[Joakim Jakobsen]

Hi.

To start with the sniffer traces and the questions regarding that.

Empty PDU's will be sent at the connection interval to maintain the connection, wether you have any real data to send or not. This is totally normal.

Regarding the "bad MIC", this is also normal. The sniffer shouldn't be able to decrypt data that you send from your devices (unless you specifically want to).
(https://devzone.nordicsemi.com/f/nordic-q-a/52240/nrf-sniffer-with-ble-communication-indicates-bad-mic)

As for the disconnect. It doesn't seem that your device receives the disconnection event, or handles it correctly. If one device disconnects and stops responding, your device should also disconnect after the defined timeout. Still strange that it works as expected some times.

Maybe you could add some relevant code?

Br,
Joakim

[nordev]

Thanks Joakim Jakobsen

here is some code: 

define APP_ADV_INTERVAL                 244                                        /**< The advertising interval (in units of 0.625 ms. Value of 300 corresponds to 187.5 ms). */
#define APP_ADV_TIMEOUT_IN_SECONDS       0                                          /**< The advertising timeout in units of seconds. */

#define MIN_CONN_INTERVAL                MSEC_TO_UNITS(25, UNIT_1_25_MS)            /**< Minimum acceptable connection interval (0.1 seconds). */
#define MAX_CONN_INTERVAL                MSEC_TO_UNITS(1500, UNIT_1_25_MS)          /**< Maximum acceptable connection interval (0.2 second). */
#define SLAVE_LATENCY                    0                                          /**< Slave latency. */
#define CONN_SUP_TIMEOUT                 MSEC_TO_UNITS(5000, UNIT_10_MS)            /**< Connection supervisory timeout (4 seconds). */

#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     2                                          /**< Number of attempts before giving up the connection parameter negotiation. */

#define SEC_PARAM_BOND                   1                                          /**< Perform bonding. */
#define SEC_PARAM_MITM                   0                                          /**< Man In The Middle protection required for Passkey */
#define SEC_PARAM_LESC                   0                                          /**< 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               /**< Changed for Passkey */
#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. */

#define SECURITY_REQUEST_DELAY          APP_TIMER_TICKS(400) // Passkey
#define APP_FEATURE_NOT_SUPPORTED       BLE_GATT_STATUS_ATTERR_APP_BEGIN + 2 

/**@brief Function for handling BLE events.
 *
 * @param[in]   p_ble_evt   Bluetooth stack event.
 * @param[in]   p_context   Unused.
 */
static void ble_evt_handler(ble_evt_t const * p_ble_evt, void * p_context)
{
    ret_code_t err_code;

    switch (p_ble_evt->header.evt_id)
    {
        case BLE_GAP_EVT_CONNECTED:
            NRF_LOG_INFO("Connected.");
            m_peer_to_be_deleted = PM_PEER_ID_INVALID;
            m_conn_handle = p_ble_evt->evt.gap_evt.conn_handle;

            nrf_gpio_pin_set(LED_BLUE);
            
            // Start Security Request timer.
            err_code = app_timer_start(m_sec_req_timer_id, SECURITY_REQUEST_DELAY, NULL);
            APP_ERROR_CHECK(err_code);
            break;

        case BLE_GAP_EVT_DISCONNECTED:
            NRF_LOG_INFO("Disconnected.");
            NRF_LOG_RAW_INFO("disconnect reason:0x%X \n",p_ble_evt->evt.gap_evt.params.disconnected.reason);
            m_conn_handle = BLE_CONN_HANDLE_INVALID;
            memset(&m_ble_db_discovery, 0 , sizeof (m_ble_db_discovery));
            
            // Turn LED back green
            nrf_gpio_pin_clear(LED_BLUE);
            nrf_gpio_pin_set(LED_GREEN);

            // Check if the last connected peer had not used MITM, if so, delete its bond information.
            if (m_peer_to_be_deleted != PM_PEER_ID_INVALID)
            {
                err_code = pm_peer_delete(m_peer_to_be_deleted);
                APP_ERROR_CHECK(err_code);
                NRF_LOG_DEBUG("Collector's bond deleted");
                m_peer_to_be_deleted = PM_PEER_ID_INVALID;
            }
            break;

#ifndef S140
        case BLE_GAP_EVT_PHY_UPDATE:
        {
            NRF_LOG_DEBUG("PHY update request.");
            ble_gap_phys_t const phys =
            {
                .rx_phys = BLE_GAP_PHY_AUTO,
                .tx_phys = BLE_GAP_PHY_AUTO,
            };
            err_code = sd_ble_gap_phy_update(p_ble_evt->evt.gap_evt.conn_handle, &phys);
            APP_ERROR_CHECK(err_code);
        } break;
#endif

        case BLE_GATTC_EVT_TIMEOUT:
            // Disconnect on GATT Client timeout event.
            NRF_LOG_DEBUG("GATT Client Timeout.");
            err_code = sd_ble_gap_disconnect(p_ble_evt->evt.gattc_evt.conn_handle,
                                             BLE_HCI_REMOTE_USER_TERMINATED_CONNECTION);
            APP_ERROR_CHECK(err_code);
            break;

        case BLE_GATTS_EVT_TIMEOUT:
            // Disconnect on GATT Server timeout event.
            NRF_LOG_DEBUG("GATT Server Timeout.");
            err_code = sd_ble_gap_disconnect(p_ble_evt->evt.gatts_evt.conn_handle,
                                             BLE_HCI_REMOTE_USER_TERMINATED_CONNECTION);
            APP_ERROR_CHECK(err_code);
            break;

        // Added for Passkey
        case BLE_GAP_EVT_SEC_PARAMS_REQUEST:
            NRF_LOG_DEBUG("BLE_GAP_EVT_SEC_PARAMS_REQUEST");
            break;

        case BLE_GAP_EVT_PASSKEY_DISPLAY:
            // Don't send delayed Security Request if security procedure is already in progress.
            err_code = app_timer_stop(m_sec_req_timer_id);
            APP_ERROR_CHECK(err_code);
            NRF_LOG_DEBUG("BLE_GAP_EVT_PASSKEY_DISPLAY");
            break;

        case BLE_EVT_USER_MEM_REQUEST:
            err_code = sd_ble_user_mem_reply(m_conn_handle, NULL);
            APP_ERROR_CHECK(err_code);
            break;

        case BLE_GATTS_EVT_RW_AUTHORIZE_REQUEST:
        {
            ble_gatts_evt_rw_authorize_request_t  req;
            ble_gatts_rw_authorize_reply_params_t auth_reply;

            req = p_ble_evt->evt.gatts_evt.params.authorize_request;

            if (req.type != BLE_GATTS_AUTHORIZE_TYPE_INVALID)
            {
                if ((req.request.write.op == BLE_GATTS_OP_PREP_WRITE_REQ)     ||
                    (req.request.write.op == BLE_GATTS_OP_EXEC_WRITE_REQ_NOW) ||
                    (req.request.write.op == BLE_GATTS_OP_EXEC_WRITE_REQ_CANCEL))
                {
                    if (req.type == BLE_GATTS_AUTHORIZE_TYPE_WRITE)
                    {
                        auth_reply.type = BLE_GATTS_AUTHORIZE_TYPE_WRITE;
                    }
                    else
                    {
                        auth_reply.type = BLE_GATTS_AUTHORIZE_TYPE_READ;
                    }
                    auth_reply.params.write.gatt_status = APP_FEATURE_NOT_SUPPORTED;
                    err_code = sd_ble_gatts_rw_authorize_reply(p_ble_evt->evt.gatts_evt.conn_handle,
                                                               &auth_reply);
                    APP_ERROR_CHECK(err_code);
                }
            }
        } break; // BLE_GATTS_EVT_RW_AUTHORIZE_REQUEST

        default:
            // No implementation needed.
            break;
    }

    bluetooth_on_ble_evt(p_ble_evt);
}

I'm not sure what else to include, because I'm not sure where I should look for the processing of the disconnection event. Can you point me to where a disconnection event is supposed to be received in the GATT event handling, or wherever else relevant? 

Joakim Jakobsen said:

It doesn't seem that your device receives the disconnection event, or handles it correctly

1. where in the code can I find where the disconnection event should be received/ handled?

2. what exactly happens / what is sent when the disconnect button is pressed in the app?

---

UPDATE: note that this long time to disconnect issue happens both when running our firmware on our custom device and also on a NRF52840 dev kit. So it doesn't seem to be a hardware issue. 

Please let me know if you need another relevant code sample

[nordev]

Hi Joakim Jakobsen are you planning to help with my question? It has been more than 2 weeks. Can anyone else help?ovrebekk? Karl Ylvisaker? I am still stuck and would be grateful for some guidance. 

Some things I have tried since my original post:

• i have tried loading a Nordic example to see if the issue persists. The one I used is ble_app_bms. The disconnects happen immediately, so the problem must be somewhere in my code. Or maybe something in the compilation settings?
• I checked the call stack for when the disconnect is triggered and compared between my app and the Nordic example. It is the same exact thing in both cases (screenshot from bms app): except for some reason, in my app, the handlers (which I believe are part of the softdevice) just don’t get triggered until 10-30 seconds after the disconnect is initiated on the phone. The whole stack executes immediately once the first handler is triggered though. 
• I have tried commenting out all the custom parts of my app (including bluetooth_init() and blietooth_on_ble_evt()) to see if I could pinpoint what is wrong, but I am still experiencing the problem. I tried connecting and disconnecting 5 times in a row, using the Nordic NRF Connect app for iPhone, and I timed how long it took from pressing the “disconnect” button in the phone to the actual disconnect event: 22s, 31s, 10s, 25s, 28s respectively. It is different every time. 

Also, this is an aside, but I am having to use my phone to send this note because your website is not working on my computer for some reason. It has been like this the whole week. It says “waiting for available socket” and stays like this forever. Other websites work fine though. 

when I regain access to your website via my computer, I can send a code snippet for what is left over after commenting out / removing the custom parts of my app. 

i am looking for guidance on what other parts of the code or configurations I can check that could possibly be causing this issue. 

thank you!

[Joakim Jakobsen]

Hi.

Sorry about the delay here. I've missed your last reply.

I will take a look and get back to you today.

Br,
Joakim