Beware that this post is related to an SDK in maintenance mode
More Info: Consider nRF Connect SDK for new designs

[NRF52840] Correct FreeRTOS logging using NRF_LOG module

NRF52840 Dev Kit

NRF SDK 17.1.0

SD version 7.2

Using GCC Make to build

Using RTT logging backend

Hello all,

Currently, we are trying to migrate over to using FreeRTOS for our applicaiton, and I began by using the FreeRTOS example ble_app_hrs_freertos in the ble_peripheral directory. I've been able to get a custom service working fine, but I've been struggling with the NRF_LOG module quite a bit. Currently, I have the logging working fine as long as I am not putting any log outputs in the timer handlers, but as soon as I do that, I get one of two issues.

  1. With NRF_LOG_DEFERRED set to 1, it appears that the application is running as the LED's are blinking and I can connect to the device via NRF Connect, but there are no log messages in the terminal past the initial "Fast advertising" found in the on_adv_evt() function. Anything beyond this, such as "Connected", "Disconnected" or any other messages I've put in are never displayed.
  2. With NRF_LOG_DEFERRED set to 0, it works (i.e. showing all the logs) until I put a message into a timer handler. When I do that, a hard fault like the following occurs 
    <error> hardfault: HARD FAULT at 0x0002C19A
    
    <error> hardfault:   R0:  0x09498C20  R1:  0x0000071F  R2:  0x0000071F  R3:  0x200072D8
    
    <error> hardfault:   R12: 0x00000000  LR:  0x0002C18D  PSR: 0x8100000E
    
    <error> hardfault: Cause: Data bus error (PC value stacked for tult).
    
     I received this data using the JLinkRTTViewer program.

For quick reference, here is all of the logging related code and main form the example:

/**@brief Function for initializing the nrf log module.
 */
static void log_init(void)
{
    ret_code_t err_code = NRF_LOG_INIT(NULL);
    APP_ERROR_CHECK(err_code);

    NRF_LOG_DEFAULT_BACKENDS_INIT();
}


#if NRF_LOG_ENABLED
/**@brief Thread for handling the logger.
 *
 * @details This thread is responsible for processing log entries if logs are deferred.
 *          Thread flushes all log entries and suspends. It is resumed by idle task hook.
 *
 * @param[in]   arg   Pointer used for passing some arbitrary information (context) from the
 *                    osThreadCreate() call to the thread.
 */
static void logger_thread(void * arg)
{
    UNUSED_PARAMETER(arg);

    while (1)
    {
        NRF_LOG_FLUSH();

        vTaskSuspend(NULL); // Suspend myself
    }
}
#endif //NRF_LOG_ENABLED

#if NRF_LOG_ENABLED && NRF_LOG_DEFERRED
 void log_pending_hook( void )
 {
     BaseType_t result = pdFAIL;

    if ( __get_IPSR() != 0 )
    {
        BaseType_t higherPriorityTaskWoken = pdFALSE;
        result = xTaskNotifyFromISR( m_logger_thread, 0, eSetValueWithoutOverwrite, &higherPriorityTaskWoken );

        if ( pdFAIL != result )
        {
        portYIELD_FROM_ISR( higherPriorityTaskWoken );
        }
    }
    else
    {
        UNUSED_RETURN_VALUE(xTaskNotify( m_logger_thread, 0, eSetValueWithoutOverwrite ));
    }
 }
#endif

/**@brief Function for initializing the clock.
 */
static void clock_init(void)
{
    ret_code_t err_code = nrf_drv_clock_init();
    APP_ERROR_CHECK(err_code);
}


/**@brief Function for application main entry.
 */
int main(void)
{
    bool erase_bonds = false;

    // Initialize modules.
    log_init();
    clock_init();

    // Do not start any interrupt that uses system functions before system initialisation.
    // The best solution is to start the OS before any other initalisation.

#if NRF_LOG_ENABLED
    // Start execution.
    if (pdPASS != xTaskCreate(logger_thread, "LOGGER", 256, NULL, 1, &m_logger_thread))
    {
        APP_ERROR_HANDLER(NRF_ERROR_NO_MEM);
    }
#endif


    // Activate deep sleep mode.
    SCB->SCR |= SCB_SCR_SLEEPDEEP_Msk;
    // Configure and initialize the BLE stack.
    ble_stack_init();

    // Initialize modules.
    timers_init();
    leds_init();
    gap_params_init();
    gatt_init();
    services_init();
    advertising_init();
    sensor_simulator_init();
    conn_params_init();
    peer_manager_init();
    application_timers_start();

    bsp_board_led_on(2);

    
    // Create a FreeRTOS task for the BLE stack.
    // The task will run advertising_start() before entering its loop.
    nrf_sdh_freertos_init(advertising_start, &erase_bonds);

    NRF_LOG_INFO("HRS FreeRTOS example started.");
    // Start FreeRTOS scheduler.
    vTaskStartScheduler();

    for (;;)
    {
        APP_ERROR_HANDLER(NRF_ERROR_FORBIDDEN);
    }
}

So my question is, what is the proper way to do logging (whether using the NRF_LOG module or any other way) with the FreeRTOS OS? In particular, what is the proper way to log/debug in the timer/task contexts?

Thanks!

Parents
  • Hi, 

    This is a known issue in SDK17.1 FreeRTOS example. Please use the patch mentioned in this thread to replace the task notify API with task resume for resuming logger thread. I accidently introduced a race condition when I patched this example while trying to solve something else.

  • I was a little ahead of myself. The issue described above is solved for the most part with the solution above, however, when I try to include an NRF_LOG_DEBUG message in the functions from the service .c files (i.e. ble_hrs.c, ble_bas.c, ble_custom.c, etc.), which are used in the timer handlers, then I get one of the following HardFault:

    <error> hardfault: HARD FAULT at 0x20005D00
    
    <error> hardfault:   R0:  0x20007108  R1:  0x20007118  R2:  0x20007118  R3:  0x20007414
    
    <error> hardfault:   R12: 0x00000000  LR:  0x20005D00  PSR: 0x6000000E
    
    <error> hardfault: Cause: The processor has attempted to execute
    I get this when I am trying to put NRF_LOG_DEBUG in the ble_hrs_heart_rate_measurement_send() function from the ble_hrs.c file.

    Or

    <error> hardfault: HARD FAULT at 0x0002C2C6
    
    <error> hardfault:   R0:  0xDB681B4B  R1:  0x00000A61  R2:  0x00000A61  R3:  0x20007414
    
    <error> hardfault:   R12: 0x00000000  LR:  0x0002C2B9  PSR: 0x8100000E
    
    <error> hardfault: Cause: The processor has made an unaligned memory access.
    I get this when I am trying to put NRF_LOG_DEBUG in the a custom service function called ble_custom_data_update() from a custom service file called ble_custom.c .

    These errors occurred independent of each other, meaning, I had one log commented out while trying to test the other one. I'm not sure if this is related to the original problem, but it is still hindering me from being able to debug as effectively as I would like.

    Thanks!

  • After looking even further into it, I have found that it is still doing something incorrect when I actually connect. The device appears to be getting stuck somewhere upon connection with another device (Phone with NRF Connect in my case). This is happening when I have no log messages being sent to the functions mentioned above.

    I am able to print some messages out at the very beginning of the timer handlers, but as mentioned in the reply above, I am unable to put messages in functions called by the handler as it causes a HardFault. 

    I've noticed a weird behavior which is the following:

    1. Turn on the Dev Kit and connect the JLinkRTTViewer to the device. I can see the normal logs I have placed in main without issue.
    2. Connect to the Dev Kit via NRF Connect on a phone. The phone remains connected for a moment before disconnecting.
    3. Anything being printed on the RTT Viewer stops being printed, and LEDs hold whatever state they had.
    4. Closing/Disconnecting the RTT Viewer from the Dev Kit, the LEDs reset (indicating a system reset) and I can reconnect with RTT Viewer and see the normal logs placed in main again. 

    It appears to get stuck somewhere, but I am unable to figure out where or how because everything is frozen. But disconnecting the RTT Viewer makes the device unfreeze and reset which is very strange.

  • That is very strange, I am not able to replicate this. Can you please give me your whole main.c file so that I can quickly test this on my desk?

Reply Children
No Data
Related