freeRTOS + nrf_logging module thread-safe?

[Axel.A]

Hi!

I have an issue with log-entrys disappearing seemingly at random. Not super frequent and possibly (but not confirmed) more often towards the beginning of a freshly started thread.

I'm using SDK 15.2.0 with soft-device s132 v6.0.0

A stripped down version of my code:

void vApplicationIdleHook( void )
{
         vTaskResume(m_logger_task);
}

static void logger_task(void * arg)
{
    UNUSED_PARAMETER(arg);

    while (1)
    {
        NRF_LOG_FLUSH();

        vTaskSuspend(NULL); // Suspend myself
    }
}

static void some_task(void * arg)
{
   NRF_LOG_INFO("some_task 1");
   ...
   do_stuff();
   ...
   NRF_LOG_INFO("some_task 2");
   while(1)
   {
      do_more_task_stuff()
   }
}


int main(void)
{
    uint32_t err_code = NRF_LOG_INIT(NULL);
    NRF_LOG_DEFAULT_BACKENDS_INIT();
    ...
    NRF_LOG_INFO("Main 1");
    ...
    xTaskCreate(logger_task, "LOGGER", 1024, NULL, 1, &m_logger_task)
    xTaskCreate(some_task, "SOME_TASK", 1024, NULL, 1, &m_some_task)
    ...
    ...  //Multiple other tasks are also started and they also log
    xTaskCreate(other_task, "OTHER_TASK", 1024, NULL, 1, &m_other_task)


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

I would expect to get
"Main 1"
"some_task 1"
"some_task 2"

But sometimes I just get 

"Main 1"
"some_task 2"

Just like the first prints from "some_tasks" get eaten. However the logs from "Main" never seem to get lost.

So I did some digging into the log-code. It seems as the NRF_LOG_DEBUG() macro trough a series of expansions ends up at 
nrf_log_frontend.c:536 std_n() function
static inline void std_n(uint32_t           severity_mid,
                         char const * const p_str,
                         uint32_t const *   args,
                         uint32_t           nargs)
{
    uint32_t mask   = m_log_data.mask;
    uint32_t wr_idx;

    if (buf_prealloc(nargs, &wr_idx, true))
    {
        // Proceed only if buffer was successfully preallocated.

        uint32_t data_idx = wr_idx + HEADER_SIZE;
        uint32_t i;
        for (i = 0; i < nargs; i++)
        {
            m_log_data.buffer[data_idx++ & mask] =args[i];
        }
        std_header_set(severity_mid, p_str, nargs, wr_idx, mask);
    }
    if (m_log_data.autoflush)
    {
        NRF_LOG_FLUSH();
    }

}
 

That function seems to directly manipulate the global singleton m_log_data object and I cannot se any mutexes or other locking mechanisms.
Cannot se any locking in the 
   nrf_log_frontend_dequeue()
function either (seems to be where the logging threads macro expansion of "NRF_LOG_FLUSH()" ends up).

So my questions are:

1. Am I missing something or are the logging functions simply not thread safe? The documentation specifically says that non-defered mode is not thread-safe. But is says nothing about defered mode (which is what I'm using). 

2. Could it be something else that I'm doing wrong? Am I the only one with this issue?

[Susheel Nuguru]

Anthony from this thread showed me that there is an issue in the way logs are handled in FreeRTOS examples.

I have attached the workaround for that in this thread. The main.c needs to handle the logs differently after replacing the file nrf_log_frontend.c

[Susheel Nuguru]

The fix is now pushed to master and will be available to you in the next release of SDK

[Axel.A]

Ah, I actually did something similar to make sure the log_thread was woken up but I made my own macro (since I also wanted __file__ and __line__ in my prints)

#define MY_DEBUG(...)  do{ NRF_DEBUG(...); wakeup_log_thread();} while(0)

But regardless of solution I also think its a good idea to not depend on the idle-hook.

That said, I still think my comments are valid regarding:
1. RTT silently dropping data
  - Dropping is fine, doing it silently is not IMHO. Somehow insert "RTT Reconnected" everytime it recovers from disconnected/overflow state would be nice.
2. Doc regarding defered-processing not clearly stating the importance of having lowest priority on the log-thread 
  - even though the examples show log-thread with lowest prio I'ts easy to assume that is just for the real-time behaviour. In my case I preffered to get logs output as promptly as possible and raised the priority and unknowingly got hit in the head by the race-condition.

Those are my thoughts on the matter anyway. My problem is solved and I'll mark this thread as solved.
Thank you for your time.

Best Regards
Axel