This post is older than 2 years and might not be relevant anymore
More Info: Consider searching for newer posts

NRF_LOG_PUSH seems to be outputting invalid data intermittently

Hi!

I'm using the nRF52840 DK with SDK 15.2 and on Windows 10. I have been testing USB communication and while I was testing input and output data, some of the data I was outputting in the RTT viewer with NRF_LOG_INFO() was invalid. What I mean by that is that the data sent through USB into Putty is the same as the data printed with NRF_LOG_INFO():

To produce this, I used the usbd_cdc_acm_pca10056 example. Originally, this example does not print in the Viewer and I had to make some changes to the config file:

#define NRF_LOG_BACKEND_RTT_ENABLED 1

#define NRF_LOG_BACKEND_UART_ENABLED 0

I also added the following to main.c:

    NRF_LOG_DEFAULT_BACKENDS_INIT();

That weird output was generated using this:

if(m_send_flag)
{
    static int  frame_counter;
    size_t size = sprintf(m_tx_buffer, "Hello USB CDC FA demo: %u\r\n", frame_counter);
    NRF_LOG_INFO("%s", NRF_LOG_PUSH(m_tx_buffer));
    ret = app_usbd_cdc_acm_write(&m_app_cdc_acm, m_tx_buffer, size);
    if (ret == NRF_SUCCESS)
    {
        ++frame_counter;
    }
}

I was able to bypass the problem and get normal output when avoiding NRF_LOG_PUSH:

if(m_send_flag)
{
    static int  frame_counter;
    size_t size = sprintf(m_tx_buffer, "Hello USB CDC FA demo: %u\r\n", frame_counter);
    NRF_LOG_INFO("Hello USB CDC FA demo: %u", frame_counter);
    ret = app_usbd_cdc_acm_write(&m_app_cdc_acm, m_tx_buffer, size);
    if (ret == NRF_SUCCESS)
    {
        ++frame_counter;
    }
}

I find it weird to NRF_LOG_PUSH doesn't work as supposed since it is advised here.

I also tried adding NRF_LOG_FLUSH() after the call to NRF_LOG_PROCESS() but it did improve the output. I also tried adding some delay (thinking that the output would be generated to quickly for RTT Viewer) using both nrf_delay_ms() and nrf_delay_us() and it didn't do anything.

I also linked the config file used and the main source file.

/**
 * Copyright (c) 2017 - 2018, 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 <stdint.h>
#include <stdbool.h>
#include <stddef.h>
#include <stdio.h>

#include "nrf.h"
#include "nrf_drv_usbd.h"
#include "nrf_drv_clock.h"
#include "nrf_gpio.h"
#include "nrf_delay.h"
#include "nrf_drv_power.h"

#include "app_error.h"
#include "app_util.h"
#include "app_usbd_core.h"
#include "app_usbd.h"
#include "app_usbd_string_desc.h"
#include "app_usbd_cdc_acm.h"
#include "app_usbd_serial_num.h"

#include "boards.h"
#include "bsp.h"
#include "bsp_cli.h"
#include "nrf_cli.h"
#include "nrf_cli_uart.h"

#include "nrf_log.h"
#include "nrf_log_ctrl.h"
#include "nrf_log_default_backends.h"

/**
 * @brief CLI interface over UART
 */
NRF_CLI_UART_DEF(m_cli_uart_transport, 0, 64, 16);
NRF_CLI_DEF(m_cli_uart,
            "uart_cli:~$ ",
            &m_cli_uart_transport.transport,
            '\r',
            4);

/**@file
 * @defgroup usbd_cdc_acm_example main.c
 * @{
 * @ingroup usbd_cdc_acm_example
 * @brief USBD CDC ACM example
 *
 */

#define LED_USB_RESUME      (BSP_BOARD_LED_0)
#define LED_CDC_ACM_OPEN    (BSP_BOARD_LED_1)
#define LED_CDC_ACM_RX      (BSP_BOARD_LED_2)
#define LED_CDC_ACM_TX      (BSP_BOARD_LED_3)

#define BTN_CDC_DATA_SEND       0
#define BTN_CDC_NOTIFY_SEND     1

#define BTN_CDC_DATA_KEY_RELEASE        (bsp_event_t)(BSP_EVENT_KEY_LAST + 1)

/**
 * @brief Enable power USB detection
 *
 * Configure if example supports USB port connection
 */
#ifndef USBD_POWER_DETECTION
#define USBD_POWER_DETECTION true
#endif


static void cdc_acm_user_ev_handler(app_usbd_class_inst_t const * p_inst,
                                    app_usbd_cdc_acm_user_event_t event);

#define CDC_ACM_COMM_INTERFACE  0
#define CDC_ACM_COMM_EPIN       NRF_DRV_USBD_EPIN2

#define CDC_ACM_DATA_INTERFACE  1
#define CDC_ACM_DATA_EPIN       NRF_DRV_USBD_EPIN1
#define CDC_ACM_DATA_EPOUT      NRF_DRV_USBD_EPOUT1


/**
 * @brief CDC_ACM class instance
 * */
APP_USBD_CDC_ACM_GLOBAL_DEF(m_app_cdc_acm,
                            cdc_acm_user_ev_handler,
                            CDC_ACM_COMM_INTERFACE,
                            CDC_ACM_DATA_INTERFACE,
                            CDC_ACM_COMM_EPIN,
                            CDC_ACM_DATA_EPIN,
                            CDC_ACM_DATA_EPOUT,
                            APP_USBD_CDC_COMM_PROTOCOL_AT_V250
);

#define READ_SIZE 1

static char m_rx_buffer[READ_SIZE];
static char m_tx_buffer[NRF_DRV_USBD_EPSIZE];
static bool m_send_flag = 0;

/**
 * @brief User event handler @ref app_usbd_cdc_acm_user_ev_handler_t (headphones)
 * */
static void cdc_acm_user_ev_handler(app_usbd_class_inst_t const * p_inst,
                                    app_usbd_cdc_acm_user_event_t event)
{
    app_usbd_cdc_acm_t const * p_cdc_acm = app_usbd_cdc_acm_class_get(p_inst);

    switch (event)
    {
        case APP_USBD_CDC_ACM_USER_EVT_PORT_OPEN:
        {
            bsp_board_led_on(LED_CDC_ACM_OPEN);

            /*Setup first transfer*/
            ret_code_t ret = app_usbd_cdc_acm_read(&m_app_cdc_acm,
                                                   m_rx_buffer,
                                                   READ_SIZE);
            UNUSED_VARIABLE(ret);
            break;
        }
        case APP_USBD_CDC_ACM_USER_EVT_PORT_CLOSE:
            bsp_board_led_off(LED_CDC_ACM_OPEN);
            break;
        case APP_USBD_CDC_ACM_USER_EVT_TX_DONE:
            bsp_board_led_invert(LED_CDC_ACM_TX);
            break;
        case APP_USBD_CDC_ACM_USER_EVT_RX_DONE:
        {
            ret_code_t ret;
            NRF_LOG_INFO("Bytes waiting: %d", app_usbd_cdc_acm_bytes_stored(p_cdc_acm));
            do
            {
                /*Get amount of data transfered*/
                size_t size = app_usbd_cdc_acm_rx_size(p_cdc_acm);
                NRF_LOG_INFO("RX: size: %lu char: %c", size, m_rx_buffer[0]);

                /* Fetch data until internal buffer is empty */
                ret = app_usbd_cdc_acm_read(&m_app_cdc_acm,
                                            m_rx_buffer,
                                            READ_SIZE);
            } while (ret == NRF_SUCCESS);
            

            bsp_board_led_invert(LED_CDC_ACM_RX);
            break;
        }
        default:
            break;
    }
}

static void usbd_user_ev_handler(app_usbd_event_type_t event)
{
    switch (event)
    {
        case APP_USBD_EVT_DRV_SUSPEND:
            bsp_board_led_off(LED_USB_RESUME);
            break;
        case APP_USBD_EVT_DRV_RESUME:
            bsp_board_led_on(LED_USB_RESUME);
            break;
        case APP_USBD_EVT_STARTED:
            break;
        case APP_USBD_EVT_STOPPED:
            app_usbd_disable();
            bsp_board_leds_off();
            break;
        case APP_USBD_EVT_POWER_DETECTED:
            NRF_LOG_INFO("USB power detected");

            if (!nrf_drv_usbd_is_enabled())
            {
                app_usbd_enable();
            }
            break;
        case APP_USBD_EVT_POWER_REMOVED:
            NRF_LOG_INFO("USB power removed");
            app_usbd_stop();
            break;
        case APP_USBD_EVT_POWER_READY:
            NRF_LOG_INFO("USB ready");
            app_usbd_start();
            break;
        default:
            break;
    }
}

static void bsp_event_callback(bsp_event_t ev)
{
    ret_code_t ret;
    switch ((unsigned int)ev)
    {
        case CONCAT_2(BSP_EVENT_KEY_, BTN_CDC_DATA_SEND):
        {
            m_send_flag = 1;
            break;
        }
        
        case BTN_CDC_DATA_KEY_RELEASE :
        {
            m_send_flag = 0;
            break;
        }

        case CONCAT_2(BSP_EVENT_KEY_, BTN_CDC_NOTIFY_SEND):
        {
            ret = app_usbd_cdc_acm_serial_state_notify(&m_app_cdc_acm,
                                                       APP_USBD_CDC_ACM_SERIAL_STATE_BREAK,
                                                       false);
            UNUSED_VARIABLE(ret);
            break;
        }

        default:
            return; // no implementation needed
    }
}

static void init_bsp(void)
{
    ret_code_t ret;
    ret = bsp_init(BSP_INIT_BUTTONS, bsp_event_callback);
    APP_ERROR_CHECK(ret);
    
    UNUSED_RETURN_VALUE(bsp_event_to_button_action_assign(BTN_CDC_DATA_SEND,
                                                          BSP_BUTTON_ACTION_RELEASE,
                                                          BTN_CDC_DATA_KEY_RELEASE));
    
    /* Configure LEDs */
    bsp_board_init(BSP_INIT_LEDS);
}

static void init_cli(void)
{
    ret_code_t ret;
    ret = bsp_cli_init(bsp_event_callback);
    APP_ERROR_CHECK(ret);
    nrf_drv_uart_config_t uart_config = NRF_DRV_UART_DEFAULT_CONFIG;
    uart_config.pseltxd = TX_PIN_NUMBER;
    uart_config.pselrxd = RX_PIN_NUMBER;
    uart_config.hwfc    = NRF_UART_HWFC_DISABLED;
    ret = nrf_cli_init(&m_cli_uart, &uart_config, true, true, NRF_LOG_SEVERITY_INFO);
    APP_ERROR_CHECK(ret);
    ret = nrf_cli_start(&m_cli_uart);
    APP_ERROR_CHECK(ret);
}

int main(void)
{
    ret_code_t ret;
    static const app_usbd_config_t usbd_config = {
        .ev_state_proc = usbd_user_ev_handler
    };

    ret = NRF_LOG_INIT(NULL);
    NRF_LOG_DEFAULT_BACKENDS_INIT();
    APP_ERROR_CHECK(ret);

    ret = nrf_drv_clock_init();
    APP_ERROR_CHECK(ret);
    
    nrf_drv_clock_lfclk_request(NULL);

    while(!nrf_drv_clock_lfclk_is_running())
    {
        /* Just waiting */
    }

    ret = app_timer_init();
    APP_ERROR_CHECK(ret);

    init_bsp();
    init_cli();

    app_usbd_serial_num_generate();

    ret = app_usbd_init(&usbd_config);
    APP_ERROR_CHECK(ret);
    NRF_LOG_INFO("USBD CDC ACM example started.");

    app_usbd_class_inst_t const * class_cdc_acm = app_usbd_cdc_acm_class_inst_get(&m_app_cdc_acm);
    ret = app_usbd_class_append(class_cdc_acm);
    APP_ERROR_CHECK(ret);

    if (USBD_POWER_DETECTION)
    {
        ret = app_usbd_power_events_enable();
        APP_ERROR_CHECK(ret);
    }
    else
    {
        NRF_LOG_INFO("No USB power detection enabled\r\nStarting USB now");

        app_usbd_enable();
        app_usbd_start();
    }

    while (true)
    {
        while (app_usbd_event_queue_process())
        {
            /* Nothing to do */
        }
        
        if(m_send_flag)
        {
            static int  frame_counter;
            size_t size = sprintf(m_tx_buffer, "Hello USB CDC FA demo: %u\r\n", frame_counter);
            NRF_LOG_INFO("Hello USB CDC FA demo: %u", frame_counter);
            ret = app_usbd_cdc_acm_write(&m_app_cdc_acm, m_tx_buffer, size);
            if (ret == NRF_SUCCESS)
            {
                ++frame_counter;
            }
        }
        nrf_delay
        nrf_cli_process(&m_cli_uart);
        UNUSED_RETURN_VALUE(NRF_LOG_PROCESS());
        NRF_LOG_FLUSH();
        /* Sleep CPU only if there was no interrupt since last loop processing */
        __WFE();
    }
}

/** @} */
sdk_config.h

Thanks for looking into this bug!

  • Hi,

    There is a lot of configs that you can play around with in your sdk_config.h file to help solve this issue. I'm not sure exactly which one is causing this in your application:

    // <o> NRF_LOG_BACKEND_RTT_TEMP_BUFFER_SIZE - Size of buffer for partially processed strings. 
    // <i> Size of the buffer is a trade-off between RAM usage and processing.
    // <i> if buffer is smaller then strings will often be fragmented.
    // <i> It is recommended to use size which will fit typical log and only the
    // <i> longer one will be fragmented.
    
    #ifndef NRF_LOG_BACKEND_RTT_TEMP_BUFFER_SIZE
    #define NRF_LOG_BACKEND_RTT_TEMP_BUFFER_SIZE 64
    #endif
    
    // <h> Log message pool - Configuration of log message pool
    
    //==========================================================
    // <o> NRF_LOG_MSGPOOL_ELEMENT_SIZE - Size of a single element in the pool of memory objects. 
    // <i> If a small value is set, then performance of logs processing
    // <i> is degraded because data is fragmented. Bigger value impacts
    // <i> RAM memory utilization. The size is set to fit a message with
    // <i> a timestamp and up to 2 arguments in a single memory object.
    
    #ifndef NRF_LOG_MSGPOOL_ELEMENT_SIZE
    #define NRF_LOG_MSGPOOL_ELEMENT_SIZE 20
    #endif
    
    // <o> NRF_LOG_MSGPOOL_ELEMENT_COUNT - Number of elements in the pool of memory objects 
    // <i> If a small value is set, then it may lead to a deadlock
    // <i> in certain cases if backend has high latency and holds
    // <i> multiple messages for long time. Bigger value impacts
    // <i> RAM memory usage.
    
    #ifndef NRF_LOG_MSGPOOL_ELEMENT_COUNT
    #define NRF_LOG_MSGPOOL_ELEMENT_COUNT 8
    #endif
    
    // </h> 
    //==========================================================
    
    // <q> NRF_LOG_ALLOW_OVERFLOW  - Configures behavior when circular buffer is full.
     
    
    // <i> If set then oldest logs are overwritten. Otherwise a 
    // <i> marker is injected informing about overflow.
    
    #ifndef NRF_LOG_ALLOW_OVERFLOW
    #define NRF_LOG_ALLOW_OVERFLOW 1
    #endif
    
    // <o> NRF_LOG_BUFSIZE  - Size of the buffer for storing logs (in bytes).
     
    
    // <i> Must be power of 2 and multiple of 4.
    // <i> If NRF_LOG_DEFERRED = 0 then buffer size can be reduced to minimum.
    // <128=> 128 
    // <256=> 256 
    // <512=> 512 
    // <1024=> 1024 
    // <2048=> 2048 
    // <4096=> 4096 
    // <8192=> 8192 
    // <16384=> 16384 
    
    #ifndef NRF_LOG_BUFSIZE
    #define NRF_LOG_BUFSIZE 1024
    #endif
    
    // <o> SEGGER_RTT_CONFIG_BUFFER_SIZE_UP - Size of upstream buffer. 
    // <i> Note that either @ref NRF_LOG_BACKEND_RTT_OUTPUT_BUFFER_SIZE
    // <i> or this value is actually used. It depends on which one is bigger.
    
    #ifndef SEGGER_RTT_CONFIG_BUFFER_SIZE_UP
    #define SEGGER_RTT_CONFIG_BUFFER_SIZE_UP 512
    #endif
    
    // <o> SEGGER_RTT_CONFIG_MAX_NUM_UP_BUFFERS - Size of upstream buffer. 
    #ifndef SEGGER_RTT_CONFIG_MAX_NUM_UP_BUFFERS
    #define SEGGER_RTT_CONFIG_MAX_NUM_UP_BUFFERS 2
    #endif
    
    // <o> SEGGER_RTT_CONFIG_BUFFER_SIZE_DOWN - Size of upstream buffer. 
    #ifndef SEGGER_RTT_CONFIG_BUFFER_SIZE_DOWN
    #define SEGGER_RTT_CONFIG_BUFFER_SIZE_DOWN 16
    #endif
    
    // <o> SEGGER_RTT_CONFIG_MAX_NUM_DOWN_BUFFERS - Size of upstream buffer. 
    #ifndef SEGGER_RTT_CONFIG_MAX_NUM_DOWN_BUFFERS
    #define SEGGER_RTT_CONFIG_MAX_NUM_DOWN_BUFFERS 2
    #endif
    
    // <o> SEGGER_RTT_CONFIG_DEFAULT_MODE  - RTT behavior if the buffer is full.
     
    
    // <i> The following modes are supported:
    // <i> - SKIP  - Do not block, output nothing.
    // <i> - TRIM  - Do not block, output as much as fits.
    // <i> - BLOCK - Wait until there is space in the buffer.
    // <0=> SKIP 
    // <1=> TRIM 
    // <2=> BLOCK_IF_FIFO_FULL 
    
    #ifndef SEGGER_RTT_CONFIG_DEFAULT_MODE
    #define SEGGER_RTT_CONFIG_DEFAULT_MODE 0
    #endif

    Best regards,
    Jørgen

  • Hi,

    I tested the output from the logger modifying each config you sent and none of them did anything to the output. However, that got me thinking and I went back on this page and read that NRF_LOG_STR_PUSH_BUFFER_SIZE is closely linked to the usage of NRF_LOG_PUSH(). I also tried NRF_LOG_HEXDUMP_INFO and  NRF_LOG_RAW_HEXDUMP_INFO. These last two do print properly. However, they print a lot of extra data which makes it not ideal. So I tested extensively with NRF_LOG_STR_PUSH_BUFFER_SIZE and found the following results when outputting incrementing data (the numbers mentioned are those where there is an error printing, so incrementing values not size values):

    NRF_LOG_STR_PUSH_BUFFER SIZE First error Interval between errors Last error recorded
    512 235 74 975
    1024 309 147 1038
    2048 309 293 895
    4096 601 562 1163
    8192 1163 9174 10337

    After the last error recorded, the buffer seems to have stabilized and doesn't output any more errors, but I might not be printing enough data. For these tests, the string printed is the following:

    NRF_LOG_RAW_INFO("\t\t%s\n", NRF_LOG_PUSH(value));

    Also, I tested using a different string for an NRF_LOG_STR_PUSH_BUFFER_SIZE of 512:

    NRF_LOG_RAW_INFO("\t%s\n", NRF_LOG_PUSH(value));

    And the first error is at 104; with an interval of 86 and the last error at 1043.

    Hopefully, that would tell you a bit more. I can always rely on NRF_LOG_RAW_HEXDUMP_INFO but this wouldn't be ideal.

    Thank you so much for your help

  • Sorry for the slow response. I forgot to include NRF_LOG_STR_PUSH_BUFFER_SIZE in my list.

    Can you provide a minimal example that we can use to reproduce this behavior?

  • /**
     * Copyright (c) 2017 - 2018, 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 <stdint.h>
    #include <stdbool.h>
    #include <stddef.h>
    #include <stdio.h>
    
    #include "nrf.h"
    #include "nrf_drv_usbd.h"
    #include "nrf_drv_clock.h"
    #include "nrf_gpio.h"
    #include "nrf_delay.h"
    #include "nrf_drv_power.h"
    
    #include "app_error.h"
    #include "app_util.h"
    #include "app_usbd_core.h"
    #include "app_usbd.h"
    #include "app_usbd_string_desc.h"
    #include "app_usbd_cdc_acm.h"
    #include "app_usbd_serial_num.h"
    
    #include "boards.h"
    #include "bsp.h"
    #include "bsp_cli.h"
    #include "nrf_cli.h"
    #include "nrf_cli_uart.h"
    
    #include "nrf_log.h"
    #include "nrf_log_ctrl.h"
    #include "nrf_log_default_backends.h"
    
    /**
     * @brief CLI interface over UART
     */
    NRF_CLI_UART_DEF(m_cli_uart_transport, 0, 64, 16);
    NRF_CLI_DEF(m_cli_uart,
                "uart_cli:~$ ",
                &m_cli_uart_transport.transport,
                '\r',
                4);
    
    /**@file
     * @defgroup usbd_cdc_acm_example main.c
     * @{
     * @ingroup usbd_cdc_acm_example
     * @brief USBD CDC ACM example
     *
     */
    
    #define LED_USB_RESUME      (BSP_BOARD_LED_0)
    #define LED_CDC_ACM_OPEN    (BSP_BOARD_LED_1)
    #define LED_CDC_ACM_RX      (BSP_BOARD_LED_2)
    #define LED_CDC_ACM_TX      (BSP_BOARD_LED_3)
    
    #define BTN_CDC_DATA_SEND       0
    #define BTN_CDC_NOTIFY_SEND     1
    
    #define BTN_CDC_DATA_KEY_RELEASE        (bsp_event_t)(BSP_EVENT_KEY_LAST + 1)
    
    /**
     * @brief Enable power USB detection
     *
     * Configure if example supports USB port connection
     */
    #ifndef USBD_POWER_DETECTION
    #define USBD_POWER_DETECTION true
    #endif
    
    
    static void cdc_acm_user_ev_handler(app_usbd_class_inst_t const * p_inst,
                                        app_usbd_cdc_acm_user_event_t event);
    
    #define CDC_ACM_COMM_INTERFACE  0
    #define CDC_ACM_COMM_EPIN       NRF_DRV_USBD_EPIN2
    
    #define CDC_ACM_DATA_INTERFACE  1
    #define CDC_ACM_DATA_EPIN       NRF_DRV_USBD_EPIN1
    #define CDC_ACM_DATA_EPOUT      NRF_DRV_USBD_EPOUT1
    
    
    /**
     * @brief CDC_ACM class instance
     * */
    APP_USBD_CDC_ACM_GLOBAL_DEF(m_app_cdc_acm,
                                cdc_acm_user_ev_handler,
                                CDC_ACM_COMM_INTERFACE,
                                CDC_ACM_DATA_INTERFACE,
                                CDC_ACM_COMM_EPIN,
                                CDC_ACM_DATA_EPIN,
                                CDC_ACM_DATA_EPOUT,
                                APP_USBD_CDC_COMM_PROTOCOL_AT_V250
    );
    
    #define READ_SIZE 1
    
    static char m_rx_buffer[READ_SIZE];
    static char m_tx_buffer[NRF_DRV_USBD_EPSIZE];
    static bool m_send_flag = 0;
    
    /**
     * @brief User event handler @ref app_usbd_cdc_acm_user_ev_handler_t (headphones)
     * */
    static void cdc_acm_user_ev_handler(app_usbd_class_inst_t const * p_inst,
                                        app_usbd_cdc_acm_user_event_t event)
    {
        app_usbd_cdc_acm_t const * p_cdc_acm = app_usbd_cdc_acm_class_get(p_inst);
    
        switch (event)
        {
            case APP_USBD_CDC_ACM_USER_EVT_PORT_OPEN:
            {
                bsp_board_led_on(LED_CDC_ACM_OPEN);
    
                /*Setup first transfer*/
                ret_code_t ret = app_usbd_cdc_acm_read(&m_app_cdc_acm,
                                                       m_rx_buffer,
                                                       READ_SIZE);
                NRF_LOG_INFO("PORT_OPEN, char read: %c", m_rx_buffer[0]);
                UNUSED_VARIABLE(ret);
                break;
            }
            case APP_USBD_CDC_ACM_USER_EVT_PORT_CLOSE:
                bsp_board_led_off(LED_CDC_ACM_OPEN);
                break;
            case APP_USBD_CDC_ACM_USER_EVT_TX_DONE:
                bsp_board_led_invert(LED_CDC_ACM_TX);
                break;
            case APP_USBD_CDC_ACM_USER_EVT_RX_DONE:
            {
                ret_code_t ret;
                NRF_LOG_INFO("Bytes waiting: %d", app_usbd_cdc_acm_bytes_stored(p_cdc_acm));
                do
                {
                    /*Get amount of data transfered*/
                    size_t size = app_usbd_cdc_acm_rx_size(p_cdc_acm);
                    NRF_LOG_INFO("RX: size: %lu char: %c", size, m_rx_buffer[0]);
                    NRF_LOG_INFO("Bytes left: %d\n", app_usbd_cdc_acm_bytes_stored(&m_app_cdc_acm));
                    /* Fetch data until internal buffer is empty */
                    ret = app_usbd_cdc_acm_read(&m_app_cdc_acm,
                                                m_rx_buffer,
                                                READ_SIZE);
                    NRF_LOG_FLUSH();
                    if (ret == NRF_SUCCESS){
                        NRF_LOG_INFO("NRF_SUCCESS");
                    }
                    else if(ret == NRF_ERROR_IO_PENDING){
                        NRF_LOG_INFO("NRF_ERROR_IO_PENDING");
                    }
                    else if(ret == NRF_ERROR_BUSY){
                        NRF_LOG_INFO("NRF_ERROR_BUSY");
                    }
                } while (ret == NRF_SUCCESS);
                
    
                bsp_board_led_invert(LED_CDC_ACM_RX);
                NRF_LOG_FLUSH();
                break;
            }
            default:
                break;
        }
    }
    
    static void usbd_user_ev_handler(app_usbd_event_type_t event)
    {
        switch (event)
        {
            case APP_USBD_EVT_DRV_SUSPEND:
                bsp_board_led_off(LED_USB_RESUME);
                break;
            case APP_USBD_EVT_DRV_RESUME:
                bsp_board_led_on(LED_USB_RESUME);
                break;
            case APP_USBD_EVT_STARTED:
                break;
            case APP_USBD_EVT_STOPPED:
                app_usbd_disable();
                bsp_board_leds_off();
                break;
            case APP_USBD_EVT_POWER_DETECTED:
                NRF_LOG_INFO("USB power detected");
    
                if (!nrf_drv_usbd_is_enabled())
                {
                    app_usbd_enable();
                }
                break;
            case APP_USBD_EVT_POWER_REMOVED:
                NRF_LOG_INFO("USB power removed");
                app_usbd_stop();
                break;
            case APP_USBD_EVT_POWER_READY:
                NRF_LOG_INFO("USB ready");
                app_usbd_start();
                break;
            default:
                break;
        }
    }
    
    static void bsp_event_callback(bsp_event_t ev)
    {
        ret_code_t ret;
        switch ((unsigned int)ev)
        {
            case CONCAT_2(BSP_EVENT_KEY_, BTN_CDC_DATA_SEND):
            {
                m_send_flag = 1;
                break;
            }
            
            case BTN_CDC_DATA_KEY_RELEASE :
            {
                m_send_flag = 0;
                break;
            }
    
            case CONCAT_2(BSP_EVENT_KEY_, BTN_CDC_NOTIFY_SEND):
            {
                ret = app_usbd_cdc_acm_serial_state_notify(&m_app_cdc_acm,
                                                           APP_USBD_CDC_ACM_SERIAL_STATE_BREAK,
                                                           false);
                UNUSED_VARIABLE(ret);
                break;
            }
    
            default:
                return; // no implementation needed
        }
    }
    
    static void init_bsp(void)
    {
        ret_code_t ret;
        ret = bsp_init(BSP_INIT_BUTTONS, bsp_event_callback);
        APP_ERROR_CHECK(ret);
        
        UNUSED_RETURN_VALUE(bsp_event_to_button_action_assign(BTN_CDC_DATA_SEND,
                                                              BSP_BUTTON_ACTION_RELEASE,
                                                              BTN_CDC_DATA_KEY_RELEASE));
        
        /* Configure LEDs */
        bsp_board_init(BSP_INIT_LEDS);
    }
    
    static void init_cli(void)
    {
        ret_code_t ret;
        ret = bsp_cli_init(bsp_event_callback);
        APP_ERROR_CHECK(ret);
        nrf_drv_uart_config_t uart_config = NRF_DRV_UART_DEFAULT_CONFIG;
        uart_config.pseltxd = TX_PIN_NUMBER;
        uart_config.pselrxd = RX_PIN_NUMBER;
        uart_config.hwfc    = NRF_UART_HWFC_DISABLED;
        ret = nrf_cli_init(&m_cli_uart, &uart_config, true, true, NRF_LOG_SEVERITY_INFO);
        APP_ERROR_CHECK(ret);
        ret = nrf_cli_start(&m_cli_uart);
        APP_ERROR_CHECK(ret);
    }
    
    int main(void)
    {
        ret_code_t ret;
        static const app_usbd_config_t usbd_config = {
            .ev_state_proc = usbd_user_ev_handler
        };
    
        ret = NRF_LOG_INIT(NULL);
        NRF_LOG_DEFAULT_BACKENDS_INIT();
        APP_ERROR_CHECK(ret);
    
        ret = nrf_drv_clock_init();
        APP_ERROR_CHECK(ret);
        
        nrf_drv_clock_lfclk_request(NULL);
    
        while(!nrf_drv_clock_lfclk_is_running())
        {
            /* Just waiting */
        }
    
        ret = app_timer_init();
        APP_ERROR_CHECK(ret);
    
        init_bsp();
        init_cli();
    
        app_usbd_serial_num_generate();
    
        ret = app_usbd_init(&usbd_config);
        APP_ERROR_CHECK(ret);
        NRF_LOG_INFO("USBD CDC ACM example started.");
    
        app_usbd_class_inst_t const * class_cdc_acm = app_usbd_cdc_acm_class_inst_get(&m_app_cdc_acm);
        ret = app_usbd_class_append(class_cdc_acm);
        APP_ERROR_CHECK(ret);
    
        if (USBD_POWER_DETECTION)
        {
            ret = app_usbd_power_events_enable();
            APP_ERROR_CHECK(ret);
        }
        else
        {
            NRF_LOG_INFO("No USB power detection enabled\r\nStarting USB now");
    
            app_usbd_enable();
            app_usbd_start();
        }
        bool start_loop = false;
        while (true)
        {
            while (app_usbd_event_queue_process())
            {
                NRF_LOG_INFO("EVENT QUEUE PROCESS");
            }
            
            if(m_send_flag)
            {
                static int  frame_counter;
                size_t size = sprintf(m_tx_buffer, "Hello USB CDC FA demo: %u\r\n", frame_counter);
                NRF_LOG_INFO("%s", NRF_LOG_PUSH(m_tx_buffer));
                ret = app_usbd_cdc_acm_write(&m_app_cdc_acm, m_tx_buffer, size);
                if (ret == NRF_SUCCESS)
                {
                    ++frame_counter;
                    start_loop = true;
                }
            }
    
            int i = 0;
            if (start_loop){
                for(i; i<=1000; i++){
                    NRF_LOG_INFO("%d", i);
                    nrf_delay_ms(1);
                    NRF_LOG_FLUSH();
                }
            }
            nrf_cli_process(&m_cli_uart);
            UNUSED_RETURN_VALUE(NRF_LOG_PROCESS());
            NRF_LOG_FLUSH();
            /* Sleep CPU only if there was no interrupt since last loop processing */
            __WFE();
        }
    }
    
    /** @} */
    

    0385.sdk_config.h

    No problem regarding the delay!

    Using SDK 15.2, example USBD_CDC_ACM found in examples/peripheral/usbd_cdc_acm. You can swap de skd_config file by the one attache. Same for main.c. Pressing button 1 on nRF52840-DK will print in the logger and then you will be able to see the behavior reproduced (the end of the string printed in the logger/viewer will regularly be missing). If that's not enough, please notify me, I can send you some more files but I believe you'll have everything you need with these two files.

    Thank you for your help!

  • Maybe check this out, if not done already:

    bool nrf_log_frontend_dequeue(void)
    {
        if (buffer_is_empty())
        {
            return false;
        }
        // Note also add atomic flag set before this __DSB() and after this function exits
        // See https://devzone.nordicsemi.com/f/nordic-q-a/39188/nrf_log_frontend_dequeue-must-be-atomically-protected-against-re-entry-from-interrupt-context
        if (nrf_atomic_flag_set_fetch(&m_log_data.log_is_busy))
        {
            return false;
        }

    See frontend dequeue interrupt context

Related