disconnecting while operations are in progress never gives BLE_GAP_EVT_DISCONNECTED event

[Paul Bradford]

2020-01-24-092119EST-ProductStoppedGettingEventsFromNordicDK.txtImprivataTestNordicEventsNotReceived.zipCalls_to_pc_ble_driver.cpp0285.2020-02-24-TestProgramUploadedToNordicSupport.zipFeb25TestProgramUploadedToNordicSupport.zipImprivata_bgTestApp.zipbgSDKTestAppMay4.zip2020-05-05-035347-NordicDK_USB840M_200505_ClockInternal_2in1.hex.txt.txtbgSDKTestAppMay6.zipI’m developing an application based on pc-ble-driver to talk to an nRF52840-based dongle (from Fanstel).

I’m having trouble disconnecting cleanly when a connection has operations in progress.  For example, I call ‘sd_ble_gattc_write’, which returns NRF_SUCCESS, but I don’t receive event BLE_GATTC_EVT_WRITE_RSP (after waiting 60 seconds), so I decide to disconnect. When this happens, sd_ble_gap_disconnect returns NRF_SUCCESS, but I do not receive BLE_GAP_EVT_DISCONNECTED even after waiting 30 seconds. The connection supervision timeout is 4 seconds.  What could cause the disconnect to not generate any BLE_GAP_EVT_DISCONNECTED event?

What I’m trying to accomplish here: if a connection is not responsive, I want to end that connection, without disturbing other connections I have open.

Thanks,

Paul Bradford

[Paul Bradford]

I have attached a new test program Imprivata_bgTestApp.zip. There is a file called README with instructions, and a description of the problem.   I suggest you try this on a Dell 64-bit Windows 10 laptop that has not had Nordic dev tools installed on it. Usually the problem occurs with in an hour or two.

This test program reproduces the problem on two 64-bit Windows 10 laptops and does not reproduce this on one 64-bit Windows 10 laptop. I don't know what difference between these laptops causes two to fail and one to succeed. All have the same driver usbser.sys 10.0.18362.1 winbuild 160101.0800. Problem has occurred when plugged into USB 2.0 and USB 3.0 ports.

Failing laptops: both Dell, one Windows 10 version 1903 build 18362.657, another Windows 10 version 1909 build 18363.752 (the latest public Windows 10 build)

Laptop that does not reproduce the problem: Lenovo ThinkPad, Windows 10 version 1903 build 18362.657 (exactly the same as one failing laptop). This one has had Nordic tools like nRF Connect installed. One consequence is that when I plugged in an nRF52840 it would show in Device Manager as 'nRF Connect USB CDC ACM (COMx)'. To make it like my other laptops that do not have Nordic tools, I uninstalled the driver so that the nRF52840 would show up as 'USB Serial Device (COMx)'

[Jørgen Holmefjord]

I have had the new application running on my PC with 5 parallel devices for 8 hours yesterday and 4 hours today. So far, I have not been able to reproduce the issue. I do have another PC that does not have Nordic tools installed, but this is not a Dell PC. I will try to setup the test on that one next. It's a bit harder to find equipment for testing this with the limited factors where you have managed to reproduce the issue, due most of us working from home-office due to the Corona situation. Is it still a requirement to have heavy Bluetooth activity around the device in order to reproduce the issue? This could also be a problem to facilitate during home-office.

[Paul Bradford]

You mentioned "UART logging". I don't know how to do that.  The only type of firmware logging I've used was with RTT Viewer and the DK. I don't know how to do logging with the dev-dongle.

[Jørgen Holmefjord]

Right, UART logging will only be available on the DK. If you are able to reproduce on a DK, please provide the logs. You can read the UART logs using a terminal software (Putty, Tera Term, RealTerm, Termite, etc). You may also be able to read UART logs from the Dongle by connecting a wire to the DK, but this would require the logging to use a different pin for UART, as the default UART TX pin is not routed out on the Dongle.

[Paul Bradford]

I'm trying to reproduce the problem with the DK. How do I get the UART output?  That shows up as JLink CDC UART Port (COM8). So if I open COM8 with Putty I should see debug output, but I see nothing. Does the baud rate matter? If so, what is it?

But if it is set to only show errors, then maybe I haven't encountered an error yet. But I don't know if I'm properly attached to the COM port.

[LeoChen]

I increased sched queue_size, enabled UART log and compiler agian.

I have  make sure the UART log has output with this BT840_USBconnectivity200430.hex.

https://www.dropbox.com/s/yqkcn95qrwto6g7/BT840_USBconnectivity200430.rar?dl=0

[Paul Bradford]

I've been testing with the firmware file "USB840_Connect200430_3in1.hex" from the DropBox link that Leo from Fanstel referenced in the support case on April 29. This firmware has the critical section fix described by Nordic on April 24, and the queue size 64 change.

With this firmware, I get errors quickly with the Fanstel dongle and Nordic dev-dongle, and after 17 hours with the Nordic Development Kit. 

Reproduced event loss problem with Nordic Development Kit on May 2 at about 8 AM eastern daylight time, after running for over 17 hours.
Test program "2020-05-02 08:02:15.759: (ERROR) no Nordic event  BLE_GATTC_EVT_WRITE_RSP  was received to complete the call to sd_ble_gattc_write"

The dropbox link below has USB trace using USBPcap and PuTTY serial port logging from the Development Kit.

The PuTTY output looks normal to me until the very end:
[00:00:58.343,695] <error> app: Fatal error
[00:00:58.710,920] <info> app: BLE connectivity 200427

www.dropbox.com/.../May2ReproNordicDK.zip

[LeoChen]

The Fanstel USB840M does not have 32K crystal.

The clock setting is different.

I change the clock setting back to default.

The application should all the same as patched SDK.

The changed were add CRITICAL_REGION_ENTER/ CRITICAL_REGION_EXIT and Scheduler queue size increase to 64.

These files can't work with USB840M.

Application + softdevice

https://www.dropbox.com/s/u77p0ub617i786e/USB840_Clock_ACCURACY_2in1.hex?dl=0

 

Application + bootloader + softdevice

https://www.dropbox.com/s/pg2hzhorhlivdoo/USB840_Clock_ACCURACY_3in1.hex?dl=0

Would you please also try these files on Nordic dongle and DK.

Leo

[Paul Bradford]

I tested the USB840_Clock_ACCURACY_3in1.hex file referenced in Leo's last post. I loaded it on the Nordic DK by dragging it to the "JLink CDC UART Port". After just a few minutes my test program got the "serial port write operation" error "The device does not recognize the command". The firmware logging over that JLink port looked the same as what I uploaded on May 2 (which was also the DK and used firmware "USB840_Connect200430_3in1.hex" ):

[00:00:13.056,233] <debug> app: event:BLE_GAP_EVT_RSSI_CHANGED

[00:00:13.061,999] <debug> sphy_hci: TX request (7 bytes)

[00:00:13.067,421] <debug> sphy_hci: Started TX packet (payload 7).

[00:00:13.074,211] <error> app: Fatal error

[00:00:13.441,628] <info> app: BLE connectivity 200427

[00:00:13.447,435] <info> app: USB power detected

[00:00:13.453,251] <info> app: USB ready

I have not been able to test this firmware with the Nordic dev-dongle. I tried loading USB840_Clock_ACCURACY_3in1.hex into the dev-dongle using nRF Connect Programmer, but that leaves the dev-dongle in a state where it does not show up as a serial port when I plug it in. If there is some other way I should try to program it, please let me know.

[Paul Bradford]

I uploaded a modified test program. The change is to have a command-line option to say how often to do the challenge/response, which is what triggers the notifications from the phone, which is what we suspect is causing this problem.   With no option, this is done every 5 minutes. I've been testing with new command-line option -f5 which means to do it every 5 seconds.

[Jørgen Holmefjord]

LeoChen: I did manage to reproduce once with today with the USB840_Clock_ACCURACY_2in1.hex file you provided on a Nordic Dongle. Unfortunately, it does not provide much information about the fatal error. I had modified this in the connectivity hex that I build with queue size of 64 and logging enabled. Can you replace this file in your SDK? It will give the location of the error and the error code on the log. 

Fullscreen ser_conn_error_handling.c Download

/**
 * Copyright (c) 2014 - 2019, Nordic Semiconductor ASA
 *
 * All rights reserved.
 *
 * Redistribution and use in source and binary forms, with or without modification,
 * are permitted provided that the following conditions are met:
 *
 * 1. Redistributions of source code must retain the above copyright notice, this
 *    list of conditions and the following disclaimer.
 *
 * 2. Redistributions in binary form, except as embedded into a Nordic
 *    Semiconductor ASA integrated circuit in a product or a software update for
 *    such product, must reproduce the above copyright notice, this list of
 *    conditions and the following disclaimer in the documentation and/or other
 *    materials provided with the distribution.
 *
 * 3. Neither the name of Nordic Semiconductor ASA nor the names of its
 *    contributors may be used to endorse or promote products derived from this
 *    software without specific prior written permission.
 *
 * 4. This software, with or without modification, must only be used with a
 *    Nordic Semiconductor ASA integrated circuit.
 *
 * 5. Any software provided in binary form under this license must not be reverse
 *    engineered, decompiled, modified and/or disassembled.
 *
 * THIS SOFTWARE IS PROVIDED BY NORDIC SEMICONDUCTOR ASA "AS IS" AND ANY EXPRESS
 * OR IMPLIED WARRANTIES, INCLUDING, BUT NOT LIMITED TO, THE IMPLIED WARRANTIES
 * OF MERCHANTABILITY, NONINFRINGEMENT, AND FITNESS FOR A PARTICULAR PURPOSE ARE
 * DISCLAIMED. IN NO EVENT SHALL NORDIC SEMICONDUCTOR ASA OR CONTRIBUTORS BE
 * LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL, SPECIAL, EXEMPLARY, OR
 * CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT LIMITED TO, PROCUREMENT OF SUBSTITUTE
 * GOODS OR SERVICES; LOSS OF USE, DATA, OR PROFITS; OR BUSINESS INTERRUPTION)
 * HOWEVER CAUSED AND ON ANY THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT
 * LIABILITY, OR TORT (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT
 * OF THE USE OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
 *
 */
#include "nrf_assert.h"
#include "app_error.h"
#include "ser_config.h"
#include "app_util_platform.h"
#include "nrf_strerror.h"

#if defined(SOFTDEVICE_PRESENT) && SOFTDEVICE_PRESENT
#include "nrf_sdm.h"
#endif

#include "boards.h"

/** @file
 *
 * @defgroup ser_conn_error_handling Errors handling for the Connectivity Chip.
 * @{
 * @ingroup sdk_lib_serialization
 *
 * @brief   A module to handle the Connectivity Chip errors and warnings.
 *
 * @details This file contains definitions of functions used for handling the Connectivity Chip
 *          errors and warnings.
 */

/**@brief Function for handling the Connectivity Chip errors and warnings.
 *
 * @details This function will be called if the ASSERT macro in the connectivity application fails.
 *          Function declaration can be found in the app_error.h file.
 *
 * @param[in] error_code  Error code supplied to the handler.
 * @param[in] line_num    Line number where the handler is called.
 * @param[in] p_file_name Pointer to the file name.
 */

#include "app_util_platform.h"
#include "nrf_soc.h"
#include "nrf_log.h"
#include "nrf_log_ctrl.h"

// uint32_t m_error_code;
// uint32_t m_error_line_num;
// const uint8_t *m_p_error_file_name;

/*lint -save -e14 */
void app_error_fault_handler(uint32_t id, uint32_t pc, uint32_t info)
{
    // disable INTs
    CRITICAL_REGION_ENTER();

    NRF_LOG_ERROR("Fatal error");
    switch (id)
    {
#if defined(SOFTDEVICE_PRESENT) && SOFTDEVICE_PRESENT
        case NRF_FAULT_ID_SD_ASSERT:
            NRF_LOG_ERROR("SOFTDEVICE: ASSERTION FAILED");
            break;
        case NRF_FAULT_ID_APP_MEMACC:
            NRF_LOG_ERROR("SOFTDEVICE: INVALID MEMORY ACCESS");
            break;
#endif
        case NRF_FAULT_ID_SDK_ASSERT:
        {
            assert_info_t * p_info = (assert_info_t *)info;
            NRF_LOG_ERROR("ASSERTION FAILED at %s:%u",
                          p_info->p_file_name,
                          p_info->line_num);
            break;
        }
        case NRF_FAULT_ID_SDK_ERROR:
        {
            error_info_t * p_info = (error_info_t *)info;
            NRF_LOG_ERROR("ERROR %u [%s] at %s:%u\r\nPC at: 0x%08x",
                          p_info->err_code,
                          nrf_strerror_get(p_info->err_code),
                          p_info->p_file_name,
                          p_info->line_num,
                          pc);
             NRF_LOG_ERROR("End of error report");
            break;
        }
        default:
            NRF_LOG_ERROR("UNKNOWN FAULT at 0x%08X", pc);
            break;
    }
    NRF_LOG_FINAL_FLUSH();

    #if LEDS_NUMBER > 0

    /* Light a LED on error or warning. */
    // nrf_gpio_cfg_output(SER_CONN_ASSERT_LED_PIN);
    // nrf_gpio_pin_set(SER_CONN_ASSERT_LED_PIN);

    #endif

    // m_p_error_file_name = p_file_name;
    // m_error_code = error_code;
    // m_error_line_num = line_num;

    /* Do not reset when warning. */
    if (SER_WARNING_CODE != id)
    {
        /* This call can be used for debug purposes during application development.
        * @note CAUTION: Activating code below will write the stack to flash on an error.
        * This function should NOT be used in a final product.
        * It is intended STRICTLY for development/debugging purposes.
        * The flash write will happen EVEN if the radio is active, thus interrupting any communication.
        * Use with care. Un-comment the line below to use. */

        /* ble_debug_assert_handler(error_code, line_num, p_file_name); */

#ifndef DEBUG
        /* Reset the chip. Should be used in the release version. */
        NVIC_SystemReset();
#else   /* Debug version. */
        /* To be able to see function parameters in a debugger. */
        uint32_t temp = 1;
        while (temp);
#endif

    }

    CRITICAL_REGION_EXIT();
}
/*lint -restore */


/**@brief Callback function for asserts in the SoftDevice.
 *
 * @details This function will be called if the ASSERT macro in the SoftDevice fails. Function
 *          declaration can be found in the nrf_assert.h file.
 *
 * @param[in] line_num    Line number of the failing ASSERT call.
 * @param[in] p_file_name File name of the failing ASSERT call.
 */
void assert_nrf_callback(uint16_t line_num, const uint8_t * p_file_name)
{
    app_error_handler(SER_SD_ERROR_CODE, line_num, p_file_name);
}
/** @} */

So far, I'm not able to reproduce the issue with the connectivity FW I'm building. Can you upload the SDK directory that you used, along with the path to the exact project used to build it?

@paul-bradford: I'm not sure this issue you are now seeing is the same as the original problem. They may look similar to the application, but I never saw the fatal error with my previous testing. I'm not sure if notifications are the cause of this anymore, but we need to find the origin of the fatal error in order to determine what is happening. Hopefully, you should be able to detect that quite fast with the above change I requested from Leo.

[LeoChen]

Hi Jorgen,

The following link is source project that I am using.

https://www.dropbox.com/s/t3pcunczygxxr7k/nRF5_SDK_15.3.0_59ac345_PC_Connect_200505.rar?dl=0

I did compare with the source patched project and can't see any thing wrong.

Would you please also give me the entire SDK that you are using to compare.

The Global setting

Macro:SDK=E:\Keil_v5\ARM\Device\Nordic\nRF5_SDK_15.3.0_59ac345_PC_Connect_200505

The Project path

~\nRF5_SDK_15.3.0_59ac345_PC_Connect_200505\examples\connectivity\ble_connectivity\pca10056\ser_s140_usb_hci\ses

The HEX files that  replace error handling (External Clock does not work with Fanstel USB840M).

https://www.dropbox.com/s/z6u7f227h2sogl7/USB840M0505.rar?dl=0

How long you will see the error happen?

I programmed 3 dongles and running over 4 hours.

I can't see that error on my Win 7  desktop.

Regards,

Leo